HA continually opens connections to localhost causing fd leak

gr_h_m · March 28, 2021, 10:01pm

Hi everyone,

I’ve been hitting a strange issue with my HA installation recently and wanted to post about it before debugging further, just in case someone else has come across it. I’m sure it’s something in my configuration/setup since otherwise it would be a widespread issue, but it’s proving hard to isolate the issue.

Every day or so, HA starts to fail because it has hit the file descriptor limit (currently set to 1024 on my system). The cause seems to be a large number of TCP socket connections to and from ephemeral ports on localhost, for example:

tcp        0      0 localhost:36072         localhost:46349         ESTABLISHED hass       427633     31009/python3.8     
tcp        0      0 localhost:41709         localhost:60174         ESTABLISHED hass       352368     31009/python3.8     
tcp        0      0 localhost:41516         localhost:39049         ESTABLISHED hass       357908     31009/python3.8     
tcp        0      0 localhost:40408         localhost:46625         ESTABLISHED hass       444383     31009/python3.8

I’ve spent some time debugging with strace and wireshark, and it looks like nothing is sent over these connections beyond the usual TCP handshake. The fact that both ends are ephemeral ports also seems unusual and probably wrong.

When the fd limit is hit, I do see errors like this (amongst others which are all just symptomatic of being out of file descriptors):

Mar 27 17:15:59 hostname hass[4687]: 2021-03-27 17:15:59 ERROR (MainThread) [homeassistant] Error doing job: socket.accept() out of system resource
Mar 27 17:15:59 hostname hass[4687]: Traceback (most recent call last):
Mar 27 17:15:59 hostname hass[4687]:   File "/nix/store/yl69v76azrz4daiqksrhb8nnmdiqdjg9-python3-3.8.8/lib/python3.8/asyncio/selector_events.py", line 164, in _accept_connection
Mar 27 17:15:59 hostname hass[4687]:     conn, addr = sock.accept()
Mar 27 17:15:59 hostname hass[4687]:   File "/nix/store/yl69v76azrz4daiqksrhb8nnmdiqdjg9-python3-3.8.8/lib/python3.8/socket.py", line 292, in accept
Mar 27 17:15:59 hostname hass[4687]:     fd, addr = self._accept()
Mar 27 17:15:59 hostname hass[4687]: OSError: [Errno 24] Too many open files

It’s possible this is the offending code that’s failing, or it could be something unrelated but since it’s async it’s not easy to track back to where the accept was initiated from. I’ve tried attaching vscode remotely, but it won’t let me set function breakpoints so it’s of limited help.

Other things I’ve tried:

Disabling integrations one by one
Setting debug logging as the default and eyeballing logs for connections to localhost

I’m running HA 2021.3.4 on Linux (NixOS) x86_64, not using docker. Unfortunately I’ve been changing my installation quite a bit recently and since the problem only manifests after HA has been running for a long time, it’s hard to say when this started happening. It definitely also occurred with 2021.3.3.

The error is similar to HA Crashing with OSError: [Errno 24] Too many open files but in that case the destination address is consistent, it’s not in my case.

If anyone has any advice on how best to debug further it would be appreciated.

Thanks in advance!

gr_h_m · April 3, 2021, 10:37pm

In case anyone else hits this, I think I made some progress on tracking the issue down to the ha-dyson custom component (which is still under development): https://github.com/shenxn/ha-dyson/issues/34.

Also, if anyone is debugging a similar issue, I found the Python audit events quite useful to find the problem: https://docs.python.org/3/library/audit_events.html. I just hacked a hook like this into the Home Assistant start script:

    import sys                                                                                                                                                                                                                                                                                                                                                                                                                                           
    import traceback                                                                                                                                                                                                                   
    def _my_audit_hook(event, args):                                                                                                                                                                                                   
        if event.startswith("socket."):                                                                                                                                                                                                
            msg = "----------------------------------\n"                                                                                                                                                                               
            msg += f"AUDIT {event} {args}\n"                                                                                                                                                                                           
            msg += "".join(traceback.format_stack())                                                                                                                                                                                   
            msg += "----------------------------------\n"                                                                                                                                                                              
            print(msg, file=sys.stderr)                                                                                                                                                                                                
    sys.addaudithook(_my_audit_hook)

