search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.71k stars 30.84k forks source link

Repeating errors with async_upnp_client.ssdp and async_upnp_client.server #118614

Open mfort01 opened 5 months ago

mfort01 commented 5 months ago

The problem

While looking in home-assistant.log for error messages related to another issue I found that the Async UPNP advertisement service repeatedly erroring (approximately every 30 secs) upon sending SSDP packets. I just yesterday had pulled the latest container version and updated to 2024.5.5 (had been on 2024.1.x). Not sure if its related though as I'd not looked at the log file for months.

While trying to troubleshoot I did enable UPNP on my router and it was found nearly immediately as a potential service in HA, so appears the device discovery side of things is working. Quick scans through documentation for the handful of integrations I'm running doesn't suggest any are using UPNP (i.e. no DLNA devices or integrations installed)

Happy to provide any additional info/debug outputs upon suggestion.

HA configuration.yaml logger config logger: default: error logs: homeassistant.components.ssdp: debug async_upnp_client.ssdp: debug async_upnp_client.server: debug async_upnp_client.traffic: error

Docker-compose.yml configuration homeassistant: container_name: homeassistant image: "ghcr.io/home-assistant/home-assistant:stable" volumes: - ./homeassistant:/config - ./etc/localtime:/etc/localtime:ro - /run/dbus:/run/dbus:ro devices: - /dev/ttyUSB0:/dev/ttyUSB0 restart: unless-stopped privileged: true network_mode: host

What version of Home Assistant Core has the issue?

