21

We are AEST (+10) here. 10 hours back in the syslog there are no relevant errors either. :frowning_face:

22

If you tail both logs, you can check on the ‘current’ time recorded so match them.

I think the problem is that the emonPi is not able to find emoncms.org and that interfacer then crashes but I would expect to see log entries.

Are you fully up to date?

Can you please do

systemctl status emonhub.service

and post output.

23

I restarted emonhub yesterday. Do you want to wait until it stops again before running the systemctl command?

24

No that will give the status of the service.

25

I checked the emonhub and syslog files, they are using the same timezones for their timestamps.
I did a full update 11 days ago, just before this issue became evident. I ran a full update again today to make my system is up to date.
I ran the systemctl command pre today’s update. The result follows.

pi@emonpi:~ $ systemctl status emonhub.service
● emonhub.service - emonHub service description
   Loaded: loaded (/opt/openenergymonitor/emonhub/service/emonhub.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2020-07-02 05:31:10 AEST; 1 day 12h ago
  Process: 10328 ExecStartPre=/bin/mkdir -p /var/log/emonhub/ (code=exited, status=0/SUCCESS)
  Process: 10329 ExecStartPre=/bin/chgrp -R emonhub /var/log/emonhub/ (code=exited, status=0/SUCCESS)
  Process: 10330 ExecStartPre=/bin/chmod 775 /var/log/emonhub/ (code=exited, status=0/SUCCESS)
 Main PID: 10331 (python3)
    Tasks: 4 (limit: 2319)
   Memory: 15.1M
   CGroup: /system.slice/emonhub.service
           └─10331 python3 /usr/local/bin/emonhub/emonhub.py --config-file=/etc/emonhub/emonhub.conf --logfile=/var/log/emonhub/emonhub.log

Jul 02 05:31:10 emonpi systemd[1]: Starting emonHub service description...
Jul 02 05:31:10 emonpi systemd[1]: Started emonHub service description.

And ran it again post update (just for good measure) and those results follow.

pi@emonpi:~ $ systemctl status emonhub.service
● emonhub.service - emonHub service description
   Loaded: loaded (/opt/openenergymonitor/emonhub/service/emonhub.service; enabled; vendor preset: enabled)
   Active: active (running) since Fri 2020-07-03 17:58:20 AEST; 6min ago
  Process: 29365 ExecStartPre=/bin/mkdir -p /var/log/emonhub/ (code=exited, status=0/SUCCESS)
  Process: 29366 ExecStartPre=/bin/chgrp -R emonhub /var/log/emonhub/ (code=exited, status=0/SUCCESS)
  Process: 29367 ExecStartPre=/bin/chmod 775 /var/log/emonhub/ (code=exited, status=0/SUCCESS)
 Main PID: 29368 (python3)
    Tasks: 4 (limit: 2319)
   Memory: 12.9M
   CGroup: /system.slice/emonhub.service
           └─29368 python3 /usr/local/bin/emonhub/emonhub.py --config-file=/etc/emonhub/emonhub.conf --logfile=/var/log/emonhub/emonhub.log

Jul 03 17:58:20 emonpi systemd[1]: Starting emonHub service description...
Jul 03 17:58:20 emonpi systemd[1]: Started emonHub service description.

Of note it has now been nearly 2 days since things played up.

26

@bwduncan - could the move to Python3 impact how a ‘no host found’ error is handled?

I also raised this Issue which is related.

27

No stoppages since 1 July. I will post again if the problems reoccurs.
Thank you for your help.

1 Like
28

Hi Brian (@borpin),
The problem occurred again approximately 48 hrs ago. The log extract at the point where it stopped is as follows. This time the send failure is recorded.

2020-07-27 20:36:44,878 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1595846182.943008,15,314216,240.85,50,0,0,363,0,860136,58103,829449,0,-0.02,-0.02,0.6,0,10,300,300,300,0,0,-67],[1595846192.9315205,15,314217,240.84,49.99,0,0,363,0,860136,58103,829450,0,-0.03,-0.02,0.6,0,10,300,300,300,0,0,-67],[1595846203.0156538,15,314218,240.84,50,0,0,363,0,860136,58103,829451,0,-0.02,-0.02,0.6,0,10,300,300,300,0,0,-66]]&sentat=1595846204
2020-07-27 20:36:53,305 INFO     MQTT       Publishing: emonhub/rx/15/values 314219,240.70000000000002,49.99,0,0,575,0,860136,58103,829453,0,-0.02,-0.02,0.77,0,10,300,300,300,0,0,-66
2020-07-27 20:37:03,230 INFO     MQTT       Publishing: emonhub/rx/15/values 314220,240.68,50,0,0,542,0,860136,58103,829454,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:37:13,256 INFO     MQTT       Publishing: emonhub/rx/15/values 314221,240.67000000000002,49.99,0,0,544,0,860136,58103,829456,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:37:16,911 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1595846213.0095506,15,314219,240.70000000000002,49.99,0,0,575,0,860136,58103,829453,0,-0.02,-0.02,0.77,0,10,300,300,300,0,0,-66],[1595846222.9820852,15,314220,240.68,50,0,0,542,0,860136,58103,829454,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66],[1595846232.9721324,15,314221,240.67000000000002,49.99,0,0,544,0,860136,58103,829456,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67]]&sentat=1595846236
2020-07-27 20:37:23,187 INFO     MQTT       Publishing: emonhub/rx/15/values 314222,240.67000000000002,49.99,0,0,545,0,860136,58103,829457,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-68
2020-07-27 20:37:26,932 WARNING  emoncmsorg emoncmsorg couldn't send to server: HTTPSConnectionPool(host='emoncms.org', port=443): Max retries exceeded with url: /input/bulk.json?apikey=1b41066907733c56b683845256988cf7 (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x75e7bb70>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution'))
2020-07-27 20:37:26,933 WARNING  emoncmsorg send failure: wanted 'ok' but got 'None'
2020-07-27 20:37:33,194 INFO     MQTT       Publishing: emonhub/rx/15/values 314223,240.67000000000002,50,0,0,543,0,860136,58103,829459,0,-0.03,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:37:43,209 INFO     MQTT       Publishing: emonhub/rx/15/values 314224,240.68,50,0,0,541,0,860136,58103,829460,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:37:53,115 INFO     MQTT       Publishing: emonhub/rx/15/values 314225,240.68,49.99,0,0,540,0,860136,58103,829462,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:37:56,964 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1595846213.0095506,15,314219,240.70000000000002,49.99,0,0,575,0,860136,58103,829453,0,-0.02,-0.02,0.77,0,10,300,300,300,0,0,-66],[1595846222.9820852,15,314220,240.68,50,0,0,542,0,860136,58103,829454,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66],[1595846232.9721324,15,314221,240.67000000000002,49.99,0,0,544,0,860136,58103,829456,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67],[1595846242.9700146,15,314222,240.67000000000002,49.99,0,0,545,0,860136,58103,829457,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-68],[1595846252.95848,15,314223,240.67000000000002,50,0,0,543,0,860136,58103,829459,0,-0.03,-0.02,0.88,0,10,300,300,300,0,0,-67],[1595846263.0282502,15,314224,240.68,50,0,0,541,0,860136,58103,829460,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67],[1595846273.0075676,15,314225,240.68,49.99,0,0,540,0,860136,58103,829462,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67]]&sentat=1595846276
2020-07-27 20:38:03,123 INFO     MQTT       Publishing: emonhub/rx/15/values 314226,240.68,50,0,0,540,0,860136,58103,829463,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:38:13,147 INFO     MQTT       Publishing: emonhub/rx/15/values 314227,240.67000000000002,50,0,0,538,0,860136,58103,829465,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:38:23,057 INFO     MQTT       Publishing: emonhub/rx/15/values 314228,240.65,49.99,0,0,538,0,860136,58103,829466,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:38:33,070 INFO     MQTT       Publishing: emonhub/rx/15/values 314229,240.66,50,0,0,537,0,860136,58103,829468,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-65
2020-07-27 20:38:43,266 INFO     MQTT       Publishing: emonhub/rx/15/values 314230,240.65,50,0,0,536,0,860136,58103,829469,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:38:53,173 INFO     MQTT       Publishing: emonhub/rx/15/values 314231,240.65,50,0,0,534,0,860136,58103,829471,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:39:03,161 INFO     MQTT       Publishing: emonhub/rx/15/values 314232,240.65,49.99,0,0,533,0,860136,58103,829472,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:39:13,270 INFO     MQTT       Publishing: emonhub/rx/15/values 314233,240.66,50,0,0,532,0,860136,58103,829474,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67
2020-07-27 20:39:23,196 INFO     MQTT       Publishing: emonhub/rx/15/values 314234,240.65,50,0,0,531,0,860136,58103,829475,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:39:33,217 INFO     MQTT       Publishing: emonhub/rx/15/values 314235,240.66,49.99,0,0,531,0,860136,58103,829477,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:39:43,121 INFO     MQTT       Publishing: emonhub/rx/15/values 314236,240.66,50,0,0,530,0,860136,58103,829478,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-68
2020-07-27 20:39:53,286 INFO     MQTT       Publishing: emonhub/rx/15/values 314237,240.66,50,0,0,528,0,860136,58103,829480,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:40:03,201 INFO     MQTT       Publishing: emonhub/rx/15/values 314238,240.65,49.99,0,0,527,0,860136,58103,829481,0,-0.03,-0.02,0.88,0,10,300,300,300,0,0,-66
2020-07-27 20:40:13,213 INFO     MQTT       Publishing: emonhub/rx/15/values 314239,240.67000000000002,50,0,0,527,0,860136,58103,829483,0,-0.02,-0.02,0.87,0,10,300,300,300,0,0,-71
2020-07-27 20:40:23,169 INFO     MQTT       Publishing: emonhub/rx/15/values 314240,240.66,50,0,0,528,0,860136,58103,829484,0,-0.02,-0.02,0.88,0,10,300,300,300,0,0,-67

