Reboot, download, rinse, repeat - Resolved

Whatto · June 15, 2020, 10:28pm

My unit has been doing some serious background working in the last few days to the point where it no longer reliably responds when I ask for data. I can occasionally get connected to it but it stopped talking to PVOUTPUT yesterday.
I can (occasionally) get a look at the log and it would appear to be continually trying to download and install new firmware (02_05_09).
As far back in the log as is interesting, it seems to cycle through this sequence every minute or so.
I did resort to my first manual restart in six months but (as expected) no change.
Any clues?

** Restart **

SD initialized.
6/15/20 22:13:01z Real Time Clock is running. Unix time 1592259181
6/15/20 22:13:01z Reset reason: Software/System restart
6/15/20 22:13:01z Trace: 1:6, 1:3, 1:4, 1:5[3], 3:0, 3:6, 3:6, 3:6, 3:6, 3:6, 3:6, 1:6, 1:1, 1:2[1], 9:0[1], 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], 5:0, 5:6, 21:100[5], 21:101
6/15/20 22:13:02z ESP8266 ChipID: 6144641
6/15/20 22:13:02z IoTaWatt 5.0, Firmware version 02_05_08
6/15/20 22:13:02z SPIFFS mounted.
6/16/20 08:13:03 Local time zone: +10:00
6/16/20 08:13:03 Using Daylight Saving Time (BST) when in effect.
6/16/20 08:13:03 device name: IotaWatt
6/16/20 08:13:04 HTTP server started
6/16/20 08:13:04 timeSync: service started.
6/16/20 08:13:04 statService: started.
6/16/20 08:13:04 dataLog: service started.
6/16/20 08:13:06 dataLog: Last log entry 06/16/20 08:12:30
6/16/20 08:13:06 historyLog: service started.
6/16/20 08:13:07 historyLog: Last log entry 06/16/20 08:12:00
6/16/20 08:13:09 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 08:13:11 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/16/20 08:13:11 MDNS responder started for hostname IotaWatt
6/16/20 08:13:11 LLMNR responder started for hostname IotaWatt
6/16/20 08:13:12 Updater: service started. Auto-update class is MINOR
6/16/20 08:13:14 PVoutput: started
6/16/20 08:13:14 EmonService: Start posting at 06/15/20 18:20:00
6/16/20 08:13:14 Updater: Update from 02_05_08 to 02_05_09
6/16/20 08:13:16 Updater: download 02_05_09
6/16/20 08:13:46 dataLog: datalog WDT - restarting

** Restart **

SD initialized.
6/15/20 22:13:47z Real Time Clock is running. Unix time 1592259227
6/15/20 22:13:47z Reset reason: Software/System restart
6/15/20 22:13:47z Trace: 1:3, 1:4, 1:5[3], 3:0, 3:6, 3:6, 3:6, 3:6, 3:6, 3:6, 1:6, 1:1, 1:2[1], 9:0[1], 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], 5:0, 5:6, 21:100[5], 21:101, 21:101[1]
6/15/20 22:13:48z ESP8266 ChipID: 6144641
6/15/20 22:13:48z IoTaWatt 5.0, Firmware version 02_05_08
6/15/20 22:13:48z SPIFFS mounted.
6/16/20 08:13:49 Local time zone: +10:00
6/16/20 08:13:49 Using Daylight Saving Time (BST) when in effect.
6/16/20 08:13:49 device name: IotaWatt
6/16/20 08:13:50 HTTP server started
6/16/20 08:13:50 timeSync: service started.
6/16/20 08:13:50 statService: started.
6/16/20 08:13:51 dataLog: service started.
6/16/20 08:13:52 dataLog: Last log entry 06/16/20 08:13:15
6/16/20 08:13:52 historyLog: service started.
6/16/20 08:13:53 historyLog: Last log entry 06/16/20 08:13:00
6/16/20 08:13:55 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 08:13:56 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/16/20 08:13:56 MDNS responder started for hostname IotaWatt
6/16/20 08:13:56 LLMNR responder started for hostname IotaWatt
6/16/20 08:13:57 Updater: service started. Auto-update class is MINOR
6/16/20 08:13:59 EmonService: Start posting at 06/15/20 18:20:00
6/16/20 08:13:59 Updater: Update from 02_05_08 to 02_05_09
6/16/20 08:14:00 Updater: download 02_05_09
6/16/20 08:14:01 PVoutput: started
6/16/20 08:14:31 dataLog: datalog WDT - restarting

