Instromet logging with 3048

[seggins]

Went away for three days. Left the logger logging.
Logger recorded rubbish-a small extract see below:
2019-03-14 19:35:09.098 New earliest timestamp 09/03/2019 00:48:16
2019-03-14 19:35:09.520 Get next log - RDLG,1
2019-03-14 19:35:09.942 rdlg,138737,1,600,00:58:14,09/03/2019,4.3,4.7,4.4,,,,71.1,74.2,72.7,988.9,989.1,988.9,0.0,13.4,3.3,254,427.86,201.08,100
2019-03-14 19:35:09.942 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 58, S = 14
2019-03-14 19:35:09.942 New earliest timestamp 09/03/2019 00:58:14
2019-03-14 19:35:10.364 Get next log - RDLG,1
2019-03-14 19:35:10.786 rdlg,138738,1,600,01:08:12,09/03/2019,4.2,4.5,4.3,,,,71.1,73.6,72.6,988.9,989.1,989.0,0.0,13.3,3.5,269,427.86,201.08,108
2019-03-14 19:35:10.786 Logger entry zero: Y = 2019, M = 3, D = 9, H = 1, M = 8, S = 12
2019-03-14 19:35:10.786 New earliest timestamp 09/03/2019 01:08:12
2019-03-14 19:35:11.194 Get next log - RDLG,1
2019-03-14 19:35:11.616 rdlg,138739,1,600,01:18:10,09/03/2019,4.1,4.5,4.3,,,,70.3,72.2,71.2,988.9,989.1,989.0,0.0,10.1,3.7,260,427.86,201.08,130
2019-03-14 19:35:11.616 Logger entry zero: Y = 2019, M = 3, D = 9, H = 1, M = 18, S = 10
2019-03-14 19:35:11.616 New earliest timestamp 09/03/2019 01:18:10
2019-03-14 19:35:12.032 Get next log - RDLG,1
2019-03-14 19:35:12.454 rdlg,138724,1,600,22:48:43,08/03/2019,4.5,4.9,4.7,,,,70.0,72.2,71.0,987.9,988.2,988.0,0.0,14.9,3.7,252,427.86,201.08,107
2019-03-14 19:35:12.454 Logger entry zero: Y = 2019, M = 3, D = 8, H = 22, M = 48, S = 43
2019-03-14 19:35:12.454 New earliest timestamp 08/03/2019 22:48:43
2019-03-14 19:35:12.876 Get next log - RDLG,1
2019-03-14 19:35:13.298 rdlg,138725,1,600,22:58:40,08/03/2019,4.6,5.0,4.7,,,,69.9,71.8,70.8,988.2,988.4,988.2,0.0,12.9,3.9,235,427.86,201.08,87
2019-03-14 19:35:13.298 Logger entry zero: Y = 2019, M = 3, D = 8, H = 22, M = 58, S = 40
2019-03-14 19:35:13.298 New earliest timestamp 08/03/2019 22:58:40
2019-03-14 19:35:13.719 Get next log - RDLG,1
2019-03-14 19:35:14.141 rdlg,138726,1,600,23:08:38,08/03/2019,4.5,5.0,4.7,,,,69.3,72.1,70.5,988.3,988.5,988.3,0.0,13.0,2.6,251,427.86,201.08,110
2019-03-14 19:35:14.141 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 8, S = 38
2019-03-14 19:35:14.141 New earliest timestamp 08/03/2019 23:08:38
2019-03-14 19:35:14.563 Get next log - RDLG,1
2019-03-14 19:35:14.985 rdlg,138727,1,600,23:18:36,08/03/2019,4.4,4.9,4.6,,,,69.9,72.5,71.1,988.2,988.3,988.2,0.0,8.5,2.0,265,427.86,201.08,141
2019-03-14 19:35:14.985 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 18, S = 36
2019-03-14 19:35:14.985 New earliest timestamp 08/03/2019 23:18:36
2019-03-14 19:35:15.406 Get next log - RDLG,1
2019-03-14 19:35:15.828 rdlg,138728,1,600,23:28:33,08/03/2019,4.5,4.8,4.6,,,,70.7,73.0,72.0,988.3,988.4,988.3,0.0,8.7,2.1,228,427.86,201.08,151
2019-03-14 19:35:15.828 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 28, S = 33
2019-03-14 19:35:15.828 New earliest timestamp 08/03/2019 23:28:33
2019-03-14 19:35:16.242 Get next log - RDLG,1
2019-03-14 19:35:16.663 rdlg,138729,1,600,23:38:31,08/03/2019,4.6,5.0,4.7,,,,70.3,72.9,71.6,988.3,988.6,988.4,0.0,9.8,2.6,236,427.86,201.08,138
2019-03-14 19:35:16.663 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 38, S = 31
2019-03-14 19:35:16.663 New earliest timestamp 08/03/2019 23:38:31
2019-03-14 19:35:17.085 Get next log - RDLG,1
2019-03-14 19:35:17.507 rdlg,138730,1,600,23:48:29,08/03/2019,4.7,5.1,4.9,,,,70.2,72.2,71.1,988.5,988.7,988.6,0.0,12.5,2.8,254,427.86,201.08,101
2019-03-14 19:35:17.507 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 48, S = 29
2019-03-14 19:35:17.507 New earliest timestamp 08/03/2019 23:48:29
2019-03-14 19:35:17.929 Get next log - RDLG,1
2019-03-14 19:35:18.350 rdlg,138731,1,600,23:58:27,08/03/2019,4.7,5.1,4.9,,,,70.4,72.2,71.4,988.7,988.8,988.7,0.0,9.6,2.5,256,427.86,201.08,134
2019-03-14 19:35:18.350 Logger entry zero: Y = 2019, M = 3, D = 8, H = 23, M = 58, S = 27
2019-03-14 19:35:18.350 New earliest timestamp 08/03/2019 23:58:27
2019-03-14 19:35:18.772 Get next log - RDLG,1
2019-03-14 19:35:19.194 rdlg,138732,1,600,00:08:25,09/03/2019,4.7,5.1,4.8,,,,69.3,72.0,71.0,988.7,988.8,988.7,0.0,10.0,2.9,267,427.86,201.08,104
2019-03-14 19:35:19.194 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 8, S = 25
2019-03-14 19:35:19.194 New earliest timestamp 09/03/2019 00:08:25
2019-03-14 19:35:19.616 Get next log - RDLG,1
2019-03-14 19:35:20.038 rdlg,138733,1,600,00:18:23,09/03/2019,4.7,5.1,4.8,,,,69.4,71.8,70.4,988.7,988.9,988.7,0.0,12.8,3.3,340,427.86,201.08,95
2019-03-14 19:35:20.038 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 18, S = 23
2019-03-14 19:35:20.038 New earliest timestamp 09/03/2019 00:18:23
2019-03-14 19:35:20.459 Get next log - RDLG,1
2019-03-14 19:35:20.881 rdlg,138734,1,600,00:28:20,09/03/2019,4.7,5.0,4.8,,,,69.7,71.5,70.7,988.6,988.8,988.6,0.0,8.5,2.6,229,427.86,201.08,135
2019-03-14 19:35:20.881 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 28, S = 20
2019-03-14 19:35:20.881 New earliest timestamp 09/03/2019 00:28:20
2019-03-14 19:35:21.290 Get next log - RDLG,1
2019-03-14 19:35:21.696 rdlg,138735,1,600,00:38:18,09/03/2019,4.6,4.9,4.7,,,,70.0,72.0,71.1,988.5,988.7,988.6,0.0,11.7,3.2,275,427.86,201.08,104
2019-03-14 19:35:21.696 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 38, S = 18
2019-03-14 19:35:21.696 New earliest timestamp 09/03/2019 00:38:18
2019-03-14 19:35:22.117 Get next log - RDLG,1
2019-03-14 19:35:22.539 rdlg,138736,1,600,00:48:16,09/03/2019,4.5,4.9,4.7,,,,70.2,72.5,71.2,988.7,988.9,988.7,0.0,14.4,4.9,253,427.86,201.08,88
2019-03-14 19:35:22.539 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 48, S = 16
2019-03-14 19:35:22.539 New earliest timestamp 09/03/2019 00:48:16
2019-03-14 19:35:22.956 Get next log - RDLG,1
2019-03-14 19:35:23.378 rdlg,138737,1,600,00:58:14,09/03/2019,4.3,4.7,4.4,,,,71.1,74.2,72.7,988.9,989.1,988.9,0.0,13.4,3.3,254,427.86,201.08,100
2019-03-14 19:35:23.378 Logger entry zero: Y = 2019, M = 3, D = 9, H = 0, M = 58, S = 14
2019-03-14 19:35:23.378 New earliest timestamp 09/03/2019 00:58:14
2019-03-14 19:35:23.800 Get next log - RDLG,1
2019-03-14 19:35:24.221 rdlg,138738,1,600,01:08:12,09/03/2019,4.2,4.5,4.3,,,,71.1,73.6,72.6,988.9,989.1,989.0,0.0,13.3,3.5,269,427.86,201.08,108
2019-03-14 19:35:24.221 Logger entry zero: Y = 2019, M = 3, D = 9, H = 1, M = 8, S = 12
2019-03-14 19:35:24.221 New earliest timestamp 09/03/2019 01:08:12
2019-03-14 19:35:24.643 Get next log - RDLG,1
2019-03-14 19:35:25.065 rdlg,138739,1,600,01:18:10,09/03/2019,4.1,4.5,4.3,,,,70.3,72.2,71.2,988.9,989.1,989.0,0.0,10.1,3.7,260,427.86,201.08,130
2019-03-14 19:35:25.065 Logger entry zero: Y = 2019, M = 3, D = 9, H = 1, M = 18, S = 10
2019-03-14 19:35:25.065 New earliest timestamp 09/03/2019 01:18:10
2019-03-14 19:35:25.487 Get next log - RDLG,1
2019-03-14 19:35:25.908 rdlg,138724,1,600,22:48:43,08/03/2019,4.5,4.9,4.7,,,,70.0,72.2,71.0,987.9,988.2,988.0,0.0,14.9,3.7,252,427.86,201.08,107
2019-03-14 19:35:25.908 Logger entry zero: Y = 2019, M = 3, D = 8, H = 22, M = 48, S = 43
2019-03-14 19:35:25.908 New earliest timestamp 08/03/2019 22:48:43
2019-03-14 19:35:26.322 Get next log - RDLG,1
2019-03-14 19:35:26.744 rdlg,138725,1,600,22:58:40,08/03/2019,4.6,5.0,4.7,,,,69.9,71.8,70.8,988.2,988.4,988.2,0.0,12.9,3.9,235,427.86,201.08,87
2019-03-14 19:35:26.744 Logger entry zero: Y = 2019, M = 3, D = 8, H = 22, M = 58, S = 40
2019-03-14 19:35:26.744 New earliest timestamp 08/03/2019 22:58:40

