End of Day Back-up Code Issue

[sfws]

I have checked through MX release announcements and can't find any relevant note to account for this. I wonder whether the Cumulus code is correctly written re writing the end of day backup, as it appears (and I don't pretend to understand how MX works) that this can sometimes be delayed from when it should happen until the next logging interval.

Let me explain why I make that assertion.

As part of End of Day, MX creates a sub-folder in CumulusMX/backup/daily.

Historically (in legacy Cumulus and MX), that folder has been named using a format that can be described by yyyyMMddHHmmss.

For me with a 10 am rollover in summer, the HH would be 10, and the minutes and seconds would be zero, providing Cumulus is left running. For over a decade I have had a script that reads the today.ini in that folder to extract information about rainfall and to derive the daily increment in Chill Hours (as the software does not report that). This has successfully for all those past years easily found the folder.

Last month, I had to modify the script as I upgraded my MX then (having previously been happy to stay with an old release. Now sometimes the backup folder is named (and created) ten minutes later. So my code still looks for zero minutes folder, but if that fails, it now looks for a folder timed 10 minutes later. I don't see any evidence of any other names, and it might be related to that my Cumulus logging interval is set to 10 minutes, as nothing else is set to 10 minutes.

In the MX code:
I find from line 6367 in Cumulus.cs within the function private void Backupdata(bool daily, DateTime timestamp) says

Code: Select all

string foldername = timestamp.ToString("yyyyMMddHHmmss");

so the time is passed into the function that creates the backup, when it is called.

Lines 5968 to 5972 triggers that function at what it calls there "StartofDay" (apparently this can be ten minutes later, than the "day rest" procedure, sometimes). To me it seems strange that the back-up call is not coded so it always at time of completing day reset!
I am assuming, that MX constantly works through the code in this area, and can only guess something somewhere else in that code section is responsible for the ten minute delay sometimes, but not other times? That is why I asserted above that maybe the code is not correctly written?

This delay happened this morning, after a run of mornings with zero minutes, so I compared the relevant parts of the two log files (a rotation happened between them) in MXdiags folder, and there is nothing to explain this, even when I look at every single line (just key lines shown below for yesterday and today):

First of all yesterday (when "startOfDay" followed "Day rest"):

2021-04-09 10:00:09.705 === Day reset, today = 9
2021-04-09 10:00:09.705 === Day reset for 08/04/2021 00:00:00
2021-04-09 10:00:09.706 Dayfile.txt entry:
2021-04-09 10:00:09.706 08/04/21,33.86,225,18:44,4.6,07:37,11.5,11:33,997.2,05:11,1006.3,10:23,3.6,07:07,1.8,8.4,230.3,25.3,18:04,48,13:27,83,08:11,0.00,0.00,11.5,11:33,7.1,12:21,0.1,01:39,0.9,07:07,2.3,06:38,3.3,04:46,-1.3,19:44,239,7.1,0.0,0,10:00,0.0,10:00,9.5,12:21,2.3,06:38,9.9,14:29
2021-04-09 10:00:09.707 Dayfile.txt opened for writing
2021-04-09 10:00:09.707 Writing entry to dayfile.txt
2021-04-09 10:00:09.707 Raincounter = 359.4 Raindaystart = 357.6
...

2021-04-09 10:03:04.950 Executing daily program: sh params: "./batch/autoEOD.sh"
2021-04-09 10:03:04.979 === Day reset complete
2021-04-09 10:03:04.979 Now recording data for day=9 month=4 year=2021
2021-04-09 10:03:04.985 DoLogFile: Writing log entry for 09/04/2021 10:00:00
2021-04-09 10:03:04.987 DoLogFile: Written log entry for 09/04/2021 10:00:00
2021-04-09 10:03:04.990 Writing today.ini, LastUpdateTime = 09/04/2021 10:00:00 raindaystart = 359.4 rain counter = 359.4
2021-04-09 10:03:04.990 Latest reading: 58D0: 08-31-AA-00-52-3E-00-E8-26-07-0A-00-08-AE-04-00
2021-04-09 10:03:10.446 Error writing today.ini: Sharing violation on path /media/pi/mx/CumulusMX/data/today.ini
2021-04-09 10:03:10.467 Creating backup folder backup/daily/20210409100000/

So yesterday there was apparently a problem with today.ini (but nothing to explain why), but it still created backup folder with zero minutes name

Now compare with today (when there was an unexplained ten minute delay):

2021-04-10 10:00:03.849 === Day reset, today = 10
2021-04-10 10:00:07.598 Realtime[128]: Start cycle
2021-04-10 10:00:08.857 Reading first block
2021-04-10 10:00:09.301 === Day reset for 09/04/2021 00:00:00
2021-04-10 10:00:09.305 Dayfile.txt entry:
2021-04-10 10:00:09.305 09/04/21,16.03,45,16:03,0.7,06:57,10.3,13:06,998.7,13:14,1001.9,09:10,3.6,14:21,0.6,4.5,55.9,13.1,16:03,53,13:10,82,10:00,0.00,0.00,10.3,13:06,8.0,12:59,-2.8,06:58,0.6,14:42,-1.0,04:02,4.4,10:28,-4.5,05:17,343,11.0,0.0,0,10:00,0.0,10:00,10.0,12:58,-1.0,04:02,9.9,12:49
2021-04-10 10:00:09.306 Dayfile.txt opened for writing
2021-04-10 10:00:09.306 Writing entry to dayfile.txt
2021-04-10 10:00:09.307 Raincounter = 360 Raindaystart = 359.4
...
2021-04-10 10:01:15.890 Executing daily program: sh params: "./batch/autoEOD.sh"
2021-04-10 10:01:15.898 === Day reset complete
2021-04-10 10:01:15.899 Now recording data for day=10 month=4 year=2021
2021-04-10 10:01:23.059 Reading first block
...
2021-04-10 10:10:12.552 DoLogFile: Written log entry for 10/04/2021 10:10:00
2021-04-10 10:10:12.560 Writing today.ini, LastUpdateTime = 10/04/2021 10:10:00 raindaystart = 360 rain counter = 360
2021-04-10 10:10:12.561 Latest reading: 61E0: 04-32-A7-00-44-1A-00-05-27-00-00-00-04-B0-04-00
2021-04-10 10:10:12.571 Creating backup folder backup/daily/20210410101000/

So today, no messages about any problems, but it creates backup folder 10 minutes after it finishes the day reset.

[mcrossley]

The backup does seem to be triggered in an odd way, I'd have thought it should be run as part of the end of day processing directly. But it just sets a flag that it needs doing and depending on the timing that can happen at the rollover interval or the interval after that.

I'll see if I can spot any good reason for it to be run like that, and if not, change it to be run consistently during the rollover.

[sfws]

Another issue:
The key question is "can the creating of a back-up by MX clash with the MX process of updating today.ini log file?"
A recent experience suggests one part of MX can clash with another part of MX, see this recent MXdiags log (Relevant lines only included from all files).

There is no process, other than MX, on my Raspberry Pi that accesses the /data folder. (Incidently, my PC was not connecting to the RPi at the time).

Yet MX seems to have created its own sharing violation when the backup was running 10 minutes, or so, after the EoD rollover.

I can also report that the today.ini file in backup folder backup/daily/20210430101013/ was empty as a result of this.

Code: Select all

2021-04-21 07:07:36.171  ========================== Cumulus MX starting ==========================
2021-04-21 07:07:36.178 Command line: /media/pi/mx/CumulusMX/CumulusMX.exe -debug 
2021-04-21 07:07:36.178 Cumulus MX v.3.10.5 build 3122
2021-04-21 07:07:36.187 Platform: Unix
2021-04-21 07:07:36.189 OS version: Unix 5.10.17.7
2021-04-21 07:07:36.190 Mono version: 6.12.0.122 (tarball Mon Feb 22 17:44:05 UTC 2021)
2021-04-21 07:07:36.191 Current culture: English (United Kingdom)
2021-04-23 08:40:00.101 Rotated log file, old log file was: 20210421-070735.txt
2021-04-25 12:50:03.696 Rotated log file, old log file was: 20210423-084000.txt
2021-04-27 18:10:00.425 Rotated log file, old log file was: 20210425-125000.txt
2021-04-29 21:00:00.051 Rotated log file, old log file was: 20210427-181000.txt
2021-04-30 10:00:00.652 Reading first block
2021-04-30 10:00:00.807  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:00:00.808  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:00:00.808  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:00:00.808  Data4: 81-00-00-F0-0F-00-C0-16
2021-04-30 10:00:00.808 First block read, addr = 000016C0
2021-04-30 10:00:00.808 Reading data, addr = 000016C0
2021-04-30 10:00:00.963  Data1: 08-30-AA-00-42-62-00-0B
2021-04-30 10:00:00.963  Data2: 27-07-0A-00-04-E2-04-00
2021-04-30 10:00:00.963  Data3: 0A-34-AE-00-4B-33-00-97
2021-04-30 10:00:00.963  Data4: 27-14-18-00-02-A6-04-00
2021-04-30 10:00:00.963 Data read - 08-30-AA-00-42-62-00-0B-27-07-0A-00-04-E2-04-00-0A-34-AE-00-4B-33-00-97-27-14-18-00-02-A6-04-00
2021-04-30 10:00:00.963 16C0: 08-30-AA-00-42-62-00-0B-27-07-0A-00-04-E2-04-00
2021-04-30 10:00:05.041 === Day reset, today = 30
2021-04-30 10:00:05.042 === Day reset for 29/04/2021 00:00:00
2021-04-30 10:00:05.051 Writing today.ini, LastUpdateTime = 30/04/2021 09:50:00 raindaystart = 375 rain counter = 375
2021-04-30 10:00:22.644  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:00:28.014  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:00:28.014  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:00:28.016  Data4: 81-00-00-F0-0F-00-C0-16
2021-04-30 10:00:28.016 First block read, addr = 000016C0
2021-04-30 10:00:28.016 Reading data, addr = 000016C0
2021-04-30 10:00:28.172  Data1: 09-30-AA-00-42-61-00-09
2021-04-30 10:00:33.538  Data2: 27-03-07-00-04-E2-04-00
2021-04-30 10:00:33.539  Data3: 0A-34-AE-00-4B-33-00-97
2021-04-30 10:00:33.540  Data4: 27-14-18-00-02-A6-04-00
2021-04-30 10:00:33.540 Data read - 09-30-AA-00-42-61-00-09-27-03-07-00-04-E2-04-00-0A-34-AE-00-4B-33-00-97-27-14-18-00-02-A6-04-00
2021-04-30 10:00:33.541 16C0: 09-30-AA-00-42-61-00-09-27-03-07-00-04-E2-04-00
2021-04-30 10:01:23.209 Realtime[92]: Warning, a previous cycle is still processing local files. Skipping this interval.
2021-04-30 10:01:25.622 Reading first block
2021-04-30 10:01:31.646  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:01:31.646  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:01:31.646  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:01:31.646  Data4: 81-00-00-F0-0F-00-D0-16
2021-04-30 10:01:31.646 First block read, addr = 000016D0
2021-04-30 10:02:35.061 Realtime[94]: Warning, a previous cycle is still processing local files. Skipping this interval.
2021-04-30 10:10:25.059 Realtime[104]: Warning, a previous cycle is still processing local files. Skipping this interval.
2021-04-30 10:01:23.516 === Day reset complete
2021-04-30 10:01:23.516 Now recording data for day=30 month=4 year=2021
2021-04-30 10:01:23.517 *** Data input appears to have stopped
2021-04-30 10:01:35.622 Reading first block
2021-04-30 10:01:35.777  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:01:35.778  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:01:35.778  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:01:35.778  Data4: 81-00-00-F0-0F-00-D0-16
2021-04-30 10:01:35.778 First block read, addr = 000016D0
2021-04-30 10:01:35.778 Reading data, addr = 000016D0
2021-04-30 10:01:35.933  Data1: 00-30-AA-00-42-60-00-0B
2021-04-30 10:01:35.934  Data2: 27-03-07-00-04-E2-04-00
2021-04-30 10:01:35.934  Data3: 0A-34-AE-00-4C-2F-00-97
2021-04-30 10:01:35.934  Data4: 27-0E-11-00-04-A6-04-00
2021-04-30 10:01:35.934 Data read - 00-30-AA-00-42-60-00-0B-27-03-07-00-04-E2-04-00-0A-34-AE-00-4C-2F-00-97-27-0E-11-00-04-A6-04-00
2021-04-30 10:01:35.934 16D0: 00-30-AA-00-42-60-00-0B-27-03-07-00-04-E2-04-00
2021-04-30 10:09:51.806  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:09:57.183  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:09:57.184  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:09:57.184  Data4: 81-00-00-F0-0F-00-D0-16
2021-04-30 10:09:57.184 First block read, addr = 000016D0
2021-04-30 10:09:57.184 Reading data, addr = 000016D0
2021-04-30 10:09:57.339  Data1: 08-30-AA-00-43-67-00-0A
2021-04-30 10:09:57.340  Data2: 27-0A-0E-00-04-E2-04-00
2021-04-30 10:09:57.340  Data3: 0A-34-AE-00-4C-2F-00-97
2021-04-30 10:09:57.340  Data4: 27-0E-11-00-04-A6-04-00
2021-04-30 10:09:57.340 Data read - 08-30-AA-00-43-67-00-0A-27-0A-0E-00-04-E2-04-00-0A-34-AE-00-4C-2F-00-97-27-0E-11-00-04-A6-04-00
2021-04-30 10:09:57.340 16D0: 08-30-AA-00-43-67-00-0A-27-0A-0E-00-04-E2-04-00
2021-04-30 10:10:52.701 Error writing today.ini: Sharing violation on path /media/pi/mx/CumulusMX/data/today.ini
2021-04-30 10:11:00.493 *** Data input appears to have stopped
2021-04-30 10:11:14.804 Error writing today.ini: Sharing violation on path /media/pi/mx/CumulusMX/data/today.ini
2021-04-30 10:11:14.815 Created backup folder backup/daily/20210430101013/
2021-04-30 10:11:23.990 Reading first block
2021-04-30 10:11:31.509  Data1: 55-67-FC-01-10-E0-8F-00
2021-04-30 10:11:42.399  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:11:42.399  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:11:42.399  Data2: FF-80-3F-21-84-FD-00-E8
2021-04-30 10:11:42.399  Data3: 0A-21-08-43-11-00-00-00
2021-04-30 10:11:42.399  Data4: 81-00-00-F0-0F-00-E0-16
2021-04-30 10:11:42.399 First block read, addr = 000016E0

There is a distraction here, it appears the USB connection dropped, came back, then dropped again, and finally came back again; and viewtopic.php?p=153111#p153111 to viewtopic.php?p=153166#p153166 discuss that issue, I don't know if this affects your solution to that problem.

[mcrossley]

Yet MX seems to have created its own sharing violation when the backup was running 10 minutes, or so, after the EoD rollover.

Quite possibly. The Ini file writer only performs internal file locking. So two separate threads like this could cause a sharing violation.

The backup is now moved to the EOD processing so I think it is less likely to have a clash. Really there should be global locking of all files, but that is a big job to add. For now I think we'll have to live with the occasional clash - hopefully they will be pretty rare.