So Brian had me run a tshark check looking for http request and response. I can see both of the OpenEVSE replies but there never is one from the IP address for Iotawatt. One thing I need to do before I do anything else is probably run a reboot on the router. I hadn’t thought of that but that could be the cause of this.
According to Brian the lack of a request or reply from Iotawatt means the problem is not from EmonCMS.
Anything on this?
Again, I’d like to know what the column headers are in that shark log above. It shows an input/bulk post from 192.168.1.13 which is what IoTaWatt would be doing and an response of OK some time later which I suspect is 4 seconds, which is consistent with a timeout (-11) from IoTaWatt.
Your message log above says your time zone is +5. You just said the problem occurred at 12:50pm EST, which is time zone -5. Where are you located and what is your local timezone?
I saw your post over on the other thread in the EmonCMS message board. Hopefully Brian can shed some light on the tshark logs. My timezone is -5 EST. You mentioned that the message log states that my timezone is +5. Any chance that could be the cause?
No. Was it changed recently?
I didn’t mess with it since the time I set it upa few months back. The only thing I did recently to it was at another input to monitor my well pump. But I didn’t mess with the time zone.
@overeasy I have a question regarding the web server sending information to EmonCMS. If I stop the server on the status page does the system still continue to record the outputs for the web server or is that also stopped?basically if I stop it and then restart it later will it upload the information between the stop time and the start time to the web server or is there a gap?
There would be no gap.
Hi Bob, Ryan,
I’ve been seeing something similar to this (HTTP -11) for the last month or so. But just got around working on it. Installed new Emoncms (10.1.9+) on new server; same -11 issue. Checked the web server logs & found really long Emoncms response times; 15 seconds! - so not surprising -11’s. Looked like a lot of the issue was the AV monitor checking the data files, added exceptions & down to 3 seconds - which works, IoTaWatt updates/catch-up are now happening (though slowly) - still some -11s, but eventually, successful retries.
Reporting to my Emoncms instance, I have one IoTaWatt and (via an Emon Hub) a couple of EmonTXs & several EmonTHs. Again, from the web server log, the API that EmonHub is using takes 300-400ms, the IoTaWatt API is taking 10 times longer. I tried bulk send anything from 1 to 10, and that doesn’t seem to make any difference.
2019-11-11 17:58:01 192.168.2.3 POST /emoncms/input/bulk.json apikey=xxxxxxxxxxxxxx 80 - 192.168.2.24 Python-urllib/2.7 - 200 0 0 413 2019-11-11 17:58:01 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 3055 2019-11-11 17:58:07 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2938 2019-11-11 17:58:11 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2954 2019-11-11 17:58:15 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 3000 2019-11-11 17:58:20 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2986 2019-11-11 17:58:24 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 0 3005 2019-11-11 17:58:27 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2964 2019-11-11 17:58:32 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2965 2019-11-11 17:58:32 192.168.2.3 POST /emoncms/input/bulk.json apikey=xxxxxxxxxxxxxx 80 - 192.168.2.24 Python-urllib/2.7 - 200 0 0 375 2019-11-11 17:58:36 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 0 3019 2019-11-11 17:58:40 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2931 2019-11-11 17:58:44 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 0 3000 2019-11-11 17:58:48 192.168.2.3 POST /emoncms/input/bulk - 80 - 192.168.2.27 - - 200 0 64 2965
In this log, the last number is the response time. 192.168.2.24 is the EmonHub, 192.168.2.27 is the IoTaWatt.
My server environment is a little unusual (I think anyway), Windows, IIS, PHP7, MariaDB - so not sure if these observations generalize.
Thanks,
Sandy
Hello Sandy,
I can see that the emonhub is using a slightly different bulk protocol, but i don’t think that is the difference. Looking at the time stamps, IoTaWatt is doing a transaction about every 4 seconds. There are only two ways that’s possible:
If the transactions are timing out and being retried.
If you are bulk uploading history during recovery.
I’m going to go with the timeouts. Even though the log shows HTTP 200 completion, if that is issued after the IoTaWatt times out the operation it gets ignored. And so I think what’s going on there is Emoncms is taking 3 seconds to respond, IoTaWatt times out after 2, and so the operation is retried. Eventually I gather it does succeed. The error message is only issued once after 30 retries, and if so there should be another message containing the total retry count when it eventually succeeds.
Probably the difference between IoTaWatt and the Emonhub is that the hub is probably sending just a single set of 4 values, and IoTaWatt is sending more values and because it’s constantly recovering, multiple “frames” - sets of values for multiple times
Hi Bob,
Actually, case 2 - It’s still tying to catch up from Oct 15th! (Though there seem to be timeouts involved also)
And it is getting there - up to the 19th now.
And yes, it gets the -11’s, retries & eventually succeeds:
SD initialized.
11/11/19 17:31:36z Real Time Clock is running. Unix time 1573493496
11/11/19 17:31:36z Reset reason: Software/System restart
11/11/19 17:31:36z Trace: 8:9, 9:3, 9:5, 9:9, 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[4], 1:2[5], 9:0[5], 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
11/11/19 17:31:36z ESP8266 ChipID: 2870702
11/11/19 17:31:37z IoTaWatt 4.x, Firmware version 02_05_01
11/11/19 17:31:37z SPIFFS mounted.
11/11/19 10:31:38 Local time zone: -7:00
11/11/19 10:31:38 Using Daylight Saving Time (BST) when in effect.
11/11/19 10:31:38 device name: IotaWatt
11/11/19 10:31:38 MDNS responder started for hostname IotaWatt
11/11/19 10:31:39 LLMNR responder started for hostname IotaWatt
11/11/19 10:31:39 HTTP server started
11/11/19 10:31:39 WiFi connected. SSID=BLACKBURN, IP=192.168.2.27, channel=6, RSSI -58db
11/11/19 10:31:39 timeSync: service started.
11/11/19 10:31:40 statService: started.
11/11/19 10:31:40 Updater: service started. Auto-update class is ALPHA
11/11/19 10:31:40 dataLog: service started.
11/11/19 10:31:45 dataLog: Last log entry 11/11/19 10:31:30
11/11/19 10:31:45 Updater: Auto-update is current for class ALPHA.
11/11/19 10:31:45 EmonService: started. url=192.168.2.3:80/emoncms, node=IotaWatt, interval=10
11/11/19 10:31:47 EmonService: Start posting at 10/17/19 16:15:00
11/11/19 10:32:40 historyLog: service started.
11/11/19 10:32:41 historyLog: Last log entry 11/11/19 10:31:00
11/11/19 11:01:43 EmonService: HTTP response -11, retrying.
11/11/19 11:03:44 EmonService: Retry successful after 47 attempts.
11/11/19 11:07:50 EmonService: HTTP response -11, retrying.
11/11/19 11:09:20 EmonService: Retry successful after 43 attempts.
11/11/19 11:13:41 EmonService: HTTP response -11, retrying.
11/11/19 11:22:58 EmonService: Retry successful after 92 attempts.
11/11/19 11:30:35 EmonService: HTTP response -11, retrying.
11/11/19 11:31:17 EmonService: Retry successful after 36 attempts.
11/11/19 11:41:33 EmonService: HTTP response -11, retrying.
11/11/19 11:48:38 EmonService: Retry successful after 80 attempts.
11/11/19 11:50:47 EmonService: HTTP response -11, retrying.
11/11/19 11:51:13 EmonService: Retry successful after 33 attempts.
11/11/19 11:55:39 EmonService: HTTP response -11, retrying.
11/11/19 11:57:19 EmonService: Retry successful after 44 attempts.
11/11/19 12:07:35 EmonService: HTTP response -11, retrying.
11/11/19 12:09:00 EmonService: Retry successful after 42 attempts.
11/11/19 13:39:09 EmonService: HTTP response -11, retrying.
11/11/19 13:40:06 EmonService: Retry successful after 38 attempts.
It just seems like Ryan & I are having similar symptoms; HTTP -11’s caused by slow Emoncms response.
IoTaWatt seems to be behaving quite reasonably, the -11’s seem right (though being able to extend the 2 second timeout slightly might be nice - and actually, my response times all look like ~3 seconds, so I’m wondering why it’s working as well as it is!), the main problem is why Emoncms is so slow!
So we’re both right. It’s timing out while doing bulk recovery. As I understand it, Emoncms takes the bulk input and breaks it down into a bunch of individual updates. Each one requires running the input processes to generate feed data that gets queued to be posted to the database. A typical IoTaWatt recovery request can have hundreds of these. I’m not sure when the original input post gets acknowledged, but i suspect it’s after some or all of that processing is done. Emoncms.org is pretty fast and handles that easily. Local instances can be a lot slower.
I think those response times will be better and the timeouts will stop after it catches up. The Emonhub has, as I understand it, has limited in memory buffering for backlog, and so history gets lost in any significant outage.
Sorry about the long delay on following up. I got a RPi 3 to give me a boost in horsepower for this. Turns out I needed a better power supply and the one I ordered from Sparkfun came on the slow boat to here. Finally got it here and loaded EmonCMS up and onto an external HDD. Just got it up and running now. Next step is to rebuild the database. Unfortunately, I accidentally deleted my backup, so I now have to rebuild it completely. Will see if this clean slate means things are working again or timing out.
Ok, got IotaWatt back to loading the inputs again. The log time is counting down. I did check in the message log and saw this EmonService: get input list failing, code: -4 . Not sure if I should worry about that or if it’s just reporting that IotaWatt sent a request for the last piece of data EmonCMS to check and EmonCMS reported a failure so it is now loading the entire database figuring it was lost.
You can see where it is in the Emoncms dropdown tab in the status display. You would also see the Emoncms input values changing as new data is posted.
The -4 is failure to connect. That could have been transient as it will continue to retry, or it could be indicative of a persistent problem. If you see progress as described above, it’s probably transient.
I do see the inputs changing. Question, does it send current data along with the historical data? Or does it start at the beginning and work its way forward?
It just picks up where it left off, in this case the beginning, and marches forward toward the present.
That works for me. Starting back in July means this might take awhile. Gives me time to rebuild the feeds.