Cumulus Support

Steve,

at around 17:00 yesterday I shut CumulusMX down and rebooted the PC. What I didn't spot was that upon starting up Cumulus was broken. cumulus.ini had been reset back to a new file and cumulus was just sitting there wondering what kind of station it was supposed to connect to. I only spotted this this afternoon.

At about 15:30 I restored cumulus.ini and set the program running. Upon checking the data file I notice it has only processed archive data from my DVP2 from 17:00 yesterday to 10:10 today. I have tried several times, but it always does the same. I know the data is there in the DVP2 archive as Weatherlink can download it and anyway, if I read the logs right it is downloading 28 pages but only processing 20 of them.

At the beginning of the log it says:
2015-05-16 15:36:20.419 Reading data: 28 pages , offset = 2

later, it says:
2015-05-16 15:36:27.146 Loaded archive record for Page=20 Record=4 Timestamp=16/05/2015 10:10:00

and then it seems to process no more archive records

Am I understanding this right and have you any idea why it is not processing all of the log?

Diag file attached.

Thanks,
Adrian

UPDATE: I set up good old Cumulus1 and restored the data files from CumuluMX as of 17:00 yesterday and ran it. Cumulus1 downloaded all the data correctly (so I copied the files back to CumuluMX and it is up to date now).

It looks like something happened which silently killed the archive data processing thread - perhaps attempting to write to today.ini, as that's the last thing logged before the end of the archive data processing - it didn't add that last entry to the WU updates. Some kinds of file access errors do seem to have the effect of silently killing the thread, even if MX is trapping errors. It also seems to have had trouble writing the daily backup, as it did it again on the next log update, so it looks like that thread was also killed silently before it unset the flag which said that the backup needed doing. It's a bit odd, though, that the same thing happened again at exactly the same point every time. Something to do with it being the next entry after the end of day rollover, perhaps. I'll try stopping mine tomorrow some time before 10:00 and starting it up again half an hour later, to see if I get the same thing.

Thanks for your thoughts Steve. I will have to mull over what you have said. I tried the restore/rerun 4 times times and looking at the logs now, they do indeed all stop at 1010 hrs. Below is another example.

Your comment that it might be failing writing a file has got me thinking and I have to mention it - although I don't think it is the problem: I use Stablebit Drivepool on my PC. I have a number of other applications that run on the same machine and none have had any problems. The machine is also used as a sort of simple file server - i.e. other PCs used its to store files of various types and they haven't had any problems either. Nevertheless, the drive that all of these files are written to is not a real one, its a drive created by Drivepool. Cumulus has been running on a pool drive for at least a couple of months now.

I can't see why it would fall over at the same time though... i.e. processing the same log record. Unless there is some sort of unusual write in Cumulus that goes on around then that is failing and panicking the program.

I don't want to muddy the water though but I thought I should mention it.

As I said in the update of the first post, Cumulus1 did the download fine - first attempt.

A final thought: I am sure I have done a restore/catchup over a 10am end of day boundary before with MX (earlier versions). I remember thinking "Nice one Steve, you coded that well" when I checked the data afterwards

Here is an excerpt from the log file from another one of the failures:

