Current log damaged

Support
1

Hi Bob, from my IotaWatt the current log was apparently damaged. It deleted the current log file and created a diagnostic file. Thank you for the IotaWatt’s ability to free itself from such a situation. However, I would like to know what could have led to this problem. Can you see a hint why the log could be damaged?

iotalog:

SD initialized.
3/19/19 05:03:13z Real Time Clock is running. Unix time 1552971793 
3/19/19 05:03:13z Reset reason: Software/System restart
3/19/19 05:03:13z Trace:  1:3, 1:4, 1:5[20], 20:0, 20:1, 20:2, 20:3, 20:4, 20:42, 1:6, 1:1[14], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3, 1:4, 1:5[20], 20:0, 20:1, 20:2, 20:3, 20:4, 20:42, 1:6, 1:3, 1:4, 1:5[21]
3/19/19 05:03:13z ESP8266 ChipID: 7283597
3/19/19 05:03:13z IoTaWatt 4.x, Firmware version 02_04_00
3/19/19 05:03:13z SPIFFS mounted.
3/19/19 05:03:14z Local time zone: +0:00
3/19/19 05:03:15z device name: IotaWatt
3/19/19 05:03:15z MDNS responder started for hostname IotaWatt
3/19/19 05:03:15z LLMNR responder started for hostname IotaWatt
3/19/19 05:03:15z HTTP server started
3/19/19 05:03:15z timeSync: service started.
3/19/19 05:03:15z statService: started.
3/19/19 05:03:15z dataLog: service started.
3/19/19 05:03:16z dataLog: Last log entry 03/19/19 05:03:10
3/19/19 05:03:17z historyLog: service started.
3/19/19 05:03:18z historyLog: Last log entry 03/19/19 05:03:00
3/19/19 05:03:20z EmonService: started. url=my.rexometer.de:80, node=IotaWatt, interval=10, encrypted
3/19/19 05:03:20z influxDB: started, url=192.168.11.76:8086, db=iotawatt, interval=10
3/19/19 05:40:19z WiFi connected. SSID=rexoweb, IP=192.168.11.117, channel=6, RSSI -78db
3/19/19 05:40:19z Updater: service started. Auto-update class is ALPHA
3/19/19 05:40:19z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:40:22z Updater: Auto-update is current for class ALPHA.
3/19/19 05:40:23z EmonService: Start posting at 03/18/19 21:02:20
3/19/19 05:40:30z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:40:41z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:40:52z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:02z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:14z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:24z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:35z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:46z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:41:56z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:42:07z timesync: Kiss-o'-Death, code RATE, ip: 37.120.164.45
3/19/19 05:42:08z influxDB: last entry query failed: -4, retrying.
4/13/19 09:12:59z EmonService: HTTP response 502, retrying.
4/13/19 09:13:17z EmonService: Retry successful after 35 attempts.
4/21/19 21:25:17z influxDB: Start posting at 01/11/19 04:22:00
4/30/19 05:42:52z timeSync: Six week routine restart.

** Restart **

SD initialized.
4/30/19 05:42:53z Real Time Clock is running. Unix time 1556602973 
4/30/19 05:42:53z Reset reason: Software/System restart
4/30/19 05:42:53z Trace:  1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:3, 1:4, 1:5[20], 20:0, 20:1
4/30/19 05:42:53z ESP8266 ChipID: 7283597
4/30/19 05:42:53z IoTaWatt 4.x, Firmware version 02_04_00
4/30/19 05:42:53z SPIFFS mounted.
4/30/19 05:42:54z Local time zone: +0:00
4/30/19 05:42:55z device name: IotaWatt
4/30/19 05:42:55z MDNS responder started for hostname IotaWatt
4/30/19 05:42:55z LLMNR responder started for hostname IotaWatt
4/30/19 05:42:55z HTTP server started
4/30/19 05:42:55z WiFi connected. SSID=rexoweb, IP=192.168.11.117, channel=6, RSSI -72db
4/30/19 05:42:55z timeSync: service started.
4/30/19 05:42:55z statService: started.
4/30/19 05:42:55z Updater: service started. Auto-update class is ALPHA
4/30/19 05:42:55z dataLog: service started.
4/30/19 05:42:56z dataLog: Last log entry 04/30/19 05:42:50
4/30/19 05:42:57z historyLog: service started.
4/30/19 05:42:58z historyLog: Last log entry 04/30/19 05:42:00
4/30/19 05:42:59z Updater: Auto-update is current for class ALPHA.
4/30/19 05:43:00z EmonService: started. url=my.rexometer.de:80, node=IotaWatt, interval=10, encrypted
4/30/19 05:43:00z influxDB: started, url=192.168.11.76:8086, db=iotawatt, interval=10
4/30/19 05:43:01z influxDB: Start posting at 04/30/19 05:43:00
4/30/19 05:43:01z EmonService: Start posting at 04/30/19 05:42:50
5/01/19 19:46:47z Updater: Invalid response from server. HTTPcode: 301
5/15/19 13:19:58z Updater: Invalid response from server. HTTPcode: -11
5/16/19 04:05:39z influxDB: Post Failed: -11

