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
74.01k stars 31.05k forks source link

UPnP/IGD integration stop working after router restart #62442

Closed ngosang closed 2 years ago

ngosang commented 2 years ago

The problem

I experience a similar error but maybe the cause is different. The router provided by my ISP is garbage and I have configured a router restart every nigh at 5:00 am. At that time the router and the home network stop working for a couple of minutes. All the integrations in Home Assistant are resilient but the UPnP/IGD integration. It stops working until I restart HA.

HA: 2021.11.1 Deploy: Docker in Linux

That are the traces. UPnP/IGD integration stopped working after the first trace.

2021-12-19 04:01:59 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2021-12-19 04:02:23 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-19 04:02:23 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-19 04:02:25 ERROR (MainThread) [homeassistant.components.upnp] Error requesting LiveboxFibra data: Cannot connect to host 192.168.1.1:59852 ssl:default [Network unreachable]
2021-12-19 04:03:23 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-19 04:03:23 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-19 13:04:06 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Timeout occurred while connecting to IPP server.

2021-12-20 04:03:25 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-20 04:03:25 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-20 04:03:50 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2021-12-20 04:04:25 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-20 04:04:25 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>
2021-12-20 05:04:03 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
2021-12-20 05:04:03 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/dhcp/__init__.py", line 197, in async_discover
    for host in await self._discover_hosts.async_discover():
  File "/usr/local/lib/python3.9/site-packages/aiodiscover/discovery.py", line 138, in async_discover
    await loop.run_in_executor(None, sys_network_data.setup)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.9/site-packages/aiodiscover/network.py", line 155, in setup
    self.network = get_network(self.local_ip, self.adapters)
  File "/usr/local/lib/python3.9/site-packages/aiodiscover/network.py", line 74, in get_network
    return ip_network(f"{local_ip}/{network_prefix}", False)
  File "/usr/local/lib/python3.9/ipaddress.py", line 83, in ip_network
    raise ValueError('%r does not appear to be an IPv4 or IPv6 network' %
ValueError: 'None/24' does not appear to be an IPv4 or IPv6 network

imagen

What version of Home Assistant Core has the issue?

2021.11.1

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

UPnP/IGD

Link to integration documentation on our website

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

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

Related #60858

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

upnp documentation upnp source (message by IssueLinks)

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

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

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

dhcp documentation dhcp source (message by IssueLinks)

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

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

StevenLooman commented 2 years ago

Given the traceback, I'm adding the dhcp integration-label.

bdraco commented 2 years ago

Looks like the ipaddress is somehow None

estebanz01 commented 2 years ago

I'm seeing the exact same issue, but I'm still trying to understand if it's caused by a drop in my internet connection or a problem with HA

StevenLooman commented 2 years ago

@estebanz01, great. Please let us know when you find anything.

Still, HA should be able to handle this/prevent tracebacks.

estebanz01 commented 2 years ago

OK, so in order to replicate this, I had to disconnect the internet from the main router that is not connected to anything, only serves as a relay between my internet provider and my home.

When the router that handles LAN gets without internet access, after an specific amount of time, the IP address gets dropped and my HA instance thinks I don't have an IP assigned (it has one, only that it cannot see the outside). Not sure if it's something related to DNS resolution.

Maybe it's something related on how HA tries to identify IP addresses ?

StevenLooman commented 2 years ago

I was going to say: Create a issue at the aiodiscover repo, but @bdraco is the creator. :)

bdraco commented 2 years ago

It's a bit hard to tell what's going on here.

Can you post the output of 'ip show' and 'ifconfig' when the problem is happening or setup something to run it every 5s so when it does happen you'll have a log?

ngosang commented 2 years ago

The integration is not working even after Home Assistant restart. I have a valid IP, Internet connection and still nothing. The output of ifconfig at the end. Home Assistant 2021.11.1 in Docker (Host network)

