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
71.07k stars 29.73k forks source link

async_upnp_client errors #69669

Closed tomasz8w closed 2 years ago

tomasz8w commented 2 years ago

The problem

After upgrading to 2022.4.1 I started getting errors like below:

Logger: async_upnp_client.ssdp
Source: /usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py:229
First occurred: 12:52:32 PM (11 occurrences)
Last logged: 1:12:32 PM

Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=15 read=polling write=<idle, bufsize=0>>

I have two DLNA Digital Media Renderers and DLNA Digital Media Server configured.

Edit: problem seems to be related with DLNA dmr, every two minutes my soundbar is switching between unavailable and idle state.

What version of Home Assistant Core has the issue?

core-2022.4.1

What was the last working version of Home Assistant Core?

core-2022.3.5

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

DLNA Digital Media Renderer

Link to integration documentation on our website

https://www.home-assistant.io/integrations/dlna_dmr/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=15 read=polling write=<idle, bufsize=0>>
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending SSDP packet, target: ('FF02::C', 1900, 0, 2), data: b'M-SEARCH * HTTP/1.1\r\nHOST:[FF02::C%2]:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2022-04-08 13:00:32 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 1] Operation not permitted, transport: <_SelectorDatagramTransport fd=15 read=polling write=<idle, bufsize=0>>
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=16 read=polling write=<idle, bufsize=0>>
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending SSDP packet, target: ('239.255.255.250', 1900), data: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.ssdp] Sending SSDP packet, transport: <_SelectorDatagramTransport fd=16 read=polling write=<idle, bufsize=0>>
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending SSDP packet, target: ('255.255.255.255', 1900), data: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.8.142', 46395): b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.8.95', 51681): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1800\r\nDATE: Fri, 08 Apr 2022 11:00:32 GMT\r\nEXT:\r\nLOCATION: http://192.168.8.95:49152/description.xml\r\nBOOTID.UPNP.ORG: FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002\r\nSERVER: Linux/4.4.22\r\nST: upnp:rootdevice\r\nUSN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002::upnp:rootdevice\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.search] Received advertisement, USN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002::upnp:rootdevice, location: http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.8.95', 51681): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1800\r\nDATE: Fri, 08 Apr 2022 11:00:32 GMT\r\nEXT:\r\nLOCATION: http://192.168.8.95:49152/description.xml\r\nBOOTID.UPNP.ORG: FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002\r\nSERVER: Linux/4.4.22\r\nST: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002\r\nUSN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.search] Received advertisement, USN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002, location: http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.8.95', 51681): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1800\r\nDATE: Fri, 08 Apr 2022 11:00:32 GMT\r\nEXT:\r\nLOCATION: http://192.168.8.95:49152/description.xml\r\nBOOTID.UPNP.ORG: FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002\r\nSERVER: Linux/4.4.22\r\nST: urn:schemas-upnp-org:device:MediaRenderer:1\r\nUSN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002::urn:schemas-upnp-org:device:MediaRenderer:1\r\n\r\n'
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.search] Received advertisement, USN: uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002::urn:schemas-upnp-org:device:MediaRenderer:1, location: http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [homeassistant.components.dlna_dmr] SSDP SsdpChange.ALIVE notification of device uuid:FFB8F002-9BCC-CB6A-95A2-4F26FFB8F002::urn:schemas-upnp-org:device:MediaRenderer:1 at http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Connecting to device at http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.client_factory] Creating device, description_url: http://192.168.8.95:49152/description.xml
2022-04-08 13:00:32 DEBUG (MainThread) [async_upnp_client.traffic.upnp] Sending request:
GET http://192.168.8.95:49152/description.xml

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

dlna_dmr documentation dlna_dmr source (message by IssueLinks)

probot-home-assistant[bot] commented 2 years ago

Hey there @stevenlooman, @chishm, mind taking a look at this issue as it has been labeled with an integration (dlna_dmr) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

mr-orange commented 2 years ago

i have the same error with the LIFX platform.

