librespot-org / librespot-java

The most up-to-date open source Spotify client
Apache License 2.0
382 stars 94 forks source link

Connecting from 2 spotify accounts #267

Closed paulbastian closed 3 years ago

paulbastian commented 3 years ago

Describe the bug Hello there, first of all thanks forbuilding this awesome project, I was havin trouble with disconnects on the original rust librespot, switching to this version has so far fixed my problems! I'm currently having only one problem: I'm running librespot on a Rpi4 using my living room hifi, therefore persons are sharing the connection. The first person to connect is successfully making a connection via wifi and play music. As soon as some other person tries to connect the speakers, the software is bugged and doesnt let you connect. I tried all sorts of combinations with original device selecting its own audio output again and killing the app. However no success. Thanks for helping!

To Reproduce Run librespot, connect spotify with acc1 from device1, connect spotify from acc2 with device2

Expected behavior Device2 should take over and disconnect Device1.

Screenshots/Stracktraces/Logs The following log is generated:

2020-11-23 19:19:39,493 TRACE CdnManager:261 - Chunk 23/38 completed, cached: false, stream: {fileId: A982F7A60369B4A3C5865899B958450AD6476878}
2020-11-23 19:19:49,725 TRACE CdnManager:261 - Chunk 24/38 completed, cached: false, stream: {fileId: A982F7A60369B4A3C5865899B958450AD6476878}
2020-11-23 19:19:51,315 INFO  Session:419 - Closing session. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee}
2020-11-23 19:19:51,316 TRACE AsyncProcessor:57 - AsyncProcessor{dealer-worker} is shutting down
2020-11-23 19:19:51,317 DEBUG DealerClient:309 - Did not dispatch connection invalidated: null != xyz.gianlu.librespot.dealer.DealerClient$ConnectionHolder@1537a53
2020-11-23 19:19:51,318 TRACE AsyncProcessor:57 - AsyncProcessor{pm-audio-keys} is shutting down
2020-11-23 19:19:51,320 TRACE AsyncProcessor:57 - AsyncProcessor{pm-channels} is shutting down
2020-11-23 19:19:51,320 TRACE AsyncProcessor:57 - AsyncProcessor{event-service-sender} is shutting down
2020-11-23 19:19:51,321 TRACE AsyncProcessor:48 - AsyncProcessor{event-service-sender} is shut down
2020-11-23 19:19:51,323 TRACE AsyncProcessor:57 - AsyncProcessor{pm-mercury} is shutting down
2020-11-23 19:19:51,330 TRACE Session:1380 - Session.Receiver stopped
2020-11-23 19:19:51,330 INFO  Session:481 - Closed session. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee} 
2020-11-23 19:19:51,331 INFO  ZeroconfServer:327 - Accepted new user from Fairphone 3. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee}
2020-11-23 19:19:51,367 DEBUG TimeProvider:74 - Loaded time offset from NTP: 3ms
2020-11-23 19:19:51,425 INFO  Session:122 - Created new session! {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee, ap: gew1-accesspoint-b-jb5p.ap.spotify.com:443, proxy: false} 
2020-11-23 19:19:51,800 INFO  Session:313 - Connected successfully!
2020-11-23 19:19:51,880 TRACE Session:1293 - Session.Receiver started
2020-11-23 19:19:51,881 TRACE AsyncProcessor:36 - AsyncProcessor{pm-mercury} has started
2020-11-23 19:19:51,883 TRACE AsyncProcessor:36 - AsyncProcessor{pm-audio-keys} has started
2020-11-23 19:19:51,885 TRACE AsyncProcessor:36 - AsyncProcessor{pm-channels} has started
2020-11-23 19:19:51,887 TRACE AsyncProcessor:36 - AsyncProcessor{dealer-worker} has started
2020-11-23 19:19:51,888 TRACE AsyncProcessor:36 - AsyncProcessor{event-service-sender} has started
2020-11-23 19:19:51,890 INFO  CacheManager:80 - There are 15 cached entries.
2020-11-23 19:19:51,890 INFO  Session:1375 - Skipping SecretBlock
2020-11-23 19:19:51,890 TRACE MercuryClient:138 - Send Mercury request, seq: 1, uri: hm://event-service/v1/events, method: POST
2020-11-23 19:19:51,890 DEBUG TokenProvider:51 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
2020-11-23 19:19:51,890 INFO  Session:1347 - Received LicenseVersion: 0
2020-11-23 19:19:51,891 INFO  Session:1337 - Received CountryCode: DE
2020-11-23 19:19:51,892 TRACE MercuryClient:138 - Send Mercury request, seq: 2, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=81ffc076e7187dbf274ca9941a3645c3e7da1fee, method: GET
2020-11-23 19:19:51,911 TRACE Session:732 - Parsed product info: {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=0, 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=0, ad-formats-video-takeover=1, npt-disabled=2, 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, ab-mobile-running-tempo-detection=Control, is_email_verified=0, shows-collection=1, enable-annotations-read=0, mobile-browse=0, payments-locked-state=0, shows-collection-jam=1, ab-browse-music-tuesday=1, offline=1, streaming=1, fb-info-confirmation=control, taste-onboarding-disabled=0, 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=5000, 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, payments-cancel-state-interstitial=0, ab-collection-union=1, key-memory-cache-mode=1:15,300, libspotify=1, high-bitrate=1, head-file-caching=1, radio=1, 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=6, network-operator-premium-activation=1, video-device-blacklisted=0, collection=1, fb-grant-permission-local-render=0, backend-advised-bitrate=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=1, name=Spotify Premium, sidebar-navigation-enabled=0, loudness-levels=1:-6.0,3.0,6.0:-3.0, mobile-login=1, preferred-locale=en, license-acceptance-grace-days=30, prefetch-strategy=2, ugc-abuse-report=1, ab-watch-now=0, payments-latest-reusable-provider=adyen_cards;2020-06-18, financial-product=pr:premium,tc:0,rt:v2_DE_default_new-family-master-1m_14.62_EUR_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=742, player-license=premium}
2020-11-23 19:19:51,912 INFO  Session:1375 - Skipping LegacyWelcome
2020-11-23 19:19:51,913 INFO  Session:1375 - Skipping UnknownData_AllZeros
2020-11-23 19:19:51,915 TRACE MercuryClient:181 - Handling packet, cmd: MercuryEvent, seq: 5905397787947696128, flags: 1, parts: 1
2020-11-23 19:19:51,916 DEBUG MercuryClient:216 - Couldn't dispatch Mercury event {seq: 5905397787947696128, uri: hm://pusher/v1/connections/ODFmZmMwNzZlNzE4N2RiZjI3NGNhOTk0MWEzNjQ1YzNlN2RhMWZlZStBUCt0Y3A6Ly9nZXcxLWFjY2Vzc3BvaW50LWItamI1cC5nZXcxLnNwb3RpZnkubmV0OjUwMjYrQjhGQjYzNEM5Mzc3MTU3RjlFNDcxNjhCN0U1RUEwMEExMTBDRTM2MTUxN0E4NzY0RDAwNDk1Nzc5QzE5QjdFOQ%3D%3D, code: 200, payload: []}
2020-11-23 19:19:51,973 DEBUG Session:1351 - Received 0x10: 25C07F93B7A14EB0C6A465B0BD12249863AB9B69
2020-11-23 19:19:51,974 TRACE MercuryClient:181 - Handling packet, cmd: MercuryReq, seq: 1, flags: 1, parts: 1
2020-11-23 19:19:51,975 DEBUG EventService:35 - Event sent. {body: 812|1|en, result: 200}
2020-11-23 19:19:51,996 TRACE MercuryClient:181 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 2
2020-11-23 19:19:51,996 INFO  Session:1302 - Skipping unknown command {cmd: 0x75, payload: 000000}
2020-11-23 19:19:51,998 DEBUG TokenProvider:55 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQB6dD...p-P5vQ', scopes=[playlist-read], timestamp=1606155592000}}
2020-11-23 19:19:52,000 INFO  Session:344 - Authenticated as 1158398333!
2020-11-23 19:19:52,002 DEBUG Session:509 - Connection was broken while Session.close() has been called
2020-11-23 19:19:52,002 DEBUG Session:490 - Connection was broken while Session.close() has been called
2020-11-23 19:19:52,004 FATAL Log4JUncaughtExceptionHandler:15 - [zeroconf-client-30848111]
java.lang.IllegalStateException: Session isn't authenticated!
    at xyz.gianlu.librespot.core.Session.eventService(Session.java:601) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.metrics.PlaybackMetrics.sendEvents(PlaybackMetrics.java:102) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Player.endMetrics(Player.java:561) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Player.close(Player.java:793) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Main$1.sessionChanged(Main.java:37) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer.lambda$handleAddUser$0(ZeroconfServer.java:355) ~[librespot-player-1.5.2.jar:1.5.2]
    at java.util.ArrayList.forEach(ArrayList.java:1511) ~[?:?]
    at xyz.gianlu.librespot.ZeroconfServer.handleAddUser(ZeroconfServer.java:355) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer.access$200(ZeroconfServer.java:40) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handleRequest(ZeroconfServer.java:469) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:544) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.lambda$run$1(ZeroconfServer.java:452) ~[librespot-player-1.5.2.jar:1.5.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
    at java.lang.Thread.run(Thread.java:832) [?:?]
2020-11-23 19:19:52,345 DEBUG DealerClient:321 - Dealer connected! {host: guc-dealer.spotify.com}
2020-11-23 19:19:52,349 DEBUG DealerClient:181 - Couldn't dispatch message: hm://pusher/v1/connections/ODFmZmMwNzZlNzE4N2RiZjI3NGNhOTk0MWEzNjQ1YzNlN2RhMWZlZStkZWFsZXIrdGNwOi8vZ3VjMy1kZWFsZXItYi03NHo3Lmd1YzMuc3BvdGlmeS5uZXQ6NTcwMCtDN0ExNDdBQTVBRUEyMUFGQzJDRUQ3NDI1N0UwNjlCNTNGOUZBQkQ4QTdBMzZDRjgzRjQzQjlBRkQ1RjdGQTBF
2020-11-23 19:19:59,732 TRACE CdnManager:261 - Chunk 25/38 completed, cached: false, stream: {fileId: A982F7A60369B4A3C5865899B958450AD6476878}
2020-11-23 19:20:09,994 TRACE CdnManager:261 - Chunk 26/38 completed, cached: false, stream: {fileId: A982F7A60369B4A3C5865899B958450AD6476878}
2020-11-23 19:20:13,244 INFO  Session:419 - Closing session. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee}
2020-11-23 19:20:13,245 TRACE AsyncProcessor:57 - AsyncProcessor{dealer-worker} is shutting down
2020-11-23 19:20:13,247 DEBUG DealerClient:309 - Did not dispatch connection invalidated: null != xyz.gianlu.librespot.dealer.DealerClient$ConnectionHolder@a43f1b
2020-11-23 19:20:13,248 TRACE AsyncProcessor:57 - AsyncProcessor{pm-audio-keys} is shutting down
2020-11-23 19:20:13,249 TRACE AsyncProcessor:57 - AsyncProcessor{pm-channels} is shutting down
2020-11-23 19:20:13,249 TRACE AsyncProcessor:57 - AsyncProcessor{event-service-sender} is shutting down
2020-11-23 19:20:13,250 TRACE AsyncProcessor:48 - AsyncProcessor{event-service-sender} is shut down
2020-11-23 19:20:13,251 TRACE AsyncProcessor:57 - AsyncProcessor{pm-mercury} is shutting down
2020-11-23 19:20:13,253 TRACE Session:1380 - Session.Receiver stopped
2020-11-23 19:20:13,253 INFO  Session:481 - Closed session. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee} 
2020-11-23 19:20:13,254 INFO  ZeroconfServer:327 - Accepted new user from Fairphone 3. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee}
2020-11-23 19:20:13,289 DEBUG TimeProvider:74 - Loaded time offset from NTP: 3ms
2020-11-23 19:20:13,346 INFO  Session:122 - Created new session! {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee, ap: gew1-accesspoint-b-zqpq.ap.spotify.com:443, proxy: false} 
2020-11-23 19:20:13,719 INFO  Session:313 - Connected successfully!
2020-11-23 19:20:13,784 TRACE Session:1293 - Session.Receiver started
2020-11-23 19:20:13,786 TRACE AsyncProcessor:36 - AsyncProcessor{pm-mercury} has started
2020-11-23 19:20:13,788 TRACE AsyncProcessor:36 - AsyncProcessor{pm-audio-keys} has started
2020-11-23 19:20:13,789 TRACE AsyncProcessor:36 - AsyncProcessor{pm-channels} has started
2020-11-23 19:20:13,798 TRACE AsyncProcessor:36 - AsyncProcessor{dealer-worker} has started
2020-11-23 19:20:13,800 TRACE AsyncProcessor:36 - AsyncProcessor{event-service-sender} has started
2020-11-23 19:20:13,802 INFO  Session:1375 - Skipping SecretBlock
2020-11-23 19:20:13,802 TRACE MercuryClient:138 - Send Mercury request, seq: 1, uri: hm://event-service/v1/events, method: POST
2020-11-23 19:20:13,802 DEBUG TokenProvider:51 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
2020-11-23 19:20:13,803 INFO  Session:1347 - Received LicenseVersion: 0
2020-11-23 19:20:13,805 INFO  Session:1337 - Received CountryCode: DE
2020-11-23 19:20:13,808 INFO  CacheManager:80 - There are 15 cached entries.
2020-11-23 19:20:13,810 TRACE MercuryClient:138 - Send Mercury request, seq: 2, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=81ffc076e7187dbf274ca9941a3645c3e7da1fee, method: GET
2020-11-23 19:20:13,825 TRACE Session:732 - Parsed product info: {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=0, 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=0, ad-formats-video-takeover=1, npt-disabled=2, 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, ab-mobile-running-tempo-detection=Control, is_email_verified=0, shows-collection=1, enable-annotations-read=0, mobile-browse=0, payments-locked-state=0, shows-collection-jam=1, ab-browse-music-tuesday=1, offline=1, streaming=1, fb-info-confirmation=control, taste-onboarding-disabled=0, 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=5000, 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, payments-cancel-state-interstitial=0, ab-collection-union=1, key-memory-cache-mode=1:15,300, libspotify=1, high-bitrate=1, head-file-caching=1, radio=1, 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=6, network-operator-premium-activation=1, video-device-blacklisted=0, collection=1, fb-grant-permission-local-render=0, backend-advised-bitrate=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=1, name=Spotify Premium, sidebar-navigation-enabled=0, loudness-levels=1:-6.0,3.0,6.0:-3.0, mobile-login=1, preferred-locale=en, license-acceptance-grace-days=30, prefetch-strategy=2, ugc-abuse-report=1, ab-watch-now=0, payments-latest-reusable-provider=adyen_cards;2020-06-18, financial-product=pr:premium,tc:0,rt:v2_DE_default_new-family-master-1m_14.62_EUR_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=742, player-license=premium}
2020-11-23 19:20:13,826 INFO  Session:1375 - Skipping LegacyWelcome
2020-11-23 19:20:13,826 INFO  Session:1375 - Skipping UnknownData_AllZeros
2020-11-23 19:20:13,828 TRACE MercuryClient:181 - Handling packet, cmd: MercuryEvent, seq: 3385018069922349056, flags: 1, parts: 1
2020-11-23 19:20:13,829 DEBUG MercuryClient:216 - Couldn't dispatch Mercury event {seq: 3385018069922349056, uri: hm://pusher/v1/connections/ODFmZmMwNzZlNzE4N2RiZjI3NGNhOTk0MWEzNjQ1YzNlN2RhMWZlZStBUCt0Y3A6Ly9nZXcxLWFjY2Vzc3BvaW50LWItenFwcS5nZXcxLnNwb3RpZnkubmV0OjUwMjcrQzk1OUFGREVDREFDMzI4QkE2Njc3QTRCODQyMkU0NkNDMjFFNkIzRUM0QTAxREYzOTc1QTBCMjkyRjFFQ0IzOA%3D%3D, code: 200, payload: []}
2020-11-23 19:20:13,834 DEBUG Session:1351 - Received 0x10: 61E2C8D9D5C3ABB8A57F5760DD5F85C160AAA0AE
2020-11-23 19:20:13,835 TRACE MercuryClient:181 - Handling packet, cmd: MercuryReq, seq: 1, flags: 1, parts: 1
2020-11-23 19:20:13,836 DEBUG EventService:35 - Event sent. {body: 812|1|en, result: 200}
2020-11-23 19:20:13,860 INFO  Session:1302 - Skipping unknown command {cmd: 0x75, payload: 000000}
2020-11-23 19:20:13,929 TRACE MercuryClient:181 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 2
2020-11-23 19:20:13,931 DEBUG TokenProvider:55 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQCrYf...5TCVsQ', scopes=[playlist-read], timestamp=1606155613933}}
2020-11-23 19:20:13,935 INFO  Session:344 - Authenticated as 1158398333!
2020-11-23 19:20:13,937 TRACE MixingLine:169 - Toggle first channel: false
2020-11-23 19:20:13,938 DEBUG PlayerQueueEntry:209 - PlayerQueueEntry{018c078e51fc46a6193178627eba03b6} has been removed from output.
2020-11-23 19:20:13,940 TRACE PlayerQueueEntry:325 - PlayerQueueEntry{018c078e51fc46a6193178627eba03b6} terminated.
2020-11-23 19:20:13,941 TRACE PlayerQueue:141 - Queue has been cleared.
2020-11-23 19:20:13,942 DEBUG Session:490 - Connection was broken while Session.close() has been called
2020-11-23 19:20:13,943 FATAL Log4JUncaughtExceptionHandler:15 - [zeroconf-client-26379876]
java.lang.IllegalStateException: Session isn't authenticated!
    at xyz.gianlu.librespot.core.Session.dealer(Session.java:573) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.StateWrapper.close(StateWrapper.java:818) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Player.close(Player.java:797) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Main$1.sessionChanged(Main.java:37) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer.lambda$handleAddUser$0(ZeroconfServer.java:355) ~[librespot-player-1.5.2.jar:1.5.2]
    at java.util.ArrayList.forEach(ArrayList.java:1511) ~[?:?]
    at xyz.gianlu.librespot.ZeroconfServer.handleAddUser(ZeroconfServer.java:355) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer.access$200(ZeroconfServer.java:40) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handleRequest(ZeroconfServer.java:469) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.handle(ZeroconfServer.java:544) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.ZeroconfServer$HttpRunner.lambda$run$1(ZeroconfServer.java:452) ~[librespot-player-1.5.2.jar:1.5.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
    at java.lang.Thread.run(Thread.java:832) [?:?]
2020-11-23 19:20:14,396 DEBUG DealerClient:321 - Dealer connected! {host: gae-dealer.spotify.com}
2020-11-23 19:20:14,399 DEBUG DealerClient:181 - Couldn't dispatch message: hm://pusher/v1/connections/ODFmZmMwNzZlNzE4N2RiZjI3NGNhOTk0MWEzNjQ1YzNlN2RhMWZlZStkZWFsZXIrdGNwOi8vZ2FlMi1kZWFsZXItYi1qOHZ2LmdhZTIuc3BvdGlmeS5uZXQ6NTcwMCs1NzVGRTU3RDUxRUE1QTlCN0QzQjBDRTM2NjYzMEI3QjI3NTQ3NDU1MzVCNUI1QUQyOUI1M0QwMUY5QUFFQjlE
^C2020-11-23 19:20:38,260 TRACE PlayerQueue:141 - Queue has been cleared.
2020-11-23 19:20:38,260 INFO  Session:419 - Closing session. {deviceId: 81ffc076e7187dbf274ca9941a3645c3e7da1fee}
2020-11-23 19:20:38,261 DEBUG Session:490 - Connection was broken while Session.close() has been called
2020-11-23 19:20:38,261 TRACE AsyncProcessor:57 - AsyncProcessor{dealer-worker} is shutting down
2020-11-23 19:20:38,263 FATAL Log4JUncaughtExceptionHandler:15 - [Thread-0]
java.lang.IllegalStateException: Session isn't authenticated!
    at xyz.gianlu.librespot.core.Session.dealer(Session.java:573) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.StateWrapper.close(StateWrapper.java:818) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Player.close(Player.java:797) ~[librespot-player-1.5.2.jar:1.5.2]
    at xyz.gianlu.librespot.player.Main$1.lambda$new$0(Main.java:31) ~[librespot-player-1.5.2.jar:1.5.2]
    at java.lang.Thread.run(Thread.java:832) [?:?]
2020-11-23 19:20:38,264 DEBUG DealerClient:309 - Did not dispatch connection invalidated: null != xyz.gianlu.librespot.dealer.DealerClient$ConnectionHolder@1ce2574
2020-11-23 19:20:38,265 TRACE AsyncProcessor:57 - AsyncProcessor{pm-audio-keys} is shutting down
2020-11-23 19:20:38,265 TRACE AsyncProcessor:57 - AsyncProcessor{pm-channels} is shutting down
2020-11-23 19:20:38,266 TRACE AsyncProcessor:57 - AsyncProcessor{event-service-sender} is shutting down

Version/Commit librespot-player-1.5.2.jar from the releases page

devgianlu commented 3 years ago

I've made some changes on dev, let me know if that works for you.

paulbastian commented 3 years ago

Not getting any device shown on spotiy connect

2020-11-24 23:14:53,045 INFO  Utils:84 - Cryptography restrictions removal not needed.
2020-11-24 23:14:53,175 INFO  ZeroconfServer:456 - Zeroconf HTTP server started successfully on port 13575!
2020-11-24 23:14:54,090 TRACE ZeroconfServer:520 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/114200622 Linux/0 (PC desktop), Host=192.168.2.202, Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-11-24 23:14:54,682 INFO  Zeroconf:473 - Announced Service{alias='librespot-java', service='spotify-connect', port=13575, text={VERSION=1.0, CPath=/, Stack=SP}, addresses=[/192.168.2.202], domain='.local', protocol='tcp', host='pi4'}.
devgianlu commented 3 years ago

My changes should be completely unrelated to this, does it work if you rollback?

paulbastian commented 3 years ago

Hey, my apologies, I had wifi off. Works great now, thank you!!

paulbastian commented 3 years ago

I only noticed one warning, fyi:

2020-11-25 21:02:26,450 WARN  DealerClient:352 - Failed handling message: {"headers":{"MC-ETag":"21880147820","Collection-Source-Revision":"21880147820","Collection-Update-Id":"08ebf15f36699480","Content-Type":"text/plain"},"payloads":["{\"items\":[{\"type\":\"track\",\"identifier\":\"4uYtDSwaLvcXiEf92xe58O\",\"unheard\":false,\"addedAt\":1606334545,\"removed\":false}]}"],"type":"message","uri":"hm://collection/collection/1158398333/json"}
java.lang.IllegalArgumentException: Illegal base64 character 7b
    at java.util.Base64$Decoder.decode0(Base64.java:791) ~[?:?]
    at java.util.Base64$Decoder.decode(Base64.java:567) ~[?:?]
    at java.util.Base64$Decoder.decode(Base64.java:590) ~[?:?]
    at xyz.gianlu.librespot.common.BytesArrayList.streamBase64(BytesArrayList.java:31) ~[librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at xyz.gianlu.librespot.dealer.DealerClient.handleMessage(DealerClient.java:131) ~[librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at xyz.gianlu.librespot.dealer.DealerClient.access$800(DealerClient.java:32) ~[librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at xyz.gianlu.librespot.dealer.DealerClient$ConnectionHolder$WebSocketListenerImpl.onMessage(DealerClient.java:350) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.ws.RealWebSocket.onReadMessage(RealWebSocket.kt:333) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.ws.WebSocketReader.readMessageFrame(WebSocketReader.kt:245) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.kt:106) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.kt:293) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.ws.RealWebSocket$connect$1.onResponse(RealWebSocket.kt:195) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:519) [librespot-player-1.5.3-SNAPHOST.jar:1.5.3-SNAPHOST]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
    at java.lang.Thread.run(Thread.java:832) [?:?]