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.65k stars 30.41k forks source link

Sonos does not update state or attributes #61909

Closed crlogic closed 2 years ago

crlogic commented 2 years ago

The problem

Sonos has stopped updating media_player state/attributes this past week. Both HA & Sonos firmware have updated therefore cause is less clear.

Problem statement: HA only retrieves correct Sonos player attributes on core restart. After core restart, attributes no longer update. State never reflects correctly on boot or after boot; remains at 'idle'.

Observations: a restart of HA always correctly retrieves attributes, but not state. HA can control the players just fine, but state/attributes never reflect the changes made.

What version of Home Assistant Core has the issue?

2021.12.1

What was the last working version of Home Assistant Core?

2021.11.5

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

N/A

Anything in the logs that might be useful for us?

I enabled debug logging and didn't see much.

2021-12-15 10:32:17 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-15 10:32:17 DEBUG (MainThread) [homeassistant.components.sonos] Reached async_setup_entry, config=OrderedDict([('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.setup] Setting up media_player
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-15 10:32:17 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-15 10:32:18 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-15 10:32:18 INFO (MainThread) [homeassistant.components.number] Setting up number.sonos
2021-12-15 10:32:18 DEBUG (MainThread) [homeassistant.components.sonos] Adding discovery job
2021-12-15 10:32:18 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-15 10:32:18 DEBUG (SyncWorker_3) [homeassistant.components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-15 10:32:19 DEBUG (SyncWorker_3) [homeassistant.components.sonos.favorites] Processing favorites update_id 7 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-15 10:32:19 DEBUG (SyncWorker_3) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-15 10:32:19 INFO (MainThread) [homeassistant.setup] Setup of domain default_config took 0.6 seconds
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-15 10:32:19 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-15 10:32:19 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-15 10:32:19 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-15 10:32:20 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Subwoofer Enabled switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Surround Enabled switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-15 10:32:20 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-15 10:32:20 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bedroom Sonos

Additional information

I use HA to "volume match" players in a group using the volume_level attribute. This no longer works. The automation is not needed to reproduce the issue. Just using the Sonos app to change volume does not reflect in HA. This can be reproduced on demand.

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

sonos documentation sonos source (message by IssueLinks)

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)

jjlawren commented 2 years ago

After start is completed, do you see any Sonos warnings in your logs that say "...falling back to polling, functionality may be limited"?

Can you enable debug for the Sonos integration to see what's happening when it appears idle? You can use the logger.set_level service during runtime, but having it enabled at startup would be best. Add this to your config and restart:

logger:
  logs:
    homeassistant.components.sonos: debug

Edit: Saw that you did enable debug. Please leave it running for a bit longer so we can get more context.

jjlawren commented 2 years ago

Since you're not seeing any "Activity on Kitchen Sonos from ..." debug messages, I have to assume that the subscription callbacks from the speakers are not reaching HA.

Did you make any networking changes in the past week? Do you have multiple subnets, local firewall restrictions, etc?

crlogic commented 2 years ago

After start is completed, do you see any Sonos warnings in your logs that say "...falling back to polling, functionality may be limited"?

None noted. If you have test-scenario's which may be helpful, I am all ears.

Edit: Saw that you did enable debug. Please leave it running for a bit longer so we can get more context.

It seems odd that when HA is used to change the volume, the volume_level attribute doesn't change nor a log event generated. I will leave it debug enabled in case this changes.

crlogic commented 2 years ago

Since you're not seeing any "Activity on Kitchen Sonos from ..." debug messages, I have to assume that the subscription callbacks from the speakers are not reaching HA.

This seems like a fair assumption. Router uptime is 172 days, I suppose a reboot wouldn't hurt for the purposes of validating potential influence. Will be back in 20..

Did you make any networking changes in the past week? Do you have multiple subnets, local firewall restrictions, etc?

AP firmware updates yes. But TV/Kitchen/Bath/etc are on Sonosnet.

Multiple subnets. Yes. No changes in 3 years. No FW b/t HA & Sonos VLAN's.

crlogic commented 2 years ago

Router reboot completed and restarted HA core after that. No change in behavior.

tcpdump on router between HA & Sonos Beam shows bi-directional traffic when performing a volume change initiated from HA. The Sonos app shows the volume change, the sound gets louder, HA does not reflect status.

11:39:58.787830 IP (tos 0x0, ttl 64, id 52432, offset 0, flags [DF], proto TCP (6), length 52)
    hassio.lab.home.48802 > 192.168.6.21.1400: Flags [.], cksum 0x70c8 (correct), seq 1, ack 1, win 502, options [nop,nop,TS val 81976597 ecr 6921126], length 0
11:39:58.787899 IP (tos 0x0, ttl 64, id 52433, offset 0, flags [DF], proto TCP (6), length 364)
    hassio.lab.home.48802 > 192.168.6.21.1400: Flags [P.], cksum 0xb13f (correct), seq 1:313, ack 1, win 502, options [nop,nop,TS val 81976597 ecr 6921126], length 312
11:39:58.787941 IP (tos 0x0, ttl 64, id 52434, offset 0, flags [DF], proto TCP (6), length 316)
    hassio.lab.home.48802 > 192.168.6.21.1400: Flags [P.], cksum 0x456e (correct), seq 313:577, ack 1, win 502, options [nop,nop,TS val 81976597 ecr 6921126], length 264
11:39:58.789073 IP (tos 0x0, ttl 63, id 30755, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.6.21.1400 > hassio.lab.home.48802: Flags [.], cksum 0x709b (correct), seq 1, ack 313, win 235, options [nop,nop,TS val 6921126 ecr 81976597], length 0
11:39:58.789375 IP (tos 0x0, ttl 63, id 30756, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.6.21.1400 > hassio.lab.home.48802: Flags [.], cksum 0x6f8b (correct), seq 1, ack 577, win 243, options [nop,nop,TS val 6921126 ecr 81976597], length 0
11:39:58.791086 IP (tos 0x0, ttl 63, id 30757, offset 0, flags [DF], proto TCP (6), length 881)
    192.168.6.21.1400 > hassio.lab.home.48802: Flags [P.], cksum 0xd92d (correct), seq 1:830, ack 577, win 243, options [nop,nop,TS val 6921126 ecr 81976597], length 829
11:39:58.791233 IP (tos 0x0, ttl 64, id 52435, offset 0, flags [DF], proto TCP (6), length 52)
    hassio.lab.home.48802 > 192.168.6.21.1400: Flags [.], cksum 0x6b49 (correct), seq 577, ack 830, win 501, options [nop,nop,TS val 81976600 ecr 6921126], length 0
11:39:58.791316 IP (tos 0x0, ttl 63, id 30758, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.6.21.1400 > hassio.lab.home.48802: Flags [F.], cksum 0x6c4c (correct), seq 830, ack 577, win 243, options [nop,nop,TS val 6921127 ecr 81976597], length 0
11:39:58.791885 IP (tos 0x0, ttl 64, id 52436, offset 0, flags [DF], proto TCP (6), length 52)
    hassio.lab.home.48802 > 192.168.6.21.1400: Flags [F.], cksum 0x6b45 (correct), seq 577, ack 831, win 501, options [nop,nop,TS val 81976601 ecr 6921127], length 0
11:39:58.792564 IP (tos 0x0, ttl 63, id 30759, offset 0, flags [DF], proto TCP (6), length 52)
    192.168.6.21.1400 > hassio.lab.home.48802: Flags [.], cksum 0x6c47 (correct), seq 831, ack 578, win 243, options [nop,nop,TS val 6921127 ecr 81976601], length 0
11:40:28.787244 IP (tos 0x0, ttl 64, id 1746, offset 0, flags [DF], proto TCP (6), length 60)
    hassio.lab.home.48838 > 192.168.6.21.1400: Flags [S], cksum 0x0d4f (correct), seq 753299374, win 64240, options [mss 1460,sackOK,TS val 82006596 ecr 0,nop,wscale 7], length 0
11:40:28.800081 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto TCP (6), length 60)
    192.168.6.21.1400 > hassio.lab.home.48838: Flags [S.], cksum 0x6f81 (correct), seq 2210790398, ack 753299375, win 28960, options [mss 1460,sackOK,TS val 6924127 ecr 82006596,nop,wscale 7], length 0

[edit] spelling

crlogic commented 2 years ago

I have reverted to 2021.11.5 and it works as expected. Any change in volume from TV remote or Sonos app is immediately reflected in HA.

What I also didn't notice is that the attribute list in 2021.12.1 is vastly reduced compared to 11.5.

This is the attribute list from 11.5, will post 12.1 after re-upgrading..

volume_level: 0.27
is_volume_muted: false
media_content_id: >-
  x-sonos-spotify:spotify%3atrack%3a5i9p3CcMiWm3yF1aTba1k2?sid=12&flags=8224&sn=21
media_content_type: music
media_duration: 156
media_position: 0
media_position_updated_at: '2021-12-15T16:48:40.720067+00:00'
media_title: Keep It Real Dumb
media_artist: Death From Above 1979
media_album_name: Keep It Real Dumb
media_playlist: Rock Mix
shuffle: false
repeat: 'off'
sonos_group:
  - media_player.tv_sonos
  - media_player.kitchen_sonos
  - media_player.bedroom_sonos
  - media_player.bathroom_sonos
bass_level: -8
treble_level: -1
queue_position: 4
friendly_name: TV Sonos
entity_picture: >-
  /api/media_player_proxy/media_player.tv_sonos?token=2c0abcfcf152119df486266648571433658c59e0529fb500e55e7cd76fcc61c9&cache=3e7bdb258e5fccff
supported_features: 457279
crlogic commented 2 years ago

Back on 12.1 and it doesn't work. Here are the attributes. Suspect the reduced attributes is expected behavior when status updates are not working?

volume_level: 0.27
is_volume_muted: false
media_content_type: music
shuffle: false
repeat: 'off'
sonos_group: []
friendly_name: TV Sonos
supported_features: 457279
jjlawren commented 2 years ago

Suspect the reduced attributes is expected behavior when status updates are not working?

Correct.

Can you leave debug on after startup is completed on 2021.12.X? You should be seeing some additional activity after what you originally posted to show if it's updating with subscriptions or polling, but it may take a few extra seconds.

If we're still not seeing anything, you may be hitting some hidden uncaught exception but I don't have any ideas on what that could be yet.

crlogic commented 2 years ago

Can you leave debug on after startup is completed on 2021.12.X? You should be seeing some additional activity after what you originally posted to show if it's updating with subscriptions or polling, but it may take a few extra seconds.

If we're still not seeing anything, you may be hitting some hidden uncaught exception but I don't have any ideas on what that could be yet.

Been up for 22 minutes and listening to music, changing volume. Here is what it has generated..

[core-ssh config]$ cat home-assistant.log | grep sonos > home-assistant-sonos.log
[core-ssh config]$ cat home-assistant-sonos.log
2021-12-15 11:54:05 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'hacs', 'scene', 'input_text', 'input_datetime', 'zeroconf', 'default_config', 'sensor', 'template', 'esphome', 'logbook', 'openweathermap', 'group', 'updater', 'unifi', 'input_number', 'sun', 'notify', 'blueprint', 'mobile_app', 'binary_sensor', 'zone', 'ssdp', 'map', 'dhcp', 'media_source', 'timer', 'history', 'system_health', 'input_select', 'mqtt', 'energy', 'input_boolean', 'trace', 'my', 'zha', 'sonos', 'shelly', 'script', 'tasmota', 'tag', 'switch', 'network', 'usb', 'persistent_notification', 'automation', 'scheduler', 'broadlink', 'light', 'tts', 'climate', 'counter'}
2021-12-15 11:54:07 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-15 11:54:07 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-15 11:54:07 DEBUG (MainThread) [homeassistant.components.sonos] Reached async_setup_entry, config=OrderedDict([('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-15 11:54:08 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-15 11:54:08 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-15 11:54:08 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-15 11:54:08 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-15 11:54:08 INFO (MainThread) [homeassistant.components.number] Setting up number.sonos
2021-12-15 11:54:08 DEBUG (MainThread) [homeassistant.components.sonos] Adding discovery job
2021-12-15 11:54:08 DEBUG (SyncWorker_5) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-15 11:54:08 DEBUG (SyncWorker_5) [homeassistant.components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-15 11:54:09 DEBUG (SyncWorker_5) [homeassistant.components.sonos.favorites] Processing favorites update_id 7 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-15 11:54:09 DEBUG (SyncWorker_5) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-15 11:54:10 DEBUG (SyncWorker_5) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-15 11:54:10 DEBUG (SyncWorker_5) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-15 11:54:10 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-15 11:54:10 DEBUG (SyncWorker_5) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Subwoofer Enabled switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Surround Enabled switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-15 11:54:11 DEBUG (SyncWorker_5) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-15 11:54:11 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bedroom Sonos
2021-12-15 11:54:12 INFO (MainThread) [homeassistant.components.automation.kitchen_sonos_mute_motion_end] Initialized trigger [MOTION END] Kitchen Sonos MUTE
2021-12-15 11:54:12 INFO (MainThread) [homeassistant.components.automation.sonos_boys_room_should_be_state] Initialized trigger SCHEDULE Boys Room Sonos
[core-ssh config]$
jjlawren commented 2 years ago

That's very odd. No subscription callbacks and no polling activity. Something must be silently failing somewhere.

Would you be willing to run sonos in debug on 2021.11.5 for comparison since things are working well there? We would at least be able to validate if you're receiving callbacks in your network setup. You should see one of these two messages:

  1. "Received event, cancelling poll timer for ..."
  2. "... falling back to polling, functionality may be limited"
crlogic commented 2 years ago

That's very odd. No subscription callbacks and no polling activity. Something must be silently failing somewhere.

Would you be willing to run sonos in debug on 2021.11.5 for comparison since things are working well there? We would at least be able to validate if you're receiving callbacks in your network setup. You should see one of these two messages:

  1. "Received event, cancelling poll timer for ..."
  2. "... falling back to polling, functionality may be limited"

Definitely willing to contribute. Love the work you have done and consider it hugely useful. Rolling back now..

crlogic commented 2 years ago

Sonos debug log after 10 minute HA core uptime.

[core-ssh config]$ cat home-aha core info
arch: amd64
audio_input: None
audio_output: None
boot: true
image: ghcr.io/home-assistant/qemux86-64-homeassistant
ip_address: 172.30.32.1
last_version: 2021.12.1
machine: qemux86-64
port: 8123
ssl: false
update_available: true
version: 2021.11.5
version_latest: 2021.12.1
wait_boot: 600
watchdog: true
[core-ssh config]$ cat home-assistant.log | grep sonos > home-assistant-sonos-11.5.log
[core-ssh config]$ cat home-assistant-sonos-11.5.log
2021-12-15 12:33:20 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'map', 'media_source', 'input_select', 'tasmota', 'notify', 'shelly', 'light', 'sensor', 'openweathermap', 'usb', 'scene', 'input_number', 'blueprint', 'mobile_app', 'zha', 'network', 'energy', 'updater', 'sonos', 'sun', 'default_config', 'timer', 'template', 'zeroconf', 'dhcp', 'broadlink', 'script', 'mqtt', 'tts', 'group', 'system_health', 'history', 'logbook', 'automation', 'hacs', 'input_text', 'esphome', 'trace', 'unifi', 'persistent_notification', 'zone', 'binary_sensor', 'ssdp', 'counter', 'climate', 'scheduler', 'switch', 'my', 'input_datetime', 'tag', 'input_boolean'}
2021-12-15 12:33:29 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-15 12:33:29 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-15 12:33:30 DEBUG (MainThread) [homeassistant.components.sonos] Reached async_setup_entry, config=OrderedDict([('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-15 12:33:30 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-15 12:33:30 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-15 12:33:30 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-15 12:33:30 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-15 12:33:30 DEBUG (MainThread) [homeassistant.components.sonos] Adding discovery job
2021-12-15 12:33:30 DEBUG (SyncWorker_6) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-15 12:33:30 DEBUG (SyncWorker_6) [homeassistant.components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-15 12:33:31 DEBUG (SyncWorker_6) [homeassistant.components.sonos.favorites] Processing favorites update_id 7 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-15 12:33:31 DEBUG (SyncWorker_6) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Kitchen Sonos [192.168.6.24] was not available, setting up
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for Kitchen Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-15 12:33:31 DEBUG (SyncWorker_6) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for Kitchen Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Bathroom Sonos [192.168.6.27] was not available, setting up
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for Bathroom Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-15 12:33:31 DEBUG (SyncWorker_6) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] TV Sonos [192.168.6.21] was not available, setting up
2021-12-15 12:33:31 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for TV Sonos
2021-12-15 12:33:32 DEBUG (SyncWorker_6) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for TV Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] TV Sonos group member unavailable (RINCON_000E58C29D2801400), will try again
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Regrouped TV Sonos: ['media_player.tv_sonos', 'media_player.bathroom_sonos', 'media_player.kitchen_sonos']
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for Bathroom Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.favorites] New favorites event 344 from <SoCo object at ip 192.168.6.27> (was None)
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-15 12:33:32 DEBUG (SyncWorker_6) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-15 12:33:32 DEBUG (SyncWorker_2) [homeassistant.components.sonos.speaker] Bedroom Sonos was missing, adding to TV Sonos group
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Bedroom Sonos [192.168.6.28] was not available, setting up
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Creating subscriptions for Bedroom Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Regrouped TV Sonos: ['media_player.tv_sonos', 'media_player.bedroom_sonos', 'media_player.bathroom_sonos', 'media_player.kitchen_sonos']
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bedroom Sonos
2021-12-15 12:33:32 DEBUG (SyncWorker_4) [homeassistant.components.sonos.favorites] Processing favorites update_id 6 for <SoCo object at ip 192.168.6.27> (was: None)
2021-12-15 12:33:32 DEBUG (SyncWorker_4) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.27>
2021-12-15 12:33:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Received event, cancelling poll timer for Bedroom Sonos
2021-12-15 12:33:33 INFO (MainThread) [homeassistant.components.automation.kitchen_sonos_mute_motion_end] Initialized trigger [MOTION END] Kitchen Sonos MUTE
2021-12-15 12:33:33 INFO (MainThread) [homeassistant.components.automation.sonos_boys_room_should_be_state] Initialized trigger SCHEDULE Boys Room Sonos
2021-12-15 12:34:32 DEBUG (MainThread) [homeassistant.components.sonos.speaker] Boys Room Sonos [192.168.6.22] was not available, setting up
[core-ssh config]$

Should be noted. My Sonos Beam has surrounds and sub which are both currently poweredoff using smart plugs. Sorry if I forgot to mention this earlier. Only turn them on for movies and it was not a problem in the past. I know HA switches for these were introduced in 12.1 so maybe that has an influence?

crlogic commented 2 years ago

Should be noted. My Sonos Beam has surrounds and sub which are both currently poweredoff using smart plugs. Sorry if I forgot to mention this earlier. Only turn them on for movies and it was not a problem in the past. I know HA switches for these were introduced in 12.1 so maybe that has an influence?

Answering my own question here. I turned on the smart plug for the sub and surrounds. Upgraded to 12.1. Same behavior in 12.1.

crlogic commented 2 years ago

Here is 12.0 logs if needed

[core-ssh config]$ ha core info
arch: amd64
audio_input: None
audio_output: None
boot: true
image: ghcr.io/home-assistant/qemux86-64-homeassistant
ip_address: 172.30.32.1
last_version: 2021.12.2
machine: qemux86-64
port: 8123
ssl: false
update_available: true
version: 2021.12.0
version_latest: 2021.12.2
wait_boot: 600
watchdog: true
[core-ssh config]$ cat home-assistant.log | grep sonos > home-assistant-sonos-12.0.log
[core-ssh config]$ cat home-assistant-sonos-12.0.log
2021-12-15 12:53:34 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'input_select', 'trace', 'ssdp', 'tts', 'updater', 'climate', 'input_datetime', 'zeroconf', 'timer', 'automation', 'script', 'logbook', 'tasmota', 'mqtt', 'scheduler', 'sonos', 'esphome', 'input_boolean', 'my', 'scene', 'shelly', 'openweathermap', 'tag', 'unifi', 'network', 'persistent_notification', 'history', 'mobile_app', 'broadlink', 'default_config', 'zone', 'binary_sensor', 'input_number', 'energy', 'dhcp', 'zha', 'template', 'sun', 'system_health', 'notify', 'hacs', 'counter', 'input_text', 'sensor', 'group', 'map', 'light', 'blueprint', 'media_source', 'switch', 'usb'}
2021-12-15 12:53:35 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-15 12:53:35 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-15 12:53:35 DEBUG (MainThread) [homeassistant.components.sonos] Reached async_setup_entry, config=OrderedDict([('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-15 12:53:36 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-15 12:53:36 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-15 12:53:36 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-15 12:53:36 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-15 12:53:36 INFO (MainThread) [homeassistant.components.number] Setting up number.sonos
2021-12-15 12:53:36 DEBUG (MainThread) [homeassistant.components.sonos] Adding discovery job
2021-12-15 12:53:36 DEBUG (SyncWorker_2) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-15 12:53:36 DEBUG (SyncWorker_2) [homeassistant.components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos.favorites] Processing favorites update_id 7 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Subwoofer Enabled switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Surround Enabled switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-15 12:53:37 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-15 12:53:37 DEBUG (SyncWorker_2) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-15 12:53:38 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-15 12:53:38 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-15 12:53:38 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-15 12:53:38 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bedroom Sonos
2021-12-15 12:53:38 INFO (MainThread) [homeassistant.components.automation.kitchen_sonos_mute_motion_end] Initialized trigger [MOTION END] Kitchen Sonos MUTE
2021-12-15 12:53:38 INFO (MainThread) [homeassistant.components.automation.sonos_boys_room_should_be_state] Initialized trigger SCHEDULE Boys Room Sonos
[core-ssh config]$
jjlawren commented 2 years ago

I think we'll need to get more creative here. Enabling asyncio debug will hopefully give us a hint. Easiest way to do this is to add a line with debugpy: to your config (https://www.home-assistant.io/integrations/debugpy/). Once you restart it'll get a bit noisy but hopefully it will show something regarding sonos that we haven't seen yet.

crlogic commented 2 years ago

Roger that, I'll update to 2021.12.x and add debugpy: to configuration.yaml.

crlogic commented 2 years ago

debugpy: added and restarted core. Lots of other things flying by in the logs, want me drop the | grep sonos?

[core-ssh config]$ ha core info
arch: amd64
audio_input: None
audio_output: None
boot: true
image: ghcr.io/home-assistant/qemux86-64-homeassistant
ip_address: 172.30.32.1
last_version: 2021.12.2
machine: qemux86-64
port: 8123
ssl: false
update_available: false
version: 2021.12.2
version_latest: 2021.12.2
wait_boot: 600
watchdog: true
[core-ssh config]$ cat home-assistant.log | grep sonos
2021-12-15 17:41:27 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'input_text', 'blueprint', 'usb', 'tag', 'unifi', 'trace', 'input_number', 'mobile_app', 'default_config', 'ssdp', 'energy', 'esphome', 'tts', 'shelly', 'zha', 'input_select', 'openweathermap', 'tasmota', 'media_source', 'mqtt', 'counter', 'sun', 'sensor', 'scheduler', 'logbook', 'my', 'zeroconf', 'dhcp', 'automation', 'switch', 'map', 'zone', 'script', 'broadlink', 'timer', 'sonos', 'updater', 'template', 'notify', 'hacs', 'group', 'binary_sensor', 'input_boolean', 'history', 'persistent_notification', 'system_health', 'network', 'climate', 'light', 'scene', 'input_datetime'}
2021-12-15 17:41:37 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-15 17:41:37 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-15 17:41:38 DEBUG (MainThread) [homeassistant.components.sonos] Reached async_setup_entry, config=OrderedDict([('advertise_addr', '192.168.0.96'), ('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-15 17:41:38 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-15 17:41:38 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-15 17:41:38 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-15 17:41:38 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-15 17:41:38 INFO (MainThread) [homeassistant.components.number] Setting up number.sonos
2021-12-15 17:41:39 DEBUG (MainThread) [homeassistant.components.sonos] Adding discovery job
2021-12-15 17:41:39 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-15 17:41:39 DEBUG (SyncWorker_3) [homeassistant.components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-15 17:41:39 DEBUG (SyncWorker_3) [homeassistant.components.sonos.favorites] Processing favorites update_id 9 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-15 17:41:39 DEBUG (SyncWorker_3) [homeassistant.components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-15 17:41:40 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-15 17:41:41 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-15 17:41:41 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-15 17:41:41 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Subwoofer Enabled switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Surround Enabled switch on TV Sonos
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-15 17:41:42 DEBUG (SyncWorker_3) [homeassistant.components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-15 17:41:42 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-15 17:41:43 DEBUG (MainThread) [homeassistant.components.sonos.switch] Creating Status Light switch on Bedroom Sonos
2021-12-15 17:41:52 INFO (MainThread) [homeassistant.components.automation.kitchen_sonos_mute_motion_end] Initialized trigger [MOTION END] Kitchen Sonos MUTE
2021-12-15 17:41:52 INFO (MainThread) [homeassistant.components.automation.sonos_boys_room_should_be_state] Initialized trigger SCHEDULE Boys Room Sonos
crlogic commented 2 years ago

Brainstorming here.. ..and went through the very busy sonos integration changes for 2021.12.

Thoughts testing a branch w/ #60642 & #59994 reverted?

Completely wild speculation on my part.

danoc commented 2 years ago

Just wanted to add that I'm also able to reproduce this issue too. All Sonos devices appear as "Idle." I'm able to change the volume of speakers through Home Assistant, but the updated volume is not then reflected in the state/attributes. I appreciate all of the debugging you two have done. 🙇‍♂️

Edit: Also confirmed that the problem doesn't appear in 2021.11.5.

crlogic commented 2 years ago

Thanks for confirming! Exactly what I am seeing.

On Thu, Dec 16, 2021, 7:22 PM Daniel O’Connor @.***> wrote:

Just wanted to add that I'm also able to reproduce this issue too. All Sonos devices appear as "Idle." I'm able to change the volume of speakers through Home Assistant, but the updated volume is not then reflected in the state/attributes. I appreciate all of the debugging you two have done. 🙇‍♂️

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/61909#issuecomment-996302793, or unsubscribe https://github.com/notifications/unsubscribe-auth/AASNI42KJWXJUL7RD3JC4EDURJ7DJANCNFSM5KD77BWA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>

crlogic commented 2 years ago

I have managed to bumble my way through forking home-assistant/core and reverting #59994 as it seems(maybe?) the most likely candidate for me as I use hard-coded player entries in configuration.yaml.

I am stuck on figuring out how to get my Home Assistant OS to use this repo/branch to test it out. Direction welcome. Have tried playing w/ ha supervisor options -r https://github.com/crlogic/home-assistant.git with no success.

danoc commented 2 years ago

I have managed to bumble my way through forking home-assistant/core and reverting #59994 as it seems(maybe?) the most likely candidate for me as I use hard-coded player entries in configuration.yaml.

I am stuck on figuring out how to get my Home Assistant OS to use this repo/branch to test it out. Direction welcome. Have tried playing w/ ha supervisor options -r https://github.com/crlogic/home-assistant.git with no success.

For what it's worth I don't have any media_player or Sonos related things in configuration.yaml and am able to reproduce the issue.

jjlawren commented 2 years ago

That seems like a possible candidate cause, but it only seems to affect specific setups and is not a general issue affecting most.

Can anyone having this issue please share environment-specific details like:

jjlawren commented 2 years ago

@crlogic if you're willing to test I'd suggest to use the custom component method instead: https://developers.home-assistant.io/docs/creating_integration_file_structure/#where-home-assistant-looks-for-integrations

When I get some time I'll update my Sonos custom component repo to gather more info. Apologies as I'm not able to do that immediately.

crlogic commented 2 years ago

Can anyone having this issue please share environment-specific details like:

When I get some time I'll update my Sonos custom component repo to gather more info. Apologies as I'm not able to do that immediately.

Thank you for the link. I was trying to learn. Go have a weekend!

crlogic commented 2 years ago

Any other details that may be relevant

Oh snap, interesting development. While trying to figure out how to get my custom_components "reverted version" working. I turn on the power to all my Sonos players and upgraded to 12.3 using the stock Sonos integration. All my Sonos automations worked because media_player state was updating correctly!

Curious to this new development, I turned off the smart plug controlling surrounds for my Beam. Then I reloaded core. This caused the Sonos integration to break again, no more state updates, therefore no Sonos automations.

I turned the surrounds smart plug back on and reloaded core again but it was still broken, state no longer updates.

I supposed that other relevant detail is that I have surrounds, sub, and three other players on various smart plugs to save power. They turn on/off based on a schedule and it has not caused a problem for the Sonos integration up to version 11.5.

So testing should include a host in yaml configuration with at least one of those players unavailable.

crlogic commented 2 years ago

I have forked and reverted #60642 & #59994 and tested each individually to no success on 12.3. But take that with a grain of salt since I was guessing wildly hoping for a hail mary.

wmn79 commented 2 years ago

Not sure if it is related, but I also had issues with Sonos component after upgrade to 2021.12.0. First got an import error after the upgrade to 12.0. When I removed the component and tried to reinstall I got config flow could not be loaded and in the log I then saw this:

Logger: homeassistant.config_entries Source: config_entries.py:720 First occurred: 9:58:25 AM (4 occurrences) Last logged: 9:58:25 AM

Error occurred loading configuration flow for integration sonos: No module named 'aiodiscover'

Solved it by manually installing both aiodiscover and scapy. There are more people with this issue not only with the Sonos component but more with DHCP related components, these are mentioned in issue #61775.

jjlawren commented 2 years ago

Okay, I have a theory on what's breaking but I'm not completely sure on what's causing it yet. I've updated my custom_component repo with a copy of 2021.12.3 and added some debug logging. You can see what's been added here.

To install the custom component, you can clone the repo directly into your config (make sure to delete any existing sonos directory in your custom_component directory first!):

mkdir -p /config/custom_components
cd /config/custom_components
git clone --branch core-61909 https://github.com/jjlawren/sonos_custom_component.git sonos

After that, make sure your logging config has custom_components.sonos: debug as the logging domain will change. Restart and share logs and hopefully we can start tracking this down.

crlogic commented 2 years ago

Roger that

Current State: 2021.12.3, fresh core restart, all players powered on, media_player state not updating, media_player.tv_sonos playing music from Spotify.

mkdir -p /config/custom_components cd /config/custom_components git clone --branch core-61909 https://github.com/jjlawren/sonos_custom_component.git sonos

Cloned successfully, configuration.yaml modified per below

logger:
  default: info
  logs:
    custom_components.sonos: debug

Upon core restart with custom_component it shows "Provided by a custom integration" in Integrations. State is still not updating. HA can change the volume but does not reflect correct volume_level in developer tools. Debug below;

[core-ssh config]$ cat home-assistant.log | grep sonos
2021-12-20 11:01:15 WARNING (SyncWorker_1) [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-12-20 11:01:18 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'automation', 'emporia_vue', 'usb', 'group', 'sun', 'tasmota', 'dhcp', 'binary_sensor', 'sensor', 'input_text', 'map', 'sonos', 'energy', 'zone', 'trace', 'zha', 'broadlink', 'switch', 'shelly', 'hacs', 'mqtt', 'ssdp', 'scene', 'input_number', 'zeroconf', 'unifi', 'blueprint', 'input_select', 'system_health', 'notify', 'counter', 'timer', 'input_datetime', 'tts', 'logbook', 'scheduler', 'esphome', 'climate', 'script', 'network', 'history', 'mobile_app', 'default_config', 'input_boolean', 'tag', 'my', 'persistent_notification', 'openweathermap', 'template', 'media_source', 'updater', 'light'}
2021-12-20 11:01:20 INFO (MainThread) [homeassistant.setup] Setting up sonos
2021-12-20 11:01:20 INFO (MainThread) [homeassistant.setup] Setup of domain sonos took 0.0 seconds
2021-12-20 11:01:20 DEBUG (MainThread) [custom_components.sonos] Reached async_setup_entry, config=OrderedDict([('advertise_addr', '192.168.0.96'), ('hosts', ['192.168.6.24', '192.168.6.27', '192.168.6.21', '192.168.6.22', '192.168.6.23', '192.168.6.28'])])
2021-12-20 11:01:21 INFO (MainThread) [homeassistant.components.switch] Setting up switch.sonos
2021-12-20 11:01:21 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.sonos
2021-12-20 11:01:21 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sonos
2021-12-20 11:01:21 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.sonos
2021-12-20 11:01:21 INFO (MainThread) [homeassistant.components.number] Setting up number.sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos] Adding discovery job
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos] Adding new speaker: {'zone_name': 'Kitchen Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_B8E93787A4DE01400', 'serial_number': 'B8-E9-37-87-A4-DE:F', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': 'B8-E9-37-87-A4-DE'}
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos.alarms] Updating processed event 1053 from <SoCo object at ip 192.168.6.24> (was None)
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos.favorites] Processing favorites update_id 2 for <SoCo object at ip 192.168.6.24> (was: None)
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos.favorites] Cached 11 favorites for household Sonos_i3T3DdH7vhsbf6toDCtueEAl4A using <SoCo object at ip 192.168.6.24>
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.number] Creating bass number control on Kitchen Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.number] Creating treble number control on Kitchen Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.media_player] Creating media_player entity for Kitchen Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Kitchen Sonos: {'number'}
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Touch Controls switch on Kitchen Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Crossfade switch on Kitchen Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Status Light switch on Kitchen Sonos
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos] Adding new speaker: {'zone_name': 'Bathroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C661EE01400', 'serial_number': '00-0E-58-C6-61-EE:9', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-61-EE'}
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.number] Creating bass number control on Bathroom Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.number] Creating treble number control on Bathroom Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.media_player] Creating media_player entity for Bathroom Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Bathroom Sonos: {'number'}
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Touch Controls switch on Bathroom Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Crossfade switch on Bathroom Sonos
2021-12-20 11:01:21 DEBUG (MainThread) [custom_components.sonos.switch] Creating Status Light switch on Bathroom Sonos
2021-12-20 11:01:21 DEBUG (SyncWorker_5) [custom_components.sonos] Adding new speaker: {'zone_name': 'TV Sonos', 'player_icon': '/img/icon-S14.png', 'uid': 'RINCON_949F3ED381BB01400', 'serial_number': '94-9F-3E-D3-81-BB:B', 'software_version': '66.4-23300', 'hardware_version': '1.23.1.10-1.2', 'model_number': 'S14', 'model_name': 'Sonos Beam', 'display_version': '13.4.1', 'mac_address': '94-9F-3E-D3-81-BB'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating bass number control on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating treble number control on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.sensor] Creating audio input format sensor on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number', 'media_player', 'switch', 'binary_sensor'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.media_player] Creating media_player entity for TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (SyncWorker_5) [custom_components.sonos] Adding new speaker: {'zone_name': 'Boys Room Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C663F001400', 'serial_number': '00-0E-58-C6-63-F0:D', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C6-63-F0'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Touch Controls switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Crossfade switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Night Sound switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Speech Enhancement switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Subwoofer Enabled switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Surround Enabled switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Status Light switch on TV Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on TV Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating bass number control on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating treble number control on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating alarm 977 on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Boys Room Sonos: {'number', 'media_player'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.media_player] Creating media_player entity for Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Boys Room Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Touch Controls switch on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Crossfade switch on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Status Light switch on Boys Room Sonos
2021-12-20 11:01:22 DEBUG (SyncWorker_5) [custom_components.sonos] Adding new speaker: {'zone_name': 'Bedroom Sonos', 'player_icon': '/img/icon-S1.png', 'uid': 'RINCON_000E58C29D2801400', 'serial_number': '00-0E-58-C2-9D-28:3', 'software_version': '66.4-23300', 'hardware_version': '1.8.3.7-1.0', 'model_number': 'S1', 'model_name': 'Sonos Play:1', 'display_version': '13.4.1', 'mac_address': '00-0E-58-C2-9D-28'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating bass number control on Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.number] Creating treble number control on Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating alarm 94 on Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.media_player] Creating media_player entity for Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Bedroom Sonos: {'number', 'media_player'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.speaker] Still waiting for platforms on Bedroom Sonos: {'number'}
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Touch Controls switch on Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Crossfade switch on Bedroom Sonos
2021-12-20 11:01:22 DEBUG (MainThread) [custom_components.sonos.switch] Creating Status Light switch on Bedroom Sonos
2021-12-20 11:01:25 INFO (MainThread) [homeassistant.components.automation.kitchen_sonos_mute_motion_end] Initialized trigger [MOTION END] Kitchen Sonos MUTE
2021-12-20 11:01:25 INFO (MainThread) [homeassistant.components.automation.sonos_boys_room_should_be_state] Initialized trigger SCHEDULE Boys Room Sonos
2021-12-20 11:02:42 DEBUG (MainThread) [custom_components.sonos.speaker] Activity on TV Sonos from SonosMediaPlayerEntity.set_volume_level

I have changed the TV_sonos volume using the Sonos app at least ten times and as you can see from the log, HA only knows about the time I used HA to do it.

Additional info: I do have some of the new switch entities disabled as I have no need to automate crossfade, eq, etc..

crlogic commented 2 years ago

Is it possible to create a 2021.11.5 branch of the sonos custom_component in https://github.com/jjlawren/sonos_custom_component ?

I wonder if trying the 11.5 version of sonos works in core 2021.12.3 in order to confirm that some other core change does not influence the behavior.

crlogic commented 2 years ago

Well that's neat. I did a thing. Following Google's sayings on blind faith I did this..

git clone https://github.com/home-assistant/core.git core
cd core
git reset --hard dbae448fe56e83eab5601d60a4c77c71f9a37afa

Then I winscp'd the sonos folder to my HAOS custom_components folder.

Took the hash from here which I'm not quite sure is right. But continued on..

Then I added a version line to manifest..

And it verks! Sonos is updating state/attributes/automations/etc in 2021.12.3 using 2021.11.4/5'ish integration :)

[edit] this is super handy; https://imgur.com/a/FcHDmho

jjlawren commented 2 years ago

Additional info: I do have some of the new switch entities disabled as I have no need to automate crossfade, eq, etc..

I think this is it. The subscriptions are never made as the new number entities (bass & treble) are disabled and that new platform never gets marked as "ready".

You can validate this theory by re-enabling at least one of those two EQ entities on a given speaker on plain 2021.12.3. I'd expect things to begin working after that.

I'll need to account for this possibility with a small refactor. Once this is ready we can test with the custom component and then I'll make a PR to fix the release version.

crlogic commented 2 years ago

Roger that. Reverting to stock 12.3 integration, enabling all Sonos entities. Will test and report.

crlogic commented 2 years ago

I think this is it.

Well gosh darn'it that's it!

Using stock sonos on 2021.12.3 and all sonos entities enabled the media_player state/attr correctly update and automations trigger.

I went as far as turning off power to five players and the remaining ones continue to update state/attr.

I had 80% of the new switch entities disabled as to reduce HA db size since I have no intention of ever changing those via HA and have found a small db keeps things snappy on the HA VM.

theetron commented 2 years ago

I also have issue with the Sonos attributes. Night sound looks to be working, but speech enhancement does not update the HA app, it always in the off state. Setting it to enable from HA will enable it, but is does not get the enabled state back, so it’s always disabled in HA. i will enable logs for Sonos as for now nothing is logged.

Core 2021.12.3 Supervisor 2021.12.2 Home assistant OS 7.0

danoc commented 2 years ago

Additional info: I do have some of the new switch entities disabled as I have no need to automate crossfade, eq, etc..

I think this is it. The subscriptions are never made as the new number entities (bass & treble) are disabled and that new platform never gets marked as "ready".

You can validate this theory by re-enabling at least one of those two EQ entities on a given speaker on plain 2021.12.3. I'd expect things to begin working after that.

I'll need to account for this possibility with a small refactor. Once this is ready we can test with the custom component and then I'll make a PR to fix the release version.

Ah, thank you! I can confirm that the issue goes away once I enable all the Sonos related entities. Like @crlogic, I had also disabled a bunch of entities because I didn't need them.

jjlawren commented 2 years ago

I've pushed a potential fix to the custom component discussed here. If you checked out that component you can update it by pulling the latest commit:

cd /config/custom_components/sonos
git pull

This should be able to handle any disabled entities without causing updating issues. Please let me know if you're able to test.

I had 80% of the new switch entities disabled as to reduce HA db size since I have no intention of ever changing those via HA and have found a small db keeps things snappy on the HA VM.

A general note that any entities that are expected to flood the database or impact performance negatively should be disabled by default according to best practices for all integrations. None of the new Sonos entities should impact database writes in any meaningful way. The two switches which require us to poll the speaker for the current state (status light & touch controls) are disabled by default because they do not have a push-based update method.

crlogic commented 2 years ago

This should be able to handle any disabled entities without causing updating issues. Please let me know if you're able to test.

Initial feedback is success. Have only tested my Beam so far. Disabled Bass, Treble, Crossfade, Status Light, Touch Controls entities and state/attr update as expected. Reloaded core and still good. Will report back if any changes.

None of the new Sonos entities should impact database writes in any meaningful way.

This is good to know. My habit of disabling entities also developed from so many Integrations adding tons of entities I don't use and my db was getting >2Gb. Now I am ~600Mb and probably twice as many devices as when it was 2Gb. Makes for smaller and quicker backups too!

PS. Thank you very much for your work. I looked at the 'Simplify platform creation' commit and I would have no clue where to start in all this. Appreciate the time you have put in.

jjlawren commented 2 years ago

It was an overly conservative (and complex) approach which deferred creating subscriptions until all the different platforms reported they were "done". This was needed a long time ago because the initial subscription callbacks could cause race conditions if the entities were not created yet. This is no longer the case because of changes in the design and underlying library improvements so we can simplify things a bit.