HTTP interfacer stops instead of retrying

[borpin]

https://community.openenergymonitor.org/t/emonhub-stops-sending-data-to-emoncms-org/14639/43

Another report of the HTTP interfacer stopping when it encounters a network/server issue. It should buffer the data and keep trying.

This has been introduced with the Python3 work I believe @bwduncan @TrystanLea.

[bwduncan]

I can't reproduce this bug. When I firewall off emoncms.org, emonhub (or rather, requests) tries really, really hard to send the data. It gives up after about 2 minutes and reports a "send failure" warning log, but the data stays in the buffer. When I remove the firewall block, it sends the buffered data and carries on happily.

2020-08-20 12:43:49,779 DEBUG    emoncmsorg Buffer size: 7
2020-08-20 12:43:49,781 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1597927402.280812,5,-1097,1529,432,238.14000000000001,18.1,0,0,0,0,0,2],[1597927407.326337,5,-1080,1541,461,238.62,18,0,0,0,0,0,2],[1597927409.6592908,23,20.8,22.1,79.5,2.4000000000000004,1,-56],[1597927412.3111854,5,-999,1549,550,238.27,18,0,0,0,0,0,2],[1597927417.2784438,5,-961,1451,490,238.1,18,0,0,0,0,0,2],[1597927422.325498,5,-297,788,491,237.9,18,0,0,0,0,0,2],[1597927427.2861547,5,-341,879,538,237.63,18.1,0,0,0,0,0,2]]&sentat=1597927429
2020-08-20 12:45:59,058 WARNING  emoncmsorg emoncmsorg couldn't send to server: HTTPSConnectionPool(host='emoncms.org', port=443): Max retries exceeded with url: /input/bulk.json?apikey=1931ca22b4a6a8d4dfe00c130573b21c (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x74b84450>: Failed to establish a new connection: [Errno 110] Connection timed out'))
2020-08-20 12:45:59,059 WARNING  emoncmsorg send failure: wanted 'ok' but got 'None'
2020-08-20 12:46:29,118 DEBUG    emoncmsorg Buffer size: 42
2020-08-20 12:46:29,122 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1597927402.280812,5,-1097,1529,432,238.14000000000001,18.1,0,0,0,0,0,2],[1597927407.326337,5,-1080,1541,461,238.62,18,0,0,0,0,0,2],[1597927409.6592908,23,20.8,22.1,79.5,2.4000000000000004,1,-56],[1597927412.3111854,5,-999,1549,550,238.27,18,0,0,0,0,0,2],[1597927417.2784438,5,-961,1451,490,238.1,18,0,0,0,0,0,2],[1597927422.325498,5,-297,788,491,237.9,18,0,0,0,0,0,2],[1597927427.2861547,5,-341,879,538,237.63,18.1,0,0,0,0,0,2],[1597927432.3329237,5,-935,1491,556,237.71,18,0,0,0,0,0,2],[1597927437.2890184,5,-497,1043,546,237.69,18,0,0,0,0,0,2],[1597927442.3426878,5,-439,965,526,238.01,18,0,0,0,0,0,2],[1597927447.2924068,5,-645,1219,574,238.3,18,0,0,0,0,0,2],[1597927452.3413112,5,-882,1455,573,238.27,18.1,0,0,0,0,0,2],[1597927457.2926416,5,-752,1369,617,237.74,18,0,0,0,0,0,2],[1597927462.3395386,5,-849,1483,634,238.31,18.1,0,0,0,0,0,2],[1597927467.304761,5,-787,1443,656,238.74,18,0,0,0,0,0,2],[1597927469.3287232,23,20.8,22.1,79,2.4000000000000004,1,-56],[1597927472.3620732,5,-859,1545,686,238.98000000000002,18.1,0,0,0,0,0,2],[1597927477.3369164,5,-860,1539,679,238.61,18.1,0,0,0,0,0,2],[1597927482.3775783,5,-825,1544,719,238.63,18,0,0,0,0,0,2],[1597927487.3815553,5,-1042,1550,508,239.17000000000002,18.1,0,0,0,0,0,2],[1597927492.332222,5,-1107,1553,446,238.95000000000002,18,0,0,0,0,0,2],[1597927497.3036237,5,-499,882,383,238.21,18.1,0,0,0,0,0,2],[1597927502.3638732,5,-96,537,441,237.91,18.1,0,0,0,0,0,2],[1597927507.3330371,5,-12,448,436,238.18,18.1,0,0,0,0,0,2],[1597927512.3018909,5,50,408,458,237.68,18.1,0,0,0,0,0,2],[1597927517.3606389,5,49,388,437,237.70000000000002,18.1,0,0,0,0,0,2],[1597927522.316835,5,-7,445,438,237.8,18.1,0,0,0,0,0,2],[1597927527.3683789,5,-51,474,423,237.68,18.1,0,0,0,0,0,2],[1597927528.9971104,23,20.8,22.1,78.60000000000001,2.4000000000000004,1,-56],[1597927532.339185,5,47,405,452,238.46,18,0,0,0,0,0,2],[1597927537.3953216,5,38,406,444,238.38,18.1,0,0,0,0,0,2],[1597927542.3539228,5,41,416,457,237.6,18.1,0,0,0,0,0,2],[1597927547.3036234,5,19,429,448,238.03,18.1,0,0,0,0,0,2],[1597927552.3618088,5,-18,426,408,237.44,18.1,0,0,0,0,0,2],[1597927557.310831,5,-12,424,412,238.20000000000002,18.1,0,0,0,0,0,2],[1597927562.3593416,5,-28,441,413,238.33,18.1,0,0,0,0,0,2],[1597927567.3343713,5,-99,487,388,238.5,18.1,0,0,0,0,0,2],[1597927572.3881333,5,-81,477,396,238.27,18.1,0,0,0,0,0,2],[1597927577.3364644,5,-25,513,488,237.99,18.1,0,0,0,0,0,2],[1597927582.3832214,5,-65,516,451,238.53,18.1,0,0,0,0,0,2],[1597927587.3390226,5,-106,604,498,237.70000000000002,18.1,0,0,0,0,0,2],[1597927588.5777912,23,20.700000000000003,22.1,78.4,2.4000000000000004,1,-57]]&sentat=1597927589
2020-08-20 12:47:01,396 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org