** Restart **

SD initialized.
5/20/19 22:17:04z Real Time Clock is running. Unix time 1558390624 
5/20/19 22:17:04z Reset reason: Software Watchdog
5/20/19 22:17:04z Trace:  18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:3, 1:4, 1:5[7], 7:0, 7:7, 7:7
5/20/19 22:17:04z ESP8266 ChipID: 7283597
5/20/19 22:17:04z IoTaWatt 4.x, Firmware version 02_04_00
5/20/19 22:17:04z SPIFFS mounted.
5/20/19 22:17:05z Local time zone: +0:00
5/20/19 22:17:05z device name: IotaWatt
5/20/19 22:17:06z MDNS responder started for hostname IotaWatt
5/20/19 22:17:06z LLMNR responder started for hostname IotaWatt
5/20/19 22:17:06z HTTP server started
5/20/19 22:17:06z WiFi connected. SSID=rexoweb, IP=192.168.11.117, channel=6, RSSI -73db
5/20/19 22:17:06z timeSync: service started.
5/20/19 22:17:06z statService: started.
5/20/19 22:17:06z Updater: service started. Auto-update class is ALPHA
5/20/19 22:17:07z dataLog: service started.
5/20/19 22:17:09z IotaLog: file damaged iotawatt/iotalog.log

5/20/19 22:17:09z IotaLog: Creating diagnostic file.
5/20/19 23:36:02z IotaLog: Deleting iotawatt/iotalog.log and restarting.


** Restart **

SD initialized.
5/20/19 23:36:06z Real Time Clock is running. Unix time 1558395366 
5/20/19 23:36:06z Reset reason: Software/System restart
5/20/19 23:36:06z Trace:  1:2[4], 9:0[4], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:4, 1:5[5], 1:6, 1:1[4], 1:2[11], 9:0[11], 9:0, 9:1, 8:4, 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:4, 1:5[19]
5/20/19 23:36:06z ESP8266 ChipID: 7283597
5/20/19 23:36:06z IoTaWatt 4.x, Firmware version 02_04_00
5/20/19 23:36:06z SPIFFS mounted.
5/20/19 23:36:07z Local time zone: +0:00
5/20/19 23:36:07z device name: IotaWatt
5/20/19 23:36:08z MDNS responder started for hostname IotaWatt
5/20/19 23:36:08z LLMNR responder started for hostname IotaWatt
5/20/19 23:36:08z HTTP server started
5/20/19 23:36:08z WiFi connected. SSID=rexoweb, IP=192.168.11.117, channel=6, RSSI -75db
5/20/19 23:36:08z timeSync: service started.
5/20/19 23:36:08z statService: started.
5/20/19 23:36:08z Updater: service started. Auto-update class is ALPHA
5/20/19 23:36:09z dataLog: service started.
5/20/19 23:36:09z dataLog: New current log created.
5/20/19 23:36:10z dataLog: Last history entry: 05/20/19 22:16:00
5/20/19 23:36:11z Updater: Auto-update is current for class ALPHA.
5/20/19 23:36:13z EmonService: started. url=my.rexometer.de:80, node=IotaWatt, interval=10, encrypted
5/20/19 23:36:13z influxDB: started, url=192.168.11.76:8086, db=iotawatt, interval=10
5/20/19 23:36:14z EmonService: Start posting at 01/01/70 00:00:10
5/20/19 23:36:14z influxDB: Start posting at 05/20/19 22:16:00
5/20/19 23:38:10z historyLog: service started.
5/20/19 23:38:10z historyLog: Last log entry 05/20/19 22:16:00
5/22/19 00:38:55z Updater: Invalid response from server. HTTPcode: -11

