music suddenly stop

[kshexe]

What version of Music Assistant has the issue?

2.2.5

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?

• [X] Yes

The problem

music suddenly stops, but MA is playing and playing more than the end of the music

How to reproduce

-

Music Providers

local storage mp3 file

Player Providers

air play / two homepods in groups

Full log output

music-assistant_240924.log

Additional information

No response

What version of Home Assistant Core are your running

2024.9.2

What type of installation are you running?

Home Assistant Core

On what type of hardware are you running?

Linux

[kshexe]

It worked well in early versions of 2.0, but it's been like this since it was recently updated around 2.2.

[OzGav]

@marcelveldt There are multiple different errors in the log??

[DrieWielRr]

I have the same issue, music sometimes stops at random but the player keeps going (and keeps going way beyond end of song):

MA logs show below, the Snapcast-client has nothing both still believe they are playing a song that has ended +15 minutes ago. We have music playing (via Spotify) nearly all day long when working from home and this happens daily, manually clicking "next track" usually fixed the problem and it starts playing the next track just fine until it cuts out again mid song and I have to select the next track again.

Log: 2024-10-18 02:01:31.790 INFO (MainThread) [music_assistant] Starting Music Assistant Server (0b8864600b48456287ce1e316d39b158) version 2.2.7 - HA add-on: False - Safe mode: False 2024-10-18 02:01:31.799 INFO (MainThread) [music_assistant.cache] Initializing cache controller... 2024-10-18 02:01:32.114 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes. 2024-10-18 02:01:32.183 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.1.1 with libsoxr support 2024-10-18 02:01:32.183 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.100.19:8097 2024-10-18 02:01:32.187 INFO (MainThread) [music_assistant.webserver] Starting server on 0.0.0.0:8095 - base url: http://192.168.100.19:8095 2024-10-18 02:01:32.713 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv 2024-10-18 02:01:32.714 INFO (MainThread) [music_assistant] Loaded metadata provider The Audio DB 2024-10-18 02:01:32.714 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz 2024-10-18 02:01:32.754 INFO (MainThread) [music_assistant] Loaded plugin provider Home Assistant 2024-10-18 02:01:32.772 INFO (MainThread) [music_assistant.snapcast.snapserver] Starting builtin Snapserver... 2024-10-18 02:01:32.990 INFO (MainThread) [music_assistant.spotify] Successfully logged in to Spotify as Randy & Stephanie 2024-10-18 02:01:32.990 INFO (MainThread) [music_assistant] Loaded music provider Spotify 2024-10-18 02:01:36.563 INFO (MainThread) [music_assistant.snapcast] Started connection to Snapserver 127.0.0.1:1705 2024-10-18 02:01:36.563 INFO (MainThread) [music_assistant] Loaded player provider Snapcast 2024-10-18 02:01:36.565 INFO (MainThread) [music_assistant.players] Player registered: ma_0242ac120002/8d7f2affccc4 2024-10-18 02:01:50.962 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 02:01:50.962 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 02:01:50.968 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 05:01:40.574 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 05:01:40.575 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 05:01:40.580 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 08:02:06.220 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 08:02:06.221 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 08:02:06.225 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 11:01:40.215 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 11:01:40.216 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 11:01:40.221 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 11:45:36.405 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True 2024-10-18 12:03:11.212 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired 2024-10-18 12:03:11.213 INFO (MainThread) [music_assistant.spotify] Retrying in 0.1 seconds... 2024-10-18 13:55:17.680 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True

Might be failing to continue after "2024-10-18 12:03:11.212 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired"?

[DrieWielRr]

It just cutout again after <1h of playtime.