[borpin]

Is it the type of error received that is the problem?

I note that the last log message received by the user is a sending, so it is not then logging a send failure or an acknowledged response.

It isn't an isolated incident so something is off somewhere.

[borpin]

What will an exception here do

emonhub/src/interfacers/EmonHubEmoncmsHTTPInterfacer.py

Line 71 in 6820033

reply = self._send_post(post_url, {'data': data_string, 'sentat': str(sentat)})

Should it raise an exception ever?
[edit1]
So you only check for specific a exception

emonhub/src/emonhub_interfacer.py

Line 256 in 58beddb

except requests.exceptions.RequestException as ex:

[edit2]
Does this help?
https://stackoverflow.com/questions/16511337/correct-way-to-try-except-using-python-requests-module
[edit3]
The old exception handling was more verbose - I think an exception must be bypassing this handler

emonhub/src/emonhub_interfacer.py

Lines 253 to 270 in afe680c

	try:
	response = urllib2.urlopen(request, timeout=60)
	except urllib2.HTTPError as e:
	self._log.warning(self.name + " couldn't send to server, HTTPError: " +
	str(e.code))
	except urllib2.URLError as e:
	self._log.warning(self.name + " couldn't send to server, URLError: " +
	str(e.reason))
	except httplib.HTTPException:
	self._log.warning(self.name + " couldn't send to server, HTTPException")
	except Exception:
	import traceback
	self._log.warning(self.name + " couldn't send to server, Exception: " +
	traceback.format_exc())
	else:
	reply = response.read()
	finally:
	return reply

[bwduncan]

Given that requests is trying so hard (at least 2 minutes for a quick failure, could be much longer if the server responds slowly, or starts responding and then gives up) it could be that we're just not waiting long enough.

