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.55k stars 30.35k forks source link

Sonos group data missing after Core restart. #55008

Closed dof250 closed 3 years ago

dof250 commented 3 years ago

The problem

Whenever i'm restarting Home Assistant Core the previous group data gets lost.

For me it's pretty easy to reproduce. Play sound in one room, then join another room. When looking at "data -> attributes -> sonos_group" it contains the speakers. Then restart Core and look at that data again. Now the sonos_group attribute is empty.

This messes up my automations with automatic grouping and leaving.

What is version of Home Assistant Core has the issue?

core-2021.8

What was the last working version of Home Assistant Core?

core-2021.7

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?

No response

Additional information

No response

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)

sonos documentation sonos source (message by IssueLinks)

jjlawren commented 3 years ago

This should already be resolved in 2021.8.1+ (https://github.com/home-assistant/core/pull/53985). What specific version are you running?

dof250 commented 3 years ago

That’s strange. I’m running 2021.8.8.

jjlawren commented 3 years ago

Do you have warnings/errors in your logs during the first ~1m after startup for the Sonos integration?

dof250 commented 3 years ago

I'm getting one error after the restart I just did, but i don't think its relevant. See below: 2021-08-22 16:06:48 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending! Below some debug logging. Maybe its usefull for you? https://pastebin.com/L04cSKdc

jjlawren commented 3 years ago

All looks normal at first glance. I see 5 speakers each in a group by themselves. Is this not what you're expecting or seeing reflected in the state attributes?

dof250 commented 3 years ago

Sorry, tested it a little stupid. They where not grouped before Core restart. Dumb mistake from me. Now i've group "Badkamer" with "Kantoor" and did a Core restart. The group data is again lost with the restart. Below the logs: https://pastebin.com/XR7LQ6HE

jjlawren commented 3 years ago

I cannot reproduce that behavior. All groups remain in place after restarts.

Any chance you have automations that regroup speakers?

dof250 commented 3 years ago

Nope, no automations are run on start. I can reproduce as follows.

  1. Group "Badkamer" with "Kantoor" and start playing some music
  2. "Developer Tools -> States -> media_player.kantoor"
  3. sonos_group:
    • media_player.badkamer
    • media_player.kantoor
  4. "Developer Tools -> States -> media_player.badkamer"
  5. sonos_group:
    • media_player.badkamer
    • media_player.kantoor
  6. Restart Core (music still playing)
  7. "Developer Tools -> States -> media_player.kantoor"
  8. sonos_group: []
  9. "Developer Tools -> States -> media_player.badkamer"
  10. sonos_group:
    • media_player.badkamer

So "Kantoor" shows just empty, while "Badkamer" shows only itself. When I remove them from the group and add them again its working as expected. and shows again: sonos_group:

jjlawren commented 3 years ago

I still can't reproduce when speakers are either idle or playing. Anything else that might be unique in your setup?

dof250 commented 3 years ago

Not that I can think off. All my automations are in Node-Red so I tried to disable Node-Red completely and still gives me the same issue. I've restarted 8 times in a row now. Every other restart the data is there...

  1. no group data
  2. group data
  3. no group data
  4. group data
  5. no group data
  6. group data
  7. no group data
  8. group data

Doesn't make any sense...

jjlawren commented 3 years ago

I believe there's a race condition on startup if the coordinator is available and the grouped speakers are not when the groups are initially built. Will need to look more later.

jjlawren commented 3 years ago

@dof250 are you able to test a potential fix using a custom component? I still cannot reproduce the problem you're experiencing.

cd /config/custom_components
git clone --branch core-55008 https://github.com/jjlawren/sonos_custom_component.git sonos
dof250 commented 3 years ago

Just tried this with below results after core restarts.

  1. no group data
  2. group data
  3. no group data
  4. group data
  5. Entered the commands above
  6. group data
  7. group data
  8. no group data
  9. group data
  10. group data
  11. no group data
  12. group data
  13. group data
  14. group data
  15. group data
  16. no group data

So it seems a bit better, but still some times it's not filled... Don't know if this makes any sense to you.

jjlawren commented 3 years ago

Can you please ensure the custom component is loading properly in the logs?

Do you see the "Regrouped : [...]" log messages for each speaker?

dof250 commented 3 years ago

Below the latest logs, says it found a custom integration sonos. I do get a lot of the "Error doing job" errors now. Don't know if this has to do with the custom component?

2021-08-23 22:25:44 WARNING (SyncWorker_4) [homeassistant.loader] We found a custom integration sonos which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant 2021-08-23 22:25:44 WARNING (MainThread) [homeassistant.config] Key whitelist_external_dirs has been replaced with allowlist_external_dirs. Please update your config 2021-08-23 22:25:45 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140554601461552] Received invalid command: energy/info 2021-08-23 22:25:48 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Thuis' for forecast_solar integration not ready yet: Rate limit for API calls reached. (error None); Retrying in background 2021-08-23 22:25:48 ERROR (MainThread) [homeassistant] Error doing job: Unclosed client session 2021-08-23 22:25:48 ERROR (MainThread) [homeassistant] Error doing job: Unclosed connector 2021-08-23 22:25:50 WARNING (MainThread) [homeassistant.components.select] Platform netatmo not ready yet: None; Retrying in background in 30 seconds 2021-08-23 22:25:51 WARNING (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for None (192.168.10.118): Error connecting to ('192.168.10.118', 6053): [Errno 113] Connect call failed ('192.168.10.118', 6053) 2021-08-23 22:25:52 WARNING (MainThread) [homeassistant.components.webhook] Received message for unregistered webhook 9b0e5682f2fe3159433c7612cb205b2afb8ed0146e6777ea8b0d707bf18e7eef from 192.168.1.40 2021-08-23 22:26:02 ERROR (SyncWorker_7) [homeassistant] Error doing job: Unclosed client session 2021-08-23 22:26:02 ERROR (SyncWorker_7) [homeassistant] Error doing job: Unclosed connector