As per previous instances, after restarting EmonHub, the posting to emoncms.org recommenced.
Other than restarting emonhub, I will leave things as they are in case you want to dig around a little.

29

Thanks, it should be better than this.

@trystan @bwduncan It seems to me emonhub gives up too easily after an http failure and never trys again. Can we get emonhub to be more resilient in retrying? Is there a buffer limit?

It does seem to be behaviour we have introduced with the Python3 updates.

30

Hi,

If the interfacer dies because of an uncaught exception I would expect it to get restarted. If the exception is caught then it should just carry on the next time it is called.

Looking at the log it looks like the latter. After the send error there is a sending line, but obviously if the data isn’t arriving then that’s no help!

I might get a chance to look at the code today.

Bruce

31

It seems to retry for a while, then gives up until restarted. I also wonder if the initial attempt should time out quicker.

32

I noticed the same issue yesterday after updating the emonpi from the GUI (full update) a few days ago.
It stops sending to emoncms.org or any other emoncms server (I have a local emoncms server running on ubuntu).
Another thing I noticed was that after the update, the wireless connection got quite unstable - much more unstable than before the update - I see many carrier lost in syslog:

Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: carrier lost
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: deleting address fe80::c832:2e4c:8ac1:d796
Aug 11 17:16:40 emonpi avahi-daemon[355]: Withdrawing address record for fe80::c832:2e4c:8ac1:d796 on wlan0.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::c832:2e4c:8ac1:d796.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Interface wlan0.IPv6 no longer relevant for mDNS.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Withdrawing address record for 172.17.1.106 on wlan0.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 172.17.1.106.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Interface wlan0.IPv4 no longer relevant for mDNS.
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: deleting route to 172.17.1.0/24
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: deleting default route via 172.17.1.1
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: carrier acquired
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: IAID eb:c6:c5:69
Aug 11 17:16:40 emonpi dhcpcd[455]: wlan0: adding address fe80::c832:2e4c:8ac1:d796
Aug 11 17:16:40 emonpi avahi-daemon[355]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::c832:2e4c:8ac1:d796.
Aug 11 17:16:40 emonpi avahi-daemon[355]: New relevant interface wlan0.IPv6 for mDNS.
Aug 11 17:16:40 emonpi avahi-daemon[355]: Registering new address record for fe80::c832:2e4c:8ac1:d796 on wlan0.*.
Aug 11 17:16:41 emonpi dhcpcd[455]: wlan0: rebinding lease of 172.17.1.106
Aug 11 17:16:41 emonpi dhcpcd[455]: wlan0: probing address 172.17.1.106/24
Aug 11 17:16:41 emonpi dhcpcd[455]: wlan0: soliciting an IPv6 router
Aug 11 17:16:47 emonpi dhcpcd[455]: wlan0: leased 172.17.1.106 for 14400 seconds
Aug 11 17:16:47 emonpi avahi-daemon[355]: Joining mDNS multicast group on interface wlan0.IPv4 with address 172.17.1.106.
Aug 11 17:16:47 emonpi avahi-daemon[355]: New relevant interface wlan0.IPv4 for mDNS.
Aug 11 17:16:47 emonpi dhcpcd[455]: wlan0: adding route to 172.17.1.0/24
Aug 11 17:16:47 emonpi avahi-daemon[355]: Registering new address record for 172.17.1.106 on wlan0.IPv4.
Aug 11 17:16:47 emonpi dhcpcd[455]: wlan0: adding default route via 172.17.1.1
Aug 11 17:16:54 emonpi dhcpcd[455]: wlan0: no IPv6 Routers available
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: carrier lost
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: deleting address fe80::c832:2e4c:8ac1:d796
Aug 11 17:17:00 emonpi avahi-daemon[355]: Withdrawing address record for fe80::c832:2e4c:8ac1:d796 on wlan0.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::c832:2e4c:8ac1:d796.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Interface wlan0.IPv6 no longer relevant for mDNS.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Withdrawing address record for 172.17.1.106 on wlan0.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 172.17.1.106.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Interface wlan0.IPv4 no longer relevant for mDNS.
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: deleting route to 172.17.1.0/24
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: deleting default route via 172.17.1.1
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: carrier acquired
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: IAID eb:c6:c5:69
Aug 11 17:17:00 emonpi dhcpcd[455]: wlan0: adding address fe80::c832:2e4c:8ac1:d796
Aug 11 17:17:00 emonpi avahi-daemon[355]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::c832:2e4c:8ac1:d796.
Aug 11 17:17:00 emonpi avahi-daemon[355]: New relevant interface wlan0.IPv6 for mDNS.
Aug 11 17:17:00 emonpi avahi-daemon[355]: Registering new address record for fe80::c832:2e4c:8ac1:d796 on wlan0.*.
Aug 11 17:17:01 emonpi dhcpcd[455]: wlan0: soliciting an IPv6 router
Aug 11 17:17:01 emonpi dhcpcd[455]: wlan0: rebinding lease of 172.17.1.106
Aug 11 17:17:01 emonpi dhcpcd[455]: wlan0: probing address 172.17.1.106/24

