My graphs seem to have disappeared

[frogmore]

I went to look at the graphs on my device are not showing any data. Here is what the end of the log shows:

** Restart **

No clock yet: SD initialized.
4/7/18 13:50:35 Real Time Clock is running. Unix time: 1523109035
4/7/18 13:50:35 Power failure detected.
4/7/18 13:50:35 Version: 02_02_30
4/7/18 13:50:35 Reset reason: External System
4/7/18 13:50:35 Trace: 803,19632,58597,37626,5579,22928,8523,19957,41425,59533,65505,23104,61099,15338,14985,14958,53691,9460,41050,60678,26864,42296,2659,42668,41614,51051,33051,10267,1134,22156,47736,59293
4/7/18 13:50:35 ESP8266 ChipID:2222239
4/7/18 05:50:35 device name: IotaWatt, version: 3
4/7/18 05:50:35 Local time zone: -8
4/7/18 05:50:43 checkUpdate: Invalid response from server.
4/7/18 05:50:43 MDNS responder started
4/7/18 05:50:43 You can now connect to http://IotaWatt.local
4/7/18 05:50:43 HTTP server started
4/7/18 05:50:44 dataLog: service started.
4/7/18 06:29:56 dataLog: Last log entry:3656990720
4/7/18 06:29:56 statService: started.
4/7/18 06:29:56 timeSync: service started.
4/7/18 06:29:56 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
4/7/18 06:30:01 checkUpdate: Invalid response from server.
4/7/18 06:35:38 timeSync: Failed to get NTPtime.
4/7/18 07:05:42 timeSync: Failed to get NTPtime.
4/7/18 16:00:00 timeSync: adjusting RTC by -2
4/8/18 19:00:00 timeSync: adjusting RTC by -2
4/8/18 22:11:13 WiFi disconnected.
4/8/18 22:16:15 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
4/9/18 21:00:00 timeSync: adjusting RTC by -2
4/10/18 20:00:00 timeSync: adjusting RTC by -2
4/12/18 00:00:00 timeSync: adjusting RTC by -2
4/13/18 01:00:00 timeSync: adjusting RTC by -2
4/13/18 22:05:42 timeSync: Failed to get NTPtime.
4/14/18 00:02:08 timeSync: adjusting RTC by -2
4/14/18 09:05:43 timeSync: Failed to get NTPtime.
4/14/18 10:05:43 timeSync: Failed to get NTPtime.
4/14/18 11:05:42 timeSync: Failed to get NTPtime.
4/14/18 12:05:42 timeSync: Failed to get NTPtime.
4/14/18 13:05:42 timeSync: Failed to get NTPtime.
4/14/18 22:00:00 timeSync: adjusting RTC by -2
4/15/18 18:30:06 checkUpdate: Invalid response from server.
4/15/18 21:00:00 timeSync: adjusting RTC by -2
4/16/18 23:01:01 timeSync: adjusting RTC by -2
4/17/18 04:59:59 timeSync: adjusting RTC by -2
4/17/18 06:00:02 timeSync: adjusting RTC by 2
4/18/18 00:00:05 timeSync: adjusting RTC by -2
4/18/18 23:00:00 timeSync: adjusting RTC by -2
4/20/18 01:00:00 timeSync: adjusting RTC by -2
4/20/18 22:00:00 timeSync: adjusting RTC by -2
4/22/18 03:00:00 timeSync: adjusting RTC by -2
4/23/18 01:00:00 timeSync: adjusting RTC by -2
4/24/18 03:00:00 timeSync: adjusting RTC by -2
4/25/18 02:00:00 timeSync: adjusting RTC by -2
4/26/18 03:00:00 timeSync: adjusting RTC by -2
4/26/18 16:30:14 checkUpdate: Invalid response from server.
4/27/18 01:00:00 timeSync: adjusting RTC by -2
4/28/18 03:00:00 timeSync: adjusting RTC by -2
4/28/18 13:30:20 checkUpdate: Invalid response from server.
4/29/18 05:00:00 timeSync: adjusting RTC by -2
4/29/18 17:52:54 Server: Sent less data than expected!
4/29/18 17:53:18 Server: Sent less data than expected!
4/29/18 17:53:28 Server: Sent less data than expected!

