IoTaWatt Timeout Sending To Local emoncms

Bschaaf · 4 January 2018 02:03

I have a new IoTaWatt and am uploading data to a local emoncms running on a Synology DiskStation. This setup has been running well for about six months with data captured with an emonTx shield.

The new IoTaWatt sends data ok with occasional “GET failed” errors that successfully recover after one or more resends. Every few hours the IoTaWatt fails to send data ten times and resets. Any idea why this may be happening? Also, after the reset, I thought the IoTaWatt would resend data not sent previously, but this doesn’t seem to happen (data is missing during the period when the IoTaWatt is unable to send data). The local graph utility shows data is being captured during the period when data not successfully sent to Synology DiskStation. A log from the IoTaWatt is shown below. Appreciate any suggestions! Thanks.

1/3/18 18:32:16 EmonService: Retry successful.
1/3/18 18:35:16 EmonService: GET failed. HTTP code:read Timeout
1/3/18 18:36:16 EmonService: Resending EmonCMS data:2
1/3/18 18:38:17 EmonService: Resending EmonCMS data:3
1/3/18 18:38:17 EmonService: Retry successful.
1/3/18 18:38:24 EmonService: GET failed. HTTP code:read Timeout
1/3/18 18:39:24 EmonService: Resending EmonCMS data:2
1/3/18 18:41:25 EmonService: Resending EmonCMS data:3
1/3/18 18:44:26 EmonService: Resending EmonCMS data:4
1/3/18 18:48:27 EmonService: Resending EmonCMS data:5
1/3/18 18:53:28 EmonService: Resending EmonCMS data:6
1/3/18 18:59:30 EmonService: Resending EmonCMS data:7
1/3/18 19:06:31 EmonService: Resending EmonCMS data:8
1/3/18 19:14:32 EmonService: Resending EmonCMS data:9
1/3/18 19:23:34 EmonService: Resending EmonCMS data:10
1/3/18 19:23:35 EmonService: Unable to post to Emoncms after 10 retries. Restarting ESP.

** Restart **

No clock yet: SD initialized.
1/4/18 00:23:37 Real Time Clock is running. Unix time: 1515025417
1/4/18 00:23:37 Version: 02_02_27
1/4/18 00:23:37 Reset reason: Software/System restart
1/4/18 00:23:37 Trace: 88,12,13,14,17,18,13,14,17,18,13,14,17,18,13,14,15,16,17,18,13,14,15,16,17,18,13,14,15,30,37,38
1/4/18 00:23:37 ESP8266 ChipID:453812
1/3/18 19:23:37 device name: IotaWatt, version: 3
1/3/18 19:23:37 Local time zone: -5
1/3/18 19:23:40 Connecting with WiFiManager.
1/3/18 19:23:43 MDNS responder started
1/3/18 19:23:43 You can now connect to http://IotaWatt.local
1/3/18 19:23:43 HTTP server started
1/3/18 19:23:44 dataLog: service started.
1/3/18 19:23:44 dataLog: Last log entry:1515025410
1/3/18 19:23:44 statService: started.
1/3/18 19:23:44 timeSync: service started.
1/3/18 19:23:44 WiFi connected. SSID: bmkema-2.4GHz, IP: 192.168.1.92
1/3/18 19:23:44 historyLog: service started.
1/3/18 19:23:44 historyLog: Last log entry:1515025380
1/3/18 19:23:49 EmonService: started.url: 192.168.1.180:80/emoncms, node: IotaWatt, post interval: 10, unsecure GET
1/3/18 19:23:49 EmonService: input/get failed.
1/3/18 19:24:19 EmonService: input/get failed.
1/3/18 19:24:49 EmonService: Start posting at 1515025485
1/3/18 19:26:16 EmonService: GET failed. HTTP code:read Timeout
1/3/18 19:27:16 EmonService: Resending EmonCMS data:2
1/3/18 19:27:16 EmonService: Retry successful.

blaal02 · 4 January 2018 02:39

Hi Brian,
I am having very similar issues:

In this usage graph, the black line is the total usage (calculated in emoncms as the sum of the 2 supply lines - US so split phase). The straight sections seem to be where IoTaWatt was having issues.

