21

I also changed the log setting. Here is the latest.

LAST ENTRIES ON THE LOG FILE
2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.937|INFO|feed_model.php|insert_data() feedid=30 updatetime=1572281845 feedtime=1572281845 value=0.77 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:01.901|INFO|feed_model.php|insert_data() feedid=22 updatetime=1572281845 feedtime=1572281845 value=829.58 arg=
2019-10-29 20:50:01.937|INFO|feed_model.php|insert_data() feedid=30 updatetime=1572281845 feedtime=1572281845 value=0.77 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:01.848|INFO|feed_model.php|insert_data() feedid=63 updatetime=1572281845 feedtime=1572281845 value=241.8 arg=
2019-10-29 20:50:01.883|INFO|feed_model.php|insert_data() feedid=62 updatetime=1572281880 feedtime=1572281880 value=233.86800362363 arg=join
2019-10-29 20:50:01.901|INFO|feed_model.php|insert_data() feedid=22 updatetime=1572281845 feedtime=1572281845 value=829.58 arg=
2019-10-29 20:50:01.901|INFO|feed_model.php|insert_data() feedid=22 updatetime=1572281845 feedtime=1572281845 value=829.58 arg=
2019-10-29 20:50:01.901|INFO|feed_model.php|insert_data() feedid=22 updatetime=1572281845 feedtime=1572281845 value=829.58 arg=
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=
2019-10-29 20:50:01.848|INFO|feed_model.php|insert_data() feedid=63 updatetime=1572281845 feedtime=1572281845 value=241.8 arg=
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=
2019-10-29 20:50:01.756|INFO|feed_model.php|insert_data() feedid=61 updatetime=1572281880 feedtime=1572281880 value=1627.4049431641 arg=join
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=
2019-10-29 20:50:01.848|INFO|feed_model.php|insert_data() feedid=63 updatetime=1572281845 feedtime=1572281845 value=241.8 arg=
2019-10-29 20:50:01.848|INFO|feed_model.php|insert_data() feedid=63 updatetime=1572281845 feedtime=1572281845 value=241.8 arg=
2019-10-29 20:50:01.797|INFO|feed_model.php|insert_data() feedid=29 updatetime=1572281845 feedtime=1572281845 value=120.9 arg=

22

I’m also looking at the log now in /var/log/emoncms and I can see values that look like what the IotaWatt should be passing to it, so it appears something is being recieved, but for some reason the EmonCMS is sending back an error or not acknowledging the receipt.

23 
sudo tshark tcp port 80

will show you the responses as well.

Even better

sudo tshark -Y "http.request || http.response"
24

Here is the IotaWatt line from that.

194 60.238194461 192.168.1.13 → 192.168.1.21 TCP 1514 POST HTTP://192.168.1.21/emoncms/input/bulk HTTP/1.1 [TCP segment of a reassembled PDU]
195 60.238477453 192.168.1.21 → 192.168.1.13 TCP 54 80 → 49267 [ACK] Seq=1 Ack=1461 Win=32120 Len=0
196 60.261928811 192.168.1.13 → 192.168.1.21 HTTP 1363 POST HTTP://192.168.1.21/emoncms/input/bulk HTTP/1.1 (application/x-www-form-urlencoded)
197 60.262048808 192.168.1.21 → 192.168.1.13 TCP 54 80 → 49267 [ACK] Seq=1 Ack=2770 Win=35040 Len=0
199 62.929419779 192.168.1.13 → 192.168.1.21 TCP 60 49267 → 80 [FIN, ACK] Seq=2770 Ack=1 Win=5840 Len=0
200 62.978935424 192.168.1.21 → 192.168.1.13 TCP 54 80 → 49267 [ACK] Seq=1 Ack=2771 Win=35040 Len=0
201 64.265328209 192.168.1.21 → 192.168.1.13 HTTP 205 HTTP/1.1 200 OK (text/plain)
202 64.265989190 192.168.1.21 → 192.168.1.13 TCP 54 80 → 49267 [FIN, ACK] Seq=152 Ack=2771 Win=35040 Len=0
203 64.273891974 192.168.1.13 → 192.168.1.21 TCP 60 49267 → 80 [RST, ACK] Seq=2771 Ack=152 Win=5840 Len=0
204 64.274224965 192.168.1.13 → 192.168.1.21 TCP 60 49267 → 80 [RST, ACK] Seq=2771 Ack=153 Win=5840 Len=0