I am just guessing here, but I would think that having a last log entry with a timestamp from Mon, 19 Nov 2085 06:45:20 GMT might have something to do with the issue
4/7/18 06:29:56 dataLog: Last log entry:3656990720

Any idea what is wrong?
And how to fix it?

There was probably a power failure right before the restart and then the automatic backup generator came on, but (since it was a major outage) there was no internet. NTP didn’t work until the internet came back several hours later. I would guess that the data writing is not completely safe if a power failure occurs at just the right/wrong time.

[overeasy]

@frogmore

There was probably a power failure right before the restart and then the automatic backup generator came on, but (since it was a major outage) there was no internet. NTP didn’t work until the internet came back several hours later. I would guess that the data writing is not completely safe if a power failure occurs at just the right/wrong time.

The real time clock was running fine back on April 7 when the power failure was detected. The apparent damage to the current log would have happened before the restart. That message is produced when the file is opened, before any new entries are posted.

That restart happened three weeks ago. All indications are that it has not posted any new data since then, possibly since before then.

I’d like to see some log entries from before that restart on April 7. Also, could I see a screenshot of the status display now, with the datalog tab open?

Do you post to Emoncms? if so, can I see a screenshot of a graph of one of your feeds for the past month?

I’m afraid your current log appears to be damaged. Whether the history log is viable from before April 7 will determine how to recover. I need this information to figure that out.

Edit: I answered my own question about Emoncms. Looking at that log you don’t. I still need the status display with the datalog info and older message log entries.

[frogmore]

Here is the whole log. It has been a long time since I looked at it, as I was busy with other stuff. There is not a whole lot of interesting data, so if it got lost, it would not be that much of a loss. It does have some data on my well pump run times (which is what I was looking for when I noticed the issue). I didn’t include the first part of the log, because there was nothing that looked very interesting (other than the invalid response from server when checking for an update). There was a power outage at 6:49AM on April 7, 2018. Power came back within a min or so (backup generator). Internet was restored at 8:25AM on the same day (based on other sensors). This appears to the section of the log where the power went out and came back, but the timestamps seem somewhat confused (but it looks like this is the way it handles GMT vs local time, it might be good to make that clearer in the log). It looks like iotaWatt doesn’t automatically handle DST, which is why the clock jumped from GMT to GMT-8 instead of GMT-7. It also looks like it took 39 min from the time it started looking at the log till it found the last entry, which seems a bit excessive

No clock yet: SD initialized.
4/7/18 13:50:35 Real Time Clock is running. Unix time: 1523109035
4/7/18 13:50:35 Power failure detected.
4/7/18 13:50:35 Version: 02_02_30
4/7/18 13:50:35 Reset reason: External System
4/7/18 13:50:35 Trace: 803,19632,58597,37626,5579,22928,8523,19957,41425,59533,65505,23104,61099,15338,14985,14958,53691,9460,41050,60678,26864,42296,2659,42668,41614,51051,33051,10267,1134,22156,47736,59293
4/7/18 13:50:35 ESP8266 ChipID:2222239
4/7/18 05:50:35 device name: IotaWatt, version: 3
4/7/18 05:50:35 Local time zone: -8
4/7/18 05:50:43 checkUpdate: Invalid response from server.
4/7/18 05:50:43 MDNS responder started
4/7/18 05:50:43 You can now connect to http://IotaWatt.local
4/7/18 05:50:43 HTTP server started
4/7/18 05:50:44 dataLog: service started.
4/7/18 06:29:56 dataLog: Last log entry:3656990720
4/7/18 06:29:56 statService: started.
4/7/18 06:29:56 timeSync: service started.
4/7/18 06:29:56 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38

