Skip unplayable tracks instead of stopping #474

ashthespy · 2020-05-09T12:04:12Z

Restoring the previous behaviour of skipping unplayable tracks.
Not tested the case when a unplayable track is at the end of a playlist though..

Yeah, sorry; here's one example:

https://open.spotify.com/playlist/4HrLayxlfZuW8YNwuK1g41?si=6_9XTofvTSW1ry4IY-95eg

spotify:playlist:4HrLayxlfZuW8YNwuK1g41

Originally posted by @pachulo in balbuze/volumio-plugins#266 (comment)

@kaymes Do you see any issues?

kaymes · 2020-05-10T04:23:58Z

Looking at the code without testing it, it should work.

The only issue I can see is that there won't be gapless playback if tracks are skipped. In case of an unplayable track, the preloading is attempted and fails. And then when the actual playback command comes, another load attempt for the same track is made and fails, too. Then the next track is loaded. Thus there will be a gap for two loading cycles until playback resumes.

The issue potentially gets worse if there is more than one track to skip.

I don't know how often unplayable tracks occur and how much effort is justified to handle them gaplessly. Doing so is probably a bit more involved because of the required interaction with spirc.

pachulo · 2020-05-10T12:15:19Z

Please ignore if I'm saying stuping things; I'm just a user not familiar with the code.

In case of an unplayable track, the preloading is attempted and fails. And then when the actual playback command comes, another load attempt for the same track is made and fails, too. Then the next track is loaded. Thus there will be a gap for two loading cycles until playback resumes.

@kaymes couldn't it just avoid queuing these tracks?

I don't know how often unplayable tracks occur and how much effort is justified to handle them gaplessly. Doing so is probably a bit more involved because of the required interaction with spirc.

I've only found this with playlists that I've been doing over the years, where some songs that use to be available aren't any more, but IMHO there's no problem with loosing gapless playback for those.

Thanks a lot for this!

ashthespy · 2020-05-10T12:41:36Z

@kaymes I went ahead and patched in the prefetching support as well. On looking at it with a fresh pair of eyes this morning, I feel it can be much more elegant, by just adding a prev_track_id to the PlayerPreload::Loading state enum, and incrementing the preload_index. Although technically a u32 is better to carry around than a SpotifyId..
If you see a simpler way as well, let me know!

Testing with this spotify:playlist:5NcULAQYuqV2tjJZ9R5LRg

awiouy · 2020-05-12T06:33:38Z

@ashthespy is this ready to merge?

ashthespy · 2020-05-12T06:37:30Z

~~It works, but~~ I'd prefer @kaymes giving it once over, as he's most familiar with the player code..

kaymes · 2020-05-12T10:31:00Z

@ashthespy at quick glance it doesn't feel quite right. But I don't have time right now. I'll have a closer look tomorrow.

kaymes · 2020-05-13T06:40:50Z

I just had a look at the code. I didn't actually run it so there is a chance I missed a subtlety somewhere. Just from looking at it I don't think it works as desired.

This is how I understand it:
The code will issue more preload requests until there is one that loads ok and then this one will get preloaded.
(I didn't check if there's a possibility for an endless loop in case the entire playlist ends up unplayable).

Now, when the track actually finishes, the play commands come in as before. Thus the track that is passed to handle_command_load is not the one that has been pre-loaded. Thus it is attempted to load the track that has already been attempted to be loaded in vain. This also has the effect of the preloaded track being discarded. Thus the whole preloading is just lost.

Thus gapless playback isn't achieved and we might as well merge the initial version which was a lot simpler.

Possible solution
Of course, there are many ways of achieving gapless skipping. Here is one that I can see that should work:

I would communicate the failed SpotifyId back to spirc. You could add it as an option to PlayerEvent::TimeToPreloadNextTrack or define a dedicated player event, PlayerEvent::PreloadFailed{spotify_id}.
Spirc's SpircPlayStatus::{Playing,Paused} gets a new Vec of SpotifyIds that failed to preload. This allows Spirc to skip the tracks that have failed to preload.
The logic to skip unplayable tracks is already in get_track_id_to_play_from_playlist. If the while loop simply checks the candidates against the list of failed tracks in SpircPlayStatus::{Playing,Paused}, everything should just work as desired.
(note: when doing this, you can also get rid of the preload_index/preview_index because the next track will always the next playable one)