25

So emoncms is sending back an OK.

[edit] - You should therefore be seeing the inputs changing in emoncms.

26

Unfortunately it is not.

image
image1071×267 21.2 KB

Is there anything else I could check on this? Could it be that IotaWatt is misreading the ok sent and it just resending the same data causing it to not post?

27

Oh fig.

That HTTP call you see is not the iotawatt. Do you actually see on tshark an HTTP request from iotawatt?

If not the problem is not with emoncms.

28

Ok, just performed the tshark with the second way you recommended.
“sudo tshark -Y “http.request || http.response””

With that I do not see IotaWatt sending anything. IotaWatt is on 192.168.1.13 and according to tshark on EmonCMS there is not request or response.

I do show the two OpenEVSE in this.

1 0.000000000  192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1 
3 0.041808652 192.168.1.21 → 192.168.1.8  HTTP 633 HTTP/1.1 200 OK  (application/json)

11 0.055397214 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
13 0.233061484 192.168.1.21 → 192.168.1.8 HTTP 1411 HTTP/1.1 200 OK (application/json)
36 4.998914789 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
38 5.051542092 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
40 5.074601349 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
42 5.252803602 192.168.1.21 → 192.168.1.8 HTTP 1410 HTTP/1.1 200 OK (application/json)
60 10.000054538 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
62 10.058299660 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
64 10.071507234 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
66 10.274793680 192.168.1.21 → 192.168.1.8 HTTP 1410 HTTP/1.1 200 OK (application/json)
84 15.000813329 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
86 15.074431956 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
88 15.092160385 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
90 15.330230711 192.168.1.21 → 192.168.1.8 HTTP 1410 HTTP/1.1 200 OK (application/json)
111 18.476932288 192.168.1.15 → 192.168.1.21 HTTP 391 GET /emoncms/input/post.json?node=openevse2&json={“amp”:0,“wh”:3751096,“temp1”:200,“temp2”:-2560,“temp3”:-2560,“pilot”:40,“state”:1,“freeram”:27800,“divertmode”:1}&apikey=5e7bdc1f53551a96b0a4f658443d0d5f HTTP/1.1
113 18.757877234 192.168.1.21 → 192.168.1.15 HTTP 224 HTTP/1.1 200 OK (text/plain)
124 19.998109263 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
126 20.042641828 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
128 20.055361418 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
130 20.226477903 192.168.1.21 → 192.168.1.8 HTTP 1415 HTTP/1.1 200 OK (application/json)
150 24.996655187 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
152 25.068279879 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
154 25.084067370 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
156 25.274318240 192.168.1.21 → 192.168.1.8 HTTP 1415 HTTP/1.1 200 OK (application/json)
177 28.823518888 192.168.1.11 → 192.168.1.21 HTTP 391 GET /emoncms/input/post.json?node=openevse1&json={“amp”:0,“wh”:1573990,“temp1”:365,“temp2”:-2560,“temp3”:-2560,“pilot”:40,“state”:2,“freeram”:27944,“divertmode”:1}&apikey=5e7bdc1f53551a96b0a4f658443d0d5f HTTP/1.1
179 29.097997045 192.168.1.21 → 192.168.1.11 HTTP 224 HTTP/1.1 200 OK (text/plain)
190 29.992415230 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
192 30.035634838 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
194 30.046856476 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
196 30.223620782 192.168.1.21 → 192.168.1.8 HTTP 1414 HTTP/1.1 200 OK (application/json)
219 35.002648837 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
221 35.059006022 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
223 35.080151341 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
225 35.286218704 192.168.1.21 → 192.168.1.8 HTTP 1414 HTTP/1.1 200 OK (application/json)
243 39.995947019 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
245 40.040907571 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
247 40.053334171 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
249 40.224029674 192.168.1.21 → 192.168.1.8 HTTP 1414 HTTP/1.1 200 OK (application/json)
268 44.998681927 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
270 45.080732285 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
272 45.094608838 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
274 45.314164769 192.168.1.21 → 192.168.1.8 HTTP 1414 HTTP/1.1 200 OK (application/json)
295 48.791674808 192.168.1.15 → 192.168.1.21 HTTP 391 GET /emoncms/input/post.json?node=openevse2&json={“amp”:0,“wh”:3751096,“temp1”:200,“temp2”:-2560,“temp3”:-2560,“pilot”:40,“state”:1,“freeram”:27744,“divertmode”:1}&apikey=5e7bdc1f53551a96b0a4f658443d0d5f HTTP/1.1
297 49.148931307 192.168.1.21 → 192.168.1.15 HTTP 224 HTTP/1.1 200 OK (text/plain)
308 49.997524988 192.168.1.8 → 192.168.1.21 HTTP 563 GET /emoncms/device/list.json HTTP/1.1
310 50.066788758 192.168.1.21 → 192.168.1.8 HTTP 669 HTTP/1.1 200 OK (application/json)
312 50.076151457 192.168.1.8 → 192.168.1.21 HTTP 562 GET /emoncms/input/list.json HTTP/1.1
318 50.188250848 192.168.1.13 → 192.168.1.21 HTTP 1363 POST HTTP://192.168.1.21/emoncms/input/bulk HTTP/1.1 (application/x-www-form-urlencoded)
320 50.325613426 192.168.1.21 → 192.168.1.8 HTTP 1415 HTTP/1.1 200 OK (application/json)
346 54.142453563 192.168.1.21 → 192.168.1.13 HTTP 205 HTTP/1.1 200 OK (text/plain)