imagen Integration traces:

Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
04:17:55 – (ERROR) /usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py - el mensaje se produjo por primera vez a las 31 de diciembre de 2021 04:14:50 y aparece 14 veces
Error fetching ipp data: Invalid response from API: Timeout occurred while connecting to IPP server.
04:17:25 – (ERROR) Internet Printing Protocol (IPP) - el mensaje se produjo por primera vez a las 30 de diciembre de 2021 14:11:43 y aparece 7 veces
:0:0 ResizeObserver loop completed with undelivered notifications.
30 de diciembre de 2021 17:57:12 – (ERROR) components/system_log/__init__.py
Config entry 'LiveboxFibra' for upnp integration not ready yet; Retrying in background
30 de diciembre de 2021 13:25:59 – (ADVERTENCIA) config_entries.py

Home Assistant traces:

2021-12-30 13:25:59 WARNING (MainThread) [homeassistant.config_entries] Config entry 'LiveboxFibra' for upnp integration not ready yet; Retrying in background
2021-12-30 14:11:43 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Timeout occurred while connecting to IPP server.
2021-12-30 17:57:12 ERROR (MainThread) [frontend.js.latest.202111030] :0:0 ResizeObserver loop completed with undelivered notifications.
2021-12-31 04:14:31 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2021-12-31 04:14:50 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2021-12-31 04:14:50 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2021-12-31 04:15:50 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2021-12-31 04:15:50 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-01 04:15:06 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2022-01-01 04:15:52 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-01 04:15:52 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-01 04:16:52 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-01 04:16:52 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-02 04:16:42 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2022-01-02 04:16:54 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-02 04:16:54 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-02 12:36:54 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2022-01-02 14:42:04 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Timeout occurred while connecting to IPP server.
2022-01-03 04:16:55 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-03 04:16:55 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-03 04:17:25 ERROR (MainThread) [homeassistant.components.ipp.coordinator] Error fetching ipp data: Invalid response from API: Error occurred while communicating with IPP server.
2022-01-03 04:17:55 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>
2022-01-03 04:17:55 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 101] Network unreachable, transport: <_SelectorDatagramTransport fd=21 read=polling write=<idle, bufsize=0>>

Ifconfig

eno1      Link encap:Ethernet  HWaddr F4:4D:30:68:70:96  
          inet addr:192.168.1.192  Bcast:192.168.1.255  Mask:255.255.255.0
          inet6 addr: fe80::f64d:30ff:fe68:7096/64 Scope:Link
          inet6 addr: fd69:e320:5a41:0:f64d:30ff:fe68:7096/64 Scope:Global
          inet6 addr: fd69:e320:5a41::ad9/128 Scope:Global
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:10329695 errors:4 dropped:0 overruns:0 frame:2
          TX packets:4626960 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:10719624102 (9.9 GiB)  TX bytes:655303071 (624.9 MiB)
          Interrupt:16 Memory:df100000-df120000
bdraco commented 2 years ago

It doesn't look like this has anything to do with aiodiscover, and the trace is just another symptom of the inability to get the local ip.

StevenLooman commented 2 years ago

Agreed. I'm unsure how I can properly reproduce it in my own setup.

ngosang commented 2 years ago

I just updated to HA 2022.2.2 and it's not working at all.

image

I tried to disable and enable the integration but it's not working. I see this error trace. That's all. 2022-02-06 10:22:40 WARNING (MainThread) [homeassistant.config_entries] Config entry 'LiveboxFibra' for upnp integration not ready yet; Retrying in background

balcanuc commented 2 years ago

When I've installed the HA about 1 month ago, the home-assistant detected my router (TP LINK AX-10) and was able to show al the sensors. Sometime, about 1 week ago, it stoped working and I have something similar to @ngosang

I've checked the router settings and UPnP is enabled.

image

Here is an excerpt from the logs:

2022-02-10 18:07:48 INFO (MainThread) [homeassistant.setup] Setting up upnp
2022-02-10 18:07:48 INFO (MainThread) [homeassistant.setup] Setup of domain upnp took 0.0 seconds
2022-02-10 18:07:58 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Archer AX10' for upnp integration not ready yet; Retrying in background
balcanuc commented 2 years ago

I solved this by deleting (not disabling) the integration then I've added it back.

jdschuitemaker commented 2 years ago

I have done the same, a couple of times already. The error will come back after a while.

StevenLooman commented 2 years ago