logdiag.txt

5/20/19 22:17:09
filesize 1614643200, entries 6307200
1558098100,6307200,1558390610,6365702
1529611350,610313,1529611350,610313
1524815910,58504,1524860105,67343
1524925710,67344,1524930980,68398
1526901780,68399,1547978930,4283829
1547981250,4283830,1558098095,6307199
End of file

56

2

Nice problem. I’m glad the diagnostics and recovery worked. Here’s what it looks like to me.

The IoTaWatt took a software watchdog exception while trying to read the latest record from the current log to post that data to influxDB. It hung while trying to read the latest record on Monday, 20-May.

Your log had wrapped, which is normal. When the current log gets to a certain size, it wraps around and starts writing over old entries. I don’t know when you installed this system but the history log begins at May 24, 2018 and that would have been the start of the current log as well. When it wrapped on May 17 of this year, it started overwriting the 2018 entries. That was just a little over three days ago. Hard to dismiss that coincidence.

There was a stray current log entry at the wrap point. It was an entry from June 21, 2018. ALPHA updated from 02_03_07 to 02_03_08 on that date. This record was from 20:02:30. If you have the complete message log, can you post the activity surrounding that date? Auto-updates can take a few hours to propagate, so that may be when your system updated and restarted.

Anyway, after the wrap, IoTaWatt must find the wrap point after restart, and that algorithm can fail if there are bad records. This is the only bad record in the log. Point is that the bad record could have been there for eleven months but became significant when the wrap detection logic was activated.

If there is some underlying problem with wrap, I think I would have seen it in my own test systems over the past six months. They wrapped every week for months without issue. That said, more and more systems will be wrapping as time passes, and whether it is old damage or something new, I’m glad to have the robust recovery.

Except for the 1.5 hours it took to create the diagnostic file, you should have recovered fully. The history log will support all local inquiries down to 1 minute resolution, and you already have 4 days of new current log at 5 second intervals.

Let me know if you have that June 21 message log.

1 Like
3

I’m impressed with what you can see in the data. Thanks for the explanations, I’m glad it’s not an SD card problem.

Here are the iotamsg entries from June 21, 2018:

6/20/18 06:11:49z EmonService: response not ok. Retrying.
6/20/18 06:11:50z EmonService: response not ok. Retrying.
6/20/18 06:11:51z EmonService: response not ok. Retrying.
6/20/18 06:11:52z EmonService: response not ok. Retrying.
6/20/18 06:11:53z EmonService: response not ok. Retrying.
6/20/18 06:11:54z EmonService: response not ok. Retrying.
6/20/18 06:11:55z EmonService: response not ok. Retrying.
6/20/18 06:11:56z EmonService: response not ok. Retrying.
6/20/18 06:11:57z EmonService: response not ok. Retrying.
6/20/18 17:16:36z EmonService: retry count 10
6/20/18 17:17:03z EmonService: retry count 20
6/20/18 17:17:30z EmonService: retry count 30
6/20/18 17:17:57z EmonService: retry count 40
6/20/18 17:18:27z EmonService: retry count 50
6/20/18 17:18:57z EmonService: retry count 60
6/20/18 21:00:23z timeSync: adjusting RTC by -2
6/21/18 19:01:02z Updater: Update from 02_03_07 to 02_03_08
6/21/18 19:01:02z Updater: download 02_03_08
6/21/18 19:01:31z Updater: Download failed HTTPcode 
6/21/18 20:01:32z Updater: Update from 02_03_07 to 02_03_08
6/21/18 20:01:32z Updater: download 02_03_08
6/21/18 20:02:21z Updater: Download failed HTTPcode 