. The top two lines (gray & gray/green) are from an EmonTX, everything else is from the IoTaWatt. Sometimes I see branch circuit details even when the totals aren’t feeding (e.g. 18:00-19:00), sometimes not (e.g. 08:00ish-09:00).

** Restart **

No clock yet: SD initialized.
1/4/18 00:34:24 Real Time Clock is running. Unix time: 1515026064
1/4/18 00:34:24 Version: 02_02_27
1/4/18 00:34:24 Reset reason: Software/System restart
1/4/18 00:34:24 Trace: 14,17,18,11,90,91,84,86,88,93,94,95,99,12,13,14,15,16,17,18,13,14,15,16,17,18,13,14,15,30,37,38
1/4/18 00:34:24 ESP8266 ChipID:2870702
1/3/18 17:34:24 device name: IotaWatt, version: 3
1/3/18 17:34:24 Local time zone: -7
1/3/18 17:34:27 MDNS responder started
1/3/18 17:34:27 You can now connect to http://IotaWatt.local
1/3/18 17:34:27 HTTP server started
1/3/18 17:34:27 dataLog: service started.
1/3/18 17:34:28 dataLog: Last log entry:1515026060
1/3/18 17:34:28 statService: started.
1/3/18 17:34:28 timeSync: service started.
1/3/18 17:34:28 WiFi connected. SSID: BLACKBURN, IP: 192.168.2.45
1/3/18 17:34:28 historyLog: service started.
1/3/18 17:34:28 historyLog: Last log entry:1515026040
1/3/18 17:34:32 EmonService: started.url: 192.168.2.44:80/emoncms, node: IotaWatt, post interval: 10, unsecure GET
1/3/18 17:34:32 EmonService: Start posting at 1515026070
1/3/18 18:18:46 EmonService: GET failed. HTTP code:read Timeout
1/3/18 18:19:46 EmonService: Resending EmonCMS data:2
1/3/18 18:19:46 EmonService: Retry successful.
1/3/18 18:19:53 EmonService: GET failed. HTTP code:read Timeout
1/3/18 18:20:53 EmonService: Resending EmonCMS data:2
1/3/18 18:22:54 EmonService: Resending EmonCMS data:3
1/3/18 18:25:55 EmonService: Resending EmonCMS data:4
1/3/18 18:29:56 EmonService: Resending EmonCMS data:5
1/3/18 18:34:57 EmonService: Resending EmonCMS data:6
1/3/18 18:40:58 EmonService: Resending EmonCMS data:7
1/3/18 18:47:59 EmonService: Resending EmonCMS data:8
1/3/18 18:56:00 EmonService: Resending EmonCMS data:9
1/3/18 19:05:01 EmonService: Resending EmonCMS data:10
1/3/18 19:05:02 EmonService: Unable to post to Emoncms after 10 retries. Restarting ESP.

** Restart **

No clock yet: SD initialized.
1/4/18 02:05:04 Real Time Clock is running. Unix time: 1515031504
1/4/18 02:05:04 Version: 02_02_27
1/4/18 02:05:04 Reset reason: Software/System restart
1/4/18 02:05:04 Trace: 14,17,18,11,90,91,84,86,88,93,94,95,99,12,13,14,15,16,17,18,13,14,15,16,17,18,13,14,15,30,37,38
1/4/18 02:05:04 ESP8266 ChipID:2870702
1/3/18 19:05:04 device name: IotaWatt, version: 3
1/3/18 19:05:04 Local time zone: -7
1/3/18 19:05:07 MDNS responder started
1/3/18 19:05:07 You can now connect to http://IotaWatt.local
1/3/18 19:05:07 HTTP server started
1/3/18 19:05:07 dataLog: service started.
1/3/18 19:05:08 dataLog: Last log entry:1515031500
1/3/18 19:05:08 statService: started.
1/3/18 19:05:08 timeSync: service started.
1/3/18 19:05:08 WiFi connected. SSID: BLACKBURN, IP: 192.168.2.45
1/3/18 19:05:08 historyLog: service started.
1/3/18 19:05:08 historyLog: Last log entry:1515031500
1/3/18 19:05:12 EmonService: started.url: 192.168.2.44:80/emoncms, node: IotaWatt, post interval: 10, unsecure GET
1/3/18 19:05:12 EmonService: Start posting at 1515031510
(the times on the log should match with the times on the graph)