If there was an exception not being caught (and as you point out, all requests exceptions inherit from RequestException, it would be logged by the emonhub main loop, the thread would be killed and restarted. I'm not seeing any evidence of this happening. If it were, the buffered data would be thrown away and fresh data would be sent.

In any case, unless there is a success or error message being logged, requests is still trying.

[bwduncan]

Can you reproduce this? Here are the commands I used to block emoncms.org:

# insert a drop rule for emoncms.org
sudo iptables -I OUTPUT --destination emoncms.org -j DROP
# delete the drop rule
sudo iptables -D OUTPUT --destination emoncms.org -j DROP

[borpin]

If there was an exception not being caught (and as you point out, all requests exceptions inherit from RequestException, it would be logged by the emonhub main loop,

Well maybe. I have seen exceptions not appearing in the emonhub log and only in syslog when I was playing with that pulse interfacer.

Could there be an exception raised that is not part of RequestException at this point?

In any case, unless there is a success or error message being logged, requests is still trying.

2020-08-20 15:51:43,688 INFO     emoncmsorg sending:

It seems this message is always the last one logged (see other reports on forum). How can that be?

Bit of a Sherlock moment; When you have eliminated the impossible, what remains however improbable must be the truth.

Can you reproduce this? Here are the commands I used to block emoncms.org:

I don't think it is a complete block that is the issue. I think it is a different error/exception that is causing the problem.

If you remove the handler and block emoncms.org, how does the script fail? do you get a sending as the last log message?

[bwduncan]

If there was an exception not being caught (and as you point out, all requests exceptions inherit from RequestException, it would be logged by the emonhub main loop,

Well maybe. I have seen exceptions not appearing in the emonhub log and only in syslog when I was playing with that pulse interfacer.

Could there be an exception raised that is not part of RequestException at this point?

It's not impossible, but I'm not aware of any, and log_exceptions_from_class_method (at the top of emonhub_interfacer.py) will catch all exceptions and log them.

In any case, unless there is a success or error message being logged, requests is still trying.

2020-08-20 15:51:43,688 INFO     emoncmsorg sending:

It seems this message is always the last one logged (see other reports on forum). How can that be?

Not waiting long enough! Once requests.post returns/raises there are only 4 code paths: log success, log error, log RequestException (in _send_post) or log another exception (in log_exceptions_from_class_method). Anything else (except for emonhub dying violently via an uncatchable signal like SIGKILL or the power being pulled) is impossible.

Bit of a Sherlock moment; When you have eliminated the impossible, what remains however improbable must be the truth.

I thought that was Spock?

Can you reproduce this? Here are the commands I used to block emoncms.org:

I don't think it is a complete block that is the issue. I think it is a different error/exception that is causing the problem.

There are other ways we could introduce errors. You could point emonhub at a server which will just return 404, or you could set up a proxy which sends one byte every minute.

If you remove the handler and block emoncms.org, how does the script fail? do you get a sending as the last log message?

Which handler? The one in _send_post? If I remove that and then block emoncms.org in the firewall, I have to wait a really long time and then I eventually get:

2020-08-20 17:08:07,740 WARNING  emoncmsorg Exception caught in emoncmsorg thread. Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connection.py", line 160, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.7/dist-packages/urllib3/util/connection.py", line 80, in create_connection
    raise err
  File "/usr/local/lib/python3.7/dist-packages/urllib3/util/connection.py", line 70, in create_connection
    sock.connect(sa)
TimeoutError: [Errno 110] Connection timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connectionpool.py", line 603, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connectionpool.py", line 344, in _make_request
    self._validate_conn(conn)
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connectionpool.py", line 843, in _validate_conn
    conn.connect()
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connection.py", line 316, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connection.py", line 169, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.VerifiedHTTPSConnection object at 0x75cda2d0>: Failed to establish a new connection: [Errno 110] Connection tim
ed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/requests/adapters.py", line 449, in send
    timeout=timeout
  File "/usr/local/lib/python3.7/dist-packages/urllib3/connectionpool.py", line 641, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.7/dist-packages/urllib3/util/retry.py", line 399, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='emoncms.org', port=443): Max retries exceeded with url: /input/bulk.json?apikey=1931ca22b4a6a8d4dfe00c130573b21c (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x75cda2d0>: Failed to establish a new connection: [Errno 110] Connection timed out'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/emonhub/src/emonhub_interfacer.py", line 32, in wrapper
    return f(*args)
  File "/home/pi/emonhub/src/emonhub_interfacer.py", line 127, in run
    self.action()
  File "/home/pi/emonhub/src/emonhub_interfacer.py", line 198, in action
    self.flush()
  File "/home/pi/emonhub/src/emonhub_interfacer.py", line 216, in flush
    if self._process_post(databuffer):
  File "/home/pi/emonhub/src/interfacers/EmonHubEmoncmsHTTPInterfacer.py", line 71, in _process_post
    reply = self._send_post(post_url, {'data': data_string, 'sentat': str(sentat)})
  File "/home/pi/emonhub/src/emonhub_interfacer.py", line 250, in _send_post
    reply = requests.post(post_url, post_body)
  File "/usr/local/lib/python3.7/dist-packages/requests/api.py", line 119, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/requests/api.py", line 61, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/requests/sessions.py", line 530, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.7/dist-packages/requests/sessions.py", line 643, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/requests/adapters.py", line 516, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='emoncms.org', port=443): Max retries exceeded with url: /input/bulk.json?apikey=1931ca22b4a6a8d4dfe00c130573b21c (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x75cda2d0>: Failed to establish a new connection: [Errno 110] Connection timed out'))

2020-08-20 17:08:07,770 WARNING  MainThread emoncmsorg thread is dead.
2020-08-20 17:08:07,771 WARNING  MainThread Attempting to restart thread emoncmsorg (thread has been restarted 0 times...
2020-08-20 17:08:07,773 INFO     MainThread Setting RFM2Pi calibration: 230V (1p)
2020-08-20 17:08:08,117 DEBUG    RFM2Pi     29 NEW FRAME : OK 5 229 0 144 0 117 1 68 93 185 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 (-0)
2020-08-20 17:08:08,121 DEBUG    RFM2Pi     29 Timestamp : 1597943288.1168897
2020-08-20 17:08:08,122 DEBUG    RFM2Pi     29 From Node : 5
2020-08-20 17:08:08,123 DEBUG    RFM2Pi     29    Values : [229, 144, 373, 238.76, 18.5, 0, 0, 0, 0, 0, 2]
2020-08-20 17:08:08,123 DEBUG    RFM2Pi     29 Sent to channel(start)' : ToEmonCMS
2020-08-20 17:08:08,124 DEBUG    RFM2Pi     29 Sent to channel(end)' : ToEmonCMS
2020-08-20 17:08:08,230 DEBUG    RFM2Pi     30 NEW FRAME : OK 23 217 0 228 0 53 3 24 0 1 0 0 0 (-56)
2020-08-20 17:08:08,233 DEBUG    RFM2Pi     30 Timestamp : 1597943288.2303572
2020-08-20 17:08:08,234 DEBUG    RFM2Pi     30 From Node : 23
2020-08-20 17:08:08,235 DEBUG    RFM2Pi     30    Values : [21.700000000000003, 22.8, 82.10000000000001, 2.4000000000000004, 1]
2020-08-20 17:08:08,236 DEBUG    RFM2Pi     30      RSSI : -56
2020-08-20 17:08:08,237 DEBUG    RFM2Pi     30 Sent to channel(start)' : ToEmonCMS
2020-08-20 17:08:08,238 DEBUG    RFM2Pi     30 Sent to channel(end)' : ToEmonCMS
2020-08-20 17:08:08,342 DEBUG    RFM2Pi     device settings updated: E i5 g210 @ 433 MHz q1 USA 0
2020-08-20 17:08:08,776 INFO     MainThread Creating EmonHubEmoncmsHTTPInterfacer 'emoncmsorg' 
2020-08-20 17:08:08,778 DEBUG    MainThread Setting emoncmsorg pubchannels: ['ToRFM12']
2020-08-20 17:08:08,779 DEBUG    MainThread Setting emoncmsorg subchannels: ['ToEmonCMS']
2020-08-20 17:08:08,780 INFO     MainThread Setting emoncmsorg apikey: set
2020-08-20 17:08:08,780 INFO     MainThread Setting emoncmsorg url: https://emoncms.org
2020-08-20 17:08:08,781 INFO     MainThread Setting emoncmsorg senddata: 1
2020-08-20 17:08:08,782 INFO     MainThread Setting emoncmsorg sendstatus: 1
2020-08-20 17:08:09,128 DEBUG    MQTT       Publishing: emon/emonpi/power1 229
2020-08-20 17:08:09,130 DEBUG    MQTT       Publishing: emon/emonpi/power2 144
2020-08-20 17:08:09,132 DEBUG    MQTT       Publishing: emon/emonpi/power1pluspower2 373
2020-08-20 17:08:09,134 DEBUG    MQTT       Publishing: emon/emonpi/vrms 238.76
2020-08-20 17:08:09,135 DEBUG    MQTT       Publishing: emon/emonpi/t1 18.5
2020-08-20 17:08:09,137 DEBUG    MQTT       Publishing: emon/emonpi/t2 0
2020-08-20 17:08:09,139 DEBUG    MQTT       Publishing: emon/emonpi/t3 0
2020-08-20 17:08:09,140 DEBUG    MQTT       Publishing: emon/emonpi/t4 0
2020-08-20 17:08:09,142 DEBUG    MQTT       Publishing: emon/emonpi/t5 0
2020-08-20 17:08:09,144 DEBUG    MQTT       Publishing: emon/emonpi/t6 0
2020-08-20 17:08:09,146 DEBUG    MQTT       Publishing: emon/emonpi/pulsecount 2
2020-08-20 17:08:09,185 DEBUG    emoncmsorg Buffer size: 1
2020-08-20 17:08:09,186 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1597943288.1168897,5,229,144,373,238.76,18.5,0,0,0,0,0,2]]&sentat=1597943289

requests.exceptions.ConnectionError of course being a subclass of requests.exceptions.RequstError which we would have previously caught and retained the buffer contents.

But "sending" is not the "last" message... just the most recent one for a while!

[borpin]

But "sending" is not the "last" message... just the most recent one for a while!

Ok, but users report it stopping for hours, so something isn't right! They also report it never recovers. In any case, I would expect it to timeout long before that. I seem to remember one report where it had stopped for over a day.

I have to wait a really long time and then I eventually get:

But not hours.

I thought that was Spock?

A bit before his time (1890) https://en.wikiquote.org/wiki/Sherlock_Holmes

What else could it be? The fact that just restarting emonhub restores communications indicates that is the source.

[edit]
Looked back through the thread, and yes a user reports 48 hours

https://community.openenergymonitor.org/t/emonhub-stops-sending-data-to-emoncms-org/14639/28?u=borpin

I think we need to add some additional logging in to try and determine what is happening.

[bwduncan]

But "sending" is not the "last" message... just the most recent one for a while!

Ok, but users report it stopping for hours, so something isn't right! They also report it never recovers. In any case, I would expect it to timeout long before that. I seem to remember one report where it had stopped for over a day.

Yes it seems there is something not right.

Incidentally, requests will happily hang forever if it starts receiving a response and then the server just quietly goes away. I will add a timeout to the requests calls (which is strongly recommended in the documentation)

I have to wait a really long time and then I eventually get:

But not hours.

No, a few minutes.

I thought that was Spock?

A bit before his time (1890) https://en.wikiquote.org/wiki/Sherlock_Holmes

What else could it be? The fact that just restarting emonhub restores communications indicates that is the source.

It's hard to say without being able to reproduce it. I'll see if I can get a tar pit firewall rule to make it go slowly, but an indefinitely hanging socket seems likely.

Whatever is happening, it looks like requests.post never returns or raises an exception...

[edit]

Please can you stop editing comments? It makes it hard to keep up when reading the emails!

Looked back through the thread, and yes a user reports 48 hours

https://community.openenergymonitor.org/t/emonhub-stops-sending-data-to-emoncms-org/14639/28?u=borpin

I think we need to add some additional logging in to try and determine what is happening.

Looking at that user's post, it looks like they have logging set to WARNING, rather than DEBUG. Turning up the debugging may help.

Bruce

[borpin]

Incidentally, requests will happily hang forever if it starts receiving a response and then the server just quietly goes away. I will add a timeout to the requests calls (which is strongly recommended in the documentation)

Sounds like a good plan. Will it generate a specific timeout log message? I suggest that should be a WARN.

[bwduncan]

#126

Yes, it will generate a WARNING message with "couldn't send to server".

Bruce

[borpin]

Could it be more specific that it timed out?

[bwduncan]

I think the exception message will be descriptive enough:

In [5]: try: 
   ...:     requests.get('http://google.com', timeout=0.0001) 
   ...: except requests.exceptions.RequestException as ex: 
   ...:     print("couldn't send to server: " + str(ex)) 
   ...:                                                                                                                                                                   
couldn't send to server: HTTPConnectionPool(host='google.com', port=80): Max retries exceeded with url: / (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f1e4bde1be0>, 'Connection to google.com timed out. (connect timeout=0.0001)'))

[lgheorghe]

In my opinion it is unlikely to reproduce the issue by blocking emoncms.org.
I think the issue appears when the wireless interface flaps.
Here is a relevant portion of the emonhub.log:

2020-08-21 23:35:06,780 INFO     MQTT       Publishing: emonhub/rx/5/values 268,0,268,230.88,25.6,0,0,0,0,0,0
2020-08-21 23:35:10,477 DEBUG    emoncmsorg Buffer size: 7
2020-08-21 23:35:10,479 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I
-K-E-Y&data=[[1598042081.5493429,5,270,0,270,230.4,25.6,0,0,0,0,0,0],[1598042086.498806,5,260,0,260,228.76,25.6,0,0
,0,0,0,0],[1598042091.4396791,5,268,0,268,227.94,25.6,0,0,0,0,0,0],[1598042096.4766777,5,262,0,262,228.55,25.6,0,0,
0,0,0,0],[1598042101.5275505,5,262,0,262,230.65,25.6,0,0,0,0,0,0],[1598042102.1392407,24,27.400000000000002,0,48.1,
2.5,1,-69],[1598042106.469771,5,268,0,268,230.88,25.6,0,0,0,0,0,0]]&sentat=1598042110
2020-08-21 23:35:11,516 DEBUG    RFM2Pi     64723 NEW FRAME : OK 5 22 1 0 0 22 1 222 89 0 1 0 0 0 0 0 0 0 0 0 0 0 0
 0 0 (-0)

After this, it never tries to send again (I left it for 12 hours this time).

and this is syslog:

Aug 21 23:34:35 emonpi dhcpcd[502]: wlan0: deleting route to 169.254.0.0/16
Aug 21 23:34:35 emonpi dhcpcd[502]: wlan0: pid 502 deleted default route via 172.17.1.1
Aug 21 23:35:01 emonpi CRON[20426]: (root) CMD (/usr/local/bin/wifi-check > /var/log/emoncms/wificheck.log 2>&1)
Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: carrier lost
Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: deleting address fe80::c832:2e4c:8ac1:d796
Aug 21 23:35:32 emonpi avahi-daemon[371]: Withdrawing address record for fe80::c832:2e4c:8ac1:d796 on wlan0.
Aug 21 23:35:32 emonpi avahi-daemon[371]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::c
832:2e4c:8ac1:d796.
Aug 21 23:35:32 emonpi avahi-daemon[371]: Interface wlan0.IPv6 no longer relevant for mDNS.
Aug 21 23:35:32 emonpi avahi-daemon[371]: Withdrawing address record for 172.17.1.106 on wlan0.
Aug 21 23:35:32 emonpi avahi-daemon[371]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 172.17.
1.106.
Aug 21 23:35:32 emonpi avahi-daemon[371]: Interface wlan0.IPv4 no longer relevant for mDNS.
Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: deleting route to 172.17.1.0/24
Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: carrier acquired
Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: IAID eb:c6:c5:69

If you guys need more info, I am happy to help - I see the issue happening once every 2-3 days.

[borpin]

Aug 21 23:35:32 emonpi dhcpcd[502]: wlan0: carrier lost

I have seen this happen where the Country code on the Router is different to the Country Code on the wlan interface.

There was a discussion somewhere about it (either community or GitHub) - It might have been on a different forum.