** Restart **

SD initialized.
6/21/18 20:02:53z Real Time Clock is running. Unix time 1529611373 
6/21/18 20:02:53z Version 02_03_07
6/21/18 20:02:53z Reset reason: Software Watchdog
6/21/18 20:02:53z Trace:  18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:3, 1:4, 1:5, 1:6, 1:3, 1:4, 1:5, 3:0, 3:6, 3:6
6/21/18 20:02:53z ESP8266 ChipID: 7283597
6/21/18 20:02:53z Local time zone: 0
6/21/18 20:02:53z device name: IotaWatt, version: 3
6/21/18 20:02:54z MDNS responder started
6/21/18 20:02:54z You can now connect to http://IotaWatt.local
6/21/18 20:02:54z HTTP server started
6/21/18 20:02:55z dataLog: service started.
6/21/18 20:02:55z dataLog: Last log entry: 1529611320
6/21/18 20:02:55z statService: started.
6/21/18 20:02:55z timeSync: service started.
6/21/18 20:02:55z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
6/21/18 20:02:55z Updater: started.
6/21/18 20:02:55z historyLog: service started.
6/21/18 20:02:56z historyLog: Last log entry 1529611320
6/21/18 20:02:56z EmonService: started. url:192.168.11.76:80/emoncms,node:IotaWatt,interval:10, unsecure GET
6/21/18 20:02:56z EmonService: Start posting at 6/21/18 20:02:10 
6/21/18 20:02:56z Updater: Update from 02_03_07 to 02_03_08
6/21/18 20:02:56z Updater: download 02_03_08
6/21/18 20:03:14z Updater: Download failed HTTPcode 
6/21/18 21:03:15z Updater: Update from 02_03_07 to 02_03_08
6/21/18 21:03:15z Updater: download 02_03_08
6/21/18 21:03:44z Updater: Download failed HTTPcode 
6/21/18 21:03:50z EmonService: response not ok. Retrying.
6/21/18 21:03:51z EmonService: response not ok. Retrying.
6/21/18 21:03:52z EmonService: response not ok. Retrying.
6/21/18 21:03:53z EmonService: response not ok. Retrying.
6/21/18 21:03:54z EmonService: response not ok. Retrying.
6/21/18 21:03:55z EmonService: response not ok. Retrying.
6/21/18 21:03:56z EmonService: response not ok. Retrying.
6/21/18 21:03:57z EmonService: response not ok. Retrying.
6/21/18 21:03:58z EmonService: response not ok. Retrying.
6/21/18 21:03:59z EmonService: response not ok. Retrying.
6/21/18 21:04:00z EmonService: response not ok. Retrying.
6/21/18 21:04:01z EmonService: response not ok. Retrying.
6/21/18 21:04:02z EmonService: response not ok. Retrying.
6/21/18 21:04:03z EmonService: response not ok. Retrying.
6/21/18 21:04:04z EmonService: response not ok. Retrying.
6/21/18 21:04:05z EmonService: response not ok. Retrying.
6/21/18 21:04:06z EmonService: response not ok. Retrying.
6/21/18 21:04:07z EmonService: response not ok. Retrying.
6/21/18 21:04:08z EmonService: response not ok. Retrying.
6/21/18 21:04:09z EmonService: response not ok. Retrying.
6/21/18 21:04:10z EmonService: response not ok. Retrying.
6/21/18 21:04:11z EmonService: response not ok. Retrying.
6/21/18 21:04:12z EmonService: response not ok. Retrying.
6/21/18 21:04:13z EmonService: response not ok. Retrying.
6/21/18 21:04:14z EmonService: response not ok. Retrying.
6/21/18 21:04:15z EmonService: response not ok. Retrying.
6/21/18 21:04:16z EmonService: response not ok. Retrying.
6/21/18 21:04:17z EmonService: response not ok. Retrying.
6/21/18 21:04:18z EmonService: response not ok. Retrying.
6/21/18 21:04:19z EmonService: response not ok. Retrying.
6/21/18 21:04:20z EmonService: response not ok. Retrying.
6/21/18 21:04:21z EmonService: response not ok. Retrying.
6/21/18 21:04:22z EmonService: response not ok. Retrying.
6/21/18 21:04:23z EmonService: response not ok. Retrying.
6/21/18 21:04:24z EmonService: response not ok. Retrying.
6/21/18 21:04:25z EmonService: response not ok. Retrying.
6/21/18 21:04:26z EmonService: response not ok. Retrying.
6/21/18 21:04:27z EmonService: response not ok. Retrying.
6/21/18 21:04:28z EmonService: response not ok. Retrying.
6/21/18 21:04:29z EmonService: response not ok. Retrying.
6/21/18 21:04:30z EmonService: response not ok. Retrying.
6/21/18 21:04:31z EmonService: response not ok. Retrying.
6/21/18 21:04:32z EmonService: response not ok. Retrying.
6/21/18 21:04:33z EmonService: response not ok. Retrying.
6/21/18 21:04:34z EmonService: response not ok. Retrying.
6/21/18 21:04:35z EmonService: response not ok. Retrying.
6/21/18 21:04:36z EmonService: response not ok. Retrying.
6/21/18 21:04:37z EmonService: response not ok. Retrying.
6/21/18 21:04:38z EmonService: response not ok. Retrying.
6/21/18 21:04:39z EmonService: response not ok. Retrying.
6/21/18 21:04:40z EmonService: response not ok. Retrying.
6/21/18 21:04:41z EmonService: response not ok. Retrying.
6/21/18 21:04:42z EmonService: response not ok. Retrying.
6/21/18 21:04:43z EmonService: response not ok. Retrying.
6/21/18 21:04:44z EmonService: response not ok. Retrying.
6/21/18 21:04:45z EmonService: response not ok. Retrying.
6/21/18 21:04:46z EmonService: response not ok. Retrying.
6/21/18 21:04:47z EmonService: response not ok. Retrying.
6/21/18 21:04:48z EmonService: response not ok. Retrying.
6/21/18 21:04:49z EmonService: response not ok. Retrying.
6/21/18 21:04:50z EmonService: response not ok. Retrying.
6/21/18 21:04:51z EmonService: response not ok. Retrying.
6/21/18 21:04:52z EmonService: response not ok. Retrying.
6/21/18 21:04:53z EmonService: response not ok. Retrying.
6/21/18 21:04:54z EmonService: response not ok. Retrying.
6/21/18 21:04:55z EmonService: response not ok. Retrying.
6/21/18 21:04:56z EmonService: response not ok. Retrying.
6/21/18 21:04:57z EmonService: response not ok. Retrying.
6/21/18 21:04:58z EmonService: response not ok. Retrying.
6/21/18 21:04:59z EmonService: response not ok. Retrying.
6/21/18 21:05:00z EmonService: response not ok. Retrying.
6/21/18 21:05:01z EmonService: response not ok. Retrying.
6/21/18 21:05:02z EmonService: response not ok. Retrying.
6/21/18 21:05:03z EmonService: response not ok. Retrying.
6/21/18 21:05:04z EmonService: response not ok. Retrying.
6/21/18 21:05:05z EmonService: response not ok. Retrying.
6/21/18 21:05:06z EmonService: response not ok. Retrying.
6/21/18 21:05:07z EmonService: response not ok. Retrying.
6/21/18 21:05:08z EmonService: response not ok. Retrying.
6/21/18 21:05:09z EmonService: response not ok. Retrying.
6/21/18 21:05:10z EmonService: response not ok. Retrying.
6/21/18 21:05:11z EmonService: response not ok. Retrying.
6/21/18 21:05:12z EmonService: response not ok. Retrying.
6/21/18 21:05:13z EmonService: response not ok. Retrying.
6/21/18 21:05:14z EmonService: response not ok. Retrying.
6/21/18 21:05:15z EmonService: response not ok. Retrying.
6/21/18 21:05:16z EmonService: response not ok. Retrying.
6/21/18 21:05:17z EmonService: response not ok. Retrying.
6/21/18 21:05:18z EmonService: response not ok. Retrying.
6/21/18 21:05:19z EmonService: response not ok. Retrying.
6/21/18 21:05:20z EmonService: response not ok. Retrying.
6/21/18 21:05:21z EmonService: response not ok. Retrying.
6/21/18 21:05:22z EmonService: response not ok. Retrying.
6/21/18 21:05:23z EmonService: response not ok. Retrying.
6/21/18 21:05:24z EmonService: response not ok. Retrying.
6/21/18 21:05:25z EmonService: response not ok. Retrying.
6/21/18 21:05:26z EmonService: response not ok. Retrying.
6/21/18 21:05:27z EmonService: response not ok. Retrying.
6/21/18 21:05:28z EmonService: response not ok. Retrying.
6/21/18 21:05:29z EmonService: response not ok. Retrying.
6/21/18 22:03:45z Updater: Update from 02_03_07 to 02_03_08
6/21/18 22:03:45z Updater: download 02_03_08
6/21/18 22:04:31z Updater: Release downloaded 46143ms, size 630304
6/21/18 22:04:43z Updater: Signature does not verify.
6/21/18 22:04:43z EmonService: response not ok. Retrying.
6/21/18 22:04:44z EmonService: response not ok. Retrying.
6/21/18 22:04:45z EmonService: response not ok. Retrying.
6/21/18 22:04:46z EmonService: response not ok. Retrying.
6/21/18 22:04:47z EmonService: response not ok. Retrying.
6/21/18 22:04:48z EmonService: response not ok. Retrying.
6/21/18 22:04:49z EmonService: response not ok. Retrying.
6/21/18 22:04:50z EmonService: response not ok. Retrying.
6/21/18 22:04:51z EmonService: response not ok. Retrying.
6/21/18 22:04:52z EmonService: response not ok. Retrying.
6/21/18 22:04:53z EmonService: response not ok. Retrying.
6/21/18 22:04:54z EmonService: response not ok. Retrying.
6/21/18 22:04:55z EmonService: response not ok. Retrying.
6/21/18 22:04:56z EmonService: response not ok. Retrying.
6/21/18 22:04:57z EmonService: response not ok. Retrying.
6/21/18 22:04:58z EmonService: response not ok. Retrying.
6/21/18 22:04:59z EmonService: response not ok. Retrying.
6/21/18 22:05:00z EmonService: response not ok. Retrying.
6/21/18 22:05:01z EmonService: response not ok. Retrying.
6/21/18 22:05:02z EmonService: response not ok. Retrying.
6/21/18 22:05:03z EmonService: response not ok. Retrying.
6/21/18 22:05:04z EmonService: response not ok. Retrying.
6/21/18 22:05:05z EmonService: response not ok. Retrying.
6/21/18 22:05:06z EmonService: response not ok. Retrying.
6/21/18 22:05:07z EmonService: response not ok. Retrying.
6/21/18 22:05:08z EmonService: response not ok. Retrying.
6/21/18 22:05:09z EmonService: response not ok. Retrying.
6/21/18 22:05:10z EmonService: response not ok. Retrying.
6/21/18 22:05:11z EmonService: response not ok. Retrying.
6/21/18 22:05:12z EmonService: response not ok. Retrying.
6/21/18 22:05:13z EmonService: response not ok. Retrying.
6/21/18 22:05:14z EmonService: response not ok. Retrying.
6/21/18 22:05:15z EmonService: response not ok. Retrying.
6/21/18 22:05:16z EmonService: response not ok. Retrying.
6/21/18 22:05:17z EmonService: response not ok. Retrying.
6/21/18 22:05:18z EmonService: response not ok. Retrying.
6/21/18 22:05:19z EmonService: response not ok. Retrying.
6/21/18 22:05:20z EmonService: response not ok. Retrying.
6/21/18 22:05:21z EmonService: response not ok. Retrying.
6/21/18 22:05:22z EmonService: response not ok. Retrying.
6/21/18 22:05:23z EmonService: response not ok. Retrying.
6/21/18 22:05:24z EmonService: response not ok. Retrying.
6/21/18 22:05:25z EmonService: response not ok. Retrying.
6/21/18 22:05:26z EmonService: response not ok. Retrying.
6/21/18 22:05:27z EmonService: response not ok. Retrying.
6/21/18 22:05:28z EmonService: response not ok. Retrying.
6/21/18 22:05:29z EmonService: response not ok. Retrying.
6/21/18 22:05:30z EmonService: response not ok. Retrying.
6/21/18 22:05:31z EmonService: response not ok. Retrying.
6/21/18 22:05:32z EmonService: response not ok. Retrying.
6/21/18 22:05:33z EmonService: response not ok. Retrying.
6/21/18 22:05:34z EmonService: response not ok. Retrying.
6/21/18 22:05:35z EmonService: response not ok. Retrying.
6/21/18 22:05:36z EmonService: response not ok. Retrying.
6/21/18 22:05:37z EmonService: response not ok. Retrying.
6/21/18 22:05:38z EmonService: response not ok. Retrying.
6/21/18 22:05:39z EmonService: response not ok. Retrying.
6/21/18 22:05:40z EmonService: response not ok. Retrying.
6/21/18 22:05:41z EmonService: response not ok. Retrying.
6/21/18 22:05:42z EmonService: response not ok. Retrying.
6/21/18 22:05:43z EmonService: response not ok. Retrying.
6/21/18 22:05:44z EmonService: response not ok. Retrying.
6/21/18 22:05:45z EmonService: response not ok. Retrying.
6/21/18 22:05:46z EmonService: response not ok. Retrying.
6/21/18 22:05:47z EmonService: response not ok. Retrying.
6/21/18 22:05:48z EmonService: response not ok. Retrying.
6/21/18 22:05:49z EmonService: response not ok. Retrying.
6/21/18 22:05:50z EmonService: response not ok. Retrying.
6/21/18 22:05:51z EmonService: response not ok. Retrying.
6/21/18 22:05:52z EmonService: response not ok. Retrying.
6/21/18 22:05:53z EmonService: response not ok. Retrying.
6/21/18 22:05:54z EmonService: response not ok. Retrying.
6/21/18 22:05:55z EmonService: response not ok. Retrying.
6/21/18 22:05:56z EmonService: response not ok. Retrying.
6/21/18 22:05:57z EmonService: response not ok. Retrying.
6/21/18 22:05:58z EmonService: response not ok. Retrying.
6/21/18 22:05:59z EmonService: response not ok. Retrying.
6/21/18 22:06:00z EmonService: response not ok. Retrying.
6/21/18 22:06:01z EmonService: response not ok. Retrying.
6/21/18 22:06:02z EmonService: response not ok. Retrying.
6/21/18 22:06:03z EmonService: response not ok. Retrying.
6/21/18 22:06:04z EmonService: response not ok. Retrying.
6/21/18 22:06:05z EmonService: response not ok. Retrying.
6/21/18 22:06:06z EmonService: response not ok. Retrying.
6/21/18 22:06:07z EmonService: response not ok. Retrying.
6/21/18 22:06:08z EmonService: response not ok. Retrying.
6/21/18 22:06:09z EmonService: response not ok. Retrying.
6/21/18 22:06:10z EmonService: response not ok. Retrying.
6/21/18 22:06:11z EmonService: response not ok. Retrying.
6/21/18 22:06:12z EmonService: response not ok. Retrying.
6/21/18 22:06:13z EmonService: response not ok. Retrying.
6/21/18 22:06:14z EmonService: response not ok. Retrying.
6/21/18 22:06:15z EmonService: response not ok. Retrying.
6/21/18 22:06:16z EmonService: response not ok. Retrying.
6/21/18 22:06:17z EmonService: response not ok. Retrying.
6/21/18 22:06:18z EmonService: response not ok. Retrying.
6/21/18 22:06:19z EmonService: response not ok. Retrying.
6/21/18 22:06:20z EmonService: response not ok. Retrying.
6/21/18 22:06:21z EmonService: response not ok. Retrying.
6/21/18 22:06:22z EmonService: response not ok. Retrying.
6/21/18 23:04:44z Updater: Update from 02_03_07 to 02_03_08
6/21/18 23:04:44z Updater: download 02_03_08
6/21/18 23:05:28z Updater: Release downloaded 43447ms, size 630304
6/21/18 23:05:39z Updater: Update downloaded and signature verified
6/21/18 23:05:46z Updater: firmware upgraded to version 02_03_08
6/21/18 23:05:46z Firmware updated, restarting.

