search

StevenLooman / async_upnp_client

Async UPnP Client for Python
Other
46 stars 37 forks source link

TypeError: async_upnp_client.utils.CaseInsensitiveDict() got multiple values for keyword argument 'SERVER' #74

Closed gulli1986 closed 3 years ago

gulli1986 commented 3 years ago

Hello,

I suddenly started getting log errors, approx. every minute. I cannot remember having touched anything in HA either:

2021-07-21 12:03:57 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 1029, in _read_ready
self._protocol.datagram_received(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 175, in datagram_received
request_line, headers = decode_ssdp_packet(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 126, in decode_ssdp_packet
headers = CaseInsensitiveDict(**parsed_headers)
TypeError: async_upnp_client.utils.CaseInsensitiveDict() got multiple values for keyword argument 'SERVER'

Running HA on a Blue edition, updated to latest core-2021.7.3.

I have been googling and cannot find what is wrong here. Everything in HA seems to work fine, I just can't figure this out... Any ideas of what might be wrong?

Cheers

StevenLooman commented 3 years ago

Hi @gulli1986, thank you for this issue. Every minute... that seems annoying. While I'm on 2021.7.3 as well, I haven't seen this traceback.

I think it is related to one of your devices. By judging from the traceback, I think one of your devices provides the header SERVER multiple times. Are you able and feel like doing some debugging? If so, enable logging by adding this to your configuration.yaml, and restart home assistant:

logger:
  default: warning
  logs:
    async_upnp_client.ssdp: debug
    async_upnp_client.traffic: error
    async_upnp_client.traffic.ssdp: debug

This will enable SSDP-traffic logging, be warned that there might be a flood of log messages. What we're looking for is the message which triggers this error. I.e., the message that is reported/logged before this traceback. I expect that it does contain the SERVER header multiple times.

This is mostly to verify my guess at what is going on.

If you're not able to do some debugging and/or don't feel like it, that is alright. I can make a fix to prevent this kind of error. Though the question will remain if there are SERVER-headers, does it provide the same value twice, or different values?

gulli1986 commented 3 years ago

Hi @StevenLooman,

Thanks for your quick response. I would love to find out about this. Here is the debugging you requested:

2021-07-21 17:51:18 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 1029, in _read_ready
self._protocol.datagram_received(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 175, in datagram_received
request_line, headers = decode_ssdp_packet(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 126, in decode_ssdp_packet
headers = CaseInsensitiveDict(**parsed_headers)
TypeError: async_upnp_client.utils.CaseInsensitiveDict() got multiple values for keyword argument 'SERVER'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending M-SEARCH packet: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending M-SEARCH packet: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.ssdp] Received error: [Errno 13] Permission denied
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.2', 1900): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1900\r\nST: upnp:rootdevice\r\nUSN: uuid:73796E6F-6473-6D00-0000-0011328e054e::upnp:rootdevice\r\nEXT:\r\nSERVER: Synology/DSM/192.168.1.2\r\nLOCATION: http://192.168.1.2:5000/ssdp/desc-DSM-eth0.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 1\r\nBOOTID.UPNP.ORG: 1\r\nCONFIGID.UPNP.ORG: 1337\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: uuid:RINCON_542A1B70E9B601400\r\nUSN: uuid:RINCON_542A1B70E9B601400\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:device:ZonePlayer:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:device:ZonePlayer:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: upnp:rootdevice\r\nUSN: uuid:RINCON_542A1B70E9B601400::upnp:rootdevice\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: uuid:RINCON_542A1B70E9B601400_MS\r\nUSN: uuid:RINCON_542A1B70E9B601400_MS\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:device:MediaServer:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MS::urn:schemas-upnp-org:device:MediaServer:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: uuid:RINCON_542A1B70E9B601400_MR\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:device:MediaRenderer:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:device:MediaRenderer:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:AlarmClock:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:AlarmClock:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:MusicServices:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:MusicServices:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:DeviceProperties:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:DeviceProperties:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:SystemProperties:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:SystemProperties:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:ZoneGroupTopology:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:ZoneGroupTopology:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:GroupManagement:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-upnp-org:service:GroupManagement:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-tencent-com:service:QPlay:1\r\nUSN: uuid:RINCON_542A1B70E9B601400::urn:schemas-tencent-com:service:QPlay:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:ContentDirectory:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MS::urn:schemas-upnp-org:service:ContentDirectory:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:ConnectionManager:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MS::urn:schemas-upnp-org:service:ConnectionManager:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:RenderingControl:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:service:RenderingControl:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:ConnectionManager:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:service:ConnectionManager:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:AVTransport:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:service:AVTransport:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-sonos-com:service:Queue:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-sonos-com:service:Queue:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:GroupRenderingControl:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:service:GroupRenderingControl:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:17 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.158', 58397): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age = 1800\r\nEXT:\r\nLOCATION: http://192.168.1.158:1400/xml/device_description.xml\r\nSERVER: Linux UPnP/1.0 Sonos/63.2-90210 (ZPS17)\r\nST: urn:schemas-upnp-org:service:VirtualLineIn:1\r\nUSN: uuid:RINCON_542A1B70E9B601400_MR::urn:schemas-upnp-org:service:VirtualLineIn:1\r\nX-RINCON-HOUSEHOLD: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk\r\nX-RINCON-BOOTSEQ: 2\r\nBOOTID.UPNP.ORG: 2\r\nX-RINCON-WIFIMODE: 1\r\nX-RINCON-VARIANT: 10\r\nHOUSEHOLD.SMARTSPEAKER.AUDIO: Sonos_PvYIL53Fzx8yqqi7s5fNTaeTWk.xDB1S13vOwO72rPT5oed\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nEXT: \r\nST: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nEXT: \r\nST: urn:schemas-upnp-org:device:Eaton-SHC-UPnP-Device:1\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::urn:schemas-upnp-org:device:Eaton-SHC-UPnP-Device:1\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nEXT: \r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nST: upnp:rootdevice\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::upnp:rootdevice\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nEXT: \r\nLOCATION: http://192.168.1.5:40044/description/uuid3aEaton2dSHC2dUPnP2dDevice2dSHC2d98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nST: urn:schemas-mbs upnp device:service:URLService:1\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::urn:schemas-mbs upnp device:service:URLService:1\r\n\r\n'
2021-07-21 17:52:18 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 1029, in _read_ready
self._protocol.datagram_received(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 175, in datagram_received
request_line, headers = decode_ssdp_packet(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 126, in decode_ssdp_packet
headers = CaseInsensitiveDict(**parsed_headers)
TypeError: async_upnp_client.utils.CaseInsensitiveDict() got multiple values for keyword argument 'SERVER'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nEXT: \r\nST: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nEXT: \r\nST: urn:schemas-upnp-org:device:Eaton-SHC-UPnP-Device:1\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::urn:schemas-upnp-org:device:Eaton-SHC-UPnP-Device:1\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nEXT: \r\nLOCATION: http://192.168.1.5:40044/description/uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f/DCPD.XML\r\nST: upnp:rootdevice\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::upnp:rootdevice\r\n\r\n'
2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276): b'HTTP/1.1 200 OK\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nCONNECTION: close\r\nDATE: Wed, 21 Jul 2021 15:52:17 GMT\r\nCACHE-CONTROL: max-age = 1800\r\nEXT: \r\nLOCATION: http://192.168.1.5:40044/description/uuid3aEaton2dSHC2dUPnP2dDevice2dSHC2d98028401412f/DCPD.XML\r\nNTS: ssdp:alive\r\nSERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\nST: urn:schemas-mbs upnp device:service:URLService:1\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\nPKK-NLS: \r\nUSN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::urn:schemas-mbs upnp device:service:URLService:1\r\n\r\n'
2021-07-21 17:52:18 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback _SelectorDatagramTransport._read_ready()
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 1029, in _read_ready
self._protocol.datagram_received(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 175, in datagram_received
request_line, headers = decode_ssdp_packet(data, addr)
File "/usr/local/lib/python3.9/site-packages/async_upnp_client/ssdp.py", line 126, in decode_ssdp_packet
headers = CaseInsensitiveDict(**parsed_headers)
TypeError: async_upnp_client.utils.CaseInsensitiveDict() got multiple values for keyword argument 'SERVER'

Could that be my Eaton xComfort Smart Home Controller integration for light controller that triggers the error?

StevenLooman commented 3 years ago

You're way quicker with your response! :)

This is the trigger. I've formatted it a bit for clarity:

2021-07-21 17:52:18 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.1.5', 52276):
b'
HTTP/1.1 200 OK\r\n
SERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\n
CONNECTION: close\r\n
DATE: Wed, 21 Jul 2021 15:52:17 GMT\r\n
CACHE-CONTROL: max-age = 1800\r\n
EXT: \r\n
LOCATION: http://192.168.1.5:40044/description/uuid3aEaton2dSHC2dUPnP2dDevice2dSHC2d98028401412f/DCPD.XML\r\n
NTS: ssdp:alive\r\n
SERVER: Linux/3.7.0a-wdt-eaton+ UPnP/1.0 ProSyst mBedded Server/7.5 UPnP Export Manager/8.5.18\r\n
ST: urn:schemas-mbs upnp device:service:URLService:1\r\n
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=PKK\r\n
PKK-NLS: \r\n
USN: uuid:Eaton-SHC-UPnP-Device-SHC-98028401412f::urn:schemas-mbs upnp device:service:URLService:1\r\n
\r\n'

SERVER: appears twice. The Eaton xComfort Smart Home Controller device triggers the error, though I don't think that integration is causing this. The ssdp integration, used for discovery of devices on your network, is scanning regularly for (new) devices. You can try disabling the ssdp integrations, but no new SSDP-devices will be discovered. Another suspect might be the upnp integration (although this integration gets its discoveries through the ssdp integration.)

I'll try to work on a fix later today, but getting the fix in home assistant requires a bit more time.

gulli1986 commented 3 years ago

Thanks for your feedback :) I installed the Eaton xComfort integration for not so long ago and I am not sure I have checked the log for errors since then so it is definitely something here!

I will try disabling the ssdp integration in the meantime.

StevenLooman commented 3 years ago

As you can see I've created a PR to upgrade to the latest release of async_upnp_client, which includes a fix for your device. Hopefully this will be included in the upcoming home assistant release.

Another thing you can do is file a bug report with Eaton (or the company which made the Eaton xComfort Smart Home Controller) and explain it includes a duplicate header. While I think this is legal, it is possible other software might not be able to handle this properly. Feel free to link to this issue, I'm sure it will provide information an Eaton developer might find useful.

gulli1986 commented 3 years ago

@StevenLooman thank you so much!

I have now sent an e-mail to Eaton support with reference to their Smart Home Controller and link to this issue.

Looking forward to the next Home Assistant release!

StevenLooman commented 3 years ago

Even earlier than expected. The fix will be included in the home assistant 2021.7.4 release.

StevenLooman commented 3 years ago

2021.7.4 is released. Are you able to test it?

And if it is fixed, can you close this issue?

gulli1986 commented 3 years ago

Just updated to 2021.7.4, no error messages in the log so far, everything looks good!

Again a big thank you to you @StevenLooman !

StevenLooman commented 3 years ago

Great!