Maybe this is the reason for the error we are seeing:

2020-08-11 00:13:39,008 WARNING  emoncmsorg emoncmsorg couldn't send to server: HTTPSConnectionPool(host='emoncms.org', port=443): Max retries exceeded with url: /input/bulk.json?apikey=e901012bd5342448e0f21ace8dc49668 (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x73ad9430>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution'))
2020-08-11 00:13:39,009 WARNING  emoncmsorg send failure: wanted 'ok' but got 'None'

If you guys need more info from my setup, please ask. I am happy to help with what I can.

33

That is interesting. AFAIK nothing has changed on the Wi-Fi network front recently I don’t think.

Can you

cat /etc/wpa_supplicant/wpa_supplicant.conf

and post the output please.

34

When I looked on my emonPi I saw the same. Did some fiddling couldn’t get it to go, rebooted and gone.

The one thing is check your Router Country ID matches what you have on the emonpi. Mine was set to World (It has OpenWRT on it). I did change that, but did not reboot immediately.

35

wpa_supplicant.conf is:

ctrl_interface=DIR=/var/run/wpa_supplicant GROUP=netdev

update_config=1

country=GB

network={

ssid="Rtc123nbs456"

#psk=".............."
psk=............................
}
36

I think you have a point - mine was set to GB on the emonpi.
I have another 2 pi’s running buster, which both have very stable wireless connection and both have Country ID set to US which matches the country ID on the access point.
I wil change it on the emonpi, reboot and see what happens.