** Restart **

SD initialized.
6/15/20 22:14:32z Real Time Clock is running. Unix time 1592259272
6/15/20 22:14:32z Reset reason: Software/System restart
6/15/20 22:14:32z Trace: 1:6, 1:3, 1:4, 1:5[3], 3:0, 3:6, 3:6, 3:6, 3:6, 3:6, 3:6, 1:6, 1:1[1], 1:2[2], 9:0[2], 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], 5:0, 5:6, 21:100[5], 21:101
6/15/20 22:14:33z ESP8266 ChipID: 6144641
6/15/20 22:14:33z IoTaWatt 5.0, Firmware version 02_05_08
6/15/20 22:14:33z SPIFFS mounted.
6/16/20 08:14:34 Local time zone: +10:00
6/16/20 08:14:34 Using Daylight Saving Time (BST) when in effect.
6/16/20 08:14:35 device name: IotaWatt
6/16/20 08:14:35 HTTP server started
6/16/20 08:14:35 timeSync: service started.
6/16/20 08:14:35 statService: started.
6/16/20 08:14:36 dataLog: service started.
6/16/20 08:14:37 dataLog: Last log entry 06/16/20 08:14:00
6/16/20 08:14:37 historyLog: service started.
6/16/20 08:14:38 historyLog: Last log entry 06/16/20 08:13:00
6/16/20 08:14:40 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 08:14:41 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -56db
6/16/20 08:14:41 MDNS responder started for hostname IotaWatt
6/16/20 08:14:41 LLMNR responder started for hostname IotaWatt
6/16/20 08:14:42 Updater: service started. Auto-update class is MINOR
6/16/20 08:14:44 EmonService: Start posting at 06/15/20 18:20:00
6/16/20 08:14:44 Updater: Update from 02_05_08 to 02_05_09
6/16/20 08:14:45 Updater: download 02_05_09
6/16/20 08:14:46 PVoutput: started
6/16/20 08:15:16 dataLog: datalog WDT - restarting

** Restart **

SD initialized.
6/15/20 22:15:17z Real Time Clock is running. Unix time 1592259317
6/15/20 22:15:17z Reset reason: Software/System restart
6/15/20 22:15:17z Trace: 1:6, 1:3, 1:4, 1:5[3], 3:0, 3:6, 3:6, 3:6, 3:6, 3:6, 3:6, 1:6, 1:1[1], 1:2[2], 9:0[2], 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], 5:0, 5:6, 21:100[5], 21:101
6/15/20 22:15:18z ESP8266 ChipID: 6144641
6/15/20 22:15:18z IoTaWatt 5.0, Firmware version 02_05_08
6/15/20 22:15:18z SPIFFS mounted.
6/16/20 08:15:19 Local time zone: +10:00
6/16/20 08:15:19 Using Daylight Saving Time (BST) when in effect.
6/16/20 08:15:20 device name: IotaWatt
6/16/20 08:15:20 HTTP server started
6/16/20 08:15:20 timeSync: service started.
6/16/20 08:15:20 statService: started.
6/16/20 08:15:21 dataLog: service started.
6/16/20 08:15:22 dataLog: Last log entry 06/16/20 08:14:45
6/16/20 08:15:22 historyLog: service started.
6/16/20 08:15:23 historyLog: Last log entry 06/16/20 08:14:00
6/16/20 08:15:25 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 08:15:26 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/16/20 08:15:26 MDNS responder started for hostname IotaWatt
6/16/20 08:15:26 LLMNR responder started for hostname IotaWatt

overeasy · June 16, 2020, 12:36am

The restarting should have stopped.

This is a problem that I only see in Australia and some less developed parts of the world. It has to do with taking excessive time to download a new release of the firmware. In this case, MINOR auto-update was recently changed from 02_05_02 to 02_05_09.