2/5/18 08:09:25 device name: IotaWatt, version: 3
2/5/18 08:09:25 Local time zone: -8
2/5/18 08:09:26 MDNS responder started
2/5/18 08:09:26 You can now connect to http://IotaWatt.local
2/5/18 08:09:26 HTTP server started
2/5/18 08:09:26 dataLog: service started.
2/5/18 08:09:26 dataLog: Last log entry:1517846925
2/5/18 08:09:26 statService: started.
2/5/18 08:09:26 timeSync: service started.
2/5/18 08:09:26 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
2/5/18 08:09:27 historyLog: service started.
2/5/18 08:09:27 historyLog: Last log entry:1517846880
2/6/18 03:09:32 checkUpdate: Invalid response from server.
2/6/18 04:00:00 timeSync: adjusting RTC by -2
2/7/18 07:00:00 timeSync: adjusting RTC by -2
2/8/18 08:00:00 timeSync: adjusting RTC by -2
2/9/18 04:00:00 timeSync: adjusting RTC by -2
2/9/18 11:09:32 Updater: Update from 02_02_29 to 02_02_30
2/9/18 11:09:49 Updater: Update downloaded and signature verified
2/9/18 11:09:59 Updater: firmware upgraded to version 02_02_30
2/9/18 11:09:59 Firmware updated, restarting.

** Restart **

