Snapcast info out of sync, likely caused by the spotify rate limiter

[chatziko]

What version of Music Assistant has the issue?

2.1.0

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

2024.6.2

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

During the last three days I'm severely hit by the spotify rate limiter, my log is full of Attempt 1/5 failed: Spotify Rate Limiter. Several other users are reporting the same thing in discord.

Apart from the limiter itself being a problem, I noticed that the playing info of snapcast players often becomes out of sync with the music. This is similar to #2402, which however was fixed in the beta, so I believe that the cause this time is the limiter (I cannot be sure of course). MA should be robust when API errors happen, since there is no way to completely avoid them.

Note that Chromecast players are not affected, I never saw the info becoming out of sync, despite having the same limiter messages in the logs.

How to reproduce

The random behaviour of the limiter makes it hard to reproduce the problem, but here's something I can reproduce quite often:

• Clean the cache in the cache controller
• Start playing a song and seek towards its end (or wait).
• When the next song starts:
  • The info of the song immediately appears
  • But the song itself (the audio) is sometimes delayed, I guess because of the limiter (Attempt 1/5 failed is shown in the logs).
  • Although the audio hasn't really started, the playing time is increasing as if the song really started. So if it takes 10 seconds to really start the song the time is showing 0:10.
  • Now the song really starts, but the time is already at 0:10 and keeps increasing, so the time is out of sync (and likely over time becomes more out of sync).

Note that with a chromecast player, I never saw the time increasing without the audio playing, and when the song actually starts the time always resets to 0:00, which might be why the out of sync issue doesn't happen.

Note also that I'm using the internal snapcast server with the default options.

Music Providers

Problem:

• Snapcast

No problem:

• Chromecast

Player Providers

Problem:

• Spotify

No problem:

• Filesystem

Full log output

music-assistant.log

Additional information

No response

What version of Home Assistant Core are your running

2024.7.3

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Generic x86-64 (e.g. Intel NUC)

[OzGav]

@SantiagoSotoC not sure the Spotify issue has anything to do with it but Snapcast has the issue when chromecast does not

[SantiagoSotoC]

@OzGav Chromecast uses flowmode ? Several of the snapcast problems are because of that, Marcel stayed to check it , but for now no news.

I can't from snapcast see what happens with other providers, I just tell the queue controller to start playing

[SantiagoSotoC]

@OzGav I don't think this is even a problem in snapcast, it's the same as the other issue it's something in the core.

[OzGav]

Single reports are difficult. Will see what Marcel thinks when he gets around to this.

[chatziko]

Some more info: since yesterday I'm running a patched version of the server that uses my own spotify client-id, so I'm no longer rate limited. The out of sync issue hasn't appeared since then, supporting my feeling that it's connected to the failed API calls.

Moreover, I still observe the following behaviour regarding the track timer at the end of each track. The timer is never perfrectly alligned, often there is a 1-2 second gap between the songs:

• On snapcast, when a track is over, the timer for the next one immediately starts. When the audio really arrives the timer is often at 0:01 or 0:02.
• On chromecast, when a track is over, the timer stays at the end of that track, until the audio of the next track starts, then it resets to 0:00.

So my theory (which could be completely wrong, of course) is that this behaviour is tolerable under normal circumstances, but under API failures it might take 5 or 10 seconds for the audio to start, in which case the timer will become out of sync (and the error will grow over time).

[SantiagoSotoC]

A few seconds delay in snapcast is normal due to buffering. That makes sense, I can start the playback as it was before with the callback and implement something like debouncing for the snapcast stream state, which was the problem that was avoided with the dryout_ms

[marcelveldt]

I think this issue can be closed now that version 2.2.0 is out with a bunch of bugfixes. Still the real solution would be that snapcast provides some accurate playback progress in its api.

[OzGav]

@chatziko given all of the above information please close this if you feel this issue has been adequately addressed.

[OzGav]

Closing due no follow-up

[chatziko]

Sorry for the late response, I'm currently travelling. There were lots of great changes recently so it makes sense to close the issue, I ll open a new one if needed.