Not sure of all my fact here, but as I remember things…
All went quite well when the IoTaWatt was first installed. Then the local Win/WAMP emoncms instance died for a day or so. I recovered when I noticed (it just ran out of disk space), nut things started going bad from then on - the IoTaWatt was trying to resend, but not really managing to catch up to real time. Then the 02_02_27 update came out & things went much better. Lastly, I moved the EmonCMS instance from Wim/WAMP to Win/IIS, and it seemed to get worse (this is the bit that’s mainly “hearsay”!), but that’s where this graph is coming from.
Thanks,
Sandy

overeasy · 4 January 2018 04:05

Two problems here:

First, a failure to communicate. I’ve been working on this, and the current state of affairs is that the data upload transaction is a synchronous request, which means that it must wait for the communication to complete before it can do anything else. That something else is sample the input channels. So there is a timeout on the transaction to keep the IoTaWatt from blocking for a long time waiting for a response that can possibly never come. The timeout is increased on the retries, but is never more than a second. So if the local emoncms is not responding or is slow, this can happen. The restart isn’t necessarily a problem, it only takes a couple of seconds, and only happens at most once per hour. I have an IoTaWatt in an outbuilding that has spotty WiFi and it resets once or twice a day, but always recovers and hasn’t lost any date.

Which brings us to your second problem. With version 02_02_27, IoTaWatt queries the instance of emoncms at startup to get the time of the last posting. It then resumes posting from that time. It appears that is not working in your instance of Emoncms. The API is not well documented, but works perfectly with Emoncms.org. There’s something you could try to verify if it is working on your system. From a browser, type the url:

192.168.1.180/emoncms/input/get?node=IotaWatt&apikey=<your api key>

and post the response. That will help me to figure why your IoTaWatt isn’t syncing with your Emoncms at startup.

Long term, the solution to the I/O timeouts is asynchronous I/O. I have this working in a development branch and hope to make a version available in about 4-6 weeks. But as I said, that isn’t really a major problem right now.

@blaal02,

You are reporting the second problem: failure to sync with a local Emoncms at startup. Can you do the same, substituting your local emoncms IP in the URL.

Also, could both of you disclose the version of Emoncms you are using?

blaal02 · 4 January 2018 04:22

Hi Bob,
Nice to “meet” you; I don’t think I’ve bothered you before.
But thanks for all the work on IoTaWatt, it’s a really nice device!!

Here’s what I get from that API call:
{“1”:{“processList”:“1:201”},“10”:{“processList”:“1:227,4:228”},“11”:{“processList”:“1:230,4:231”},“12”:{“processList”:“1:233,4:234”},“13”:{“processList”:“1:236,4:237”},“14”:{“processList”:“1:239,4:240”},“15”:{“processList”:“1:242,4:243”},“2”:{“processList”:“1:202,4:203,11:673,1:245,4:246”},“3”:{“processList”:“1:206,4:207”},“4”:{“processList”:“1:209,4:210”},“5”:{“processList”:“1:212,4:213”},“6”:{“processList”:“1:215,4:216”},“7”:{“processList”:“1:218,4:219”},“8”:{“processList”:“1:221,4:222”},“9”:{“processList”:“1:224,4:225”}}
I’m on the latest GITHUB master version as of 12/23/2017 (basically 9.8.27), with graph from 12/30/2017 (which has some of the “stack” options)
Thanks again,
Sandy
P.S. What are you doing answering email @ 11:00!! (I’m in MST, so a slight excuse)

overeasy · 4 January 2018 04:35

No bother. I see the problem. Your Emoncms isn’t including the time of the last update. I need to follow up with Trystan to understand why your Emoncms doesn’t return the time of last update. Without that, the IoTaWatt will start with the current time, hence the gap.

blaal02 · 4 January 2018 17:46

Hi Bob,
One thought; I don’t have Redis running on this machine. Could it be required for this particular API call?
Thanks, Sandy

overeasy · 4 January 2018 18:34