2015-05-16 15:23:29.789 Page=20 Record=3 Timestamp=16/05/2015 10:00:00
2015-05-16 15:23:29.789 Writing log entry for 16/05/2015 10:00:00
2015-05-16 15:23:29.789 max gust: 35.5
2015-05-16 15:23:29.790 Written log entry for 16/05/2015 10:00:00
2015-05-16 15:23:29.792 Writing today.ini, LastUpdateTime = 16/05/2015 10:00:00 raindaystart = 267 rain counter = 267.4
2015-05-16 15:23:29.794 Creating WU URL #102
2015-05-16 15:23:29.794 http://weatherstation.wunderground.com/ ... =updateraw
2015-05-16 15:23:29.794 Creating PWS URL #102
2015-05-16 15:23:29.794 http://www.pwsweather.com/pwsupdate/pws ... =updateraw
2015-05-16 15:23:29.794 Creating WOW URL #102
2015-05-16 15:23:29.795 http://wow.metoffice.gov.uk/automaticre ... =updateraw
2015-05-16 15:23:29.795 Creating Weatherbug URL #102
2015-05-16 15:23:29.795 http://data.backyard2.weatherbug.com/da ... =updateraw
Day rollover 10:00
2015-05-16 15:23:29.810 === Day reset, today = 16
2015-05-16 15:23:29.811 === Day reset for 16/05/2015 00:00:00
Writing entry to dayfile.txt:
15/05/15,35.5,265,14:27,11.3,05:50,17.3,14:28,1022.62,02:50,1026.38,10:00,0.0,10:00,0.4,13.4,193.6,19.5,09:30,59,14:14,95,03:50,2.69,3.0,17.3,14:28,16.1,15:05,8.5,05:30,0.2,04:20,11.3,05:50,11.5,04:00,7.0,11:01,359,2.2,0.1,1034,11:11,0.0,10:00
2015-05-16 15:23:29.821 Raincounter = 267.4 Raindaystart = 267
2015-05-16 15:23:29.821 Rainyesterday (calibrated) set to 0.399999999999977
2015-05-16 15:23:29.822 RainDayThreshold = -1
2015-05-16 15:23:29.822 rdt1000=200 ry1000=400
2015-05-16 15:23:29.822 Yesterday was a rain day
2015-05-16 15:23:29.823 Consecutive rain days = 3
Raindaystart set to 267.4
2015-05-16 15:23:29.834 StartofdayET set to 208.2038
2015-05-16 15:23:29.835 Writing today.ini, LastUpdateTime = 16/05/2015 10:00:00 raindaystart = 267.4 rain counter = 267.4
2015-05-16 15:23:29.839 Creating NOAA monthly report for 15 May 2015
2015-05-16 15:23:30.179 Saving monthly report as Reports\NOAAMO0515.txt
2015-05-16 15:23:30.181 Creating NOAA yearly report
2015-05-16 15:23:31.183 Saving yearly report as Reports\NOAAYR2015.txt
2015-05-16 15:23:31.185 Executing daily program: D:\Cumulus\daily.bat params:
2015-05-16 15:23:31.228 === Day reset complete
2015-05-16 15:23:31.229 Now recording data for day=16 month=5 year=2015
2015-05-16 15:23:31.229 Loaded archive record for Page=20 Record=4 Timestamp=16/05/2015 10:10:00
2015-05-16 15:23:31.229 Processing archive record for 16/05/2015 10:10:00
2015-05-16 15:23:31.244 Page=20 Record=4 Timestamp=16/05/2015 10:10:00
2015-05-16 15:23:31.244 Writing log entry for 16/05/2015 10:10:00
2015-05-16 15:23:31.244 max gust: 35.5
2015-05-16 15:23:31.245 Written log entry for 16/05/2015 10:10:00
2015-05-16 15:23:31.246 Writing today.ini, LastUpdateTime = 16/05/2015 10:10:00 raindaystart = 267.4 rain counter = 267.4
2015-05-16 15:23:31.262 Creating backup folder backup\daily\20150516101000\
2015-05-16 15:23:31.266 Updating highs and lows
2015-05-16 15:23:31.269 Start normal reading loop
2015-05-16 15:23:31.276 Start Timers
2015-05-16 15:23:31.276 Starting 1-minute timer
2015-05-16 15:23:31.280 Attempting realtime FTP connect
2015-05-16 15:23:31.321 Starting Realtime timer, interval = 13000ms
2015-05-16 15:23:31.327 Uploading WU archive #1
2015-05-16 15:23:31.354 Uploading PWS archive #1
2015-05-16 15:23:31.364 Uploading WOW archive #1
2015-05-16 15:23:31.374 Uploading Weatherbug archive #1
2015-05-16 15:23:31.496 Sending command LPS 2 1 - pass 1
2015-05-16 15:23:31.598 PWS Response: OK: OK
2015-05-16 15:23:31.598 Uploading PWS archive #2
2015-05-16 15:23:31.701 Loop2: 4C-4F-4F-14-01-FF-7F-A3-76-05-03-29-41-02-0C-FF-DD-00-6D-00-62-00-14-00-24-01-FF-7F-FF-7F-2A-00-FF-38-FF-38-00-36-00-3D-00-00-00-FF-E8-02-00-00-FF-FF-02-00-00-00-00-00-6F-00-02-00-02-10-00-C3-FF-71-75-81-75-A3-76-FF-09-06-0D-11-04-11-15-1D-17-04-04-FF-7F-FF-7F-FF-7F-FF-7F-FF-7F-FF-7F-0A-0D-06-40

