Random "Cumulus has stopped receiving data"

[stefanbagnato]

Within the last six weeks or so, Cumulus will randomly give "Cumulus has stopped receiving data". The only fix has been to reboot. Via logs, I've confirmed that "something" must be bouncing the connection over COM3, as everything will work fine for X days, but then:

2021-08-14 14:53:01.069 InitSerial: Connecting to the station
2021-08-14 14:53:01.072 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-14 14:53:01.074 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-14 14:53:31.076 InitSerial: Connecting to the station
2021-08-14 14:53:31.076 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-14 14:53:31.077 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again

It'll then send me the alarm email and keep trying to reconnect. I've rolled back all Windows Updates since then but no difference. I am on CMX v3.11.4 b3133 (I know, slightly behind, just need the time to update). I don't recall exactly when this issue started, but I do not believe it was due to updating CMX either.

For background, everything besides my domain name itself is hosted locally. Nothing else is plugged into the server besides peripherals. I have a usb-to-serial adapter that runs from my Weather Envoy to the server, but there are no driver updates for it and it's been on the same version for 5+ years now.

I am guessing that my issue is probably not a CMX issue but rather something else local, but just seeing if anybody else has experienced this before.

[mcrossley]

Only thing I can think of is to look at the power settings for your USB hubs and devices in Windows Device Manager and make sure it is disabled on all of them.

[stefanbagnato]

Okay got it. I checked and two of the "devices" (drivers) did have power saving turned on. Not certain why, and also not certain when/if anything changed since this was never an issue. Either way, I'll keep an eye on it and see what happens.

[stefanbagnato]

So the issue still exists. It actually happened while I am sitting here at the server reviewing some lines of code for the website. It's still the same issue of "something" taking over the COM port. Bouncing the service fixes it. I've turned on literally all logging...

Issues starts at 10:58:50

2021-08-28 10:58:48.866 Realtime[157]: Start cycle
2021-08-28 10:58:48.867 Realtime[157]: Processing extra file[10] -(cleared out)
2021-08-28 10:58:48.875 Realtime[157]: Copying extra file[10] (cleared out) to (cleared out)
2021-08-28 10:58:48.893 Realtime[157]: Copying extra file[11] (cleared out) to (cleared out)
2021-08-28 10:58:48.897 Realtime[157]: End cycle
2021-08-28 10:58:48.898 Realtime[157]: MySQL executing - INSERT IGNORE INTO Realtime (LogDateTime,temp,hum,dew,wspeed,wlatest,bearing,rrate,rfall,press,currentwdir,beaufortnumber,windunit,tempunitnodeg,pressunit,rainunit,windrun,presstrendval,rmonth,ryear,rfallY,intemp,inhum,wchill,temptrend,tempTH,TtempTH,tempTL,TtempTL,windTM,TwindTM,wgustTM,TwgustTM,pressTH,TpressTH,pressTL,TpressTL,version,build,wgust,heatindex,humidex,UV,ET,SolarRad,avgbearing,rhour,forecastnumber,isdaylight,SensorContactLost,wdir,cloudbasevalue,cloudbaseunit,apptemp,SunshineHours,CurrentSolarMax,IsSunny,FeelsLike) Values('21-08-28 10:58:48',85.9,79,78.6,2.7,1.0,177,0.00,0.00,30.16,'S','1','mph','F','in','in',4.0,'+0.01',4.07,31.45,0.00,77.3,52,85.9,+4.0,86.5,'10:48',71.4,'06:44',2.7,'10:58',9.0,'10:49',30.16,'10:44',30.10,'05:12','3.12.1','3143',9.0,99.0,42.9,5.2,0.018,645,301,0.00,1,'1','0','WNW',1653,'ft',97.0,4.0,750,'1',93.8)
2021-08-28 10:58:48.953 Realtime[157]: MySQL 1 rows were affected.
2021-08-28 10:58:50.912 LOOP: 11 - Expected data not received, expected 99 bytes, got 0
2021-08-28 10:58:51.920 LOOP: 11 - Timed out waiting for LOOP data
2021-08-28 10:58:51.920 Sending BARREAD
2021-08-28 10:58:51.920 WakeVP: Not required
2021-08-28 10:58:51.966 SendBarRead: Error - A device attached to the system is not functioning.

