Harvest crashes and never recovers if internet is lost

[h0bb3]

Seems like the harvest transport crashes if there is no internet and this for some reason crashes the whole harvesting process. This should not be the case and this is not cool.

[2024-03-25T19:48:26.606Z] [web] ERROR:server.tasks.srcfulAPICallTask:HTTPSConnectionPool(host='api.srcful.dev', port=443): Max retries exceeded with url: / (Caused by NameResolutionError("<urllib3.connection.HTTPSConnection object at 0x7f7c3feb90>: Failed to resolve 'api.srcful.dev' ([Errno -3] Try again)"))'Traceback (most recent call last):\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connection.py", line 198, in _new_conn\n    sock = connection.create_connection(\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/urllib3/util/connection.py", line 60, in create_connection\n    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/socket.py", line 962, in getaddrinfo\n    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\nsocket.gaierror: [Errno -3] Try again\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connectionpool.py", line 793, in urlopen\n    response = self._make_request(\n               ^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connectionpool.py", line 491, in _make_request\n    raise new_e\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connectionpool.py", line 467, in _make_request\n    self._validate_conn(conn)\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connectionpool.py", line 1099, in _validate_conn\n    conn.connect()\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connection.py", line 616, in connect\n    self.sock = sock = self._new_conn()\n                       ^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connection.py", line 205, in _new_conn\n    raise NameResolutionError(self.host, self, e) from e\nurllib3.exceptions.NameResolutionError: <urllib3.connection.HTTPSConnection object at 0x7f7c3feb90>: Failed to resolve \'api.srcful.dev\' ([Errno -3] Try again)\n\nThe above exception was the direct cause of the following exception:\n\nTraceback (most recent call last):\n  File "/usr/local/lib/python3.11/site-packages/requests/adapters.py", line 486, in send\n    resp = conn.urlopen(\n           ^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/urllib3/connectionpool.py", line 847, in urlopen\n    retries = retries.increment(\n              ^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/urllib3/util/retry.py", line 515, in increment\n    raise MaxRetryError(_pool, url, reason) from reason  # type: ignore[arg-type]\n    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\nurllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host=\'api.srcful.dev\', port=443): Max retries exceeded with url: / (Caused by NameResolutionError("<urllib3.connection.HTTPSConnection object at 0x7f7c3feb90>: Failed to resolve \'api.srcful.dev\' ([Errno -3] Try again)"))\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File "/server/tasks/srcfulAPICallTask.py", line 66, in post\n    self.reply = requests.post(self.post_url, json=json, timeout=5)\n                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/requests/api.py", line 115, in post\n    return request("post", url, data=data, json=json, **kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/requests/api.py", line 59, in request\n    return session.request(method=method, url=url, **kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/requests/sessions.py", line 589, in request\n    resp = self.send(prep, **send_kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/requests/sessions.py", line 703, in send\n    r = adapter.send(request, **kwargs)\n        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File "/usr/local/lib/python3.11/site-packages/requests/adapters.py", line 519, in send\n    raise ConnectionError(e, request=request)\nrequests.exceptions.ConnectionError: HTTPSConnectionPool(host=\'api.srcful.dev\', port=443): Max retries exceeded with url: / (Caused by NameResolutionError("<urllib3.connection.HTTPSConnection object at 0x7f7c3feb90>: Failed to resolve \'api.srcful.dev\' ([Errno -3] Try again)"))'
[Logs]    [2024-03-25T19:48:26.608Z] [web] ----------------------------------------
[Logs]    [2024-03-25T19:48:26.608Z] [web] Exception occurred during processing of request from ('172.17.0.1', 56158)
[Logs]    [2024-03-25T19:48:26.610Z] [web] Traceback (most recent call last):
[Logs]    [2024-03-25T19:48:26.611Z] [web]   File "/usr/local/lib/python3.11/socketserver.py", line 317, in _handle_request_noblock
[Logs]    [2024-03-25T19:48:26.612Z] [web]     self.process_request(request, client_address)
[Logs]    [2024-03-25T19:48:26.612Z] [web]   File "/usr/local/lib/python3.11/socketserver.py", line 348, in process_request
[Logs]    [2024-03-25T19:48:26.612Z] [web]     self.finish_request(request, client_address)
[Logs]    [2024-03-25T19:48:26.612Z] [web]   File "/usr/local/lib/python3.11/socketserver.py", line 361, in finish_request
[Logs]    [2024-03-25T19:48:26.612Z] [web]     self.RequestHandlerClass(request, client_address, self)
[Logs]    [2024-03-25T19:48:26.612Z] [web]   File "/server/web/server.py", line 57, in __init__
[Logs]    [2024-03-25T19:48:26.612Z] [web]     super(Handler, self).__init__(*args, **kwargs)
[Logs]    [2024-03-25T19:48:26.613Z] [web]   File "/usr/local/lib/python3.11/socketserver.py", line 755, in __init__
[Logs]    [2024-03-25T19:48:26.614Z] [web]     self.handle()
[Logs]    [2024-03-25T19:48:26.614Z] [web]   File "/usr/local/lib/python3.11/http/server.py", line 436, in handle
[Logs]    [2024-03-25T19:48:26.614Z] [web]     self.handle_one_request()
[Logs]    [2024-03-25T19:48:26.614Z] [web]   File "/usr/local/lib/python3.11/http/server.py", line 424, in handle_one_request
[Logs]    [2024-03-25T19:48:26.614Z] [web]     method()
[Logs]    [2024-03-25T19:48:26.615Z] [web]   File "/server/web/server.py", line 153, in do_GET
[Logs]    [2024-03-25T19:48:26.615Z] [web]     code, response = api_handler.do_get(rdata)
[Logs]    [2024-03-25T19:48:26.615Z] [web]                      ^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.615Z] [web]   File "/server/web/handler/get/name.py", line 26, in do_get
[Logs]    [2024-03-25T19:48:26.615Z] [web]     return t.reply.status, json.dumps({"body": t.reply.body})
[Logs]    [2024-03-25T19:48:26.615Z] [web]            ^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.615Z] [web] AttributeError: 'Response' object has no attribute 'status'
[Logs]    [2024-03-25T19:48:26.615Z] [web] ----------------------------------------
[Logs]    [2024-03-25T19:48:26.830Z] [bluetooth] Exception in thread Thread-6 (handle_write_request):
[Logs]    [2024-03-25T19:48:26.831Z] [bluetooth] Traceback (most recent call last):
[Logs]    [2024-03-25T19:48:26.832Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 467, in _make_request
[Logs]    [2024-03-25T19:48:26.833Z] [bluetooth]     six.raise_from(e, None)
[Logs]    [2024-03-25T19:48:26.833Z] [bluetooth]   File "<string>", line 3, in raise_from
[Logs]    [2024-03-25T19:48:26.834Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 462, in _make_request
[Logs]    [2024-03-25T19:48:26.834Z] [bluetooth]     httplib_response = conn.getresponse()
[Logs]    [2024-03-25T19:48:26.835Z] [bluetooth]                        ^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.835Z] [bluetooth]   File "/usr/local/lib/python3.11/http/client.py", line 1386, in getresponse
[Logs]    [2024-03-25T19:48:26.836Z] [bluetooth]     response.begin()
[Logs]    [2024-03-25T19:48:26.837Z] [bluetooth]   File "/usr/local/lib/python3.11/http/client.py", line 325, in begin
[Logs]    [2024-03-25T19:48:26.838Z] [bluetooth]     version, status, reason = self._read_status()
[Logs]    [2024-03-25T19:48:26.838Z] [bluetooth]                               ^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.839Z] [bluetooth]   File "/usr/local/lib/python3.11/http/client.py", line 286, in _read_status
[Logs]    [2024-03-25T19:48:26.840Z] [bluetooth]     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
[Logs]    [2024-03-25T19:48:26.840Z] [bluetooth]                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.841Z] [bluetooth]   File "/usr/local/lib/python3.11/socket.py", line 706, in readinto
[Logs]    [2024-03-25T19:48:26.841Z] [bluetooth]     return self._sock.recv_into(b)
[Logs]    [2024-03-25T19:48:26.841Z] [bluetooth]            ^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.842Z] [bluetooth] TimeoutError: timed out
[Logs]    [2024-03-25T19:48:26.842Z] [bluetooth]
[Logs]    [2024-03-25T19:48:26.842Z] [bluetooth] During handling of the above exception, another exception occurred:
[Logs]    [2024-03-25T19:48:26.842Z] [bluetooth]
[Logs]    [2024-03-25T19:48:26.843Z] [bluetooth] Traceback (most recent call last):
[Logs]    [2024-03-25T19:48:26.843Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/adapters.py", line 440, in send
[Logs]    [2024-03-25T19:48:26.843Z] [bluetooth]     resp = conn.urlopen(
[Logs]    [2024-03-25T19:48:26.843Z] [bluetooth]            ^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.844Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 799, in urlopen
[Logs]    [2024-03-25T19:48:26.844Z] [bluetooth]     retries = retries.increment(
[Logs]    [2024-03-25T19:48:26.844Z] [bluetooth]               ^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.845Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/util/retry.py", line 550, in increment
[Logs]    [2024-03-25T19:48:26.845Z] [bluetooth]     raise six.reraise(type(error), error, _stacktrace)
[Logs]    [2024-03-25T19:48:26.845Z] [bluetooth]           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.845Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/packages/six.py", line 770, in reraise
[Logs]    [2024-03-25T19:48:26.846Z] [bluetooth]     raise value
[Logs]    [2024-03-25T19:48:26.846Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 715, in urlopen
[Logs]    [2024-03-25T19:48:26.846Z] [bluetooth]     httplib_response = self._make_request(
[Logs]    [2024-03-25T19:48:26.846Z] [bluetooth]                        ^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.847Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 469, in _make_request
[Logs]    [2024-03-25T19:48:26.847Z] [bluetooth]     self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
[Logs]    [2024-03-25T19:48:26.848Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 358, in _raise_timeout
[Logs]    [2024-03-25T19:48:26.849Z] [bluetooth]     raise ReadTimeoutError(
[Logs]    [2024-03-25T19:48:26.849Z] [bluetooth] urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='127.0.0.1', port=80): Read timed out. (read timeout=5)
[Logs]    [2024-03-25T19:48:26.849Z] [bluetooth]
[Logs]    [2024-03-25T19:48:26.850Z] [bluetooth] During handling of the above exception, another exception occurred:
[Logs]    [2024-03-25T19:48:26.850Z] [bluetooth]
[Logs]    [2024-03-25T19:48:26.850Z] [bluetooth] Traceback (most recent call last):
[Logs]    [2024-03-25T19:48:26.851Z] [bluetooth]   File "/usr/local/lib/python3.11/threading.py", line 1045, in _bootstrap_inner
[Logs]    [2024-03-25T19:48:26.851Z] [bluetooth]     self.run()
[Logs]    [2024-03-25T19:48:26.851Z] [bluetooth]   File "/usr/local/lib/python3.11/threading.py", line 982, in run
[Logs]    [2024-03-25T19:48:26.851Z] [bluetooth]     self._target(*self._args, **self._kwargs)
[Logs]    [2024-03-25T19:48:26.851Z] [bluetooth]   File "/code/ble_service_twochars.py", line 111, in handle_write_request
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]     request_get(header["path"], header["Offset"])
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]   File "/code/ble_service_twochars.py", line 89, in request_get
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]     return handle_response(path, "GET", requests.get(API_URL + path, timeout=REQUEST_TIMEOUT), offset)
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]                                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/api.py", line 75, in get
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]     return request('get', url, params=params, **kwargs)
[Logs]    [2024-03-25T19:48:26.852Z] [bluetooth]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/api.py", line 61, in request
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]     return session.request(method=method, url=url, **kwargs)
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/sessions.py", line 529, in request
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]     resp = self.send(prep, **send_kwargs)
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.853Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/sessions.py", line 645, in send
[Logs]    [2024-03-25T19:48:26.854Z] [bluetooth]     r = adapter.send(request, **kwargs)
[Logs]    [2024-03-25T19:48:26.854Z] [bluetooth]         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[Logs]    [2024-03-25T19:48:26.854Z] [bluetooth]   File "/code/venv/lib/python3.11/site-packages/requests/adapters.py", line 532, in send
[Logs]    [2024-03-25T19:48:26.854Z] [bluetooth]     raise ReadTimeout(e, request=request)
[Logs]    [2024-03-25T19:48:26.854Z] [bluetooth] requests.exceptions.ReadTimeout: HTTPConnectionPool(host='127.0.0.1', port=80): Read timed out. (read timeout=5)
[Logs]    [2024-03-25T20:30:53.686Z] [bluetooth] DEBUG:__main__:Chars value set to GET /api/name EGWTTP/1.1
[Logs]    [2024-03-25T20:30:53.688Z] [bluetooth] Content-Type: text/json
[Logs]    [2024-03-25T20:30:53.688Z] [bluetooth] Content-Length: 2
[Logs]    [2024-03-25T20:30:53.688Z] [bluetooth]
[Logs]    [2024-03-25T20:30:53.689Z] [bluetooth] {}
[Logs]    [2024-03-25T20:30:53.689Z] [bluetooth] DEBUG:egwttp:line:" GET /api/name EGWTTP/1.1"
[Logs]    [2024-03-25T20:30:53.689Z] [bluetooth] DEBUG:__main__:Request received...
[Logs]    [2024-03-25T20:30:53.689Z] [bluetooth] DEBUG:__main__:Header: {'Content-Type': 'text/json', 'Content-Length': '2', 'Offset': 0, 'method': 'GET', 'path': '/api/name', 'version': 'EGWTTP/1.1'}
[Logs]    [2024-03-25T20:30:53.690Z] [bluetooth] DEBUG:__main__:Content: {}
[Logs]    [2024-03-25T20:30:53.696Z] [bluetooth] DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:80

[h0bb3]

The way to test this is to run in local dev and disable your wifi.... then see what happens in the log...

So the problem in this case was that the open inverter task failed as there was no netowork so the inverter was never started. E.g. as the inverted does not know that it suddenly has a network connection.

The same problem would occur even if the harvest is in progress. It would start failing backing off and then kill the inverter and try to reopen wich would then fail and there would be no inverter connection when the network is restored. We are talking about local network here...

So if we add a local network connection task that periodically checks for network and then checks if there is an inverter and if not try bootstrapping.

[h0bb3]

Checking for an active network is quite straight forward in a normal environment but basically impossible in a docker container without e.g. pinging some external service.... this would then rather indicate Internet connection than local connection. But maybe this is enough...

[h0bb3]

Another issue here is that the wifi scanning fails if wifi is disabled...

But the good news is that it seems possible to get the ip address using some dbus network manager magic even from within the container... very linux specific... but nontheless... need to test some more in balena os also... but promising... so far.

[h0bb3]

This actually seems to be working... need to clean up the code and remove all the not now needed bash stuff for the balena supervisor. Big win!

[h0bb3]

This should be fixed now, see #156 for comments.