upnp no longer working properly

[Segfault198]

Home Assistant release with the issue:

0.81.2

Last working Home Assistant release (if known):
0.78

Operating environment (Hass.io/Docker/Windows/etc.):

Python virtual environment/Ubuntu 18.04 on Asus VivoStick PC (TS10)
Router Asus RT-AC3100 running ASUSWRT Merlin 384.7

Component/platform:

upnp

Description of problem:
After 0.78 upnp no longer creates sensors and no longer maps ports, before this sensors worked fine as did port mapping. Port mapping does still work for other devices in the house (i.e. xbox one)

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

#Enable upnp component
upnp:
  port_mapping: true
  ports:
    hass: 443
  sensors: true

Traceback (if applicable):

2018-10-31 14:32:59 DEBUG (MainThread) [async_upnp_client.traffic] Sending request:
GET http://192.168.1.1:36460/rootDesc.xml



2018-10-31 14:33:00 ERROR (MainThread) [homeassistant.components.upnp] Unable to create upnp-device

Additional information:

[dgomes]

Can you check if UPnP/IGD was discovered in Configuration -> Integrations ?

CC @StevenLooman

[Segfault198]

Yes, sorry should have included those with the initial post:
https://gyazo.com/9eed617aca6eeb8e0b6415cf7a7e6037
https://gyazo.com/ca2f9607b8975f5169b21fdc961c800b

[StevenLooman]

Interesting. Can you enable debugging for components.upnp and async_upnp_client, by adding this to your configuration?

logger:
  default: info
  logs:
    homeassistant.components.discovery: debug
    homeassistant.components.upnp: debug
    async_upnp_client: debug
    async_upnp_client.igd: debug
    async_upnp_client.traffic: debug

This will silence home assistant mostly, but show debug messages and related traffic for UPnP devices, such as your router.

It seems however, from the message Unable to create upnp-device, that home assistant was not able to fetch the XML from the router.

[Segfault198]

Running it now, I already had most of that enabled. I do believe you are correct about it not getting XML but its strange as I've been using merlin for a while now with little to no problems, and it uses miniupnp.

[Segfault198]

Here are the results. Sorry about the few goofy errors in there, I know its extra noise, playing with a new camera a couple of other things.
https://pastebin.com/5hmYRmxc

[StevenLooman]

This doesn't provide any more information, unfortunately.

Are you familiar with a shell on the device Home Assistant is running on? If so, can you try this, from your virtual env:

$ upnp-client  --debug subscribe upnp-client subscribe http://192.168.1.1:36460/rootDesc.xml \*

Also, can you download the XML from your router from http://192.168.1.1:36460/rootDesc.xml and post it somewhere?

[jmutnick]

What do I do if my rootDesc.xml address for my router is: http://192.168.1.1:54506/rootDesc.xml ?

[StevenLooman]

Replace your url with the one mentioned at other places/in commands.

[jmutnick]

Replace your url with the one mentioned at other places/in commands.

Where would I do that? Sorry, I am new to this particular component.

[Segfault198]

@StevenLooman,
Sorry for the delay. I'll get you that information ad soon as I can. Unfortunately gotta do my chores before I can tinker.

[Segfault198]

Command results: https://pastebin.com/A6GfG0XZ
XML: https://pastebin.com/1sVLG28U

[StevenLooman]

@Segfault198 Thank you for the information. The command I gave you was wrong, probably due to a copy/paste and edit error on my side. Can you try this?

$ upnp-client --debug subscribe http://192.168.1.1:36460/rootDesc.xml \*

The downloaded XML looks normal though.

Currently, the software simply checks if an error occurs and reports Unable to create upnp-device. We can, temporarily(!), change a file in your Home Assistant installation to get the real error. Are you comfortable doing this?