29

So it isn’t an emoncms issue if the HTTP request is never reaching that machine. I suggest you ask further on the IotaWatt forum although my guess is an internal network issue.

Have you rebooted your WiFi router?

30

Not yet, honestly I hadn’t thought of that. I’ll do that next. Would seem all that everything else is working though and that’s the only thing that’s not but I can’t say it’s unheard of.

31

@Ryan_S, @borpin,

First, thanks to @borpin for the contribution top this issue. While it’s not quite resolved, the effort to secure shark logs has provided some key information. At the same time @Ryan_S has been posting to a similar thread in the IoTaWatt Forum https://community.iotawatt.com/t/not-posting-to-emoncms/1348

This morning I received a key piece of information that has, I think, brought this into better focus. The local timezone in the IoTaWatt appears to be set to UTC+5 hours while it should be UTC-5, and with DST the difference is -9 hours. That has no bearing on the IoTaWatt/Emoncms link as both are using UTC, but it does resolve discrepancies in the IoTaWatt log that are timestamped with the wrong local time.

So the background is that this user attempted an update to his local Emoncms sometime the morning of Oct 28. The exact time is uncertain by the details offered, in fact, this was not even mentioned in the original report but came out a day later. In hindsight, I believe the problem originates there.

The IoTaWatt log covering that period:

image
image737×646 16.2 KB

Note that while the log begins with UTC (z), the timestamps change to local time after the config is processed to declare local time +5. Those subsequent timestamps should be -9 hours.

So the system was restarted by the user at 11:12:53 EDT on Oct 28. It was running OK with Emoncms posting from just before the restart at 11:12:50. Then at 12:52:52 communication to Emoncms began to timeout (-11 is an IoTaWatt timeout indication). After 1.5 hours of normal operation, this problem begins spontaneously i.e. nothing remarkable being logged.

Subsequently, everytime the IoTaWatt is restarted, it successfully obtains a list of inputs from Emoncms. That list contains the last post time for each of the inputs, and IoTaWatt assumes those inputs were processed to feeds. So it begins uploading with the next frame. But that subsequent upload times out, and as the IoTaWatt continues to retry, the retries also time-out. IoTaWatt times out after two seconds without a response.

To reinforce this scenario, the /input/bulk transaction contains 15 frames at 5 second intervals covering 75 seconds. Each time the IoTaWatt restarts, the last input timestamp advances by 75 seconds, indicating that the input was updated with the new data.

Now the shark tank from the tshark log above:

image
image699×410 13.7 KB

Here we see an /input/bulk from IoTaWatt. The first is the connection followed by the payload. I’m not familiar with the format, but I’m taking a leap here to guess that the second column is the time in seconds. So after the ACK to the connection the payload followed within 23ms. The subsequent payload transfer seems to have taken longer at about 2717ms. Emoncms responds OK after about 4 seconds from the initial connect. That’s too long. IoTaWatt has already timed out.

Now the question is “What’s the holdup?”

  • It could be the router as Brian’s last post suggests, but I doubt it.
  • It could be the server that Emoncms is running on, more likely.
  • It could be Emoncms is having database trouble (Im getting out of my comfort zone here) and it takes a long time to post the inputs.

