Spotify streaming errors

[niteguide]

What version of Music Assistant has the issue?

2.3.0b16

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

2024.8.1

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

• Yes

The problem

Unfortunately Issue #2765 was marked as closed very fast. Because the problem persists in my setup I open this new entry. The problem still comes back after a non predictable amount of time - on Chromecast/Google Cast as well as on AirPlay. Arbitrarily (but usually only between songs) the sound-output stops and does not come back although music still appears to be playing within MA. I have both players also added via Apple-TV/Google Cast integration - these entities immediately go to idle when the sound-output stops. Music provider in use is Spotify only.

How to reproduce

Happens arbitrarily during playback (Spotify playlist). Usually between two songs (after one song ends).

Music Providers

Spotify only

Player Providers

Happens on HomePod Mini, Google Home Mini

Full log output

Log-entries from yesterday and today:
log.docx

Additional information

As a workaround I have set up an automation that gets triggered when the entity from Apple-TV/Google Cast integration goes to Idle for 4 seconds - the automation then stops the MA-entity and restarts the playlist. But this however is of course far from what the system should be.

Router in use: Synology MR2200ac
Did a lot of experimenting with router settings but nothing makes the situation better. I have not noticed any other issues within my network.

What version of Home Assistant Core are your running

2024.8.3

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Raspberry Pi

[OzGav]

Based on the log excerpt this appears to be a duplicate of #2860

[niteguide]

Based on the log excerpt this appears to be a duplicate of #2860

The description of the problem over there is not very detailed, so I could not say, if we talk about the same issue. Nevertheless this one points out that also AirPlay and Google Cast is affected.

[OzGav]

Yes but only because that is what you have tried. I expect that if you try Snapcast you will get the same thing because if you look in the log it is full of Spotify errors. To confirm you can try a radio station and see what happens

[marcelveldt]

please test if this is fixed in 2.3.0b18

[niteguide]

Unfortunately not fixed at all (2.3.0.b19).
music-assistant (2).log

[OzGav]

Please check if this is fixed in beta 21

[niteguide]

Thanks!
Looked very promising at first. However after 2:48 hours playtime the chromecast player stopped - exactly at time 08:35:02
log: music-assistant (3).log

[niteguide]

Have recent beta 23 running.
No problems for a very very long time. I started the playlist at time 13:37 and it kept running until time 20:49. At this point chromecast player suddenly stopped in the middle of a song.
log:
music-assistant (4).log

I might add that I have not yet installed 2024.9.0 that just came out.

And I further want to add that I have put the playlist to randomly repeat.

[OzGav]

Ok this will continue to get investigated. The log is helpful.

[nikito]

Bit more logging as well for me, I also tried turning off shuffle and just letting the playlist go. For a while it worked but eventually ran into this:
2024-09-16 08:20:33.431 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 1/3) 2024-09-16 08:20:34.175 WARNING (MainThread) [music_assistant.spotify] librespot failed to stream track, retrying... (attempt 2/3) 2024-09-16 08:20:34.680 WARNING (MainThread) [music_assistant.audio.media_stream] Stream error on spotify--jdi6zRXV://track/53va7kEIt0pn7tOhrTB99q 2024-09-16 08:20:34.706 ERROR (MainThread) [music_assistant.streams] Error streaming QueueItem Jesse Cook/Hampig Djavorian - Luna Llena (Live) (library://track/1849) to Workshop Music 2024-09-16 08:20:35.261 INFO (MainThread) [music_assistant.spotify] Attempt 1/5 failed: Token expired 2024-09-16 08:20:35.261 INFO (MainThread) [music_assistant.spotify] Retrying in 6 seconds...

I am noticing that this seems to happen pretty consistently in my logs when the music just stops playing. Maybe related to the token expiring and not renewing before the next track is requested?

[OzGav]

Thanks. We can see what the problem is. No need for any more followup. When there is news of a fix you will hear it here first.

[niteguide]

Beta 24 came out. This time I first ran into a problem with Apple HomePod Mini: At exactly time 07:51:39 no sound output, while the music appears to be playing within MA (both Chromecast and Airplay started playing at time 06:36).
Log: music-assistant (5).log

[flexmatics]

I have the same issue as identified here