All of the MINOR units that were going to successfully download and install this release have done it by now. Without getting into details, I had the ability to selectively specify that MINOR systems that are still 02_05_02 stay on 02_05_02. So your unit should now be running fine on 02_05_02.

This problem seems to be geographic. Admittedly the timeout on the download is too short (20 seconds) but worldwide it takes less than ten seconds due to the new firmware being available on the cloudflare CDN. Cloudflare has several points of presence in Australia, but the problem may be that one or more ISPs are not served by one of them, necessitating the download go more than halfway around the world. The routing from Australia to the US can be circuitous as there are no direct paths. The release 02_05_09 has more tolerance for the latency, but you need to get there to stay on the upgrade bus. There is a solution for those who want to.

With another computer, download the file HTTPS://iotawatt.com/firmware/bin/02_05_09.bin
Upload that file to the iotawatt in the “download” directory creating: download/02_05_09.bin
Use the following URL in your browser to update the IoTaWatt to that release:
http://iotawaa.local/update?release=02_05_09

Your unit should update within a few seconds and restart with the new release.

Whatto · June 16, 2020, 12:49am

Nice! Didn’t even leave my office:
6/16/20 00:45:37z IoTaWatt 5.0, Firmware version 02_05_09

I had set the update to ‘None’ which got me monitoring back but now I’ve kicked it on to 02_05_09, I’ll set it back to MINOR.
Thanks

superbrudd · June 16, 2020, 7:18am

Having the same problem since the weekend…
When I try to run the update as per the above, I get the message “Release file not validated.”
(I’m located in Australia as well)

superbrudd · June 16, 2020, 7:41am

I can’t get the upload working in the small window of time I have between resets… Any ideas?

Whatto · June 16, 2020, 8:04am

I set the update from MINOR to NONE which stabilised it as it was no longer trying to download and update. From there, Bob’s instructions worked first time.
Good luck!

superbrudd · June 16, 2020, 10:20am

Took about half an hour of trying but finally got there. Thanks!

overeasy · June 16, 2020, 11:41am

@superbrudd, @Whatto,

Units running 02_05_02 should have stopped the reboot cycle last night, so I’m wondering what’s going on. Could either (or both) of you post your message log from after 10:00 am 6/16 local time?

Thanks

UPDATE: Also, could you do a tracert iotawatt.com and post the results

Whatto · June 16, 2020, 10:33pm

At the risk of blowing out the thread, here’s some backlog as requested.
It clearly shows the change to update class of minor at 08:38 stopped the looping and also shows the manual update at 10:45 local. In short, I intervened about 90 minutes before it would have corrected itself.
It also shows a bonafide power failure here at 07:40 today.
All good now. Thanks Bob

** Restart **

SD initialized.
6/15/20 22:31:27z Real Time Clock is running. Unix time 1592260287
6/15/20 22:31:27z Reset reason: Software/System restart
6/15/20 22:31:27z Trace: 1:2, 1:3, 1:4, 1:5[3], 3:0, 3:6, 3:6, 3:6, 3:6, 3:6, 3:6, 1:6, 1:1, 1:2[1], 9:0[1], 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], 5:0, 5:6, 21:100[5], 21:101
6/15/20 22:31:28z ESP8266 ChipID: 6144641
6/15/20 22:31:28z IoTaWatt 5.0, Firmware version 02_05_08
6/15/20 22:31:28z SPIFFS mounted.
6/16/20 08:31:29 Local time zone: +10:00
6/16/20 08:31:29 Using Daylight Saving Time (BST) when in effect.
6/16/20 08:31:30 device name: IotaWatt
6/16/20 08:31:30 HTTP server started
6/16/20 08:31:30 timeSync: service started.
6/16/20 08:31:30 statService: started.
6/16/20 08:31:31 dataLog: service started.
6/16/20 08:31:32 dataLog: Last log entry 06/16/20 08:30:55
6/16/20 08:31:32 historyLog: service started.
6/16/20 08:31:33 historyLog: Last log entry 06/16/20 08:30:00
6/16/20 08:31:35 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 08:31:36 Updater: service started. Auto-update class is MINOR
6/16/20 08:31:36 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/16/20 08:31:36 MDNS responder started for hostname IotaWatt
6/16/20 08:31:37 LLMNR responder started for hostname IotaWatt
6/16/20 08:31:39 Updater: Update from 02_05_08 to 02_05_09
6/16/20 08:31:39 Updater: download 02_05_09
6/16/20 08:31:55 Updater: Download failed HTTPcode
6/16/20 08:31:56 PVoutput: started
6/16/20 08:32:02 EmonService: Start posting at 06/15/20 18:20:00
6/16/20 08:32:23 Updater: Invalid response from server. HTTPcode: -4
6/16/20 08:32:25 PVoutput: System Wally’s Shed, interval 5, freeload mode
6/16/20 08:32:26 PVoutput: Start status beginning 06/15/20 18:00:00
6/16/20 08:38:55 Updater: Auto-update class changed to NONE
6/16/20 09:06:47 WiFi disconnected.
6/16/20 09:06:56 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/16/20 10:45:18 Updater: signature verified
6/16/20 10:45:26 Updater: firmware upgraded to version 02_05_09
6/16/20 10:45:26 Updater: Firmware updated, restarting.

