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
73.69k stars 30.82k forks source link

Sonos warning: Subscriptions for xxx failed, speaker may have lost power #65538

Closed emufan closed 2 years ago

emufan commented 2 years ago

The problem

Since 2022.2.0 I see a lot of Subscriptions for xxx failed, speaker may have lost power messages. Didn't see this before and don't think that these devices lose power at all.

In these cases (see log below) these are ZP80 (aka connect) and ZP100 (aka connect:amp).

What version of Home Assistant Core has the issue?

core-2022.2.0

What was the last working version of Home Assistant Core?

core-2021.12.10

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/

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-02-03 12:17:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Keller failed, speaker may have lost power
2022-02-03 12:17:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Wohnzimmer failed, speaker may have lost power

022-02-03 12:35:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Keller failed, speaker may have lost power
2022-02-03 12:35:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Wohnzimmer failed, speaker may have lost power

2022-02-03 12:53:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Keller failed, speaker may have lost power
2022-02-03 12:53:31 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Wohnzimmer failed, speaker may have lost power

etc.

Additional information

Sonos S1

probot-home-assistant[bot] commented 2 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)

sonos documentation sonos source (message by IssueLinks)

jjlawren commented 2 years ago

Diagnostics would hopefully help understand what's going on here. Grabbing those both before & after an error would be most useful.

emufan commented 2 years ago

Here we go.

2022-02-03 17:44:14 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from SonosSwitchEntity.update
2022-02-03 17:44:14 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from SonosSwitchEntity.update
2022-02-03 17:44:14 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from SonosSwitchEntity.update
2022-02-03 17:44:14 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from SonosSwitchEntity.update

