Connection to server closed

[zhjb7]

Description

After a few hours of continuous playback, spotify will disconnect from librespot and playback will stop.

Version

librespot 0.6.0 release

How to reproduce

Steps to reproduce the behavior in librespot e.g.
Compile and running in ubuntu 22.04.
Compile:cargo build --release
Running: ./target/release/librespot -v -n myubuntu

Log

[2025-04-22T11:05:28Z TRACE librespot_audio::fetch] Streaming from https://audio-fa.scdn.co/audio/df2da2cb6f496e6952eb7f9edae4751048862e4f?1745406328_VizjM4T-hm1tM8VYmv3lAuSKEGEHSBD0JHoOh7ka0zM=
[2025-04-22T11:05:30Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 288 ms
[2025-04-22T11:05:30Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 167 kbps
[2025-04-22T11:05:30Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 246 ms
[2025-04-22T11:05:31Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 288 ms
[2025-04-22T11:05:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 186 kbps
[2025-04-22T11:05:32Z INFO  librespot_playback::player] <To Be Loved By You> (199680 ms) loaded
[2025-04-22T11:05:34Z TRACE librespot_core::session] Sending Pong
[2025-04-22T11:05:34Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-22T11:05:34Z TRACE librespot_core::session] Received PongAck
[2025-04-22T11:05:34Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-22T11:05:55Z DEBUG librespot_connect::spirc] At track 13 of 60 <"spotify:playlist:37i9dQZF1E35tZmaR3qqwW"> update [false]
[2025-04-22T11:05:55Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2025-04-22T11:05:55Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2pUQX4d3Cjh3umGkVz0XyI"), true, 0)
[2025-04-22T11:05:55Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2025-04-22T11:05:55Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2025-04-22T11:05:56Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 250 ms
[2025-04-22T11:05:57Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 276 ms
[2025-04-22T11:05:57Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 149 kbps
[2025-04-22T11:05:57Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 103 kbps
[2025-04-22T11:05:58Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 146 kbps
[2025-04-22T11:05:59Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 127 kbps
[2025-04-22T11:05:59Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 68 kbps
[2025-04-22T11:05:59Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 129 kbps
[2025-04-22T11:05:59Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 244 ms
[2025-04-22T11:05:59Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 192 kbps
[2025-04-22T11:06:00Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 258 kbps
[2025-04-22T11:06:00Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 215 ms
[2025-04-22T11:06:00Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 332 kbps
[2025-04-22T11:06:01Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 240 ms
[2025-04-22T11:06:01Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 482 kbps
[2025-04-22T11:06:01Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 627 kbps
[2025-04-22T11:06:01Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 307 ms
[2025-04-22T11:06:02Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 723 kbps
[2025-04-22T11:06:02Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 472 kbps
[2025-04-22T11:06:03Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 819 kbps
[2025-04-22T11:06:03Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 912 kbps
[2025-04-22T11:06:04Z DEBUG librespot_audio::fetch] Downloading file df2da2cb6f496e6952eb7f9edae4751048862e4f complete
[2025-04-22T11:06:34Z TRACE librespot_core::session] Received Ping
[2025-04-22T11:06:34Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-22T11:06:34Z DEBUG librespot_core::session] Session strong=4 weak=7
[2025-04-22T11:07:34Z TRACE librespot_core::session] Sending Pong
[2025-04-22T11:07:34Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-22T11:07:48Z WARN  librespot_core::session] Connection to server closed.
[2025-04-22T11:07:48Z DEBUG librespot_core::session] Shutdown: Invalidating session
[2025-04-22T11:07:48Z DEBUG librespot::component] new ChannelManager
[2025-04-22T11:07:48Z DEBUG librespot_core::session] drop Dispatch
[2025-04-22T11:07:48Z ERROR librespot_connect::spirc] remote update selected, but none received
[2025-04-22T11:07:48Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2025-04-22T11:07:48Z WARN  librespot] Spirc shut down unexpectedly
[2025-04-22T11:07:48Z DEBUG librespot_core::session] new Session
[2025-04-22T11:07:48Z DEBUG librespot_connect::spirc] new Spirc[1]
[2025-04-22T11:07:48Z DEBUG librespot::component] new MercuryManager
[2025-04-22T11:07:48Z DEBUG librespot::component] new SpClient
[2025-04-22T11:07:48Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2025-04-22T11:07:48Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2025-04-22T11:07:48Z DEBUG librespot_playback::player] command=SetSession
[2025-04-22T11:07:48Z DEBUG librespot_core::session] drop Session
[2025-04-22T11:07:48Z DEBUG librespot::component] drop ApResolver
[2025-04-22T11:07:48Z DEBUG librespot::component] drop AudioKeyManager
[2025-04-22T11:07:48Z DEBUG librespot::component] drop ChannelManager
[2025-04-22T11:07:48Z DEBUG librespot::component] drop MercuryManager
[2025-04-22T11:07:48Z DEBUG librespot::component] drop SpClient
[2025-04-22T11:07:48Z DEBUG librespot::component] drop Login5Manager
[2025-04-22T11:08:08Z ERROR librespot] could not initialize spirc: Service unavailable { client error (Connect) }

Host (what you are running librespot on):

• OS: ubuntu 22.04
• Platform:HP computer

Additional context

[kingosticks]

What is "a few hours"? Is it two?

[zhjb7]

Thanks for your reply. Tested it a couple times, once for 3 hours with this problem, once for 5 hours with this problem. Since no one else has had this problem, I'm not sure if it's caused by a problem with my network. I will continue testing using a different network. I hope I won’t waste your time.

[Lustyn]

I ran into this as well, I'm guessing its related to this TODO:

librespot/core/src/session.rs

Line 785 in 59381cc

// TODO: Optionally reconnect (with cached/last credentials?)

[zhjb7]

Tested many times and often after a couple hours of playback, the spotify app is stopped, but the device is not disconnected. For example, this one was playing at 10:00 and stopped playing at 12:33. Not sure if it's my network that's causing this.

[2025-04-29T12:30:25Z TRACE librespot_audio::fetch] Streaming from https://audio-fa.scdn.co/audio/811963f0609f8388f1b958a2b87769558ea41864?1746016197_NYA-xnGSOKBhdZcAKVyPXTDZqyKfwDewBv5iCFcindA=
[2025-04-29T12:30:27Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 276 ms
[2025-04-29T12:30:29Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 40 kbps
[2025-04-29T12:30:31Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 48 kbps
[2025-04-29T12:30:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 58 kbps
[2025-04-29T12:30:34Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 304 ms
[2025-04-29T12:30:34Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 69 kbps
[2025-04-29T12:30:34Z INFO  librespot_playback::player] <Pick Me Up> (169440 ms) loaded
[2025-04-29T12:30:34Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2025-04-29T12:30:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 510 ms
[2025-04-29T12:30:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 304 ms
[2025-04-29T12:30:36Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 56 kbps
[2025-04-29T12:30:38Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 68 kbps
[2025-04-29T12:30:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 43 kbps
[2025-04-29T12:30:40Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 73 kbps
[2025-04-29T12:30:40Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 262 ms
[2025-04-29T12:30:40Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 115 kbps
[2025-04-29T12:30:42Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 123 kbps
[2025-04-29T12:30:43Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 75 kbps
[2025-04-29T12:30:43Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 302 ms
[2025-04-29T12:30:43Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 51 kbps
[2025-04-29T12:30:44Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 87 kbps
[2025-04-29T12:30:45Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 70 kbps
[2025-04-29T12:30:46Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 79 kbps
[2025-04-29T12:30:47Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 69 kbps
[2025-04-29T12:30:48Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 81 kbps
[2025-04-29T12:30:48Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 270 ms
[2025-04-29T12:30:50Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 408 ms
[2025-04-29T12:30:50Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 307 ms
[2025-04-29T12:30:52Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 74 kbps
[2025-04-29T12:30:53Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 83 kbps
[2025-04-29T12:30:54Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 99 kbps
[2025-04-29T12:30:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:30:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:30:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:30:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:30:57Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 90 kbps
[2025-04-29T12:30:57Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 243 ms
[2025-04-29T12:30:59Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 304 ms
[2025-04-29T12:31:03Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 566 ms
[2025-04-29T12:31:05Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 85 kbps
[2025-04-29T12:31:06Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 300 ms
[2025-04-29T12:31:07Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 108 kbps
[2025-04-29T12:31:08Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 125 kbps
[2025-04-29T12:31:08Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 214 ms
[2025-04-29T12:31:09Z DEBUG librespot_audio::fetch] Downloading file 811963f0609f8388f1b958a2b87769558ea41864 complete
[2025-04-29T12:31:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:31:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:31:56Z DEBUG librespot_core::session] Session strong=4 weak=7
[2025-04-29T12:32:54Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:4k3lPl8YTKuY8c1HelVnm3"))
[2025-04-29T12:32:54Z DEBUG librespot_playback::player] Preloading track
[2025-04-29T12:32:54Z DEBUG librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/metadata/4/track/8e0e186eb4324346b6f5b45843cffdbb?product=0&country=US&salt=1202821492
[2025-04-29T12:32:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:32:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:32:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:32:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:33:08Z DEBUG librespot_core::spclient] Error was: Err(Error { kind: Unavailable, error: hyper_util::client::legacy::Error(Connect, Custom { kind: Other, error: Custom { kind: Other, error: Custom { kind: UnexpectedEof, error: "tls handshake eof" } } }) })
[2025-04-29T12:33:08Z DEBUG librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/metadata/4/track/8e0e186eb4324346b6f5b45843cffdbb?product=0&country=US&salt=2638749837
[2025-04-29T12:33:19Z INFO  librespot_playback::player] Loading <'Til You Can't> with Spotify URI <spotify:track:4k3lPl8YTKuY8c1HelVnm3>
[2025-04-29T12:33:19Z DEBUG librespot_audio::fetch] Downloading file 0d0af103e04b1e3bbd826f1d427d0d009e8af5a8
[2025-04-29T12:33:19Z DEBUG librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/storage-resolve/files/audio/interactive/0d0af103e04b1e3bbd826f1d427d0d009e8af5a8?product=0&country=US&salt=1051684226
[2025-04-29T12:33:23Z DEBUG librespot_connect::spirc] At track 48 of 81 <"spotify:playlist:37i9dQZF1DXdfhOsjRMISB"> update [false]
[2025-04-29T12:33:23Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2025-04-29T12:33:23Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:4k3lPl8YTKuY8c1HelVnm3"), false, 0)
[2025-04-29T12:33:23Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2025-04-29T12:33:23Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2025-04-29T12:33:32Z TRACE librespot_core::cdn_url] Resolved CDN storage: CdnUrl {
        file_id: FileId(
            Ok(
                "0d0af103e04b1e3bbd826f1d427d0d009e8af5a8",
            ),
        ),
        urls: MaybeExpiringUrls(
            [
                MaybeExpiringUrl(
                    "https://audio-fa.scdn.co/audio/0d0af103e04b1e3bbd826f1d427d0d009e8af5a8?1746016411_3GvpIWvD6ezTY7qFApUSduTVMGjKILU2iYOTJPceitQ=",
                    Some(
                        Date(
                            2025-04-30 12:28:31.0 +00:00:00,
                        ),
                    ),
                ),
                MaybeExpiringUrl(
                    "https://audio4-ak.spotifycdn.com/audio/0d0af103e04b1e3bbd826f1d427d0d009e8af5a8?__token__=exp=1746016411~hmac=ca2bf433cb3f8ab87b9e55e39710991135f6bc85b913420a3f024ee1de69ac73",
                    Some(
                        Date(
                            2025-04-30 12:28:31.0 +00:00:00,
                        ),
                    ),
                ),
            ],
        ),
    }
[2025-04-29T12:33:32Z TRACE librespot_audio::fetch] Streaming from https://audio-fa.scdn.co/audio/0d0af103e04b1e3bbd826f1d427d0d009e8af5a8?1746016411_3GvpIWvD6ezTY7qFApUSduTVMGjKILU2iYOTJPceitQ=
[2025-04-29T12:33:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 305 ms
[2025-04-29T12:33:35Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 78 kbps
[2025-04-29T12:33:35Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 262 ms
[2025-04-29T12:33:36Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 302 ms
[2025-04-29T12:33:39Z TRACE librespot_audio::fetch::receive] Throughput now estimated as: 77 kbps
[2025-04-29T12:33:40Z INFO  librespot_playback::player] <'Til You Can't> (224213 ms) loaded
[2025-04-29T12:33:40Z TRACE librespot_playback::player] == Stopping sink ==
[2025-04-29T12:33:40Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2025-04-29T12:33:40Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2025-04-29T12:33:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:33:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:33:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:34:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:34:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:34:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:34:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:35:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:35:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:35:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:36:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:36:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:36:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:36:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:37:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:37:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:37:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:38:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:38:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:38:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:38:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:39:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:39:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:39:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:40:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:40:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:40:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:40:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:41:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:41:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:41:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:42:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:42:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:42:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:42:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:43:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:43:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:43:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:44:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:44:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:44:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:44:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:45:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:45:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:45:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:46:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:46:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:46:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:46:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:47:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:47:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:47:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:48:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:48:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:48:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:48:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:49:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:49:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:49:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:50:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:50:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:50:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:50:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:51:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:51:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:51:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:52:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:52:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:52:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:52:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:53:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:53:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:53:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:54:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:54:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:54:56Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:54:56Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:55:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:55:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:55:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:56:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:56:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:56:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:56:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:57:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:57:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:57:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T12:58:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T12:58:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T12:58:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T12:58:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T12:59:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T12:59:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T12:59:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T13:00:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T13:00:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T13:00:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T13:00:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T13:01:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T13:01:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T13:01:56Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T13:02:56Z TRACE librespot_core::session] Sending Pong
[2025-04-29T13:02:56Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T13:02:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T13:02:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T13:03:57Z TRACE librespot_core::session] Received Ping
[2025-04-29T13:03:57Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T13:03:57Z DEBUG librespot_core::session] Session strong=7 weak=7
[2025-04-29T13:04:57Z TRACE librespot_core::session] Sending Pong
[2025-04-29T13:04:57Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
[2025-04-29T13:04:57Z TRACE librespot_core::session] Received PongAck
[2025-04-29T13:04:57Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
[2025-04-29T13:05:56Z TRACE librespot_core::session] Received Ping
[2025-04-29T13:05:56Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-04-29T13:05:56Z DEBUG librespot_core::session] Session strong=7 weak=7
.
.
.