37

Interestingly, I have one of these GL.iNet GL-MT300N-V2 routers setup as my IOT AP using a vanilla version of OpenWRT.

On checking the wireless was set to ‘World’. I set it to GB and restarted it.

Looking at a second Pi I have running, I noticed it stopped dropping the connection at exactly the time I restarted the router - it definitely makes a difference.

38

In your case, the second Pi is also running en emonSD image?
The reason I am asking is that, in my case, the only one experiencing the issue with the drops is the emonPi. The other two Pi’s I have, which have a more stable wlan connection, are running the latest image downloaded from raspberrypi.org:
### Debian Buster with Raspberry Pi Desktop

The Raspberry Pi Desktop OS for PC and Mac - based on Debian Buster

Version: **February 2020**

Release date: **2020-02-12**

Kernel version: **4.19**
39

Yes.

The image does have changed made to various network items to accommodate the need for an AP mode.

40

In my case, after matching the country setting in emonPi and access point, there is no significant change:

pi@emonpi:~ $ cat /var/log/syslog|grep lost

Aug 12 09:38:41 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:39:26 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:42:35 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:43:14 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:44:28 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:53:38 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:54:39 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:55:19 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:58:36 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 09:59:05 emonpi dhcpcd[502]: wlan0: carrier lost

Aug 12 10:09:01 emonpi dhcpcd[502]: wlan0: carrier lost