No clock yet: SD initialized.
2/9/18 19:10:07 Real Time Clock is running. Unix time: 1518203407
2/9/18 19:10:07 Version: 02_02_30
2/9/18 19:10:07 Updater: Installing update files for version 02_02_30
2/9/18 19:10:07 Updater: Installing GRAPH.HTM
2/9/18 19:10:07 Updater: Installing GRAPH.JS
2/9/18 19:10:08 Updater: Installing INDEX.HTM
2/9/18 19:10:09 Updater: Installing TABLES.TXT
2/9/18 19:10:09 Updater: Installing CNFSTYLE.CSS
2/9/18 19:10:09 Updater: Installing EDIT.HTM
2/9/18 19:10:09 Updater: Installation complete.
2/9/18 19:10:10 Reset reason: Software/System restart
2/9/18 19:10:10 Trace: 14,13,14,13,14,13,14,13,14,13,14,13,14,13,14,13,14,13,14,13,14,13,14,11,90,84,86,88,12,13,14,15
2/9/18 19:10:10 ESP8266 ChipID:2222239
2/9/18 11:10:10 device name: IotaWatt, version: 3
2/9/18 11:10:10 Local time zone: -8
2/9/18 11:10:10 MDNS responder started
2/9/18 11:10:10 You can now connect to http://IotaWatt.local
2/9/18 11:10:10 HTTP server started
2/9/18 11:10:10 dataLog: service started.
2/9/18 11:10:11 dataLog: Last log entry:1518203370
2/9/18 11:10:11 statService: started.
2/9/18 11:10:11 timeSync: service started.
2/9/18 11:10:11 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
2/9/18 11:10:11 historyLog: service started.
2/9/18 11:10:12 historyLog: Last log entry:1518203340
2/10/18 08:00:00 timeSync: adjusting RTC by -2
2/11/18 09:00:00 timeSync: adjusting RTC by -2
2/12/18 08:00:00 timeSync: adjusting RTC by -2
2/13/18 11:00:00 timeSync: adjusting RTC by -2
2/14/18 11:00:00 timeSync: adjusting RTC by -2
2/15/18 10:00:00 timeSync: adjusting RTC by -2
2/16/18 12:00:00 timeSync: adjusting RTC by -2
2/17/18 12:00:00 timeSync: adjusting RTC by -2
2/18/18 17:00:00 timeSync: adjusting RTC by -2
2/19/18 00:10:18 checkUpdate: Invalid response from server.
2/19/18 16:00:00 timeSync: adjusting RTC by -2
2/20/18 17:00:00 timeSync: adjusting RTC by -2
2/21/18 09:10:25 checkUpdate: Invalid response from server.
2/21/18 15:00:00 timeSync: adjusting RTC by -2
2/22/18 17:00:00 timeSync: adjusting RTC by -2
2/23/18 14:00:00 timeSync: adjusting RTC by -2
2/24/18 16:00:00 timeSync: adjusting RTC by -2
2/25/18 17:00:00 timeSync: adjusting RTC by -2
2/26/18 10:10:31 checkUpdate: Invalid response from server.
2/26/18 10:34:45 WiFi disconnected.
2/26/18 10:35:26 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
2/26/18 17:00:00 timeSync: adjusting RTC by -2
2/27/18 12:00:00 timeSync: adjusting RTC by -2
2/28/18 19:00:00 timeSync: adjusting RTC by -2
3/1/18 07:10:37 checkUpdate: Invalid response from server.
3/1/18 14:00:00 timeSync: adjusting RTC by -2
3/2/18 14:00:00 timeSync: adjusting RTC by -2
3/3/18 12:00:00 timeSync: adjusting RTC by -2
3/3/18 17:10:43 checkUpdate: Invalid response from server.
3/4/18 10:10:49 checkUpdate: Invalid response from server.
3/4/18 17:00:00 timeSync: adjusting RTC by -2
3/4/18 18:10:54 checkUpdate: Invalid response from server.
3/5/18 14:00:00 timeSync: adjusting RTC by -2
3/6/18 08:00:08 Server: Sent less data than expected!
3/6/18 17:00:00 timeSync: adjusting RTC by -2
3/7/18 03:10:56 checkUpdate: Invalid response from server.
3/7/18 16:00:00 timeSync: adjusting RTC by -2
3/8/18 18:00:00 timeSync: adjusting RTC by -2
3/9/18 04:11:04 checkUpdate: Invalid response from server.
3/9/18 23:00:00 timeSync: adjusting RTC by -2
3/11/18 00:00:00 timeSync: adjusting RTC by -2
3/11/18 18:05:45 Server: Sent less data than expected!
3/11/18 18:34:00 Server: Sent less data than expected!
3/12/18 01:00:00 timeSync: adjusting RTC by -2
3/13/18 00:00:00 timeSync: adjusting RTC by -2
3/13/18 23:00:00 timeSync: adjusting RTC by -2
3/14/18 07:11:12 checkUpdate: Invalid response from server.
3/15/18 01:00:00 timeSync: adjusting RTC by -2
3/15/18 22:00:00 timeSync: adjusting RTC by -2
3/17/18 03:00:00 timeSync: adjusting RTC by -2
3/18/18 03:00:00 timeSync: adjusting RTC by -2
3/19/18 00:31:38 Server: Sent less data than expected!
3/19/18 09:00:00 timeSync: adjusting RTC by -2
3/20/18 08:00:00 timeSync: adjusting RTC by -2
3/21/18 05:00:00 timeSync: adjusting RTC by -2
3/22/18 06:00:00 timeSync: adjusting RTC by -2
3/23/18 07:00:00 timeSync: adjusting RTC by -2
3/24/18 12:00:00 timeSync: adjusting RTC by -2
3/25/18 10:00:00 timeSync: adjusting RTC by -2
3/26/18 10:00:00 timeSync: adjusting RTC by -2
3/26/18 19:11:25 checkUpdate: Invalid response from server.
3/27/18 02:11:27 checkUpdate: Invalid response from server.
3/27/18 12:00:00 timeSync: adjusting RTC by -2
3/28/18 00:11:32 checkUpdate: Invalid response from server.
3/28/18 09:00:00 timeSync: adjusting RTC by -2
3/29/18 10:11:37 checkUpdate: Invalid response from server.
3/29/18 11:00:00 timeSync: adjusting RTC by -2
3/29/18 22:33:28 Server: Sent less data than expected!
3/30/18 13:11:38 checkUpdate: Invalid response from server.
3/30/18 15:00:00 timeSync: adjusting RTC by -2
3/31/18 06:11:44 checkUpdate: Invalid response from server.
3/31/18 13:00:00 timeSync: adjusting RTC by -2
4/1/18 07:11:46 checkUpdate: Invalid response from server.
4/1/18 13:11:48 checkUpdate: Invalid response from server.
4/1/18 15:00:00 timeSync: adjusting RTC by -2
4/2/18 16:00:00 timeSync: adjusting RTC by -2
4/2/18 19:11:53 checkUpdate: Invalid response from server.
4/3/18 12:00:00 timeSync: adjusting RTC by -2
4/4/18 15:00:00 timeSync: adjusting RTC by -2
4/5/18 16:00:00 timeSync: adjusting RTC by -2
4/6/18 17:00:00 timeSync: adjusting RTC by -2

