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

Error 403 #1179

Open
xhpohanka opened this issue Jun 20, 2023 · 43 comments · May be fixed by #1220 or #1246
Open

Error 403 #1179

xhpohanka opened this issue Jun 20, 2023 · 43 comments · May be fixed by #1220 or #1246
Labels

Comments

@xhpohanka
Copy link

xhpohanka commented Jun 20, 2023

Hello,

suddenly my librespot instance on libreelec stopped playing any songs.

[2023-06-20T05:24:59Z INFO  librespot] librespot 0.5.0-dev d07b2ce (Built on 2023-06-18, Build ID: e4T4YlCt, Profile: release)
*** WARNING *** The program 'librespot' uses the Apple Bonjour compatibility layer of Avahi.
*** WARNING *** Please fix your application to use the native API of Avahi!
*** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
[2023-06-20T05:24:59Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2023-06-20T05:24:59Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2023-06-20T05:24:59Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[2023-06-20T05:24:59Z INFO  librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2023-06-20T05:24:59Z INFO  librespot_core::session] Authenticated as "11127372133" !
[2023-06-20T05:24:59Z INFO  librespot_core::session] Country: "CZ"
[2023-06-20T05:25:08Z INFO  librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point
[2023-06-20T05:25:08Z ERROR librespot_core::mercury] error 403 for uri hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292
[2023-06-20T05:25:08Z ERROR librespot_connect::spirc] ContextError: Error { kind: Unavailable, error: Response(MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] }) }
[2023-06-20T05:25:08Z ERROR librespot_core::mercury] error 403 for uri hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292
[2023-06-20T05:25:08Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: Unavailable, error: Response(MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] }) }
[2023-06-20T05:25:08Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4vGFfCD9PvBuKDbTourDdW")>: ()
[2023-06-20T05:25:08Z ERROR librespot_core::mercury] error 403 for uri hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292
[2023-06-20T05:25:08Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: Unavailable, error: Response(MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=78f3d06ba0952bdccb9e15230ae4f8c6891f6292", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] }) }

I think it is similar to #972 if it is not the same, but I have not found any way how to fix it yet...

~ # curl http://apresolve.spotify.com/
{"ap_list":["ap-gew4.spotify.com:4070","ap-gew4.spotify.com:443","ap-gew4.spotify.com:80","ap-gue1.spotify.com:4070","ap-gew1.spotify.com:443","ap-guc3.spotify.com:80"]}
@xhpohanka xhpohanka added the bug label Jun 20, 2023
@xhpohanka
Copy link
Author

It seems that libreelec jumped directly to development branch, version 0.4.2 works fine...

@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Jun 23, 2023

This is the main blocker for me to switch to dev in Raspotify if/when this PR is merged I plan on poking around the network code and seeing if I can figure out a fix. I might checkout librespot java and see what works for them and attempt to port it over? Up until this point though my knowledge and contributions have primarily been limited to the audio side of the code base. The author of most of the network stack isn't active in the project anymore so I could use whatever help anyone can offer.

In the meantime the workaround is to disable zeroconf discovery and use your Spotify credentials to log librespot in manually.

@herrernst
Copy link
Contributor

Happens to me (in Austria) also since yesterday, never has happened before. Using current dev branch.

@JasonLG1979
Copy link
Contributor

Happens to me (in Austria) also since yesterday, never has happened before. Using current dev branch.

I'm in the US, and discovery hasn't worked for me in dev for a year or more. I don't think the network bits in dev are complete? I think they're kinda in a transitional place between APIs? That was @roderickvd's baby but I'm not sure where he left off?

@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Jun 27, 2023

If I had to guess it may be that the 403 is because we're still using http://apresolve.spotify.com and those ap's are returning 403's because they are not local to us as far as Spotify is concerned but they may be local so some people including @roderickvd because when he made the changes that broke discovery for all of us it still worked for him so he thought it was Ok.

I don't think that the dealer API has been implemented yet? That may fix discovery for everyone, idk though? All of that are just guesses. I'm not very familiar at all with the Spotify API's or the networking bits of librespot. My focus is generally on the audio side of things.

@roderickvd
Copy link
Member

I might checkout librespot java and see what works for them and attempt to port it over?

Sure you can look at that. librespot-java is also pretty dormant, although I think last few weeks it has also seen a couple of issues and who knows commits on network problems. Seems like Spotify is changing things on their side.

Last time I reworked the network code, I took librespot-java as basis and updated that based on the latest official Spotify clients at that time, proxying the traffic and mimicking the requests. For example, this dev sends more extensive query strings (with client ID for example) than librespot-java does. Maybe stripping it down will fix things, I don't know, I'd actually recommend following the latest clients again and updating any code necessary.

I'm in the US, and discovery hasn't worked for me in dev for a year or more. I don't think the network bits in dev are complete? I think they're kinda in a transitional place between APIs? That was @roderickvd's baby but I'm not sure where he left off?

Except for the dealer (websockets-based messaging) that is not in, it should be fully functional and was ready for release pending wider testing.

If I had to guess it may be that the 403 is because we're still using http://apresolve.spotify.com and those ap's are returning 403's because they are not local to us as far as Spotify is concerned but they may be local so some people including @roderickvd because when he made the changes that broke discovery for all of us it still worked for him so he thought it was Ok.

I cannot think of any reason why the access point resolver should influence zeroconf discovery.

apresolve.spotify.com is what the official clients use for geographically load balanced DNS lookups.

I don't think that the dealer API has been implemented yet? That may fix discovery for everyone, idk though? All of that are just guesses. I'm not very familiar at all with the Spotify API's or the networking bits of librespot. My focus is generally on the audio side of things.

Also the dealer holds no relationship with zeroconf discovery. The dealer, simply put, replaces the current spirc messaging interface between the Spotify server and client. Which also has no relationship with zeroconf discovery.

Concerning zeroconf you may want to go through the commit log in librespot-discovery. I remember I did update some code there related to how the service is advertised. Not sure anymore.

I understand this may not seem helpful, though hopefully it will rule out some things or help focus any debugging efforts. Because that's what should happen really.

@JasonLG1979
Copy link
Contributor

For example, this dev sends more extensive query strings (with client ID for example) than librespot-java does. Maybe stripping it down will fix things, I don't know, I'd actually recommend following the latest clients again and updating any code necessary.

I tried that no dice.

I cannot think of any reason why the access point resolver should influence zeroconf discovery.

That was just a guess. Basically me pulling stuff out of my butt,lol!!!

Concerning zeroconf you may want to go through the commit log in librespot-discovery. I remember I did update some code there related to how the service is advertised. Not sure anymore.

I guess I get to bisect,lol!!! Because discovery in stable works perfectly fine for me.

I understand this may not seem helpful, though hopefully it will rule out some things or help focus any debugging efforts. Because that's what should happen really.

No, it is very helpful. It narrows my target. Thanks.

After I figure this out my next step as far as discovery is to replace with-dns-sd with an option to use avahi on Linux via it's DBus interface. @Johannesd3 already did most of the work here: https://github.com/Johannesd3/dnssd-rs/blob/master/src/avahi.rs. But it doesn't really make much sense to work on that until the current issue is fixed.

@herrernst
Copy link
Contributor

When I start librespot with --username USERNAMEand enter my password, it works FWIW

@JasonLG1979
Copy link
Contributor

Same. That's the only way it dev has worked for me in a long time.

@roderickvd
Copy link
Member

To add to tracing down the issue, maybe dev is sending a client or device ID as part of the discovery request that is not correct. Or the HTTP worker / spclient is sending a header that does not correspond to the actual client or device ID.

@JasonLG1979
Copy link
Contributor

To add to tracing down the issue, maybe dev is sending a client or device ID as part of the discovery request that is not correct. Or the HTTP worker / spclient is sending a header that does not correspond to the actual client or device ID.

I'll step though the discovery changes from stable (which works perfectly fine) to the current state of dev and see what broke what.

@kingosticks
Copy link
Contributor

I just gave it a try and discovery is still working for me using dev:

2023-06-29T23:21:02Z INFO  librespot] librespot 0.5.0-dev e5d364b (Built on 2023-06-29, Build ID: EOO1uOaS, Profile: release)
[2023-06-29T23:22:02Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2023-06-29T23:22:02Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2023-06-29T23:22:02Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[2023-06-29T23:22:02Z INFO  librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2023-06-29T23:22:03Z INFO  librespot_core::session] Authenticated as "kingosticks4" !
[2023-06-29T23:22:03Z INFO  librespot_core::session] Country: "GB"
[2023-06-29T23:22:03Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2023-06-29T23:22:03Z INFO  librespot_playback::player] Loading <The Brightest Days> with Spotify URI <spotify:track:3aBHjYg7xHAXu4Y5u19oqh>
[2023-06-29T23:22:03Z INFO  librespot_connect::spirc] Resolved 50 tracks from <"spotify:album:65EjKAFPc043WetlaXNFtW">
[2023-06-29T23:22:04Z INFO  librespot_playback::player] <The Brightest Days> (146948 ms) loaded

@roderickvd
Copy link
Member

Also from Europe right?
So weird.

@kingosticks
Copy link
Contributor

Yep, I'm in the UK. I can share the IP that my access point resolves to and someone who's having problems can try to hardcode that, to see if it makes any difference ?

@kingosticks
Copy link
Contributor

And one thing which I'm not 100% clear on here (sorry if I missed it), for those having discovery problems, can you confirm that librespot-java's discovery does actually work instead? I can't see what would be different at this fundamental level, all we've done up to this point is a session login (working) and then ask for a token (broken). It's only later on that things start to diverge between the two implementations.

@herrernst
Copy link
Contributor

Happens to me (in Austria) also since yesterday, never has happened before. Using current dev branch.

By the way, I also tried from another Internet connection in Austria, and there it works! And if I've read correctly, it did use the same access points. Will investigate further ...

@kingosticks
Copy link
Contributor

If possible can you double check that the same access point hostname definitely resolves to the same IP in both working and non-working cases? Presumably it was the same user account in both cases also?

@xhpohanka
Copy link
Author

I have no time now to look closer to the log, but it seems to me that librespot-java also ends with 403 here in Czechia...

2023-06-30 12:04:44,181 TRACE FileConfiguration:148 - Added new entry to configuration file: clientToken
2023-06-30 12:04:44,183 TRACE FileConfiguration:148 - Added new entry to configuration file: network.connectionTimeout
2023-06-30 12:04:44,183 TRACE FileConfiguration:148 - Added new entry to configuration file: proxy.ssl
2023-06-30 12:04:44,183 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onTrackSeeked
2023-06-30 12:04:44,183 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onStartedLoading
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onConnectionDropped
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onMetadataAvailable
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onTrackChanged
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onPlaybackFailed
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onPanicState
2023-06-30 12:04:44,184 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onFinishedLoading
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.enabled
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onPlaybackResumed
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onConnectionEstablished
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onPlaybackEnded
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onContextChanged
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.executeWithBash
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onPlaybackPaused
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onInactiveSession
2023-06-30 12:04:44,185 TRACE FileConfiguration:148 - Added new entry to configuration file: shell.onVolumeChanged
2023-06-30 12:04:44,186 TRACE FileConfiguration:148 - Added new entry to configuration file: player.bypassSinkVolume
2023-06-30 12:04:44,186 TRACE FileConfiguration:148 - Added new entry to configuration file: player.localFilesPath
2023-06-30 12:04:44,186 TRACE FileConfiguration:148 - Added new entry to configuration file: player.outputClass
2023-06-30 12:04:44,201 INFO  Utils:104 - Cryptography restrictions removal not needed.
2023-06-30 12:04:44,229 INFO  ZeroconfServer:472 - Zeroconf HTTP server started successfully on port 53259!
2023-06-30 12:04:44,997 TRACE ZeroconfServer:536 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/121300661 Linux/0 (PC desktop), Host=10.88.0.26, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2023-06-30 12:04:45,666 INFO  Zeroconf:500 - Announced Service{alias='librespot-java-player', service='spotify-connect', port=53259, text={VERSION=1.0, CPath=/, Stack=SP}, addresses=[/10.88.0.26], domain='.local', protocol='tcp', host='jules-ntb'}.
2023-06-30 12:04:50,343 TRACE ZeroconfServer:536 - Handling request: GET /?action=getInfo&version=2.7.1 HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/121300661 Linux/0 (PC desktop), Host=10.88.0.26, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2023-06-30 12:04:54,374 TRACE ZeroconfServer:536 - Handling request: GET /?action=getInfo&version=2.7.1 HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/121300661 Linux/0 (PC desktop), Host=10.88.0.26, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2023-06-30 12:04:54,390 TRACE ZeroconfServer:536 - Handling request: POST / HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/121300661 Linux/0 (PC desktop), Host=10.88.0.26, Accept-Encoding=gzip, Content-Length=822, Content-Type=application/x-www-form-urlencoded}
2023-06-30 12:04:54,452 INFO  ZeroconfServer:345 - Accepted new user from jules-ntb. {deviceId: 95125d2c2a63cfc6f6d2aa267bfa8443d425b37b}
2023-06-30 12:04:54,515 DEBUG TimeProvider:90 - Loaded time offset from NTP: 0ms
2023-06-30 12:04:54,778 INFO  ApResolver:99 - Loaded aps into pool: {accesspoint=[ap-gew4.spotify.com:4070, ap-gew4.spotify.com:443, ap-gew4.spotify.com:80, ap-gew1.spotify.com:4070, ap-guc3.spotify.com:443, ap-gue1.spotify.com:80], dealer=[gew4-dealer.spotify.com:443, gew1-dealer.spotify.com:443, guc3-dealer.spotify.com:443, gue1-dealer.spotify.com:443], spclient=[gew4-spclient.spotify.com:443, gew1-spclient.spotify.com:443, guc3-spclient.spotify.com:443, gue1-spclient.spotify.com:443]}
2023-06-30 12:04:54,822 INFO  Session:140 - Created new session! {deviceId: 95125d2c2a63cfc6f6d2aa267bfa8443d425b37b, ap: ap-gew1.spotify.com:4070, proxy: false}
2023-06-30 12:04:55,330 INFO  Session:334 - Connected successfully!
2023-06-30 12:04:55,563 TRACE Session:1413 - Session.Receiver started
2023-06-30 12:04:55,576 INFO  CacheManager:95 - There are 0 cached entries.
2023-06-30 12:04:55,579 TRACE AsyncProcessor:52 - AsyncProcessor{dealer-worker} has started
2023-06-30 12:04:55,580 TRACE AsyncProcessor:52 - AsyncProcessor{event-service-sender} has started
2023-06-30 12:04:55,581 INFO  Session:1495 - Skipping SecretBlock
2023-06-30 12:04:55,581 INFO  Session:1467 - Received LicenseVersion: 0
2023-06-30 12:04:55,581 INFO  Session:1457 - Received CountryCode: CZ
2023-06-30 12:04:55,581 DEBUG TokenProvider:68 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
2023-06-30 12:04:55,587 TRACE MercuryClient:148 - Send Mercury request, seq: 1, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=95125d2c2a63cfc6f6d2aa267bfa8443d425b37b, method: GET
2023-06-30 12:04:55,591 TRACE Session:784 - Parsed product info: {audiobook-onboarding-completed=0, remote-control=6, publish-activity=0, 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=1, buffering-strategy=0, expiry=1, ab-desktop-hide-follow=0, ab-collection-hide-unavailable-albums=0, capper-profile=, payments-initial-campaign=default, profile-image-upload=1, enable-annotations=2, ab-ad-player-targeting=1, 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, ab-sugarpills-sanity-check=0, playlist-folders=1, arsenal_country=1, track-cap=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=0, 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, shuffle=0, instant-search=0, instant-search-expand-sidebar=0, use-playlist-uris=0, user-profile-show-invitation-codes=0, 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, 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.scdn.co/head/{file_id}, ab-collection-followed-artists-only=0, browse-overview-enabled=1, on-demand=1, ap-resolve-pods=0, name=Spotify Premium, sidebar-navigation-enabled=0, loudness-levels=1:-5.0,0.0,3.0:-2.0, mobile-login=1, 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, 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=976, player-license=premium}
2023-06-30 12:04:55,591 INFO  Session:1495 - Skipping UnknownData_AllZeros
2023-06-30 12:04:55,591 INFO  Session:1495 - Skipping LegacyWelcome
2023-06-30 12:04:55,592 TRACE MercuryClient:191 - Handling packet, cmd: MercuryEvent, seq: 6906288720270327808, flags: 1, parts: 1
2023-06-30 12:04:55,594 DEBUG MercuryClient:226 - Couldn't dispatch Mercury event {seq: 6906288720270327808, uri: hm://pusher/v1/connections/OTUxMjVkMmMyYTYzY2ZjNmY2ZDJhYTI2N2JmYTg0NDNkNDI1YjM3YitBUCt0Y3A6Ly9nZXcxLWFjY2Vzc3BvaW50LWMtcDR6Zi5nZXcxLnNwb3RpZnkubmV0OjUwMTErRUM2NDg0NEE2NkNCNTEyQkMwNEMzNTFGRDhBNTBFMUJCMDQyQzlFMDA1M0E0Mjk5OUQwNUQxRDg5MDhGQzNDQQ%3D%3D, code: 200, payload: []}
2023-06-30 12:04:55,652 DEBUG Session:1471 - Received 0x10: EF217D8324B2DA4B50052920D623A1FEBB1328CC
2023-06-30 12:04:55,726 TRACE MercuryClient:191 - Handling packet, cmd: MercuryReq, seq: 1, flags: 1, parts: 2
2023-06-30 12:04:55,729 ERROR ZeroconfServer:375 - Couldn't establish a new session.
xyz.gianlu.librespot.mercury.MercuryClient$MercuryException: status: 403
        at xyz.gianlu.librespot.mercury.MercuryClient.sendSync(MercuryClient.java:107) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.core.TokenProvider.getToken(TokenProvider.java:69) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.core.TokenProvider.get(TokenProvider.java:80) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.dealer.DealerClient.connect(DealerClient.java:78) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.core.Session.authenticate(Session.java:362) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.core.Session.access$600(Session.java:77) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.core.Session$Builder.create(Session.java:1057) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer.handleAddUser(ZeroconfServer.java:367) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer.access$200(ZeroconfServer.java:56) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handleRequest(ZeroconfServer.java:499) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:574) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.lambda$run$1(ZeroconfServer.java:482) ~[librespot-player.jar:1.6.3]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-06-30 12:04:55,744 ERROR ZeroconfServer:501 - Failed handling addUser!
java.net.SocketException: Broken pipe (Write failed)
        at java.net.SocketOutputStream.socketWrite0(Native Method) ~[?:?]
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:110) ~[?:?]
        at java.net.SocketOutputStream.write(SocketOutputStream.java:138) ~[?:?]
        at xyz.gianlu.librespot.ZeroconfServer.handleAddUser(ZeroconfServer.java:382) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer.access$200(ZeroconfServer.java:56) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handleRequest(ZeroconfServer.java:499) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:574) ~[librespot-player.jar:1.6.3]
        at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.lambda$run$1(ZeroconfServer.java:482) ~[librespot-player.jar:1.6.3]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-06-30 12:04:56,015 INFO  Session:1422 - Skipping unknown command {cmd: 0x75, payload: 000000}