@jmutnick Do you have the same router? You can try to download the file you mentioned ( http://192.168.1.1:54506/rootDesc.xml ), in your browser to see if this works.

[Segfault198]

Sure, let me know what changes need made. I'll rerun the command in a little bit and get you the results

[StevenLooman]

Find this file: homeassistant/components/upnp/__init__.py

Find the async_setup_entry() function, probably on line 117.
Then, after line 127, add this:

        raise

So, this is what the new function will look like, notice the raise after the except (...): part:

# config flow
async def async_setup_entry(hass: HomeAssistantType,
                            config_entry: ConfigEntry):
    """Set up UPnP/IGD-device from a config entry."""
    await async_ensure_domain_data(hass)
    data = config_entry.data

    # build UPnP/IGD device
    ssdp_description = data[CONF_SSDP_DESCRIPTION]
    try:
        device = await Device.async_create_device(hass, ssdp_description)
    except (asyncio.TimeoutError, aiohttp.ClientError):
        raise
        _LOGGER.error('Unable to create upnp-device')
        return False

    hass.data[DOMAIN]['devices'][device.udn] = device

This will cause a traceback in the Home Assistant output, but the original error will be preserved.

[jmutnick]

@StevenLooman I added the raise and I think this may be significant:

aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host 192.168.1.1:37891 ssl:None [Connect call failed ('192.168.1.1', 37891)]

Here is all of it:

2018-11-04 14:30:12 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry RT-AC68U for upnp
Traceback (most recent call last):
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 822, in _wrap_create_connection
    return await self._loop.create_connection(*args, **kwargs)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 943, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 930, in create_connection
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 475, in sock_connect
    return await fut
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 505, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('192.168.1.1', 37891)

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

Traceback (most recent call last):
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/homeassistant/config_entries.py", line 241, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/homeassistant/components/upnp/__init__.py", line 113, in async_setup_entry
    device = await Device.async_create_device(hass, ssdp_description)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/homeassistant/components/upnp/device.py", line 36, in async_create_device
    upnp_device = await factory.async_create_device(ssdp_description)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/__init__.py", line 843, in async_create_device
    root = await self._async_get_url_xml(description_url)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/__init__.py", line 1041, in _async_get_url_xml
    await self.requester.async_http_request('GET', url)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/__init__.py", line 78, in async_http_request
    body_type=body_type)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/aiohttp.py", line 80, in async_do_http_request
    async with self._session.request(method, url, headers=headers, data=body) as response:
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/client.py", line 855, in __aenter__
    self._resp = await self._coro
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/client.py", line 370, in _request
    timeout=timeout
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 445, in connect
    proto = await self._create_connection(req, traces, timeout)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 757, in _create_connection
    req, traces, timeout)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 879, in _create_direct_connection
    raise last_exc
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 862, in _create_direct_connection
    req=req, client_error=client_error)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/aiohttp/connector.py", line 829, in _wrap_create_connection
    raise client_error(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host 192.168.1.1:37891 ssl:None [Connect call failed ('192.168.1.1', 37891)]

[jmutnick]

Oh, and this:

$ upnp-client --debug subscribe http://192.168.1.1:54506/rootDesc.xml
usage: upnp-client [-h] --device DEVICE [--debug] [--debug-traffic] [--pprint] {call-action,subscribe} ...
upnp-client: error: the following arguments are required: --device

[Segfault198]

@StevenLooman
Let me know if you need anything else. Thanks for all your help!
https://pastebin.com/puJ0iNFN
https://pastebin.com/C0EqGk33

@jmutnick
Alter the command like this, I ran into the same issue:
upnp-client --device "http://192.168.1.1:/rootDesc.xml" --debug subscribe *

[jmutnick]

(homeassistant3.7) pi@home-assistant:~/homeassistant3.7 $ upnp-client --device "http://192.168.1.1:54506/rootDesc.xml" --debug subscribe *
DEBUG:upnp-client:Listening on: http://192.168.1.237:11302/notify
Traceback (most recent call last):
  File "/home/pi/homeassistant3.7/bin/upnp-client", line 11, in <module>
    sys.exit(main())
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 225, in main
    loop.run_until_complete(async_main())
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 215, in async_main
    await subscribe(device, args.service)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 186, in subscribe
    service.on_event = on_event
AttributeError: 'NoneType' object has no attribute 'on_event'

[StevenLooman]

@jmutnick @Segfault198 Thank you for testing and reporting. Your error is ConnectionRefusedError, which means Home Assistant is now allowed to connect to your router. Either no webservice serving the XML is running (which is not true, as you can run upnp-client which also gets the XML.) Do you have any other Home Assistant components using your router?

If you are willing, you can try to run with an empty Home Assistant config. I.e., no other components to ensure nothing is interfering. Be sure to backup your original configuration, of course! Perhaps your router thinks it is being hammered and blocks requests (a guess.) Another possibility is that a firewall is blocking outgoing requests from Home Assistant at your Asus VivoStick PC/Raspberry Pi or your router is blocking incoming requests.

@jmutnick About upnp-client*, it is important that you prefix the last parameter with a \, like this:

$ upnp-client --device "http://192.168.1.1:54506/rootDesc.xml" --debug subscribe \*

* I upgraded upnp-client a few days ago and the current Home Assistant-version installs a slightly older version of the command. A newer version will come soon. Nevertheless, the functionality of this part of the command is not changed so results will be the same.

[Segfault198]

@StevenLooman, yes I use it for device_tracking/presence detection(ASUSWRT component). Which seems to work just fine. I'll give it a go with minimal configuration and update, but it'll likely take a little time. Thanks for your help!

[jmutnick]

$ upnp-client --device "http://192.168.1.1:54506/rootDesc.xml" --debug subscribe \*
DEBUG:upnp-client:Listening on: http://192.168.1.237:11302/notify
DEBUG:async_upnp_client:Subscribing to: <UpnpService(urn:upnp-org:serviceId:Layer3Forwarding1, uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a9e20)>, callback URL: http://192.168.1.237:11302/notify
DEBUG:async_upnp_client:Got SID: uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a9e32, renewal_time: 2018-11-05 18:05:47.898528
DEBUG:async_upnp_client:Subscribing to: <UpnpService(urn:upnp-org:serviceId:WANCommonIFC1, uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a9e20)>, callback URL: http://192.168.1.237:11302/notify
DEBUG:async_upnp_client.aiohttp:Received request: <BaseRequest NOTIFY /notify >
DEBUG:async_upnp_client.aiohttp:NOTIFY response status: 200
DEBUG:async_upnp_client:Got SID: uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a20a6, renewal_time: 2018-11-05 18:05:47.919646
DEBUG:async_upnp_client:Subscribing to: <UpnpService(urn:upnp-org:serviceId:WANIPConn1, uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a9e20)>, callback URL: http://192.168.1.237:11302/notify
DEBUG:async_upnp_client.aiohttp:Received request: <BaseRequest NOTIFY /notify >
DEBUG:async_upnp_client.aiohttp:NOTIFY response status: 200
DEBUG:async_upnp_client:Got SID: uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a23e5, renewal_time: 2018-11-05 18:05:47.938993
DEBUG:async_upnp_client.aiohttp:Received request: <BaseRequest NOTIFY /notify >
DEBUG:async_upnp_client.aiohttp:NOTIFY response status: 200
DEBUG:async_upnp_client:Resubscribing to: <UpnpService(urn:upnp-org:serviceId:Layer3Forwarding1, uuid:3ddcd1d3-2380-45f5-b069-9c5c8e4a9e20)>
Traceback (most recent call last):
  File "/home/pi/homeassistant3.7/bin/upnp-client", line 11, in <module>
    sys.exit(main())
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 225, in main
    loop.run_until_complete(async_main())
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 215, in async_main
    await subscribe(device, args.service)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/cli.py", line 197, in subscribe
    await event_handler.async_resubscribe_all()
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/__init__.py", line 255, in async_resubscribe_all
    await self.async_resubscribe(service)
  File "/home/pi/homeassistant3.7/lib/python3.7/site-packages/async_upnp_client/__init__.py", line 246, in async_resubscribe
    sid = response_headers['sid']
  File "multidict/_multidict.pyx", line 58, in multidict._multidict._Base.__getitem__
  File "multidict/_multidict.pyx", line 53, in multidict._multidict._Base._getone
  File "multidict/_multidict.pyx", line 48, in multidict._multidict._Base._getone
KeyError: 'sid'

[jmutnick]

It worked on another instance I was running, but the difference seems to be the SSL settings on the one it is not working on? Does that make any sense based on the error from above when the ssl issue appeared?

[Segfault198]

Works on a clean instance of Hass.io I stood up for testing. @jmutnick may be onto something. I have SSL setup on my primary instance as well.

[StevenLooman]

The error should not happen, but otherwise it looks like upnp-client can get the XML normally. Perhaps it is the home assistant/async_upnp_client (upnp-client) combination.

[Segfault198]

Let me know how I can help test. As I said I fired up that instance of Hass.io and it discovered upnp immediately and added the sensors like normal. So something odd is going on.

[dgomes]

@Segfault198 can you test your theory by disabling SSL for some minutes ?

[Segfault198]

As requested here ya go. Obviously I trimmed the log a bit but if you'd like the full log I'll happily get it to you. The component still doesn't work 100% with SSL off but now I get this new set of messages repeating. Its very odd. Maybe I just need to rebuild.

https://pastebin.com/CM4aewrR

[StevenLooman]

Fixed the bug @jmutnick reported. Will look into the SSL thing soon.

[jmutnick]

@StevenLooman If you have a build I can test, please let me know where to retrieve it.

[StevenLooman]

Just released async_upnp_client==0.13.2 and created pull request #18377 for home assistant to update.

However, I am not able to reproduce any errors when SSL is enabled. Followed the steps from Self-signed certificate for SSL/TLS

Are there any other specifics to your configurations with regard to SSL?

@jmutnick You can test this pull request. You can either clone my repository/branch or just change the required version of async_upnp_client in the relevant files (see the changes files in pull request #18377)

[StevenLooman]

Apparently upnp is forbidden completely from now on via #17937 by @pvizeli. While I agree with the danger by of the port forward, it was included after discussion with @dgomes.

Still, simply disabling discovery, effectively destroying the functionality was a bit of an overkill. @pvizeli was there no other way, such as discussing this with @dgomes or me about other options?

[dgomes]

It would be dangerous if auto-discovery would enable the port-forwarding automatically. But users still needed to tick the option to open the port. Or did I miss a step ?

[StevenLooman]

I agree that it is too easy to enable the port-forward. If a user does not know what it is, it is very easy to simply tick it.

If a port-forward can only be enabled via the configuration file, then users will be safer.

[dgomes]

On the other hand the all point of using UPnP to port-forward stuff is not to mess with configurations :)

I think a warning in the GUI should have been enough

(BTW I think these comments should be moved to the other thread)

[StevenLooman]

I know I shouldn't comment in closed issues, but this seems the correct place.
@jmutnick @Segfault198 Home Assistant 0.85.0 includes a fix by @tsvi which might fix your issue too. Can you test and report results?

[jmutnick]

Yes, it appears to be working now!

[Segfault198]

Confirmed. All working well now. Could you link to the fix? I'd be interested to see what the issue was. Thanks!

[StevenLooman]

Great, thank you for testing and reporting.