** Restart **

No clock yet: SD initialized.
4/7/18 13:50:35 Real Time Clock is running. Unix time: 1523109035
4/7/18 13:50:35 Power failure detected.
4/7/18 13:50:35 Version: 02_02_30
4/7/18 13:50:35 Reset reason: External System
4/7/18 13:50:35 Trace: 803,19632,58597,37626,5579,22928,8523,19957,41425,59533,65505,23104,61099,15338,14985,14958,53691,9460,41050,60678,26864,42296,2659,42668,41614,51051,33051,10267,1134,22156,47736,59293
4/7/18 13:50:35 ESP8266 ChipID:2222239
4/7/18 05:50:35 device name: IotaWatt, version: 3
4/7/18 05:50:35 Local time zone: -8
4/7/18 05:50:43 checkUpdate: Invalid response from server.
4/7/18 05:50:43 MDNS responder started
4/7/18 05:50:43 You can now connect to http://IotaWatt.local
4/7/18 05:50:43 HTTP server started
4/7/18 05:50:44 dataLog: service started.
4/7/18 06:29:56 dataLog: Last log entry:3656990720
4/7/18 06:29:56 statService: started.
4/7/18 06:29:56 timeSync: service started.
4/7/18 06:29:56 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
4/7/18 06:30:01 checkUpdate: Invalid response from server.
4/7/18 06:35:38 timeSync: Failed to get NTPtime.
4/7/18 07:05:42 timeSync: Failed to get NTPtime.
4/7/18 16:00:00 timeSync: adjusting RTC by -2
4/8/18 19:00:00 timeSync: adjusting RTC by -2
4/8/18 22:11:13 WiFi disconnected.
4/8/18 22:16:15 WiFi connected. SSID: FrogmoreN66, IP: 192.168.0.38
4/9/18 21:00:00 timeSync: adjusting RTC by -2
4/10/18 20:00:00 timeSync: adjusting RTC by -2
4/12/18 00:00:00 timeSync: adjusting RTC by -2
4/13/18 01:00:00 timeSync: adjusting RTC by -2
4/13/18 22:05:42 timeSync: Failed to get NTPtime.
4/14/18 00:02:08 timeSync: adjusting RTC by -2
4/14/18 09:05:43 timeSync: Failed to get NTPtime.
4/14/18 10:05:43 timeSync: Failed to get NTPtime.
4/14/18 11:05:42 timeSync: Failed to get NTPtime.
4/14/18 12:05:42 timeSync: Failed to get NTPtime.
4/14/18 13:05:42 timeSync: Failed to get NTPtime.
4/14/18 22:00:00 timeSync: adjusting RTC by -2
4/15/18 18:30:06 checkUpdate: Invalid response from server.
4/15/18 21:00:00 timeSync: adjusting RTC by -2
4/16/18 23:01:01 timeSync: adjusting RTC by -2
4/17/18 04:59:59 timeSync: adjusting RTC by -2
4/17/18 06:00:02 timeSync: adjusting RTC by 2
4/18/18 00:00:05 timeSync: adjusting RTC by -2
4/18/18 23:00:00 timeSync: adjusting RTC by -2
4/20/18 01:00:00 timeSync: adjusting RTC by -2
4/20/18 22:00:00 timeSync: adjusting RTC by -2
4/22/18 03:00:00 timeSync: adjusting RTC by -2
4/23/18 01:00:00 timeSync: adjusting RTC by -2
4/24/18 03:00:00 timeSync: adjusting RTC by -2
4/25/18 02:00:00 timeSync: adjusting RTC by -2
4/26/18 03:00:00 timeSync: adjusting RTC by -2
4/26/18 16:30:14 checkUpdate: Invalid response from server.
4/27/18 01:00:00 timeSync: adjusting RTC by -2
4/28/18 03:00:00 timeSync: adjusting RTC by -2
4/28/18 13:30:20 checkUpdate: Invalid response from server.
4/29/18 05:00:00 timeSync: adjusting RTC by -2
4/29/18 17:52:54 Server: Sent less data than expected!
4/29/18 17:53:18 Server: Sent less data than expected!
4/29/18 17:53:28 Server: Sent less data than expected!
4/29/18 18:33:45 Server: Sent less data than expected!
4/29/18 18:34:04 Server: Sent less data than expected!
4/29/18 19:30:26 checkUpdate: Invalid response from server.
4/30/18 02:00:00 timeSync: adjusting RTC by -2
5/1/18 01:30:27 checkUpdate: Invalid response from server.
5/1/18 03:00:00 timeSync: adjusting RTC by -2

