Fix intermittent soft failures of the player after seeking

[arybczak]

I had issues with "soft" failures of the player after seeking backwards in songs played from Spotify (curiously enough, seeking forward was working fine the vast majority of time).

Soft, because the music was stopping after seeking, but Mopidy behaved like it was playing (i.e. elapsed time counter was moving forward). The sound was returning eventually, but it could take 5 seconds, 10 or 100.

I got nothing interesting from the logs, so I tried clearing the buffered data (which makes sense anyway, because any data buffered so far will be stale after seeking) and it marvelously fixed the issue, i.e. seeking now reliably works.

Though I'm slightly confused why it fixed it :thinking:

[codecov[bot]]

Codecov Report

Merging #293 (8ae039c) into master (7284b4a) will increase coverage by 0.00%. The diff coverage is 100.00%.

@@           Coverage Diff           @@
##           master     #293   +/-   ##
=======================================
  Coverage   96.68%   96.68%           
=======================================
  Files          13       13           
  Lines        1206     1207    +1     
=======================================
+ Hits         1166     1167    +1     
  Misses         40       40           

Impacted Files	Coverage Δ
mopidy_spotify/playback.py	100.00% <100.00%> (ø)

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 7284b4a...8ae039c. Read the comment docs.

[kingosticks]

Yes, I am also confused why this fix worked! There's only ever one buffer in that list, it should just add an almost unnoticeable bit of extra latency to the seek. But maybe there is something going on. Can you give some more details on your hardware so I might try and replicate this? Does how far I seek make a difference?

[kingosticks]

I can get it to fail every time when seeking backwards but never when seeking forwards. In fact, seeking forwards is the way to get it working again. I'm assuming this must have been introduced in the last-minute refactoring of the gapless fix because I am pretty sure this was working for the original fix.

[arybczak]

Sorry for not providing more info earlier. Indeed, that's the same behaviour I'm experiencing. Seeking backwards pretty much never works, but seeking forward almost always does. And yes, seeking forwards fixes the broken state most of the time.

Does this patch also fix the problem for you?

śr., 6 sty 2021, 02:21 użytkownik Nick Steel notifications@github.com napisał:

I can get it to fail every time when seeking backwards but never when seeking forwards. In fact, seeking forwards is the way to get it working again. I'm assuming this must have been introduced in the last-minute refactoring of the gapless fix because I am pretty sure this was working for the original fix.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/mopidy/mopidy-spotify/pull/293#issuecomment-755014559, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAC6USTN3LVTELMOSSO7X23SYO3ITANCNFSM4VEPT3VA .

[arybczak]

The behaviour is very peculiar though, isn't it? Perhaps libspotify is handling backward seeks differently.

The joy of interacting with buggy closed source libraries, eh.

[kingosticks]

I can sort of now see why what we do is a bit weird but don't understand why exactly it breaks our playback. I also don't understand why it only happens when I seek backwards - I have still never had it break when seeking forwards. I guess it's not a big deal, it's not like the fix isn't a sensible thing to do.

This is how I see it:

• We are delivered buffer for time 100 and we hold it.
• We emit the previous held buffer for time 99
• All is good
• We are told to seek back to time 50. We set our timestamp to 50 and we tell libspotify to seek to 50
• We drop anything we are delivered and emit nothing more until libspotify signals to us it has finished seeking
• We are delivered buffer for time 50 and we hold it
• We emit the held buffer for time 100 <-- this is useless and in the case of seeking backwards, also bad
• We are delivered buffer for time 51 and we hold it
• We emit the held buffer for time 50 <-- this is where we want to be
• All should be good, but isn't.

So it seems that feeding it buffer x when the pipeline is supposed to be at y and with x > y is bad. But when y < x it's OK.

The suggested fix to clear the held buffers as part of seeking stops us emitting that useless buffer. Whatever the actual underlying problem is, this seems like the correct thing to do. Maybe if we looked at the GStreamer logs it might help to understand but life is too short.

[kingosticks]

Thanks for fixing this.