Wrong behaviour after finishing a playlist/album

[JPW21]

Official Spotify Clients jump to the first song in the playlist/album after playing the last one.

Librespot jumps 10 songs back when the playlist is over. For example if the last song in an album is 26, librespot will jump to song number 16 when the last song is over. If the album has 11 or less songs, it goes to the first, which is correct.

This issue would be minor, but this breaks looping any album/list longer than 11 songs.

[ashthespy]

10 tracks seems quite serendipitous ;-)
But does this happen even for non dynamic playlists as well?

We have to revisit this again https://github.com/librespot-org/librespot/pull/305#pullrequestreview-214843475. I would guess we need to either store the initial state's track_vec, and reset to that when we are done.

[JPW21]

But does this happen even for non dynamic playlists as well?

What exactly do you mean with dynamic playlists? I just tried it with the fresh compiled version and could reproduce it on my own custom playlist and on longer albums.

Here is the log after it happens (with repeat on, jumping back to track number 10 from 20 instead of starting at the beginning):

Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_connect::spirc] kMessageTypeLoad ... kPlayStatusPlay
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:album:4JoNzfgF4QuZ0wqlE2CKnZ" index: 10 position_ms: 0 status: kPlayStatusPlay position_measured_at: 1596422483
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_connect::spirc] Frame has 11 tracks
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 68457340032009232544605880416923070790, audio_type: Track }, true, 0)
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z INFO  librespot_playback::player] Loading <Motorball> with Spotify URI <spotify:track:1zbhWUb6w41pIpDaDThHHE>
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_audio::fetch] Downloading file df315d50ef516ed492a09a98d484a5d56800b61b
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 144. Downloaded ranges: (). Pending ranges: ([0, 221183])
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_audio::fetch] Ping time estimated as: 70 ms.
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_audio::fetch] Read at postion 144 completed. 4 bytes returned, 4 bytes were requested.
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -9.059998, track_peak: 1.0517305, album_gain_db: -6.8700027, album_peak: 1.0517305
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z DEBUG librespot_playback::player] Applied normalisation factor: 0.35237095
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z INFO  librespot_playback::player] <Motorball> (314946 ms) loaded
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_playback::player] == Starting sink ==
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:23 hifiberry librespot[7798]: [2020-08-03T02:41:23Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z DEBUG librespot_connect::spirc] kMessageTypeSeek ... kPlayStatusPlay
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z DEBUG librespot_playback::player] command=Seek(299101)
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 13983664. Downloaded ranges: ([0, 999271]). Pending ranges: ([999272, 1059295])
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z DEBUG librespot_audio::fetch] Read at postion 13983664 completed. 27 bytes returned, 27 bytes were requested.
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z TRACE librespot_audio::fetch] Ping time estimated as: 37 ms.
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:25 hifiberry librespot[7798]: [2020-08-03T02:41:25Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Aug 03 04:41:25 hifiberry librespot[7798]: ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 199031886193124570032976963886128878632, audio_type: Track })
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_playback::player] Preloading track
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z INFO  librespot_playback::player] Loading <Unlocking the Past> with Spotify URI <spotify:track:4yxQ5pB4hf9zfqzMZftgVO>
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_audio::fetch] Downloading file 2b36043c460934dea7b9dcb031339f66f8fc2183
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 144. Downloaded ranges: (). Pending ranges: ([0, 221183])
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z TRACE librespot_audio::fetch] Ping time estimated as: 100 ms.
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_audio::fetch] Read at postion 144 completed. 4 bytes returned, 4 bytes were requested.
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -6.840004, track_peak: 1.0325394, album_gain_db: -6.8700027, album_peak: 1.0517305
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_playback::player] Applied normalisation factor: 0.45498785
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 4096. Downloaded ranges: ([0, 4095]). Pending ranges: ([4096, 221183])
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z DEBUG librespot_audio::fetch] Read at postion 4096 completed. 97 bytes returned, 97 bytes were requested.
Aug 03 04:41:26 hifiberry librespot[7798]: [2020-08-03T02:41:26Z INFO  librespot_playback::player] <Unlocking the Past> (232786 ms) loaded
Aug 03 04:41:36 hifiberry librespot[7798]: [2020-08-03T02:41:36Z DEBUG librespot_audio::fetch] File 2b36043c460934dea7b9dcb031339f66f8fc2183 complete
Aug 03 04:41:40 hifiberry librespot[7798]: [2020-08-03T02:41:40Z DEBUG librespot_connect::spirc] At track 11 of 11 <"spotify:album:4JoNzfgF4QuZ0wqlE2CKnZ"> update [true]
Aug 03 04:41:40 hifiberry librespot[7798]: [2020-08-03T02:41:40Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:40 hifiberry librespot[7798]: [2020-08-03T02:41:40Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 199031886193124570032976963886128878632, audio_type: Track }, true, 0)
Aug 03 04:41:40 hifiberry librespot[7798]: [2020-08-03T02:41:40Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Aug 03 04:41:40 hifiberry librespot[7798]: [2020-08-03T02:41:40Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Aug 03 04:42:22 hifiberry librespot[7798]: [2020-08-03T02:42:22Z DEBUG librespot_core::session] Session[0] strong=3 weak=4

[roderickvd]

Is this still the case? If I remember from testing #844 I believe it now does jump to the first track even on albums with more than 10 tracks. I think I had repeat disabled though.

[JPW21]

Yes still happening for me :( Compiled from source today to make sure i have the newest version: librespot 0.2.0 57937a1 (Built on 2021-09-22, Build ID: WZl0JoZA) alsa backend

For example it jumps from 27 to 17, even with repeat disabled.

[roderickvd]

OK thanks for getting back so soon. I'll put it on my list.

[roderickvd]

I just tried, but I can't reproduce this. Can you please post the full command line you are launching librespot with, as well as a full verbose log?

[roderickvd]

Never mind, have been able to reproduce it now!

[roderickvd]

@JPW21 could you please try the fix at #859 and report back?

[edoiks]

I tried #859 but still problem persist. when I have list with 20 elements but I start playback from the last song on the list, after end of the song next song is not the first but tenth from the end. However when I start from the first song on the list all the songs are played.

[roderickvd]

Yes that’s the extent of this fix, only partly. Thanks for verifying. I’ll leave this issue open after merging that PR. The rest of it will require quite a bit more work.

[roderickvd]

Re-opening as it's known that #859 is only a part fix.

[roderickvd]

Reporting back after some time, this remains elusive.

spirc only sends 10 tracks happily saying that you're on position 10 even when you in fact started playback on 53 or whatever. Two things I can think of:

1. Wait and see what happens when we get on the dealer. Who knows it may give us more tracks, I don't know. @devgianlu can you chime in?

2. From the spirc frame we know the context (e.g. the playlist or album). We could use metadata to get the full track list ourselves, then establish the current position on that list by finding the active track gotten from spirc.

Depending on whether #1 will work we can decide to put development time on #2 or spend it on implementing the dealer (not for v0.5 though).

[devgianlu]

I am very of out of the loop on Spotify stuff. It is possible that you need to fetch the entire playlist yourself, but I don't remember it being a problem with the "new API" (which is probably old too now).

[roderickvd]

Thanks for the swift reply in spite of that. I remembered that we get to publish Spirc V3 (actually 3.2.6) support when we publish the device connect state over HTTPS. I will try and do so shortly, see if it will matter for this and a whole slew of other issues coming from these Spirc frame deficiencies.