search

music-assistant / hass-music-assistant

Turn your Home Assistant instance into a jukebox, hassle free streaming of your favorite media to Home Assistant media players.
Apache License 2.0
1.37k stars 52 forks source link

Playback stops randomly after few songs #2925

Closed flexmatics closed 1 month ago

flexmatics commented 1 month ago

What version of Music Assistant has the issue?

2.3.0b23

What version of the Home Assistant Integration have you got installed?

2024.9.1

Have you tried everything in the Troubleshooting FAQ and reviewed the Open and Closed Issues and Discussions to resolve this yourself?

The problem

Playlist with enqued tracks playback stops randomly even though songs are present in the queue. No buttons are clicked by user.

How to reproduce

  1. Start playback of the playlist (Spotify used)
  2. After several songs (no clear pattern), playback stops

Music Providers

Spotify

Player Providers

Slimproto (piCoreplayer)

Full log output

music-assistant.log

Additional information

Playback is started via service call or manually - no difference. Tried beta and stable of Music assistant - no difference.

What version of Home Assistant Core are your running

2024.9.1

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Linux

OzGav commented 1 month ago

Please replace the log with one at the default log level not debug

flexmatics commented 1 month ago

Hey, I've set up WARNING log level (not sure, is it default log level), rebooted MA server, started playback and got the following output after reboot (again, after several songs played):

2024-09-15 14:42:43.547 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3) 2024-09-15 14:42:44.243 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 2/3) 2024-09-15 14:42:44.748 WARNING (MainThread) [music_assistant.audio.media_stream] Stream error on spotify--B8avHsBc://track/5sveGuwaXH0AAYnR9tYglj 2024-09-15 14:42:44.783 ERROR (MainThread) [music_assistant.streams] Error streaming QueueItem Natasha Bedingfield - Unwritten (2019 Remix) (spotify://track/5sveGuwaXH0AAYnR9tYglj) to living_room

EDIT: also adding INFO level log with the same error:

2024-09-15 14:52:47.367 INFO (MainThread) [music_assistant] Starting Music Assistant Server (add8b535ce464403a2cdc585972e4c11) version 2.3.0b23 - HA add-on: True - Safe mode: False 2024-09-15 14:52:47.370 INFO (MainThread) [music_assistant.cache] Initializing cache controller... 2024-09-15 14:52:47.441 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes. 2024-09-15 14:52:47.481 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.1.1 with libsoxr support 2024-09-15 14:52:47.481 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.0.108:8097 2024-09-15 14:52:47.484 INFO (MainThread) [music_assistant.webserver] Starting server on 172.30.32.1:8095 - base url: http://172.30.32.1:8095 2024-09-15 14:52:50.073 INFO (MainThread) [music_assistant] Loaded music provider Music Assistant 2024-09-15 14:52:50.074 INFO (MainThread) [music_assistant] Loaded metadata provider The Audio DB 2024-09-15 14:52:50.074 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz 2024-09-15 14:52:50.074 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv 2024-09-15 14:52:50.084 INFO (MainThread) [music_assistant] Loaded player provider Slimproto (Squeezebox players) 2024-09-15 14:52:50.186 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed 2024-09-15 14:52:50.186 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-09-15 14:52:50.188 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-09-15 14:52:50.408 INFO (MainThread) [music_assistant.spotify] Successfully logged in to Spotify as Inga 2024-09-15 14:52:50.408 INFO (MainThread) [music_assistant] Loaded music provider Spotify 2024-09-15 14:52:51.559 INFO (MainThread) [music_assistant.slimproto] Player squeezeplay: dc:a6:32:06:9e:c9 connected 2024-09-15 14:52:51.560 INFO (MainThread) [music_assistant.players] Player registered: dc:a6:32:06:9e:c9/squeezeplay: dc:a6:32:06:9e:c9 2024-09-15 14:52:51.563 INFO (MainThread) [music_assistant.slimproto] Player squeezeplay: 00:00:00:00:00:00 connected 2024-09-15 14:52:51.563 INFO (MainThread) [music_assistant.players] Player registered: 00:00:00:00:00:00/squeezeplay: 00:00:00:00:00:00 2024-09-15 14:53:06.352 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed 2024-09-15 14:53:06.352 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-09-15 14:53:06.354 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-09-15 15:02:34.050 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3) 2024-09-15 15:24:36.288 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3) 2024-09-15 15:54:01.686 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3) 2024-09-15 15:54:02.543 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 2/3) 2024-09-15 15:54:03.047 WARNING (MainThread) [music_assistant.audio.media_stream] Stream error on spotify--B8avHsBc://track/7LwJc7I5YNQHRQuQ9G5dXu 2024-09-15 15:54:03.082 ERROR (MainThread) [music_assistant.streams] Error streaming QueueItem Sonny Tennet - Princess (spotify://track/7LwJc7I5YNQHRQuQ9G5dXu) to living_room 2024-09-15 15:54:03.445 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired 2024-09-15 15:54:03.446 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...

