Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

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

Closed
dwedia opened this issue Apr 12, 2023 · 27 comments
Closed

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

dwedia opened this issue Apr 12, 2023 · 27 comments
Labels

Comments

@dwedia
Copy link

dwedia commented Apr 12, 2023

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:

  1. 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.
  2. Connect with '...'
  3. In the client click on '...'
  4. 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.

@dwedia dwedia added the bug label Apr 12, 2023
@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Apr 13, 2023

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
Copy link
Author

dwedia commented Apr 18, 2023

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
Copy link

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
Copy link
Contributor

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
Copy link

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
Copy link

HinzundKunz commented May 30, 2023

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

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
Copy link

jkp commented Apr 10, 2024

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

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
Copy link

jkp commented Apr 11, 2024

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
Copy link
Contributor

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
Copy link

jkp commented Apr 12, 2024 via email

@JCBird1012
Copy link

JCBird1012 commented Jun 24, 2024

So, I encountered this issue myself using the fork vollibrespot in HiFiBerryOS (see hifiberry/hifiberry-os#519 and ashthespy/Vollibrespot#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
Copy link
Member

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
Copy link

JCBird1012 commented Jun 24, 2024

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)

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

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

@hamishfagg
Copy link

FWIW I seem to have found a workaround which is to connect to spotify through a US VPN.

I'm not sure why connections from US IPs are treated differently, but it sure seems like they are.

@JCBird1012
Copy link

JCBird1012 commented Aug 8, 2024 via email

@jkp
Copy link

jkp commented Aug 8, 2024 via email

@roderickvd
Copy link
Member

Spotify provides a couple based on geo DNS, in random order. We pick the first one that we can connect to.

@jkp
Copy link

jkp commented Aug 8, 2024 via email

@roderickvd
Copy link
Member

DHT? I don’t know about that.

It just queries apresolve.spotify.com and relies on Spotify’s infrastructure to provide some hostnames, which it should based on geographic location. The library does not contain any intelligence beyond that.

I believe that even two equal host names will resolve to different IPs when resolved in different parts of the world.

See: https://github.com/librespot-org/librespot/blob/dev/core/src/apresolve.rs

@roqueeee
Copy link

roqueeee commented Sep 4, 2024

I'm getting this error after switching to librespot 0.5.0-dev 2ea7436 yesterday because 0.4.2 stopped working. Never had any issues with 0.4.2 for almost two years.

This is an excerpt from my logs. It appears that librespot reconnects to the AP succesfully after Connection reset by peer (os error 104) but never resumes playback and the Spotify Connect connection to my PC or phone is also lost:

...
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] Session strong=4 weak=7
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] Invalidating session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new ChannelManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] drop Dispatch
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z ERROR librespot_core::session] Connection reset by peer (os error 104)
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z ERROR librespot_connect::spirc] remote update selected, but none received
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_connect::spirc] drop Spirc[0]
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z WARN  librespot] Spirc shut down unexpectedly
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] new Session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_connect::spirc] new Spirc[1]
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new MercuryManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new ApResolver
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_playback::player] command=SetSession
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] drop Session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop ApResolver
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop AudioKeyManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop ChannelManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop MercuryManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop SpClient
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop TokenProvider
Sep 04 11:06:37 pi1 librespot[1721]: [2024-09-04T09:06:37Z INFO  librespot_core::session] Connecting to AP "ap2-gew4.spotify.com:4070"
Sep 04 11:06:37 pi1 librespot[1721]: [2024-09-04T09:06:37Z INFO  librespot_core::session] Authenticated as "xyz" !
...

I can manually reconnect and resume playback after this error without having to restart the service. So the AP reconnection at least seems to be successful.

@RSKriegs
Copy link

RSKriegs commented Sep 4, 2024

I'm getting this error after switching to librespot 0.5.0-dev 2ea7436 yesterday because 0.4.2 stopped working. Never had any issues with 0.4.2 for almost two years.

This is an excerpt from my logs. It appears that librespot reconnects to the AP succesfully after Connection reset by peer (os error 104) but never resumes playback and the Spotify Connect connection to my PC or phone is also lost:

...
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] Session strong=4 weak=7
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] Invalidating session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new ChannelManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] drop Dispatch
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z ERROR librespot_core::session] Connection reset by peer (os error 104)
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z ERROR librespot_connect::spirc] remote update selected, but none received
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_connect::spirc] drop Spirc[0]
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z WARN  librespot] Spirc shut down unexpectedly
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] new Session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_connect::spirc] new Spirc[1]
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new MercuryManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] new ApResolver
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_playback::player] command=SetSession
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot_core::session] drop Session
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop ApResolver
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop AudioKeyManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop ChannelManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop MercuryManager
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop SpClient
Sep 04 11:06:36 pi1 librespot[1721]: [2024-09-04T09:06:36Z DEBUG librespot::component] drop TokenProvider
Sep 04 11:06:37 pi1 librespot[1721]: [2024-09-04T09:06:37Z INFO  librespot_core::session] Connecting to AP "ap2-gew4.spotify.com:4070"
Sep 04 11:06:37 pi1 librespot[1721]: [2024-09-04T09:06:37Z INFO  librespot_core::session] Authenticated as "xyz" !
...

I can manually reconnect and resume playback after this error without having to restart the service. So the AP reconnection at least seems to be successful.

I also began to receive these after switching to Librespot dev from Raspotify, basing on older comments it seems to be expected. Raspotify manages to handle it by design, but it uses other fork and I am not sure if settings tweaks on compiled Librespot could fix it with current version. Would be happy to hear any other solutions.

@noahhaon
Copy link

Seeing this very frequently now on 0.5.0 during playback using Spotify Connect. Would be great if librespot had the option for resuming the session and playback like raspotify does, as this behavior makes automated usage of librespot quite flaky.

The AP I get typically is ap-gew4.spotify.com:4070 if that is of any benefit.

@Eirikr70
Copy link

Same problem here. Disconnections happen several times an hour, with ap-gew1.spotify.com:443

@star-glider
Copy link

I'm now seeing this problem as well, almost certainly related to Raspotify's switch to this librespot source. It's pretty inconsistent, and I haven't been able to figure out any pattern to the disconnections. I'm running it on two devices: a RPi4 that's connected via Ethernet and a Zero 2W that's wireless; they behave similarly.

@kingosticks
Copy link
Contributor

kingosticks commented Oct 2, 2024

@roderickvd shall we close this issue and concentrate everyone at #1340

Edit. Oh, wow, it already is closed and yet people still post here over the more updated one. Let's lock it??

@librespot-org librespot-org locked and limited conversation to collaborators Oct 3, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests