Autoplay is not working

[PocketMiner82]

Describe the bug When using librespot with the described command, autoplay doesn't work: Either the same song gets repeated over and over again or the last selected radio/playlist/album gets played instead.

To reproduce Steps to reproduce the behavior:

1. Use the following command to start librespot: librespot --disable-audio-cache -n "mycroft-librespot" -b 320 --mixer alsa --enable-volume-normalisation --autoplay on --volume-ctrl linear --verbose. I also tried this command with the same result: librespot --disable-audio-cache -n "mycroft-librespot" -b 320 --mixer alsa --enable-volume-normalisation --autoplay --volume-ctrl linear --verbose.
2. Connect with the device in the (Android) spotify app
3. In the app, play a song.
4. Try to press the "Next" button, the song will repeat.
5. If you previously played a radio over librespot, this radio will play, even if the selected song is entirely different from the radio.

Log

Log

``` [2023-09-25T20:29:34Z INFO librespot] librespot 0.4.2 UNKNOWN (Built on 2023-09-25, Build ID: wdnG81uE, Profile: release) [2023-09-25T20:29:34Z TRACE librespot] Command line argument(s): [2023-09-25T20:29:34Z TRACE librespot] disable-audio-cache [2023-09-25T20:29:34Z TRACE librespot] n "mycroft-librespot" [2023-09-25T20:29:34Z TRACE librespot] b "320" [2023-09-25T20:29:34Z TRACE librespot] mixer "alsa" [2023-09-25T20:29:34Z TRACE librespot] enable-volume-normalisation [2023-09-25T20:29:34Z TRACE librespot] autoplay [2023-09-25T20:29:34Z TRACE librespot] volume-ctrl "linear" [2023-09-25T20:29:34Z TRACE librespot] verbose [2023-09-25T20:29:34Z WARN librespot] Alsa specific options have no effect if the alsa backend is not enabled at build time. [2023-09-25T20:29:34Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:46221 [2023-09-25T20:29:55Z DEBUG librespot_discovery::server] POST "/" {} [2023-09-25T20:29:55Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070 [2023-09-25T20:29:55Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443 [2023-09-25T20:29:55Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80 [2023-09-25T20:29:55Z INFO librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070" [2023-09-25T20:29:55Z INFO librespot_core::session] Authenticated as "87zak4din53ffbyaelpp59uia" ! [2023-09-25T20:29:55Z DEBUG librespot_core::session] new Session[0] [2023-09-25T20:29:55Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Linear [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Type: Auto [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Pregain: 0.0 dB [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Threshold: -2.0 dBFS [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Method: Dynamic [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Attack: 5 ms [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Release: 100 ms [2023-09-25T20:29:55Z DEBUG librespot_playback::player] Normalisation Knee: 5 dB [2023-09-25T20:29:55Z DEBUG librespot_connect::spirc] new Spirc[0] [2023-09-25T20:29:55Z DEBUG librespot_connect::spirc] canonical_username: 87zak4din53ffbyaelpp59uia [2023-09-25T20:29:55Z DEBUG librespot::component] new MercuryManager [2023-09-25T20:29:55Z DEBUG librespot_playback::mixer::mappings] Input volume 32767 mapped to: 50.00% [2023-09-25T20:29:55Z DEBUG librespot_core::session] Session[0] strong=3 weak=2 [2023-09-25T20:29:55Z INFO librespot_core::session] Country: "DE" [2023-09-25T20:29:55Z DEBUG librespot_playback::player] new Player[0] [2023-09-25T20:29:55Z INFO librespot_playback::convert] Converting with ditherer: tpdf [2023-09-25T20:29:55Z INFO librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA [2023-09-25T20:29:55Z INFO librespot_playback::audio_backend::rodio] Using audio device: default [2023-09-25T20:29:55Z DEBUG librespot_playback::audio_backend::rodio] Rodio sink was created [2023-09-25T20:29:55Z DEBUG librespot_playback::player] command=AddEventSender [2023-09-25T20:29:55Z DEBUG librespot_playback::player] command=VolumeSet(32767) [2023-09-25T20:29:56Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/87zak4din53ffbyaelpp59uia/ count=0 [2023-09-25T20:29:56Z DEBUG librespot_connect::spirc] kMessageTypeNotify "23049PCD8G" e37645146993c8db2977307701543e3572845800 1309198469 1695673795952 kPlayStatusPlay [2023-09-25T20:29:56Z DEBUG librespot_connect::spirc] kMessageTypeNotify "mycroft-spotifyd" 039f9248fdfc790f08a86cd90cb230bb734bc88c 1309198469 1695673795952 kPlayStatusStop [2023-09-25T20:29:56Z DEBUG librespot_connect::spirc] kMessageTypeLoad "23049PCD8G" e37645146993c8db2977307701543e3572845800 1309198737 1695673792998 kPlayStatusPlay [2023-09-25T20:29:56Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:search:i%20want%20to%20break" index: 0 position_ms: 5170 status: kPlayStatusPlay position_measured_at: 1695673796581 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 0 track {gid: "\357\3313\253x7O\033\273\027\307Ug\363k6"} [2023-09-25T20:29:56Z DEBUG librespot_connect::spirc] Frame has 1 tracks [2023-09-25T20:29:56Z INFO librespot_connect::spirc] Fetching autoplay context uri [2023-09-25T20:29:56Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2023-09-25T20:29:56Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false) [2023-09-25T20:29:56Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 318813267399007593070930267639173573430, audio_type: Track }, true, 5170) [2023-09-25T20:29:56Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2023-09-25T20:29:56Z WARN librespot_core::mercury] error 400 for uri hm://autoplay-enabled/query?uri=spotify:search:i%20want%20to%20break [2023-09-25T20:29:56Z ERROR librespot_connect::spirc] AutoplayError: MercuryError [2023-09-25T20:29:56Z INFO librespot_playback::player] Loading with Spotify URI [2023-09-25T20:29:56Z DEBUG librespot_audio::fetch] Downloading file e94f9894b92365637e1b7cb826473fa8e8b86f22 [2023-09-25T20:29:56Z DEBUG librespot::component] new ChannelManager [2023-09-25T20:29:57Z DEBUG librespot::component] new AudioKeyManager [2023-09-25T20:29:57Z DEBUG librespot_connect::spirc] kMessageTypeNotify "23049PCD8G" e37645146993c8db2977307701543e3572845800 1309199653 1695673797136 kPlayStatusStop [2023-09-25T20:29:59Z INFO librespot_playback::player] (223080 ms) loaded [2023-09-25T20:29:59Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -6.312110900878906, track_peak: 1.0102968215942383, album_gain_db: -9.44301700592041, album_peak: 1.0522888898849487 } [2023-09-25T20:29:59Z DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 48.35% [2023-09-25T20:29:59Z TRACE librespot_playback::player] == Starting sink == [2023-09-25T20:29:59Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2023-09-25T20:29:59Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay [2023-09-25T20:29:59Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 210780. Downloaded ranges: ([0, 16383][141424, 157811][176736, 210779][212052, 228439][282680, 299067][565200, 581583][1130232, 1146619][2260296, 2276683][4520428, 4536815][9040696, 9057079]). Pending ranges: ([210780, 212051][228440, 282679][299068, 432699]) [2023-09-25T20:29:59Z DEBUG librespot_audio::fetch] Read at postion 210780 completed. 1811 bytes returned, 1811 bytes were requested. [2023-09-25T20:30:13Z DEBUG librespot_connect::spirc] kMessageTypeNext "23049PCD8G" e37645146993c8db2977307701543e3572845800 1309215959 1695673799319 kPlayStatusStop [2023-09-25T20:30:13Z DEBUG librespot_connect::spirc] At track 2 of 1 <"spotify:search:i%20want%20to%20break"> update [true] [2023-09-25T20:30:13Z DEBUG librespot_connect::spirc] Extending playlist [2023-09-25T20:30:13Z WARN librespot_connect::spirc] No context to update from! [2023-09-25T20:30:13Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2023-09-25T20:30:13Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false) [2023-09-25T20:30:13Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 318813267399007593070930267639173573430, audio_type: Track }, true, 0) [2023-09-25T20:30:13Z DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -6.312110900878906, track_peak: 1.0102968215942383, album_gain_db: -9.44301700592041, album_peak: 1.0522888898849487 } [2023-09-25T20:30:13Z DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 48.35% [2023-09-25T20:30:13Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] [2023-09-25T20:30:13Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay [2023-09-25T20:30:13Z DEBUG librespot_audio::fetch] Stream waiting for download of file position 16384. Downloaded ranges: ([0, 16383][141424, 157811][176736, 3321163][4520428, 4536815][9040696, 9057079]). Pending ranges: ([16384, 141423][157812, 176735][3321164, 3341643]) [2023-09-25T20:30:13Z DEBUG librespot_audio::fetch] Read at postion 16384 completed. 1653 bytes returned, 1653 bytes were requested. [2023-09-25T20:30:21Z DEBUG librespot_connect::spirc] kMessageTypePause "23049PCD8G" e37645146993c8db2977307701543e3572845800 1309223486 1695673813930 kPlayStatusPlay [2023-09-25T20:30:21Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause] [2023-09-25T20:30:21Z DEBUG librespot_playback::player] command=Pause [2023-09-25T20:30:21Z TRACE librespot_playback::player] == Stopping sink == [2023-09-25T20:30:21Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause] [2023-09-25T20:30:21Z TRACE librespot_connect::spirc] ==> kPlayStatusPause ^C[2023-09-25T20:30:25Z INFO librespot] Gracefully shutting down [2023-09-25T20:30:25Z DEBUG librespot_playback::player] command=Stop [2023-09-25T20:30:26Z DEBUG librespot_connect::spirc] drop Spirc[0] [2023-09-25T20:30:26Z DEBUG librespot_playback::player] Shutting down player thread ... [2023-09-25T20:30:26Z DEBUG librespot_playback::player] drop PlayerInternal[0] [2023-09-25T20:30:26Z DEBUG librespot_playback::player] PlayerInternal thread finished. [2023-09-25T20:30:26Z DEBUG librespot_core::session] drop Session[0] [2023-09-25T20:30:26Z DEBUG librespot::component] drop AudioKeyManager [2023-09-25T20:30:26Z DEBUG librespot::component] drop ChannelManager [2023-09-25T20:30:26Z DEBUG librespot::component] drop MercuryManager [2023-09-25T20:30:26Z DEBUG librespot_core::session] drop Dispatch ```

Host (what you are running librespot on):

• OS: Raspberry PI OS 64bit
• Platform: RPi 4B 8GB

[roderickvd]

Yes, that code is quite crufty. Can you also try on latest dev?

[PocketMiner82]

It is still not working, here is the log:

Log

``` [2023-11-17T17:15:32Z INFO librespot] librespot 0.5.0-dev a8fcd99 (Built on 2023-11-17, Build ID: eK5RhOcr, Profile: release) [2023-11-17T17:15:32Z WARN librespot] Alsa specific options have no effect if the alsa backend is not enabled at build time. [2023-11-17T17:15:32Z INFO librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Linear [2023-11-17T17:15:32Z INFO librespot_playback::convert] Converting with ditherer: tpdf [2023-11-17T17:15:32Z INFO librespot_playback::audio_backend::pulseaudio] Using PulseAudioSink with format: S16 [2023-11-17T17:15:39Z INFO librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070" [2023-11-17T17:15:39Z INFO librespot_core::session] Authenticated as "87zak4din53ffbyaelpp59uia" ! [2023-11-17T17:15:39Z INFO librespot_core::session] Country: "DE" [2023-11-17T17:15:40Z INFO librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point [2023-11-17T17:15:40Z INFO librespot_playback::player] Loading with Spotify URI [2023-11-17T17:15:40Z ERROR librespot_connect::spirc] ContextError: Error { kind: Unknown, error: StatusCode(502) } [2023-11-17T17:15:40Z INFO librespot_playback::player] (223080 ms) loaded [2023-11-17T17:15:44Z ERROR librespot_connect::spirc] ContextError: Error { kind: InvalidArgument, error: StatusCode(400) } ^C[2023-11-17T17:16:34Z INFO librespot] Gracefully shutting down ```