I was also wondering whether get_track_id_to_play_from_playlist can already see which tracks won't be able to load. There is already SpotifyAudioType::NonPlayable which is checked, but maybe there are other fields that could be used to indicate whe

ashthespy · 2020-05-13T09:00:00Z

I just see that I messed up while force pushing, with an incomplete implementation. Sorry for wasting you time..
I'll take your suggestions and revise this later this evening when I get back. Apologies again!

… skip_unplayable

ashthespy · 2020-05-13T10:41:59Z

Okay, this should be much simpler - what do you think?

Log of a playlist with unavailable tracks

[2020-05-13T10:27:36Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:user:xx:playlist:5NcULAQYuqV2tjJZ9R5LRg" index: 0 position_ms: 1284 status: kPlayStatusPause position_
measured_at: 1589365656625 context_description: "Missing the 80s" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 0 track {gid: "\320\307\344As\233M\246\
245\210\004\357\220\227\261\317"} track {gid: "4\250\370\013b\371I\352\243W\220$\301\031C~"} track {gid: "\246\307\230\010_@B\005\244\230\240\007L;\274\""} track {gid: "\321\342\356\tL\242C\
370\221\200n\253No:S"} track {gid: "\351\026\363@\201\365NV\207\037\316\037\275+\214\350"} track {gid: "\350\253\035\304\200\353D\251\235\374a'\342,\234;"} track {gid: "\355\367\034\rH]G\374
\214#\026\001\321aj\354"} track {gid: "\327Mo\204\274\206@\257\233\226\030\220\264\022z\317"} track {gid: "\003\207vB\346;N\356\270\225^E\025\014e\371"}
[2020-05-13T10:27:36Z DEBUG librespot_connect::spirc] Frame has 9 tracks
[2020-05-13T10:27:36Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 277517319773109654597909477525433070031, audio_type: Track }, false, 1284)
[2020-05-13T10:27:36Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusLoading]
[2020-05-13T10:27:36Z INFO  librespot_playback::player] Loading <Major Tom> with Spotify URI <spotify:track:6lXKNdOsnaLv9LwulZbxNl>
[2020-05-13T10:27:36Z DEBUG librespot_core::audio_key] new AudioKeyManager
[2020-05-13T10:27:36Z DEBUG librespot_audio::fetch] File 112829cc4a3f42cd15fec5a799db37e71d92c7e7 already in cache
[2020-05-13T10:27:36Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -5.529999, track_peak: 1.0630234, album_gain_db: -5.080002, album_peak: 1.19040
81 }
[2020-05-13T10:27:36Z DEBUG librespot_playback::player] Applied normalisation factor: 0.5290541
[2020-05-13T10:27:36Z INFO  librespot_playback::player] <Major Tom> (299560 ms) loaded
[2020-05-13T10:27:36Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2020-05-13T10:27:36Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2020-05-13T10:27:36Z DEBUG librespot_connect::spirc] kMessageTypeNotify "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 227758080 1589365656860 kPlayStatusStop
[2020-05-13T10:27:43Z DEBUG librespot_connect::spirc] kMessageTypePlay "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 227764414 1589365656860 kPlayStatusPause
[2020-05-13T10:27:43Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:27:43Z DEBUG librespot_playback::player] command=Play
[2020-05-13T10:27:43Z TRACE librespot_playback::player] == Starting sink ==
[2020-05-13T10:27:43Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:27:43Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:27:52Z DEBUG librespot_connect::spirc] kMessageTypeSeek "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 227773305 1589365663239 kPlayStatusPlay
[2020-05-13T10:27:52Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:27:52Z DEBUG librespot_playback::player] command=Seek(235707)
[2020-05-13T10:27:52Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:28:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 69997192592771872256401199735544300414, audio_type: Track })
[2020-05-13T10:28:25Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:28:25Z INFO  librespot_playback::player] Loading <White Wedding - Part 1> with Spotify URI <spotify:track:1BmOQ94SgATSokQdOUTj1I>
[2020-05-13T10:28:25Z DEBUG librespot_audio::fetch] File a183491ae799fc29e8751a2073491e3df32b1732 already in cache
[2020-05-13T10:28:25Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -1.4599991, track_peak: 0.82888156, album_gain_db: -6.830002, album_peak: 1.1227702 }
[2020-05-13T10:28:25Z DEBUG librespot_playback::player] Applied normalisation factor: 0.8452789
[2020-05-13T10:28:25Z INFO  librespot_playback::player] <White Wedding – Part 1> (214573 ms) loaded
[2020-05-13T10:28:55Z DEBUG librespot_connect::spirc] At track 1 of 9 <"spotify:user:xxxx:playlist:5NcULAQYuqV2tjJZ9R5LRg"> update [false]
[2020-05-13T10:28:55Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 69997192592771872256401199735544300414, audio_type: Track }, true, 0)
[2020-05-13T10:28:55Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:28:55Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:28:58Z DEBUG librespot_connect::spirc] kMessageTypeSeek "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 227840016 1589365736156 kPlayStatusPlay
[2020-05-13T10:28:58Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:28:58Z DEBUG librespot_playback::player] command=Seek(159565)
[2020-05-13T10:28:58Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:29:23Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 221688197964708279733893794639650733090, audio_type: Track })
[2020-05-13T10:29:23Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:29:23Z INFO  librespot_playback::player] Loading <Dancing With Myself - 2001 Digital Remaster> with Spotify URI <spotify:track:54HWkXBa3O7jH4vletYhc6>
[2020-05-13T10:29:23Z WARN  librespot_playback::player] <spotify:track:54HWkXBa3O7jH4vletYhc6> is not available
[2020-05-13T10:29:23Z WARN  librespot_playback::player] Unable to preload SpotifyId { id: 221688197964708279733893794639650733090, audio_type: Track }
[2020-05-13T10:29:23Z DEBUG librespot_playback::player] Signaling unavilable: 1
[2020-05-13T10:29:23Z DEBUG librespot_connect::spirc] Removing unavailable track_ref at 1
[2020-05-13T10:29:23Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 278986938159332447919914684866834152019, audio_type: Track })
[2020-05-13T10:29:23Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:29:24Z INFO  librespot_playback::player] Loading <Love Is In The Air - Original> with Spotify URI <spotify:track:6o36q5KrEhVKuhAIUQQMkr>
[2020-05-13T10:29:24Z WARN  librespot_playback::player] <spotify:track:6o36q5KrEhVKuhAIUQQMkr> is not available
[2020-05-13T10:29:24Z WARN  librespot_playback::player] Unable to preload SpotifyId { id: 278986938159332447919914684866834152019, audio_type: Track }
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Signaling unavilable: 1
[2020-05-13T10:29:24Z DEBUG librespot_connect::spirc] Removing unavailable track_ref at 1
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 309829287285129375896746820873197685992, audio_type: Track })
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:29:24Z INFO  librespot_playback::player] Loading <The Hustle - Original Mix> with Spotify URI <spotify:track:75PHqzep3Lf11sIYP5ps5q>
[2020-05-13T10:29:24Z WARN  librespot_playback::player] <spotify:track:75PHqzep3Lf11sIYP5ps5q> is not available
[2020-05-13T10:29:24Z WARN  librespot_playback::player] Unable to preload SpotifyId { id: 309829287285129375896746820873197685992, audio_type: Track }
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Signaling unavilable: 1
[2020-05-13T10:29:24Z DEBUG librespot_connect::spirc] Removing unavailable track_ref at 1
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 309269381543406799806960686689866783803, audio_type: Track })
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:29:24Z INFO  librespot_playback::player] Loading <Terra Titanic> with Spotify URI <spotify:track:752q3k1ds8JckA7tIakICn>
[2020-05-13T10:29:24Z DEBUG librespot_audio::fetch] File 2c50f098afa5e06c7581935f0795757e2e559f57 already in cache
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -6.9300003, track_peak: 1.1261528, album_gain_db: -5.080002, album_peak: 1.1904081 }
[2020-05-13T10:29:24Z DEBUG librespot_playback::player] Applied normalisation factor: 0.45029798
[2020-05-13T10:29:24Z INFO  librespot_playback::player] <Terra Titanic> (274706 ms) loaded
[2020-05-13T10:29:25Z DEBUG librespot_core::session] Session[0] strong=3 weak=3
[2020-05-13T10:29:53Z DEBUG librespot_connect::spirc] At track 2 of 6 <"spotify:user:xxx:playlist:5NcULAQYuqV2tjJZ9R5LRg"> update [true]
[2020-05-13T10:29:53Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 309269381543406799806960686689866783803, audio_type: Track }, true, 0)
[2020-05-13T10:29:53Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:29:53Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:30:58Z DEBUG librespot_connect::spirc] kMessageTypeSeek "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 227960169 1589365793816 kPlayStatusPlay
[2020-05-13T10:30:58Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:30:58Z DEBUG librespot_playback::player] command=Seek(203285)
[2020-05-13T10:30:58Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:31:25Z DEBUG librespot_core::session] Session[0] strong=3 weak=3
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 316310101284913869989716299886473865964, audio_type: Track })
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:31:40Z INFO  librespot_playback::player] Loading <Don´t Scratch Your Vinyl - Interlude> with Spotify URI <spotify:track:7f26SfPivhnPaZNrO9uOTO>
[2020-05-13T10:31:40Z WARN  librespot_playback::player] <spotify:track:7f26SfPivhnPaZNrO9uOTO> is not available
[2020-05-13T10:31:40Z WARN  librespot_playback::player] Unable to preload SpotifyId { id: 316310101284913869989716299886473865964, audio_type: Track }
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] Signaling unavilable: 2
[2020-05-13T10:31:40Z DEBUG librespot_connect::spirc] Removing unavailable track_ref at 1
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 286186087815793034997112511788613794511, audio_type: Track })
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:31:40Z INFO  librespot_playback::player] Loading <Joy - Original> with Spotify URI <spotify:track:6ygJMIdIuX1wDdKsMrAOqH>
[2020-05-13T10:31:40Z DEBUG librespot_audio::fetch] File ea7f60871739f2200659c3071cbae591be736c93 already in cache
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -5.92, track_peak: 1.1399819, album_gain_db: -8.17, album_peak: 1.2050169 }
[2020-05-13T10:31:40Z DEBUG librespot_playback::player] Applied normalisation factor: 0.5058247
[2020-05-13T10:31:40Z INFO  librespot_playback::player] <Joy> (262169 ms) loaded
[2020-05-13T10:32:10Z DEBUG librespot_connect::spirc] At track 3 of 5 <"spotify:user:xxxxx:playlist:5NcULAQYuqV2tjJZ9R5LRg"> update [true]
[2020-05-13T10:32:10Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 286186087815793034997112511788613794511, audio_type: Track }, true, 0)
[2020-05-13T10:32:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:32:10Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:32:17Z DEBUG librespot_connect::spirc] kMessageTypeSeek "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 228038354 1589365930728 kPlayStatusPlay
[2020-05-13T10:32:17Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:32:17Z DEBUG librespot_playback::player] command=Seek(187869)
[2020-05-13T10:32:17Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:32:18Z DEBUG librespot_connect::spirc] kMessageTypeSeek "ASHXPS15" 2e4c3f0d6c618cbc37d5ebdd3fcd3a67f0ac6838 228039879 1589365937181 kPlayStatusPlay
[2020-05-13T10:32:18Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2020-05-13T10:32:18Z DEBUG librespot_playback::player] command=Seek(211914)
[2020-05-13T10:32:18Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 4691042687902157817597368163352995321, audio_type: Track })
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:32:38Z INFO  librespot_playback::player] Loading <Jezabel - Original> with Spotify URI <spotify:track:06ESLhItfc6xyCZlYwtdmp>
[2020-05-13T10:32:38Z WARN  librespot_playback::player] <spotify:track:06ESLhItfc6xyCZlYwtdmp> is not available
[2020-05-13T10:32:38Z WARN  librespot_playback::player] Unable to preload SpotifyId { id: 4691042687902157817597368163352995321, audio_type: Track }
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] Signaling unavilable: 3
[2020-05-13T10:32:38Z DEBUG librespot_connect::spirc] Removing unavailable track_ref at 1
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 277517319773109654597909477525433070031, audio_type: Track })
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] Preloading track
[2020-05-13T10:32:38Z INFO  librespot_playback::player] Loading <Major Tom> with Spotify URI <spotify:track:6lXKNdOsnaLv9LwulZbxNl>
[2020-05-13T10:32:38Z DEBUG librespot_audio::fetch] File 112829cc4a3f42cd15fec5a799db37e71d92c7e7 already in cache
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -5.529999, track_peak: 1.0630234, album_gain_db: -5.080002, album_peak: 1.1904081 }
[2020-05-13T10:32:38Z DEBUG librespot_playback::player] Applied normalisation factor: 0.5290541
[2020-05-13T10:32:38Z INFO  librespot_playback::player] <Major Tom> (299560 ms) loaded
[2020-05-13T10:33:08Z DEBUG librespot_connect::spirc] At track 4 of 4 <"spotify:user:xxxx:playlist:5NcULAQYuqV2tjJZ9R5LRg"> update [true]
[2020-05-13T10:33:08Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 277517319773109654597909477525433070031, audio_type: Track }, false, 0)
[2020-05-13T10:33:08Z TRACE librespot_playback::player] == Stopping sink ==
[2020-05-13T10:33:08Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2020-05-13T10:33:08Z TRACE librespot_connect::spirc] ==> kPlayStatusPause