I've updated to 2.3.0b26. Not sure if that was suppossed to fix the issue, but I still get dropped playback of queued tracks.

1. I've noted that in all cases, it just stops playing and on front end it shows like in screenshot (few seconds from the end of track it gets stuck):
   

2. The log with INFO level doesn't say anything relevant. At 09:09 playback was started, it stopped at ~09:30, but nothing noted.

2024-09-21 07:33:45.782 INFO (MainThread) [music_assistant] Starting Music Assistant Server (add8b535ce464403a2cdc585972e4c11) version 2.3.0b26 - HA add-on: True - Safe mode: False
2024-09-21 07:33:45.786 INFO (MainThread) [music_assistant.cache] Initializing cache controller...
2024-09-21 07:33:45.875 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes.
2024-09-21 07:33:45.912 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.1.1 with libsoxr support
2024-09-21 07:33:45.912 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.0.108:8097
2024-09-21 07:33:45.915 INFO (MainThread) [music_assistant.webserver] Starting server on 172.30.32.1:8095 - base url: http://172.30.32.1:8095
2024-09-21 07:33:48.465 INFO (MainThread) [music_assistant] Loaded music provider Music Assistant
2024-09-21 07:33:48.465 INFO (MainThread) [music_assistant] Loaded metadata provider The Audio DB
2024-09-21 07:33:48.466 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz
2024-09-21 07:33:48.466 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv
2024-09-21 07:33:48.478 INFO (MainThread) [music_assistant] Loaded player provider Slimproto (Squeezebox players)
2024-09-21 07:33:48.577 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-09-21 07:33:48.578 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-21 07:33:48.579 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-21 07:33:48.825 INFO (MainThread) [music_assistant.spotify] Successfully logged in to Spotify as Inga
2024-09-21 07:33:48.825 INFO (MainThread) [music_assistant] Loaded music provider Spotify
2024-09-21 07:33:49.873 INFO (MainThread) [music_assistant.slimproto] Player squeezeplay: dc:a6:32:06:9e:c9 connected
2024-09-21 07:33:49.873 INFO (MainThread) [music_assistant.players] Player registered: dc:a6:32:06:9e:c9/squeezeplay: dc:a6:32:06:9e:c9
2024-09-21 07:33:49.876 INFO (MainThread) [music_assistant.slimproto] Player squeezeplay: 00:00:00:00:00:00 connected
2024-09-21 07:33:49.876 INFO (MainThread) [music_assistant.players] Player registered: 00:00:00:00:00:00/squeezeplay: 00:00:00:00:00:00
2024-09-21 07:34:00.806 INFO (MainThread) [music_assistant.music] Sync task for Spotify: Inga completed
2024-09-21 07:34:00.807 INFO (MainThread) [music_assistant.metadata] Starting metadata scanner
2024-09-21 07:34:00.808 INFO (MainThread) [music_assistant.metadata] Metadata scanner finished.
2024-09-21 09:09:05.362 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue living_room - crossfade: False

[niteguide]

Also beta 26 here.
With beta 25 I mainly had problems with Chromecast. This beta it's AirPlay again. No sound exactly since time 9:53. Because in MA the playlist still appears as playing (in my case the track does not appear as stuck in the frontend, as @flexmatics points out), the missing sound output is not shown in the logs, as always, I attach it nevertheless:
music-assistant (6).log

To bring the sound output back, I just have to click on the forward button in the frontend and the playlist continues with the next song.

edit: at time 13:23 also Google Home Mini stopped sound output - Google Cast entity status changed to buffering; MA entity still status playing;

[nikito]

Tried beta 26 as well. The same issue happens where it just stops playing after a few tracks, though i notice noting in the log now. Am I see are the sync task and metadata scan task, nothing else of note.

[nikito]

Just another update I noticed, seems inconsistent for me. Today for instance I've got through 22 tracks so far without a problem. Yesterday it got through something like 16 track before stopping without any error.

EDIT: So far today I am not sure I have even seen it randomly stop. Guess I am getting super lucky!
Spoke too soon, finally stopped without any errors, think it got through 25-30 songs this time though!

[syst3x]

I'm assuming MA uses librespot behind the scenes? Might be related to this PR, which was recently merged into dev. This fixed Spotify issues for several 3rd party applications using librespot under the hood.

librespot-org/librespot#1345