Error importing platform config_flow from integration lifx to set up lifx configuration entry: cannot import name 'determine_source_target' from 'async_upnp_client.ssdp' (/srv/homeassistant/lib/python3.9/site-packages/async_upnp_client/ssdp.py)

treb33 commented 2 years ago

Same issue here with my LG TV. Went back to core_2022.3.8 and it works fine again.

chishm commented 2 years ago

This is a complicated IPv6 problem, related to the ssdp component and the async-upnp-client library. @StevenLooman you're probably interested in this too.

I have a few questions to help narrow down the cause:

  1. Do you have any firewalls running on the machine where HA is installed?
  2. Looking at this line: [async_upnp_client.traffic.ssdp] Sending SSDP packet, target: ('FF02::C', 1900, 0, 2) tells me that it's interface 2 that it's trying to use. If you run ip link show | grep -hE '^2:' at a command line, can you please tell me what it tells you? This will be an interface name, and I'm curious if it's your normal network interface, a virtual interface, or something else.
  3. Are you using "Auto Configure" for the network in Configuration -> Settings -> General -> Network? Note: This setting will only be available if you have advanced mode enabled for your profile. It's not important to get this information if you're not using advanced mode.

@mr-orange: That looks like a different issue. The determine_source_target function was introduced in async-upnp-client 0.24.0 (and is still there), and Home Assistant 2022.4.0 needs async-upnp-client 0.27.0. So first thing to check is that you have async-upnp-client==0.27.0 in whatever Python environment Home Assistant is running in.

tomasz8w commented 2 years ago

  1. I have few ufw rules, this two are relevant i guess:

    To                Action      From
[ 2] Anywhere     ALLOW IN    192.168.0.0/16
[ 4] Anywhere     ALLOW IN    172.30.32.0/23

    172.30.32.0 is a subnet with HA containers.

  2. Interface 2 is a physical Interface: 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP mode DEFAULT group default qlen 1000

  3. Yes, auto configure is checked. eno1 interface is detected.

It started working after few hours, but after HA restart it is unavailable again.

chishm commented 2 years ago

Very interesting. Does that mean you have HA running in a Docker container with host networking? And IPv6 too?

Here's another thing to test: can you successfully run ping6 FF02::C%2 from within the HA container and also the host machine?

I suspect there's something interfering with IPv6 multicast traffic. The physical interface has "MULTICAST" enabled, so that's probably not it. More likely is a firewall -- Docker likes to install its own iptables rules that ufw might not show. Also, the iptables --list command will only show you the IPv4 rules. For IPv6, you'll need ip6tables --list (possibly with sudo).

I also realise that the log messages are not helpful for diagnosing a misconfigured network. This might need some kind of better warning message from Home Assistant when IPv6 socket multicasts fail.

tomasz8w commented 2 years ago

Very interesting. Does that mean you have HA running in a Docker container with host networking? And IPv6 too?

Driver for HA stack is bridge

Here's another thing to test: can you successfully run ping6 FF02::C%2 from within the HA container and also the host machine?

I suspect there's something interfering with IPv6 multicast traffic. The physical interface has "MULTICAST" enabled, so that's probably not it. More likely is a firewall -- Docker likes to install its own iptables rules that ufw might not show. Also, the iptables --list command will only show you the IPv4 rules. For IPv6, you'll need ip6tables --list (possibly with sudo).

I also realise that the log messages are not helpful for diagnosing a misconfigured network. This might need some kind of better warning message from Home Assistant when IPv6 socket multicasts fail.

I'm able to ping FF02::C%2 from host and container after disabling ufw. I checked and default ufw policy is to drop ipv6 traffic. After changing this option in /etc/default/ufw I'm able to ping FF02::C%2 either from host and container. Looks that this issue is fixed, I don't observe errors mentioned here anymore. Thanks for help, I'll observe logs for a while but I guess that was it. However I'm still getting errors described in #57240 sometimes, I mean:

Error during call async_play_media: UpnpConnectionError('[Errno None] Can not write request body for http://192.168.8.95:49152/upnp/control/rendertransport1', None)