I doubt it. I’ve checked my Emonpi and it is returning the expected response. I’ve put in a request for clarification of this function with the developer. Hopefully, he can shed some light on why your installation doesn’t respond as the others, and whether this is something new or old.

Would it be possible to put up a screen shot that shows the API response in your browser window with the associated URL also visible? You can omit the apikey in the URL if you logon to Emoncms from another window. Not to diminish your assertion that it’s as I requested, but I’ve been in this business along time…

blaal02 · 4 January 2018 18:42

Hi Bob,
No problem, I’ve been caught that kind of way before too. Like this?

(It’s an internal network, so not really worried about the api key)
Thanks, Sandy

overeasy · 4 January 2018 19:18

@blaal02,
Sandy,
Trystan got back to me and it looks like you were on to something with Redis not running. He put through a PR to fix the response w/o Redis:

Could you mark this resolved if this solves your problem?

Bob

overeasy · 4 January 2018 19:24

Hi Brian,

See above with respect to holes in data upload after restart. Seems to be related to not running Redis. I suspect that’s your problem as well. If this fixes your gaps in upload, I’m going to let the timeout error problem ride because the fix is a pretty major change that is in progress but will take some time to roll out safely. The restarts should not be an issue for you once the upload gap problem is remediated.

Let me know if this doesn’t fix the upload problem or the communication/restart problem becomes a significant problem.

Bob

blaal02 · 4 January 2018 20:25

Hi Bob, @TrystanLea,
Looking hopeful! Here are the new results from that API call:

And my IoTaWatt seems to be heading for a restart (28 mins since last data) so we should see quite soon if it fills in the gaps!
Thanks everyone for such a quick response/resolution!!
Sandy
P.S. I have nothing against installing Redis (I have had it working on Windows before). I just hadn’t done it since I hadn’t found a need yet (or at least I didn’t think I had!)

blaal02 · 4 January 2018 21:30

Hi Bob, Trystan,
All looks good! The IoTaWatt recovered on the 10th resend, and went back & filled in the bit that had been missed.
Incidentally, I think I found where the timeouts were coming from - Windows Defender seemed to be rather too enthusiastic about scanning the PHP files; I was seeing some 6 second response times to the IoTaWatt postings.
So, next question(!!)…
Now that logging (normal & restarted) is working nicely, is there a way to clear the feeds so that the IoTaWatt will recreate the data from the beginning (without the gaps)? Maybe delete, clear or overwrite with an ‘empty’ file all the appropriate phpfina???.dat files?
Thanks a lot,
Sandy

overeasy · 5 January 2018 00:08

Yes and no. The IoTaWatt has all of the data and under the right circumstances will upload it all. Unfortunately there’s no UI to make that happen. Given the status-quo, hetre’s how I’d approach it…

As indicated by this problem, the IoTaWatt resumes posting from the time of the last input posted to the node. So:

Stop IoTaWatt posting by changing the server to NONE.
Delete all of the Emoncms feeds and inputs on the node.
Look at your IoTaWatt status display, expanding the datalog tab. Pump the start date and time into one of the unixtime converters available on the internet. Use that (add 60 seconds or so to be sure) and use that as the time to create a single feed entry on the node using the the URL:
192.168.2.44/input/post?node=IotaWatt&time=<unixstarttime>,csv=0,apikey=<yourapi>
Now configure the IoTaWatt server for that nodename. It should start at the time you used in the above input/post and bulk update to the present.

Don’t worry about interrupting the process, once started, it will continue to plug away and restart where it leaves off.

May take a few hours, but will get the job done.

Edit: An afterthought is that you can do this without deleting the current inputs and feeds by just using a new node name, creating it with that single backdated entry… Then if all goes well, you can delete the old. If not, just change the nodename of the server to the old name and it will update that node from where it left off, as if nothing had happened.

Bschaaf · 5 January 2018 01:17

Thanks so much Bob, Trystan, and Sandy — I’ve made the change to my local emoncms. As luck would have it, the IoTaWatt has run for more than 24 hours without a reset, so I’ll let you know if this doesn’t solve the upload problem. BTW — I’ve been so impressed with my emonTx shield, your OpenEnergyMonitor.com site, emoncms and now the IoTaWatt! Thanks again, Brian