Upload to 3rd party services stopped

Support
1

On Friday evening (6/26/20 19:30), my Iotawatt unit stopped loading data to both PVOUTPUT and EMONCMS.
It had been running nicely since the firmware update two weeks ago (and the six months before that) so this was quite curious.
I was away from home for the weekend so it gave it a good shot at self-correcting without me intervening. Alas, it did not for the next three days.
On return home (6/29/20 14:39:27) I gave the router a reboot to see if that was the issue. It wasn’t.
About two hours after that (6/29/20 16:08:20), I rebooted the unit via the web interface.
From here it connected as expected and back loaded all the data that had not gone there in the previous three days.
All is well at the moment but the underlying cause of the glitch is unknown.
Any ideas?

** 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.
6/17/20 11:12:20 WiFi disconnected.
6/17/20 11:12:32 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=11, RSSI -57db
6/17/20 14:44:22 WiFi disconnected.
6/17/20 14:44:34 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -52db
6/17/20 18:16:03 WiFi disconnected.
6/17/20 18:16:15 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=11, RSSI -55db
6/17/20 21:47:12 WiFi disconnected.
6/17/20 21:47:24 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -52db
6/18/20 01:18:30 WiFi disconnected.
6/18/20 01:18:42 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -52db
6/18/20 04:49:44 WiFi disconnected.
6/18/20 04:49:56 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -53db
6/18/20 08:21:06 WiFi disconnected.
6/18/20 08:21:18 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -54db
6/19/20 08:04:44 EmonService: HTTP response -4, retrying.
6/19/20 08:09:39 EmonService: Retry successful after 53 attempts.
6/20/20 11:57:24 EmonService: HTTP response 302, retrying.
6/20/20 11:57:52 EmonService: Retry successful after 38 attempts.
6/20/20 12:11:30 WiFi disconnected.
6/20/20 12:11:39 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/22/20 16:06:15 WiFi disconnected.
6/22/20 16:06:24 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -58db
6/23/20 00:03:29 EmonService: HTTP response -4, retrying.
6/23/20 00:05:01 PVoutput: Unrecognized HTTP completion, upload
6/23/20 00:57:43 Updater: Invalid response from server. HTTPcode: -4
6/23/20 01:01:39 EmonService: Retry successful after 158 attempts.
6/23/20 01:05:01 PVoutput: System Wally’s Shed, interval 5, freeload mode
6/23/20 01:05:02 PVoutput: Start status beginning 06/23/20 00:00:00
6/23/20 11:13:30 EmonService: HTTP response -4, retrying.
6/23/20 11:13:59 EmonService: Retry successful after 31 attempts.
6/24/20 20:01:59 WiFi disconnected.
6/24/20 20:02:11 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -56db
6/26/20 10:12:55 EmonService: HTTP response 302, retrying.
6/26/20 10:13:26 EmonService: Retry successful after 39 attempts.
6/26/20 10:47:38 EmonService: HTTP response 302, retrying.
6/26/20 10:50:14 EmonService: Retry successful after 40 attempts.
6/26/20 10:51:28 EmonService: HTTP response 302, retrying.
6/26/20 23:56:29 WiFi disconnected.
6/26/20 23:56:40 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -57db
6/27/20 09:40:16 PVoutput: Unrecognized HTTP completion, upload
6/27/20 10:02:51 timeSync: No time update in last 24 hours.
6/28/20 10:03:57 timeSync: No time update in last 24 hours.
6/28/20 10:12:25 PVoutput: Unrecognized HTTP completion, getSystemService
6/29/20 03:45:13 WiFi disconnected.
6/29/20 03:45:25 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/29/20 09:35:49 PVoutput: Unrecognized HTTP completion, getSystemService
6/29/20 10:04:55 timeSync: No time update in last 24 hours.
6/29/20 14:39:27 WiFi disconnected.
6/29/20 14:40:17 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/29/20 16:08:20 Restart command received.

** Restart **