2021-08-28 10:58:51.966 SendBarRead: Attempting to reconnect to logger
2021-08-28 10:58:51.966 InitSerial: Connecting to the station
2021-08-28 10:58:51.982 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-28 10:58:51.982 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-28 10:59:00.313 DoLogFile: Writing log entry for 8/28/2021 10:59:00 AM
2021-08-28 10:59:00.313 DoLogFile: max gust: 9.0
2021-08-28 10:59:00.328 DoLogFile: log entry for 8/28/2021 10:59:00 AM written
2021-08-28 10:59:00.328 Writing today.ini, LastUpdateTime = 8/28/2021 10:59:00 AM raindaystart = 31.5 rain counter = 31.5
2021-08-28 10:59:00.344 DoLogFile: MySQL executing - INSERT IGNORE INTO Monthly (LogDateTime,Temp,Humidity,Dewpoint,Windspeed,Windgust,Windbearing,RainRate,TodayRainSoFar,Pressure,Raincounter,InsideTemp,InsideHumidity,LatestWindGust,WindChill,HeatIndex,UVindex,SolarRad,Evapotrans,AnnualEvapTran,ApparentTemp,MaxSolarRad,HrsSunShine,CurrWindBearing,RG11rain,RainSinceMidnight,WindbearingSym,CurrWindBearingSym,FeelsLike,Humidex) Values('21-08-28 10:59',85.9,79,78.6,2.7,9.0,301,0.00,0.00,30.16,31.50,77.3,52,1.0,85.9,99.0,5.2,645,0.018,26.838,97.0,750,4.0,177,0.00,0.00,'WNW','S',93.8,42.9)
2021-08-28 10:59:00.344 Creating standard web files
2021-08-28 10:59:00.344 Done creating standard Data file
2021-08-28 10:59:00.344 Creating graph data files
2021-08-28 10:59:00.375 DoLogFile: MySQL 1 rows were affected.
2021-08-28 10:59:01.073 Done creating graph data files
2021-08-28 10:59:01.073 Interval: Processing extra file[0] - (cleared out)
2021-08-28 10:59:01.088 Interval: Copying extra file[0] (cleared out) to (cleared out)
2021-08-28 10:59:01.135 Interval: Processing extra file[1] - (cleared out)
cleared for brevity
2021-08-28 10:59:01.932 Interval: Copying extra file[41] (cleared out)
2021-08-28 10:59:03.880 Realtime[158]: Start cycle
2021-08-28 10:59:03.880 Realtime[158]: Processing extra file[10] -(cleared out)
2021-08-28 10:59:03.880 Realtime[158]: Copying extra file[10] (cleared out) to (cleared out)
2021-08-28 10:59:03.895 Realtime[158]: Copying extra file[11] (cleared out) to (cleared out)
2021-08-28 10:59:03.895 Realtime[158]: End cycle
2021-08-28 10:59:03.895 Realtime[158]: MySQL executing - INSERT IGNORE INTO Realtime (LogDateTime,temp,hum,dew,wspeed,wlatest,bearing,rrate,rfall,press,currentwdir,beaufortnumber,windunit,tempunitnodeg,pressunit,rainunit,windrun,presstrendval,rmonth,ryear,rfallY,intemp,inhum,wchill,temptrend,tempTH,TtempTH,tempTL,TtempTL,windTM,TwindTM,wgustTM,TwgustTM,pressTH,TpressTH,pressTL,TpressTL,version,build,wgust,heatindex,humidex,UV,ET,SolarRad,avgbearing,rhour,forecastnumber,isdaylight,SensorContactLost,wdir,cloudbasevalue,cloudbaseunit,apptemp,SunshineHours,CurrentSolarMax,IsSunny,FeelsLike) Values('21-08-28 10:59:03',85.9,79,78.6,2.7,1.0,177,0.00,0.00,30.16,'S','1','mph','F','in','in',4.0,'+0.01',4.07,31.45,0.00,77.3,52,85.9,+4.0,86.5,'10:48',71.4,'06:44',2.7,'10:58',9.0,'10:49',30.16,'10:44',30.10,'05:12','3.12.1','3143',9.0,99.0,42.9,5.2,0.018,645,301,0.00,1,'1','0','WNW',1653,'ft',97.0,4.0,750,'1',93.8)
2021-08-28 10:59:03.944 Realtime[158]: MySQL 1 rows were affected.
2021-08-28 10:59:18.885 Realtime[159]: Start cycle
2021-08-28 10:59:18.885 Realtime[159]: Processing extra file[10] - (cleared out)
2021-08-28 10:59:18.885 Realtime[159]: Copying extra file[10] (cleared out) to (cleared out)
2021-08-28 10:59:18.901 Realtime[159]: Copying extra file[11] (cleared out) to (cleared out)
2021-08-28 10:59:18.917 Realtime[159]: End cycle
2021-08-28 10:59:18.917 Realtime[159]: MySQL executing - INSERT IGNORE INTO Realtime (LogDateTime,temp,hum,dew,wspeed,wlatest,bearing,rrate,rfall,press,currentwdir,beaufortnumber,windunit,tempunitnodeg,pressunit,rainunit,windrun,presstrendval,rmonth,ryear,rfallY,intemp,inhum,wchill,temptrend,tempTH,TtempTH,tempTL,TtempTL,windTM,TwindTM,wgustTM,TwgustTM,pressTH,TpressTH,pressTL,TpressTL,version,build,wgust,heatindex,humidex,UV,ET,SolarRad,avgbearing,rhour,forecastnumber,isdaylight,SensorContactLost,wdir,cloudbasevalue,cloudbaseunit,apptemp,SunshineHours,CurrentSolarMax,IsSunny,FeelsLike) Values('21-08-28 10:59:18',85.9,79,78.6,2.7,1.0,177,0.00,0.00,30.16,'S','1','mph','F','in','in',4.0,'+0.01',4.07,31.45,0.00,77.3,52,85.9,+4.0,86.5,'10:48',71.4,'06:44',2.7,'10:58',9.0,'10:49',30.16,'10:44',30.10,'05:12','3.12.1','3143',9.0,99.0,42.9,5.2,0.018,645,301,0.00,1,'1','0','WNW',1653,'ft',97.0,4.0,750,'1',93.8)
2021-08-28 10:59:18.964 Realtime[159]: MySQL 1 rows were affected.
2021-08-28 10:59:21.983 InitSerial: Connecting to the station
2021-08-28 10:59:21.983 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-28 10:59:21.983 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-28 10:59:33.888 Realtime[160]: Start cycle
2021-08-28 10:59:33.888 Realtime[160]: Processing extra file[10] - (cleared out)
2021-08-28 10:59:33.888 Realtime[160]: Copying extra file[10] (cleared out) to (cleared out)
2021-08-28 10:59:33.904 Realtime[160]: Copying extra file[11] (cleared out) to (cleared out)
2021-08-28 10:59:33.904 Realtime[160]: End cycle
2021-08-28 10:59:33.904 Realtime[160]: MySQL executing - INSERT IGNORE INTO Realtime (LogDateTime,temp,hum,dew,wspeed,wlatest,bearing,rrate,rfall,press,currentwdir,beaufortnumber,windunit,tempunitnodeg,pressunit,rainunit,windrun,presstrendval,rmonth,ryear,rfallY,intemp,inhum,wchill,temptrend,tempTH,TtempTH,tempTL,TtempTL,windTM,TwindTM,wgustTM,TwgustTM,pressTH,TpressTH,pressTL,TpressTL,version,build,wgust,heatindex,humidex,UV,ET,SolarRad,avgbearing,rhour,forecastnumber,isdaylight,SensorContactLost,wdir,cloudbasevalue,cloudbaseunit,apptemp,SunshineHours,CurrentSolarMax,IsSunny,FeelsLike) Values('21-08-28 10:59:33',85.9,79,78.6,2.7,1.0,177,0.00,0.00,30.16,'S','1','mph','F','in','in',4.0,'+0.01',4.07,31.45,0.00,77.3,52,85.9,+4.0,86.5,'10:48',71.4,'06:44',2.7,'10:58',9.0,'10:49',30.16,'10:44',30.10,'05:12','3.12.1','3143',9.0,99.0,42.9,5.2,0.018,645,301,0.00,1,'1','0','WNW',1653,'ft',97.0,4.0,750,'1',93.8)
2021-08-28 10:59:33.998 Realtime[160]: MySQL 1 rows were affected.
2021-08-28 10:59:48.902 Realtime[161]: Start cycle
2021-08-28 10:59:48.902 Realtime[161]: Processing extra file[10] - (cleared out)
2021-08-28 10:59:48.902 Realtime[161]: Copying extra file[10] (cleared out) to (cleared out)
2021-08-28 10:59:48.917 Realtime[161]: Copying extra file[11] (cleared out) to (cleared out)
2021-08-28 10:59:48.917 Realtime[161]: End cycle
2021-08-28 10:59:48.933 Realtime[161]: MySQL executing - INSERT IGNORE INTO Realtime (LogDateTime,temp,hum,dew,wspeed,wlatest,bearing,rrate,rfall,press,currentwdir,beaufortnumber,windunit,tempunitnodeg,pressunit,rainunit,windrun,presstrendval,rmonth,ryear,rfallY,intemp,inhum,wchill,temptrend,tempTH,TtempTH,tempTL,TtempTL,windTM,TwindTM,wgustTM,TwgustTM,pressTH,TpressTH,pressTL,TpressTL,version,build,wgust,heatindex,humidex,UV,ET,SolarRad,avgbearing,rhour,forecastnumber,isdaylight,SensorContactLost,wdir,cloudbasevalue,cloudbaseunit,apptemp,SunshineHours,CurrentSolarMax,IsSunny,FeelsLike) Values('21-08-28 10:59:48',85.9,79,78.6,2.7,1.0,177,0.00,0.00,30.16,'S','1','mph','F','in','in',4.0,'+0.01',4.07,31.45,0.00,77.3,52,85.9,+4.0,86.5,'10:48',71.4,'06:44',2.7,'10:58',9.0,'10:49',30.16,'10:44',30.10,'05:12','3.12.1','3143',9.0,99.0,42.9,5.2,0.018,645,301,0.00,1,'1','0','WNW',1653,'ft',97.0,4.0,750,'1',93.8)
2021-08-28 10:59:48.996 Realtime[161]: MySQL 1 rows were affected.
2021-08-28 10:59:51.995 InitSerial: Connecting to the station
2021-08-28 10:59:51.995 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-28 10:59:51.995 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-28 11:00:00.363 Hour changed: 11
2021-08-28 11:00:00.363 Calculating sunrise and sunset times
2021-08-28 11:00:00.363 Sunrise: 06:43:46
2021-08-28 11:00:00.363 Sunset : 19:47:07
2021-08-28 11:00:00.363 Tomorrow sunrise: 06:44:32
2021-08-28 11:00:00.363 Tomorrow sunset : 19:45:46
2021-08-28 11:00:00.363 Tomorrow length diff: -127
2021-08-28 11:00:00.363 Generating new Moon image
2021-08-28 11:00:00.582 SendEmail: Waiting for lock...
2021-08-28 11:00:00.582 SendEmail: Has the lock
2021-08-28 11:00:00.582 SendEmail: Sending email, to [(cleared out)], subject [Cumulus MX Alarm], body ["A Cumulus MX alarm has been triggered.\r\nCumulus has stopped receiving data from y" +
"our weather station."]...
2021-08-28 11:00:00.613 *** Data input appears to have stopped
2021-08-28 11:00:01.765 SendEmail: Releasing lock...
2021-08-28 11:00:22.007 InitSerial: Connecting to the station
2021-08-28 11:00:22.007 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-28 11:00:22.007 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-28 11:00:52.016 InitSerial: Connecting to the station
2021-08-28 11:00:52.016 InitSerial: Error opening port - Access to the port 'COM3' is denied.
2021-08-28 11:00:52.016 InitSerial: Failed to connect to the station, waiting 30 seconds before trying again
2021-08-28 11:01:00.437 *** Data input appears to have stopped