** Restart **

SD initialized.
6/21/18 23:05:53z Real Time Clock is running. Unix time 1529622353 
6/21/18 23:05:53z Version 02_03_08
6/21/18 23:05:53z Updater: Installing update files for version 02_03_08
6/21/18 23:05:53z Updater: Installing GRAPH.HTM
6/21/18 23:05:53z Updater: Installing GRAPH.JS
6/21/18 23:05:53z Updater: Installing INDEX.HTM
6/21/18 23:05:54z Updater: Installing TABLES.TXT
6/21/18 23:05:54z Updater: Installing CNFSTYLE.CSS
6/21/18 23:05:54z Updater: Installing EDIT.HTM
6/21/18 23:05:55z Updater: Installation complete.
6/21/18 23:05:55z Reset reason: Software/System restart
6/21/18 23:05:55z Trace:  18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:2, 18:3, 18:4, 18:5, 1:6, 1:1, 9:0, 8:4, 8:6, 8:8, 1:2, 1:3, 1:4, 1:5, 1:6, 1:3, 1:4, 1:5
6/21/18 23:05:55z ESP8266 ChipID: 7283597
6/21/18 23:05:55z Local time zone: 0
6/21/18 23:05:55z device name: IotaWatt, version: 3
6/21/18 23:05:58z Connecting with WiFiManager.
6/21/18 23:06:03z MDNS responder started
6/21/18 23:06:03z You can now connect to http://IotaWatt.local
6/21/18 23:06:03z HTTP server started
6/21/18 23:06:03z dataLog: service started.
6/21/18 23:06:03z dataLog: Last log entry 6/21/18 23:05:25 
6/21/18 23:06:03z statService: started.
6/21/18 23:06:03z timeSync: service started.
6/21/18 23:06:04z WiFi connected. SSID: rexoweb, IP: 192.168.11.117
6/21/18 23:06:04z Updater: service started. Auto-update class is ALPHA
6/21/18 23:06:04z historyLog: service started.
6/21/18 23:06:04z historyLog: Last log entry 6/21/18 23:05:00 
6/21/18 23:06:05z updater: Auto-update is current for class ALPHA.
6/21/18 23:06:08z EmonService: started. url:192.168.11.76:80/emoncms,node:IotaWatt,interval:10, unsecure GET
6/21/18 23:06:09z EmonService: Start posting at 6/21/18 23:05:20 
6/24/18 01:07:23z timeSync: adjusting RTC by -2
6/25/18 23:00:04z WiFi disconnected.
6/26/18 00:00:04z WiFi disconnected more than 60 minutes, restarting.

** Restart **
4

It was a rocky update. I’m putting my money on that, but I cannot rule out an SDcard problem.

5

The errant datalog entry was for 6/21/2008 20:02:30z. The log shows that a download failed at 20:02:21z and then the IoTaWatt took a software watchdog restart at 20:02:53.

image
image.png836×332 20.6 KB

Back then, the download of a software update was done asynchronously with the release file written to SDcard. Other processes were allowed to run during the wait time, and it was later discovered that activity to the datalog could be corrupted if written to during this time. That was changed in a later release. Update download happens so infrequently that it is reasonable to quiesce the processes and concentrate on achieving the download. This change resulted in remarkable improvement in download integrity. (More recently, adding the Cloudflare global cache has improved it even further).

But it appears the damage was done to your system during that instant on 6/21/2008 20:02:30z and it was just a time-bomb waiting to go off after the datalog wrapped.

This issue bodes poorly for other systems with datalogs going back to the pre-quiescent update download. So there may be others that trip over this problem in the coming months. I’ll look to see if I can add some code to detect and skip any such misplaced entries.

1 Like