I'll try to investigate soon. In the mean time, can you supply logging? See https://github.com/home-assistant/core/issues/60858#issuecomment-986006589 for instructions on how to enable upnp-specific logging.

jdschuitemaker commented 2 years ago

Due to the problems I had uninstalled it, but now re-installed. I also followed the instructoins required to enable logging. As soon it stops working again I will provide logging.

balcanuc commented 2 years ago

I've reinstalled the component, but before that I've enabled the logging. Here is a recent output, but I don't think that it can trouble-shooting request. If it fails again, I'll update the issue with new logs.

2022-02-15 12:19:09 DEBUG (MainThread) [homeassistant.components.upnp] Device discovered: uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1, at: http://192.168.0.1:1900/nzebc/rootDesc.xml
2022-02-15 12:19:09 DEBUG (MainThread) [homeassistant.components.upnp] SSDP Callback, change: SsdpChange.ALIVE, headers: {'CACHE-CONTROL': 'max-age=120', 'ST': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'USN': 'uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'EXT': '', 'SERVER': 'TP-LINK/TP-LINK UPnP/1.1 MiniUPnPd/1.8', 'OPT': '"http://schemas.upnp.org/upnp/1/0/"; ns=01', '01-NLS': '1', 'BOOTID.UPNP.ORG': '1', 'CONFIGID.UPNP.ORG': '1337', '_location_original': 'http://192.168.0.1:1900/nzebc/rootDesc.xml', 'location': 'http://192.168.0.1:1900/nzebc/rootDesc.xml', '_timestamp': datetime.datetime(2022, 2, 15, 12, 19, 9, 818357), '_host': '192.168.0.1', '_port': 1900, '_udn': 'uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a'}
2022-02-15 12:19:09 DEBUG (MainThread) [homeassistant.components.upnp] update_interval: 0:00:30
2022-02-15 12:19:09 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Archer AX10/uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1
2022-02-15 12:19:09 DEBUG (MainThread) [homeassistant.components.upnp] Getting status for device: IGD Device: Archer AX10/uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Exception occurred while trying to get status external IP address for device IGD Device: Archer AX10/uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1: Error during async_call(), status: 500, upnp error: 401 (Invalid Action)
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Archer AX10 data in 0.075 seconds (success: True)
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Enabling sensors
2022-02-15 12:19:10 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.upnp
2022-02-15 12:19:10 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.upnp
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Adding binary sensor
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Adding entities: []
2022-02-15 12:19:10 DEBUG (MainThread) [homeassistant.components.upnp] Adding entities: [<Entity Archer AX10 B received>, <Entity Archer AX10 B sent>, <Entity Archer AX10 packets received>, <Entity Archer AX10 packets sent>, <Entity Archer AX10 External IP>, <Entity Archer AX10 KiB/s received>, <Entity Archer AX10 KiB/s sent>, <Entity Archer AX10 packets/s received>, <Entity Archer AX10 packets/s sent>]
balcanuc commented 2 years ago

Integration with my router is broken again. The first symptom was the fact that no bytes in or out were reported in the graphs. I've disabled and enabled the integration without success. So, I've rebooted the Raspberry Pi (RP4 with 4G).

Here are the logs: https://pastebin.com/8AnqWCQV

StevenLooman commented 2 years ago

Thank you for the logging @balcanuc.

So, I've rebooted the Raspberry Pi (RP4 with 4G).

Does that fix things?

From the logging... There are some interesting things. This is a search response from a router.

2022-02-25 19:07:37 DEBUG (MainThread) [async_upnp_client.ssdp_listener] Received invalid search headers: {'CACHE-CONTROL': 'max-age=120', 'ST': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'USN': 'uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f::urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'EXT': '', 'SERVER': 'TP-LINK/TP-LINK UPnP/1.1 MiniUPnPd/1.8', 'OPT': '"http://schemas.upnp.org/upnp/1/0/"; ns=01', '01-NLS': '1', 'BOOTID.UPNP.ORG': '1', 'CONFIGID.UPNP.ORG': '1337', '_location_original': 'http://[::1]:1900/dkzfv/rootDesc.xml', 'location': 'http://[::1]:1900/dkzfv/rootDesc.xml', '_timestamp': datetime.datetime(2022, 2, 25, 19, 7, 37, 199085), '_host': '192.168.0.1', '_port': 1900, '_udn': 'uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f', '_source': <SsdpSource.SEARCH: 'search'>}

This is a router reporting (different one than that was configured before!) it can be reached at IPv6-localhost (see location.) Also, the search-response was sent via IPv4 (see _host.)

Seeing this however, from the originally configured config entry:

2022-02-25 19:18:29 DEBUG (MainThread) [homeassistant.components.upnp] Setting up config entry: uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1
2022-02-25 19:18:39 DEBUG (MainThread) [homeassistant.components.upnp] Device not discovered: uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1

The UDN (uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a) is different than the one in your later logs (uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f.) Do you have two routers, or an extra device such as a access point? Or perhaps the router is changing its UDN (Unique Device Name, a 'number' which should be static over the lifetime of a single device.)

Another thing is this, though not related to the problems in this issue:

2022-02-25 19:19:37 DEBUG (MainThread) [async_upnp_client.ssdp_listener] Received invalid search headers: {'CACHE-CONTROL': 'max-age=1800', 'DATE': 'Fri, 25 Feb 2022 17:19:37 GMT', 'EXT': '', 'OPT': '"http://schemas.upnp.org/upnp/1/0/"; ns=01', '01-NLS': '53e7fe52-9405-11ec-993f-a5b083283c96', 'SERVER': 'Linux/5.10.60-qnap, UPnP/1.0, Portable SDK for UPnP devices/1.6.22', 'X-User-Agent': 'redsonic', 'ST': 'urn:schemas-upnp-org:service:ContentDirectory:1', 'USN': '46f7d7eb-0be5-4527-928d-e8b6deb857a2::urn:schemas-upnp-org:service:ContentDirectory:1', '_location_original': 'http://192.168.0.122:8080/upnpd/067b2a5664.xml', 'location': 'http://192.168.0.122:8080/upnpd/067b2a5664.xml', '_timestamp': datetime.datetime(2022, 2, 25, 19, 19, 37, 11887), '_host': '192.168.0.122', '_port': 39707, '_source': <SsdpSource.SEARCH: 'search'>}

Your QNAP NAS has an invalid UDN: It should start with uuid:. Perhaps this can be addressed in the used library, but for later...

Anto79-ops commented 2 years ago

I can confirm that this happens to me too, where after I restart my router (Actiontec T3200M), the integration fails or tries to restart setup. The only solution is that I have to delete the integration and and install it again...and then it works. I'm reading the post above...any solution? I can share more information if requested.

StevenLooman commented 2 years ago

@Anto79-ops Does the key of the entry (e.g., uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1) change when you delete the integration and install it again?

Anto79-ops commented 2 years ago

@Anto79-ops Does the key of the entry (e.g., uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a::urn:schemas-upnp-org:device:InternetGatewayDevice:1) change when you delete the integration and install it again?

Thanks for your reply. I didn't check this but I can check this next time it happens... or did you want me to do it now by deleting the integration and then installing it again even though it's working? By the way where do I find such information?

balcanuc commented 2 years ago

@StevenLooman

So, I've rebooted the Raspberry Pi (RP4 with 4G).

No, just rebooting the host did not solve the problem. Next, I've deleted the integration then I've rebooted theRP4. The HA detected the router again and so I've added back the integration. Everything started working again.

Do you have two routers, or an extra device such as a access point?

TLDR: yes.

Here is my setup: I have the TP-Link Router (Archer AX10 v1.0, Firmware Version: 1.2.5 Build 20211117 Rel. 38093(4555) ) that is doing routing, DHCP (and some other things that are not important for this discussin). It has the RP4 with HA connected to along with a bunch of other things (the QNAP NAS, doorbell etc). However the router has the WiFi disabled. For WiFi connection I'm using Amazon eero WLAN-Mesh-System - 3er-Set. All 3 eero devices are wired connected to the router.

Your QNAP NAS has an invalid UDN: It should start with uuid:. Perhaps this can be addressed in the used library, but for later...

I'm not fully getting this. Is something I should configure or is it something that QNAP should fix? The QNAP is not detected by the HA. I did not tried to integrate it yet.

Here is a link to how the logs are looking now after reboot and few days later: https://pastebin.com/FYqNr1uX

Thanks a lot for taking time looking into this.

StevenLooman commented 2 years ago

Here is my setup: I have the TP-Link Router (Archer AX10 v1.0, Firmware Version: 1.2.5 Build 20211117 Rel. 38093(4555) ) that is doing routing, DHCP (and some other things that are not important for this discussin). It has the RP4 with HA connected to along with a bunch of other things (the QNAP NAS, doorbell etc). However the router has the WiFi disabled. For WiFi connection I'm using Amazon eero WLAN-Mesh-System - 3er-Set. All 3 eero devices are wired connected to the router.

Do you also see both devices via the upnp integration in home assitant?

balcanuc commented 2 years ago

On UPnp integration, only the router is detected.

I've made a copy paste (and redact) from the integration.

Archer AX10
UPnP/IGD
[1 device](https://b[redacted]c.duckdns.org/config/devices/device/7ca588[redacted]e362c6) and [9 entities](https://b[redacted]c.duckdns.org/config/entities?historyBack=1&config_entry=89dc3[redacted]8bec)
StevenLooman commented 2 years ago

No, just rebooting the host did not solve the problem. Next, I've deleted the integration then I've rebooted the RP4. The HA detected the router again and so I've added back the integration. Everything started working again.

The UDN (uuid:b8dce60b-93ab-4dea-8541-ca9ede0e607a) is different than the one in your later logs (uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f.)

Does the device still have the same UDN? You can see this in the logs, or in the .storage/core.config_entries file which contains the config entries. Find the entry with the domain: upnp. Something like:

            {
                ...
                "domain": "upnp",
                "title": "Compal Broadband Networks, Inc CH7465LG",
                "data": {
                    "udn": "uuid:...",
                    "st": "urn:schemas-upnp-org:device:InternetGatewayDevice:1",
                    "hostname": ...
                },
                ...
                "unique_id": "uuid:...::urn:schemas-upnp-org:device:InternetGatewayDevice:1",
                ...
            },
balcanuc commented 2 years ago

here is the the section form the file .storage/core.config_entries

{
    "entry_id": "89dc3c05c8c378758f64a799f7178bec",
    "version": 1,
    "domain": "upnp",
    "title": "Archer AX10",
    "data": {
        "udn": "uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f",
        "st": "urn:schemas-upnp-org:device:InternetGatewayDevice:1",
        "hostname": "192.168.0.1"
    },
    "options": {},
    "pref_disable_new_entities": false,
    "pref_disable_polling": false,
    "source": "ssdp",
    "unique_id": "uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f::urn:schemas-upnp-org:device:InternetGatewayDevice:1",
    "disabled_by": null
}
StevenLooman commented 2 years ago

Ok good, the UDN is still uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f, so that has not changed.

However, still no explanation on why it isn't working. I'm also seeing this in your logging:

2022-03-01 22:41:39 DEBUG (MainThread) [homeassistant.components.upnp] Exception occurred while trying to get status external IP address for device IGD Device: Archer AX10/uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f::urn:schemas-upnp-org:device:InternetGatewayDevice:1: Error during async_call(), status: 500, upnp error: 401 (Invalid Action)

This is your device saying that getting some data (external IP among other things) isn't succeeding. Perhaps this is preventing the device from working.

balcanuc commented 2 years ago

The configuration above is the one after I've remove and I've added` integration again and a restart. And now it works.

Should I check this configuration if it start failing again?

StevenLooman commented 2 years ago

Yes please.

balcanuc commented 2 years ago

got it.

StevenLooman commented 2 years ago

I've been trying to reproduce the situation by letting the non-traffic-counter-related calls fail, but no success so far.

StevenLooman commented 2 years ago

Also, if possible, can you provide new logging before+after the it starts failing again?

balcanuc commented 2 years ago

I'll do that. For that I've left the logging levels as below. Let me know if do you think that I have to change anything related to logging levels.

logger:
  default: info
  logs:
    homeassistant.components.alexa: info
    async_upnp_client: debug
    async_upnp_client.traffic: warning
    homeassistant.components.upnp: debug
StevenLooman commented 2 years ago

You can add homeassistant.components.ssdp: debug just to be sure.

balcanuc commented 2 years ago

And it happened again. Here are relevant things.

  1. I've noticed the fact that my Graphana dashboard did not show any data for the last ~ 7 hours. However, when I've checked the integration status on Configuration->Device & Services there was no error.
  2. I've restarted the HA service by clicking on Configuration->Settings->RESTART
  3. I've checked the status of integration on Configuration->Device & Services and there was an error at the router integration.
  4. I've saved the corresponding section from the .storage/core_configentries file and then I've deleted the integration.
  5. I've rebooted the HA host (it runs on RP4) using Configuration/Addon Backup & Supervisor/System/REBOOT HOST
  6. After reboot I've added back the integration and now I can see the points on my Graphana dashboards again.

Below are snippets from core.config_entries that are related to integration.

// before deleting the integration
{
    "entry_id": "89dc3c05c8c378758f64a799f7178bec",
    "version": 1,
    "domain": "upnp",
    "title": "Archer AX10",
    "data": {
        "udn": "uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f",
        "st": "urn:schemas-upnp-org:device:InternetGatewayDevice:1",
        "hostname": "192.168.0.1"
    },
    "options": {},
    "pref_disable_new_entities": false,
    "pref_disable_polling": false,
    "source": "ssdp",
    "unique_id": "uuid:e95b55e3-3576-49bb-a613-2ae14d0de75f::urn:schemas-upnp-org:device:InternetGatewayDevice:1",
    "disabled_by": null
}

// after deleting integration, host restart and adding integration back
{
    "entry_id": "5dd2855da2796a3047e10c9d2ac8f9db",
    "version": 1,
    "domain": "upnp",
    "title": "Archer AX10",
    "data": {
        "udn": "uuid:68b83caf-bb01-49f7-9f67-a080a1af0cc6",
        "st": "urn:schemas-upnp-org:device:InternetGatewayDevice:1",
        "hostname": "192.168.0.1"
    },
    "options": {},
    "pref_disable_new_entities": false,
    "pref_disable_polling": false,
    "source": "ssdp",
    "unique_id": "uuid:68b83caf-bb01-49f7-9f67-a080a1af0cc6::urn:schemas-upnp-org:device:InternetGatewayDevice:1",
    "disabled_by": null
}

The logs gets rotated each time the HA docker gets rotated. I think I've saved them. I've looked into them and seems to not contain sensitive information but to be sure I'm going to send link to them by email.

StevenLooman commented 2 years ago

You are right, the logs show your router is changing its UDN. The UDN should be static over the entire lifetime of the router, but some manufacturers think its better to change this regularly for unknown reasons.

We've dealt with this problem before. The current state of the integration is that it ignores any new discoveries (with a different UDN than the one stored in the config entry) when there is an existing config entry for the same host/hostname. This was built explicitly to prevent new discoveries each time the router changes its UDN. Some users were complaining about several discoveries for the same device, see #45802 for example.

As such, when your router changes its UDN, home assistant explicitly ignores the "new" discovery. Meanwhile, when home assistant restarts, and the upnp component is 'started' again, it tries to find the router by the old UDN, but will never find it. As such, it will stay unavailable until a new config entry is created with the then-current UDN.

I'm unsure what to do. In most situations automatically updating the UDN of the config entry can be without any problems. The host will most likely stay 192.168.1.1 in case of a router, for example. There are some situations where an WiFI Access Point also reports itself as a IGD via UPnP and is thus picked up by the upnp component. I'm currently uncertain what will happen when these devices change their IP (in case of DHCP/non-static IPs) and their UDN. Again, I'm sure this situation will not happen very often, but when it does it might be very annoying.

StevenLooman commented 2 years ago

Here is the code responsible for ignoring the discovery: https://github.com/home-assistant/core/blob/9d6e1ab0e5d8776bf14f500e4637b037c27b8738/homeassistant/components/upnp/config_flow.py#L237. And the accompanying unit test: https://github.com/home-assistant/core/blob/9d6e1ab0e5d8776bf14f500e4637b037c27b8738/tests/components/upnp/test_config_flow.py#L83

balcanuc commented 2 years ago

So, is this an implemented feature that broke my use case (when router changes its urn)?

On Tue, Mar 15, 2022 at 12:00 AM Steven Looman @.***> wrote:

Here is the code responsible for ignoring the discovery: https://github.com/home-assistant/core/blob/dev/homeassistant/components/upnp/config_flow.py#L237. And the accompanying unit test: https://github.com/home-assistant/core/blob/dev/tests/components/upnp/test_config_flow.py#L83

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/62442#issuecomment-1067342012, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEEIZOZEWOV4IF5LNU5AMOLU76ZJPANCNFSM5KOUODLA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you were mentioned.Message ID: @.***>

StevenLooman commented 2 years ago

Yes. But I'd like to try to change the component such that the component will work better with routers like these. I'll try to do this in the upcoming weekend.

StevenLooman commented 2 years ago

@balcanuc Are you able to test changes? I.e., change files in your installation and run home assistant with those changes? If so, can you test the changes from https://github.com/StevenLooman/home-assistant/commit/cf22bbac1801d9a743abe390de00d9310a538772 ? Only the changes to homeassistant/components/upnp/config_flow.py need to be applied.

Anto79-ops commented 2 years ago

Hi, I've been following this thread closely, as I have the sample problem. It was pretty stable since my last post on this thread 18 days ago, but then yesterday night, my internet had a lapse in service, so I had to restart my router and then I broke the integration again. Uninstalled and reinstalled again and it works. I'm looking forward to your conversations.

By the way, not related to this, the intergration doesn't actully report usage for my router (i.e. bytes, packets, sent/received, it never did, just says 0 for all those entities), but it reports everything else OK. I'm just assuming that not all the features (entities) of this plug-in are compatible with my router (Actiontec T3200M).

balcanuc commented 2 years ago

homeassistant/components/upnp/config_flow

I'm not clear what should I do. Should I comment out the line 237 from file _homeassistant/components/upnp/configflow.py?

return self.async_abort(reason="discovery_ignored")

Next, should I reboot the host or only restart the home-assistant?

Also, I'm not clear how can we test it, because I can't broke the integration whenever I want but it seems that it happens at a cadence of once ever 3 weeks or so. After the last fix it continued to work.

However, after I'll get the confirmation of what I should do, I'll go ahead and do it.

After an upgrade I should go and apply the change again?

StevenLooman commented 2 years ago

@balcanuc, the easiest would be to simply replace the file with this file: https://raw.githubusercontent.com/StevenLooman/home-assistant/cf22bbac1801d9a743abe390de00d9310a538772/homeassistant/components/upnp/config_flow.py

Next up, restart home assistant. This makes sure the new file is loaded. No need to restart the host.

To test it... I was hoping you would be able to reproduce it consistently. I am expecting that your router generates a new UDN when it is restarted/rebooted. Can you try that? This way reproducing this will make it a lot easier.

If you do upgrade, you should apply the change again indeed.

@Anto79-ops

By the way, not related to this, the intergration doesn't actully report usage for my router (i.e. bytes, packets, sent/received, it never did, just says 0 for all those entities), but it reports everything else OK. I'm just assuming that not all the features (entities) of this plug-in are compatible with my router (Actiontec T3200M).

Some routers are not reporting statistics properly. For example, my own router (Compal Broadband Networks, Inc CH7465LG), provided by my ISP (dutch, Ziggo/Liberty Global) properly reports input/output byte counters up to ~4.3GB traffic. After that, it always reports 4.294.967.295 bytes. It should actually roll over to 0 bytes and restart the counter again. Given that the per-second-sensors are derived from the traffic-counters, those always report 0 KB/s from that point on as well.

Not sure if the same is happening with your router, but there are lots of buggy implementations.

StevenLooman commented 2 years ago

@Anto79-ops, you state you have the same problem. Are you able to test this change as well?

Anto79-ops commented 2 years ago

sure, i can replace the file....just figuring out how to get to the file in HA. Sorry, could you please tell me where the file is? I use file editor.