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
72.4k stars 30.3k forks source link

Unhandled Sonos UPnP error 1024 when the coordinator is unavailable #56724

Closed rytilahti closed 2 years ago

rytilahti commented 3 years ago

The problem

When grouped Sonos speakers are missing their coordinator, the connected devices are still discoverable but commands are not getting through, causing repeated logger warnings on requests.

Maybe this special case should be handled more gracefully, by having a more explicit warnings and only reporting this once? Or in the best case, the speakers could keep functioning even if their coordinator is missing, but that is probably something that is out of control of the integration.

What is version of Home Assistant Core has the issue?

2021.10.0.dev0

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

sonos

Link to integration documentation on our website

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

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2021-09-28 00:28:23 DEBUG (MainThread) [homeassistant.components.sonos] New Zeroconf discovery uid=***REDACTED***: {'_raw': {'info': b'/api/v1/players/***REDACTED/info', 'vers': b'3', 'protovers': b'1.25.1', 'bootseq': b'57', 'hhid': b'***REDACTED***', 'mhhid': b'***REDACTED***', 'location': b'http://***REDACTED***:1400/xml/device_description.xml', 'sslport': b'1443', 'hhsslport': b'1843', 'variant': b'2', 'mdnssequence': b'0'}, 'info': '/api/v1/players/***REDACTED***/info', 'vers': '3', 'protovers': '1.25.1', 'bootseq': '57', 'hhid': '***REDACTED***', 'mhhid': '***REDACTED***', 'location': 'http://***REDACTED***:1400/xml/device_description.xml', 'sslport': '1443', 'hhsslport': '1843', 'variant': '2', 'mdnssequence': '0'}
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.core] Created SoCo instance for ip: ***REDACTED***
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Dispatching method GetZoneGroupState
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Sending GetZoneGroupState [] to ***REDACTED***
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Sending {'Content-Type': 'text/xml; charset="utf-8"', 'SOAPACTION': 'urn:schemas-upnp-org:service:ZoneGroupTopology:1#GetZoneGroupState'}, <?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:GetZoneGroupState xmlns:u="urn:schemas-upnp-org:service:ZoneGroupTopology:1"/>
  </s:Body>
</s:Envelope>

2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Received {'CONTENT-LENGTH': '2605', 'CONTENT-TYPE': 'text/xml; charset="utf-8"', 'EXT': '', 'Server': 'Linux UPnP/1.0 Sonos/65.1-21040 (ZPS12)', 'Connection': 'close'}, <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetZoneGroupStateResponse xmlns:u="urn:schemas-upnp-org:service:ZoneGroupTopology:1"><ZoneGroupState>&lt;ZoneGroupState&gt;&lt;ZoneGroups&gt;&lt;ZoneGroup Coordinator=&quot;***REDACTED***quot; ID=&quot;***REDACTED***quot;&gt;&lt;ZoneGroupMember UUID=&quot;***REDACTED***quot; Location=&quot;http://***REDACTED***:1400/xml/device_description.xml&quot; ZoneName=&quot;Beam&quot; Icon=&quot;x-rincon-roomicon:bedroom&quot; Configuration=&quot;1&quot; Invisible=&quot;1&quot; SoftwareVersion=&quot;65.1-21040&quot; SWGen=&quot;2&quot; MinCompatibleVersion=&quot;64.0-00000&quot; LegacyCompatibleVersion=&quot;58.0-00000&quot; HTSatChanMapSet=&quot;***REDACTED***quot; BootSeq=&quot;89&quot; TVConfigurationError=&quot;0&quot; HdmiCecAvailable=&quot;0&quot; WirelessMode=&quot;1&quot; WirelessLeafOnly=&quot;0&quot; ChannelFreq=&quot;2412&quot; BehindWifiExtender=&quot;0&quot; WifiEnabled=&quot;1&quot; Orientation=&quot;0&quot; RoomCalibrationState=&quot;5&quot; SecureRegState=&quot;3&quot; VoiceConfigState=&quot;0&quot; MicEnabled=&quot;0&quot; AirPlayEnabled=&quot;0&quot; IdleState=&quot;1&quot; MoreInfo=&quot;&quot;/&gt;&lt;/ZoneGroup&gt;&lt;ZoneGroup Coordinator=&quot;***REDACTED***quot; ID=&quot;***REDACTED***quot;&gt;&lt;ZoneGroupMember UUID=&quot;***REDACTED***quot; Location=&quot;http://***REDACTED***:1400/xml/device_description.xml&quot; ZoneName=&quot;Beam&quot; Icon=&quot;x-rincon-roomicon:living&quot; Configuration=&quot;1&quot; Invisible=&quot;1&quot; SoftwareVersion=&quot;65.1-21040&quot; SWGen=&quot;2&quot; MinCompatibleVersion=&quot;64.0-00000&quot; LegacyCompatibleVersion=&quot;58.0-00000&quot; HTSatChanMapSet=&quot;***REDACTED***quot; BootSeq=&quot;57&quot; TVConfigurationError=&quot;0&quot; HdmiCecAvailable=&quot;0&quot; WirelessMode=&quot;1&quot; WirelessLeafOnly=&quot;0&quot; ChannelFreq=&quot;2412&quot; BehindWifiExtender=&quot;0&quot; WifiEnabled=&quot;1&quot; Orientation=&quot;0&quot; RoomCalibrationState=&quot;5&quot; SecureRegState=&quot;3&quot; VoiceConfigState=&quot;0&quot; MicEnabled=&quot;0&quot; AirPlayEnabled=&quot;0&quot; IdleState=&quot;1&quot; MoreInfo=&quot;&quot;/&gt;&lt;/ZoneGroup&gt;&lt;/ZoneGroups&gt;&lt;VanishedDevices&gt;&lt;/VanishedDevices&gt;&lt;/ZoneGroupState&gt;</ZoneGroupState></u:GetZoneGroupStateResponse></s:Body></s:Envelope>
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Received status 200 from ***REDACTED***
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Dispatching method GetVolume
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Sending GetVolume [('InstanceID', 0), ('Channel', 'Master')] to ***REDACTED***
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Sending {'Content-Type': 'text/xml; charset="utf-8"', 'SOAPACTION': 'urn:schemas-upnp-org:service:RenderingControl:1#GetVolume'}, <?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:GetVolume xmlns:u="urn:schemas-upnp-org:service:RenderingControl:1">
      <InstanceID>0</InstanceID>
      <Channel>Master</Channel>
    </u:GetVolume>
  </s:Body>
