UPNP/IGD Fails To ReEstablish A Connection When Device Is Power Cycled.

The problem

When I'm forced to power cycle my device (modem/router), hass loses the connection and fails to reestablish it when the device comes back up.

Environment

Home Assistant Core release with the issue: 0.112.2
Last working Home Assistant Core release (if known): N/A
Operating environment (OS/Container/Supervised/Core): Arch Linux
Integration causing this issue: UPNP
Link to integration documentation on our website: https://www.home-assistant.io/integrations/upnp

Problem-relevant `configuration.yaml`

N/A. UPNP Integration was added via the web interface.

Traceback/Error logs

2020-08-26 12:59:09 ERROR (MainThread) [homeassistant.components.upnp] Error requesting ZTE-UPnP data: Cannot connect to host <igd_ip>:39719 ssl:default [Connect call failed ('<igd_ip>', 39719)]

Additional information

And in case you're wondering if the device is transmitting after the power cycle, I have run the "GUPnP Universal Control Point" program and was able to receive data from that device.

https://github.com/home-assistant/core/issues/28206#issuecomment-636410785 I will say that at least hass isn't constantly puking a python error like before when it happens. Now it's only that one message.

EDIT0: I'll also mention the web interface shows "Unavailable" for all of the device's entities/stats like "\<device>-UPnP B received Unavailable"

Hey there @stevenlooman, mind taking a look at this issue as its been labeled with an integration (upnp) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

Just to check I have right thing in my mind: does the error disappear once the router is fully restarted?

If it does not, did the router get a different IP?

The error is only registered 1 time in the log. The connection does not get reestablished and the router's IP address is static.

What do you mean with this?

The connection does not get reestablished

There never is a constant connection. Once every 30 seconds a new connection is made to get the traffic counters (a SOAP request over HTTP.)

Okay, I looked into it a little more using wireshark this time and after my router comes back up and the request is made:

Ð[¨+O/L»XJ}EÔo8@@EÀ¨À¨¤êSú¦- /öÄ
'q¥*ÿÿ¢lGET /rootDesc.xml HTTP/1.1
Host: <sanitized>:59987
User-Agent: HomeAssistant/0.112.2 aiohttp/3.6.2 Python/3.8
Accept: */*
Accept-Encoding: gzip, deflate

HTTP/1.1 200 OK
Content-Type: text/xml; charset="utf-8"
Connection: close
Content-Length: 2556
Server: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9
Ext:

<?xml version="1.0"?>
<root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:InternetGatewayDevice:1</deviceType><friendlyName><sanitized>-UPnP</friendlyName><manufacturer><sanitized></manufacturer><manufacturerURL><sanitized></manufacturerURL><modelDescription><sanitized></modelDescription><modelName><sanitized></modelName><modelNumber>MBB</modelNumber><modelURL><sanitized></modelURL><serialNumber><sanitized></serialNumber><UDN>uuid:<sanitized></UDN><serviceList><service><serviceType>urn:schemas-upnp-org:service:Layer3Forwarding:1</serviceType><serviceId>urn:upnp-org:serviceId:Layer3Forwarding1</serviceId><controlURL>/ctl/L3F</controlURL><eventSubURL>/evt/L3F</eventSubURL><SCPDURL>/L3F.xml</SCPDURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANDevice:1</deviceType><friendlyName>WANDevice</friendlyName><manufacturer>MiniUPnP</manufacturer><manufacturerURL>http://miniupnp.free.fr/</manufacturerURL><modelDescription>WAN Device</modelDescription><modelName>WAN Device</modelName><modelNumber><sanitized></modelNumber><modelURL>http://miniupnp.free.fr/</modelURL><serialNumber><sanitized></serialNumber><UDN>uuid:<sanitized></UDN><UPC><sanitized></UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1</serviceType><serviceId>urn:upnp-org:serviceId:WANCommonIFC1</serviceId><controlURL>/ctl/CmnIfCfg</controlURL><eventSubURL>/evt/CmnIfCfg</eventSubURL><SCPDURL>/WANCfg.xml</SCPDURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANConnectionDevice:1</deviceType><friendlyName>WANConnectionDevice</friendlyName><manufacturer>MiniUPnP</manufacturer><manufacturerURL>http://miniupnp.free.fr/</manufacturerURL><modelDescription>MiniUPnP daemon</modelDescription><modelName>MiniUPnPd</modelName><modelNumber><sanitized></modelNumber><modelURL>http://miniupnp.free.fr/</modelURL><serialNumber><sanitized></serialNumber><UDN>uuid:<sanitized></UDN><UPC><sanitized></UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANIPConnection:1</serviceType><serviceId>urn:upnp-org:serviceId:WANIPConn1</serviceId><controlURL>/ctl/IPConn</controlURL><eventSubURL>/evt/IPConn</eventSubURL><SCPDURL>/WANIPCn.xml</SCPDURL></service></serviceList></device></deviceList></device></deviceList><presentationURL>http://<sanitized>/</presentationURL></device></root>

Wireshark has still been running the entire time I've been composing this and there had been no further connections made.

EDIT0: Going through the log and expecting the same error, but instead see a different one: 2020-08-30 14:28:26 ERROR (MainThread) [homeassistant.components.upnp] Timeout fetching <sanitized> data It's fine though because that is when I took my router down. Not really important/applicable.

The garbage in front of the request is a bit strange. Perhaps the the connection pool has problems? On the other hand you do get a valid response, so this is not really important, perhaps a WireShark thing.

This request is usually made to (re)create the sensors etc. This usually only happens when the component is initialized from a ConfigEntry. Did you manually re-add the component in home assistant?

I hope to be able to reproduce this during the weekend.

The garbage in front of the HTTP request might be the ethernet header/ip header/tcp header.

Nevertheless, I've tried to reproduce your situation by blocking outgoing connections for to my router. Before the blocking the component gets the data as usual:

2020-09-05 22:03:23 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:03:23 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 0.061 seconds
2020-09-05 22:03:53 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:03:53 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 0.062 seconds

When the outgoing traffic is blocked:

2020-09-05 22:04:23 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:04:28 ERROR (MainThread) [homeassistant.components.upnp] Timeout fetching Ambit EVW320B data
2020-09-05 22:04:28 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 5.012 seconds
2020-09-05 22:04:58 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:05:03 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 5.012 seconds
2020-09-05 22:05:33 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:05:38 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 5.011 seconds

Then, when traffic is allowed again:

2020-09-05 22:06:08 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:06:08 INFO (MainThread) [homeassistant.components.upnp] Fetching Ambit EVW320B data recovered
2020-09-05 22:06:08 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 0.064 seconds
2020-09-05 22:06:38 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: Ambit EVW320B/uuid:upnp-InternetGatewayDevice-1_0-889ffacb9043
2020-09-05 22:06:38 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching Ambit EVW320B data in 0.155 seconds

It explicitly mentions it has recovered even.

When your router reboots, does your computer/server loose its ethernet connection? I.e., some routers have integrated switches which might powerless for a few moments resulting in your computer/serves regarding it as a disconnected cable.

You can skip down to my "AH HA!" moment/solution at the bottom.

All wifi here. No ethernet.

Hass started up (with router enabled):

...
2020-09-05 18:39:58 INFO (MainThread) [homeassistant.setup] Setup of domain cloud took 0.0 seconds.
2020-09-05 18:39:58 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cloud>
2020-09-05 18:41:37 INFO (SyncWorker_5) [homeassistant.loader] Loaded device_tracker from homeassistant.components.device_tracker
2020-09-05 18:41:37 INFO (MainThread) [homeassistant.setup] Setting up frontend
//This bothered me with the nearly 1.6 minutes before the web interface came back up.
...
2020-09-05 18:41:49 INFO (MainThread) [homeassistant.setup] Setup of domain upnp took 0.0 seconds.
2020-09-05 18:41:49 DEBUG (MainThread) [homeassistant.components.upnp] async_setup_entry, config_entry: {'st': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'udn': 'uuid:<sanitized>'}
2020-09-05 18:41:49 DEBUG (MainThread) [homeassistant.components.upnp] Discovering UPnP/IGD devices
...
2020-09-05 18:41:49 DEBUG (MainThread) [async_upnp_client.traffic] Received packet from ('<sanitizedIP>', 1900):
b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=120\r\nST: urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\nUSN: uuid:<sanitized>::urn:schemas-upnp-org:device:InternetGatewayDevice:1\r\nEXT:\r\nSERVER: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9\r\nLOCATION: http://<sanitizedIP>:43502/rootDesc.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 1599325271\r\nBOOTID.UPNP.ORG: 1599325271\r\nCONFIGID.UPNP.ORG: 1337\r\n\r\n'
2020-09-05 18:41:49 DEBUG (MainThread) [async_upnp_client.traffic] Received packet from ('<sanitizedIP>', 1900):
b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=120\r\nST: upnp:rootdevice\r\nUSN: uuid:<sanitized>::upnp:rootdevice\r\nEXT:\r\nSERVER: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9\r\nLOCATION: http://<sanitizedIP>:43502/rootDesc.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 1599325271\r\nBOOTID.UPNP.ORG: 1599325271\r\nCONFIGID.UPNP.ORG: 1337\r\n\r\n'
...
2020-09-05 18:41:49 DEBUG (MainThread) [async_upnp_client.traffic] Received packet from ('<sanitizedIP>', 1900):
b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=120\r\nST: urn:schemas-upnp-org:service:WANIPConnection:1\r\nUSN: uuid:<sanitized>::urn:schemas-upnp-org:service:WANIPConnection:1\r\nEXT:\r\nSERVER: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9\r\nLOCATION: http://<sanitizedIP>:43502/rootDesc.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 1599325271\r\nBOOTID.UPNP.ORG: 1599325271\r\nCONFIGID.UPNP.ORG: 1337\r\n\r\n'
...
2020-09-05 18:41:49 DEBUG (MainThread) [async_upnp_client.traffic] Received packet from ('<sanitizedIP>', 1900):
b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=120\r\nST: uuid:<sanitized>\r\nUSN: uuid:<sanitized>\r\nEXT:\r\nSERVER: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9\r\nLOCATION: http://<sanitizedIP>:43502/rootDesc.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 1599325271\r\nBOOTID.UPNP.ORG: 1599325271\r\nCONFIGID.UPNP.ORG: 1337\r\n\r\n'
...
2020-09-05 18:41:51 DEBUG (MainThread) [homeassistant.components.ssdp] Discovered upnp at http://<sanitizedIP>:43502/rootDesc.xml
2020-09-05 18:41:51 DEBUG (MainThread) [homeassistant.components.upnp] async_step_ssdp: discovery_info: {'ssdp_location': 'http://<sanitizedIP>:43502/rootDesc.xml', 'ssdp_st': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'st': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'deviceType': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1', 'friendlyName': '<sanitizedManufacturer>-UPnP', 'manufacturer': '<sanitizedManufacturer>', 'manufacturerURL': 'http://<sanitizedWebsite>', 'modelDescription': '<sanitizedModel>', 'modelName': '<sanitizedModel>', 'modelNumber': '<sanitizedModel>', 'modelURL': 'http://<sanitizedWebsite>', 'serialNumber': '<sanitizedSN>', 'UDN': 'uuid:<sanitized>', 'serviceList': {'service': {'serviceType': 'urn:schemas-upnp-org:service:Layer3Forwarding:1', 'serviceId': 'urn:upnp-org:serviceId:Layer3Forwarding1', 'controlURL': '/ctl/L3F', 'eventSubURL': '/evt/L3F', 'SCPDURL': '/L3F.xml'}}, 'deviceList': {'device': {'deviceType': 'urn:schemas-upnp-org:device:WANDevice:1', 'friendlyName': 'WANDevice', 'manufacturer': 'MiniUPnP', 'manufacturerURL': 'http://miniupnp.free.fr/', 'modelDescription': 'WAN Device', 'modelName': 'WAN Device', 'modelNumber': '<sanitizedModel>', 'modelURL': 'http://miniupnp.free.fr/', 'serialNumber': '<sanitizedSN>', 'UDN': 'uuid:<sanitized>', 'UPC': '000000000000', 'serviceList': {'service': {'serviceType': 'urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1', 'serviceId': 'urn:upnp-org:serviceId:WANCommonIFC1', 'controlURL': '/ctl/CmnIfCfg', 'eventSubURL': '/evt/CmnIfCfg', 'SCPDURL': '/WANCfg.xml'}}, 'deviceList': {'device': {'deviceType': 'urn:schemas-upnp-org:device:WANConnectionDevice:1', 'friendlyName': 'WANConnectionDevice', 'manufacturer': 'MiniUPnP', 'manufacturerURL': 'http://miniupnp.free.fr/', 'modelDescription': 'MiniUPnP daemon', 'modelName': 'MiniUPnPd', 'modelNumber': '<sanitizedModel>', 'modelURL': 'http://miniupnp.free.fr/', 'serialNumber': '<sanitizedSN>', 'UDN': 'uuid:<sanitized>', 'UPC': '000000000000', 'serviceList': {'service': {'serviceType': 'urn:schemas-upnp-org:service:WANIPConnection:1', 'serviceId': 'urn:upnp-org:serviceId:WANIPConn1', 'controlURL': '/ctl/IPConn', 'eventSubURL': '/evt/IPConn', 'SCPDURL': '/WANIPCn.xml'}}}}}}, 'presentationURL': 'http://<sanitizedIP>/'}
...
2020-09-05 18:41:53 DEBUG (MainThread) [async_upnp_client.traffic] Received packet from ('<sanitizedIP>1', 55461):
b'HTTP/1.1 200 OK\r\nLocation: http://<sanitizedIP>1:1116/\r\nCache-Control: max-age=1800\r\nServer: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nEXT: \r\nBOOTID.UPNP.ORG: 0\r\nCONFIGID.UPNP.ORG: 300971\r\nUSN: uuid:<sanitized>::urn:schemas-upnp-org:service:RenderingControl:1\r\nST: urn:schemas-upnp-org:service:RenderingControl:1\r\nDate: Sat, 05 Sep 2020 23:41:53 GMT\r\n\r\n'
...
2020-09-05 18:41:59 DEBUG (MainThread) [async_upnp_client.traffic] Sending request:
GET http://<sanitizedIP>:43502/rootDesc.xml

2020-09-05 18:41:59 DEBUG (MainThread) [async_upnp_client.traffic] Got response:
200
Content-Type: text/xml; charset="utf-8"
Connection: close
Content-Length: 2556
Server: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9
Ext: 

<?xml version="1.0"?>
<root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:InternetGatewayDevice:1</deviceType><friendlyName><sanitizedManufacturer>-UPnP</friendlyName><manufacturer><sanitizedManufacturer></manufacturer><manufacturerURL>http://<sanitizedWebsite></manufacturerURL><modelDescription><sanitizedModel></modelDescription><modelName><sanitizedModel></modelName><modelNumber><sanitizedModel></modelNumber><modelURL>http://<sanitizedWebsite></modelURL><serialNumber><sanitizedSN></serialNumber><UDN>uuid:<sanitized></UDN><serviceList><service><serviceType>urn:schemas-upnp-org:service:Layer3Forwarding:1</serviceType><serviceId>urn:upnp-org:serviceId:Layer3Forwarding1</serviceId><controlURL>/ctl/L3F</controlURL><eventSubURL>/evt/L3F</eventSubURL><SCPDURL>/L3F.xml</SCPDURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANDevice:1</deviceType><friendlyName>WANDevice</friendlyName><manufacturer>MiniUPnP</manufacturer><manufacturerURL>http://miniupnp.free.fr/</manufacturerURL><modelDescription>WAN Device</modelDescription><modelName>WAN Device</modelName><modelNumber><sanitizedModel></modelNumber><modelURL>http://miniupnp.free.fr/</modelURL><serialNumber><sanitizedSN></serialNumber><UDN>uuid:<sanitized></UDN><UPC>000000000000</UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1</serviceType><serviceId>urn:upnp-org:serviceId:WANCommonIFC1</serviceId><controlURL>/ctl/CmnIfCfg</controlURL><eventSubURL>/evt/CmnIfCfg</eventSubURL><SCPDURL>/WANCfg.xml</SCPDURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANConnectionDevice:1</deviceType><friendlyName>WANConnectionDevice</friendlyName><manufacturer>MiniUPnP</manufacturer><manufacturerURL>http://miniupnp.free.fr/</manufacturerURL><modelDescription>MiniUPnP daemon</modelDescription><modelName>MiniUPnPd</modelName><modelNumber><sanitizedModel></modelNumber><modelURL>http://miniupnp.free.fr/</modelURL><serialNumber><sanitizedSN></serialNumber><UDN>uuid:<sanitized></UDN><UPC>000000000000</UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANIPConnection:1</serviceType><serviceId>urn:upnp-org:serviceId:WANIPConn1</serviceId><controlURL>/ctl/IPConn</controlURL><eventSubURL>/evt/IPConn</eventSubURL><SCPDURL>/WANIPCn.xml</SCPDURL></service></serviceList></device></deviceList></device></deviceList><presentationURL>http://<sanitizedIP>/</presentationURL></device></root>
...
2020-09-05 18:41:59 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching <sanitizedManufacturer>-UPnP data in 0.046 seconds
2020-09-05 18:41:59 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.<sanitizedManufacturer>_upnp_b_received, old_state=None, new_state=<state sensor.<sanitizedManufacturer>_upnp_b_received=547116736; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B received, icon=mdi:server-network @ 2020-09-05T18:41:59.818067-05:00>>
...
2020-09-05 18:43:29 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.126211919471808] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.<sanitizedManufacturer>_upnp_b_received, old_state=<state sensor.<sanitizedManufacturer>_upnp_b_received=547149150; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B received, icon=mdi:server-network @ 2020-09-05T18:42:59.080896-05:00>, new_state=<state sensor.<sanitizedManufacturer>_upnp_b_received=547151082; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B received, icon=mdi:server-network @ 2020-09-05T18:43:29.048587-05:00>>}

Router power off for 2 minutes:

...
2020-09-05 18:57:31 ERROR (MainThread) [homeassistant.components.upnp] Error requesting <sanitizedManufacturer>-UPnP data: Cannot connect to host <sanitizedIP>:43502 ssl:default [Connect call failed ('<sanitizedIP>', 43502)]
2020-09-05 18:57:31 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching <sanitizedManufacturer>-UPnP data in 2.781 seconds
2020-09-05 18:57:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.<sanitizedManufacturer>_upnp_b_sent, old_state=<state sensor.<sanitizedManufacturer>_upnp_b_sent=20233220; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B sent, icon=mdi:server-network @ 2020-09-05T18:56:59.060711-05:00>, new_state=<state sensor.<sanitizedManufacturer>_upnp_b_sent=unavailable; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B sent, icon=mdi:server-network @ 2020-09-05T18:57:31.783908-05:00>>
...
2020-09-05 18:57:31 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.126211919471808] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.<sanitizedManufacturer>_upnp_b_received, old_state=<state sensor.<sanitizedManufacturer>_upnp_b_received=547395296; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B received, icon=mdi:server-network @ 2020-09-05T18:56:59.061721-05:00>, new_state=<state sensor.<sanitizedManufacturer>_upnp_b_received=unavailable; unit_of_measurement=B, friendly_name=<sanitizedManufacturer>-UPnP B received, icon=mdi:server-network @ 2020-09-05T18:57:31.788122-05:00>>}
...
2020-09-05 18:57:52 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.126211919471808] Sending {'id': 28, 'type': 'result', 'success': True, 'result': [{'domain': 'upnp', 'name': 'UPnP', 'config_flow': True, 'documentation': 'https://www.home-assistant.io/integrations/upnp', 'requirements': ['async-upnp-client==0.14.13'], 'dependencies': [], 'codeowners': ['@StevenLooman'], 'ssdp': [{'st': 'urn:schemas-upnp-org:device:InternetGatewayDevice:1'}, {'st': 'urn:schemas-upnp-org:device:InternetGatewayDevice:2'}], 'is_built_in': True}, {'domain': 'websocket_api', 'name': 'Home Assistant WebSocket API', 'documentation': 'https://www.home-assistant.io/integrations/websocket_api', 'dependencies': ['http'], 'codeowners': ['@home-assistant/core'], 'quality_scale': 'internal', 'is_built_in': True}, ...
...

Router powered on:

2020-09-05 18:58:01 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: <sanitizedManufacturer>-UPnP/uuid:<sanitized>
2020-09-05 18:58:01 DEBUG (MainThread) [async_upnp_client.traffic] Sending request:
POST http://<sanitizedIP>:43502/ctl/CmnIfCfg
SOAPAction: "urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1#GetTotalBytesReceived"
Host: <sanitizedIP>:43502
Content-Type: text/xml; charset="utf-8"
Content-Length: 292
<?xml version="1.0"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:GetTotalBytesReceived xmlns:u="urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1"></u:GetTotalBytesReceived></s:Body></s:Envelope>
...
2020-09-05 18:58:01 DEBUG (MainThread) [async_upnp_client.traffic] Sending request:
POST http://<sanitizedIP>:43502/ctl/CmnIfCfg
SOAPAction: "urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1#GetTotalPacketsSent"
Host: <sanitizedIP>:43502
Content-Type: text/xml; charset="utf-8"
Content-Length: 288
<?xml version="1.0"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:GetTotalPacketsSent xmlns:u="urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1"></u:GetTotalPacketsSent></s:Body></s:Envelope>

2020-09-05 18:58:02 DEBUG (MainThread) [homeassistant.components.upnp] Finished fetching <sanitizedManufacturer>-UPnP data in 1.180 seconds
...
2020-09-05 18:58:32 DEBUG (MainThread) [homeassistant.components.upnp] Getting traffic statistics from device: IGD Device: <sanitizedManufacturer>-UPnP/uuid:<sanitized>
2020-09-05 18:58:32 DEBUG (MainThread) [async_upnp_client.traffic] Sending request:
POST http://<sanitizedIP>:43502/ctl/CmnIfCfg
SOAPAction: "urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1#GetTotalBytesReceived"
Host: <sanitizedIP>:43502
Content-Type: text/xml; charset="utf-8"
Content-Length: 292
<?xml version="1.0"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:GetTotalBytesReceived xmlns:u="urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1"></u:GetTotalBytesReceived></s:Body></s:Envelope>
//No corresponding "Got response"

So this is an interesting effect that there's the "Sending request:" with a follow-up "Got response:" up until I power off my router, at which time there is STILL "Sending request:" occurring, even though there was a "Cannot connect to host". But that continual "Sending request" would also perform as a ping/poll for whenever the connection gets reestablished. But even then, when the router comes back up, the "Sending request:" continues as expected, but there is no corresponding "Got response:".

Hmm, I was going to use the GUPnP Universal Control Point program like I did before, but for some reason, it isn't getting data either now. Okay, that just looked to be some side issue which I resolved by flipping the router upnp setting between disabled/enabled to get it back. It was enabled, so I don't know what was up with that.

AH HA! I had a feeling. You can consider this your solution (I think/hope). When you're "Sending request:" You're sending it to a particular port. That port was supposedly received during a "discovery" request:

^ÿúL»XJ}Eµó«@ÏÞÀ¨ïÿÿúÕvl¡ÛM-SEARCH * HTTP/1.1
Host: 239.255.255.250:1900
Man: "ssdp:discover"
ST: upnp:rootdevice
MX: 3
User-Agent: Linux/5.7.4-dirty UPnP/1.0 GUPnP/1.2.4

The port received in response was "43502". Now when I power cycled my router, that port was no longer assigned for the distribution of upnp data. I just took a look in wireshark and this time it's "41395":

L»XJ}Ð[¨+O/E@@´À¨À¨lÕvn@³HTTP/1.1 200 OK
CACHE-CONTROL: max-age=120
ST: upnp:rootdevice
USN: uuid:<sanitized>::upnp:rootdevice
EXT:
SERVER: Ubuntu/precise UPnP/1.1 MiniUPnPd/1.9
LOCATION: http://<sanitized>:41395/rootDesc.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: 1599334247
BOOTID.UPNP.ORG: 1599334247
CONFIGID.UPNP.ORG: 1337

So instead of doing a continuous poll of "Send request" when you get a "Cannot connect to host" or "Timeout fetching", I think you should be doing a "discovery" instead.

Perhaps, but your router seems to be the first which actually requires this (i.e., I've seen no other issues.)

Can't you choose a fixed port? In miniupnpd.conf (probably located at /etc/miniupnpd/miniupnpd.conf, you can set the option http_port to a fixed value, instead of letting it choose randomly. See the configuration file for more information.

Nope. Even though it says it's an Ubuntu-based router, I have no shell access. It's locked down I guess by the manufacturer and only has a web interface. I don't know why there would be a discovery stage for upnp if there would be a static port. I mean, a device could contain other(multiple) programs that make use of upnp like Kodi, which would require another listening port, no? How is it normally done, if not by discovery?

The discovery mechanism is used to ease installation/integration. The average user will not be able find the required URL such as http://192.168.178.1:80/RootDevice.xml, which is different for each device. Through discovery, the user does not have to do anything and the device can be automatically found and used. The same for Kodi/your TV/receiver/printer/..., which all use UPnP and all are discovered automatically and can be used. Discovery is one of the parts of the UPnP standard.

You are the first who reports this, therefore there probably aren't many users having this issue. Also, how often do you reboot your router, resulting in use of a different port? I'd rather not make the integration much more complex for a single case. Also, I don't have that much time to work on this as other projects require most of my attention currently.

As a work-around, when the router is rebooted, you can remove and add the integration again. This will trigger a new discovery and initialization and the new port will be used. Restarting home assistant is another option.

It's truly random when my router just doesn't let my device(s) authenticate with it (when I leave and come back), requiring me to reboot it. It may be once a week, or maybe a month.

Me being the first to report it wouldn't mean it isn't more commonplace. There's probably a lot of users who never report their issues. Maybe don't know how or that they can, or they find software to be so buggy they just opt to give up on it rather than report it. I know I've done that. Sometimes I may revisit software months later to see how far it's progressed to decide whether to give it another chance.

It isn't even important for me to have the stats, but I like to make use of everything I have to the fullest.

At least I now know what is going on and that I can just deal with it myself in various ways. I may just make a script to monitor the log and do the removal/addition myself. So with that, I'll just close it with no fix attributed.

Me being the first to report it wouldn't mean it isn't more commonplace.

You are most likely right, but we cannot be entirely sure. Now there is this issue to which people can reply if they are having the same problems. When this happens I'll reconsider this.

I hope you understand that there are many routers which support upnp and supporting them all with their quirks is a major task. The question is how much the users gain vs the complexity of the component to work around all the problems. Also, the more complex a component becomes, the more bugs it most likely contains.

Brand-related components can be much more narrow in terms of the devices they have to support. There are fewer quirks to support/work around.

Thank you for reporting this though! Now I know that there is at least one device which does this.

Now there is this issue to which people can reply if they are having the same problems. When this happens I'll reconsider this.

Hey, that's me, I'm having the exact same issue. Didn't dump network traffic, but it would make sense.

I have a TP-Link Archer AX55 router. Every time it's rebooted HA loses all information about it and I have to re-add it to the system. Restarting HA doesn't fix anything. Would be nice if it was rediscovered.

I could try to have a look at the code myself and figure out how to re-discover etc, but if someone knows already that would of course be easier.

Hi @Symbiatch. #75657 was just merged. Can you wait for the next hass release, and test it? If the problem persists, can you create a new issue referring this issue?

I'll be happy to. Thanks!

home-assistant / core