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

UPNP Fails during setup #56491

Closed ShayGus closed 3 years ago

ShayGus commented 3 years ago

The problem

Home assistant detects upnp and suggests to set it up. The upnp card is added but it shows an error on the card (Exclamation mark)

What is version of Home Assistant Core has the issue?

2021.9.7

What was the last working version of Home Assistant Core?

core-2021.8.*

What type of installation are you running?

Home Assistant OS

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?

Logger: homeassistant.config_entries
Source: components/upnp/device.py:65
First occurred: 12:26:29 (1 occurrences)
Last logged: 12:26:29

Error setting up entry *.*.*.* for upnp
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 969, in _wrap_create_connection
    return await self._loop.create_connection(*args, **kwargs)  # type: ignore  # noqa
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1056, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1041, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 955, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 502, in sock_connect
    return await fut
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 537, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('::1', 1900, 0, 0)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/aiohttp.py", line 110, in async_do_http_request
    async with self._session.request(
  File "/usr/local/lib/python3.9/site-packages/aiohttp/client.py", line 1117, in __aenter__
    self._resp = await self._coro
  File "/usr/local/lib/python3.9/site-packages/aiohttp/client.py", line 520, in _request
    conn = await self._connector.connect(
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 535, in connect
    proto = await self._create_connection(req, traces, timeout)
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 892, in _create_connection
    _, proto = await self._create_direct_connection(req, traces, timeout)
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 1051, in _create_direct_connection
    raise last_exc
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 1020, in _create_direct_connection
    transp, proto = await self._wrap_create_connection(
  File "/usr/local/lib/python3.9/site-packages/aiohttp/connector.py", line 975, in _wrap_create_connection
    raise client_error(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host ::1:1900 ssl:default [Connect call failed ('::1', 1900, 0, 0)]

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 304, in async_setup
    result = await component.async_setup_entry(hass, self)  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/upnp/__init__.py", line 122, in async_setup_entry
    device = await Device.async_create_device(hass, location)
  File "/usr/src/homeassistant/homeassistant/components/upnp/device.py", line 65, in async_create_device
    upnp_device = await factory.async_create_device(ssdp_location)
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/client_factory.py", line 68, in async_create_device
    root = await self._async_get_url_xml(description_url)
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/client_factory.py", line 345, in _async_get_url_xml
    status_code, _, response_body = await self.requester.async_http_request(
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/client.py", line 78, in async_http_request
    ) = await self.async_do_http_request(method, url, headers=headers, body=body)
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/aiohttp.py", line 119, in async_do_http_request
    raise UpnpConnectionError from err
async_upnp_client.exceptions.UpnpConnectionError

Additional information

This used to work before 2021.9

probot-home-assistant[bot] commented 3 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)

upnp documentation upnp source (message by IssueLinks)

StevenLooman commented 3 years ago

Interesting, it tries to connect to your own server using IPv6 as the address is ::1. Not sure what is happening or how to approach this as I don't have a IPv6 enabled router.

ShayGus commented 3 years ago

The thing is that I have the IPv6 disabled on the Pi (the supervisor) the HA running on, and also it's disabled on my router. So I can't see a real reason this integration to start looking for ipv6.

StevenLooman commented 3 years ago

Do you have a custom network configuration (see: Configuration --> General --> Network)?

ShayGus commented 3 years ago

No, I have Autoconfigure marked.

StevenLooman commented 3 years ago

Does it state a IPv6 in the Auto Configure description? Such as:

Auto Configure
Detected: br0 (192.168..../24, fe80::7a08:.../64)

Lets try enable additional logging. Can you add this to your configuration.yaml file?

logger:
  default: warning
  logs:
    homeassistant.components.upnp: debug
    async_upnp_client: debug
    async_upnp_client.traffic: error

This will disable most logging from home assitant itself and other components, but enable logging for the upnp component and async-upnp-client, the library used to communicate with the router.

I'm uncertain if it'll give the information we seek, but perhaps... Try finding log entries which contain ::1 or your router-IP. Feel free to redact any sensitive information. Please also include messages before and after the logs of interest.

ShayGus commented 3 years ago

It's actually: Detected: eth0 (.../24) No ipv6 there

From the log:

<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetExternalIPAddressResponse xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1"><NewExternalIPAddress>*.*.*.*</NewExternalIPAddress></u:GetExternalIPAddressResponse></s:Body></s:Envelope>

2021-09-27 20:22:55 DEBUG (MainThread) [async_upnp_client.traffic.upnp] Got response:
500
Content-Type: text/xml; charset="utf-8"
Connection: close
Content-Length: 398
Server: TP-LINK/TP-LINK UPnP/1.1 MiniUPnPd/1.8
Ext: 

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>401</errorCode><errorDescription>Invalid Action</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>
Content-Type: text/xml; charset="utf-8"
Connection: close
Content-Length: 376
Server: TP-LINK/TP-LINK UPnP/1.1 MiniUPnPd/1.8
Ext: 

<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetTotalPacketsReceivedResponse xmlns:u="urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1"><NewTotalPacketsReceived>435737624</NewTotalPacketsReceived></u:GetTotalPacketsReceivedResponse></s:Body></s:Envelope>

2021-09-27 20:22:55 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('*.*.*.*', 47471): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1800\r\nDATE: Mon, 27 Sep 2021 17:22:52 GMT\r\nEXT:\r\nLOCATION: http://10.0.0.7:9080\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 0e64ce70-1f9b-11ec-8175-bfeea9b70db9\r\nSERVER: Linux/4.9.140-tegra-g19e7acaac93b, UPnP/1.0, Portable SDK for UPnP devices\r\nX-User-Agent: NRDP MDX\r\nX-Friendly-Name: TGl2aW5nIFJvb20gVFY=\r\nX-Accepts-Registration: 3\r\nX-MSL: 1\r\nX-MDX-Caps: \r\nX-MDX-Registered: 1\r\nX-MDX-Remote-Login-Supported: 0\r\nX-MDX-Remote-Login-Requested-By-Witcher: 0\r\nST: upnp:rootdevice\r\nUSN: uuid:NFANDROID2-PRV-SHIELDANDROIDTV-NVIDISHIELD=ANDROID=TV-15895-049D29958C394CC5F275A1DA1FB38F2917C8B1DC95624FB9043DE574A1F31EC4::upnp:rootdevice\r\n\r\n'
2021-09-27 20:22:55 ERROR (MainThread) [homeassistant.components.upnp] Unexpected error fetching Archer AX20 data: Error during async_call(), status: 500, body: <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>401</errorCode><errorDescription>Invalid Action</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 187, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/upnp/__init__.py", line 209, in _async_update_data
    update_values = await asyncio.gather(
  File "/usr/src/homeassistant/homeassistant/components/upnp/device.py", line 165, in async_get_status
    values = await asyncio.gather(
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/profiles/igd.py", line 406, in async_get_status_info
    result = await action.async_call()
  File "/usr/local/lib/python3.9/site-packages/async_upnp_client/client.py", line 541, in async_call
    raise UpnpError(
async_upnp_client.exceptions.UpnpError: Error during async_call(), status: 500, body: <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>401</errorCode><errorDescription>Invalid Action</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>
2021-09-27 20:22:55 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Archer AX20 data in 0.370 seconds (success: False)
2021-09-27 20:22:55 DEBUG (MainThread) [async_upnp_client.search] Received response, request line: HTTP/1.1 200 OK, headers: {'CACHE-CONTROL': 'max-age=1800', 'DATE': 'Mon, 27 Sep 2021 17:22:52 GMT', 'EXT': '', 'location': 'http://10.0.0.7:9080', 'OPT': '"http://schemas.upnp.org/upnp/1/0/"; ns=01', '01-NLS': '0e64ce70-1f9b-11ec-8175-bfeea9b70db9', 'SERVER': 'Linux/4.9.140-tegra-g19e7acaac93b, UPnP/1.0, Portable SDK for UPnP devices', 'X-User-Agent': 'NRDP MDX', 'X-Friendly-Name': 'TGl2aW5nIFJvb20gVFY=', 'X-Accepts-Registration': '3', 'X-MSL': '1', 'X-MDX-Caps': '', 'X-MDX-Registered': '1', 'X-MDX-Remote-Login-Supported': '0', 'X-MDX-Remote-Login-Requested-By-Witcher': '0', 'ST': 'upnp:rootdevice', 'USN': 'uuid:NFANDROID2-PRV-SHIELDANDROIDTV-NVIDISHIELD=ANDROID=TV-15895-049D29958C394CC5F275A1DA1FB38F2917C8B1DC95624FB9043DE574A1F31EC4::upnp:rootdevice', '_location_original': 'http://*.*.*.*:9080', '_timestamp': datetime.datetime(2021, 9, 27, 20, 22, 55, 172416), '_host': '*.*.*.*', '_port': 47471, '_udn': 'uuid:NFANDROID2-PRV-SHIELDANDROIDTV-NVIDISHIELD=ANDROID=TV-15895-049D29958C394CC5F275A1DA1FB38F2917C8B1DC95624FB9043DE574A1F31EC4'}
2021-09-27 20:22:55 DEBUG (MainThread) [async_upnp_client.traffic.upnp] Got response:
200
Content-Type: text/xml; charset="utf-8"
Connection: close
Content-Length: 353
Server: TP-LINK/TP-LINK UPnP/1.1 MiniUPnPd/1.8
Ext: 

<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetTotalBytesSentResponse xmlns:u="urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1"><NewTotalBytesSent>3106765536</NewTotalBytesSent></u:GetTotalBytesSentResponse></s:Body></s:Envelope>
StevenLooman commented 3 years ago

This seems to be a different error, a 401 UPnP error (note this is not the HTTP 401 error!) It states that the call is not supported (though it should be supported by the device implementing the IGD specs.)

There are multiple devices with this problem. I hope to resolve these soon, but other things have more priority at the moment such as https://github.com/home-assistant/core/pull/55267/

StevenLooman commented 3 years ago

Is the original issue resolved, where the integration tries to connect to ::1?

ShayGus commented 3 years ago

I think they are somehow connected? Because I see both of them in the logs. Before this started happening I didn't get any of the two.

StevenLooman commented 3 years ago

Are you still seeing ::1 in your logs?

The second error is fixed with #56744.