jjlawren commented 3 years ago

Those errors are not related to using the custom component. Do you see the "Regrouped" debug messages after startup? Some were missing before.

dof250 commented 3 years ago

I don't see any debug logging for the sonos integration anymore. Should I edit my logger config now it's using the custom component? Below is what's configured now.

logger: default: warning logs: homeassistant.components.sonos: debug pysonos: debug

jjlawren commented 3 years ago

Ah yes, you'll need to add custom_components.sonos: debug

dof250 commented 3 years ago

I've created two logs. This is the one where group data is filled correctly: https://pastebin.com/DtzfNk0v

And this is the one where it's empty: https://pastebin.com/AcAN5T9T

jjlawren commented 3 years ago

While I think about this I added some more debug. You can update the custom component like this:

cd /config/custom_components/sonos
git pull

If you can reproduce the problem and share logs maybe something will jump out.

dof250 commented 3 years ago

This is the working one: https://pastebin.com/c5qsjj5t

And this is the non working: https://pastebin.com/pmzZ9kF0

jjlawren commented 3 years ago

Okay, confirms the theory. Now just need to find a clean way to address it.

jjlawren commented 3 years ago

Pushed a potential fix, but I want to think about this a bit more even if it works.

dof250 commented 3 years ago

Did a git pull and around 10 core restarts. Every time the group data is filled now so thats great! I do however see a difference in restarts. Whenever it does a "good" restart. ALL data is filled. So I also see current playing song, position etcetera. Sometimes that data is missing, but whenever thats the case it now does include the group data. So my particular issue is solved, but maybe its some usefull information to you. This is the log when that data is missing: https://pastebin.com/cF8SYCzt

jjlawren commented 3 years ago

Is the group data accurate, though? For example, the latest logs imply that Kantoor's group is updated properly to['media_player.badkamer', 'media_player.kantoor'] but Badkamer's group remains as ['media_player.badkamer'].

jjlawren commented 3 years ago

I was able to reproduce the issue with more complex groups. The custom component now has a different approach which seems more reliable. Can you give it another shot?

dof250 commented 3 years ago

Just tried again. Did 10 Core restarts and every time all data was filled correctly. Tried multiple group configurations and everything worked every time.

jjlawren commented 3 years ago

Submitted a fix to core, thanks for reporting and providing so much helpful context and information. 👍