čen 30 12:05:25 jules-ntb systemd[1]: Stopping A spotify playing daemon...
čen 30 12:05:26 jules-ntb systemd[1]: librespot-java.service: Main process exited, code=exited, status=143/n/a
čen 30 12:05:26 jules-ntb systemd[1]: librespot-java.service: Failed with result 'exit-code'.
čen 30 12:05:26 jules-ntb systemd[1]: Stopped A spotify playing daemon.
čen 30 12:05:26 jules-ntb systemd[1]: librespot-java.service: Consumed 3.424s CPU time.

@kingosticks
Copy link
Contributor

kingosticks commented Jun 30, 2023

I wonder if librespot-org/librespot-java#445 (comment) holds the answer:

It is currently not possible to retrieve playlist-read tokens from Facebook/Spotify originated tokens (will return 403, like describe in librespot-org/librespot-java#370). That scope is mandatory for initializing the mercury connection which we still rely on.

What type of devices are you using to connect to librespot with? When I tried it yesterday (working) I was running librespot on Linux and connecting from the Android app. I've just tried running librespot on Windows and connecting from the Windows app but now I see error 403 from hm://keymaster/token/authenticated. Annoyingly, for some reason the Android app can't see librespot running on my Windows box, which I really wanted to test. Maybe someone else will have more luck there.

The way login works on their Windows client has definitely changed from what I remember. You now have to do an OAuth login through your web browser which provides their app with an "Authorization Code" which it then exchanges for an access token. I am guessing it then uses that access token to create a Mercury session (usingauth type AUTHENTICATION_SPOTIFY_TOKEN??) from which to obtain stored credentials, those stored creds are then used with login5.spotify.com/v3/login - which seems to provide another access token that's used for everything interesting via spclient.wg.spotify.com. I suspect this client isn't using keymaster anymore, maybe it's not using Mercury/hermes at all. Sadly I don't have anything setup to capture the hermes traffic (is there anything that still works for this?).

So maybe there is something different with the credentials blob passed via discovery, depending on what client you use? And some blobs don't have permission (scope) to access keymaster. Can anyone else help test that theory?

@roderickvd
Copy link
Member

You may be onto something here. From what I remember, the Windows client indeed uses a different keymaster ID. In dev I made changes to better mimicking that actual behavior and do the “right thing” per platform instead of using the same ID everywhere. And/or I think I am also sending the actual client ID gotten from discovery instead of a hardcoded one.

Finally I rarely used Spotify on Windows so probably haven’t properly tested it either.

@JasonLG1979
Copy link
Contributor

JasonLG1979 commented Jun 30, 2023

In my case librespot runs on Linux and so do the players either via the web player in a browser or the Linux desktop client, which is AFAIK basically an electron app so basically the web client. I will check again but I don't remember having any luck from my Android phone either.

I also made sure to be signed in directly to Spotify and not through Facebook or Google if that makes a difference.

@JasonLG1979
Copy link
Contributor

Ok just checked and it works fine from my phone.

@kingosticks
Copy link
Contributor

I've had success getting the bearer access token using login5 instead of keymaster with https://github.com/kingosticks/librespot/tree/auth-token-from-login5. This is currently what the official Windows client does and is (something like) what we should move towards anyway. I'm not 100% sure if I have broken anything else with this hack, I was very surprised it just worked. I think this will also unblock #1098 which is nice.

@JasonLG1979
Copy link
Contributor

@kingosticks That works for me as expected so far with the Linux desktop client. I think you're on the right track and big thanks for figuring this out.

@SuisChan
Copy link
Contributor

SuisChan commented Jul 1, 2023

I've had success getting the bearer access token using login5 instead of keymaster with https://github.com/kingosticks/librespot/tree/auth-token-from-login5.

Was it a problem to get a bearer token? For some reason I thought it just wasn't implemented

@kingosticks
Copy link
Contributor

kingosticks commented Jul 1, 2023

No problem and yes that's correct. I could have phrased that better. What I meant to say is I had success fixing playback by implementing login5 and obtaining an access token that way. Just as you had suggested doing in a previous issue somewhere - thanks for the tip. The alternative method using keymaster now seems to be dead in some cases.

@xhpohanka
Copy link
Author

I can confirm that @kingosticks branch is working for me on linux with linux and android clients too...

@herrernst
Copy link
Contributor

I can confirm that current dev works only when initiated from iOS client, but not when initiated from macOS desktop client. (So it has most certainly nothing to do with my internet connection.) I can also confirm that initiation from desktop macOS app now works with the branch from @kingosticks . Unfortunately, with this branch, playback from iOS client results in an error:

[2023-07-02T12:43:52Z INFO  librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point
[2023-07-02T12:43:52Z ERROR librespot_connect::spirc] ContextError: Error { kind: InvalidArgument, error: StatusCode(400) }
[2023-07-02T12:43:52Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: InvalidArgument, error: StatusCode(400) }
[2023-07-02T12:43:52Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:16weYq1yI3d7pyjkRLYlrY")>: ()
[2023-07-02T12:43:52Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: InvalidArgument, error: StatusCode(400) }

@kingosticks
Copy link
Contributor

Can you get a log with more debug. I don't have Apple devices.

I wonder if this is because spclient.request is now always sending a client-token header along with the auth token it got from login5. Perhaps some requests don't like that.

@Gerrelt
Copy link

Gerrelt commented Jul 3, 2023

I had the same 403 problem, and it was also solved by using @kingosticks branch.
I now have librespot running on piCore (14.0) and Raspbian (11 Bullseye), connecting to it with the windows and android spotify app, all working fine. Thanks kingosticks!

@herrernst
Copy link
Contributor

Thank you @kingosticks. Here is a more detailed log when using the iOS app:

[2023-07-03T19:11:59Z INFO  librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point
[2023-07-03T19:11:59Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-07-03T19:11:59Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitSessionClientChangedEvent("58bd3<redacted>aaa033eb3", "iPhone", "Apple", "iPhone")
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitVolumeChangedEvent(58958)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitAutoPlayChangedEvent(false)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitShuffleChangedEvent(false)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=EmitRepeatChangedEvent(false)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(true)
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:49ceentvDOPJFsRNrwYrfb"), false, 154071)
[2023-07-03T19:11:59Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-07-03T19:11:59Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-07-03T19:11:59Z ERROR librespot_connect::spirc] ContextError: Error { kind: InvalidArgument, error: StatusCode(400) }
[2023-07-03T19:11:59Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-07-03T19:11:59Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-07-03T19:11:59Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: InvalidArgument, error: StatusCode(400) }
[2023-07-03T19:11:59Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:49ceentvDOPJFsRNrwYrfb")>: ()
[2023-07-03T19:11:59Z DEBUG librespot_connect::spirc] Marked <TrackRef { gid: Some([136, 77, 47, 10, 225, 144, 68, 201, 158, 81, 189, 104, 177, 182, 125, 153]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at 3 as NonPlayable
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2DI0lPhJcYHHO0DDv7VUxj"))
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] Preloading track
[2023-07-03T19:11:59Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-07-03T19:11:59Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-07-03T19:11:59Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: InvalidArgument, error: StatusCode(400) }
[2023-07-03T19:11:59Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:2DI0lPhJcYHHO0DDv7VUxj")

@xhpohanka
Copy link
Author

Hi - will the @kingosticks's PR be merged? I don't know if the solution is optimal but for me it works :)

@roderickvd
Copy link
Member

If he can make it a PR? Currently it’s in one of his branches but not yet a PR here.

@kingosticks
Copy link
Contributor

I can't remember what state it is in. I'll take a look when I get time

@eldar
Copy link

eldar commented Sep 3, 2023

I can confirm that @kingosticks branch fixes it for me. Any chance this get merged?

@kingosticks
Copy link
Contributor

I'm away for the next week without a computer. Anyone who has the time is welcome to take the code and submit a PR. I can't remember what state I left it in.

@Gerrelt
Copy link

Gerrelt commented Nov 13, 2023

I've created a pull request with the changes of @kingosticks , I am not an experienced github user, so I hope I did it right..
Thank you @kingosticks for providing this solution.

Here's the pull request:
#1220

@herrernst
Copy link
Contributor

Have you tested this change with an iOS client? Because it then broke for me on iPhone

@Gerrelt
Copy link

Gerrelt commented Nov 13, 2023

No, but I can test it with an iPhone, I'll be back.

@herrernst
Copy link
Contributor

Please test the case when iPhone makes the first connection. So after (re)starting librespot.

@Gerrelt
Copy link

Gerrelt commented Nov 13, 2023

I've rebooted the Raspberry Pi, connected to the spotify connect device in the iPhone spotify app, and it worked.
We played around a bit, skipped to the middle of the song, skipped to the next song, let it go to the next song automatically, and it all worked fine.

@herrernst
Copy link
Contributor

Okay, great. I only had a problem when the iOS client did the authentication, but that was some weeks or even months ago (I am currently not a Premium subscriber anymore, so I can't test). But if I remember correctly, when using with @kingosticks' change iOS client couldn't authenticate:

  • librespot (re)starts, macOS client authenticates, iOS also works then
  • librespot (re)starts, iOS tries authentication, doesn't work

If it works now, that would be great.

@roderickvd
Copy link
Member

Let's continue this conversation at #1220

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment