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

Audio key error

Open publicstaticvoidmain42 opened this issue 1 month ago • 18 comments

Description

Track fails to load and play. Logs say "audio key error 0 1".

Version

0.7.0+

How to reproduce

  1. Launch librespot with --enable-oauth for authentication and some client name
  2. Authenticate and then open Spotify
  3. Using Spotify Connect try to play music on the librespot client

Log

./target/release/librespot --name "a client" --disable-discovery --enable-oauth

[2025-11-20T07:52:30Z INFO  librespot] librespot 0.8.0 c797acc (Built on 2025-11-15, Build ID: Qyl7XpHd, Profile: release)
[2025-11-20T07:52:30Z WARN  librespot] Credential caching is unavailable, but advisable when using OAuth login.
Browse to: https://accounts.spotify.com/authorize?response_type=code&client_id=65b708073fc0480ea92a077233ca87bd&state=QN_9-jOQ8hmE5R6koCDmWw&code_challenge=69FJhs46TOI3oejOi739Vl-RWMTA3sM9rPs7b4FVW18&code_challenge_method=S256&redirect_uri=http%3A%2F%2F127.0.0.1%3A5588%2Flogin&scope=app-remote-control+playlist-modify+playlist-modify-private+playlist-modify-public+playlist-read+playlist-read-collaborative+playlist-read-private+streaming+ugc-image-upload+user-follow-modify+user-follow-read+user-library-modify+user-library-read+user-modify+user-modify-playback-state+user-modify-private+user-personalized+user-read-birthdate+user-read-currently-playing+user-read-email+user-read-play-history+user-read-playback-position+user-read-playback-state+user-read-private+user-read-recently-played+user-top-read
[2025-11-20T07:52:30Z INFO  librespot_oauth] OAuth server listening on 127.0.0.1:5588
[2025-11-20T07:52:33Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2025-11-20T07:52:33Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2025-11-20T07:52:33Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2025-11-20T07:52:33Z INFO  librespot_playback::audio_backend::rodio] Using audio device: default
[2025-11-20T07:52:34Z INFO  librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2025-11-20T07:52:34Z INFO  librespot_core::session] Authenticated as '31uhs5qiw6bvec7yhx3uy3lfngxa' !
[2025-11-20T07:52:34Z INFO  librespot_core::session] Country: "GB"
[2025-11-20T07:52:35Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2025-11-20T07:52:35Z INFO  librespot_connect::spirc] active device is <> with session <009f3713-9077-4676-8735-d2dae3d6a0fc>
[2025-11-20T07:53:08Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-11-20T07:53:08Z INFO  librespot_playback::player] Loading <Chinatown> with Spotify URI <spotify:track:3BRfgsKjcakny2wCYfZrvz>
[2025-11-20T07:53:08Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:08Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:12Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:12Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:3BRfgsKjcakny2wCYfZrvz")>: ()
[2025-11-20T07:53:12Z INFO  librespot_playback::player] Loading <In Between> with Spotify URI <spotify:track:3jFCjIuQAveQdM1S7zPzJt>
[2025-11-20T07:53:12Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:12Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:14Z INFO  librespot_playback::player] Loading <A Teenager in Love> with Spotify URI <spotify:track:5JMur5IZCCWUdFFRt7ekbf>
[2025-11-20T07:53:14Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:14Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:17Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:18Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:18Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:5JMur5IZCCWUdFFRt7ekbf")>: ()
[2025-11-20T07:53:18Z INFO  librespot_playback::player] Loading <Bite> with Spotify URI <spotify:track:7oviAIcW50bElbRnHPynvc>
[2025-11-20T07:53:19Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:19Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:23Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:23Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:7oviAIcW50bElbRnHPynvc")>: ()
[2025-11-20T07:53:23Z INFO  librespot_playback::player] Loading <Annie Blue> with Spotify URI <spotify:track:2CL9DIH08V6ZrpsmDMcZxM>
[2025-11-20T07:53:23Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:23Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:26Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:2CL9DIH08V6ZrpsmDMcZxM")>: ()
[2025-11-20T07:53:26Z INFO  librespot_playback::player] Loading <Don't Move> with Spotify URI <spotify:track:1BeNZQORyV0jEF2toAmrsA>
[2025-11-20T07:53:27Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:27Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-20T07:53:32Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2025-11-20T07:53:32Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:1BeNZQORyV0jEF2toAmrsA")>: ()
[2025-11-20T07:53:32Z INFO  librespot_playback::player] Loading <The One to Wait> with Spotify URI <spotify:track:0Q6OskXNfChXfBpN2oswue>
[2025-11-20T07:53:32Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-20T07:53:32Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
^C[2025-11-20T07:53:35Z INFO  librespot] Gracefully shutting down
[2025-11-20T07:53:35Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default

Host (what you are running librespot on):

  • OS: Ubuntu 24.04.2

publicstaticvoidmain42 avatar Nov 21 '25 09:11 publicstaticvoidmain42

Debug log please. I cannot reproduce this.

kingosticks avatar Nov 21 '25 10:11 kingosticks

inb4 it turns out the old method of getting keys is being phased out

drobotk avatar Nov 21 '25 10:11 drobotk

@kingosticks Sorry, there you go:

[2025-11-21T19:59:39Z INFO  librespot] librespot 0.8.0 c797acc (Built on 2025-11-15, Build ID: Qyl7XpHd, Profile: release)
[2025-11-21T19:59:39Z WARN  librespot] Credential caching is unavailable, but advisable when using OAuth login.
[2025-11-21T19:59:39Z DEBUG librespot_core::session] new Session
Browse to: https://accounts.spotify.com/authorize?response_type=code&client_id=65b708073fc0480ea92a077233ca87bd&state=ywzJlrsoxxWVmGdqVRM6Lw&code_challenge=KWs1cqn0nsz2hptU8O576yO11KJ1uyaGm73a1VtD_ro&code_challenge_method=S256&redirect_uri=http%3A%2F%2F127.0.0.1%3A5588%2Flogin&scope=app-remote-control+playlist-modify+playlist-modify-private+playlist-modify-public+playlist-read+playlist-read-collaborative+playlist-read-private+streaming+ugc-image-upload+user-follow-modify+user-follow-read+user-library-modify+user-library-read+user-modify+user-modify-playback-state+user-modify-private+user-personalized+user-read-birthdate+user-read-currently-playing+user-read-email+user-read-play-history+user-read-playback-position+user-read-playback-state+user-read-private+user-read-recently-played+user-top-read
[2025-11-21T19:59:39Z INFO  librespot_oauth] OAuth server listening on 127.0.0.1:5588
[2025-11-21T19:59:49Z DEBUG reqwest::connect] starting new connection: https://accounts.spotify.com/
[2025-11-21T19:59:50Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2025-11-21T19:59:50Z DEBUG librespot_playback::player] new Player [0]
[2025-11-21T19:59:50Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2025-11-21T19:59:50Z DEBUG librespot_connect::spirc] new Spirc[0]
[2025-11-21T19:59:50Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: ALSA
[2025-11-21T19:59:50Z INFO  librespot_playback::audio_backend::rodio] Using audio device: default
[2025-11-21T19:59:50Z DEBUG librespot::component] new DealerManager
[2025-11-21T19:59:50Z DEBUG librespot_playback::audio_backend::rodio] Rodio sink was created
[2025-11-21T19:59:50Z DEBUG librespot::component] new SpClient
[2025-11-21T19:59:50Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2025-11-21T19:59:50Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2025-11-21T19:59:50Z DEBUG librespot_core::spclient] Received a granted token
[2025-11-21T19:59:50Z DEBUG librespot::component] new ApResolver
[2025-11-21T19:59:50Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2025-11-21T19:59:50Z INFO  librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Connection to "ap-gew1.spotify.com:4070" failed: Connection refused (os error 111)
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Retry access point...
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_SPOTIFY_TOKEN
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-21T19:59:51Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[2025-11-21T19:59:51Z INFO  librespot_core::session] Authenticated as '31uhs5qiw6bvec7yhx3uy3lfngxa' !
[2025-11-21T19:59:51Z DEBUG librespot::component] new Login5Manager
[2025-11-21T19:59:51Z DEBUG librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[2025-11-21T19:59:51Z DEBUG librespot_core::session] Session strong=5 weak=6
[2025-11-21T19:59:51Z INFO  librespot_core::session] Country: "GB"
[2025-11-21T19:59:51Z DEBUG librespot::component] new MercuryManager
[2025-11-21T19:59:51Z DEBUG librespot_connect::spirc] SpircTask::set_volume(32767)
[2025-11-21T19:59:51Z DEBUG librespot_playback::mixer::mappings] Input volume 32767 mapped to: 3.16%
[2025-11-21T19:59:51Z DEBUG librespot_playback::player] command=AddEventSender
[2025-11-21T19:59:51Z DEBUG librespot_core::dealer::manager] Launching dealer
[2025-11-21T19:59:51Z DEBUG tungstenite::handshake::client] Client handshake done.
[2025-11-21T19:59:51Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2025-11-21T19:59:51Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=3806333557
[2025-11-21T19:59:52Z DEBUG librespot_connect::spirc] successfully put connect state for 2e1428d3e9d21e8cf777bdea2526d20ee0e87e83 with connection-id YzZmMDM0NGItZGM1Ni00OTA3LWE3NmUtZDdlNmViYmJjZGUwK2RlYWxlcit0Y3A6Ly8wYWNhNDAwYy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArODQ5RDlFMEIyREQyOUQyREM4MzhFQTk2RTBCOTIzRkI2QTM1QTM1OURBODM0MkFDQzhCRDQ1QUM5OEE2RDRBOA==
[2025-11-21T19:59:52Z INFO  librespot_connect::spirc] active device is <> with session <1cb1474331a24baa861fa962d55f5c66>
[2025-11-21T20:00:38Z DEBUG librespot_connect::spirc] cluster update: Ok(NEW_DEVICE_APPEARED) from e06bb2f8e4eb5374618457772f2dd4381d478c5f, active device: 
[2025-11-21T20:00:40Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from e06bb2f8e4eb5374618457772f2dd4381d478c5f, active device: e06bb2f8e4eb5374618457772f2dd4381d478c5f
[2025-11-21T20:00:42Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from e06bb2f8e4eb5374618457772f2dd4381d478c5f, active device: e06bb2f8e4eb5374618457772f2dd4381d478c5f
[2025-11-21T20:00:44Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from e06bb2f8e4eb5374618457772f2dd4381d478c5f, active device: e06bb2f8e4eb5374618457772f2dd4381d478c5f
[2025-11-21T20:00:45Z DEBUG librespot_connect::spirc] handling: 'endpoint: transfer' from e06bb2f8e4eb5374618457772f2dd4381d478c5f
[2025-11-21T20:00:45Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-11-21T20:00:45Z DEBUG librespot_connect::state::transfer] transfer track was the current track
[2025-11-21T20:00:45Z DEBUG librespot_connect::spirc] found initial track <spotify:track:3BRfgsKjcakny2wCYfZrvz>
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitSessionConnectedEvent("YzZmMDM0NGItZGM1Ni00OTA3LWE3NmUtZDdlNmViYmJjZGUwK2RlYWxlcit0Y3A6Ly8wYWNhNDAwYy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArODQ5RDlFMEIyREQyOUQyREM4MzhFQTk2RTBCOTIzRkI2QTM1QTM1OURBODM0MkFDQzhCRDQ1QUM5OEE2RDRBOA==", "31uhs5qiw6bvec7yhx3uy3lfngxa")
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitSessionClientChangedEvent("65b708073fc0480ea92a077233ca87bd", "", "", "")
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitVolumeChangedEvent(32767)
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitAutoPlayChangedEvent(true)
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitShuffleChangedEvent(false)
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=EmitRepeatChangedEvent(false, false)
[2025-11-21T20:00:45Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-21T20:00:45Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-21T20:00:45Z DEBUG librespot_playback::player] command=Load(SpotifyUri("spotify:track:3BRfgsKjcakny2wCYfZrvz"), true, 0)
[2025-11-21T20:00:45Z DEBUG librespot_connect::state] update position to 0:00 at 20:00:45.539
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=4183091500
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/extended-metadata/v0/extended-metadata?product=0&country=GB&salt=4097306603
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-21T20:00:45Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-21T20:00:45Z INFO  librespot_playback::player] Loading <Chinatown> with Spotify URI <spotify:track:3BRfgsKjcakny2wCYfZrvz>
[2025-11-21T20:00:45Z DEBUG librespot_audio::fetch] Downloading file 8b2551eb348f9a2ba503251e7b59a39f94c012a7
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/8b2551eb348f9a2ba503251e7b59a39f94c012a7?product=0&country=GB&salt=3885840213
[2025-11-21T20:00:45Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-21T20:00:45Z DEBUG librespot_connect::state] update position to 0:00 at 20:00:45.825
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=643724130
[2025-11-21T20:00:45Z DEBUG librespot::component] new AudioKeyManager
[2025-11-21T20:00:45Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-21T20:00:45Z ERROR librespot_core::audio_key] error audio key 0 1
[2025-11-21T20:00:45Z WARN  librespot_playback::player] Unable to load key, continuing without decryption: Service unavailable { audio key error }
[2025-11-21T20:00:46Z DEBUG symphonia_core::probe] found a possible format marker within [ff, f6, b8, 3, 85, 53, b2, 31, 31, f4, 24, 68, 6f, cb, a5, e3] @ 0+2592 bytes.
[2025-11-21T20:00:46Z DEBUG symphonia_core::probe] found the format marker [ff, f6] @ 0+2592 bytes.
[2025-11-21T20:00:46Z DEBUG librespot_connect::spirc] handling next context Some("spotify:track:3BRfgsKjcakny2wCYfZrvz")
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::context] updated context Default to <Some("spotify:track:3BRfgsKjcakny2wCYfZrvz")> (1 tracks)
[2025-11-21T20:00:46Z DEBUG librespot_connect::context_resolver] last item of type <Default>, finishing state setup
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::transfer] active track is <spotify:track:3BRfgsKjcakny2wCYfZrvz> with index Ok(0) in Default context, has 1 tracks
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::transfer] setting up next and prev: index is at Some(0) while shuffle false
[2025-11-21T20:00:46Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:3BRfgsKjcakny2wCYfZrvz at 0 of 1 tracks
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (0)
[2025-11-21T20:00:46Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-21T20:00:46Z DEBUG librespot_connect::state] update position to 0:00 at 20:00:46.017
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 2590 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 10245 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 24584 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 26387 bytes
[2025-11-21T20:00:46Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=2449200037
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 34029 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 48825 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 52160 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 55612 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 61688 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 64332 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 68243 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 70304 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 71726 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 72080 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 78610 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 86630 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 87821 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 93317 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 99472 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 105396 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 115928 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 116665 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 117213 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 120165 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 120501 bytes
[2025-11-21T20:00:46Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/autoplay
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 135136 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 136148 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 141381 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 143110 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 149347 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 154112 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 155098 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 161380 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 166453 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 175113 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 182435 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 185745 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 185770 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 198372 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 201025 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 214478 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 214741 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 221354 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 225669 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 226692 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 230432 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 241093 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 241671 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 245922 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 271593 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 273204 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 274352 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 280501 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 294229 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 309427 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 312205 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 316239 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 318524 bytes
[2025-11-21T20:00:46Z DEBUG librespot_connect::spirc] handling next context Some("spotify:station:track:3BRfgsKjcakny2wCYfZrvz")
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::context] updated context Autoplay to <Some("spotify:station:track:3BRfgsKjcakny2wCYfZrvz")> (50 tracks)
[2025-11-21T20:00:46Z DEBUG librespot_connect::context_resolver] last item of type <Autoplay>, finishing state setup
[2025-11-21T20:00:46Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (51)
[2025-11-21T20:00:46Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-21T20:00:46Z DEBUG librespot_connect::state] update position to 0:00 at 20:00:46.466
[2025-11-21T20:00:46Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=3873614887
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 338464 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] invalid mpeg audio header
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 349401 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 350769 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 375825 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 382718 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 383639 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 384618 bytes
[2025-11-21T20:00:46Z WARN  symphonia_bundle_mp3::demuxer] skipping junk at 388803 bytes
...

publicstaticvoidmain42 avatar Nov 21 '25 20:11 publicstaticvoidmain42

Is this with all tracks? Does switching to a different album make any difference? What about selecting different --bitrate? Just to double check, you do have premium, yes? Is this suddenly a new failure i.e. did librespot used to work for you?

kingosticks avatar Nov 21 '25 21:11 kingosticks

It seems to be thinking that it's an MP3 file?

roderickvd avatar Nov 22 '25 00:11 roderickvd

I think that's Symphonia's probe trying hard to interpret the encrypted file as audio

drobotk avatar Nov 22 '25 08:11 drobotk

You’re right, I glimpsed over that “could not get audio key” line. Is it the same for you in other gateways? (Here: gew1) you can try blocking that one using your hosts file.

roderickvd avatar Nov 22 '25 11:11 roderickvd

Is this with all tracks?

Yes.

Does switching to a different album make any difference?

No.

What about selecting different --bitrate?

Checked it, same error.

Just to double check, you do have premium, yes?

Yes. I have Spotify Premium.

Is this suddenly a new failure i.e. did librespot used to work for you?

Yes. It was working fine for ~8 months.

publicstaticvoidmain42 avatar Nov 22 '25 14:11 publicstaticvoidmain42

Just to check if it was just me, I contacted one of my friends to try it with some of their family accounts. Almost all of them had the same audio key error but there's a new error we did get on one of the accounts. I'll paste the debug output below. The issue that happens here is that it starts librespot but as soon as he tried to play a song with Spotify Connect, the client kept jumping through songs without even playing then and eventually he had to quit with ctrl c.

RUST_LOG=debug ./target/release/librespot --disable-discovery --enable-oauth --bitrate 96
[2025-11-22T14:29:45Z INFO  librespot] librespot 0.7.1 987dfa5 (Built on 2025-11-15, Build ID: agxLoNyj, Profile: release)
[2025-11-22T14:29:45Z WARN  librespot] Credential caching is unavailable, but advisable when using OAuth login.
[2025-11-22T14:29:45Z DEBUG librespot_core::session] new Session
Browse to: https://accounts.spotify.com/authorize?response_type=code&client_id=65b708073fc0480ea92a077233ca87bd&state=CAIgRfB7nfrp2uh9FPI5hQ&code_challenge=vdvabHg7ryv_nwW4dk4AGnQK3kDNRSwEyGUbmxkNPAI&code_challenge_method=S256&redirect_uri=http%3A%2F%2F127.0.0.1%3A5588%2Flogin&scope=app-remote-control+playlist-modify+playlist-modify-private+playlist-modify-public+playlist-read+playlist-read-collaborative+playlist-read-private+streaming+ugc-image-upload+user-follow-modify+user-follow-read+user-library-modify+user-library-read+user-modify+user-modify-playback-state+user-modify-private+user-personalized+user-read-birthdate+user-read-currently-playing+user-read-email+user-read-play-history+user-read-playback-position+user-read-playback-state+user-read-private+user-read-recently-played+user-top-read
[2025-11-22T14:29:45Z INFO  librespot_oauth] OAuth server listening on 127.0.0.1:5588
[2025-11-22T14:29:47Z DEBUG reqwest::connect] starting new connection: https://accounts.spotify.com/
[2025-11-22T14:29:47Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2025-11-22T14:29:47Z DEBUG librespot_playback::player] new Player [0]
[2025-11-22T14:29:47Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2025-11-22T14:29:47Z DEBUG librespot_connect::spirc] new Spirc[0]
[2025-11-22T14:29:47Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: CoreAudio
[2025-11-22T14:29:47Z DEBUG librespot::component] new DealerManager
[2025-11-22T14:29:47Z DEBUG librespot::component] new SpClient
[2025-11-22T14:29:47Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2025-11-22T14:29:47Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2025-11-22T14:29:47Z INFO  librespot_playback::audio_backend::rodio] Using audio device: Mad's AirPods Pro
[2025-11-22T14:29:47Z DEBUG librespot_core::spclient] Received a granted token
[2025-11-22T14:29:47Z DEBUG librespot::component] new ApResolver
[2025-11-22T14:29:47Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2025-11-22T14:29:48Z INFO  librespot_core::session] Connecting to AP "ap-gae2.spotify.com:4070"
[2025-11-22T14:29:48Z DEBUG librespot_playback::audio_backend::rodio] Rodio sink was created
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Connection to "ap-gae2.spotify.com:4070" failed: Connection refused (os error 61)
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Retry access point...
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_SPOTIFY_TOKEN
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Connection to "ap-gae2.spotify.com:4070" failed: Connection refused (os error 61)
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Retry access point...
[2025-11-22T14:29:48Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-22T14:29:49Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[2025-11-22T14:29:49Z INFO  librespot_core::session] Authenticated as 'drh8spxczmnxeqlywln0iptuo' !
[2025-11-22T14:29:49Z DEBUG librespot::component] new Login5Manager
[2025-11-22T14:29:49Z DEBUG librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[2025-11-22T14:29:49Z DEBUG librespot_core::session] Session strong=5 weak=6
[2025-11-22T14:29:49Z INFO  librespot_core::session] Country: "IN"
[2025-11-22T14:29:49Z DEBUG librespot::component] new MercuryManager
[2025-11-22T14:29:49Z DEBUG librespot_playback::player] command=AddEventSender
[2025-11-22T14:29:49Z DEBUG librespot_connect::spirc] SpircTask::set_volume(32767)
[2025-11-22T14:29:49Z DEBUG librespot_playback::mixer::mappings] Input volume 32767 mapped to: 3.16%
[2025-11-22T14:29:49Z DEBUG librespot_core::dealer::manager] Launching dealer
[2025-11-22T14:29:49Z DEBUG tungstenite::handshake::client] Client handshake done.
[2025-11-22T14:29:49Z INFO  librespot_core::spclient] Resolved "gae2-spclient.spotify.com:443" as spclient access point
[2025-11-22T14:29:49Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=109946115
[2025-11-22T14:29:50Z DEBUG librespot_connect::spirc] successfully put connect state for 7c28ab8a5c9512e4266ac7cb756312c82ee43d7e with connection-id YTRhZWVlN2EtODI1OS00Y2ViLWFmYjEtOGFiODVkOGYxMGVmK2RlYWxlcit0Y3A6Ly8wYWIxNTgyMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQjE0RUY4RTk3RjJFNkU5NzNFN0Y2MUE1ODE5MkFFQzJGMzkxMDQ4RTJENjNFNDdDNENFOTNGQkExODk4NzM3RA==
[2025-11-22T14:29:50Z INFO  librespot_connect::spirc] active device is <> with session <bd42c750578c49af993b8d288ed13cde>
[2025-11-22T14:30:20Z DEBUG librespot_connect::spirc] handling: 'endpoint: transfer' from 0f0348b6ca9c3911ac2b0c7de40faeb14dd9bb33
[2025-11-22T14:30:20Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-11-22T14:30:20Z DEBUG librespot_connect::spirc] found initial track <spotify:track:5XBUtdLhHkWMacY3I5kz8X>
[2025-11-22T14:30:20Z DEBUG librespot_connect::context_resolver] update for resolve_uri: <Some("spotify:user:drh8spxczmnxeqlywln0iptuo:collection")>, context_uri: <spotify:user:drh8spxczmnxeqlywln0iptuo:collection>, update: <Default> is already added
[2025-11-22T14:30:20Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:20Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitSessionConnectedEvent("YTRhZWVlN2EtODI1OS00Y2ViLWFmYjEtOGFiODVkOGYxMGVmK2RlYWxlcit0Y3A6Ly8wYWIxNTgyMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQjE0RUY4RTk3RjJFNkU5NzNFN0Y2MUE1ODE5MkFFQzJGMzkxMDQ4RTJENjNFNDdDNENFOTNGQkExODk4NzM3RA==", "drh8spxczmnxeqlywln0iptuo")
[2025-11-22T14:30:20Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=3886604105
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitSessionClientChangedEvent("65b708073fc0480ea92a077233ca87bd", "", "", "")
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitVolumeChangedEvent(32767)
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitAutoPlayChangedEvent(true)
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitShuffleChangedEvent(false)
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=EmitRepeatChangedEvent(false, false)
[2025-11-22T14:30:20Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5XBUtdLhHkWMacY3I5kz8X"), false, 133)
[2025-11-22T14:30:20Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/c3e015b91e1a42cd9a48c879075f28a7?product=0&country=IN&salt=459606325
[2025-11-22T14:30:21Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:user:drh8spxczmnxeqlywln0iptuo:collection
[2025-11-22T14:30:21Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-22T14:30:21Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:21Z WARN  librespot_playback::player] <spotify:track:5XBUtdLhHkWMacY3I5kz8X> is not available
[2025-11-22T14:30:21Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5XBUtdLhHkWMacY3I5kz8X")>: ()
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::tracks] marking spotify:track:5XBUtdLhHkWMacY3I5kz8X as unavailable
[2025-11-22T14:30:21Z ERROR librespot_connect::spirc] could not dispatch player event: Invalid state { context is not available. type: Default }
[2025-11-22T14:30:21Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:21Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=1057592120
[2025-11-22T14:30:21Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:user:drh8spxczmnxeqlywln0iptuo:collection
[2025-11-22T14:30:21Z DEBUG librespot_connect::spirc] handling next context Some("spotify:user:drh8spxczmnxeqlywln0iptuo:collection")
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::context] updated context Default to <Some("spotify:user:drh8spxczmnxeqlywln0iptuo:collection")> (1025 tracks)
[2025-11-22T14:30:21Z DEBUG librespot_connect::context_resolver] last item of type <Default>, finishing state setup
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::transfer] active track is <spotify:track:5XBUtdLhHkWMacY3I5kz8X> with index Ok(43) in Default context, has 1025 tracks
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::transfer] setting up next and prev: index is at Some(43) while shuffle false
[2025-11-22T14:30:21Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:5XBUtdLhHkWMacY3I5kz8X at 43 of 1025 tracks
[2025-11-22T14:30:21Z DEBUG librespot_connect::state] has 10 prev tracks
[2025-11-22T14:30:21Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:21Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:21Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=1372393879
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] handling: 'endpoint: play' from 0f0348b6ca9c3911ac2b0c7de40faeb14dd9bb33
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::context] context didn't change, no reset
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] context <spotify:user:drh8spxczmnxeqlywln0iptuo:collection> didn't change, no resolving required
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] play track <Some(Uri("spotify:track:6n2UqLNVojFMhqsfcCkNCT"))>
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] loading with shuffle: <false>, repeat track: <false> context: <false>
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] skipped track spotify:track:5XBUtdLhHkWMacY3I5kz8X during fillup as it's unavailable or should be skipped
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/d15ad6f54b3d4102aa7ed97211a06b2f?product=0&country=IN&salt=4243044473
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:6n2UqLNVojFMhqsfcCkNCT> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:6n2UqLNVojFMhqsfcCkNCT as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/9cac30f2913445a1a091663a26cabc5c?product=0&country=IN&salt=998204811
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:4LDuFh8tES3xOVYRHhUADG> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:4LDuFh8tES3xOVYRHhUADG as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/8aa1cd29111a41f8b6f175be74676dbb?product=0&country=IN&salt=3397950881
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:4dASQiO1Eoo3RJvt74FtXB> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:4dASQiO1Eoo3RJvt74FtXB as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/bd75296b37754bce8129db3927599fba?product=0&country=IN&salt=1083098528
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:5Lv5L45PQmp5CTjs5PlQ6e> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:5Lv5L45PQmp5CTjs5PlQ6e as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/1c3fa503db0b4457868e79375fbe8e18?product=0&country=IN&salt=3617114323
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:0RiRZpuVRbi7oqRdSMwhQY> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:0RiRZpuVRbi7oqRdSMwhQY as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/e04ad72a6f24456e930a473751478653?product=0&country=IN&salt=1157635710
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] handling: 'endpoint: play' from 0f0348b6ca9c3911ac2b0c7de40faeb14dd9bb33
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::context] context didn't change, no reset
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] context <spotify:user:drh8spxczmnxeqlywln0iptuo:collection> didn't change, no resolving required
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] play track <Some(Uri("spotify:track:6n2UqLNVojFMhqsfcCkNCT"))>
[2025-11-22T14:30:24Z DEBUG librespot_connect::spirc] loading with shuffle: <false>, repeat track: <false> context: <false>
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] skipped track spotify:track:5XBUtdLhHkWMacY3I5kz8X during fillup as it's unavailable or should be skipped
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/d15ad6f54b3d4102aa7ed97211a06b2f?product=0&country=IN&salt=2666619161
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:6PetYmvjKZBjiUYlnlAcn1> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:24Z WARN  librespot_playback::player] <spotify:track:6n2UqLNVojFMhqsfcCkNCT> is not available
[2025-11-22T14:30:24Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT")>: ()
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] marking spotify:track:6n2UqLNVojFMhqsfcCkNCT as unavailable
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"))
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:24Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:24Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"), true, 0)
[2025-11-22T14:30:24Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/9cac30f2913445a1a091663a26cabc5c?product=0&country=IN&salt=2890820945
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:4LDuFh8tES3xOVYRHhUADG> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:4LDuFh8tES3xOVYRHhUADG as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/8aa1cd29111a41f8b6f175be74676dbb?product=0&country=IN&salt=600837887
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:4dASQiO1Eoo3RJvt74FtXB> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:4dASQiO1Eoo3RJvt74FtXB as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/bd75296b37754bce8129db3927599fba?product=0&country=IN&salt=2353244753
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:5Lv5L45PQmp5CTjs5PlQ6e> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:5Lv5L45PQmp5CTjs5PlQ6e as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/1c3fa503db0b4457868e79375fbe8e18?product=0&country=IN&salt=1354607927
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:0RiRZpuVRbi7oqRdSMwhQY> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:0RiRZpuVRbi7oqRdSMwhQY as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/e04ad72a6f24456e930a473751478653?product=0&country=IN&salt=3776010380
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:6PetYmvjKZBjiUYlnlAcn1> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:6PetYmvjKZBjiUYlnlAcn1 as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/79da87266628409d82dd33c83bf9c912?product=0&country=IN&salt=1250661171
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:3HVWdVOQ0ZA45FuZGSfvns> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:3HVWdVOQ0ZA45FuZGSfvns as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/563b1aaa5b664c95b8aa40536756b053?product=0&country=IN&salt=2069224517
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:2CIlKt4lRwAAUx5fYgCBxN> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:2CIlKt4lRwAAUx5fYgCBxN as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/6a1cbfea560a4cca9bc7044b6591fa2c?product=0&country=IN&salt=1375665903
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:3eekarcy7kvN4yt5ZFzltW> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:3eekarcy7kvN4yt5ZFzltW as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/2c6a455065a6459b8db93687b6b4f26a?product=0&country=IN&salt=2896421804
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:25Z WARN  librespot_playback::player] <spotify:track:1lOe9qE0vR9zwWQAOk6CoO> is not available
[2025-11-22T14:30:25Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO")>: ()
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] marking spotify:track:1lOe9qE0vR9zwWQAOk6CoO as unavailable
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:25Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g"))
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:25Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g"), true, 0)
[2025-11-22T14:30:25Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/58a5b851a717464884632c176649a4da?product=0&country=IN&salt=2426999623
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:2Hh3ETdQKrmSI3QS0hme7g> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:2Hh3ETdQKrmSI3QS0hme7g as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/67c1b9e3f8d345ddb366a61ce6eb4837?product=0&country=IN&salt=63330714
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:39MK3d3fonIP8Mz9oHCTBB> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:39MK3d3fonIP8Mz9oHCTBB as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/88e51600a92444c99f9f05c787750b2f?product=0&country=IN&salt=2511804933
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:4ajEeUByf22nxfhqCHuJD9> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:4ajEeUByf22nxfhqCHuJD9 as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/064c08ee65f74769b0daf8e17318735c?product=0&country=IN&salt=2118395515
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:0bSHwuTOZVJUXWT03H9oD2> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:0bSHwuTOZVJUXWT03H9oD2 as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/6d0668557174478e975669337e88c53e?product=0&country=IN&salt=341400401
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:3jJ5HgLRNydtLRghjWVaCG> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:3jJ5HgLRNydtLRghjWVaCG as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/be8617a12e69420e83c283e8eb8785e3?product=0&country=IN&salt=3837763106
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:5NvOZCjZaGGGL597exlQWv> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:5NvOZCjZaGGGL597exlQWv as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/256108db925e42fb99620e9faddfb2a4?product=0&country=IN&salt=3429908706
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:18x3MCjaft6XBVrLBI0DUo> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:18x3MCjaft6XBVrLBI0DUo as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/edb4d0474d0348de973691545fc4acf3?product=0&country=IN&salt=3607482138
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:26Z WARN  librespot_playback::player] <spotify:track:7exOrewyAiFxxHkGMXIvUn> is not available
[2025-11-22T14:30:26Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn")>: ()
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] marking spotify:track:7exOrewyAiFxxHkGMXIvUn as unavailable
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:26Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN"))
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN"), true, 0)
[2025-11-22T14:30:26Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/c2692529c514420f9c7bab3a5c06d859?product=0&country=IN&salt=3763156954
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:5UQyTPDqHDBl8oqCoJ2iMN> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:5UQyTPDqHDBl8oqCoJ2iMN as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4kCry3MgYbMFppDv8KHsON"))
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4kCry3MgYbMFppDv8KHsON"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/8e5ae2325c2e4e54b73b79951a79f185?product=0&country=IN&salt=554743381
[2025-11-22T14:30:27Z DEBUG librespot_connect::spirc] handling: 'endpoint: play' from 0f0348b6ca9c3911ac2b0c7de40faeb14dd9bb33
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::context] context didn't change, no reset
[2025-11-22T14:30:27Z DEBUG librespot_connect::spirc] context <spotify:user:drh8spxczmnxeqlywln0iptuo:collection> didn't change, no resolving required
[2025-11-22T14:30:27Z DEBUG librespot_connect::spirc] play track <Some(Uri("spotify:track:6n2UqLNVojFMhqsfcCkNCT"))>
[2025-11-22T14:30:27Z DEBUG librespot_connect::spirc] loading with shuffle: <false>, repeat track: <false> context: <false>
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:6n2UqLNVojFMhqsfcCkNCT at 0 of 1025 tracks
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] skipped track spotify:track:5XBUtdLhHkWMacY3I5kz8X during fillup as it's unavailable or should be skipped
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/d15ad6f54b3d4102aa7ed97211a06b2f?product=0&country=IN&salt=2398809165
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:4kCry3MgYbMFppDv8KHsON> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:6n2UqLNVojFMhqsfcCkNCT> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:6n2UqLNVojFMhqsfcCkNCT")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:6n2UqLNVojFMhqsfcCkNCT as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"))
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/9cac30f2913445a1a091663a26cabc5c?product=0&country=IN&salt=1971209131
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:4LDuFh8tES3xOVYRHhUADG> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4LDuFh8tES3xOVYRHhUADG")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:4LDuFh8tES3xOVYRHhUADG as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"))
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/8aa1cd29111a41f8b6f175be74676dbb?product=0&country=IN&salt=2397426887
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:4dASQiO1Eoo3RJvt74FtXB> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4dASQiO1Eoo3RJvt74FtXB")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:4dASQiO1Eoo3RJvt74FtXB as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"))
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/bd75296b37754bce8129db3927599fba?product=0&country=IN&salt=3078854009
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:5Lv5L45PQmp5CTjs5PlQ6e> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5Lv5L45PQmp5CTjs5PlQ6e")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:5Lv5L45PQmp5CTjs5PlQ6e as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"))
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/1c3fa503db0b4457868e79375fbe8e18?product=0&country=IN&salt=4122419272
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:0RiRZpuVRbi7oqRdSMwhQY> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0RiRZpuVRbi7oqRdSMwhQY")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:0RiRZpuVRbi7oqRdSMwhQY as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"))
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/e04ad72a6f24456e930a473751478653?product=0&country=IN&salt=1209569666
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:6PetYmvjKZBjiUYlnlAcn1> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:6PetYmvjKZBjiUYlnlAcn1")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:6PetYmvjKZBjiUYlnlAcn1 as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns"))
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/79da87266628409d82dd33c83bf9c912?product=0&country=IN&salt=2707859715
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:3HVWdVOQ0ZA45FuZGSfvns> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3HVWdVOQ0ZA45FuZGSfvns")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:3HVWdVOQ0ZA45FuZGSfvns as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN"))
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/563b1aaa5b664c95b8aa40536756b053?product=0&country=IN&salt=2254994606
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:27Z WARN  librespot_playback::player] <spotify:track:2CIlKt4lRwAAUx5fYgCBxN> is not available
[2025-11-22T14:30:27Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:2CIlKt4lRwAAUx5fYgCBxN")>: ()
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] marking spotify:track:2CIlKt4lRwAAUx5fYgCBxN as unavailable
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:27Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW"))
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW"), true, 0)
[2025-11-22T14:30:27Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/6a1cbfea560a4cca9bc7044b6591fa2c?product=0&country=IN&salt=4010605403
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:3eekarcy7kvN4yt5ZFzltW> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3eekarcy7kvN4yt5ZFzltW")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:3eekarcy7kvN4yt5ZFzltW as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/2c6a455065a6459b8db93687b6b4f26a?product=0&country=IN&salt=2839525319
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:1lOe9qE0vR9zwWQAOk6CoO> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:1lOe9qE0vR9zwWQAOk6CoO")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:1lOe9qE0vR9zwWQAOk6CoO as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/58a5b851a717464884632c176649a4da?product=0&country=IN&salt=1483018803
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:2Hh3ETdQKrmSI3QS0hme7g> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:2Hh3ETdQKrmSI3QS0hme7g")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:2Hh3ETdQKrmSI3QS0hme7g as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/67c1b9e3f8d345ddb366a61ce6eb4837?product=0&country=IN&salt=4247165081
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:39MK3d3fonIP8Mz9oHCTBB> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:39MK3d3fonIP8Mz9oHCTBB")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:39MK3d3fonIP8Mz9oHCTBB as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/88e51600a92444c99f9f05c787750b2f?product=0&country=IN&salt=2311431455
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:4ajEeUByf22nxfhqCHuJD9> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4ajEeUByf22nxfhqCHuJD9")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:4ajEeUByf22nxfhqCHuJD9 as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/064c08ee65f74769b0daf8e17318735c?product=0&country=IN&salt=2828643713
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:0bSHwuTOZVJUXWT03H9oD2> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:0bSHwuTOZVJUXWT03H9oD2")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:0bSHwuTOZVJUXWT03H9oD2 as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/6d0668557174478e975669337e88c53e?product=0&country=IN&salt=14124278
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:3jJ5HgLRNydtLRghjWVaCG> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3jJ5HgLRNydtLRghjWVaCG")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:3jJ5HgLRNydtLRghjWVaCG as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv"))
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/be8617a12e69420e83c283e8eb8785e3?product=0&country=IN&salt=1706925999
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:28Z WARN  librespot_playback::player] <spotify:track:5NvOZCjZaGGGL597exlQWv> is not available
[2025-11-22T14:30:28Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5NvOZCjZaGGGL597exlQWv")>: ()
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] marking spotify:track:5NvOZCjZaGGGL597exlQWv as unavailable
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:28Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo"))
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:28Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo"), true, 0)
[2025-11-22T14:30:28Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/256108db925e42fb99620e9faddfb2a4?product=0&country=IN&salt=1195332802
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:29Z WARN  librespot_playback::player] <spotify:track:18x3MCjaft6XBVrLBI0DUo> is not available
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:18x3MCjaft6XBVrLBI0DUo")>: ()
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] marking spotify:track:18x3MCjaft6XBVrLBI0DUo as unavailable
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn"))
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn"), true, 0)
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/edb4d0474d0348de973691545fc4acf3?product=0&country=IN&salt=2701238600
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:29Z WARN  librespot_playback::player] <spotify:track:7exOrewyAiFxxHkGMXIvUn> is not available
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:7exOrewyAiFxxHkGMXIvUn")>: ()
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] marking spotify:track:7exOrewyAiFxxHkGMXIvUn as unavailable
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN"))
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN"), true, 0)
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/c2692529c514420f9c7bab3a5c06d859?product=0&country=IN&salt=1355904942
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:29Z WARN  librespot_playback::player] <spotify:track:5UQyTPDqHDBl8oqCoJ2iMN> is not available
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:5UQyTPDqHDBl8oqCoJ2iMN")>: ()
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] marking spotify:track:5UQyTPDqHDBl8oqCoJ2iMN as unavailable
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4kCry3MgYbMFppDv8KHsON"))
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4kCry3MgYbMFppDv8KHsON"), true, 0)
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/8e5ae2325c2e4e54b73b79951a79f185?product=0&country=IN&salt=3397205087
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:29Z WARN  librespot_playback::player] <spotify:track:4kCry3MgYbMFppDv8KHsON> is not available
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4kCry3MgYbMFppDv8KHsON")>: ()
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] marking spotify:track:4kCry3MgYbMFppDv8KHsON as unavailable
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:7MJ8g0egEkhvGu44IamrDE"))
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:7MJ8g0egEkhvGu44IamrDE"), true, 0)
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/ffd242f762594ce984b36bb08afe3876?product=0&country=IN&salt=947201715
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] update position to 0:00 at 14:30:29.543
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=618967340
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:29Z WARN  librespot_playback::player] <spotify:track:7MJ8g0egEkhvGu44IamrDE> is not available
[2025-11-22T14:30:29Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:7MJ8g0egEkhvGu44IamrDE")>: ()
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] marking spotify:track:7MJ8g0egEkhvGu44IamrDE as unavailable
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (80)
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:3Dgmyz32dxvtxvUTPS0CUI"))
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] Preloading track
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:3Dgmyz32dxvtxvUTPS0CUI"), true, 0)
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com/metadata/4/track/7760e2c1a1c64c849c2c0ccbc21ebc14?product=0&country=IN&salt=1306030562
^C[2025-11-22T14:30:29Z INFO  librespot] Gracefully shutting down
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] update position to 0:00 at 14:30:29.95
[2025-11-22T14:30:29Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:29Z DEBUG librespot_playback::player] command=Pause
[2025-11-22T14:30:29Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=786228234
[2025-11-22T14:30:30Z ERROR librespot_playback::player] Track should be available, but no alternatives found.
[2025-11-22T14:30:30Z WARN  librespot_playback::player] <spotify:track:3Dgmyz32dxvtxvUTPS0CUI> is not available
[2025-11-22T14:30:30Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:3Dgmyz32dxvtxvUTPS0CUI")>: ()
[2025-11-22T14:30:30Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-11-22T14:30:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e/inactive?notify=false&product=0&country=IN&salt=4098692375
[2025-11-22T14:30:30Z DEBUG librespot_playback::player] command=EmitSessionDisconnectedEvent("YTRhZWVlN2EtODI1OS00Y2ViLWFmYjEtOGFiODVkOGYxMGVmK2RlYWxlcit0Y3A6Ly8wYWIxNTgyMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQjE0RUY4RTk3RjJFNkU5NzNFN0Y2MUE1ODE5MkFFQzJGMzkxMDQ4RTJENjNFNDdDNENFOTNGQkExODk4NzM3RA==", "drh8spxczmnxeqlywln0iptuo")
[2025-11-22T14:30:30Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-11-22T14:30:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=3079093765
[2025-11-22T14:30:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/7c28ab8a5c9512e4266ac7cb756312c82ee43d7e?product=0&country=IN&salt=1795994099
[2025-11-22T14:30:30Z DEBUG librespot_core::dealer] closing dealer
[2025-11-22T14:30:30Z DEBUG librespot_core::dealer] Dropping send task
[2025-11-22T14:30:30Z DEBUG tungstenite::protocol] Received close frame: None
[2025-11-22T14:30:30Z DEBUG librespot_core::dealer] Websocket connection closed.
[2025-11-22T14:30:30Z DEBUG librespot_core::dealer] Dropping receive task
[2025-11-22T14:30:30Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2025-11-22T14:30:30Z DEBUG librespot_playback::player] Shutting down player thread ...
[2025-11-22T14:30:30Z DEBUG librespot_playback::player] drop PlayerInternal[0]
[2025-11-22T14:30:30Z DEBUG librespot_playback::player] PlayerInternal thread finished.
[2025-11-22T14:30:30Z DEBUG librespot_core::session] drop Session
[2025-11-22T14:30:30Z DEBUG librespot::component] drop ApResolver
[2025-11-22T14:30:30Z DEBUG librespot::component] drop MercuryManager
[2025-11-22T14:30:30Z DEBUG librespot::component] drop DealerManager
[2025-11-22T14:30:30Z DEBUG librespot::component] drop SpClient
[2025-11-22T14:30:30Z DEBUG librespot::component] drop Login5Manager
[2025-11-22T14:30:30Z DEBUG librespot_core::session] drop Dispatch

publicstaticvoidmain42 avatar Nov 22 '25 14:11 publicstaticvoidmain42

Just to check if it was just me, I contacted one of my friends to try it with some of their family accounts. Almost all of them had the same audio key error but there's a new error we did get on one of the accounts. I'll paste the debug output below. The issue that happens here is that it starts librespot but as soon as he tried to play a song with Spotify Connect, the client kept jumping through songs without even playing then and eventually he had to quit with ctrl c.

That version of librespot has a bug that was fixed in 0.8.0.

drobotk avatar Nov 22 '25 14:11 drobotk

@drobotk Sorry. I'll ask them to update and check again.

publicstaticvoidmain42 avatar Nov 22 '25 14:11 publicstaticvoidmain42

Right, it works for them with 0.8.0. Not sure why it doesn't work for me however.

publicstaticvoidmain42 avatar Nov 22 '25 14:11 publicstaticvoidmain42

When Spotify change things they do it on a handful of accounts at a time. They may be phasing out this way of getting the key and you're unlucky enough to be one of the first. I'll grab my debug log later for this song and I'm also in the UK so it should be identical except mine works, so the only difference is then your account. Which isn't good news for anyone.

kingosticks avatar Nov 22 '25 20:11 kingosticks

Here's my debug log. Very similar... except it can get the key and play audio like normal. So not much insight there, just to show everything is the same... right up until it doesn't work for you. I've got a family account.

[2025-11-23T22:06:24Z INFO  librespot] librespot 0.8.0 ea81314 (Built on 2025-11-23, Build ID: RW6uTeOr, Profile: debug)
[2025-11-23T22:06:24Z WARN  librespot] Credential caching is unavailable, but advisable when using OAuth login.
[2025-11-23T22:06:24Z DEBUG librespot_core::session] new Session
Browse to: https://accounts.spotify.com/authorize?response_type=code&client_id=65b708073fc0480ea92a077233c...................
[2025-11-23T22:06:24Z INFO  librespot_oauth] OAuth server listening on 127.0.0.1:5588
[2025-11-23T22:06:26Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2025-11-23T22:06:26Z DEBUG librespot_playback::player] new Player [0]
[2025-11-23T22:06:26Z DEBUG librespot_connect::spirc] new Spirc[0]
[2025-11-23T22:06:26Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2025-11-23T22:06:26Z INFO  librespot_playback::audio_backend::pulseaudio] Using PulseAudioSink with format: S16
[2025-11-23T22:06:26Z DEBUG librespot::component] new DealerManager
[2025-11-23T22:06:26Z DEBUG librespot::component] new SpClient
[2025-11-23T22:06:26Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2025-11-23T22:06:26Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2025-11-23T22:06:26Z DEBUG librespot_core::spclient] Received a granted token
[2025-11-23T22:06:26Z DEBUG librespot::component] new ApResolver
[2025-11-23T22:06:26Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2025-11-23T22:06:26Z INFO  librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2025-11-23T22:06:26Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-23T22:06:26Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_SPOTIFY_TOKEN
[2025-11-23T22:06:26Z DEBUG librespot_core::connection] Connection to AP established.
[2025-11-23T22:06:26Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[2025-11-23T22:06:26Z INFO  librespot_core::session] Authenticated as 'kingosticksx' !
[2025-11-23T22:06:26Z DEBUG librespot::component] new Login5Manager
[2025-11-23T22:06:26Z DEBUG librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[2025-11-23T22:06:26Z DEBUG librespot_core::session] Session strong=5 weak=6
[2025-11-23T22:06:26Z INFO  librespot_core::session] Country: "GB"
[2025-11-23T22:06:26Z DEBUG librespot::component] new MercuryManager
[2025-11-23T22:06:26Z DEBUG librespot_connect::spirc] SpircTask::set_volume(32767)
[2025-11-23T22:06:26Z DEBUG librespot_playback::player] command=AddEventSender
[2025-11-23T22:06:26Z DEBUG librespot_playback::mixer::mappings] Input volume 32767 mapped to: 3.16%
[2025-11-23T22:06:26Z DEBUG librespot_core::dealer::manager] Launching dealer
[2025-11-23T22:06:26Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2025-11-23T22:06:26Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=3069860670
[2025-11-23T22:06:27Z DEBUG librespot_connect::spirc] successfully put connect state for 2e1428d3e9d21e8cf777bdea2526d20ee0e87e83 with connection-id NjdkNTgyNWYtOGNkNy00ZjFkLWE1MjktNjE4ZTQ1ZDlhNDMwK2RlYWxlcit0Y3A6Ly8wYWNhNDA4Yi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQzNBQzZGNzgzODRGMjdEQkUxMEYyMTczMjY4M0Q0RjI0RTE4QkU5OTI5QThGRjM2MTdEQzU3MjUwMUE0MjIyOA==
[2025-11-23T22:06:27Z INFO  librespot_connect::spirc] active device is <28fb1d3ac29157ee722f47befb360195aeec1c5a> with session <56913899-9503-479d-82e9-b3012151551f>
[2025-11-23T22:06:39Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICES_DISAPPEARED) from 28fb1d3ac29157ee722f47befb360195aeec1c5a, active device:
[2025-11-23T22:06:40Z DEBUG librespot_connect::spirc] cluster update: Ok(NEW_DEVICE_APPEARED) from 2a94bc2eeeda310423bda6ee3c9541f82eea301a, active device:
[2025-11-23T22:06:41Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from 2a94bc2eeeda310423bda6ee3c9541f82eea301a, active device: 2a94bc2eeeda310423bda6ee3c9541f82eea301a
[2025-11-23T22:06:41Z DEBUG librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[2025-11-23T22:06:41Z DEBUG librespot_core::mercury] unknown subscription uri=social-connect/v2/broadcast_status_update
[2025-11-23T22:06:41Z DEBUG librespot_core::session] could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "social-connect/v2/broadcast_status_update", status_code: 200, payload: [[123, 34, 100, 101, 118, 105, 99, 101, 66, 114, 111, 97, 100, 99, 97, 115, 116, 83, 116, 97, 116, 117, 115, 34, 58, 123, 34, 116, 105, 109, 101, 115, 116, 97, 109, 112, 34, 58, 34, 49, 55, 54, 51, 57, 51, 53, 54, 48, 52, 49, 51, 57, 34, 44, 34, 98, 114, 111, 97, 100, 99, 97, 115, 116, 95, 115, 116, 97, 116, 117, 115, 34, 58, 34, 66, 82, 79, 65, 68, 67, 65, 83, 84, 95, 85, 78, 65, 86, 65, 73, 76, 65, 66, 76, 69, 34, 44, 34, 100, 101, 118, 105, 99, 101, 95, 105, 100, 34, 58, 34, 50, 97, 57, 52, 98, 99, 50, 101, 101, 101, 100, 97, 51, 49, 48, 52, 50, 51, 98, 100, 97, 54, 101, 101, 51, 99, 57, 53, 52, 49, 102, 56, 50, 101, 101, 97, 51, 48, 49, 97, 34, 44, 34, 108, 105, 110, 107, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 50, 79, 70, 105, 79, 104, 57, 80, 100, 122, 105, 109, 66, 117, 117, 67, 104, 83, 82, 84, 108, 65, 34, 125, 125, 125]] } }
[2025-11-23T22:06:41Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_VOLUME_CHANGED) from 2a94bc2eeeda310423bda6ee3c9541f82eea301a, active device: 2a94bc2eeeda310423bda6ee3c9541f82eea301a
[2025-11-23T22:06:41Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from 2a94bc2eeeda310423bda6ee3c9541f82eea301a, active device: 2a94bc2eeeda310423bda6ee3c9541f82eea301a
[2025-11-23T22:06:42Z DEBUG librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from 2a94bc2eeeda310423bda6ee3c9541f82eea301a, active device: 2a94bc2eeeda310423bda6ee3c9541f82eea301a
[2025-11-23T22:06:47Z DEBUG librespot_connect::spirc] handling: 'endpoint: transfer' from 2a94bc2eeeda310423bda6ee3c9541f82eea301a
[2025-11-23T22:06:47Z WARN  librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::transfer] transfer track was the current track
[2025-11-23T22:06:47Z DEBUG librespot_connect::spirc] found initial track <spotify:track:3BRfgsKjcakny2wCYfZrvz>
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitSessionConnectedEvent("NjdkNTgyNWYtOGNkNy00ZjFkLWE1MjktNjE4ZTQ1ZDlhNDMwK2RlYWxlcit0Y3A6Ly8wYWNhNDA4Yi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQzNBQzZGNzgzODRGMjdEQkUxMEYyMTczMjY4M0Q0RjI0RTE4QkU5OTI5QThGRjM2MTdEQzU3MjUwMUE0MjIyOA==", "kingosticks4")
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitSessionClientChangedEvent("65b708073fc0480ea92a077233ca87bd", "", "", "")
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitVolumeChangedEvent(32767)
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitAutoPlayChangedEvent(false)
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitShuffleChangedEvent(false)
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] update position to 0:00 at 22:06:50.115
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=EmitRepeatChangedEvent(false, false)
[2025-11-23T22:06:47Z DEBUG librespot_playback::player] command=Load(SpotifyUri("spotify:track:3BRfgsKjcakny2wCYfZrvz"), true, 0)
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=1645640644
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/extended-metadata/v0/extended-metadata?product=0&country=GB&salt=3000220167
[2025-11-23T22:06:47Z INFO  librespot_playback::player] Loading <Chinatown> with Spotify URI <spotify:track:3BRfgsKjcakny2wCYfZrvz>
[2025-11-23T22:06:47Z DEBUG librespot_audio::fetch] Downloading file 8b2551eb348f9a2ba503251e7b59a39f94c012a7
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/8b2551eb348f9a2ba503251e7b59a39f94c012a7?product=0&country=GB&salt=1432432236
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-23T22:06:47Z DEBUG librespot_core::dealer::manager] replying to ws request: Success
[2025-11-23T22:06:47Z DEBUG librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[2025-11-23T22:06:47Z DEBUG librespot_core::mercury] unknown subscription uri=social-connect/v2/broadcast_status_update
[2025-11-23T22:06:47Z DEBUG librespot_core::session] could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "social-connect/v2/broadcast_status_update", status_code: 200, payload: [[123, 34, 100, 101, 118, 105, 99, 101, 66, 114, 111, 97, 100, 99, 97, 115, 116, 83, 116, 97, 116, 117, 115, 34, 58, 123, 34, 116, 105, 109, 101, 115, 116, 97, 109, 112, 34, 58, 34, 49, 55, 54, 51, 57, 51, 53, 54, 48, 57, 54, 49, 55, 34, 44, 34, 98, 114, 111, 97, 100, 99, 97, 115, 116, 95, 115, 116, 97, 116, 117, 115, 34, 58, 34, 66, 82, 79, 65, 68, 67, 65, 83, 84, 95, 79, 78, 34, 44, 34, 100, 101, 118, 105, 99, 101, 95, 105, 100, 34, 58, 34, 50, 101, 49, 52, 50, 56, 100, 51, 101, 57, 100, 50, 49, 101, 56, 99, 102, 55, 55, 55, 98, 100, 101, 97, 50, 53, 50, 54, 100, 50, 48, 101, 101, 48, 101, 56, 55, 101, 56, 51, 34, 44, 34, 109, 100, 110, 115, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 49, 73, 53, 54, 80, 108, 56, 51, 97, 105, 118, 86, 113, 100, 89, 74, 108, 56, 70, 51, 80, 98, 34, 125, 44, 34, 115, 111, 99, 105, 97, 108, 95, 114, 97, 100, 97, 114, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 87, 49, 78, 76, 68, 75, 65, 85, 66, 69, 87, 71, 55, 89, 89, 78, 81, 55, 80, 82, 34, 125, 44, 34, 108, 105, 110, 107, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 50, 79, 70, 105, 79, 104, 57, 80, 100, 122, 105, 109, 66, 117, 117, 67, 104, 83, 82, 84, 108, 65, 34, 125, 125, 125]] } }
[2025-11-23T22:06:47Z INFO  librespot_connect::spirc] session update: <Ok(NEW_SESSION)> for self, current session_id af7c14ec3ba0412486a7381efb442b27, new session_id 47463ca9c75bb57c388768871e9c4757
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] update position to 0:00 at 22:06:50.421
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=1560014905
[2025-11-23T22:06:47Z DEBUG librespot::component] new AudioKeyManager
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/context-resolve/v1/spotify:track:3BRfgsKjcakny2wCYfZrvz
[2025-11-23T22:06:47Z DEBUG librespot_connect::spirc] handling next context Some("spotify:track:3BRfgsKjcakny2wCYfZrvz")
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::context] updated context Default to <Some("spotify:track:3BRfgsKjcakny2wCYfZrvz")> (1 tracks)
[2025-11-23T22:06:47Z DEBUG librespot_connect::context_resolver] last item of type <Default>, finishing state setup
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::transfer] active track is <spotify:track:3BRfgsKjcakny2wCYfZrvz> with index Ok(0) in Default context, has 1 tracks
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::transfer] setting up next and prev: index is at Some(0) while shuffle false
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::tracks] set track to: spotify:track:3BRfgsKjcakny2wCYfZrvz at 0 of 1 tracks
[2025-11-23T22:06:47Z DEBUG librespot_connect::state::tracks] finished filling up next_tracks (0)
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] update position to 0:00 at 22:06:50.502
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=3114892456
[2025-11-23T22:06:47Z DEBUG librespot_connect::spirc] Received SessionUpdate::WIFI_BROADCAST_CHANGED
[2025-11-23T22:06:47Z INFO  librespot_playback::player] <Chinatown> (198842 ms) loaded
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: false
[2025-11-23T22:06:47Z DEBUG librespot_connect::state] update position to 0:00 at 22:06:50.932
[2025-11-23T22:06:47Z DEBUG librespot_core::http_client] Requesting https://gew1-spclient.spotify.com:443/connect-state/v1/devices/2e1428d3e9d21e8cf777bdea2526d20ee0e87e83?product=0&country=GB&salt=987957144
[2025-11-23T22:06:48Z DEBUG librespot_audio::fetch] Downloading file 8b2551eb348f9a2ba503251e7b59a39f94c012a7 complete

kingosticks avatar Nov 23 '25 22:11 kingosticks

When Spotify change things they do it on a handful of accounts at a time. They may be phasing out this way of getting the key and you're unlucky enough to be one of the first.

Is there any way I can help with getting the new audio key logic?

publicstaticvoidmain42 avatar Nov 24 '25 04:11 publicstaticvoidmain42

As far as we know, there is no "new audio key logic" that librespot could legally implement. For now we have to wait and see.

drobotk avatar Nov 24 '25 09:11 drobotk

Is this the same issue as this?

drobotk avatar Dec 02 '25 11:12 drobotk

I don't think so because that was discovered by comparing the difference in behaviour between go-librespot and librespot as per https://github.com/devgianlu/go-librespot/issues/235#issuecomment-3599449993. And the above working log I provided replicates exactly what @publicstaticvoidmain42 is doing, including the same market so we should be getting the exact same IDs.

kingosticks avatar Dec 02 '25 11:12 kingosticks