Two questions

Should we remove the item from the queue as currently, or mark it as NonPlayable?
Can we directly use the Fetcher to check if a track_id has a corresponding file?

@kaymes looks like 6fed8d0 breaks the track cycling -
index should be new_playlist_index..?

librespot/connect/src/spirc.rs

Lines 1155 to 1175 in 0056400

    
           let mut track_ref = self.state.get_track()[new_playlist_index as usize].clone(); 
        
           let mut track_id = self.get_spotify_id_for_track(&track_ref); 
        
           while track_id.is_err() || track_id.unwrap().audio_type == SpotifyAudioType::NonPlayable { 
        
               warn!( 
        
                   "Skipping track <{:?}> at position [{}] of {}", 
        
                   track_ref.get_uri(), 
        
                   new_playlist_index, 
        
                   tracks_len 
        
               ); 
        
               new_playlist_index += 1; 
        
               if new_playlist_index >= tracks_len { 
        
                   new_playlist_index = 0; 
        
               } 
        
               if new_playlist_index == start_index { 
        
                   warn!("No playable track found in state: {:?}", self.state); 
        
                   return None; 
        
               } 
        
               track_ref = self.state.get_track()[index as usize].clone(); 
        
               track_id = self.get_spotify_id_for_track(&track_ref);

Flag them as `NonPlayable` instead of removing them from the queue

kaymes · 2020-05-13T13:37:17Z

index should be new_playlist_index..?

Looks like I overlooked to rename the "index" and also pushed an incomplete change. My bad, sorry about that. new_playlist_index makes more sense.

The code looks much better now. Only the get_track_index_for_spotify_id() method worries me a little. What happens if the play list contains an unplayable track multiple times?

Should we remove the item from the queue as currently, or mark it as NonPlayable?

Regarding removing / marking unplayable: I'd replicate whatever behaviour the official client does. From memory it just skips tracks without removing them. But I could be wrong.

Can we directly use the Fetcher to check if a track_id has a corresponding file?

Not the way it is currently implemented. But there's nothing wrong with a little refactoring if you think it's useful.
You'd have to refactor the first two blocks of load_track(): the AudioItem::get_audio_item and the find_available_alternative() parts.
The tricky thing is, that both of them are blocking. There's a wait() in the first and find_available_alternatives() has another wait() inside. Those would have to get refactored into properly chained futures.
Then Spirc could use this new future to analyse the playlist upfront and mark all tracks that aren't playable. This probably requires another bunch of annoying boiler plate code to launch and poll those futures correctly.
So... doable? yes. Worth it? not sure...

ashthespy · 2020-05-13T21:03:06Z

Okay, changed a few more things to make it less janky..

The code looks much better now. Only the get_track_index_for_spotify_id() method worries me a little. What happens if the play list contains an unplayable track multiple times?

While it worked initially as we were removing each missing instance, the current implementation should cover more bases.

Regarding removing / marking unplayable: I'd replicate whatever behaviour the official client does. From memory it just skips tracks without removing them. But I could be wrong.

Hmm, we are just removing the track from the queue, not the Frame, so it should be the similar behaviour in the client - the track just skips, and the right track is highlighted in the client (tested on windows).
While testing later, found it led to funky stuff when the playlist ended, due to the miss match.

So, It's now a bit involved, to mark it NonPlayable as we don't store a vec of spotifiy_ids in spirc but use the Frame's vec track from the protobuf directly. Which contains only a gid, uri, queued and context. I went with the context field, and misuse it to mark it as unplayable..

Hopefully when we transition to a SpotifyObjectId, we can streamline these things..

Malvineous · 2020-05-27T04:29:49Z

Just started testing this. It seems to work really well. It can handle multiple blocked tracks in a row, the preloader remembers the unavailable tracks and skips them all in one go (as opposed to the old behaviour of trying to load them one by one until the next available track was encountered) and although I haven't been testing it for long, I haven't been able to get it to break yet. Nice job!

The only odd thing I've noticed is that in the debugging messages it looks like the track name is not available:

WARN  librespot_connect::spirc] Skipping track <""> at position [5] of 15
WARN  librespot_connect::spirc] Skipping track <""> at position [6] of 15
WARN  librespot_connect::spirc] Skipping track <""> at position [7] of 15
WARN  librespot_connect::spirc] Skipping track <""> at position [8] of 15
WARN  librespot_connect::spirc] Skipping track <""> at position [9] of 15
WARN  librespot_connect::spirc] Skipping track <""> at position [10] of 15

It's no big deal but I guess if that information isn't there, there's no need to print a blank string.

Malvineous · 2020-05-27T09:43:07Z

Found a bug. If the first song in a playlist is blocked, when you get near the end of the last track in the playlist, it tries to preload the first song, fails because it's unavailable, and then librespot crashes with an assertion failure in spirc.rs:1185:

DEBUG librespot_playback::player] Unable to preload SpotifyId { id: 123, audio_type: Track }
thread 'main' panicked at 'assertion failed: !index.is_empty()', connect/src/spirc.rs:1185:9

To reproduce, create a new playlist, add a blocked song as the first one, and a normal song as the second. Start playing the second song, and skip to about 40 seconds before the end. Once you hit 30 seconds from the end the preloader will kick in and the assertion will fail.

Note that it only crashes when it tries to preload the blocked first song. If you are skipping songs or all songs in the list are blocked, it won't preload anything and will loop around to the start of the list just fine.

ashthespy · 2020-05-27T10:21:07Z

Found a bug. If the first song in a playlist is blocked, when you get near the end of the last track in the playlist, it tries to preload the first song, fails because it's unavailable, and then librespot crashes with an assertion failure in spirc.rs:1185:

Ah, that debug assertion is actually counter intuitive in this case - as the index is indeed 0. I am not near my dev machine, but it should work fine when it's compiled in --release mode..

Malvineous · 2020-05-27T10:40:43Z

Rather than compile in --release, I just commented out the offending debug_assert figuring that does the same thing? However now when it preloads the first blocked track, instead of aborting, it gets stuck in a loop, trying and failing to preload that same blocked track over and over again.

No rush with a fix, it can wait until you've got time to investigate.

ashthespy · 2020-05-27T11:00:27Z

That does indeed make sense - will have a look.. Hopefully this is the last edge case we need to check for ;-)

@Malvineous I was trying to be cheeky and search for the unplayable track_id only from the current playing index. Hence it would fail in the scenario you described.
Added a check that cycles back to the start of playlist if we are at the end, so it should be good to go now. Do let me know if you find more issues!

Malvineous · 2020-05-28T03:55:24Z

Nice job, that fixed the issue!

If I read the fix correctly though, the cycle only jumps back to the first song when you're listening to the last song in the playlist. If you're on any other song then it won't jump back?

I tried a playlist where both the first and the last song are blocked, and I get the same error:

thread 'main' panicked at 'assertion failed: !index.is_empty()', connect/src/spirc.rs:1189:9

If I comment out the debug_assert() then it again gets stuck in a loop, forever trying and failing to preload the first (blocked) song in the playlist.

I guess the search for the next available song should start at the track following the current one no matter what position it is in the playlist, but when it gets to the end of the playlist, then it should loop back to the first song and keep going? It does seem to do this correctly (looping and stopping just prior to the current song) but only if the current song is last in the playlist.

Some experiments have also revealed some other possible bugs. If there is an album with only one playable song on it, then even if it does loop around correctly, the preloader is going to stop just before the currently playing song and come up empty handed, having found every other song in the playlist unplayable. This also seems to trigger the assertion failure, as the preloader seems to require finding at least one playable song to get ready.

Likewise sometimes I remove songs from the playlist once I have listened to them, occasionally ending up "playing" a playlist composed entirely of blocked songs. In this case the preloader would definitely come up empty handed and presumably complain there too.

I think that as well as correctly looping back to the start of the playlist when looking for the next song to play, the preloader should be able to cope with finding no suitable song to preload, and gracefully fall back to the old behaviour without preloading.

This way a single-unblocked-song playlist would either loop or stop depending on autorepeat settings, and if it chose to loop, the song would already be cached so the preloading may not be as critical. It would also handle the admittedly rare case of playing a list containing only blocked songs.

ashthespy · 2020-05-28T12:21:53Z

@Malvineous I came across the same issues last evening, forgot to push it..

I guess the search for the next available song should start at the track following the current one no matter what position it is in the playlist, but when it gets to the end of the playlist, then it should loop back to the first song and keep going? It does seem to do this correctly (looping and stopping just prior to the current song) but only if the current song is last in the playlist.

Now, we first search from (playing_index..playlist.len()) for the particular track_id. If we don't find it, we try again, from the beginning of the playlist. If we still don't find it, something is wrong..

Malvineous · 2020-05-28T12:54:22Z

As long as it doesn't crash or get stuck in a loop when it can't find a suitable next song, then all good :)

ashthespy · 2020-05-28T13:53:10Z

That is the general idea ;-)
I was just trying to avoid searching from the start of the playlist for the track_id each time, so now we do it only if we have reached the end. There are still some optimisations we can do to avoid re searching from (start..playing_index) , but will leave that for a later, when we refactor this whole "marking as unplayable' logic..

If there are no further issues will merge this tonight..

kaymes · 2020-05-28T14:04:27Z

I haven't tested it. But from reviewing the code I'm worried about what happens when the first and last track of a playlist are the same track which isn't playable and you are playing the second last track without having attempted to play the first one.
I think in this case you would only mark the last track as unplayable but never the first one.

ashthespy · 2020-05-28T14:25:05Z

Hmm, your right - instead of handling all these edge cases, and micro optimise this, I guess the simplest way is to scan through the entire playlist each time.

Given that we shouldn't encounter unplayable(s) with context/dynamic playlists, and we aren't dealing with couple of thousand tracks in the playlist, it should be fine to just scan through them for each unplayable we encounter.

Malvineous · 2020-06-10T06:23:05Z

FYI I've been using this every day for two weeks now and haven't run into any problems, so I would have no issues if it were merged. Yes there are probably one or two edge cases still there but in my opinion the benefits are worth it.

sashahilton00 · 2020-07-22T16:27:18Z

@ashthespy are you happy to merge this once you and @kaymes are happy with the code?

ashthespy · 2020-07-22T17:18:47Z

Hmm, your right - instead of handling all these edge cases, and micro optimise this, I guess the simplest way is to scan through the entire playlist each time.

This is what it does now, not had any reports of issues for a few months now from anyone using the plugin - LGTM ;-)

Skip unplayable tracks instead of stopping

b631997

awiouy approved these changes May 10, 2020

View reviewed changes

Handle unplayable tracks during prefetch

9024409

ashthespy force-pushed the skip_unplayable branch from b5dde82 to 9024409 Compare May 10, 2020 12:54

ashthespy added 2 commits May 13, 2020 11:49

Let spirc handle unavailable tracks

14709b9

Merge branch 'dev' of https://github.com/librespot-org/librespot into…

172cb94

… skip_unplayable

ashthespy added 2 commits May 13, 2020 13:24

Fix regression in track cycling

9cacc2d

Tweak unavailable track handling

01813cf

Flag them as `NonPlayable` instead of removing them from the queue

ashthespy force-pushed the skip_unplayable branch from 504ba87 to 01813cf Compare May 13, 2020 20:58

kaymes mentioned this pull request May 27, 2020

Regression: Playback stops when a blocked song is encountered #484

Closed

ashthespy added 2 commits May 27, 2020 16:24

Handle unplayable track at start of playlist

1da80ce

Tweak handling unavailables at start of playlists

a28199f

Search through full playlist for unplayable tracks

16112d7

sashahilton00 merged commit 43ab7fc into librespot-org:dev Jul 24, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Skip unplayable tracks instead of stopping #474

Skip unplayable tracks instead of stopping #474

ashthespy commented May 9, 2020 •

edited

kaymes commented May 10, 2020

pachulo commented May 10, 2020 •

edited

ashthespy commented May 10, 2020

awiouy commented May 12, 2020

ashthespy commented May 12, 2020 •

edited

kaymes commented May 12, 2020

kaymes commented May 13, 2020

ashthespy commented May 13, 2020 •

edited

ashthespy commented May 13, 2020 •

edited

kaymes commented May 13, 2020

ashthespy commented May 13, 2020

Malvineous commented May 27, 2020

Malvineous commented May 27, 2020

ashthespy commented May 27, 2020

Malvineous commented May 27, 2020 •

edited

ashthespy commented May 27, 2020 •

edited

Malvineous commented May 28, 2020

ashthespy commented May 28, 2020 •

edited

Malvineous commented May 28, 2020

ashthespy commented May 28, 2020

kaymes commented May 28, 2020

ashthespy commented May 28, 2020

Malvineous commented Jun 10, 2020

sashahilton00 commented Jul 22, 2020

ashthespy commented Jul 22, 2020

Skip unplayable tracks instead of stopping #474

Skip unplayable tracks instead of stopping #474

Conversation

ashthespy commented May 9, 2020 • edited

kaymes commented May 10, 2020

pachulo commented May 10, 2020 • edited

ashthespy commented May 10, 2020

awiouy commented May 12, 2020

ashthespy commented May 12, 2020 • edited

kaymes commented May 12, 2020

kaymes commented May 13, 2020

ashthespy commented May 13, 2020 • edited

ashthespy commented May 13, 2020 • edited

Two questions

kaymes commented May 13, 2020

ashthespy commented May 13, 2020

Malvineous commented May 27, 2020

Malvineous commented May 27, 2020

ashthespy commented May 27, 2020

Malvineous commented May 27, 2020 • edited

ashthespy commented May 27, 2020 • edited

Malvineous commented May 28, 2020

ashthespy commented May 28, 2020 • edited

Malvineous commented May 28, 2020

ashthespy commented May 28, 2020

kaymes commented May 28, 2020

ashthespy commented May 28, 2020

Malvineous commented Jun 10, 2020

sashahilton00 commented Jul 22, 2020

ashthespy commented Jul 22, 2020

ashthespy commented May 9, 2020 •

edited

pachulo commented May 10, 2020 •

edited

ashthespy commented May 12, 2020 •

edited

ashthespy commented May 13, 2020 •

edited

ashthespy commented May 13, 2020 •

edited

Malvineous commented May 27, 2020 •

edited

ashthespy commented May 27, 2020 •

edited

ashthespy commented May 28, 2020 •

edited