2022-02-03 17:44:42 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Keller failed, speaker may have lost power
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribing from events for Keller
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Keller: 412, message='Precondition Failed', url=URL('http://192.168.178.30:1400/MediaRenderer/RenderingControl/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Keller: 412, message='Precondition Failed', url=URL('http://192.168.178.30:1400/ZoneGroupTopology/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Keller: 412, message='Precondition Failed', url=URL('http://192.168.178.30:1400/DeviceProperties/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Keller: 412, message='Precondition Failed', url=URL('http://192.168.178.30:1400/AlarmClock/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Keller: 412, message='Precondition Failed', url=URL('http://192.168.178.30:1400/MediaServer/ContentDirectory/Event')
2022-02-03 17:44:42 WARNING (MainThread) [homeassistant.components.sonos.speaker] Subscriptions for Wohnzimmer failed, speaker may have lost power
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribing from events for Wohnzimmer
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Wohnzimmer: 412, message='Precondition Failed', url=URL('http://192.168.178.27:1400/MediaServer/ContentDirectory/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Wohnzimmer: 412, message='Precondition Failed', url=URL('http://192.168.178.27:1400/ZoneGroupTopology/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Wohnzimmer: 412, message='Precondition Failed', url=URL('http://192.168.178.27:1400/MediaRenderer/AVTransport/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Wohnzimmer: 412, message='Precondition Failed', url=URL('http://192.168.178.27:1400/AlarmClock/Event')
2022-02-03 17:44:42 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Unsubscribe failed for Wohnzimmer: 412, message='Precondition Failed', url=URL('http://192.168.178.27:1400/DeviceProperties/Event')

2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from discovery
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for Wohnzimmer
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from SonosSpeaker.update_volume
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from discovery
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for Keller
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for Wohnzimmer
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from DeviceProperties subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from ContentDirectory subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from SonosSpeaker.update_volume
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from AVTransport subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from AlarmClock subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for Keller
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from DeviceProperties subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from ContentDirectory subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from RenderingControl subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from SonosSpeaker.update_media
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from AVTransport subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Keller from AlarmClock subscription
2022-02-03 17:45:10 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Activity on Wohnzimmer from ZoneGroupTopology subscription
jjlawren commented 2 years ago

Sorry, I meant the new "Download diagnostics" option on the integration: image

This feature assumes you have diagnostics enabled or are running with default_config: in your configuration.

emufan commented 2 years ago

In this download is unfortunately nothing related to the warning text above, I don't see the warning message, no corresponding text, .... And these are coming more or less exactly every 18 minutes, with the same debug log as posted above. And it is subscribed again some seconds afterwards, at least shown in the log this way. So there is no before/after either.

jjlawren commented 2 years ago

There may be other useful information in there, such as event payload contents, activity profile, etc.

Either way, it appears that the event subscription renewal requests are being rejected by the Sonos devices. Normally they allow you to renew them as long as the request is made before the previous subscription expired. It seems like they're expiring on the Sonos side before the renewal is requested, but I'm not sure why that would happen.

Since you've also opened https://github.com/home-assistant/core/issues/65537 it makes me wonder if there is something else going on in your setup. Events seem to be working, so it's not clearly a network setup issue. Perhaps it's related to your older firmware, but nothing has changed recently that should begin causing these problems. It's kind of a nuclear option, but have you tried power cycling some of the Sonos devices?

emufan commented 2 years ago

I didn't change anything other than updating to 2022.2.0. And perhaps it is related to S1. But I didn't see these warnings before. At least 100% not his from this issue, which now come every 18 minutes.

And only for the two ZP80/100 in the house. Nothing for all the other devices.

I would of course volunteer to share the nodes/sections, which are relevant for you, but the whole diagnostics would disclose too many information, custom components, IPs, URLs, ... So there I'm a little bit afraid/don't like to post the whole file here.

If I compare different downloads, the only changes I see between them are several entries likes this

image

For the other one, I found it now in other logs from 2021.12.10 some times.

dap35 commented 2 years ago

I am seeing similar error in the logs after upgrading to 2022.0.

2022-02-02 20:45:37 WARNING (MainThread) [homeassistant.components.sonos.switch] Migration of Speech Enhancement switches on TV Room failed, manual cleanup required: ['switch.sonos_tv_room_speech_enhancement', 'switch.sonos_tv_room_speech_enhancement_2'] 2022-02-02 20:45:38 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.9/site-packages/soco/events_asyncio.py", line 147, in notify subscription.send_event(event) File "/usr/local/lib/python3.9/site-packages/soco/events_base.py", line 596, in send_event callback(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 457, in async_dispatch_event dispatcher(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 704, in async_update_groups for vanished_device in zgs.find("VanishedDevices"): TypeError: 'NoneType' object is not iterable 2022-02-02 20:45:39 WARNING (MainThread) [homeassistant.components.sonos.switch] Migration of Speech Enhancement switches on Bedroom failed, manual cleanup required: ['switch.sonos_bedroom_speech_enhancement', 'switch.sonos_bedroom_speech_enhancement_2'] 2022-02-02 20:45:43 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.9/site-packages/soco/events_asyncio.py", line 147, in notify subscription.send_event(event) File "/usr/local/lib/python3.9/site-packages/soco/events_base.py", line 596, in send_event callback(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 457, in async_dispatch_event dispatcher(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 704, in async_update_groups for vanished_device in zgs.find("VanishedDevices"): TypeError: 'NoneType' object is not iterable 2022-02-02 20:45:54 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.9/site-packages/soco/events_asyncio.py", line 147, in notify subscription.send_event(event) File "/usr/local/lib/python3.9/site-packages/soco/events_base.py", line 596, in send_event callback(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 457, in async_dispatch_event dispatcher(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 704, in async_update_groups for vanished_device in zgs.find("VanishedDevices"): TypeError: 'NoneType' object is not iterable 2022-02-02 20:46:24 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.9/site-packages/soco/events_asyncio.py", line 147, in notify subscription.send_event(event) File "/usr/local/lib/python3.9/site-packages/soco/events_base.py", line 596, in send_event callback(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 457, in async_dispatch_event dispatcher(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 704, in async_update_groups for vanished_device in zgs.find("VanishedDevices"): TypeError: 'NoneType' object is not iterable 2022-02-02 20:47:09 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.9/site-packages/soco/events_asyncio.py", line 147, in notify subscription.send_event(event) File "/usr/local/lib/python3.9/site-packages/soco/events_base.py", line 596, in send_event callback(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 457, in async_dispatch_event dispatcher(event) File "/usr/src/homeassistant/homeassistant/components/sonos/speaker.py", line 704, in async_update_groups for vanished_device in zgs.find("VanishedDevices"): TypeError: 'NoneType' object is not iterable

emufan commented 2 years ago

Updates: Wanted to narrow down the problem and first use the 2021.12.10 sonos integtation as custom_component. Was not successfull. Is there now a hardcoded connection to plex? It only set up switches, etc. but no media_player anymore. Regardless if plex integration was enabled or disabled.

Unable to prepare setup for platform sonos.media_player: Platform not found (cannot import name 'play_on_sonos' from 'homeassistant.components.plex.services' (/usr/src/homeassistant/homeassistant/components/plex/services.py)).

Anyway. Stopped this try and went back completely to 2021.12.10. After reboot, the error messages are gone. So it is 100% not related to any change of my household or Sonos network and only to the update to 2022.2.0.

emufan commented 2 years ago

I am seeing similar error in the logs after upgrading to 2022.0.

Your errors are more related to this one: https://github.com/home-assistant/core/issues/65463

tdejneka commented 2 years ago

Not sure if this sheds any light but I never saw the following warning message in 2021.11.3 but after upgrading to 2021.12.10, just two days ago, I now see it for the first time:

Logger: homeassistant.components.sonos.speaker
Source: components/sonos/speaker.py:401
Integration: Sonos (documentation, issues)
First occurred: 10:36:24 (2 occurrences)
Last logged: 12:22:15

Subscription renewals for Office failed:

Either it's due to something having change between 2021.11 and 2021.12 or just a coincidence. Either way, it's there now and the only difference from emufan's warning message is it doesn't indicate why the subscription process failed.

jjlawren commented 2 years ago

@tdejneka are you also on S1 firmware?

emufan commented 2 years ago

Interesting, but in my case this is really only because of the direct update from the latest available version 2021.12.10 to the new today. There was nothing in between or changed and the message directly started every 18 minutes from the first start of 2022.2.0 and directly stopped of returning back to the last available version 2021.12.10.

Hopefully jjlawren can find these recent changes in the integration, which are resulting in these messages. Perhaps something, that is only refering to zp80/100 or something what is running exactly every 18 minutes.

jjlawren commented 2 years ago

Looking through the history, all of the code related to creating/renewing/cancelling subscriptions has been the same for 6+ months. No changes in SoCo either that should affect this. No obvious changes in aiohttp recently either, which is also involved here.

As for the delay, a subscription renewal period is 17 minutes (85% of 1200s). Since this is failing, perhaps there is some TCP timeout occurring which adds another minute to the observed time.

jjlawren commented 2 years ago

I've added more logging to uncover the empty error message during unsubscribe failures in 2022.2.1. This won't solve the problem here, but hopefully will give us a bit more context.

@tdejneka the empty error messages you're seeing during renewals will show the full traceback if you set the log level for homeassistant.components.sonos in debug.

tdejneka commented 2 years ago

on S1 firmware?

They're all S2 (Sonos One Gen 2, firmware version 14.0).

FWIW, I haven't seen another instance of that warning message today.

emufan commented 2 years ago

I've added more logging to uncover the empty error message during unsubscribe failures in 2022.2.1. This won't solve the problem here, but hopefully will give us a bit more context.

Today I did another try and wanted to double-check, where the problems might be.

Yesterday I did it twice .12 (no warnings/errors) -> .2.0 (warnings and errors above). Restore to .12 (no warnings/errors) -> again to .2.0 (same behavior as before)

So today I wanted to test again .2.x with the sonos integration from .12. But as yesterday you are not able to use it anymore

Unable to prepare setup for platform sonos.media_player: Platform not found (cannot import name 'play_on_sonos' from 'homeassistant.components.plex.services' (/usr/src/homeassistant/homeassistant/components/plex/services.py)).

Even with .12, removed sonos and removed plex -> .2.1, replace sonos and plex with .12-versions as custom components, restart, same behavior. So I had to stop this apporach.

Therefor again, restore to .12 (with enabled sonos, plex, etc., same starting point as yesteday) and directly update to .2.1 afterwards

And wtf, until now, 4 hours later, not a single warning or error message anymore, neither from this issues nor from the other. Nothing. So whatever happened in .2.1, it might be, that it automatically solved these issues.

So for now, I'll close and only re-open, if the messages re-appear. Thanks for your help anyway.

emufan commented 2 years ago

closed for now.

jjlawren commented 2 years ago

The Sonos devices themselves seemed to be behaving in very unexpected ways. Hopefully it was a fluke, but I don't yet have a good explanation for what would have put them in that odd state. Glad it's working normally again now.

Any chance you power cycled the devices during the troubleshooting process? Very rarely I've had that clear up strange unexplained behavior on my own speakers.

emufan commented 2 years ago

Any chance you power cycled the devices during the troubleshooting process? Very rarely I've had that clear up strange unexplained behavior on my own speakers.

No. Nothing happens. I swear 😉

For me it is still suspicious, that it only happened (reproducable) with one device class (ZP80/100) and there on both devices, whereas all other devices didn't show this behavior.

I cross fingers, that the messages don't come back.

tdejneka commented 2 years ago

FWIW, I got another one today:

Logger: homeassistant.components.sonos.speaker
Source: components/sonos/speaker.py:401
Integration: Sonos (documentation, issues)
First occurred: 11:26:59 (1 occurrences)
Last logged: 11:26:59

Subscription renewals for Office failed:

It's the same device as was reported previously but I don't know if that's meaningful. The Office Sonos is unremarkable; it's identical to all the others (hardware and firmware) and definitely not the farthest one from the Wi-Fi access point.

jjlawren commented 2 years ago

@tdejneka I'm 90% sure that's going to end up being a timeout error as that's the only exception I've consistently seen that doesn't pass along a printable message. That means that when it came time to renew the subscription, the speaker was simply unreachable or otherwise didn't respond to the request. If it came back online by itself, then at least the error handling is doing what it's supposed to be doing.

It doesn't fix your problem (I'm not sure what would at this point), but #66025 will clean up the message and reduce the severity to a warning as it's not truly an error condition--the integration just encountered something unexpected and will try again.