HassOS 8.1 breaks add-on

alfredopironti commented 2 years ago

Describe the issue you are experiencing

I'm the maintainer of a niche Home Assistant add-on that adds an MQTT interface to a web-based burglar alarm (https://github.com/maisken/Paradox_IP150). It's mostly python, wrapped into an Home Assistant add-on.

The code has been stable (no updates) for the last 2+ years at v1.1, working reliably up to and including HassOS 8.0.

With the update to HassOS 8.1, both myself and a few users have experienced an erratic behavior of the add-on. It seems that, at random intervals, outgoing network connections to the web UI of the burglar alarm go on timeout (at which point the add-on quits -- see add-on logs below).

I know the link between the add-on behavior and the HassOS 8.1 update seems far fetched, but I ran several tests, and I wouldn't be opening this issue if (to my own surprise) I hadn't identified this as the cause of the erratic behavior. See below for all the tests I carried out which led me to this conclusion.

I've also just released v1.2 of the add-on, where I have refreshed all python dependencies, as well as rebuilt the add-on image against the latest Home Assistant add-on base image. But the problem persists.

Downgrading to HassOS 8.0 (ha os update --version 8.0) fixes the erratic behavior, and the add-on (both v1.1 and v1.2) works reliably as usual. Also, running the python code on a local machine, or running the add-on on the VS devcontainer deployment of Home Assistant (which, crucially, doesn't use HassOS) works reliably. It's just using HassOS 8.1 that seems problematic.

I've inspected the commits between 8.0 and 8.1:

some add support for additional wireless network interfaces, or deal with NTP -- these shouldn't be relevant
guest agents have been bumped: I tried to run 8.1 with agent support disabled on the host (so the guest agent would not start), but the same problem persist. So I tend to assume this is not the cause
Kernel version has been bumped: I would be shocked if this was causing the issue, but I don't know how to try more systematically
Other items like: buildroot; grub2 alignment, RPI-RF-MOD etc: I'm not sure I understand their potential impact on the matter

The rest of my Home Assistant production deployment seems to operate correctly with 8.1 -- just the add-on breaks this way.

If not a solution, would you have any insight on further tests I could perform, or how to test one-by-one the different commits that go from 8.0 to 8.1, maybe?

What operating system image do you use?

ova (for Virtual Machines)

What version of Home Assistant Operating System is installed?

8.1

Did you upgrade the Operating System.

Yes

Steps to reproduce the issue

The add-on can be installed via this repository, however it won't start if it can't connect to the expected burglar alarm web interface. Reproducing the issue may be tricky, but I'd be happy to run more tests and share the results as instructed.

Here I can provide evidence showing the update to HassOS 8.1 is causing the issue. In the image below, you see the history for the add-on MQTT alarm status. The red circle represents a 8.0 -> 8.1 update Screen Shot 2022-05-29 at 15 30 26 Before the update, you can see the MQTT alarm status is reliable (Disarmed, then Armed Home). After the 8.1 update, see the several grey bits, where the add-on becomes "Unavailable". This is a network connection timing out, the add-on quitting, then watchdog restarting it, making it available again. Notice the grey slots are frequent, but not regular.

Similarly, the image below shows a 8.1 -> 8.0 downgrade.

Before downgrading, you can see the "grey slot" (Unavailable) pattern. After the downgrade (red circle), the add-on becomes reliable again.

When running under 8.1, the add-on logs show "time out" errors like (taken from add-on v1.1; the v1.2 would use python 3.9, but the error is the same):

Exception in thread Thread-1: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/urllib3/connection.py", line 156, in _new_conn conn = connection.create_connection( File "/usr/lib/python3.8/site-packages/urllib3/util/connection.py", line 84, in create_connection raise err File "/usr/lib/python3.8/site-packages/urllib3/util/connection.py", line 74, in create_connection sock.connect(sa) TimeoutError: [Errno 110] Operation timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/urllib3/connectionpool.py", line 665, in urlopen httplib_response = self._make_request( File "/usr/lib/python3.8/site-packages/urllib3/connectionpool.py", line 387, in _make_request conn.request(method, url, httplib_request_kw) File "/usr/lib/python3.8/http/client.py", line 1255, in request self._send_request(method, url, body, headers, encode_chunked) File "/usr/lib/python3.8/http/client.py", line 1301, in _send_request self.endheaders(body, encode_chunked=encode_chunked) File "/usr/lib/python3.8/http/client.py", line 1250, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib/python3.8/http/client.py", line 1010, in _send_output self.send(msg) File "/usr/lib/python3.8/http/client.py", line 950, in send self.connect() File "/usr/lib/python3.8/site-packages/urllib3/connection.py", line 184, in connect conn = self._new_conn() File "/usr/lib/python3.8/site-packages/urllib3/connection.py", line 168, in _new_conn raise NewConnectionError( urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7fb5f6b50940>: Failed to establish a new connection: [Errno 110] Operation timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/requests/adapters.py", line 439, in send resp = conn.urlopen( File "/usr/lib/python3.8/site-packages/urllib3/connectionpool.py", line 719, in urlopen retries = retries.increment( File "/usr/lib/python3.8/site-packages/urllib3/util/retry.py", line 436, in increment raise MaxRetryError(_pool, url, error or ResponseError(cause)) urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='10.0.100.20', port=80): Max retries exceeded with url: /keep_alive.html?msgid=1 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fb5f6b50940>: Failed to establish a new connection: [Errno 110] Operation timed out')) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3.8/threading.py", line 932, in _bootstrap_inner self.run() File "/ip150.py", line 29, in run self._one_keepalive() File "/ip150.py", line 24, in _one_keepalive requests.get('{}/keep_alive.html'.format( File "/usr/lib/python3.8/site-packages/requests/api.py", line 75, in get return request('get', url, params=params, kwargs) File "/usr/lib/python3.8/site-packages/requests/api.py", line 60, in request return session.request(method=method, url=url, kwargs) File "/usr/lib/python3.8/site-packages/requests/sessions.py", line 533, in request resp = self.send(prep, send_kwargs) File "/usr/lib/python3.8/site-packages/requests/sessions.py", line 646, in send r = adapter.send(request, **kwargs) File "/usr/lib/python3.8/site-packages/requests/adapters.py", line 516, in send raise ConnectionError(e, request=request) requests.exceptions.ConnectionError: HTTPConnectionPool(host='10.0.100.20', port=80): Max retries exceeded with url: /keep_alive.html?msgid=1 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7fb5f6b50940>: Failed to establish a new connection: [Errno 110] Operation timed out'))

Anything in the Supervisor logs that might be useful for us?

I've extensively looked at the Supervisor logs, but didn't find anything apparently relevant. Please let me know if there's any part of that log you'd like me to report here.

Anything in the Host logs that might be useful for us?

I've extensively looked at the Host logs, but didn't find anything apparently relevant. Please let me know if there's any part of that log you'd like me to report here.

System Health information

System Health

version	core-2022.5.5
installation_type	Home Assistant OS
dev	false
hassio	true
docker	true
user	root
virtualenv	false
python_version	3.9.9
os_name	Linux
os_version	5.15.41
arch	x86_64
timezone	Europe/Madrid

Home Assistant Community Store

Home Assistant Cloud

Home Assistant Supervisor

Dashboards

Additional information

No response

ddppddpp commented 2 years ago

I'm reproducing the issue on a odroid-n2. My System Health output:

`

Version	core-2022.5.5
Installation Type	Home Assistant OS
Development	false
Supervisor	true
Docker	true
User	root
Virtual Environment	false
Python Version	3.9.9
Operating System Family	Linux
Operating System Version	5.15.41
CPU Architecture	aarch64
Timezone	Europe/Sofia

`

agners commented 2 years ago

Hm, yeah not really that many changes went into 8.1 which could affect network connectivity. My best guesses are the NTP change or the new kernel somehow causes issues.

Can all affected people confirm that 8.0 resolves the issue?

Do you have host level SSH access (SSH on port 22222)? You can set it up using this instructions. Interesting would be to run journalctl -fwhen the issue happens, and/or check journalctl -b 0 after it happens to see if something suspicious is logged just before the add-on crash.

wojcior1 commented 2 years ago

I have the same issue, I am using windows 10 and Oracle VirtualBox 6.1.34

System Health

version	core-2022.5.5
installation_type	Home Assistant OS
dev	false
hassio	true
docker	true
user	root
virtualenv	false
python_version	3.9.9
os_name	Linux
os_version	5.15.38
arch	x86_64
timezone	Europe/Warsaw

Home Assistant Community Store

Home Assistant Cloud

Home Assistant Supervisor

Dashboards

Spotify

api_endpoint_reachable | ok -- | --

agners commented 2 years ago

@wojcior1 probably your best approach is to downgrade to 7.6 using ha os update --version 8.0 for now.

agners commented 2 years ago

@alfredopironti I just made a new development build with the latest kernel, maybe its worth a shot. It should be safe to upgrade and downgrade back to 8.1 using

ha su options --channel=dev
ha su reload
ha os info # verify an update is listed
ha os update

ddppddpp commented 2 years ago

I can confirm downgrading to 8.0 solves the issue for me.

alfredopironti commented 2 years ago

Hi @agners sorry for the slow response. I'm developing this in my spare time and I went through a couple of busy days.

I've now updated to HassOS 9.0.dev20220601, and it does not seem to fix the issue. Please see the screenshot below, with the red circle indicating the update. After the update, the same pattern persists.

When still running 8.1, I ran dmesg when connected via SSH port 22 ("Terminal and SSH" official add-on), and I found one possibly interesting entry (only one across a few days, while my add-on has issues every few minutes):

[12091.468183] sd 0:0:0:0: [sda] tag#2 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=43s
[12091.468190] sd 0:0:0:0: [sda] tag#2 CDB: Write(10) 2a 00 00 51 b6 f0 00 00 08 00
[12091.468191] blk_update_request: I/O error, dev sda, sector 5355248 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[12091.468237] EXT4-fs warning (device sda8): ext4_end_bio:344: I/O error 10 writing to inode 157178 starting block 669407)
[12091.468242] Buffer I/O error on device sda8, logical block 490974