</s:Envelope>

2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Received {'CONTENT-LENGTH': '348', 'CONTENT-TYPE': 'text/xml; charset="utf-8"', 'EXT': '', 'Server': 'Linux UPnP/1.0 Sonos/65.1-21040 (ZPS12)', 'Connection': 'close'}, <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>1024</errorCode></UPnPError></detail></s:Fault></s:Body></s:Envelope>
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Received status 500 from ***REDACTED***
2021-09-28 00:28:23 DEBUG (SyncWorker_5) [soco.services] Error b'<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>1024</errorCode></UPnPError></detail></s:Fault></s:Body></s:Envelope>'
2021-09-28 00:28:23 WARNING (SyncWorker_5) [homeassistant.components.sonos] Failed to connect to discovered player '***REDACTED***': UPnP Error 1024 received:  from ***REDACTED***


### Additional information

_No response_
probot-home-assistant[bot] commented 3 years ago

sonos documentation sonos source (message by IssueLinks)

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

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

jjlawren commented 3 years ago

When grouped Sonos speakers are missing their coordinator

What are some scenarios where this situation could be expected?

rytilahti commented 3 years ago

What are some scenarios where this situation could be expected?

To be honest, I just encountered this while testing other parts of my setup. In this case, my television, soundbar (which is connected to rear speakers) et al. are plugged into a smart plug, which was left turned off as I wasn't using it.

Considering that the sonos app itself cannot handle the missing controller amicably (showing Beam (?+LS+RS) +1 being non-configured), I'm not sure there is much to do besides having a cleaner warning & avoid spamming the logs.

rytilahti commented 2 years ago

I think this is still valid.

github-actions[bot] commented 2 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

rytilahti commented 2 years ago

This is still valid, at least partially. The solution would be suppressing the repeated warnings.

I just spotted this as my rear speakers have suddenly jumped from their original network to another one. I suppose this caused them to be discovered & they are now being polled even when they are hidden:

Room/Zone Name    IP Address       Device Model         Visibility    SW Version
----------------  ---------------  -------------------  ------------  ------------
Beam              192.168.100.xxx  Play:1               Hidden        14.2
Beam              192.168.100.xxx  Play:1               Hidden        14.2
Beam              192.168.220.xx   Beam                 Visible       14.2

This is the (repeated) log spam that I'm seeing every 30 seconds for both of those hidden speakers:

[homeassistant.components.sonos] Failed to connect to discovered player '192.168.100.xxx': UPnP Error 1024 received:  from 192.168.100.xxx
jjlawren commented 2 years ago
  1. Is the 192.168.100.X subnet expected on your network? Are there other devices on this network, a DHCP service providing addresses, etc?
  2. Can you reach/ping those devices from your HA host? It seems you can reach them but are rejected with a UPnP protocol error.
rytilahti commented 2 years ago
  1. Yes, 192.168.100/24 is my regular network, the second one is reserved for iot stuff where the main coordinator (beam) still resides. It's a mystery why they suddenly jumped into that another network, but it's not important for this issue.
  2. Yes, I can ping them, download the description files etc. They are rejecting UPnP commands as they are bound to the beam, and as such not directly controllable.

I think the warning should be just suppressed (the "log a warning once when unavailable" rule per https://developers.home-assistant.io/docs/integration_quality_scale_index/#silver-) and call it a day :-)

jjlawren commented 2 years ago
  1. I'd argue it does matter as it implies the network topology is changing in unexpected ways. The Sonos devices are very sensitive to networking changes and this should be understood.
  2. Based on the error message, it can only happen when requesting the device's uid or volume which should work for every speaker, even satellites. Are you able to test this more with this speaker using soco directly?
rytilahti commented 2 years ago

Yes, the network topology indeed changed in an unexpected way! Here's step-wise what I think happened in this most recent case:

  1. Unrelated to the issue, I wanted to try out using Sonosnet instead of having all devices connected over wifi by their own. To do that, I wired one of my rear speaker to test this out.
  2. That did not work out, and the devices stayed connected over wifi. Later "research" revealed that the satellites cannot be used as sonosnet masters.
  3. I forgot to remove the network cable from the device, and as part of an update cycle that ethernet-connected rear speaker started suddenly acting as a Sonosnet host for the another rear speaker. Maybe it didn't do this earlier as it detected that it'd be an incompatible setup, who knows?
  4. Now I had two rear speakers connected directly to my main network, one acting as Sonosnet router for another. The Beam (the coordinator for these rear speakers) did not connect to that newly created Sonosnet but stayed connected to the wifi network.
  5. I think this network change left these rear speakers "parentless", causing them to be invisible for the app, soco-cli etc., and also responding UPnP errors on most of UPnP commands I tested. While calls to some services succeeded (like those to ZoneGroupTopology), some were failing (including querying RenderingControl and AVTransport).