Issues Reconnecting with Discovery Mode

[davidcooper1]

Description
Reconnecting in discovery mode does not always work. There are two main scenarios:

1. Transferring to and from a different Spotify Connect device.
2. Switching from spotifyd device to main speakers then back to spotifyd.

Side note: This is in a different code area, but there is also an issue with relaunching spotifyd when using discovery mode credentials. It uses the credentials to recapture the same session, but spotifyd does not show up as the output speaker on Spotify clients.

If you try to connect at this point, a similar output loop to the one described below occurs. Likely offering an option to disable credential caching (or even just discovery credential caching) would be a good idea to make usage of the discovery mode easier. Is there already something in the works for disabling credential caching or should I make a feature request for this?

To Reproduce
Either scenario boils down to the following:

1. With no credentials cached, connect to spotifyd.
2. Transfer to ANY other device (includes the device you started the connection from such as a phone).
3. Try to transfer back

In either case, the connection will eventually error out by disconnecting from spotifyd without user intervention. If you don't do anything from here, you can still see session state changes, but you cannot play music. Attempts to reconnect again from here result in looping log error messages.

Expected behavior
A user should be able to swap between devices at will without worrying about potential disconnects or session errors.

Using raspotify, this behavior is seamless. I also have credential caching off there. However, I cannot use raspotify for my use-case, as I need to rely on MPRIS.

Logs
I've filtered out any libmdns lines as they were particularly useless and clogged up the logs. If so desired, I can regenerate logs with these lines, but after looking into this a bit, I do not believe they are relevant. These logs also do not contain the aforementioned log loop, as triggering this loop makes it hard to tell what parts of the logs are relevant and worth sending.

Click to show logs

[�[37mINFO�[0m spotifyd::config] Loading config from "/etc/spotifyd.conf"
[�[37mDEBUG�[0m spotifyd::config] No proxy specified
[�[37mINFO�[0m spotifyd::setup] Using software volume controller.
[�[37mINFO�[0m librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[�[37mINFO�[0m spotifyd::setup] Starting zeroconf server to advertise on local network.
[�[37mDEBUG�[0m spotifyd::setup] Using device id 'f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a'
[�[37mDEBUG�[0m librespot_discovery::server] Zeroconf server listening on 0.0.0.0:42031
[�[37mDEBUG�[0m librespot_discovery::server] POST "/" {}
[�[37mDEBUG�[0m librespot_core::session] new Session
[�[37mDEBUG�[0m librespot_connect::spirc] new Spirc[0]
[�[37mDEBUG�[0m librespot::component] new DealerManager
[�[37mDEBUG�[0m librespot_playback::player] new Player [0]
[�[37mINFO�[0m librespot_playback::convert] Converting with ditherer: tpdf
[�[37mINFO�[0m librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[�[37mDEBUG�[0m librespot::component] new SpClient
[�[37mDEBUG�[0m librespot_core::spclient] Client token unavailable or expired, requesting new token.
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[�[37mDEBUG�[0m librespot_core::spclient] Received a granted token
[�[37mDEBUG�[0m librespot::component] new ApResolver
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[�[37mINFO�[0m librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[�[37mDEBUG�[0m librespot_core::connection] Connection to AP established.
[�[37mDEBUG�[0m librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[�[37mINFO�[0m librespot_core::session] Authenticated as 'sz5c75x30yy1lc0nvqgzeahpw' !
[�[37mDEBUG�[0m librespot::component] new Login5Manager
[�[37mDEBUG�[0m librespot_core::session] Session strong=4 weak=6
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[�[37mINFO�[0m librespot_core::session] Country: "US"
[�[37mDEBUG�[0m librespot::component] new MercuryManager
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::mixer::mappings] Input volume 58981 mapped to: 50.12%
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::dealer::manager] Launching dealer
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m tungstenite::handshake::client] Client handshake done.
[�[37mINFO�[0m librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=2281426203
[�[37mDEBUG�[0m librespot_connect::spirc] successfully put connect state for f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a with connection-id ZmU5MjdjOTktMjMxYi00MjZjLTg1ZjUtY2I0NzMyNTkwM2IwK2RlYWxlcit0Y3A6Ly8wYWIxNDhhOS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArM0M4NjEzQzc5NkM2MUFGOTUyNTZERjJDM0NCOTgzMUE1OTAzQ0U0QzAxRUE5RkIwRjBBM0I2NjVGMjlENDUxMw==
[�[37mINFO�[0m librespot_connect::spirc] active device is <dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba> with session <439731eb-c159-459a-aaeb-a6c4c1358fe9>
[�[37mDEBUG�[0m librespot_connect::spirc] handling: 'endpoint: transfer' from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_connect::state::transfer] transfer track was the current track
[�[37mDEBUG�[0m librespot_connect::spirc] found initial track <spotify:track:2pZkX6yyPuF8UdRqGXsDci>
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionConnectedEvent("ZmU5MjdjOTktMjMxYi00MjZjLTg1ZjUtY2I0NzMyNTkwM2IwK2RlYWxlcit0Y3A6Ly8wYWIxNDhhOS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArM0M4NjEzQzc5NkM2MUFGOTUyNTZERjJDM0NCOTgzMUE1OTAzQ0U0QzAxRUE5RkIwRjBBM0I2NjVGMjlENDUxMw==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionClientChangedEvent("65b708073fc0480ea92a077233ca87bd", "", "", "")
[�[37mDEBUG�[0m librespot_playback::player] command=EmitVolumeChangedEvent(58981)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitAutoPlayChangedEvent(false)
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1041073160
[�[37mDEBUG�[0m librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitShuffleChangedEvent(false)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitRepeatChangedEvent(false, false)
[�[37mDEBUG�[0m librespot_playback::player] command=Load(SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), false, 67369)
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/extended-metadata/v0/extended-metadata?product=0&country=US&salt=2508493486
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event SessionClientChanged { client_id: "65b708073fc0480ea92a077233ca87bd", client_name: "", client_brand_name: "", client_model_name: "" }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event VolumeChanged { volume: 58981 }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event AutoPlayChanged { auto_play: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event FilterExplicitContentChanged { filter: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event ShuffleChanged { shuffle: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event RepeatChanged { context: false, track: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event PlayRequestIdChanged { play_request_id: 0 }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Loading { play_request_id: 0, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), position_ms: 67369 }
[�[37mINFO�[0m librespot_playback::player] Loading <Ganja Tape> with Spotify URI <spotify:track:2pZkX6yyPuF8UdRqGXsDci>
[�[37mDEBUG�[0m librespot_audio::fetch] Downloading file 2a440d87c277316c01f02168302742e117a9c736
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/storage-resolve/files/audio/interactive/2a440d87c277316c01f02168302742e117a9c736?product=0&country=US&salt=4000116564
[�[37mDEBUG�[0m librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m librespot_core::mercury] unknown subscription uri=social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m 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, 55, 52, 55, 57, 55, 54, 54, 55, 53, 57, 53, 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, 102, 55, 53, 48, 53, 48, 101, 52, 97, 100, 97, 49, 99, 102, 101, 56, 56, 50, 97, 55, 102, 52, 54, 51, 101, 102, 52, 97, 50, 48, 99, 49, 97, 51, 102, 101, 48, 101, 52, 97, 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, 55, 111, 81, 77, 56, 70, 113, 82, 54, 48, 54, 75, 70, 115, 103, 82, 49, 122, 117, 122, 67, 65, 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, 74, 85, 49, 82, 76, 81, 68, 72, 72, 48, 90, 56, 71, 72, 69, 85, 71, 86, 69, 87, 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, 55, 97, 79, 102, 68, 74, 104, 112, 78, 55, 89, 104, 49, 102, 118, 115, 49, 103, 90, 57, 101, 103, 34, 125, 44, 34, 100, 101, 118, 105, 99, 101, 95, 116, 121, 112, 101, 34, 58, 34, 83, 80, 69, 65, 75, 69, 82, 34, 125, 125]] } }
[�[37mDEBUG�[0m librespot::component] new AudioKeyManager
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Success
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:3CsqNkt4RuyYKqHsecxNmO
[�[37mDEBUG�[0m librespot_connect::spirc] Received SessionUpdate::WIFI_BROADCAST_CHANGED
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:3CsqNkt4RuyYKqHsecxNmO
[�[37mDEBUG�[0m symphonia_core::probe] found a possible format marker within [4f, 67, 67, 53, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] @ 0+2 bytes.
[�[37mDEBUG�[0m symphonia_core::probe] found the format marker [4f, 67, 67, 53] @ 0+2 bytes.
[�[37mDEBUG�[0m symphonia_format_ogg::page] grow page buffer to 8192 bytes
[�[37mINFO�[0m symphonia_format_ogg::demuxer] starting new physical stream
[�[37mINFO�[0m symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba, active device: f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a
[�[37mDEBUG�[0m symphonia_codec_vorbis] vorbis: leftover bits in setup head extra data
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seeking track=0x0 to frame_ts=2970972
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=5636416, end_ts=5639552 } byte_range=[4026, 6087533, 12171040]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=3209536, end_ts=3212800 } byte_range=[4026, 3045779, 6087533]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=1668160, end_ts=1671232 } byte_range=[4026, 1524902, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2536384, end_ts=2540480 } byte_range=[1524902, 2285340, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2909568, end_ts=2912128 } byte_range=[2285340, 2665559, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=3061056, end_ts=3064640 } byte_range=[2665559, 2855669, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2980032, end_ts=2983360 } byte_range=[2665559, 2760614, 2855669]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seeked track=0x0 to packet_ts=2970880 (delta=-92)
[�[37mINFO�[0m librespot_playback::player] <Ganja Tape> (254488 ms) loaded
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event TrackChanged { audio_item: AudioItem { track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), uri: "spotify:track:2pZkX6yyPuF8UdRqGXsDci", files: AudioFiles({AAC_24: FileId(Ok("3b45b31ce3b3941347033e78b91c9eb869eb9ba7")), OGG_VORBIS_160: FileId(Ok("fbe757de3f73b359fe1aa0b4fd0a340565e12393")), OGG_VORBIS_320: FileId(Ok("2a440d87c277316c01f02168302742e117a9c736")), OGG_VORBIS_96: FileId(Ok("1d9b6b35b18bcdb37e37d32a62126979e378d841"))}), name: "Ganja Tape", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b273340883dda987a2bbce4cdadd", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e02340883dda987a2bbce4cdadd", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00004851340883dda987a2bbce4cdadd", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 254488, is_explicit: false, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyUri("spotify:artist:1a6oIpEh4DGgaqgWg5xwd3"), name: "Ganja White Night", role: ARTIST_ROLE_MAIN_ARTIST }, ArtistWithRole { id: SpotifyUri("spotify:artist:59tlsKpLWoLTxjNNS2wdPi"), name: "Tape B", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "Ganja Tape", album_artists: ["Ganja White Night", "Tape B"], popularity: 45, number: 1, disc_number: 1 } } }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Paused { play_request_id: 0, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), position_ms: 67366 }
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=4262659304
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:3CsqNkt4RuyYKqHsecxNmO
[�[37mDEBUG�[0m librespot_connect::spirc] handling next context Some("spotify:playlist:3CsqNkt4RuyYKqHsecxNmO")
[�[37mDEBUG�[0m librespot_connect::state::context] updated context Default to <Some("spotify:playlist:3CsqNkt4RuyYKqHsecxNmO")> (1228 tracks)
[�[37mDEBUG�[0m librespot_connect::context_resolver] last item of type <Default>, finishing state setup
[�[37mDEBUG�[0m librespot_connect::state::transfer] active track is <spotify:track:2pZkX6yyPuF8UdRqGXsDci> with index Ok(725) in Default context, has 1228 tracks
[�[37mDEBUG�[0m librespot_connect::state::transfer] setting up next and prev: index is at Some(725) while shuffle true
[�[37mDEBUG�[0m librespot_connect::state::tracks] set track to: spotify:track:2pZkX6yyPuF8UdRqGXsDci at 725 of 1228 tracks
[�[37mDEBUG�[0m librespot_connect::state::tracks] skipped track spotify:track:2pZkX6yyPuF8UdRqGXsDci during fillup as it's unavailable or should be skipped
[�[37mDEBUG�[0m librespot_connect::state::tracks] finished filling up next_tracks (80)
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=6210849
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=437616815
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba, active device: dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba
[�[37mINFO�[0m librespot_connect::spirc] device became inactive
[�[37mDEBUG�[0m librespot_connect::state] update position to 1:11 at 15:21:10.95
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1205786723
[�[37mDEBUG�[0m librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m librespot_core::mercury] unknown subscription uri=social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m 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, 55, 52, 55, 57, 55, 54, 55, 49, 57, 55, 50, 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, 100, 97, 98, 102, 50, 49, 55, 50, 102, 101, 98, 57, 98, 99, 53, 100, 48, 54, 55, 99, 52, 100, 49, 53, 54, 101, 56, 99, 48, 50, 97, 54, 97, 55, 101, 101, 100, 48, 98, 97, 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, 48, 113, 75, 110, 80, 76, 117, 107, 107, 55, 87, 49, 71, 113, 79, 89, 72, 51, 71, 77, 65, 107, 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, 75, 74, 66, 68, 67, 67, 76, 65, 81, 70, 68, 77, 84, 67, 70, 70, 90, 88, 56, 49, 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, 55, 97, 79, 102, 68, 74, 104, 112, 78, 55, 89, 104, 49, 102, 118, 115, 49, 103, 90, 57, 101, 103, 34, 125, 44, 34, 100, 101, 118, 105, 99, 101, 95, 116, 121, 112, 101, 34, 58, 34, 65, 86, 82, 34, 125, 125]] } }
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a/inactive?notify=false&product=0&country=US&salt=661458926
[�[37mDEBUG�[0m librespot_connect::state] reset_playback with active ctx <Default> fill_up ctx <Default>
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionDisconnectedEvent("ZmU5MjdjOTktMjMxYi00MjZjLTg1ZjUtY2I0NzMyNTkwM2IwK2RlYWxlcit0Y3A6Ly8wYWIxNDhhOS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArM0M4NjEzQzc5NkM2MUFGOTUyNTZERjJDM0NCOTgzMUE1OTAzQ0U0QzAxRUE5RkIwRjBBM0I2NjVGMjlENDUxMw==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_playback::player] command=Stop
[�[33mWARN�[0m librespot_connect::spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
[�[37mDEBUG�[0m librespot_connect::spirc] Received SessionUpdate::WIFI_BROADCAST_CHANGED
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Stopped { play_request_id: 0, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci") }
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba, active device: dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba
[�[37mDEBUG�[0m librespot_connect::spirc] handling: 'endpoint: transfer' from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_connect::state::transfer] transfer track was the current track
[�[37mDEBUG�[0m librespot_connect::spirc] found initial track <spotify:track:2pZkX6yyPuF8UdRqGXsDci>
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionConnectedEvent("ZmU5MjdjOTktMjMxYi00MjZjLTg1ZjUtY2I0NzMyNTkwM2IwK2RlYWxlcit0Y3A6Ly8wYWIxNDhhOS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArM0M4NjEzQzc5NkM2MUFGOTUyNTZERjJDM0NCOTgzMUE1OTAzQ0U0QzAxRUE5RkIwRjBBM0I2NjVGMjlENDUxMw==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionClientChangedEvent("65b708073fc0480ea92a077233ca87bd", "", "", "")
[�[37mDEBUG�[0m librespot_playback::player] command=EmitVolumeChangedEvent(58981)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitAutoPlayChangedEvent(false)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitShuffleChangedEvent(false)
[�[37mDEBUG�[0m librespot_playback::player] command=EmitRepeatChangedEvent(false, false)
[�[37mDEBUG�[0m librespot_playback::player] command=Load(SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), false, 67366)
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1090428777
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/extended-metadata/v0/extended-metadata?product=0&country=US&salt=2937651115
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event SessionClientChanged { client_id: "65b708073fc0480ea92a077233ca87bd", client_name: "", client_brand_name: "", client_model_name: "" }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event VolumeChanged { volume: 58981 }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event AutoPlayChanged { auto_play: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event FilterExplicitContentChanged { filter: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event ShuffleChanged { shuffle: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event RepeatChanged { context: false, track: false }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event PlayRequestIdChanged { play_request_id: 1 }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Loading { play_request_id: 1, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), position_ms: 67366 }
[�[37mINFO�[0m librespot_playback::player] Loading <Ganja Tape> with Spotify URI <spotify:track:2pZkX6yyPuF8UdRqGXsDci>
[�[37mDEBUG�[0m librespot_audio::fetch] Downloading file 2a440d87c277316c01f02168302742e117a9c736
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/storage-resolve/files/audio/interactive/2a440d87c277316c01f02168302742e117a9c736?product=0&country=US&salt=4022690781
[�[37mDEBUG�[0m librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m librespot_core::mercury] unknown subscription uri=social-connect/v2/broadcast_status_update
[�[37mDEBUG�[0m 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, 55, 52, 55, 57, 55, 54, 55, 54, 51, 50, 51, 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, 102, 55, 53, 48, 53, 48, 101, 52, 97, 100, 97, 49, 99, 102, 101, 56, 56, 50, 97, 55, 102, 52, 54, 51, 101, 102, 52, 97, 50, 48, 99, 49, 97, 51, 102, 101, 48, 101, 52, 97, 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, 55, 111, 81, 77, 56, 70, 113, 82, 54, 48, 54, 75, 70, 115, 103, 82, 49, 122, 117, 122, 67, 65, 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, 74, 85, 49, 82, 76, 81, 68, 72, 72, 48, 90, 56, 71, 72, 69, 85, 71, 86, 69, 87, 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, 55, 97, 79, 102, 68, 74, 104, 112, 78, 55, 89, 104, 49, 102, 118, 115, 49, 103, 90, 57, 101, 103, 34, 125, 44, 34, 100, 101, 118, 105, 99, 101, 95, 116, 121, 112, 101, 34, 58, 34, 83, 80, 69, 65, 75, 69, 82, 34, 125, 125]] } }
[�[37mDEBUG�[0m symphonia_core::probe] found a possible format marker within [4f, 67, 67, 53, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] @ 0+2 bytes.
[�[37mDEBUG�[0m symphonia_core::probe] found the format marker [4f, 67, 67, 53] @ 0+2 bytes.
[�[37mDEBUG�[0m symphonia_format_ogg::page] grow page buffer to 8192 bytes
[�[37mINFO�[0m symphonia_format_ogg::demuxer] starting new physical stream
[�[37mINFO�[0m symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0
[�[37mDEBUG�[0m librespot_connect::spirc] Received SessionUpdate::WIFI_BROADCAST_CHANGED
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Success
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:3CsqNkt4RuyYKqHsecxNmO
[�[37mDEBUG�[0m symphonia_codec_vorbis] vorbis: leftover bits in setup head extra data
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seeking track=0x0 to frame_ts=2970840
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=5636416, end_ts=5639552 } byte_range=[4026, 6087533, 12171040]
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from dabf2172feb9bc5d067c4d156e8c02a6a7eed0ba, active device: f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=3209536, end_ts=3212800 } byte_range=[4026, 3045779, 6087533]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=1668160, end_ts=1671232 } byte_range=[4026, 1524902, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2536384, end_ts=2540480 } byte_range=[1524902, 2285340, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2909568, end_ts=2912128 } byte_range=[2285340, 2665559, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=3061056, end_ts=3064640 } byte_range=[2665559, 2855669, 3045779]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2980032, end_ts=2983360 } byte_range=[2665559, 2760614, 2855669]
[�[37mDEBUG�[0m symphonia_format_ogg::demuxer] seeked track=0x0 to packet_ts=2970752 (delta=-88)
[�[37mINFO�[0m librespot_playback::player] <Ganja Tape> (254488 ms) loaded
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event TrackChanged { audio_item: AudioItem { track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), uri: "spotify:track:2pZkX6yyPuF8UdRqGXsDci", files: AudioFiles({AAC_24: FileId(Ok("3b45b31ce3b3941347033e78b91c9eb869eb9ba7")), OGG_VORBIS_96: FileId(Ok("1d9b6b35b18bcdb37e37d32a62126979e378d841")), OGG_VORBIS_160: FileId(Ok("fbe757de3f73b359fe1aa0b4fd0a340565e12393")), OGG_VORBIS_320: FileId(Ok("2a440d87c277316c01f02168302742e117a9c736"))}), name: "Ganja Tape", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b273340883dda987a2bbce4cdadd", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e02340883dda987a2bbce4cdadd", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00004851340883dda987a2bbce4cdadd", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 254488, is_explicit: false, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyUri("spotify:artist:1a6oIpEh4DGgaqgWg5xwd3"), name: "Ganja White Night", role: ARTIST_ROLE_MAIN_ARTIST }, ArtistWithRole { id: SpotifyUri("spotify:artist:59tlsKpLWoLTxjNNS2wdPi"), name: "Tape B", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "Ganja Tape", album_artists: ["Ganja White Night", "Tape B"], popularity: 45, number: 1, disc_number: 1 } } }
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Paused { play_request_id: 1, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), position_ms: 67363 }
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=650141838
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:3CsqNkt4RuyYKqHsecxNmO
[�[37mDEBUG�[0m librespot_connect::spirc] handling next context Some("spotify:playlist:3CsqNkt4RuyYKqHsecxNmO")
[�[37mDEBUG�[0m librespot_connect::state::context] updated context Default to <Some("spotify:playlist:3CsqNkt4RuyYKqHsecxNmO")> (1228 tracks)
[�[37mDEBUG�[0m librespot_connect::context_resolver] last item of type <Default>, finishing state setup
[�[37mDEBUG�[0m librespot_connect::state::transfer] active track is <spotify:track:2pZkX6yyPuF8UdRqGXsDci> with index Ok(725) in Default context, has 1228 tracks
[�[37mDEBUG�[0m librespot_connect::state::transfer] setting up next and prev: index is at Some(725) while shuffle true
[�[37mDEBUG�[0m librespot_connect::state::tracks] set track to: spotify:track:2pZkX6yyPuF8UdRqGXsDci at 725 of 1228 tracks
[�[37mDEBUG�[0m librespot_connect::state::tracks] skipped track spotify:track:2pZkX6yyPuF8UdRqGXsDci during fillup as it's unavailable or should be skipped
[�[37mDEBUG�[0m librespot_connect::state::tracks] finished filling up next_tracks (80)
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1392456261
[�[37mDEBUG�[0m librespot_connect::spirc] handling: 'endpoint: resume' from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::player] command=Play
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Success
[�[37mDEBUG�[0m spotifyd::dbus_mpris] handling event Playing { play_request_id: 1, track_id: SpotifyUri("spotify:track:2pZkX6yyPuF8UdRqGXsDci"), position_ms: 67363 }
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: false, buffering: false
[�[37mDEBUG�[0m librespot_connect::state] update position to 1:07 at 15:21:43.758
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=688550036
[�[37mDEBUG�[0m librespot_audio::fetch] Downloading file 2a440d87c277316c01f02168302742e117a9c736 complete
[�[37mDEBUG�[0m librespot_audio::fetch] File 2a440d87c277316c01f02168302742e117a9c736 cached to "/opt/spotifyd/2a/440d87c277316c01f02168302742e117a9c736"
[�[37mDEBUG�[0m librespot_core::session] Session strong=8 weak=8

Compilation flags

• dbus_mpris
• alsa_backend
• portaudio_backend
• pulseaudio_backend
• rodio_backend

Versions (please complete the following information):

• OS: Raspberry Pi OS Lite Trixie for Raspberry Pi 4 (arm64/aarch64)
• Spotifyd:
  • Tried full pre-compiled binary from CD pipeline at 6af1e48
  • Also personally cross compiled v0.4.2 using Docker
• cargo: 1.94.1 (According to rust:1-bookworm image in Docker Hub)

When there is no connection cache and the device is in its first session everything seems to go okay. It is just when the session either times out or swaps devices that everything stops working with discovery authentication.

[davidcooper1]

Logs for starting spotifyd without wiping credentials then trying to connect. There is an endless error loop here, and the official Spotify client shows as connecting for a long time. I've stopped this before it went on too long because it will go on practically forever.

Click to show logs

[�[37mINFO�[0m spotifyd::config] Loading config from "/etc/spotifyd.conf"
[�[37mDEBUG�[0m spotifyd::config] No proxy specified
[�[37mINFO�[0m spotifyd::setup] Using software volume controller.
[�[37mINFO�[0m librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[�[37mINFO�[0m spotifyd::setup] Restoring previous login as user sz5c75x30yy1lc0nvqgzeahpw.
[�[37mINFO�[0m spotifyd::setup] Starting zeroconf server to advertise on local network.
[�[37mDEBUG�[0m spotifyd::setup] Using device id 'f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a'
[�[37mDEBUG�[0m librespot_discovery::server] Zeroconf server listening on 0.0.0.0:34163
[�[37mDEBUG�[0m librespot_core::session] new Session
[�[37mDEBUG�[0m librespot_connect::spirc] new Spirc[0]
[�[37mDEBUG�[0m librespot::component] new DealerManager
[�[37mDEBUG�[0m librespot_playback::player] new Player [0]
[�[37mINFO�[0m librespot_playback::convert] Converting with ditherer: tpdf
[�[37mINFO�[0m librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[�[37mDEBUG�[0m librespot::component] new SpClient
[�[37mDEBUG�[0m librespot_core::spclient] Client token unavailable or expired, requesting new token.
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[�[37mDEBUG�[0m librespot_core::spclient] Received a granted token
[�[37mDEBUG�[0m librespot::component] new ApResolver
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[�[37mINFO�[0m librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[�[37mDEBUG�[0m librespot_core::connection] Connection to AP established.
[�[37mDEBUG�[0m librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[�[37mINFO�[0m librespot_core::session] Authenticated as 'sz5c75x30yy1lc0nvqgzeahpw' !
[�[37mDEBUG�[0m librespot::component] new Login5Manager
[�[37mDEBUG�[0m librespot_core::session] Session strong=4 weak=6
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[�[37mINFO�[0m librespot_core::session] Country: "US"
[�[37mDEBUG�[0m librespot::component] new MercuryManager
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::mixer::mappings] Input volume 58981 mapped to: 50.12%
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::dealer::manager] Launching dealer
[�[37mDEBUG�[0m tungstenite::handshake::client] Client handshake done.
[�[37mINFO�[0m librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=3866318192
[�[37mDEBUG�[0m librespot_connect::spirc] successfully put connect state for f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a with connection-id NDE5ZTFiOGEtMmIyYS00NWQ3LTgyMWMtM2ZlNDA2Njk2ZThhK2RlYWxlcit0Y3A6Ly8wYWIxNDgwNy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArREVEQ0I0MTM0RTUxRjgyNzI5MUVDMzZFNThFNzUzRjNFNjc1M0IwOTAwNzdBMjRBRTg3RTcxMDdBRTUwQUIzQQ==
[�[37mINFO�[0m librespot_connect::spirc] active device is <> with session <5genOuVZYMn1fOxAl0m3JK>
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_NEW_CONNECTION) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: 
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: 
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(DEVICE_STATE_CHANGED) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: 
[�[37mDEBUG�[0m librespot_connect::spirc] cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 6fbfa02db9fbc3241eab2f605830fb630aba8b0e, active device: 
[�[37mDEBUG�[0m librespot_core::session] Session strong=6 weak=7
[�[37mDEBUG�[0m librespot_discovery::server] POST "/" {}
[�[37mDEBUG�[0m librespot_connect::state] update position to 29580042:01 at 16:42:01.711
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=2550595038
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a/inactive?notify=false&product=0&country=US&salt=4183169693
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionDisconnectedEvent("NDE5ZTFiOGEtMmIyYS00NWQ3LTgyMWMtM2ZlNDA2Njk2ZThhK2RlYWxlcit0Y3A6Ly8wYWIxNDgwNy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArREVEQ0I0MTM0RTUxRjgyNzI5MUVDMzZFNThFNzUzRjNFNjc1M0IwOTAwNzdBMjRBRTg3RTcxMDdBRTUwQUIzQQ==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=3037464781
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=2309302882
[�[37mDEBUG�[0m librespot_core::dealer] closing dealer
[�[37mDEBUG�[0m librespot_core::dealer] Dropping send task
[�[37mDEBUG�[0m tungstenite::protocol] Received close frame: None
[�[37mDEBUG�[0m librespot_core::dealer] Websocket connection closed.
[�[37mDEBUG�[0m librespot_core::dealer] Dropping receive task
[�[37mDEBUG�[0m librespot_connect::spirc] drop Spirc[0]
[�[37mDEBUG�[0m librespot_playback::player] Shutting down player thread ...
[�[37mDEBUG�[0m librespot_playback::player] drop PlayerInternal[0]
[�[37mDEBUG�[0m librespot_playback::player] PlayerInternal thread finished.
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Failure
[�[33mWARN�[0m librespot_core::dealer] Wasn't able to reply to dealer request: channel closed
[�[37mDEBUG�[0m librespot_core::session] new Session
[�[37mDEBUG�[0m librespot_connect::spirc] new Spirc[1]
[�[37mDEBUG�[0m librespot::component] new DealerManager
[�[37mDEBUG�[0m librespot_playback::player] new Player [1]
[�[37mINFO�[0m librespot_playback::convert] Converting with ditherer: tpdf
[�[37mINFO�[0m librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[�[37mDEBUG�[0m librespot::component] new SpClient
[�[37mDEBUG�[0m librespot_core::spclient] Client token unavailable or expired, requesting new token.
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[�[37mDEBUG�[0m librespot_core::spclient] Received a granted token
[�[37mDEBUG�[0m librespot::component] new ApResolver
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[�[37mINFO�[0m librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[�[37mDEBUG�[0m librespot_core::connection] Connection to AP established.
[�[37mDEBUG�[0m librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[�[37mINFO�[0m librespot_core::session] Authenticated as 'sz5c75x30yy1lc0nvqgzeahpw' !
[�[37mDEBUG�[0m librespot::component] new Login5Manager
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[�[37mDEBUG�[0m librespot_core::session] Session strong=5 weak=6
[�[37mINFO�[0m librespot_core::session] Country: "US"
[�[37mDEBUG�[0m librespot::component] new MercuryManager
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::mixer::mappings] Input volume 58981 mapped to: 50.12%
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::dealer::manager] Launching dealer
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::session] drop Session
[�[37mDEBUG�[0m librespot::component] drop ApResolver
[�[37mDEBUG�[0m librespot::component] drop MercuryManager
[�[37mDEBUG�[0m librespot::component] drop DealerManager
[�[37mDEBUG�[0m librespot::component] drop SpClient
[�[37mDEBUG�[0m librespot::component] drop Login5Manager
[�[37mDEBUG�[0m librespot_core::session] drop Dispatch
[�[37mDEBUG�[0m tungstenite::handshake::client] Client handshake done.
[�[37mINFO�[0m librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=770301753
[�[37mDEBUG�[0m librespot_connect::spirc] successfully put connect state for f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a with connection-id ZmFmYTJhMGUtOTlkYS00YzBlLTgxNWYtOTgyZGRmZTM5YzE1K2RlYWxlcit0Y3A6Ly8wYWIxNDgwNy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArNTkyNUU5MkE3QTUwNEJDNDc3QTg2RTlCRkY3RTQ1QkJDQzE4QTgyRjE0RTQxMzUwNkIzNTgxNEM4QUE5QkVDOQ==
[�[37mINFO�[0m librespot_connect::spirc] active device is <> with session <5genOuVZYMn1fOxAl0m3JK>
[�[37mDEBUG�[0m librespot_discovery::server] POST "/" {}
[�[37mDEBUG�[0m librespot_connect::state] update position to 29580042:08 at 16:42:08.096
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1912307512
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a/inactive?notify=false&product=0&country=US&salt=1635058917
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionDisconnectedEvent("ZmFmYTJhMGUtOTlkYS00YzBlLTgxNWYtOTgyZGRmZTM5YzE1K2RlYWxlcit0Y3A6Ly8wYWIxNDgwNy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArNTkyNUU5MkE3QTUwNEJDNDc3QTg2RTlCRkY3RTQ1QkJDQzE4QTgyRjE0RTQxMzUwNkIzNTgxNEM4QUE5QkVDOQ==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=2265257772
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=1637028414
[�[37mDEBUG�[0m librespot_core::dealer] closing dealer
[�[37mDEBUG�[0m librespot_core::dealer] Dropping send task
[�[37mDEBUG�[0m tungstenite::protocol] Received close frame: None
[�[37mDEBUG�[0m librespot_core::dealer] Websocket connection closed.
[�[37mDEBUG�[0m librespot_core::dealer] Dropping receive task
[�[37mDEBUG�[0m librespot_connect::spirc] drop Spirc[1]
[�[37mDEBUG�[0m librespot_playback::player] Shutting down player thread ...
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Failure
[�[33mWARN�[0m librespot_core::dealer] Wasn't able to reply to dealer request: channel closed
[�[37mDEBUG�[0m librespot_playback::player] drop PlayerInternal[1]
[�[37mDEBUG�[0m librespot_playback::player] PlayerInternal thread finished.
[�[37mDEBUG�[0m librespot_core::session] new Session
[�[37mDEBUG�[0m librespot_connect::spirc] new Spirc[2]
[�[37mDEBUG�[0m librespot::component] new DealerManager
[�[37mDEBUG�[0m librespot_playback::player] new Player [2]
[�[37mINFO�[0m librespot_playback::convert] Converting with ditherer: tpdf
[�[37mDEBUG�[0m librespot::component] new SpClient
[�[37mINFO�[0m librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[�[37mDEBUG�[0m librespot_core::spclient] Client token unavailable or expired, requesting new token.
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[�[37mDEBUG�[0m librespot_core::spclient] Received a granted token
[�[37mDEBUG�[0m librespot::component] new ApResolver
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[�[37mINFO�[0m librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[�[37mDEBUG�[0m librespot_core::connection] Connection to "ap-guc3.spotify.com:443" failed: Connection refused (os error 111)
[�[37mDEBUG�[0m librespot_core::connection] Retry access point...
[�[37mDEBUG�[0m librespot_core::connection] Connection to AP established.
[�[37mDEBUG�[0m librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[�[37mINFO�[0m librespot_core::session] Authenticated as 'sz5c75x30yy1lc0nvqgzeahpw' !
[�[37mDEBUG�[0m librespot::component] new Login5Manager
[�[37mDEBUG�[0m librespot_core::session] Session strong=4 weak=6
[�[37mINFO�[0m librespot_core::session] Country: "US"
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[�[37mDEBUG�[0m librespot::component] new MercuryManager
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::mixer::mappings] Input volume 58981 mapped to: 50.12%
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::dealer::manager] Launching dealer
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::session] drop Session
[�[37mDEBUG�[0m librespot::component] drop ApResolver
[�[37mDEBUG�[0m librespot::component] drop MercuryManager
[�[37mDEBUG�[0m librespot::component] drop DealerManager
[�[37mDEBUG�[0m librespot::component] drop SpClient
[�[37mDEBUG�[0m librespot::component] drop Login5Manager
[�[37mDEBUG�[0m librespot_core::session] drop Dispatch
[�[37mDEBUG�[0m tungstenite::handshake::client] Client handshake done.
[�[37mINFO�[0m librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=4085105746
[�[37mDEBUG�[0m librespot_connect::spirc] successfully put connect state for f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a with connection-id OGRmMDY4NjUtZWZlNi00MjU3LTk4YjMtYTMyYjY0NDVkYjAxK2RlYWxlcit0Y3A6Ly8wYWIxNDk3Yy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRkVDMzdGRDI3MzM4M0Y5NzYxQ0Q1MkNCQUYxQThFNUU1OTdCNjNFNjNGMTM3QzJFNDBBMEZGMDkxOEVBNkU4OQ==
[�[37mINFO�[0m librespot_connect::spirc] active device is <> with session <5genOuVZYMn1fOxAl0m3JK>
[�[37mDEBUG�[0m librespot_discovery::server] POST "/" {}
[�[37mDEBUG�[0m librespot_connect::state] update position to 29580042:14 at 16:42:14.41
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=2788710984
[�[33mWARN�[0m librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a/inactive?notify=false&product=0&country=US&salt=4130968830
[�[37mDEBUG�[0m librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[�[37mDEBUG�[0m librespot_playback::player] command=EmitSessionDisconnectedEvent("OGRmMDY4NjUtZWZlNi00MjU3LTk4YjMtYTMyYjY0NDVkYjAxK2RlYWxlcit0Y3A6Ly8wYWIxNDk3Yy5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRkVDMzdGRDI3MzM4M0Y5NzYxQ0Q1MkNCQUYxQThFNUU1OTdCNjNFNjNGMTM3QzJFNDBBMEZGMDkxOEVBNkU4OQ==", "sz5c75x30yy1lc0nvqgzeahpw")
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=935355754
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=3494394511
[�[37mDEBUG�[0m librespot_core::dealer] closing dealer
[�[37mDEBUG�[0m librespot_core::dealer] Dropping send task
[�[37mDEBUG�[0m tungstenite::protocol] Received close frame: None
[�[37mDEBUG�[0m librespot_core::dealer] Websocket connection closed.
[�[37mDEBUG�[0m librespot_core::dealer] Dropping receive task
[�[37mDEBUG�[0m librespot_connect::spirc] drop Spirc[2]
[�[37mDEBUG�[0m librespot_playback::player] Shutting down player thread ...
[�[37mDEBUG�[0m librespot_core::dealer::manager] replying to ws request: Failure
[�[33mWARN�[0m librespot_core::dealer] Wasn't able to reply to dealer request: channel closed
[�[37mDEBUG�[0m librespot_playback::player] drop PlayerInternal[2]
[�[37mDEBUG�[0m librespot_playback::player] PlayerInternal thread finished.
[�[37mDEBUG�[0m librespot_core::session] new Session
[�[37mDEBUG�[0m librespot_connect::spirc] new Spirc[3]
[�[37mDEBUG�[0m librespot::component] new DealerManager
[�[37mDEBUG�[0m librespot_playback::player] new Player [3]
[�[37mINFO�[0m librespot_playback::convert] Converting with ditherer: tpdf
[�[37mINFO�[0m librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[�[37mDEBUG�[0m librespot::component] new SpClient
[�[37mDEBUG�[0m librespot_core::spclient] Client token unavailable or expired, requesting new token.
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[�[37mDEBUG�[0m librespot_core::spclient] Received a granted token
[�[37mDEBUG�[0m librespot::component] new ApResolver
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[�[37mINFO�[0m librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[�[37mDEBUG�[0m librespot_core::connection] Connection to AP established.
[�[37mDEBUG�[0m librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[�[37mINFO�[0m librespot_core::session] Authenticated as 'sz5c75x30yy1lc0nvqgzeahpw' !
[�[37mDEBUG�[0m librespot::component] new Login5Manager
[�[37mDEBUG�[0m librespot_core::session] Session strong=4 weak=6
[�[37mINFO�[0m librespot_core::session] Country: "US"
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[�[37mDEBUG�[0m librespot::component] new MercuryManager
[�[37mDEBUG�[0m librespot_connect::spirc] SpircTask::set_volume(58981)
[�[37mDEBUG�[0m librespot_playback::mixer::mappings] Input volume 58981 mapped to: 50.12%
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::dealer::manager] Launching dealer
[�[37mDEBUG�[0m librespot_playback::player] command=AddEventSender
[�[37mDEBUG�[0m librespot_core::session] drop Session
[�[37mDEBUG�[0m librespot::component] drop ApResolver
[�[37mDEBUG�[0m librespot::component] drop MercuryManager
[�[37mDEBUG�[0m librespot::component] drop DealerManager
[�[37mDEBUG�[0m librespot::component] drop SpClient
[�[37mDEBUG�[0m librespot::component] drop Login5Manager
[�[37mDEBUG�[0m librespot_core::session] drop Dispatch
[�[37mDEBUG�[0m tungstenite::handshake::client] Client handshake done.
[�[37mINFO�[0m librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
[�[37mDEBUG�[0m librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/connect-state/v1/devices/f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a?product=0&country=US&salt=750256600
[�[37mDEBUG�[0m librespot_connect::spirc] successfully put connect state for f75050e4ada1cfe882a7f463ef4a20c1a3fe0e4a with connection-id OTUyNGMzOGQtOGE5ZC00NjEzLWE4NWEtNWVmZWFhZmIwNmY3K2RlYWxlcit0Y3A6Ly8wYWIxNDk0YS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArQkM2RkVDREUyQjE0OUMzRDQ2NTY2NzhBQTcxNUY4MTE5MEI3NTRDQTQwQzhBOURENTdDQUI1MUQyQjIxQ0ZCNg==
[�[37mINFO�[0m librespot_connect::spirc] active device is <> with session <5genOuVZYMn1fOxAl0m3JK>

[djdjfjfkeocj]

same