Does anyone recognise this behaviour?

[seggins]

Have done a few short test (about 1 hour) and restarts.
All worked exactly a they should!!
Have been in touch with Instromet and they are checking with their design engineer to find out what was going and why the fault no longer is occurring.
Will report back......

[mcrossley]

No idea why, but this is the second Instromet logger recently that returns odd values when Cumulus requests the catch-up records. Cumulus is just asking for the next record and the logger controls what is sent.

[seggins]

I have some thoughts from the Instromet engineer:

Please see our electronic engineers comments below. It looks likely to be software related and you may need to post to the Cumulus forum for further help.

I've had a look at the file, and I have a few thoughts:

Firstly, this can't be showing exactly how the software is talking to the datalogger. the RDLG,n command will read the oldest log, but it doesn't move the pointer forwards - you need to follow it with PRLG,n (progress log). The idea being that if you receive a corrupted log, you can request the same one(s) again. The PRLG command does not appear anywhere in the file. However, if the software just kept executing RDLG,1 it would keep reading the same single log, where what I'm seeing is a repeated block of 16 (138724-138739). This would be consistent with the software actually calling RDLG,16 and no PRLG,16 to follow it. This is more likely, as RDLG,1 is going to be extremely slow! This is just a possible extrapolation of the missing data in the PC log file.