logan893 · October 24, 2022, 10:49pm

@gr_h_m could you elaborate on where you added this hook code into HA?

Might need something like this to troubleshoot this new issue.

github.com/home-assistant/core

Google Nest starts oscillating between on/off serveral times per second which results in huge logs every night

opened 05:11AM - 03 Oct 22 UTC

troelde

integration: cast

### The problem Every night at about 2-4 am, my google nest starts oscillating …between on/off several times per second due to exception. This results in huge logs and degraded performance. To stop it, I need to deactivate Google Cast integration, and restart Home assistant core. It is impossible to download complete log without choking the server and hard reboot is the only option. ### What version of Home Assistant Core has the issue? 2022.9.7 ### What was the last working version of Home Assistant Core? _No response_ ### What type of installation are you running? Home Assistant OS ### Integration causing the issue Google Cast ### Link to integration documentation on our website https://www.home-assistant.io/integrations/cast ### Diagnostics information Error from log summary: ``` Logger: pychromecast.socket_client Source: /usr/local/lib/python3.10/site-packages/pychromecast/socket_client.py:571 First occurred: 03:46:31 (192766 occurrences) Last logged: 06:05:30 [Google nest(192.168.1.113):8009] Error in select call: filedescriptor out of range in select() Logger: pychromecast.socket_client Source: /usr/local/lib/python3.10/site-packages/pychromecast/socket_client.py:663 First occurred: 03:46:13 (192767 occurrences) Last logged: 06:05:30 [Google nest(192.168.1.113):8009] Error communicating with socket, resetting connection ### Example YAML snippet _No response_ ### Anything in the logs that might be useful for us? _No response_ ### Additional information Home Assistant 2022.9.7 Supervisor 2022.09.1 Operating System 9.0 UI 20220907.2

(Tagging @frenck in case he has additional ideas.)

gr_h_m · October 25, 2022, 6:34am

I added it to __main__ somewhere round here: core/homeassistant at 559e28143147b85a606ef76e409b14a04c6bef3f · home-assistant/core · GitHubmain.py#L155.

Here was the final audit hook I ended up with:

import sys
import socket
import traceback
def _my_audit_hook(event, args):
    if event == "socket.bind"
        sock, addr = args
        addr_host, addr_port = addr
        if sock.type == socket.SOCK_STREAM and addr_port == 0:
            msg = "----------------------------------\n"
            msg += f"AUDIT {event} {sock} {addr}\n"
            msg += "".join(traceback.format_stack())
            msg += "----------------------------------\n"
            print(msg, file=sys.stderr)
sys.addaudithook(_my_audit_hook)

Hope that helps!

logan893 · October 25, 2022, 11:30am

Thanks!

Had to make a couple of modifications to get this to work.

You missed a “:” for the added if statement above, which prevents HA from even starting.
And even though I don’t use IPv6 it seems to still be present, and “addr” for IPv6 is a four-tuple, and this issue makes the HA GUI not come up since this hook interrupts even that.

Updated code:

import sys
import socket
import traceback
def _my_audit_hook(event, args):
    if event == "socket.bind":
        sock, addr = args
        addr_host, addr_port, *_ = addr
        if sock.type == socket.SOCK_STREAM and addr_port == 0:
            msg = "----------------------------------\n"
            msg += f"AUDIT {event} {sock} {addr}\n"
            msg += "".join(traceback.format_stack())
            msg += "----------------------------------\n"
            print(msg, file=sys.stderr)
sys.addaudithook(_my_audit_hook)

rorygallagher2010 · August 25, 2024, 11:18am

I recently encountered this issue, and was able to determine the cause by using netstat (netstat -A inet -p).

The netstat output showed that there were hundreds of UDP connections from my home assistant instance to a single LIFX bulb. A potential issue with the Lifx integration then. The only cause I can think of is that I recently replaced my ISP router, and this correlates to around when the issue started. None of my other lifx bulbs are experiencing this issue though.

It’s possible resetting or removing and re-adding the bulb could resolve this but I went fully nuclear, and just replaced the problem bulb with a spare Philips Hue bulb I had lying around.