Looks like a timeout from the virtual hard disk. I could not relate this to any physical error on the host.

On my most recent boot (HassOS 9.0.dev) I also enabled SSH on port 22222. From journalctl -b 0 I found the below related to the add-on startup (interleaved with core_ssh, to not touch the log):

Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service s6rc-oneshot-runner: starting
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service s6rc-oneshot-runner successfully started
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service fix-attrs: starting
Jun 02 20:23:16 homeassistant-vm homeassistant/amd64-addon-ssh:9.4.0/addon_core_ssh[382]: [22:23:16] INFO: Starting the SSH daemon...
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service fix-attrs successfully started
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service legacy-cont-init: starting
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service legacy-cont-init successfully started
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service legacy-services: starting
Jun 02 20:23:16 homeassistant-vm homeassistant/amd64-addon-ssh:9.4.0/addon_core_ssh[382]: Server listening on 0.0.0.0 port 22.
Jun 02 20:23:16 homeassistant-vm homeassistant/amd64-addon-ssh:9.4.0/addon_core_ssh[382]: Server listening on :: port 22.
Jun 02 20:23:16 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: s6-rc: info: service legacy-services successfully started

Other add-ons don't seem to be loaded as "legacy"; however, when refreshing it for v1.2 I didn't find any instructions on how to not make your add-on legacy (I mean, I believe I'm using any latest technology; apparmor is not enabled, but that should be optional).

Then find below an add-on timeout crash; for context, I'm reporting the few lines above, which is me logging via SSH a few minutes before, but otherwise nothing seems to be logged before the crash. After the crash, there are some cleanup logs some few minutes later, but I'm not sure they relate as well.

Jun 02 20:29:13 homeassistant-vm dropbear[5303]: [5303] Jun 02 20:29:13 Child connection from 10.0.69.219:52032
Jun 02 20:29:13 homeassistant-vm dropbear[5303]: [5303] Jun 02 20:29:13 Generated hostkey /etc/dropbear/dropbear_ed25519_host_key, fingerprint is sha1!! ec:62:a2:5d:0a:e0:92:8e:05:40:97:23:3d:2f:33:b0:c9:b8:35:43
Jun 02 20:29:16 homeassistant-vm dropbear[5303]: [5303] Jun 02 20:29:16 Pubkey auth succeeded for 'root' with key sha1!! c6:ac:07:0d:49:44:96:90:6a:55:46:35:c9:4e:0c:ca:16:79:d4:32 from 10.0.69.219:52032
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: Exception in thread Thread-1:
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: Traceback (most recent call last):
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:   File "/usr/lib/python3.9/site-packages/urllib3/connection.py", line 174, in _new_conn
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:     conn = connection.create_connection(
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:   File "/usr/lib/python3.9/site-packages/urllib3/util/connection.py", line 95, in create_connection
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:     raise err
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:   File "/usr/lib/python3.9/site-packages/urllib3/util/connection.py", line 85, in create_connection
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:     sock.connect(sa)
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: TimeoutError: [Errno 110] Operation timed out
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: 
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: During handling of the above exception, another exception occurred:
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: 
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: Traceback (most recent call last):
Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]:   File "/usr/lib/python3.9/site-packages/urllib3/connectionpool.py", line 703, in urlopen
Jun 02 20:32:51 homeassistant-vm homeassistant/amd64-hassio-supervisor:latest/hassio_supervisor[382]: 
Jun 02 20:37:16 homeassistant-vm systemd[1]: Starting Cleanup of Temporary Directories...
Jun 02 20:37:16 homeassistant-vm systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Jun 02 20:37:16 homeassistant-vm systemd[1]: Finished Cleanup of Temporary Directories.

I'm still quite clueless on the culprit here. Would there be a way of selectively adding commits on top of HassOS 8.0, to run some focused regression tests, and at least trying to understand what change is generating the issue? I'm also open to any further test you'd like me to run. Thanks for all the support!

alfredopironti commented 2 years ago

As a quick update, I let HassOS 9.0.dev20220601 run for a few more days, and via journalctl -b 0 I found several (more than 10) instances of the error below (another timeout):

Jun 04 06:19:38 homeassistant-vm ghcr.io/home-assistant/qemux86-64-homeassistant:2022.5.5/homeassistant[382]: 2022-06-04 08:19:38 ERROR (MainThread) [homeassistant.components.version] Error fetching version data: Timeout of 10 seconds was reached while fetching version for supervisor

It's hard to relate these to my add-on timeouts (meaning, all the errors appear quite sparsely in time).

I plan now reverting to 8.1 (as that version appears to be the one where the regression appears first) and see if similar errors are reported, too.

agners commented 2 years ago

Other add-ons don't seem to be loaded as "legacy"; however, when refreshing it for v1.2 I didn't find any instructions on how to not make your add-on legacy (I mean, I believe I'm using any latest technology; apparmor is not enabled, but that should be optional).

The add-on base images recently changed to use the new s6 v3 overlay. If you rebuilt the add-on since that change, it will use the new overlay and declare your scripts as being legacy. See also: https://developers.home-assistant.io/blog/2022/05/12/s6-overlay-base-images

That said, it shouldn't really be problematic.

Jun 04 06:19:38 homeassistant-vm ghcr.io/home-assistant/qemux86-64-homeassistant:2022.5.5/homeassistant[382]: 2022-06-04 08:19:38 ERROR (MainThread) [homeassistant.components.version] Error fetching version data: Timeout of 10 seconds was reached while fetching version for supervisor

It's hard to relate these to my add-on timeouts (meaning, all the errors appear quite sparsely in time).

Hm, that would mean its a more generic problem then :cold_sweat:

Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: File "/usr/lib/python3.9/site-packages/urllib3/util/connection.py", line 85, in create_connection Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: sock.connect(sa) Jun 02 20:30:20 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[382]: TimeoutError: [Errno 110] Operation timed out

Just in general, connection timeout can (and do) happen from time to time, and you should probably handle this exception somehow. However, it is a bit concerning that this happens much more just caused by an OS update...

ddppddpp commented 2 years ago

The issue persists in OS 8.2

alfredopironti commented 2 years ago

Hi @agners, thanks for all your comments. For the record, my crashing python script is wrapped by a watchdog bash script. I will never defend this error management style ;-) but that explain why you see the crashes in the log (and the addon, eventually, gets back working).

I've now let run 8.1 for a few more days, and ended up collecting a few more interesting bits. See [1] for a "bad file descriptor" error and, interestingly, [2] for the python interpreter itself crashing, and being core-dumped.

I also found mosquitto timing out [3], as well as another timeout error while searching for dev releases [4] (I still have the dev channel open).

I'm still not clear what the culprit could be, but given the errors seem to be more systemic (not just timeouts), could it be some incompatibility between docker and the underlying OS (maybe kernel version, ABI version...?). A quick search online didn't seem to bring anything relevant, however.

Is there a way to build OS versions by picking specific commits, so I could try to nail down the 8.0 -> 8.1 change that seemingly introduced the issue? I'm happy to run further tests as suitable. Thanks!

[1] Bad file descriptor

Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Traceback (most recent call last): Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "//ip150_mqtt.py", line 140, in Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: ip_mqtt.loop_forever() Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "//ip150_mqtt.py", line 133, in loop_forever Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: mqc.loop_forever() Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/paho/mqtt/client.py", line 1756, in loop_forever Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: rc = self._loop(timeout) Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/paho/mqtt/client.py", line 1164, in _loop Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: rc = self.loop_read() Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/paho/mqtt/client.py", line 1556, in loop_read Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: rc = self._packet_read() Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/paho/mqtt/client.py", line 2419, in _packet_read Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: data = self._sock_recv(self._in_packet['to_process']) Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/paho/mqtt/client.py", line 640, in _sock_recv Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: return self._sock.recv(bufsize) Jun 05 15:50:48 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: OSError: [Errno 9] Bad file descriptor

[2] Python core dumped

Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Exception in thread Thread-1: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Traceback (most recent call last): Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connection.py", line 174, in _new_conn Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: conn = connection.create_connection( Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/util/connection.py", line 95, in create_connection Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: raise err Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/util/connection.py", line 85, in create_connection Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: sock.connect(sa) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: TimeoutError: [Errno 110] Operation timed out Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: During handling of the above exception, another exception occurred: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Traceback (most recent call last): Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connectionpool.py", line 703, in urlopen Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: httplib_response = self._make_request( Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connectionpool.py", line 398, in _make_request Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: conn.request(method, url, **httplib_request_kw) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connection.py", line 239, in request Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: super(HTTPConnection, self).request(method, url, body=body, headers=headers) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/http/client.py", line 1279, in request Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: self._send_request(method, url, body, headers, encode_chunked) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/http/client.py", line 1325, in _send_request Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: self.endheaders(body, encode_chunked=encode_chunked) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/http/client.py", line 1274, in endheaders Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: self._send_output(message_body, encode_chunked=encode_chunked) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/http/client.py", line 1034, in _send_output Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: self.send(msg) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/http/client.py", line 974, in send Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: self.connect() Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connection.py", line 205, in connect Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: conn = self._new_conn() Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connection.py", line 186, in _new_conn Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: raise NewConnectionError( Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f2194a604c0>: Failed to establish a new connection: [Errno 110] Operation timed out Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: During handling of the above exception, another exception occurred: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Traceback (most recent call last): Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/requests/adapters.py", line 440, in send Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: resp = conn.urlopen( Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/connectionpool.py", line 785, in urlopen Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: retries = retries.increment( Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: File "/usr/lib/python3.9/site-packages/urllib3/util/retry.py", line 592, in increment Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: raise MaxRetryError(_pool, url, error or ResponseError(cause)) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='10.0.100.20', port=80): Max retries exceeded with url: /keep_alive.html?msgid=1 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f2194a604c0>: Failed to establish a new connection: [Errno 110] Operation timed out')) Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: During handling of the above exception, another exception occurred: Jun 20 16:51:28 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:29 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Fatal Python error: _enter_buffered_busy: could not acquire lock for <_io.BufferedWriter name=''> at interpreter shutdown, possibly due to daemon threads Jun 20 16:51:29 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Python runtime state: finalizing (tstate=0x7f219631b0c0) Jun 20 16:51:29 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:29 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Current thread 0x00007f219631ab48 (most recent call first): Jun 20 16:51:29 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: Jun 20 16:51:30 homeassistant-vm audit[141357]: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 subj==docker-default (enforce) pid=141357 comm="python3" exe="/usr/bin/python3.9" sig=6 res=1 Jun 20 16:51:30 homeassistant-vm kernel: audit: type=1701 audit(1655743890.577:1866): auid=4294967295 uid=0 gid=0 ses=4294967295 subj==docker-default (enforce) pid=141357 comm="python3" exe="/usr/bin/python3.9" sig=6 res=1 Jun 20 16:51:30 homeassistant-vm audit: BPF prog-id=789 op=LOAD Jun 20 16:51:30 homeassistant-vm kernel: audit: type=1334 audit(1655743890.581:1867): prog-id=789 op=LOAD Jun 20 16:51:30 homeassistant-vm kernel: audit: type=1334 audit(1655743890.581:1868): prog-id=790 op=LOAD Jun 20 16:51:30 homeassistant-vm audit: BPF prog-id=790 op=LOAD Jun 20 16:51:30 homeassistant-vm systemd[1]: Started Process Core Dump (PID 141370/UID 0). Jun 20 16:51:30 homeassistant-vm systemd-coredump[141371]: Process 141357 (python3) of user 0 dumped core. Jun 20 16:51:30 homeassistant-vm maisken/paradox-ip150-amd64:1.2/addon_213cc295_paradox_ip150_mqtt[393]: /run.sh: line 8: 10567 Aborted (core dumped) python3 ip150_mqtt.py /data/options.json Jun 20 16:51:30 homeassistant-vm systemd[1]: systemd-coredump@13-141370-0.service: Deactivated successfully. Jun 20 16:51:30 homeassistant-vm audit: BPF prog-id=0 op=UNLOAD Jun 20 16:51:30 homeassistant-vm audit: BPF prog-id=0 op=UNLOAD Jun 20 16:51:30 homeassistant-vm kernel: audit: type=1334 audit(1655743890.889:1869): prog-id=0 op=UNLOAD Jun 20 16:51:30 homeassistant-vm kernel: audit: type=1334 audit(1655743890.889:1870): prog-id=0 op=UNLOAD

[3] Mosquitto timing out

Jun 05 08:32:07 homeassistant-vm homeassistant/amd64-addon-mosquitto:6.1.2/addon_core_mosquitto[393]: time="2022-06-05T10:32:07+02:00" level=error msg="POST error: Post \"http://127.0.0.1:80/superuser\": EOF"

[4]

Jun 20 15:28:33 homeassistant-vm homeassistant/amd64-hassio-supervisor:latest/hassio_supervisor[393]: 22-06-20 17:28:33 WARNING (MainThread) [supervisor.updater] Can't fetch versions from https://version.home-assistant.io/dev.json: Timeout

scstraus commented 2 years ago

I am having the same issue on Supervised on Debian 11, so I don't think this is an OS issue.

jorgbad commented 1 year ago

Same issue with vmware ova from hassos 8.1 hassos 8.0 works ok I have an vm snapshot in 8.0, I tried to update to 8.1 and 8.2 and had to restore the vm snapshot

adriangit123 commented 1 year ago

Same issue on raspberry pi 4. :(

agners commented 1 year ago

@jorgbad @alfredopironti can you try 8.4 and the upcoming 8.5 soon to be on beta channel. It doesn't really has an update which addresses the problem specifically, but since the issue appeared without known change it is likely cause by a stable kernel update. In every OS version we update the kernel to latest stable, so there is a chance that this resolves the problem again.

One thing which could explain the issue is memory pressure. Do your system have enough memory (assigned) and can you monitor the amount of free memory in these instances.

@adriangit123 so reverting to 8.0 helps in your case too? Can you share error messages from your case?

adriangit123 commented 1 year ago

No, reventing to 8.0 don't solve my problem, ghive me error:

s6-overlay-suexec: fatal: can only run as pid 1.  New erorr is: "s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
Traceback (most recent call last):
  File "//ip150_mqtt.py", line 140, in <module>
    ip_mqtt.loop_forever()
  File "//ip150_mqtt.py", line 122, in loop_forever
    self.ip.login(self._cfg['PANEL_CODE'], self._cfg['PANEL_PASSWORD'])
  File "/ip150.py", line 142, in login
    raise Paradox_IP150_Error(
ip150.Paradox_IP150_Error: Wrong page fetcehd. Did you connect to the right server and port? Server returned: <!DOCTYPE HTML PUBLIC '-//W3C//DTD HTML 4.01 Transitional//EN' 'http://www.w3.org/TR/html4/loose.dtd'>
<html>
<head>
    <meta http-equiv='content-type' content='text/html; charset=UTF-8' />
    <link rel='stylesheet' type='text/css' href='webstyles.css' />
    <script type='text/javascript' src='langue.js'></script><script type='text/javascript' src='commun.js'></script></head><body><div id = 'ERROR' style='margin-top:60px;'></div><title>aaa</title><script type='text/javascript'>;var sre = "<table><tr><td align='middle'><div class='box' style='width:460px;margin:80px;'><div class='box-title strips'>" + top.ln_cant[1] + "</div><div class='box-content'><div class='msg' id='MESSAGE'></div></div></div></td></tr></table>";document.getElementById('ERROR').innerHTML = sre; document.getElementById('MESSAGE').innerHTML = top.cant('System Master');</script></body></html>"

Thank you.

agners commented 1 year ago

@adriangit123 then it is a different error. Please read the original issue carefully: It says 8.0 solves the problem, and your errors are quite a bit different. Your problem is unlikely related to the operating system, and does not belong here. Please report your poblem in the add-on repository: https://github.com/maisken/Paradox_IP150/issues.

adriangit123 commented 1 year ago

@agners thank you.

ddppddpp commented 1 year ago

upgrading to OS 8.5 doesn't fix the issue for me.

alfredopironti commented 1 year ago

FYI, using HassOS 8.5, I tried to rebuild the add-on changing the base image. Instead of using the Home Assistant add-on recommended image, I tried with both plain Alpine and plain Debian. The issue persists, so I'm ruling out this is something specific to the add-on base image.

alfredopironti commented 1 year ago

One thing which could explain the issue is memory pressure. Do your system have enough memory (assigned) and can you monitor the amount of free memory in these instances.

@agners I allocated 8GB of RAM to the instance. The Home Assistant Memory graph under System -> Hardware shows 10% usage (0.8 GB); the VM hypervisor (proxmox) shows 1.63GB used, and I'm still observing the timeout issues.

I also tried to disable IPv6 in Home Assistant, via System -> Network, but the issue persisted as well. (Just trying out random troubleshooting, in case it sheds some more light.)

Also, may this issue be related? Sadly there's no much info there as well.

alfredopironti commented 1 year ago

FYI, upgrading to OS 9.0 doesn't fix the issue for me.

scstraus commented 1 year ago

Again, has nothing to do with HassOS. Same issue on Debian, started happening with zero change in OS version.

alfredopironti commented 1 year ago

I believe I figured out the core issue, and now sorted it somewhat in the add-on itself. In a nutshell, the add-on HTTP client is re-using source TCP ports too early, before the TIME_WAIT timeout expires on the Paradox web server. Since there are several TCP source ports, usually the kernel picks a fresh one (or re-uses one after a long time), and the HTTP connection goes well. However, sometimes the kernel picks the same source TCP port that was just used a few seconds before. In that case, the Paradox web server (which is still in its TIME_WAIT state) ignores the new TCP SYN packets, leading to the timeout on the client.

The problem was fundamentally always there, but it became exacerbated with kernel 5.15.41 (introduced in HassOS 8.1, and several other recent Linux distributions), when the source TCP port picking algorithm was changed, making early port re-use more likely.

The add-on now uses a very aggressive timeout on HTTP polling GET requests. If the timeout expires, it likely means we're facing an early TCP source port re-use; so the GET request is re-issued (up to 5 attempts).

More background, for completeness:

Review of TCP WAIT states
Linux 5.15.41 Changelog: commit b763fce193b42048444afd85d066b136288ad2c8 (and related) explain the change in TCP source port allocation
TCP source port fingerprinting attack, motivating the changes in 5.15.41

That may explain other timeouts at the OS level, as reported above in this thread.

Hope this helps and thanks for the support!

scstraus commented 1 year ago

Yay! Will we be seeing a new version of the add-on soon?

djsomi commented 1 year ago

Its already published, seems OK for me from yesterday, sensors not showing offline status. I only get this in the logs:

_WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
WARNING:root:Error getting Paradox status update. Doing clean shutdown. Error details: HTTPConnectionPool(host='192.168.1.138', port=80): Read timed out.
Traceback (most recent call last):
  File "//ip150_mqtt.py", line 153, in <module>
    ip_mqtt.loop_forever()
  File "//ip150_mqtt.py", line 135, in loop_forever
    self.ip.login(self._cfg['PANEL_CODE'], self._cfg['PANEL_PASSWORD'])
  File "/ip150.py", line 149, in login
    raise Paradox_IP150_Error(
ip150.Paradox_IP150_Error: Wrong page fetcehd. Did you connect to the right server and port? Server returned: <!DOCTYPE HTML PUBLIC '-//W3C//DTD HTML 4.01 Transitional//EN' 'http://www.w3.org/TR/html4/loose.dtd'>
<html>
<head>
    <meta http-equiv='content-type' content='text/html; charset=UTF-8' />
    <link rel='stylesheet' type='text/css' href='webstyles.css' />
    <script type='text/javascript' src='langue.js'></script><script type='text/javascript' src='commun.js'></script></head><body><div id = 'ERROR' style='margin-top:60px;'></div><title>RiasztÃ³ - Paradox</title><script type='text/javascript'>;var sre = "<table><tr><td align='middle'><div class='box' style='width:460px;margin:80px;'><div class='box-title strips'>" + top.ln_cant[1] + "</div><div class='box-content'><div class='msg' id='MESSAGE'></div></div></div></td></tr></table>";document.getElementById('ERROR').innerHTML = sre; document.getElementById('MESSAGE').innerHTML = top.cant('System Master');</script></body></html>_

alfredopironti commented 1 year ago

@djsomi thanks for sharing. Please let's move to the add-on thread for support about running the add-on.

agners commented 1 year ago

@alfredopironti interesting find! Thanks for the update and detailed explanation!

Kinda surprising to me that a stable kernel update would update such an algorithm.. Oh well.

alfredopironti commented 1 year ago

Oh well, indeed! Also thanks for all the support, and patience with this issue!

home-assistant / operating-system