[overeasy]

@frogmore

This appears to the section of the log where the power went out and came back, but the timestamps seem somewhat confused (but it looks like this is the way it handles GMT vs local time, it might be good to make that clearer in the log)

The RTC is maintained on UTC time, and the time zone isn’t known until the configuration is processed, so the first few messages are UTC time. The latest development version marks those with a ‘z’.

@frogmore

It looks like iotaWatt doesn’t automatically handle DST, which is why the clock jumped from GMT to GMT-8 instead of GMT-7.

Right, it doesn’t work with time zone, just a time difference. To do DST I’d need to ask for the actual time zone. Suffice to change it in the config twice a year. All of the data is kept at UTC, so it’s a whole can of worms whether to display historical data based on the time difference then or now. Maybe some day.

@frogmore

It also looks like it took 39 min from the time it started looking at the log till it found the last entry, which seems a bit excessive

Yes, that is troubling. Also, the history log never started. That may be a good thing. I believe this problem is completely unrelated to the power failure. I believe there is a bug somewhere when the internal millisecond clock rolls over after ~49 days. I tested that a few months back, but it’s hard to do perpetually as it takes 49 days to set it up. Probably a way around that, but I think the best remedy is to restart the thing every 30 days whether it needs it or not. I’ll put that into the development code.

To recover your IoTaWatt, first delete the current log using this URL in a browser:

http://IotaWatt.local/command?deletelog=current

The IoTaWatt will respond “ok” and then restart. When it comes back, check the current and history log in the status display “Data logs” tab.

If the history log has bogus dates as well, issue the similar URL

http://IotaWatt.local/command?deletelog=history

Hopefully you won’t need to delete the history log and you will be able to see your data until the current log became corrupted. If you still have history, I’d be interested in whether there is a gap beginning around March 30, which would confirm my clock theory.

[frogmore]

It appears to be back to working. The history log shows the last reading at 6:50AM April 7, which matches (to the min) the time the power failed. So, it appears the log got corrupted during the power down/up sequence.

[overeasy]

@frogmore

It appears to be back to working

Thanks, that’s good information. Your history log should have advanced to the current date, with null entries for the gap.

[frogmore]

Yes, the history log is fine and has a large gap in it. There really wasn’t too much interesting in the normal log (other than more details about well pump power utilization that I can probably infer from other monitoring I have). The main log was about 660MB. I started to copy it off of the device (using the web UI) but it was taking forever (it estimated it would take 4 or more hours).

For a future code change, it might be a good idea to start a new log on each power cycle and perhaps every so often. Or, it looks like it might be a good idea to power the IotaWatt from a UPS or battery backed supply to help prevent file corruption. The RPi is known for having issues with SD cards and many of them have been traced poor power supply regulation. A unexpected power outage is a given here at least a few times a year. I have had mine about a year and a half, so it probably went through 10ish power cycles before failing. That’s not bad, but probably too high to be considered reliable enough to not need backup power.