Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Autoplay is not working #1205

Open
PocketMiner82 opened this issue Sep 25, 2023 · 2 comments
Open

Autoplay is not working #1205

PocketMiner82 opened this issue Sep 25, 2023 · 2 comments
Labels
bug

Comments

@PocketMiner82
Copy link

PocketMiner82 commented Sep 25, 2023 •
edited
Loading

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
@roderickvd
Copy link
Member

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

@PocketMiner82
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@roderickvd @PocketMiner82