I'm also pretty sure that this code does all work in normal circumstances (but I'm still going to try it this morning) and I suspect that your Drivepool software is related, and it is also likely related to why Cumulus couldn't find or read the Cumulus.ini on the occasion that you mentioned. But I don't know what Cumulus does at rollover time which is now apparently causing disk writes to subsequently fail. Assuming the code does actually still work OK on a 'standard' disk setup, I think it's going to be quite difficult to track down the problem on your system, unless the software has some form of log or other diagnostics.

Could you check whether the first backup folder got created, and contains the usual files?

2015-05-16 15:23:31.262 Creating backup folder backup\daily\20150516101000\

The result of my test was that it processed all of the logger entries, and performed the rollover correctly, and wrote all of the entries to the log files - this is with Linux on a Pi, however.

Presumably you don't get this problem when running live, so this must be something to do with the sequence of drive accesses during logger download that the Drivepool software doesn't like. Writing to files during logger download uses the same code as when running live, the only difference that I can think of is that the disk writes are much more frequent during logger download.

Thanks for the test Steve.

If it does turn out to be Drivepool it will be really annoying (from the point of view of using that software) it will mean I can never trust it properly - what other software will cause the issue?

I will see if I can do two more tests one on Drivepool, restoring back to the day before yesterday (or maybe just yesterday) and then - assuming I can replicate the problem - with cumulus on another drive.

Will report back.

Adrian

I did a little bit of research on Drivepool, and it does seem to be highly regarded. I would imagine that its developers know more about what they're doing than I do, so if it does turn out to be an incompatibility between Drivepool and MX, it could be that I'm doing something wrong somewhere and I get away with it on non-Drivepool systems. It does seem to have some diagnostics that can be turned on.

Quite frankly Steve, unless you are doing some low level, direct to disk I/O - which I very much doubt), you shouldn't be able to "[do] something wrong" and I can't be bothered with software (Drivepool) that works at this sort of basic level (disk I/O). It should be pretty much bombproof. It has already caused me grief by changing the volume serial number on the drive when I upgraded versions - which caused software to become un-registered and now this (potential, albeit unproven) issue which casts doubt on the integrity of data on the machine. I am currently deinstalling it.

Adrian Hudson wrote:.......It has already caused me grief by changing the volume serial number on the drive when I upgraded versions - which caused software to become un-registered and now...........

It's very unlikely that Drive Pool caused that situation. A lot of registered software uses the drive serial number against your license / registration number, therefore changing the drive serial number will cause the software to think that it's been installed on another / some one elses machine and you gave them your license / registration number to prevent them from having to purchase another license.

That's what I meant. When I put a new version of Drivepool on the machine, it didn't preserve the volume serial number and so the software thought I had moved it to a new machine.

I have to say, that using the volume serial number isn't a good idea (been there, done that myself) but that's not the point Drivepool should preserve the volume serial number through a simple Drivepool upgrade. I could understand if I recreated the pool but I didn't - and still the vol serial number changed - most aggravating.

Anyway, we are going a bit off subject

Did you get anywhere with this? Mark has a similar problem, but on a Raspberry Pi - https://cumulus.hosiene.co.uk/viewtopic.p ... 23#p107623

One thing you have in common is that you are both executing an external command at rollover.

Hi Steve,

No, sorry, after I deinstalled DrivePool (and decided to use Win 8.1 Storage Spaces - very opaque and fairly inflexible -but does just work) I didn't bother to re-test as it had been a bit of a palaver to deinstall.

However, as a belated test, I have just restored back two days and let it run through the two ends of days which it appears to have done perfectly. Obviously its not the same data as before so maybe its a bit of a moot test.

So, sorry, not going to be able to help with Mark's problem. Odd it appears to die in the same place as I was having. Maybe it really some sort of file system thing that MX is sensitive to - order of operations or something.

Adrian