Alternatively, if the PC does call PRLG,1 after every RDLG,1, but just isn't showing it in the file, then it looks like the logger is stuck repeating the same block of 16 entries. This would be an unusual, but not impossible, failure of the dataflash chip. However, you say that the unit is now working okay again? I'd be extremely surprised if the dataflash chip just "got better" by itself!

I can't think of anything else, but if they're working on the Cumulus software, it would be nice if they could get the PC log file to show all of the serial communication...!

Hope this is of use
Regards
John

[mcrossley]

Can you post the whole log instead on a snippet please.
The code does progress the log and log the command normally, so maybe something has gone wrong earlier in the log you posted a bit of.
See below, it only logs the progress log pointer commands if debug logging is enabled.

[mcrossley]

Actually, looking at that log again I see that debug logging is NOT enabled, the "PRLG,1" commands are only logged if that is enabled.
When diagnosing issues with protocols and data its always best to enable debug logging.

It makes sense that the PRLG,1 commands are being sent otherwise the logger would always return the same entry, which it does not, it is looping around the same entries.

And this code does work perfectly with other peoples Instroment loggers, I still remain convinced its a hardware problem.

[seggins]

3048 logging failed again this morning.
I am attaching three diagnostic files.
Some strange things are happening.....
Regards
John

[mcrossley]

You haven't switched on debug logging so you are still only capturing part of what is going on, but...

The first log looks OK to me, but it doesn't have to read any logger history on startup.

The second log does read the logger history, and it all goes fine until it gets to record 143412, then when asked for the next record the logger returns 143397 instead of 143413. And so the loop starts.

I don't know what you want me to do, the logger isn't working properly, Cumulus MX is.

If the logger cannot be reset, then I think your only hope is to leave Cumulus running long enough to write to every logger location and hope that sorts it. You could set the logging to 1 minute intervals to speed that up. How many logger entries does it hold?

[seggins]

Many thanks Mike. I think your diagnosis is correct and the memory chip has some issues. I have sent diag files to Instromet too. Just thought I should keep you in the loop.
Regards
John

[mcrossley]

Just remember your logs are missing all the commands sent because debug logging is not enabled. With debug enabled it will log each command sent, not just a summary of what is happening.