** Restart **

SD initialized.
6/16/20 00:45:36z Real Time Clock is running. Unix time 1592268336
6/16/20 00:45:36z Reset reason: Software/System restart
6/16/20 00:45:36z Trace: 3:0, 3:11, 1:6, 1:1[3], 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[3], 3:0, 3:11, 1:6, 1:1[4], 1:2, 9:0, 9:0, 8:4, 8:6, 8:8, 8:9, 1:2, 1:3
6/16/20 00:45:37z ESP8266 ChipID: 6144641
6/16/20 00:45:37z IoTaWatt 5.0, Firmware version 02_05_09
6/16/20 00:45:37z Updater: Installing update files for version 02_05_09
6/16/20 00:45:38z Updater: Installing EDIT.HTM
6/16/20 00:45:38z Updater: Installing GRAPH.HTM
6/16/20 00:45:39z Updater: Installing GRAPH.JS
6/16/20 00:45:39z Updater: Installing GRAPH2.HTM
6/16/20 00:45:39z Updater: Installing GRAPH2.JS
6/16/20 00:45:40z Updater: Installing INDEX.HTM
6/16/20 00:45:41z Updater: Installing TABLES.TXT
6/16/20 00:45:41z Updater: Installing CNFSTYLE.CSS
6/16/20 00:45:42z Updater: Installation complete.
6/16/20 00:45:42z SPIFFS mounted.
6/16/20 10:45:42 Local time zone: +10:00
6/16/20 10:45:43 Using Daylight Saving Time (BST) when in effect.
6/16/20 10:45:43 device name: IotaWatt
6/16/20 10:45:43 HTTP server started
6/16/20 10:45:44 timeSync: service started.
6/16/20 10:45:44 statService: started.
6/16/20 10:45:44 dataLog: service started.
6/16/20 10:45:45 dataLog: Last log entry 06/16/20 10:45:10
6/16/20 10:45:49 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/16/20 10:45:51 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/16/20 10:45:51 MDNS responder started for hostname IotaWatt
6/16/20 10:45:51 LLMNR responder started for hostname IotaWatt
6/16/20 10:45:52 Updater: service started. Auto-update class is NONE
6/16/20 10:45:57 EmonService: Start posting at 06/16/20 10:45:20
6/16/20 10:46:44 historyLog: service started.
6/16/20 10:46:44 historyLog: Last log entry 06/16/20 10:45:00
6/16/20 10:46:54 PVoutput: started
6/16/20 10:46:54 PVoutput: System Wally’s Shed, interval 5, freeload mode
6/16/20 10:46:55 PVoutput: Start status beginning 06/16/20 10:45:00
6/16/20 10:47:09 Updater: Auto-update class changed to MINOR
6/16/20 10:47:10 Updater: Auto-update is current for class MINOR.
6/16/20 12:38:24 WiFi disconnected.
6/16/20 12:38:35 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/16/20 15:23:57 EmonService: HTTP response -4, retrying.
6/16/20 15:33:52 EmonService: Retry successful after 77 attempts.
6/16/20 16:10:36 WiFi disconnected.
6/16/20 16:10:45 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/16/20 19:41:48 WiFi disconnected.
6/16/20 19:42:00 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -53db
6/16/20 23:13:05 WiFi disconnected.
6/16/20 23:13:13 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/17/20 02:44:22 WiFi disconnected.
6/17/20 02:44:34 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -53db
6/17/20 06:15:43 WiFi disconnected.
6/17/20 06:15:51 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -53db

