Spotify/Sonos skipping tracks

[jstebbins]

What version of Music Assistant has the issue?

2.0.4

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

2024.5.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

Sometimes, when starting playback of the next track in a spotify playlist, the next track only plays for about 1 second then skips to the next track. Sometimes this will happen several times consecutively. Sometimes it will start the next track correctly several times consecutively.

I was previously using the HACS Sonos Card and did not experience this problem. So it's something particular to MA.

How to reproduce

Start playback of a spotify playlist over Sonos (I'm using sonos amp and and port devices). Wait for it to eventually skip a track.

Music Providers

Sonos

Player Providers

Spotify

Full log output

2024-05-15 08:10:04.665 INFO (MainThread) [music_assistant] Starting Music Assistant Server (59c8f5ec2fd5409286340bede8ed8b93) version 2.0.4 - HA add-on: True - Safe mode: False
2024-05-15 08:10:04.691 INFO (MainThread) [music_assistant.cache] Initializing cache controller...
2024-05-15 08:10:04.787 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes.
2024-05-15 08:10:05.591 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 6.0.1 with libsoxr support
2024-05-15 08:10:05.591 INFO (MainThread) [music_assistant.streams] Starting server on 0.0.0.0:8097 - base url: http://192.168.4.138:8097
2024-05-15 08:10:05.607 INFO (MainThread) [music_assistant.webserver] Starting server on 172.30.32.1:8095 - base url: http://172.30.32.1:8095
2024-05-15 08:10:06.211 INFO (MainThread) [music_assistant] Loaded metadata provider TheAudioDB Metadata provider
2024-05-15 08:10:06.212 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz Metadata provider
2024-05-15 08:10:06.212 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv Metadata provider
2024-05-15 08:10:06.212 INFO (MainThread) [music_assistant] Loaded music provider Music Assistant
2024-05-15 08:10:06.340 INFO (MainThread) [music_assistant] Loaded player provider SONOS
2024-05-15 08:10:06.536 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 08:10:06.679 INFO (MainThread) [music_assistant.players] Player registered: RINCON_347E5C0707B201400/Office
2024-05-15 08:10:06.684 WARNING (MainThread) [soco.events_asyncio] Could not bind to 192.168.4.138:1400: [Errno 98] Address already in use
2024-05-15 08:10:06.789 INFO (MainThread) [music_assistant.players] Player registered: RINCON_C438755B67FF01400/Office
2024-05-15 08:10:06.917 INFO (MainThread) [music_assistant.players] Player registered: RINCON_347E5C0708F901400/Bunk Room
2024-05-15 08:10:07.038 INFO (MainThread) [music_assistant.players] Player registered: RINCON_C438755B676301400/Sherri's Studio
2024-05-15 08:10:07.160 INFO (MainThread) [music_assistant.players] Player registered: RINCON_38420B83677601400/Common Areas
2024-05-15 08:10:07.872 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 08:10:07.873 INFO (MainThread) [music_assistant] Loaded music provider Spotify
2024-05-15 08:10:19.813 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-15 08:36:07.566 WARNING (MainThread) [music_assistant.providers.sonos] No recent activity and cannot reach D's Office, marking unavailable
2024-05-15 10:17:59.357 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 11:10:04.908 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 11:10:05.989 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 11:10:15.430 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-15 13:04:30.869 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 13:56:04.059 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 14:10:04.910 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 14:10:15.246 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-15 14:47:40.086 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 15:39:57.893 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 17:10:04.912 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 17:10:05.936 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 17:10:15.326 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-15 20:10:04.915 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 20:10:05.837 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 20:10:15.371 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-15 23:10:04.915 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-15 23:10:05.921 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-15 23:10:15.379 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 02:10:04.920 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 02:10:05.967 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 02:10:15.375 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 05:04:29.124 WARNING (MainThread) [music_assistant.providers.sonos] No recent activity and cannot reach D's Office, marking unavailable
2024-05-16 05:04:40.899 WARNING (MainThread) [music_assistant.providers.sonos] No recent activity and cannot reach Office, marking unavailable
2024-05-16 05:10:04.927 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 05:10:05.969 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 05:10:15.344 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 07:42:26.074 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 07:42:26.075 INFO (MainThread) [music_assistant] Loaded music provider Spotify
2024-05-16 07:42:36.362 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 08:10:04.936 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 08:10:05.902 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 08:10:15.308 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 08:10:25.557 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 09:00:24.661 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 09:50:40.584 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 10:42:51.806 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 11:10:04.991 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 11:10:17.452 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 11:10:20.200 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 11:10:27.684 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 11:33:06.014 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 12:26:36.251 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 13:18:53.224 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 13:51:39.395 INFO (MainThread) [music_assistant.webserver] Starting server on 0.0.0.0:8095 - base url: http://192.168.4.138:8095
2024-05-16 14:10:04.922 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 14:10:05.853 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 14:10:15.436 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 14:10:18.189 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 14:10:25.675 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 15:01:24.700 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 17:10:04.914 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 17:10:05.940 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 17:10:15.258 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 17:10:17.990 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 17:10:25.730 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 20:10:04.923 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 20:10:05.853 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 20:10:15.377 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 20:10:20.190 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 20:10:26.816 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 23:10:04.919 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-16 23:10:05.878 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 23:10:15.268 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-16 23:10:18.069 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-16 23:10:25.585 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 02:10:04.926 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-17 02:10:05.951 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 02:10:15.323 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 02:10:18.201 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 02:10:25.524 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 05:10:04.928 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-17 05:10:05.852 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 05:10:15.345 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 05:10:18.115 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 05:10:25.549 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 07:45:09.902 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 08:10:05.000 INFO (MainThread) [music_assistant.music] Sync task for Music Assistant completed
2024-05-17 08:10:15.431 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 08:10:18.108 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 08:10:25.719 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2024-05-17 08:35:20.819 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 09:26:45.028 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX
2024-05-17 10:18:46.697 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as XXX

Additional information

No response

What version of Home Assistant Core are your running

2024.5.4

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Raspberry Pi

[OzGav]

Firstly can you PLEASE follow the instructions and not paste the log but attach it!

Now do you see QUEUE FLOW MODE in the settings for the player? If so try enabling that and see if that fixes it.

[jstebbins]

queue flow mode does seem to work around the problem.

But... the display of the currently playing item is severely out of sync with the audio that is currently playing. There appears to be several minutes of buffering happening somewhere and the item being displayed is ahead of the audio by a song or two (depending on how long the songs are).

Aside, I find Music Assistant very usable. I'm impressed with what you've done. I'm just reporting the issues I see so that they may someday be addressed.

[Sorjak]

But... the display of the currently playing item is severely out of sync with the audio that is currently playing. There appears to be several minutes of buffering happening somewhere and the item being displayed is ahead of the audio by a song or two (depending on how long the songs are).

I'm experiencing this exact same issue, it's almost like it's moving the next track in the queue to "played" while the track is playing, which then desyncs from the song that's actually playing.

[PyrusofImpetus]

But... the display of the currently playing item is severely out of sync with the audio that is currently playing. There appears to be several minutes of buffering happening somewhere and the item being displayed is ahead of the audio by a song or two (depending on how long the songs are).

I'm experiencing this exact same issue, it's almost like it's moving the next track in the queue to "played" while the track is playing, which then desyncs from the song that's actually playing.

Seconding as I have this issue. I also have the skipping issue when playing from my SMB-mounted UnRaid NAS. Enabling flow mode helped, but occasionally MA seems to skip back to the first song I queued. Also facing the really rough GUI desync when playing. Pausing the active song sometimes snaps it back to the actually active track, but not always.

I'd also like to add once this skip occurs, attempting to skip to the next song will often jump several songs forward.

[OzGav]

All those reporting this please advise if this is only a Spotify / Sonos combination (as that is the issue title) So check with Spotify and some other player and check with some other music provider and Sonos

[PyrusofImpetus]

All those reporting this please advise if this is only a Spotify / Sonos combination

I only have Sonos players, so no other candidates to demo on there. I primarily play music off my NAS mounted via SMB in MA, where I ran into this issue. If I try to play from a Spotify-provided playlist, I have the same problematic behavior. It appears to not be a problem specifically with Spotify and Sonos, but perhaps Sonos in general?

[OzGav]

@jstebbins can you confirm if this is actually a Sonos problem?

[jstebbins]

@jstebbins can you confirm if this is actually a Sonos problem?

I installed HA's Denon Heos integration to test this. So playing through the HA provider to the Heos media player. I have queue flow mode off. Still using a Spotify playlist as my source.

I can not confirm if the problem exists with this setup because the behavior is much much worse. Here's what I see.

• 1st song gets cut short by a couple of seconds
• 2nd song shows correct duration, but current time doesn't reset to 0, keeps running
• At 3rd song, playback stops, display transistion from showing pause button to showing play button. Queue display shows it is ready to play 3rd song.
• Press play button and the 1st song plays again, while the queue shows it skipped one song and is playing the 4th in the queue.
• 1st song gets cut short by a few seconds again.
• Starts playing the 5th queue song, and correctly displays that it is playing the 5th song.
• 5th song gets cut short.
• 6th song plays. Current time display doesn't reset again.
• 2nd song in queue plays again. Queue display shows it is still playing 6th.
• Playback stops again. Queue display shows it is ready to play 7th song.
• Press play and it starts the 1st song again. Queue display shows it is playing the 8th song.

I see a pattern developing here...

[PyrusofImpetus]

To add additional data for the desyncing, Here's an example in my setup. I'm playing queue flow mode on, an album from my SMB share on my NAS (Spotify albums exhibit the same behavior) to one of my Sonos beam soundbars:

1. Play Now (clear queue)
2. First song begins playing on the speaker, but shows the second song as playing ~20 seconds in. The first song is already in the "played" part of the queue despite still playing on the speaker.
3. ~15 seconds later, MA realizes and updates back to the first song, but about 30 seconds too far into the song.
4. If I hit the pause button, MA correctly syncs back up to the correct timestamp in the correct song.
5. When I hit play again, the queue song advances, while the first one continues on the speaker. Pausing no longer resyncs the queue unless I wait ~30 seconds.
6. If I hit the Next button while desynced, I expect the second song to begin, but instead MA seems to think it's already playing the second song, so the queue and the speaker jump to the third song.
7. While synced, if I hit the next button I do get the second song on the speaker, but the queue skips to the third before snapping back to the second ~5 seconds later.
8. If I touch the timestamp and move it manually, the queue advances every single time, and the song on the speaker changes to the next, but neither are in sync with the other (wrong song and timestamp)

I've yet to be able to reproduce the "reset" back to the first song on command, it is still random for me.