Another piece of the puzzle seems to be evident in the sample of Emoncms log that was posted:

2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.937|INFO|feed_model.php|insert_data() feedid=30 updatetime=1572281845 feedtime=1572281845 value=0.77 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:02.004|INFO|feed_model.php|insert_data() feedid=23 updatetime=1572281845 feedtime=1572281845 value=19.28 arg=
2019-10-29 20:50:01.966|INFO|feed_model.php|insert_data() feedid=31 updatetime=1572281845 feedtime=1572281845 value=5.62 arg=
2019-10-29 20:50:01.901|INFO|feed_model.php|insert_data() feedid=22 updatetime=1572281845

I don’t understand all of this, but my sense is that it’s a log of data being sent from the inputs to the feeds. This snapshot is taken the next day, yet the timestamps for the data are Oct 28, 12:57pm EDT, which is consistent with the advanced input time resulting from several 75 second restart advances.

So to sum up, it appears that something has happened to the Emoncms server that causes consistently delayed responses outside of the 2 minute time-out window. My sense is that it’s an installation/configuration issue rather than a bug in either software. The two second time-out has been in place for a long time, with both local and remote Emoncms systems experiencing an occasional timeout that is retried and recovered. That’s preferred to leaving an operation hanging with associated buffers for extended periods because it consumes limited resources in IoTaWatt that may be needed to post to other servers or do internal housekeeping.

I would look at performing a clean install of Emoncms.

32

I should add, the server EmonCMS is running on it a Raspberry Pi single processor. Don’t suppose maybe I’m expecting to much of the little thing and should upgrade it?

33

Once again, what has changed? If that was working before, it’s probably not the culprit, although you may have an issue with something happening to the file-system on the SDcard when you “updated”.

34

Very possible. A reinstall is an option in the end. Need to see if I can backup my dashboards and apps and inputs before I do it as I don’t want to rebuild all of that. Does the Iotawatt reload all of the history or only a chuck?

35

@Ryan_S, have you checked the current time of the Pi?

I would also therefore look at htop and see if there is a process hogging the processor causing emoncms to time out.

Secondly, I’d run a couple of terminals and watch the iotawatt log (if you can), the emoncms.log and the tshark trace at the same time.

I don’t think a fresh install will solve this personally, not if the existing feeds etc are imported.

Ah I wonder, @overeasy, does the Iotawatt buffer data and then try to upload all of the outstanding data in one go? That might overload the inputs if there was a lot of outstanding data I’d suggest.

@Ryan_S, I asked previously what feedIDs the IotaWatt feeds were - is this an IotaWatt feed?

Yes AFAIK.

36

Not yet, when I get home I plan to check the time on both the IotaWatt and Raspberry Pi EmonCMS. Reboot the router and see if that fixes it. Then if not, I guess perform a backup of the dashboards, apps and configurations and reinstall EmonCMS.

37

I’m not sure that will solve the issue.

38

I would certainly prefer to solve and save the data in there verses risking losing it. I can ssh in 2 terminal windows with one on htop and the other on tshark. Also can keep an eye on the Iotawatt log, and if possible activate a more detailed log to see what might be going on.

That does look like one, possibly the current measurement of the whole house. I am not in front of the EmonCMS at this time to verify, but I will when I get home.

39

No, Brian, it doesn’t work like that. It uploads whatever will fit in a modest buffer (dynamic). In this case, that’s 15 “frames” of 15 sets of inputs from 15 consecutive 5 second intervals. In the past, @TrystanLea has suggested that the more frames the better, but that may just apply to Emoncms.org.

The IoTaWatt doesn’t “buffer” the historic data in the sense that, for instance, the ESPHUB buffers in memory. IoTaWatt has a 5 second resolution datastore, functionally equivalent to Emoncms with respect to time-series-database. The historic upload, and even the real time uploads, are scraped from that.

Ryan should be able to access all of his data, and produce plots and downloads, directly from IoTaWatt. It’s still chugging away and working fine, and once this communication isuue is resolved, his Emoncms should be seamlessly restored.

IoTaWatt doesn’t feal with feed, only inputs. They are identified using the older ordinal system 01, 02 etc.

40

Yes I realise that - no system does, it was whether that feed log was as a result of an IotaWatt input.

I’m at my limit of the internal workings of Emoncms now.