Page 1 of 1

Strange issue that has just started happening.

Posted: Tue 23 Aug 2022 2:26 pm
by BigOkie
For the most part for the last year my CumulusMX install on my Pi3b+ has been running well.

The last week or so, I've had some issues about every 24 to 48 hours that requires me to restart the service. Now this isn't a huge issue, but it's baffling.

My setup is this:

Davis VP2plus connected via USB/serial to the Pi running Buster (got it from the Pi image on the wiki page). The only change that I have made since that was to *grudgingly* update Mono during an update.

I update an inhouse website using Saratoga that is private to me that I have on a separate device (Odroid XU4). I mount the webdir on the Odroid to the the Pi via NFS and it's assigned a share. I have that set in the extraweb files on CMX by just doing a copy, and no FTP. I've done this for years now without issue.

What has been happening for about a week now is that after some time CMX runs ok, but then I will use the standard web interface on http://someserver:8998 and I can't get to it. I check the Pi via ssh and note that CMX is running ok (I have it running as a service). I notice the files have stopped updating on the remote webserver, but the Pi MXdiags are still populating data within like the program is running. The difference I see is that the 'today.ini' file has stopped indicating it is updating every five minutes in the log.

A restart of CMX service corrects the issue straight away, and it will plug away for some time. Then the issue will pop up again and I have to restart CMX.

Here's what my diag file looks like when it stops updating. I'm not sure if it's something happening on the remote Odroid that could be doing this or something else. I'm running b3190 right now (haven't had much time to update).

Code: Select all

2022-08-21 19:45:00.351 DoLogFile: Writing log entry for 08/21/2022 19:45:00
2022-08-21 19:45:00.352 DoLogFile: log entry for 08/21/2022 19:45:00 written
2022-08-21 19:45:00.356 Writing today.ini, LastUpdateTime = 08/21/2022 19:45:00 raindaystart = 22.63 rain counter = 22.64
2022-08-21 19:46:38.227 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:46:38.322 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:48:16.238 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:48:16.316 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:49:54.229 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:49:54.305 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:50:00.478 DoLogFile: Writing log entry for 08/21/2022 19:50:00
2022-08-21 19:50:00.479 DoLogFile: log entry for 08/21/2022 19:50:00 written
2022-08-21 19:50:00.483 Writing today.ini, LastUpdateTime = 08/21/2022 19:50:00 raindaystart = 22.63 rain counter = 22.64
2022-08-21 19:50:00.489 Updating CWOP
2022-08-21 19:51:32.227 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:51:32.303 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:53:10.209 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:53:10.300 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:54:48.202 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:54:48.278 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:55:00.632 DoLogFile: Writing log entry for 08/21/2022 19:55:00
2022-08-21 19:55:00.633 DoLogFile: log entry for 08/21/2022 19:55:00 written
2022-08-21 19:55:00.637 Writing today.ini, LastUpdateTime = 08/21/2022 19:55:00 raindaystart = 22.63 rain counter = 22.64
2022-08-21 19:56:26.224 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:56:26.301 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:58:04.220 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:58:04.296 SendLoopCommand: Starting - LOOP 50
2022-08-21 19:59:42.200 Reading reception stats
2022-08-21 19:59:42.234 SendLoopCommand: Starting - LPS 2 1
2022-08-21 19:59:42.320 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:01:20.198 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:01:20.274 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:02:58.216 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:02:58.292 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:04:36.218 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:04:36.296 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:06:14.188 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:06:14.266 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:07:52.212 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:07:52.287 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:09:30.204 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:09:30.281 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:11:08.207 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:11:08.284 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:12:46.209 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:12:46.287 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:14:24.201 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:14:24.278 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:16:02.206 Reading reception stats
2022-08-21 20:16:02.243 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:16:02.318 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:17:40.203 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:17:40.279 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:19:18.201 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:19:18.278 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:20:56.195 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:20:56.272 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:22:34.200 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:22:34.277 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:24:12.198 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:24:12.276 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:25:50.169 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:25:50.246 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:27:28.195 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:27:28.273 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:29:06.183 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:29:06.260 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:30:44.183 SendLoopCommand: Starting - LPS 2 1
2022-08-21 20:30:44.259 SendLoopCommand: Starting - LOOP 50
2022-08-21 20:32:22.185 Reading reception stats
You'll notice the 20:00 today.ini file write doesn't happen, but I do see the program appears to still be logging loop sends and reception stat reading.

Any ideas? I'm going to disconnect the remote server to start troubleshooting to see if maybe something weird with the NFS mount could be happening. I've looked through all the logs on both machines with no real indication of the issue.

Thank you.

Re: Strange issue that has just started happening.

Posted: Tue 23 Aug 2022 5:39 pm
by SamiS
Every time when my Raspberries have started behaving badly, I have had an issue with the sd card. Turning on debug logging might also give a hint for troubleshooting.

Re: Strange issue that has just started happening.

Posted: Thu 25 Aug 2022 1:29 pm
by BigOkie
SamiS wrote: Tue 23 Aug 2022 5:39 pm Every time when my Raspberries have started behaving badly, I have had an issue with the sd card. Turning on debug logging might also give a hint for troubleshooting.
I would think that might be the case had I not replaced the SD Card just over a year ago. The previous SD card I had on this setup lasted me five years without issue but I went ahead and replaced it when I made the change from b3043 to the later builds and just did the Pi image install. I haven't seen anything in the system logs to indicate i/o errors on the card but not sure they would show up anyway. Like I said it started when I updated Mono to the latest version the Buster repo had. For now, I have a cron job running a script to check the today.ini file age and if it's over a certain threshold I tell the script to restart the CMX service. Not ideal but solves the issue short-term.