core
core copied to clipboard
Published
20 hours ago •
home-assistant
home-assistant
Snapcast entities unavailable on boot
The problem
Continuing https://github.com/home-assistant/core/issues/99192
The issue keeps occurring on HAOS reboots - In my case, the reboots are automated and occur once per week.
The bug does not happen on every reboot. It seems like some sort of race condition which hasn't been resolved yet.
To recap, since my Snapserver is running as an addon on HAOS, the snapcast integration seems to load before the addon, and doesn't know what to do afterwards.
I'm not seeing anything interesting in the debug logs. These are the only two relevant errors:
# Line below occurs around the time of the reboot
2023-12-25 02:11:53.538 WARNING (MainThread) [snapcast.control.server] could not send request
...
# Line below occurred around the time I disabled/enabled the integration (while Debug was enabled)
2023-12-25 10:03:05.778 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
The Snapserver works normally, it's just the player entities that get lost until I restart HA:
What version of Home Assistant Core has the issue?
core-2023.12.1
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant OS
Integration causing the issue
Snapcast
Link to integration documentation on our website
https://www.home-assistant.io/integrations/snapcast/
Diagnostics information
No response
Example YAML snippet
No response
Anything in the logs that might be useful for us?
No response
Additional information
No response
Hey there @luar123, mind taking a look at this issue as it has been labeled with an integration (snapcast) you are listed as a code owner for? Thanks!
Code owner commands
Code owners of snapcast can trigger bot actions by commenting:
-
@home-assistant closeCloses the issue. -
@home-assistant rename Awesome new titleRenames the issue. -
@home-assistant reopenReopen the issue. -
@home-assistant unassign snapcastRemoves the current integration label and assignees on the issue, add the integration domain after the command. -
@home-assistant add-label needs-more-informationAdd a label (needs-more-information, problem in dependency, problem in custom component) to the issue. -
@home-assistant remove-label needs-more-informationRemove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.
(message by CodeOwnersMention)
snapcast documentation snapcast source (message by IssueLinks)
![home-assistant[bot] avatar](https://avatars.githubusercontent.com/in/97978?v=4 "Published by a pub.dev verified publisher"){kind=small}
Just to double-check: You don't use a custom snapcast integration through HACS or in your custom_components folder?
Could you provide a full debug log of a working and a failed reboot? I would expect something like you posted in: https://github.com/home-assistant/core/issues/99192#issuecomment-1698738933
You don't use a custom snapcast integration
Confirmed, I do not.
For the love of god I cannot reproduce the bug, even after 3 reboots.
Here are all the logs that contain the word snap:
Reboot 1:
2023-12-30 14:45:53.332 DEBUG (MainThread) [snapcast.control.server] connected to snapserver on localhost:1705
2023-12-30 14:45:53.400 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (Spotify)
2023-12-30 14:45:53.401 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (TTS)
2023-12-30 14:45:53.418 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-livingroom, devpi)
2023-12-30 14:45:53.424 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-bedroom, devpi2)
2023-12-30 14:45:53.429 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 14:45:53.433 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.5.0 (Snapweb client, [REDACTED])
2023-12-30 14:45:53.436 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#4#4)
2023-12-30 14:45:53.438 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 14:45:53.440 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#6)
2023-12-30 14:45:53.446 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#7)
2023-12-30 14:45:53.463 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#8)
2023-12-30 14:45:53.467 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-balcony, balcony)
2023-12-30 14:45:53.471 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#9)
2023-12-30 14:45:53.471 DEBUG (MainThread) [snapcast.control.server] Server connected
Reboot 2:
2023-12-30 14:54:18.517 DEBUG (MainThread) [snapcast.control.server] connected to snapserver on localhost:1705
2023-12-30 14:54:18.525 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (Spotify)
2023-12-30 14:54:18.526 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (TTS)
2023-12-30 14:54:18.532 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-livingroom, devpi)
2023-12-30 14:54:18.535 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-bedroom, devpi2)
2023-12-30 14:54:18.538 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 14:54:18.542 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.5.0 (Snapweb client, [REDACTED])
2023-12-30 14:54:18.544 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#4#4)
2023-12-30 14:54:18.550 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 14:54:18.551 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#6)
2023-12-30 14:54:18.552 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#7)
2023-12-30 14:54:18.557 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#8)
2023-12-30 14:54:18.561 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-balcony, balcony)
2023-12-30 14:54:18.563 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#9)
2023-12-30 14:54:18.563 DEBUG (MainThread) [snapcast.control.server] Server connected
2023-12-30 14:54:18.976 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-bedroom
2023-12-30 14:54:18.976 DEBUG (MainThread) [snapcast.control.server] client snap-bedroom connected
2023-12-30 14:54:18.979 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-livingroom
2023-12-30 14:54:18.979 DEBUG (MainThread) [snapcast.control.server] client snap-livingroom connected
2023-12-30 14:54:19.027 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on [REDACTED]
2023-12-30 14:54:19.027 DEBUG (MainThread) [snapcast.control.server] client [REDACTED] connected
SnapServer addon logs (reboot 2):
[13:54:16] INFO: Populating snapserver.conf...
[13:54:18] INFO: Starting SnapServer...
2023-12-30 13-54-18.366 [Info] (Snapserver) Version 0.27.0
2023-12-30 13-54-18.366 [Info] (Snapserver) Adding stream: .....
As you can see, the SnapServer started a little before the Snapcast integration, and I think this is the race condition we're having.
Reboot 3:
2023-12-30 15:01:51.389 DEBUG (MainThread) [snapcast.control.server] connected to snapserver on localhost:1705
2023-12-30 15:01:51.462 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (Spotify)
2023-12-30 15:01:51.462 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (TTS)
2023-12-30 15:01:51.474 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-livingroom, devpi)
2023-12-30 15:01:51.478 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-bedroom, devpi2)
2023-12-30 15:01:51.482 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 15:01:51.488 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.5.0 (Snapweb client, [REDACTED])
2023-12-30 15:01:51.493 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#4#4)
2023-12-30 15:01:51.497 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2023-12-30 15:01:51.502 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#6)
2023-12-30 15:01:51.504 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#7)
2023-12-30 15:01:51.506 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#8)
2023-12-30 15:01:51.509 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-balcony, balcony)
2023-12-30 15:01:51.512 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED]#9)
2023-12-30 15:01:51.512 DEBUG (MainThread) [snapcast.control.server] Server connected
SnapServer addon logs (reboot 3):
[14:01:24] INFO: Populating snapserver.conf...
[14:01:26] INFO: Starting SnapServer...
2023-12-30 14-01-26.378 [Info] (Snapserver) Version 0.27.0
2023-12-30 14-01-26.378 [Info] (Snapserver) Adding stream: .....
Same scenario.
Thanks for the logs, that is exactly what we need...just for a failed reboot. Without it will be hard to find the issue. So either you were just (un)lucky or the debug log is adding enough delay to prevent the race condition.
The only hint we have so far is this line:
# Line below occurs around the time of the reboot 2023-12-25 02:11:53.538 WARNING (MainThread) [snapcast.control.server] could not send request
Do you remember if this happened before or after the reboot?
Based on this I would expect the error to be in the python-snapcast module and not in home-assistant directly. If I give you a modified python file with added logging, would you be able to replace it in your installation?
As expected, it happened again today after the weekly backup. I forgot to turn on the debug logs unfortunately...
To recap, HAOS is turned off by the hypervisor before the backup.
Backup logs:
Start: Jan 1, 2024, 01:35:26 AM
End: Jan 1, 2024, 01:39:40 AM
Duration: 4 minutes
I did not prepare well for this, because I initially planned to document the time it took for the snapserver addon to start after the backup, but I forgot that I have an automation which restarts the addon every day at the same time during night (04:05).
So for now, I only have logs that show the addon restarted at the pre-configured time (Note how it seems like there is time difference between the snapserver addon and HA, but that is because the container doesn't have the correct timezone set, 03:05 in the addon is 04:05 on HA)
[03:05:05] INFO: Populating snapserver.conf...
[03:05:06] INFO: Starting SnapServer...
2024-01-01 03-05-06.463 [Info] (Snapserver) Version 0.27.0
2024-01-01 03-05-06.463 [Info] (Snapserver) Adding stream:
After bootup, HA logs are filled with an endless stream of the following WARNING+ERROR combo:
2024-01-01 01:36:10.827 First log line (just a reference for startup time)
You might be confused why the backup took 4 min but HA booted during the 1st min:
I would guess because the HAOS VM backup finished, and the rest of the backup time was the actual transfer of the snapshot to the backup system, so the HAOS VM was free to boot up.
... SNIP HACS components ...
2024-01-01 01:36:54.134 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-01 01:36:54.135 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
... 2,496 iterations of the same 2 lines, between above and below lines - note that this is only 5 seconds apart ...
2024-01-01 01:36:59.609 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-01 01:36:59.609 WARNING (MainThread) [snapcast.control.server] could not send request
... Here I have a few errors for failing volume control automations, since the media player entities are unavailable ...
... Then a couple more of these:
2024-01-01 02:13:54.015 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-01 02:13:54.015 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-01 02:13:54.015 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-01 02:13:54.015 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-01 02:13:54.015 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
... Then they stopped, but much more returned after the addon restart ...
2024-01-01 04:05:00.092 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-01 04:05:00.092 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
... This time it took 10 minutes for the combo to stop, with 8,812 repeated combo lines in between the above and below timeframe...
2024-01-01 04:15:09.430 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-01 04:15:09.430 WARNING (MainThread) [snapcast.control.server] could not send request
... Then more of errors for setting volume on media players that don't exist, all up until the time of restarting HA yaml and typing this ...
I think the Snapcast integration needs to chill a bit when it can't reach the snapserver, instead of blasting out requests like this.
This confirms at least that there is an issue with the communication which crashes the snapcast integrations. Here is a modified snapcast/control/server.py file: server.py.zip
It enables more detailed logging and maybe it solves already the issue. Could you please unzip and copy to your vm. Should be somewhere in /usr/local/lib/python3.11/site-packages/snapcast/control/ (or a similar folder, depending on your environment). Then restart your vm and post logs please.
I was prepared this time:
Backup:
Start: Jan 8, 2024, 01:35:27 AM
End: Jan 8, 2024, 01:37:36 AM
Duration: 2 minutes
Snapserver addon:
[00:36:53] INFO: Populating snapserver.conf...
[00:36:58] INFO: Starting SnapServer...
2024-01-08 00-36-58.154 [Info] (Snapserver) Version 0.27.0
2024-01-08 00-36-58.154 [Info] (Snapserver) Adding stream: ...
System logs:
2024-01-08 01:36:10.792 ... First log line (just HACS stuff)
...
2024-01-08 01:36:52.400 DEBUG (MainThread) [snapcast.control.server] connected to snapserver on localhost:1705
2024-01-08 01:36:52.401 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 01:36:52.401 DEBUG (MainThread) [snapcast.control.server] try reconnect
...
2024-01-08 01:36:52.527 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 01:36:52.527 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 01:36:52.528 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 01:36:52.528 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
...
2024-01-08 01:36:52.555 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 01:36:52.555 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 01:36:52.571 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 01:36:52.572 DEBUG (MainThread) [snapcast.control.server] try reconnect
...
2024-01-08 01:36:58.189 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 01:36:58.189 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 01:36:58.209 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (Spotify)
2024-01-08 01:36:58.210 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (TTS)
2024-01-08 01:36:58.210 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 01:36:58.210 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
...
2024-01-08 01:36:58.212 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 01:36:58.212 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 01:36:58.229 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-livingroom, devpi)
2024-01-08 01:36:58.232 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 (snap-bedroom, devpi2)
2024-01-08 01:36:58.234 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([redacted], [redacted])
2024-01-08 01:36:58.234 DEBUG (MainThread) [snapcast.control.server] Server connected
2024-01-08 01:36:58.730 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-bedroom
2024-01-08 01:36:58.730 DEBUG (MainThread) [snapcast.control.server] client snap-bedroom connected
2024-01-08 01:36:58.751 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-livingroom
2024-01-08 01:36:58.751 DEBUG (MainThread) [snapcast.control.server] client snap-livingroom connected
2024-01-08 01:37:00.635 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 01:37:00.635 WARNING (MainThread) [snapcast.control.server] could not send request
...
2024-01-08 01:37:00.636 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 01:37:00.636 WARNING (MainThread) [snapcast.control.server] could not send request
... errors for changing volume on broken snapcast media players ...
...
2024-01-08 02:00:01.934 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:00:02.100 DEBUG (MainThread) [snapcast.control.server] stream Spotify updated
2024-01-08 02:00:16.545 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:02:45.566 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:05:31.069 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:05:50.687 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 02:05:50.687 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 02:05:50.687 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 02:05:50.687 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 02:05:50.687 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 02:05:50.687 WARNING (MainThread) [snapcast.control.server] could not send request
2024-01-08 02:09:25.399 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:12:14.878 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:15:00.264 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:18:22.448 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:21:32.985 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:25:22.847 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 02:28:18.610 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
...
2024-01-08 03:16:18.825 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:19:10.768 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:22:28.248 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:25:23.981 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:28:29.779 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:31:04.490 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:33:38.890 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:36:40.945 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:39:33.334 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:42:50.407 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:46:04.370 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:49:11.775 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:52:27.848 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:55:50.126 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 03:58:21.969 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:01:34.024 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:01:59.302 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-bedroom
2024-01-08 04:01:59.302 DEBUG (MainThread) [snapcast.control.server] client snap-bedroom connected
2024-01-08 04:02:11.349 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-livingroom
2024-01-08 04:02:11.349 DEBUG (MainThread) [snapcast.control.server] client snap-livingroom connected
2024-01-08 04:02:18.210 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on snap-livingroom
2024-01-08 04:02:18.210 DEBUG (MainThread) [snapcast.control.server] client snap-livingroom connected
2024-01-08 04:04:18.923 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:07:26.052 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:10:00.573 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:13:03.522 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:15:34.288 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:18:23.849 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:20:39.529 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:23:49.518 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:27:13.521 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:29:41.257 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
2024-01-08 04:33:05.261 DEBUG (MainThread) [snapcast.control.server] stream Spotify properties updated
... errors for changing volume on broken snapcast media players ...
... repeat error of "stream Spotify properties updated" ...
Integration stuck in initializing:
I've put the file over in the first found folder (/control subdir).
homeassistant:/config# find / -name snapcast -type d
/usr/local/lib/python3.11/site-packages/snapcast
/usr/src/homeassistant/homeassistant/components/snapcast
Triggered a manual backup, and the issue still seems to occur.
Start: Jan 8, 2024, 09:31:50 AM
End: Jan 8, 2024, 09:32:16 AM
Duration: a few seconds
[08:33:20] INFO: Populating snapserver.conf...
[08:33:23] INFO: Starting SnapServer...
2024-01-08 08-33-24.033 [Info] (Snapserver) Version 0.27.0
2024-01-08 08-33-24.033 [Info] (Snapserver) Adding stream: ...
2024-01-08 09:32:36.521 ... First log line
...
2024-01-08 09:33:17.750 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:17.750 DEBUG (MainThread) [snapcast.control.server] try reconnect
...
2024-01-08 09:33:17.925 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:17.925 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 09:33:17.926 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
...
2024-01-08 09:33:17.927 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:17.938 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:17.949 DEBUG (MainThread) [snapcast.control.server] try reconnect
..
2024-01-08 09:33:18.129 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:18.129 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 09:33:18.130 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
...
2024-01-08 09:33:18.134 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:18.145 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:18.145 DEBUG (MainThread) [snapcast.control.server] try reconnect
...
2024-01-08 09:33:18.364 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:18.364 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 09:33:18.371 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
...
2024-01-08 09:33:18.372 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:18.385 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:18.385 DEBUG (MainThread) [snapcast.control.server] try reconnect
..
2024-01-08 09:33:18.580 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:18.580 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 09:33:18.581 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
....... Looping a million more times ...... All up until:
2024-01-08 09:33:24.074 DEBUG (MainThread) [snapcast.control.server] Server disconnected
2024-01-08 09:33:24.074 DEBUG (MainThread) [snapcast.control.server] try reconnect
2024-01-08 09:33:24.122 DEBUG (MainThread) [snapcast.control.server] {'server': {'groups': [{'clients': [{'config': {'instance': 1, 'latency': 0, 'name': '', 'volume': {'muted': False, 'percent': 30}}, 'connected': False, 'host': {'arch': 'armv6l', 'ip': '[REDACTED]', 'mac': '[REDACTED]', 'name': '[REDACTED]', 'os': 'Raspbian GNU/Linux 11 (bullseye)'}, 'id': '[REDACTED]', 'lastSeen': {'sec': 1704702687, 'usec': 900564}, 'snapclient': {'name': 'Snapclient', 'protocolVersion': 2, 'version': '0.27.0'}}], 'id': '[REDACTED]', 'muted': False, 'name': '', 'stream_id': 'Spotify'}, {'clients': [{'config': {'instance': 1, 'latency': 0, 'name': '', 'volume': {'muted': False, 'percent': 20}}, 'connected': False, 'host': {'arch': 'armv6l', 'ip': '[REDACTED]', 'mac': '[REDACTED]', 'name': '[REDACTED]', 'os': 'Raspbian GNU/Linux 11 (bullseye)'}, 'id': '[REDACTED]', 'lastSeen': {'sec': 1704702687, 'usec': 999622}, 'snapclient': {'name': 'Snapclient', 'protocolVersion': 2, 'version': '0.27.0'}}], 'id': '[REDACTED]', 'muted': False, 'name': '', 'stream_id': 'Spotify'}, {'clients': [{'config': {'instance': 1, 'latency': 0, 'name': '', 'volume': {'muted': False, 'percent': 70}}, 'connected': False, 'host': {'arch': 'x86_64', 'ip': '[REDACTED]', 'mac': '[REDACTED]', 'name': '[REDACTED]', 'os': '[REDACTED]'}, 'id': '[REDACTED]', 'lastSeen': {'sec': 1704702687, 'usec': 924908}, 'snapclient': {'name': 'Snapclient', 'protocolVersion': 2, 'version': '0.27.0'}}], 'id': '[REDACTED]', 'muted': False, 'name': '', 'stream_id': 'Spotify'}], 'server': {'host': {'arch': 'x86_64', 'ip': '', 'mac': '', 'name': 'local-snapcast-server-libspot', 'os': '[REDACTED]'}, 'snapserver': {'controlProtocolVersion': 1, 'name': 'Snapserver', 'protocolVersion': 1, 'version': '0.27.0'}}, 'streams': [{'id': 'Spotify', 'properties': {'canControl': False, 'canGoNext': False, 'canGoPrevious': False, 'canPause': False, 'canPlay': False, 'canSeek': False}, 'status': 'idle', 'uri': {'fragment': '', 'host': '', 'path': '/librespot', 'query': {'autoplay': 'true', 'bitrate': '320', 'chunk_ms': '20', 'codec': 'flac', 'devicename': '[REDACTED]', 'name': 'Spotify', 'password': 'xxx', 'sampleformat': '44100:16:2', 'username': 'xxx', 'volume': '100'}, 'raw': 'spotify:////librespot?autoplay=true&bitrate=320&chunk_ms=20&codec=flac&devicename=[REDACTED]&name=Spotify&password=xxx&sampleformat=44100:16:2&username=xxx&volume=100', 'scheme': 'spotify'}}, {'id': 'TTS', 'properties': {'canControl': False, 'canGoNext': False, 'canGoPrevious': False, 'canPause': False, 'canPlay': False, 'canSeek': False}, 'status': 'idle', 'uri': {'fragment': '', 'host': '[REDACTED]', 'path': '', 'query': {'chunk_ms': '20', 'codec': 'pcm', 'mode': 'server', 'name': 'TTS', 'sampleformat': '48000:16:2'}, 'raw': 'tcp://[REDACTED]/?chunk_ms=20&codec=pcm&mode=server&name=TTS&sampleformat=48000:16:2', 'scheme': 'tcp'}}]}}
2024-01-08 09:33:24.122 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (Spotify)
2024-01-08 09:33:24.124 DEBUG (MainThread) [snapcast.control.server] stream found: Snapstream (TTS)
2024-01-08 09:33:24.124 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:24.140 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2024-01-08 09:33:24.149 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2024-01-08 09:33:24.161 DEBUG (MainThread) [snapcast.control.server] client found: Snapclient 0.27.0 ([REDACTED], [REDACTED])
2024-01-08 09:33:24.161 DEBUG (MainThread) [snapcast.control.server] Server connected
2024-01-08 09:33:24.889 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on [REDACTED]
2024-01-08 09:33:24.889 DEBUG (MainThread) [snapcast.control.server] client [REDACTED] connected
2024-01-08 09:33:24.895 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on [REDACTED]
2024-01-08 09:33:24.895 DEBUG (MainThread) [snapcast.control.server] client [REDACTED] connected
2024-01-08 09:33:24.939 DEBUG (MainThread) [snapcast.control.client] updated connected status to True on [REDACTED]
2024-01-08 09:33:24.939 DEBUG (MainThread) [snapcast.control.server] client [REDACTED] connected
2024-01-08 09:33:25.066 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:25.066 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:25.066 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2024-01-08 09:33:25.066 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
Even though it stopped trying to reconnect, and both Snapserver and the Snapclients work (they play music), only the media player entities are unavailable in HA.
I think this is the first time that the correct side of the race condition won. The weekly backup completed and the entities are still available.
Note that at the time of writing, I'm running Core 2024.1.6, which came with the server.py that is currently on ha-core, and not the custom one you gave me.
I don't have much time to look into this at the moment and totally forgot about your last message. So thanks for the logs and the reminder, it seems the snapcast integration is connecting to the server successfully, but the connection is then terminated immediately. I checked the protocol implementation and it seems that this case, where the connection is lost while the integration tries to get all the data from the server is not handled properly.
So here is another modified server.py and protocol.py you could replace in your installation: snapcast.zip
No worries, I truly appreciate you taking the time for all the help so far.
I installed the new files, will keep you posted.
I'm not seeing the issue occur after 2 backup iterations, with the modified files you sent me.
I'm just getting these two warnings (which I suppose are related to what you referenced above):
Logger: py.warnings
Source: components/snapcast/__init__.py:22
First occurred: February 26, 2024 at 1:37:01 AM (1 occurrences)
Last logged: February 26, 2024 at 1:37:01 AM
/usr/local/lib/python3.12/site-packages/snapcast/control/server.py:117: RuntimeWarning: coroutine 'Snapserver.stop' was never awaited self.stop()
Logger: snapcast.control.server
Source: components/snapcast/__init__.py:22
First occurred: February 26, 2024 at 1:37:01 AM (1 occurrences)
Last logged: February 26, 2024 at 1:37:01 AM
connected, but no valid response: connection lost
But other than that, everything seems to be working as it should.
Great! Yes the second message is expected. The first is actually a small bug. I will clean up and submit upstream.
Bless you for all the help @luar123.
Now we can only imagine where the world would be, if more of Github code owners were as friendly, knowledgeable and responsive as you!