Sonos integration fails upon HA restart, if any device is powered off #90226

JCPvanHooren · 2023-03-24T10:46:23Z

The problem

While I only have to restart my Home Assistant occasionally, every time I do, I need to make sure all my Sonos devices are turned on / have power, to avoid the integration from failing to setup and all Sonos devices being unavailable.

My Sonos Roam is not always on.
Both my Sonos Beam and Play5 are behind a smart plug that switches off e.g. during the night.

Environment:

HA core in docker container @ host: 192.168.1.104
Docker container NOT on host network
configuration.yaml adjusted according to: Sonos 'advanced-use' (see below yaml snippet)

What version of Home Assistant Core has the issue?

core-2023.3.4

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Sonos

Link to integration documentation on our website

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

Diagnostics information

config_entry-sonos-2a2fb28b09fe9fbc04d5d8322c2ac283.json.txt

Example YAML snippet

sonos:
  media_player:
    advertise_addr: 192.168.1.104
    hosts:
      - 192.168.1.28 #Play5
      - 192.168.1.30 #Beam
      - 192.168.1.42 #Roam

Anything in the logs that might be useful for us?

2023-03-24 11:23:35.637 DEBUG (SyncWorker_3) [soco.zonegroupstate] Cache still active (GetZoneGroupState) during poll for 192.168.1.42
2023-03-24 11:23:35.637 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Sonos Roam from manual zone scan while in cooldown, ignoring
2023-03-24 11:23:35.638 DEBUG (SyncWorker_16) [soco.services] Request timeout set to 1
2023-03-24 11:23:35.638 DEBUG (SyncWorker_16) [soco.services] Sending GetVolume [('InstanceID', 0), ('Channel', 'Master')] to 192.168.1.42
2023-03-24 11:23:35.638 DEBUG (SyncWorker_16) [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>

2023-03-24 11:23:36.642 DEBUG (MainThread) [homeassistant.components.sonos] Manual poll to 192.168.1.42 failed, keeping unavailable
2023-03-24 11:23:40.778 WARNING (MainThread) [soco.events_asyncio] Could not bind to 172.20.0.5:1400: [Errno 98] Address in use
2023-03-24 11:23:51.471 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Sonos for sonos
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 383, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 156, in async_setup_entry
    await manager.setup_platforms_and_discovery()
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 514, in setup_platforms_and_discovery
    await self.async_poll_manual_hosts()
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 390, in async_poll_manual_hosts
    await self._async_handle_discovery_message(
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 416, in _async_handle_discovery_message
    await self.async_subscribe_to_zone_updates(discovered_ip)
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 203, in async_subscribe_to_zone_updates
    sub = await soco.zoneGroupTopology.subscribe()
  File "/usr/local/lib/python3.10/site-packages/soco/events_asyncio.py", line 374, in _async_wrap_subscribe
    await subscribe(requested_timeout, auto_renew)
  File "/usr/local/lib/python3.10/site-packages/soco/events_asyncio.py", line 507, in _async_make_request
    response = await self.event_listener.session.request(
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 467, in _request
    with timer:
  File "/usr/local/lib/python3.10/site-packages/aiohttp/helpers.py", line 721, in __exit__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError

Additional information

No response

home-assistant · 2023-03-24T10:46:28Z

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!

Code owner commands

Code owners of sonos can trigger bot actions by commenting:

@home-assistant close Closes the issue.
@home-assistant rename Awesome new title Renames the issue.
@home-assistant reopen Reopen the issue.
@home-assistant unassign sonos Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

sonos documentation
sonos source
_{^{(message by IssueLinks)}}

PeteRager · 2023-03-25T11:45:27Z

@jjlawren

I just fixed a different issue in this section of code. And would be glad to look at this one also. That is unless you want to fix it. Lmk.

jjlawren · 2023-03-25T12:39:22Z

@PeteRager I won't have time to sit down and take a look for a couple more days. Please feel free to submit a fix. 👍

PeteRager · 2023-03-25T12:48:48Z

Sounds good, Ive looked at the code and know what to fix and will get something together next few days.

PeteRager · 2023-03-28T00:39:27Z

@JCPvanHooren I'm unable to reproduce this on my Sonos system, not sure why. I've tried starting HASS with all 3 devices off, and it does log errors but not the ones you are getting and the integration does not fail to setup. Then when I turn the devices on they become available in HASS. I also tried it with one off and 2 on which resulted in a different error (and a stack dump) but the setup did succeed and when i turned the device it then became available in HASS. In general I seem to get "Host is unreachable" error while your log has a "Timeout" error. Anything else special on your network?

Based on your error log, I can fix this issue. But may need you to test it, in order to verify that it recovers properly.

JCPvanHooren · 2023-03-28T06:20:59Z

Anything else special on your network?

Well, I use a reverse proxy server to connect with my HA instance and have AdGuard as DNS server, but then I feel like I'm reaching for things that shouldn't be related.

Based on your error log, I can fix this issue. But may need you to test it, in order to verify that it recovers properly.

I'm happy to test, if you're ok to provide a little guidance. I'm OK to fiddle around with the system, but not a pro either.

PeteRager · 2023-03-28T11:21:57Z

Thanks, that's very similar to my setup.

One test I'd like you to run when you have time is this:

a) start HASS when all the Sonos devices are turned off

Do you still get the setup error?

JCPvanHooren · 2023-03-28T14:58:02Z

This is the error that I get when I restart with all Sonos' powered off / disconnected from power:

Logger: homeassistant.config_entries
Source: util/async_.py:146
First occurred: 4:55:52 PM (1 occurrences)
Last logged: 4:55:52 PM

Error setting up entry Sonos for sonos
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 383, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 156, in async_setup_entry
    await manager.setup_platforms_and_discovery()
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 514, in setup_platforms_and_discovery
    await self.async_poll_manual_hosts()
  File "/usr/src/homeassistant/homeassistant/components/sonos/__init__.py", line 391, in async_poll_manual_hosts
    soco.uid, ip_addr, "manual zone scan"
  File "/usr/local/lib/python3.10/site-packages/soco/core.py", line 422, in uid
    self.zone_group_state.poll(self)
  File "/usr/local/lib/python3.10/site-packages/soco/core.py", line 1559, in zone_group_state
    zgs = self.zone_group_states.get(self.household_id)
  File "/usr/local/lib/python3.10/site-packages/soco/core.py", line 444, in household_id
    self._household_id = self.deviceProperties.GetHouseholdID()[
  File "/usr/local/lib/python3.10/site-packages/soco/services.py", line 206, in _dispatcher
    return self.send_command(action, *args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/soco/services.py", line 473, in send_command
    args = self.compose_args(action, kwargs)
  File "/usr/local/lib/python3.10/site-packages/soco/services.py", line 333, in compose_args
    for action in self.actions:
  File "/usr/local/lib/python3.10/site-packages/soco/services.py", line 675, in actions
    self._actions = list(self.iter_actions())
  File "/usr/local/lib/python3.10/site-packages/soco/services.py", line 701, in iter_actions
    scpd_body = requests.get(self.base_url + self.scpd_url, timeout=10).content
  File "/usr/local/lib/python3.10/site-packages/requests/api.py", line 73, in get
    return request("get", url, params=params, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/api.py", line 59, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/sessions.py", line 587, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/sessions.py", line 701, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/requests/adapters.py", line 489, in send
    resp = conn.urlopen(
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 398, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 244, in request
    super(HTTPConnection, self).request(method, url, body=body, headers=headers)
  File "/usr/local/lib/python3.10/http/client.py", line 1282, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/local/lib/python3.10/http/client.py", line 1293, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 219, in putrequest
    return _HTTPConnection.putrequest(self, method, url, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 159, in protected_loop_func
    check_loop(func, strict=strict)
  File "/usr/src/homeassistant/homeassistant/util/async_.py", line 146, in check_loop
    raise RuntimeError(
RuntimeError: Blocking calls must be done in the executor or a separate thread; Use `await hass.async_add_executor_job()`; at homeassistant/components/sonos/__init__.py, line 391: soco.uid, ip_addr, "manual zone scan"

JCPvanHooren · 2023-03-28T14:59:08Z

As well as this:

Logger: homeassistant.util.async_
Source: util/async_.py:159
First occurred: 4:55:52 PM (1 occurrences)
Last logged: 4:55:52 PM

Detected blocking call to putrequest inside the event loop. This is causing stability issues. Please report issue for sonos doing blocking calls at homeassistant/components/sonos/__init__.py, line 391: soco.uid, ip_addr, "manual zone scan"

PeteRager · 2023-03-28T16:06:13Z

That latest issue has been fixed here #88554

JCPvanHooren · 2023-03-28T17:57:53Z

That latest issue has been fixed here #88554

That's what I thought; just wasn't sure and not sure when it'd reach me trough a release/update.
Didn't want to leave it out to later figure out it was relevant after all.

PeteRager · 2023-04-14T10:32:50Z

I was able to recreate your issue in my setup. I have fixed that issue and other that I found through extensive testing of plugging and unplugging speakers in different scenarios. Unplugged at startup, unplugged latter, all unplugged, some unplugged. I also created extensive unit tests for these scenarios so we can guarantee they continue to work into the future.

Next step is to get the code review completed. Need some help from @epenet, @jjlawren or @cgtobi on that step.

JCPvanHooren · 2023-04-14T14:40:43Z

Thank you Pete. Much appreciated.
Anything I can do to help?

PeteRager · 2023-04-18T00:36:53Z

Not sure, put a bunch of effort putting together a proposed fix, not seeing much uptake on getting this change reviewed and approved so we can resolve this issue we both have.

PeteRager · 2023-05-21T23:18:01Z

The change has been approved! Got some really good help getting the unit tests improved.

I don't know if it will make the cutoff for 2023.6.0; or if will be in 2023.7.0

home-assistant bot added the integration: sonos label Mar 24, 2023

home-assistant bot assigned cgtobi Mar 24, 2023

home-assistant bot assigned jjlawren Mar 24, 2023

PeteRager mentioned this issue Apr 1, 2023

Sonos setup fails with unhandled exceptions on discovery messages #90648

Merged

19 tasks

bdraco closed this as completed in #90648 May 30, 2023

github-actions bot locked and limited conversation to collaborators Jun 29, 2023

bdraco added the blocking event loop label Apr 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sonos integration fails upon HA restart, if any device is powered off #90226

Sonos integration fails upon HA restart, if any device is powered off #90226

JCPvanHooren commented Mar 24, 2023 •

edited

home-assistant bot commented Mar 24, 2023

PeteRager commented Mar 25, 2023 •

edited

jjlawren commented Mar 25, 2023

PeteRager commented Mar 25, 2023

PeteRager commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

PeteRager commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

PeteRager commented Mar 28, 2023 •

edited

JCPvanHooren commented Mar 28, 2023 •

edited

PeteRager commented Apr 14, 2023

JCPvanHooren commented Apr 14, 2023

PeteRager commented Apr 18, 2023

PeteRager commented May 21, 2023

Sonos integration fails upon HA restart, if any device is powered off #90226

Sonos integration fails upon HA restart, if any device is powered off #90226

Comments

JCPvanHooren commented Mar 24, 2023 • edited

The problem

What version of Home Assistant Core has the issue?

What was the last working version of Home Assistant Core?

What type of installation are you running?

Integration causing the issue

Link to integration documentation on our website

Diagnostics information

Example YAML snippet

Anything in the logs that might be useful for us?

Additional information

home-assistant bot commented Mar 24, 2023

PeteRager commented Mar 25, 2023 • edited

jjlawren commented Mar 25, 2023

PeteRager commented Mar 25, 2023

PeteRager commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

PeteRager commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

JCPvanHooren commented Mar 28, 2023

PeteRager commented Mar 28, 2023 • edited

JCPvanHooren commented Mar 28, 2023 • edited

PeteRager commented Apr 14, 2023

JCPvanHooren commented Apr 14, 2023

PeteRager commented Apr 18, 2023

PeteRager commented May 21, 2023

JCPvanHooren commented Mar 24, 2023 •

edited

PeteRager commented Mar 25, 2023 •

edited

PeteRager commented Mar 28, 2023 •

edited

JCPvanHooren commented Mar 28, 2023 •

edited