** Restart **

SD initialized.
6/16/20 21:40:32z Real Time Clock is running. Unix time 1592343632
6/16/20 21:40:32z Power failure detected.
6/16/20 21:40:32z Reset reason: Power on
6/16/20 21:40:32z ESP8266 ChipID: 6144641
6/16/20 21:40:33z IoTaWatt 5.0, Firmware version 02_05_09
6/16/20 21:40:33z SPIFFS mounted.
6/17/20 07:40:33 Local time zone: +10:00
6/17/20 07:40:33 Using Daylight Saving Time (BST) when in effect.
6/17/20 07:40:34 device name: IotaWatt
6/17/20 07:40:37 Connecting with WiFiManager.
6/17/20 07:42:46 Did not connect after power-fail. Restarting to reset WiFi.

** Restart **

SD initialized.
6/16/20 21:42:48z Real Time Clock is running. Unix time 1592343768
6/16/20 21:42:48z Reset reason: Software/System restart
6/16/20 21:42:48z Trace: 0:0, 0:0, 0:0, 0:0, 11:0, 11:4, 11:5, 11:5, 11:6, 11:7, 11:8, 11:9, 16:0, 16:1, 16:2, 16:3, 16:4, 16:5, 16:6, 16:7, 11:10, 11:11, 22:200, 22:201, 22:202, 22:203, 22:204, 22:205, 22:206, 22:207, 11:12, 11:12
6/16/20 21:42:49z ESP8266 ChipID: 6144641
6/16/20 21:42:49z IoTaWatt 5.0, Firmware version 02_05_09
6/16/20 21:42:49z SPIFFS mounted.
6/17/20 07:42:50 Local time zone: +10:00
6/17/20 07:42:50 Using Daylight Saving Time (BST) when in effect.
6/17/20 07:42:51 device name: IotaWatt
6/17/20 07:42:51 HTTP server started
6/17/20 07:42:51 timeSync: service started.
6/17/20 07:42:51 statService: started.
6/17/20 07:42:52 dataLog: service started.
6/17/20 07:42:53 dataLog: Last log entry 06/17/20 07:40:25
6/17/20 07:42:56 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/17/20 07:42:57 Updater: service started. Auto-update class is MINOR
6/17/20 07:42:57 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -56db
6/17/20 07:42:58 MDNS responder started for hostname IotaWatt
6/17/20 07:42:58 LLMNR responder started for hostname IotaWatt
6/17/20 07:43:00 EmonService: Start posting at 06/17/20 07:40:30
6/17/20 07:43:00 Updater: Auto-update is current for class MINOR.
6/17/20 07:43:54 historyLog: service started.
6/17/20 07:43:54 historyLog: Last log entry 06/17/20 07:40:00
6/17/20 07:44:07 PVoutput: started
6/17/20 07:44:08 PVoutput: System Wally’s Shed, interval 5, freeload mode
6/17/20 07:44:09 PVoutput: Start status beginning 06/17/20 07:40:00
6/17/20 08:13:09 EmonService: HTTP response -4, retrying.
6/17/20 08:20:48 EmonService: Retry successful after 61 attempts.

superbrudd · June 17, 2020, 5:29am

Sorry - can’t get the log file now as I’ve lost web-access. This seems to happen regularly… it keeps sending data to pvoutput and emoncms, but the iotawatt web page is not responsive. I don’t have easy physical access to it (it’s in a separate rented out part of our house).

From memory, I believe it was on 02_05_07 while doing the rebooting.

Tracert: