librespot icon indicating copy to clipboard operation
librespot copied to clipboard
Published 1 month ago • verified publisher icon librespot-org

Autoplay is not working

Open PocketMiner82 opened this issue 2 years ago • 2 comments

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 <I Want To Break Free> with Spotify URI <spotify:track:7iAqvWLgZzXvH38lA06QZg>
[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] <I Want To Break Free> (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 <spotify:search:i%20want%20to%20break>
[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

PocketMiner82 avatar Sep 25 '23 20:09 PocketMiner82

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

roderickvd avatar Nov 14 '23 20:11 roderickvd

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 <I Want To Break Free> with Spotify URI <spotify:track:7iAqvWLgZzXvH38lA06QZg>
[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] <I Want To Break Free> (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

PocketMiner82 avatar Nov 17 '23 17:11 PocketMiner82