eamonnsullivan commented 1 month ago

Weirdly, I'm having the same issue (stopping after a few songs), but only when playing through a chromecast player. When I play my Spotify playlist on an Airplay group (a couple Wiim Minis), I don't have the problem.

hamun8 commented 1 month ago

I am having the same issue but with local song, placed in HA-Media folder.

marcelveldt commented 1 month ago

I suspect this issue only exists on players without flow mode (or with flow mode disabled) so if you enable flow mode on the cast players they will probably keep playing. Now the next thing which is interesting to know is if you all have spotify as the music provider or it stops playing also with other music providers.

hamun8 commented 1 month ago

But it worked fine before the update to version 9

OzGav commented 1 month ago

@hamun8 it will be helpful if you could answer Marcels questions. Is flow mode on and are you using Spotify?

hamun8 commented 1 month ago

@hamun8 it will be helpful if you could answer Marcels questions. Is flow mode on and are you using Spotify?

I just mentioned above in my case it is happening with locally stored files.

I do not see the option for flow mode so it is not enabled

flexmatics commented 1 month ago

I suspect this issue only exists on players without flow mode (or with flow mode disabled) so if you enable flow mode on the cast players they will probably keep playing. Now the next thing which is interesting to know is if you all have spotify as the music provider or it stops playing also with other music providers.

Your assumption re flow mode is correct in my case - it was disabled. I've now enabled 'Enable queue flow mode' for both my end points (piCoreplayers, which had identical issue), will test and report back.

OzGav commented 1 month ago

@hamun8 then you don’t have this issue.

@flexmatics if you still have a problem then looking at your log you have this issue https://github.com/music-assistant/hass-music-assistant/issues/2863

niteguide commented 1 month ago

I suspect this issue only exists on players without flow mode (or with flow mode disabled) so if you enable flow mode on the cast players they will probably keep playing. Now the next thing which is interesting to know is if you all have spotify as the music provider or it stops playing also with other music providers.

I can not confirm the assumption that with flow-mode enabled + Spotify those issues vanish on Google Home Mini.

OzGav commented 1 month ago

@niteguide It is only helpful if you attach a log showing the exact same issue as the OP.

flexmatics commented 1 month ago

@OzGav

I've tested with flow mode enabled, multiple times. I still get the issue, but the log looks different. Given this, do you think the issue is duplicate of this issue?

2024-09-16 11:28:30.513 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 11:28:30.513 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 11:28:37.634 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 11:52:47.618 INFO (Mai2024-09-16 11:28:30.513 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 11:28:30.513 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 11:28:37.634 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 11:52:47.618 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-09-16 11:52:57.614 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed
2024-09-16 11:52:57.614 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-16 11:52:57.615 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-16 12:16:57.438 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 12:57:34.497 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 12:57:34.497 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 12:57:42.058 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 13:00:32.966 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3)
2024-09-16 13:57:51.533 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 13:57:51.533 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 14:48:34.989 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3)
2024-09-16 14:52:47.627 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-09-16 14:52:57.626 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed
2024-09-16 14:52:57.626 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-16 14:52:57.628 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-16 15:00:03.641 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 15:00:03.641 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...nThread) [music_assistant.music] Sync task for Music Assistant completed
2024-09-16 11:52:57.614 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed
2024-09-16 11:52:57.614 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-16 11:52:57.615 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-16 12:16:57.438 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 12:57:34.497 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 12:57:34.497 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 12:57:42.058 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False
2024-09-16 13:00:32.966 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3)
2024-09-16 13:57:51.533 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 13:57:51.533 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
2024-09-16 14:48:34.989 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3)
2024-09-16 14:52:47.627 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-09-16 14:52:57.626 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed
2024-09-16 14:52:57.626 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-16 14:52:57.628 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-16 15:00:03.641 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired
2024-09-16 15:00:03.641 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...
OzGav commented 1 month ago

@flexmatics yes. I will close this. Please follow along there. Thanks for the follow up logs.