Log shows nothing: 2024-10-18 02:01:31.790 INFO (MainThread) [music_assistant] Starting Music Assistant Server (0b8864600b48456287ce1e316d39b158) version 2.2.7 - HA add-on: False - Safe mode: False 2024-10-18 02:01:31.799 INFO (MainThread) [music_assistant.cache] Initializing cache controller... 2024-10-18 02:01:32.114 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes. 2024-10-18 02:01:32.183 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.1.1 with libsoxr support 2024-10-18 02:01:32.183 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.100.19:8097 2024-10-18 02:01:32.187 INFO (MainThread) [music_assistant.webserver] Starting server on 0.0.0.0:8095 - base url: http://192.168.100.19:8095 2024-10-18 02:01:32.713 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv 2024-10-18 02:01:32.714 INFO (MainThread) [music_assistant] Loaded metadata provider The Audio DB 2024-10-18 02:01:32.714 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz 2024-10-18 02:01:32.754 INFO (MainThread) [music_assistant] Loaded plugin provider Home Assistant 2024-10-18 02:01:32.772 INFO (MainThread) [music_assistant.snapcast.snapserver] Starting builtin Snapserver... 2024-10-18 02:01:32.990 INFO (MainThread) [music_assistant.spotify] Successfully logged in to Spotify as Randy & Stephanie 2024-10-18 02:01:32.990 INFO (MainThread) [music_assistant] Loaded music provider Spotify 2024-10-18 02:01:36.563 INFO (MainThread) [music_assistant.snapcast] Started connection to Snapserver 127.0.0.1:1705 2024-10-18 02:01:36.563 INFO (MainThread) [music_assistant] Loaded player provider Snapcast 2024-10-18 02:01:36.565 INFO (MainThread) [music_assistant.players] Player registered: ma_0242ac120002/8d7f2affccc4 2024-10-18 02:01:50.962 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 02:01:50.962 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 02:01:50.968 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 05:01:40.574 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 05:01:40.575 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 05:01:40.580 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 08:02:06.220 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 08:02:06.221 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 08:02:06.225 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 11:01:40.215 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 11:01:40.216 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 11:01:40.221 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 11:45:36.405 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True 2024-10-18 12:03:11.212 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired 2024-10-18 12:03:11.213 INFO (MainThread) [music_assistant.spotify] Retrying in 0.1 seconds... 2024-10-18 13:55:17.680 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True 2024-10-18 14:02:06.207 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Randy & Stephanie completed 2024-10-18 14:02:06.208 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner 2024-10-18 14:02:06.213 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished. 2024-10-18 15:52:21.018 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True 2024-10-18 15:52:22.730 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Beneden - crossfade: True

It seems to have happened on the end of the song this time during the crossfade, ill keep monitoring if it always happens during crossfade or also mid track.

[OzGav]

@DrieWielRr can you try with a different player type and see if you can reproduce.

[DrieWielRr]

@DrieWielRr can you try with a different player type and see if you can reproduce.

What exactly do you mean, something else than Spotify, or a different client than spotcast-client?

[OzGav]

I meant different player but looking at your log you have posted in the wrong thread. This is a Spotify error https://github.com/music-assistant/hass-music-assistant/issues/2863 The OP is about local storage and AirPlay

[DrieWielRr]

I meant different player but looking at your log you have posted in the wrong thread. This is a Spotify error #2863 The OP is about local storage and AirPlay

Ohh, my bad did not notice that.

[OzGav]

@kshexe Groups have been reworked in the beta. Can you try the beta and see if this has been fixed, You can install the beta server alongside the stable just don't have them running at the same time.

[kshexe]

music-assistant1023.log

The situation is similar. @OzGav

and Switch to player stop button.

[OzGav]

OK lets wait until @marcelveldt can look at this one

[marcelveldt]

fixed in 2.3.0 rc 1

[OzGav]

2.3.0rc1 is released. Please test again

[kshexe]

@OzGav Now the song doesn't break, it stops on the player. test Current version: 2.4.0b0 music-assistant (1).log

[OzGav]

@marcelveldt a lot of errors in the log?

[kshexe]

@OzGav I think it stops once 9-10 seconds before the end of the song. music-assistant1028.log

[OzGav]

@marcelveldt there are still a ton of errors in the log?

[marcelveldt]

@marcelveldt there are still a ton of errors in the log?

The queue/player name is using non-ascii characters which makes the imageproxy crash. I will have to look into that.

[flexmatics]

Hey,

It does look like I have the same issue - songs randomly stop with 7-10 sec remaining until the end of the song. See logs - a) music started at 18:54, music stopped at 18:58 (no errors), then at 19:01 there is an error. At 19:01 there was also 0.5-1 sec sound from speakers of this previous song.

2024-11-06 18:54:31.106 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False 2024-11-06 19:01:42.677 ERROR (MainThread) [ffmpeg.2412] Stream error: TimeoutError

MA server: 2.4.0b4 MA integration: 2024.11.1 Spotify used (with Client ID) Player: Slimproto player

Should I raise a new issue, or can track here? any other info to be provided?

[lwsrbrts]

I reverted to 2.2.7 due to a random stopping issue affecting me since 2.3.0.

I am playing to a Google Cast group with 3 x Chromecast Audio devices in. I am playing long "tracks" which are basically podcasts of music (DJ mixes). Unfortunately I can't extract the errors from the log as it has since disappeared post revert but I do recall there being an error referring to cmd_power and there additionally being a notification that the queue had finished. It hadn't since the track was often barely 1-2 minutes in before the error occurred.

I'll attempt to update to 2.3.2 or 2.4.0 when that's released and see if I still see the issue.

[lor74]

Hi same issue with Airplay please find attached the full log music-assistant.log

Current MA version: 2.4.0b5 HA Core 2024.11.2 HA Supervisor 2024.11.2 HA Operating System 13.2 HA Frontend 20241106.2

2024-11-17 08:28:57.496 DEBUG (MainThread) [music_assistant.audio.media_stream] stream finished (with code 0) for spotify://track/6m6nCDeDNpfW78utlH3Qte - seconds streamed: 146.17333333333335
2024-11-17 08:28:58.613 DEBUG (MainThread) [music_assistant.streams] Finished Streaming queue track: spotify://track/6m6nCDeDNpfW78utlH3Qte (Hank Shizzoe - California) on queue AirPlayGroup
2024-11-17 08:28:58.613 DEBUG (MainThread) [music_assistant.audio] Getting streamdetails for spotify://track/4ltSwgfNcUSl42nu0YKd3L
2024-11-17 08:28:58.624 DEBUG (MainThread) [music_assistant.audio] retrieved streamdetails for spotify://track/4ltSwgfNcUSl42nu0YKd3L in 10 milliseconds
2024-11-17 08:28:58.625 DEBUG (MainThread) [music_assistant.streams] Start Streaming queue track: spotify://track/4ltSwgfNcUSl42nu0YKd3L (Hank Shizzoe/Loose Gravel - Handmade Love (Live)) for queue AirPlayGroup
2024-11-17 08:28:58.625 DEBUG (MainThread) [music_assistant.audio.media_stream] start media stream for: spotify://track/4ltSwgfNcUSl42nu0YKd3L
2024-11-17 08:29:43.293 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/app/venv/lib/python3.12/site-packages/aiohttp/web_protocol.py", line 377, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "aiohttp/_http_parser.pyx", line 563, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.InvalidURLError: 400, message:
  Invalid char in url query:

    b'GET /imageproxy?path=https%253A//i.scdn.co/image/ab67616d0000b273a1f9e983ad47bb292dfbd6ea&provider=spotify&size=500&fmt=jp\x07 HTTP/1.0'

I don't know if is the same problem but here #2952 @OzGav closed the issue reverting here. If is not the "right place" I can open a new issue.

Thanks fpr support

[niteguide]

Just for reference: in #3131 I describe the same kind of issue for other music providers (Spotify, Tidal).