SD initialized.
6/29/20 06:08:27z Real Time Clock is running. Unix time 1593410907
6/29/20 06:08:27z Reset reason: Software/System restart
6/29/20 06:08:27z Trace: 8:6, 8:8, 8:9, 9:3, 9:5, 9:9, 1:2, 1:3, 1:4, 1:5[22], 22:0, 22:1, 22:0, 22:120, 22:2, 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, 10:2, 10:3
6/29/20 06:08:28z ESP8266 ChipID: 6144641
6/29/20 06:08:28z IoTaWatt 5.0, Firmware version 02_05_09
6/29/20 06:08:28z SPIFFS mounted.
6/29/20 16:08:29 Local time zone: +10:00
6/29/20 16:08:29 Using Daylight Saving Time (BST) when in effect.
6/29/20 16:08:30 device name: IotaWatt
6/29/20 16:08:30 HTTP server started
6/29/20 16:08:30 timeSync: service started.
6/29/20 16:08:30 statService: started.
6/29/20 16:08:31 dataLog: service started.
6/29/20 16:08:32 dataLog: Last log entry 06/29/20 16:08:20
6/29/20 16:08:35 EmonService: started. url=HTTP://emoncms.org, node=IotaWatt, interval=10
6/29/20 16:08:37 Updater: service started. Auto-update class is MINOR
6/29/20 16:08:37 WiFi connected. SSID=Frog, IP=192.168.0.106, channel=6, RSSI -55db
6/29/20 16:08:37 MDNS responder started for hostname IotaWatt
6/29/20 16:08:38 LLMNR responder started for hostname IotaWatt
6/29/20 16:08:40 EmonService: Start posting at 06/26/20 10:50:40
6/29/20 16:08:40 Updater: Auto-update is current for class MINOR.
6/29/20 16:09:32 historyLog: service started.
6/29/20 16:09:32 historyLog: Last log entry 06/29/20 16:08:00
6/29/20 16:09:40 PVoutput: started
6/29/20 16:09:41 PVoutput: System Wally’s Shed, interval 5, freeload mode
6/29/20 16:09:42 PVoutput: Start status beginning 06/26/20 19:30:00
6/30/20 07:47:31 EmonService: HTTP response -4, retrying.
6/30/20 07:47:56 EmonService: Retry successful after 32 attempts.
6/30/20 09:12:54 EmonService: HTTP response 302, retrying.
6/30/20 09:14:19 EmonService: Retry successful after 37 attempts.
6/30/20 09:27:44 EmonService: HTTP response 302, retrying.
6/30/20 09:28:49 EmonService: Retry successful after 37 attempts.
6/30/20 10:44:14 EmonService: HTTP response 302, retrying.
6/30/20 10:48:03 EmonService: Retry successful after 43 attempts.

2

Emoncms appears to have stopped uploading on 6/26 at 10:50:40:

6/29/20 16:08:40 EmonService: Start posting at 06/26/20 10:50:40

That coincides with a string of 302 redirects that occured at that time:

6/26/20 10:12:55 EmonService: HTTP response 302, retrying.
6/26/20 10:13:26 EmonService: Retry successful after 39 attempts.
6/26/20 10:47:38 EmonService: HTTP response 302, retrying.
6/26/20 10:50:14 EmonService: Retry successful after 40 attempts.
6/26/20 10:51:28 EmonService: HTTP response 302, retrying.
6/26/20 23:56:29 WiFi disconnected.

Emoncms never recovered, and PVoutput stopped at 19:30:

6/29/20 16:09:42 PVoutput: Start status beginning 06/26/20 19:30:00

The unit was having a lot of trouble communicating out. Not only communicating with Emoncms.org (halfway around the world), but with PVoutput and time servers. That you were able to access the unit via the web interface tells me the WiFi was working, at least after the router restart.

TBH, the only reports I get of internet problems these days are from Australia. I could ask OEM if they had any 302 redirect issues over the last three days, but I’m confident they didn’t . This forum would be lighting up.

You appear to be continuing top have problems with 302 redirects today according to the log that you posted. This appears to be a problem with your internet, and I don’t think it’s resolved. Your log shows a string of them between 09:12 and 10:48 today.

3

Yes. I would have to agree that my connection to the world is sub-standard but I was curious that a reboot of the unit got it going. I will be getting an NBN connection in the coming weeks/months so I’ll just wait and see how that plays out. I have not much confidence it will be better but there’s not much point troubleshooting the current connection given that it will be replaced in the near term.
Thanks

4

The bulk of the TCP stack in the ESP8266 is maintained by Espresive and the core developers. I have no visibility into it. It has gotten a lot better over the past year, but at the end of the day it’s an IOT platform and can get jammed up.

The primary IoTaWatt mission is to measure your power. If I restarted to reset the TCP stack every time there were communications problems, it would compromise the monitoring. Worst case is it doesn’t restart for about six weeks, but usually there is a power failure of human intervention.

The good news is that it did keep monitoring, and backfilled three days to both PVoutput and Emoncms. Not too many energy monitors do that.