Librespot playback stops - Connection reset by peer (os error 104)

dwedia commented 1 year ago

Describe the bug A clear and concise description of what the bug is.

Playback stops randomly. Sometimes after a few seconds, sometimes after a few hours Librespot seems to crash and I have to reconnect from spotify. Sometimes I can reconnect at once, at other times a complete OS reboot is necessary

Gives these two errors in the log: ERROR librespot_core::session] Connection reset by peer (os error 104) WARN librespot] Spirc shut down unexpectedly

To reproduce Steps to reproduce the behavior:

Launch librespot with '...' running Librespot through Raspotify, had the same issue (though much worse), when I used Volumio. both use Librespot for the actually spotify connection.
Connect with '...'
In the client click on '...'
See error

Log A full log so we may trace your problem (launch librespot with --verbose). Format the log as code.

´ Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z ERROR librespot_core::session] Connection reset by peer (os error 104) Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z ERROR librespot_connect::spirc] subscription terminated Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z WARN librespot] Spirc shut down unexpectedly Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070 Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443 Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80 Apr 12 19:58:06 barry librespot[1552]: [2023-04-12T17:58:06Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070 ´

Host (what you are running librespot on):

OS: Linux barry 6.1.21-v8+ - Raspberry Pi OS ( PRETTY_NAME="Debian GNU/Linux 11 (bullseye)" )
Platform: Raspberry Pi Zero 2

Additional context Add any other context about the problem here. If your issue is related to sound playback, at a minimum specify the type and make of your output device.

JasonLG1979 commented 1 year ago

Connection reset by peer (os error 104) means that Spotify has dropped the connection for any number of potential reasons. In a perfect world librespot would try to seamlessly reconnect without the user noticing if that's possible. Currently I think it may just restart Spirc which isn't seamless. In Raspotify if librespot crashes or exits the service restarts.

In short on librespot's side there's nothing that can be done to prevent a 104, but it could be handled a little better maybe?

dwedia commented 1 year ago

Connection reset by peer (os error 104) means that Spotify has dropped the connection for any number of potential reasons. In a perfect world librespot would try to seamlessly reconnect without the user noticing if that's possible. Currently I think it may just restart Spirc which isn't seamless. In Raspotify if librespot crashes or exits the service restarts.

In short on librespot's side there's nothing that can be done to prevent a 104, but it could be handled a little better maybe?

Thank you for the reply. Not the answer I was hoping for, but if the issue is on Spotify's end, there doesnt seem like there would be much to do about it =\

tofublock commented 1 year ago

I experience this issue, but with an added wrinkle: My RPi3+HifiberryDAC+ running OSMC and raspotify had been working perfectly until I decided to upgrade raspotify a few months ago (if I'm not mistaken I upgraded from 0.31.3 to 0.31.6, since I had to redo my raspotify configuration and set up an asound.conf.) Since then, I see frequent crashes and service reboots as described in the issue here, but haven't changed anything else. Is there any way this could also be related to asound configuration or anything other than "bad network"?

JasonLG1979 commented 1 year ago

If you're having a Raspotify issue this is the wrong place. File a bug report at the Raspotify repo and if it is a librespot issue we can file a bug here.

tofublock commented 1 year ago

Sorry, all 104-related topics in the raspotify repo get referred back to librespot, so I thought I'd jump on this issue report directly. Will file it over there.

HinzundKunz commented 1 year ago

I experience the same issue with Spot under Linux. I then have to end Spot manually via the task manager and restart. Spot doesn't even see the problem and goes on playing stuff, but no sound is heard, and the pulseaudio applet says that no app plays any media. Anyway, this is not a raspberry-only issue.

roderickvd commented 1 year ago

Peers shutting librespot down is hardly a librespot problem. We could discuss how librespot handles such disconnections, which indeed is a problem, and is logged in separate issues.

jkp commented 3 months ago

Seeing this very same issue and as others have reported, the lowest layer where there is control of this seems to be in librespot. I understand that it feels like the client is doing the Right Thing™ but I'm pretty sure this isn't how things are supposed to work :) @roderickvd you mentioned other tickets which propose solutions...would you mind adding a link so folks can contribute to that line of enquiry?

(also speaking here as an ex-Spotify developer I may be able to poke some old friends at the mothership to help debug the issue and ask for advice on what the client should really be doing?)

roderickvd commented 3 months ago

See #609.

Help from the mothership would be awesome! If they'd be willing to help, then I'd like them to focus on other stuff first. Because reconnection handling is just a problem with librespot, that wasn't architected to that and is hard to fix now. It's not a problem on the server side or the understanding of the API.

Do let us know if there are Spotify devs willing to help us with a thing or two. For example with the reporting of tracks that were played and the obfuscated keys in the new HTTP API are two parts that are really not understood by us yet. And you know this project has always tried to do the right thing to combat piracy -- we're here for the music.

jkp commented 3 months ago

Nice! I'll have to reach out to a few folks and see if I can drum up any interest (there's one particular person I know who was pretty much the architect behind a full rewrite of the player stack who recently finished up at Spotify - assuming PTSD isn't too strong he might be willing to help out :))

The player/playback stack (including Connect and the Web APIs) was a thing I worked on directly for about five years (I moved on to something new in 2017) so I do have a fair bit of familiarity myself...but likely the details are hazy now. But if there are specifics I might be able to take a look (if I can find some time).

kingosticks commented 3 months ago

If possible, I'd specifically like to know about shuffle/repeat modes which I think at least of which isn't working properly, and echo @roderickvd's request for reporting (we're keen for the correct artists to get paid), and also clarify which keymaster client IDs we should be using (we seemed to have a bunch), and if playback using just an access_token is possible (I would really like to get #1098 working).

Sorry, that snowballed. Very keen for any details you have.

jkp commented 3 months ago

When it comes to reporting of tracks: I don’t think I’m breaking any NDAs to say that (in my day….) anything past 30 seconds has to be counted and the way to register something as played is with log messages (so you’ll need to reverse engineer the logs of a genuine client to figure out the format).

The caveat here is that I have read there have been some tweaks to counteract stream fraud however I’d imagine that any correction happens downstream.

One thing I think plays in favour of building third-party clients is that even very old Spotify devices still work - having worked on the platform team building SDKs I can say that they are extremely generous about backward compatibility which I can tell you can prove extremely challenging at times!

Sent from Proton Mail for iOS

On Wed, Apr 10, 2024 at 20:41, Roderick van Domburg @.***(mailto:On Wed, Apr 10, 2024 at 20:41, Roderick van Domburg < wrote:

See #609.

Help from the mothership would be awesome! If they'd be willing to help, then I'd like them to focus on other stuff first. Because reconnection handling is just a problem with librespot, that wasn't architected to that and is hard to fix now. It's not a problem on the server side or the understanding of the API.

Do let us know if there are Spotify devs willing to help us with a thing or two. For example with the reporting of tracks that were played and the obfuscated keys in the new HTTP API are two parts that are really not understood by us yet. And you know this project has always tried to do the right thing to combat piracy -- we're here for the music.

— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you commented.Message ID: @.***>

JCBird1012 commented 1 month ago

So, I encountered this issue myself using the fork vollibrespot in HiFiBerryOS (see https://github.com/hifiberry/hifiberry-os/issues/519 and https://github.com/ashthespy/Vollibrespot/issues/17) - and I was curious to see if this was still happening on 0.5.0-dev - I'm still seeing disconnects.

librespot establishes a new connection, but the Spotify Connect session does not get resumed, and playback (sometimes) stops within a few seconds of the disconnect, but always after the current song is finished.

Here's some log output (for brevity, I haven't attached logs running with --verbose, but that output isn't much more helpful) -

[2024-06-24T00:18:54Z INFO  librespot] librespot 0.5.0-dev cdff6da (Built on 2024-06-24, Build ID: cGn8N5Z2, Profile: release)
[2024-06-24T00:18:54Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2024-06-24T00:18:54Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2024-06-24T00:18:54Z INFO  librespot_playback::audio_backend::rodio] Using Rodio sink with format S16 and cpal host: CoreAudio
[2024-06-24T00:18:55Z INFO  librespot_playback::audio_backend::rodio] Using audio device: MacBook Pro Speakers
[2024-06-24T00:18:58Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:18:59Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:00Z INFO  librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"
[2024-06-24T00:19:00Z INFO  librespot_core::session] Authenticated as "1225120197" !
[2024-06-24T00:19:00Z INFO  librespot_core::session] Country: "US"
[2024-06-24T00:19:00Z INFO  librespot_core::spclient] Resolved "gue1-spclient.spotify.com:443" as spclient access point
[2024-06-24T00:19:00Z WARN  librespot_core::spclient] Unable to get client token: Client specified an invalid argument { Response status code: 400 Bad Request } Trying to continue without...
[2024-06-24T00:19:00Z WARN  librespot_core::spclient] Unable to get client token: Client specified an invalid argument { Response status code: 400 Bad Request } Trying to continue without...
[2024-06-24T00:19:01Z ERROR librespot_connect::spirc] ContextError: Error { kind: Unknown, error: StatusCode(502) }
[2024-06-24T00:19:01Z WARN  librespot_core::spclient] Unable to get client token: Client specified an invalid argument { Response status code: 400 Bad Request } Trying to continue without...
[2024-06-24T00:19:01Z INFO  librespot_playback::player] Loading <Lilac, I Think> with Spotify URI <spotify:track:0IJV2dILcU0M0dPwQzZh2T>
[2024-06-24T00:19:01Z WARN  librespot_core::spclient] Unable to get client token: Client specified an invalid argument { Response status code: 400 Bad Request } Trying to continue without...
[2024-06-24T00:19:01Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:01Z INFO  librespot_playback::player] <Lilac, I Think> (243505 ms) loaded
[2024-06-24T00:19:02Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:03Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:05Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:07Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:09Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:11Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:13Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:15Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:17Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:19Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:21Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:23Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:25Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:27Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:29Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:31Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:33Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:35Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:37Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:39Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:41Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:43Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:45Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:47Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:49Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:51Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:53Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:55Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:19:57Z WARN  libmdns::fsm] error sending packet Os { code: 65, kind: HostUnreachable, message: "No route to host" }
[2024-06-24T00:21:05Z ERROR librespot_core::session] session lost connection to server
[2024-06-24T00:21:05Z ERROR librespot_connect::spirc] remote update selected, but none received
[2024-06-24T00:21:05Z WARN  librespot] Spirc shut down unexpectedly
[2024-06-24T00:21:05Z INFO  librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"
[2024-06-24T00:21:06Z INFO  librespot_core::session] Authenticated as "1225120197" !
[2024-06-24T00:21:06Z INFO  librespot_core::session] Country: "US"
[2024-06-24T00:25:11Z ERROR librespot_core::session] session lost connection to server
[2024-06-24T00:25:11Z ERROR librespot_connect::spirc] connection ID update selected, but none received
[2024-06-24T00:25:11Z WARN  librespot] Spirc shut down unexpectedly
[2024-06-24T00:25:11Z INFO  librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"
[2024-06-24T00:25:11Z INFO  librespot_core::session] Authenticated as "1225120197" !
[2024-06-24T00:25:11Z INFO  librespot_core::session] Country: "US"
[2024-06-24T00:29:16Z ERROR librespot_core::session] session lost connection to server
[2024-06-24T00:29:16Z ERROR librespot_connect::spirc] user attributes mutation selected, but none received
[2024-06-24T00:29:16Z WARN  librespot] Spirc shut down unexpectedly
[2024-06-24T00:29:17Z INFO  librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"
[2024-06-24T00:29:17Z INFO  librespot_core::session] Authenticated as "1225120197" !
[2024-06-24T00:29:17Z INFO  librespot_core::session] Country: "US"

Something that's interesting to me - the session gets terminated consistently after a few minutes - even with no activity (i.e. no audio playing + no active Spotify Connect session). Not sure much can be done if Spotify's terminating the connection themselves.

I initially suspected this might be related to the work done in #1129, but that's probably a red herring since this still happens in v0.4.2 before that was merged.

roderickvd commented 1 month ago

Thanks for the debugging. It’s a known architecture flaw, and unfortunately a hard one at that.

Whether a song is playing or not does not matter, because a Spirc session is always connected and notices the hang up.

JCBird1012 commented 1 month ago

I tested librespot-java for the heck of it to see if it's affected by this same issue - it looks like it is (on the surface), but it appears it gets handled much more gracefully. The Spotify Connect session on the controlling device never gets interrupted (+ it can continue controlling after the disconnection happens in the logs), and audio never stops playing. In the half-hour or so that I've played with it, I haven't seen it have the same behavior I see in librespot (except in a few rare circumstances such as the controlling device changing networks).

2024-06-24 09:55:21,750 TRACE CdnManager:277 - Chunk 4/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:55:34,593 TRACE CdnManager:277 - Chunk 5/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:55:47,488 TRACE CdnManager:277 - Chunk 6/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:55:59,376 TRACE CdnManager:277 - Chunk 7/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:56:11,762 TRACE CdnManager:277 - Chunk 8/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:56:23,200 TRACE CdnManager:277 - Chunk 9/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:56:34,962 TRACE CdnManager:277 - Chunk 10/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}

2024-06-24 09:56:45,869 TRACE CdnManager:277 - Chunk 11/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:56:57,041 TRACE CdnManager:277 - Chunk 12/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:57:08,322 TRACE CdnManager:277 - Chunk 13/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:57:16,413 WARN  Session:1440 - Socket timed out. Reconnecting...
2024-06-24 09:57:16,417 TRACE Session:1500 - Session.Receiver stopped
2024-06-24 09:57:16,455 INFO  ApResolver:99 - Loaded aps into pool: {accesspoint=[ap-gue1.spotify.com:4070, ap-gue1.spotify.com:443, ap-gue1.spotify.com:80, ap-gae2.spotify.com:4070, ap-gew1.spotify.com:443, ap-gew4.spotify.com:80], dealer=[gue1-dealer.spotify.com:443, gae2-dealer.spotify.com:443, gew1-dealer.spotify.com:443, gew4-dealer.spotify.com:443], spclient=[gue1-spclient.spotify.com:443, gae2-spclient.spotify.com:443, gew1-spclient.spotify.com:443, gew4-spclient.spotify.com:443]}
2024-06-24 09:57:17,346 INFO  Session:334 - Connected successfully!
2024-06-24 09:57:17,688 TRACE Session:1413 - Session.Receiver started
2024-06-24 09:57:17,689 INFO  Session:736 - Re-authenticated as 1225120197!
2024-06-24 09:57:17,690 INFO  Session:1495 - Skipping SecretBlock
2024-06-24 09:57:17,690 INFO  Session:1467 - Received LicenseVersion: 0
2024-06-24 09:57:17,690 INFO  Session:1457 - Received CountryCode: US
2024-06-24 09:57:17,701 TRACE Session:784 - Parsed product info: {audiobook-onboarding-completed=0, remote-control=6, publish-activity=1, audio-preview-url-template=https://p.scdn.co/mp3-preview/{id}, incognito_mode_timeout=21600, ad-formats-preroll-video=0, type=premium, ab_recently_played_feature_time_filter_threshold=com.spotify.gaia=30,driving-mode=120,spotify%3Ainternal%3Astartpage=30, license-agreements=, publish-playlist=0, buffering-strategy=0, expiry=1, ab-desktop-hide-follow=1, ab-collection-hide-unavailable-albums=0, capper-profile=, payments-initial-campaign=default, profile-image-upload=1, enable-annotations=2, ab-ad-player-targeting=1, subscription-enddate=, india-experience=0, video-wifi-initial-bitrate=800000, ab-mobile-running-onlymanualmode=only-manual, playlist-annotations-markup=0, prefetch-keys=1, allow-override-internal-prefs=0, prefetch-window-max=2, send-email=1, ad-formats-video-takeover=1, ab-collection-bookmark-model=1, pause-after=0, local-files-import=0, video-manifest-url=https://spclient.wg.spotify.com/manifests/v6/{type}/sources/{source_id}/options/supports_drm, playlist-folders=1, arsenal_country=1, track-cap=0, restrict-playlist-collaboration=0, audiobook-onboarding-dismissed=0, ab-mobile-running-tempo-detection=Control, is_email_verified=1, shows-collection=1, enable-annotations-read=0, addon-hifi=0, mobile-browse=0, payments-locked-state=0, employee-free-opt-in=0, shows-collection-jam=1, ab-browse-music-tuesday=1, offline=1, streaming=1, fb-info-confirmation=control, audio-quality=1, wanted-licenses=, lastfm-session=, ab-desktop-playlist-annotation-edit=1, ab-mobile-discover=0, widevine-license-url=https://spclient.wg.spotify.com/widevine-license/v1/video/license, key-caching-max-count=10000, hifi-eligible=0, ad-session-persistence=1, video-initial-bitrate=200000, ab-play-history=0, mobile-payment=0, payment-state=, key-caching-max-offline-seconds=1800, ugc-abuse-report-url=https://support.spotify.com/abuse/?uri={uri}, shuffle-algorithm=1, use-pl3=0, image-url=https://i.scdn.co/image/{file_id}, use-playlist-app=0, enable-autostart=1, metadata-link-lookup-modes=0, multiuserplan-current-size=4, shuffle=0, instant-search=0, instant-search-expand-sidebar=0, use-playlist-uris=0, user-profile-show-invitation-codes=0, multiuserplan-member-type=FAMILY_MANAGER, ab-ad-requester=1, nft-disabled=1, ab-collection-union=1, key-memory-cache-mode=1:15,300, libspotify=1, high-bitrate=1, head-file-caching=1, radio=1, key-caching-auto-offline=0, explicit-content=1, video-cdn-sampling=1, ab-android-push-notifications=1, unrestricted=1, use-fb-publish-backend=2, app-developer=0, buffering-strategy-parameters=0.8:0.2:0.0:0.0:0.0:0.0:1.0:10:10:2000:10000:10485760, enable-gapless=1, ab-playlist-extender=5, enable-crossfade=1, ad-persist-reward-time=0, public-toplist=1, network-operator-premium-activation=1, video-device-blacklisted=0, collection=1, fb-grant-permission-local-render=0, backend-advised-bitrate=1, autoplay=1, catalogue=premium, storage-size-config=10240,90,500,3, ads=0, head-files-url=https://heads-fa-tls13.spotifycdn.com/head/{file_id}, ab-collection-followed-artists-only=0, browse-overview-enabled=1, on-demand=1, ap-resolve-pods=1, name=Spotify Premium, sidebar-navigation-enabled=0, loudness-levels=1:-5.0,0.0,3.0:-2.0, mobile-login=1, product-expiry=, hifi-optin-intent=0, preferred-locale=en, license-acceptance-grace-days=30, prefetch-strategy=18, ugc-abuse-report=1, ab-watch-now=0, financial-product=pr:premium,tc:0,rt:v2_US_default_new-family-master-1m_16.99_USD_default, ab-collection-offline-mode=0, streaming-rules=, head-files=1, capping-bar-threshold=3601, ab-new-share-flow=0, video-keyframe-url=http://keyframes-fa.cdn.spotify.com/keyframes/v1/sources/{source_id}/keyframe/heights/{height}/timestamps/{timestamp_ms}.jpg, mobile=1, is_maybe_in_social_session=0, ab-mobile-startpage=0, ab-moments-experience=0, ab-mobile-social-feed=1, ab-test-group=168, player-license=premium}
2024-06-24 09:57:17,702 INFO  Session:1495 - Skipping UnknownData_AllZeros
2024-06-24 09:57:17,702 INFO  Session:1495 - Skipping LegacyWelcome
2024-06-24 09:57:17,875 TRACE MercuryClient:191 - Handling packet, cmd: MercuryEvent, seq: -126318492868673536, flags: 1, parts: 1
2024-06-24 09:57:17,875 DEBUG MercuryClient:226 - Couldn't dispatch Mercury event {seq: -126318492868673536, uri: hm://pusher/v1/connections/YTU1ZTE2YzViMzBmM2U3YWQ2ODdiMWY4NTkzYWFjODQ3OWU1ZDE3MStBUCt0Y3A6Ly9nYWUyLWFjY2Vzc3BvaW50LWMtenRqZi5nYWUyLnNwb3RpZnkubmV0OjUwMTIrNUI4REU4QzhBRTVBNDJEMkY3ODMzMjZFMjhERjBFNEYzNDYxRDJDOURDQUIwN0JGNjYxQTg3MjNEM0QyNTQ3Rg%3D%3D, code: 200, payload: []}
2024-06-24 09:57:18,062 DEBUG Session:1471 - Received 0x10: 43B6DFFAA2A7D71CE576B6BEC40CF1A5736983E9
2024-06-24 09:57:18,251 INFO  Session:1422 - Skipping unknown command {cmd: 0x75, payload: 000000}
2024-06-24 09:57:20,099 TRACE CdnManager:277 - Chunk 14/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:57:32,692 TRACE CdnManager:277 - Chunk 15/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:57:45,419 TRACE CdnManager:277 - Chunk 16/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:57:58,630 TRACE CdnManager:277 - Chunk 17/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:58:11,448 TRACE CdnManager:277 - Chunk 18/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:58:23,494 TRACE CdnManager:277 - Chunk 19/20 completed, cached: false, stream: {fileId: 9EA919FC2D34817E61280E0AA700B45762E914E1}
2024-06-24 09:58:25,474 TRACE DealerClient:113 - Received request. {mid: hm://connect-state/v1/player/command, key: 7323e193-24bc-4590-adc6-8727132a229b, pid: 1250587711, sender: 386d8ede68b726268a4f447b6e31cb8e071e6391, command: {"endpoint":"skip_next","options":{"override_restrictions":false,"only_for_local_device":false,"system_initiated":false},"logging_params":{"command_initiated_time":1719237505198,"command_received_time":1719237505201,"device_identifier":"386d8ede68b726268a4f447b6e31cb8e071e6391","command_id":"6564ce8bd340bdb6c1c67ffdb27aaffa"}}}
2024-06-24 09:58:25,474 DEBUG Player:107 - Received command: SkipNext
2024-06-24 09:58:25,486 TRACE MercuryClient:148 - Send Mercury request, seq: 5, uri: hm://event-service/v1/events, method: POST
2024-06-24 09:58:25,486 DEBUG Player:492 - Loading track, id: TrackId{spotify:track:1Ac5BDsGUMQ3tsW2vnc52x}, session: TsolA+3CEjrYAfHFsyB9cg, playback: 01ce76dd22c85ffa56fb91a6fcbb64ea, play: true
2024-06-24 09:58:25,488 TRACE PlayerQueueEntry:92 - Created new PlayerQueueEntry{0147b1fe4ea6756df72096f4572a3832}.
2024-06-24 09:58:25,489 TRACE PlayerQueue:82 - PlayerQueueEntry{0147b1fe4ea6756df72096f4572a3832} added to queue.
2024-06-24 09:58:25,489 DEBUG CrossfadeController:192 - Changed fade out. {curr: null, custom: false, why: TRACK_DONE, id: 01ce76dd22c85ffa56fb91a6fcbb64ea}
2024-06-24 09:58:25,489 TRACE PlayerSession:162 - PlayerQueueEntry{0147b1fe4ea6756df72096f4572a3832} started loading.
2024-06-24 09:58:25,489 DEBUG CrossfadeController:192 - Changed fade out. {curr: null, custom: false, why: FORWARD_BTN, id: 01ce76dd22c85ffa56fb91a6fcbb64ea}
2024-06-24 09:58:25,489 TRACE MixingLine:184 - Toggle first channel: false
2024-06-24 09:58:25,490 DEBUG PlayerQueueEntry:234 - PlayerQueueEntry{01ce76dd22c85ffa56fb91a6fcbb64ea} has been removed from output.
2024-06-24 09:58:25,490 TRACE PlayerQueueEntry:350 - PlayerQueueEntry{01ce76dd22c85ffa56fb91a6fcbb64ea} terminated.
2024-06-24 09:58:25,490 DEBUG PlayerSession:283 - PlayerQueueEntry{0147b1fe4ea6756df72096f4572a3832} has been added to the output. {sessionId: TsolA+3CEjrYAfHFsyB9cg, pos: 2, reason: FORWARD_BTN}
2024-06-24 09:58:25,492 DEBUG DealerClient:125 - Handled request. {key: 7323e193-24bc-4590-adc6-8727132a229b, result: SUCCESS}
2024-06-24 09:58:25,862 TRACE MercuryClient:191 - Handling packet, cmd: MercuryReq, seq: 5, flags: 1, parts: 1
2024-06-24 09:58:25,863 DEBUG EventService:51 - Event sent. {body: 12|38|0|a55e16c5b30f3e7ad687b1f8593aac8479e5d171|01ce76dd22c85ffa56fb91a6fcbb64ea|00000000000000000000000000000000|playlist/ondemand|clickrow|playlist/ondemand|fwdbtn|2510832|2510832|195139|195139|237958|1|0|0|0|1|8|0|-1|context|71|0|0|0|0|0|195139|195139|0|176400|spotify:playlist:71fQTNrM5KzjBQfuw181Pd|vorbis|714fa403d5a540b4b07712fcea59936e||0|1719237308472|0|context|find|8.9.48.455|com.spotify|crossfade|none|386d8ede68b726268a4f447b6e31cb8e071e6391|na|none, result: 200}
2024-06-24 09:58:25,863 TRACE MercuryClient:148 - Send Mercury request, seq: 6, uri: hm://event-service/v1/events, method: POST

I suspect they're re-using the existing session and just re-connecting (There's a TODO to do something similar in session.rs)

https://github.com/librespot-org/librespot/blob/cdff6da1f86c284897c0566fd92e332d925e5cd4/core/src/session.rs#L264

Here's what their logs look like on initial connect -

2024-06-24 10:08:55,061 INFO  ApResolver:99 - Loaded aps into pool: {accesspoint=[ap-gue1.spotify.com:4070, ap-gue1.spotify.com:443, ap-gue1.spotify.com:80, ap-gae2.spotify.com:4070, ap-gew1.spotify.com:443, ap-gew4.spotify.com:80], dealer=[gue1-dealer.spotify.com:443, gae2-dealer.spotify.com:443, gew1-dealer.spotify.com:443, gew4-dealer.spotify.com:443], spclient=[gue1-spclient.spotify.com:443, gae2-spclient.spotify.com:443, gew1-spclient.spotify.com:443, gew4-spclient.spotify.com:443]}
2024-06-24 10:08:55,099 INFO  Session:140 - Created new session! {deviceId: f98691d4969217ceac650b9595b694eee55bc45a, ap: ap-gue1.spotify.com:80, proxy: false}
2024-06-24 10:08:55,486 INFO  Session:334 - Connected successfully!
2024-06-24 10:08:55,613 TRACE Session:1413 - Session.Receiver started
2024-06-24 10:08:55,623 INFO  CacheManager:95 - There are 9 cached entries.
2024-06-24 10:08:55,624 TRACE AsyncProcessor:52 - AsyncProcessor{dealer-worker} has started
2024-06-24 10:08:55,625 TRACE AsyncProcessor:52 - AsyncProcessor{event-service-sender} has started
2024-06-24 10:08:55,626 INFO  Session:1495 - Skipping SecretBlock
2024-06-24 10:08:55,626 INFO  Session:1467 - Received LicenseVersion: 0
2024-06-24 10:08:55,626 DEBUG TokenProvider:68 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
2024-06-24 10:08:55,626 INFO  Session:1457 - Received CountryCode: US
2024-06-24 10:08:55,629 TRACE MercuryClient:148 - Send Mercury request, seq: 1, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=f98691d4969217ceac650b9595b694eee55bc45a, method: GET

... <snip some non-helpful logs> ...

2024-06-24 10:08:55,631 INFO  Session:1495 - Skipping UnknownData_AllZeros
2024-06-24 10:08:55,631 INFO  Session:1495 - Skipping LegacyWelcome
2024-06-24 10:08:55,631 TRACE MercuryClient:191 - Handling packet, cmd: MercuryEvent, seq: 6511323252852260864, flags: 1, parts: 1
2024-06-24 10:08:55,632 DEBUG MercuryClient:226 - Couldn't dispatch Mercury event {seq: 6511323252852260864, uri: hm://pusher/v1/connections/Zjk4NjkxZDQ5NjkyMTdjZWFjNjUwYjk1OTViNjk0ZWVlNTViYzQ1YStBUCt0Y3A6Ly9ndWUxLWFjY2Vzc3BvaW50LWMtbjVoaC5ndWUxLnNwb3RpZnkubmV0OjUwMTQrQTk1QzI3NjIzRTlCRkIyRkZCNzVBMzlEN0EzMjBBRTA0QzI1NzZDN0IxNzYzMEIzMzNGREU5RkU0QkVENzUzRA%3D%3D, code: 200, payload: []}
2024-06-24 10:08:55,667 DEBUG Session:1471 - Received 0x10: 42FBF47638046984A8B4A094D3CD0D02EB3FF5F3
2024-06-24 10:08:55,709 TRACE MercuryClient:191 - Handling packet, cmd: MercuryReq, seq: 1, flags: 1, parts: 2
2024-06-24 10:08:55,710 DEBUG TokenProvider:72 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQDw6L...l8SU5Q', scopes=[playlist-read], timestamp=1719238135754}}
2024-06-24 10:08:55,714 INFO  Session:364 - Authenticated as 1225120197!

and on re-connect -

2024-06-24 10:11:05,619 WARN  Session:1440 - Socket timed out. Reconnecting...
2024-06-24 10:11:05,624 TRACE Session:1500 - Session.Receiver stopped
2024-06-24 10:11:05,665 INFO  ApResolver:99 - Loaded aps into pool: {accesspoint=[ap-gue1.spotify.com:4070, ap-gue1.spotify.com:443, ap-gue1.spotify.com:80, ap-guc3.spotify.com:4070, ap-gew1.spotify.com:443, ap-gew4.spotify.com:80], dealer=[gue1-dealer.spotify.com:443, guc3-dealer.spotify.com:443, gew1-dealer.spotify.com:443, gew4-dealer.spotify.com:443], spclient=[gue1-spclient.spotify.com:443, guc3-spclient.spotify.com:443, gew1-spclient.spotify.com:443, gew4-spclient.spotify.com:443]}
2024-06-24 10:11:06,101 INFO  Session:334 - Connected successfully!
2024-06-24 10:11:06,216 TRACE Session:1413 - Session.Receiver started
2024-06-24 10:11:06,216 INFO  Session:736 - Re-authenticated as 1225120197!
2024-06-24 10:11:06,217 INFO  Session:1495 - Skipping SecretBlock
2024-06-24 10:11:06,218 INFO  Session:1467 - Received LicenseVersion: 0
2024-06-24 10:11:06,218 INFO  Session:1457 - Received CountryCode: US

librespot-org / librespot

Librespot playback stops - Connection reset by peer (os error 104) #1151