[mcrossley]

That's an odd one. And your are 100% sure no other program attempts to open the port, and no duplicate background copy of Cumulus is still running?

The "InitSerial" routine fully closes and then disposes of the object accessing the COM port, then starts again from scratch, so there isn't really anything more Cumulus can do to recover the situation.

But if as you say stopping and starting the Cumulus MX service allows it to recover it doesn't sound like anything else is holding the port open and preventing CMX from re-opening it. It begins to smell like a bug in the MS .Net code (or my code! though I cannot see one at the moment).

[stefanbagnato]

99.5% sure, yes. Now that I switched to running as a service, I've disabled the exe from running period. And only one copy of the service exists.

I setup a script to restart the service automatically; I just need to figure out how to feed it 'Error opening port - Access to the port 'COM3' is denied.' so it knows when to run. But this is obviously just a bandaid for right now.

[stefanbagnato]

For anybody who might be following this for whatever reason, just an update. I am fairly certain the issue is NOT with CMX, but rather local. I am still logging/monitoring/etc to track it down. While it happens on random days and random intervals, it is nearly the same time in the morning when it does happen. Now, to just find out what is causing it....

[water01]

I remember many, many years ago when I was working on mainframe computers our main server always went down about 20.00. Engineers were investigating for months, until one decided to stay and see what happened at that time.

At about 20.00 a cleaner wandered into the machine room and plugged her vacuum cleaner into a mainframe power supply (only meant for diagnostic equipment) and switched it on. Down went the mainframe. The vacuum cleaner was causing a power spike that automatically shutdown the mainframe to save it from damage (in those days replacement boards were very expensive).

Problem solved, the cleaner was told always to use power sockets outside the machine room and it never happened again.

Got someone plugging a cleaner in or using high powered radio waves near your equipment?

[stefanbagnato]

Hahahaha, that story is a common, famous story in IT. Nope, I am the cleaner and every other person in that story. My server sits right next to me. One thing I didn't think of trying til today is to change the COM port (who knows, might work?). Changed it in Device Manager, confirmed Weatherlink see's it updated (even though I don't use it) and then updated it in CMX and confirm all is well.

This is super maddening, but I am also planning a new server build later this year. Could be one of those magical issues that's only resolved with new hardware. Or, that's my excuse for new hardware