core-2024.5.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Unknown

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2024-06-01 16:49:15.140 DEBUG (MainThread) [homeassistant.components.ssdp] Binding UPnP HTTP server to: 192.168.10.203:40000
2024-06-01 16:49:15.140 DEBUG (MainThread) [homeassistant.components.ssdp] Binding UPnP HTTP server to: fe80::f86c:18ff:feb2:f3cc%2:40000
2024-06-01 16:49:15.173 DEBUG (MainThread) [async_upnp_client.server] Device listening at http://192.168.10.203:40000/device.xml
2024-06-01 16:49:15.173 DEBUG (MainThread) [async_upnp_client.server] Starting SSDP handling, source: ('192.168.10.203', 0), target: ('239.255.255.250', 1900)
2024-06-01 16:49:15.173 DEBUG (MainThread) [async_upnp_client.server] Start listening for search requests
2024-06-01 16:49:15.173 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '192.168.10.203', ('192.168.10.203', 0)), target: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '239.255.255.250', ('239.255.255.250', 1900))
2024-06-01 16:49:15.174 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '192.168.10.203', ('192.168.10.203', 0)), target: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '239.255.255.250', ('239.255.255.250', 1900))
2024-06-01 16:49:15.174 DEBUG (MainThread) [async_upnp_client.server] Binding socket, socket: <socket.socket fd=82, family=2, type=2, proto=0, laddr=('0.0.0.0', 0)>, address: ('', 1900)
2024-06-01 16:49:15.176 DEBUG (MainThread) [async_upnp_client.ssdp] Connection made, transport: <_SelectorDatagramTransport fd=82 read=idle write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=82, family=2, type=2, proto=0, laddr=('0.0.0.0', 1900)>
2024-06-01 16:49:15.177 DEBUG (MainThread) [async_upnp_client.server] Start advertisements announcer
2024-06-01 16:49:15.178 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '192.168.10.203', ('192.168.10.203', 0)), target: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_DGRAM: 2>, 17, '239.255.255.250', ('239.255.255.250', 1900))
2024-06-01 16:49:15.178 DEBUG (MainThread) [async_upnp_client.server] Device listening at http://[fe80::f86c:18ff:feb2:f3cc%2]:40000/device.xml
2024-06-01 16:49:15.178 DEBUG (MainThread) [async_upnp_client.server] Starting SSDP handling, source: ('fe80::f86c:18ff:feb2:f3cc', 0, 0, 2), target: ('FF02::C', 1900, 0, 2)
2024-06-01 16:49:15.178 DEBUG (MainThread) [async_upnp_client.server] Start listening for search requests
2024-06-01 16:49:15.178 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'fe80::f86c:18ff:feb2:f3cc%2', ('fe80::f86c:18ff:feb2:f3cc', 0, 0, 2)), target: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'ff02::c%2', ('ff02::c', 1900, 0, 2))
2024-06-01 16:49:15.179 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'fe80::f86c:18ff:feb2:f3cc%2', ('fe80::f86c:18ff:feb2:f3cc', 0, 0, 2)), target: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'ff02::c%2', ('ff02::c', 1900, 0, 2))
2024-06-01 16:49:15.180 DEBUG (MainThread) [async_upnp_client.server] Binding socket, socket: <socket.socket fd=89, family=10, type=2, proto=0, laddr=('::', 0, 0, 0)>, address: ('', 1900)
2024-06-01 16:49:15.181 DEBUG (MainThread) [async_upnp_client.ssdp] Connection made, transport: <_SelectorDatagramTransport fd=86 read=idle write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=86, family=2, type=2, proto=0, laddr=('0.0.0.0', 0)>
2024-06-01 16:49:15.181 DEBUG (MainThread) [async_upnp_client.ssdp] Connection made, transport: <_SelectorDatagramTransport fd=89 read=idle write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=89, family=10, type=2, proto=0, laddr=('::', 1900, 0, 0)>
2024-06-01 16:49:15.182 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:49:15.182 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: upnp:rootdevice, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::upnp:rootdevice
2024-06-01 16:49:15.182 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=86 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=86, family=2, type=2, proto=0, laddr=('0.0.0.0', 0)>, target: ('239.255.255.250', 1900)
2024-06-01 16:49:15.183 DEBUG (MainThread) [async_upnp_client.server] Start advertisements announcer
2024-06-01 16:49:15.183 DEBUG (MainThread) [async_upnp_client.ssdp] Creating socket, source: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'fe80::f86c:18ff:feb2:f3cc%2', ('fe80::f86c:18ff:feb2:f3cc', 0, 0, 2)), target: (<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_DGRAM: 2>, 17, 'ff02::c%2', ('ff02::c', 1900, 0, 2))
2024-06-01 16:49:15.184 DEBUG (MainThread) [async_upnp_client.ssdp] Connection made, transport: <_SelectorDatagramTransport fd=91 read=idle write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 0, 0, 0)>
2024-06-01 16:49:15.185 DEBUG (MainThread) [homeassistant.components.ssdp] SSDP: ssdp_device: <SsdpDevice(UUID:F44041A5-30C1-4632-8882-D7BE2B09B577)>, dst: upnp:rootdevice, source: SsdpSource.ADVERTISEMENT_ALIVE
2024-06-01 16:49:15.185 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:49:15.185 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: upnp:rootdevice, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::upnp:rootdevice
2024-06-01 16:49:15.185 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 0, 0, 0)>, target: ('FF02::C', 1900, 0, 2)
2024-06-01 16:49:15.186 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>
2024-06-01 16:49:45.185 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:49:45.185 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577
2024-06-01 16:49:45.185 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=86 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=86, family=2, type=2, proto=0, laddr=('0.0.0.0', 60242)>, target: ('239.255.255.250', 1900)
2024-06-01 16:49:45.186 DEBUG (MainThread) [homeassistant.components.ssdp] SSDP: ssdp_device: <SsdpDevice(UUID:F44041A5-30C1-4632-8882-D7BE2B09B577)>, dst: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577, source: SsdpSource.ADVERTISEMENT_ALIVE
2024-06-01 16:49:45.187 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:49:45.187 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577
2024-06-01 16:49:45.187 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>, target: ('FF02::C', 1900, 0, 2)
2024-06-01 16:49:45.188 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>
2024-06-01 16:50:15.186 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:50:15.187 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: urn:home-assistant.io:device:HomeAssistant:1, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::urn:home-assistant.io:device:HomeAssistant:1
2024-06-01 16:50:15.187 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=86 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=86, family=2, type=2, proto=0, laddr=('0.0.0.0', 60242)>, target: ('239.255.255.250', 1900)
2024-06-01 16:50:15.187 DEBUG (MainThread) [homeassistant.components.ssdp] SSDP: ssdp_device: <SsdpDevice(UUID:F44041A5-30C1-4632-8882-D7BE2B09B577)>, dst: urn:home-assistant.io:device:HomeAssistant:1, source: SsdpSource.ADVERTISEMENT_ALIVE
2024-06-01 16:50:15.189 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:50:15.189 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: urn:home-assistant.io:device:HomeAssistant:1, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::urn:home-assistant.io:device:HomeAssistant:1
2024-06-01 16:50:15.189 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>, target: ('FF02::C', 1900, 0, 2)
2024-06-01 16:50:15.189 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>
2024-06-01 16:50:45.188 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:50:45.188 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: upnp:rootdevice, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::upnp:rootdevice
2024-06-01 16:50:45.188 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=86 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=86, family=2, type=2, proto=0, laddr=('0.0.0.0', 60242)>, target: ('239.255.255.250', 1900)
2024-06-01 16:50:45.190 DEBUG (MainThread) [async_upnp_client.server] Announcing
2024-06-01 16:50:45.190 DEBUG (MainThread) [async_upnp_client.server] Sending advertisement, NTS: ssdp:alive, NT: upnp:rootdevice, USN: UUID:F44041A5-30C1-4632-8882-D7BE2B09B577::upnp:rootdevice
2024-06-01 16:50:45.190 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>, target: ('FF02::C', 1900, 0, 2)
2024-06-01 16:50:45.191 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=91 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=91, family=10, type=2, proto=0, laddr=('::', 50935, 0, 0)>

Additional information

No response

home-assistant[bot] commented 5 months ago

ssdp documentation ssdp source

StevenLooman commented 4 months ago

Thank you for this issue @mfort01. The ssdp component is both used for announcing the Home Assistant presence on the network and listening for any UPnP devices (such as, as you mentioned, DLNA devices, IGD devices (routers, upnp), ...).

Given the log entries before the ERRORs, I do think the error originates from the announcing the Home Assistant presence. It also appears that it is related to the IPv6 address ::, on the fd=91 socket.

I'm not entirely sure why this is happening. Can you elaborate a bit more on your set up? Like, are you running HAOS, from a container, VM, ...

And is there a firewall preventing sending any packets?

Edwin184 commented 1 month ago

I had what looks the same problem and solved it for me. In my configuration I had a static IP address defined and have made a address reservation in my Deco. However what I found was that the MAC address on the address reservation in my Deco was not the same MAC address as my Home Assistant has. So I corrected this everything is working fine again.