Device can not connect #281
Description
Describe the bug
Connection is by ZeroConf. Player is successfully advertised, but connection fails.
To Reproduce
Start Spotify on device (in my case, an iPhone), find player, select to connect. This will not happen 100% of the time, but once it has happened, subsequent attempts to connect will also fail. Player is restarted at 4am every day.
Expected behavior
Device should connect to player.
Version/Commit
Commit 26818c6
Screenshots/Stracktraces/Logs
Logs as follows:
2020-12-29 04:00:04,879 INFO Utils:84 - Cryptography restrictions removal not needed.
2020-12-29 04:00:04,963 INFO ZeroconfServer:456 - Zeroconf HTTP server started successfully on port [My Port]!
2020-12-29 04:00:06,665 INFO Zeroconf:473 - Announced Service{alias='[My Alias]', service='spotify-connect', port=[My Port], text={VERSION=1.0, CPath=/, Stack=SP}, addresses=[/[My Internal IP], /192.168.192.106], domain='.local', protocol='tcp', host='[My Alias]'}.
2020-12-29 06:06:53,606 TRACE ZeroconfServer:520 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.86 iOS/14.3 (iPhone11,2), Host=[My Internal IP], Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-12-29 06:38:24,363 TRACE ZeroconfServer:520 - Handling request: GET /?action=getInfo HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.86 iOS/14.3 (iPhone11,2), Host=[My Internal IP], Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-12-29 06:38:27,392 TRACE ZeroconfServer:520 - Handling request: GET /?action=getInfo&version=2.7.1 HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.86 iOS/14.3 (iPhone11,2), Host=[My Internal IP], Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-12-29 06:38:29,350 TRACE ZeroconfServer:520 - Handling request: GET /?action=getInfo&version=2.7.1 HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.86 iOS/14.3 (iPhone11,2), Host=[My Internal IP], Accept-Encoding=gzip, Content-Type=application/x-www-form-urlencoded}
2020-12-29 06:38:29,369 TRACE ZeroconfServer:520 - Handling request: POST / HTTP/1.1, headers: {Keep-Alive=0, Connection=keep-alive, User-Agent=Spotify/8.5.86 iOS/14.3 (iPhone11,2), Host=[My Internal IP], Accept-Encoding=gzip, Content-Length=663, Content-Type=application/x-www-form-urlencoded}
2020-12-29 06:38:29,522 INFO ZeroconfServer:329 - Accepted new user from Benæs iPhone. {deviceId: [My Device ID]}
2020-12-29 06:38:29,902 INFO ApResolver:68 - Loaded aps into pool: {accesspoint=[gae2-accesspoint-b-fzx5.ap.spotify.com:4070, gae2-accesspoint-b-pnz9.ap.spotify.com:443, gae2-accesspoint-b-htx9.ap.spotify.com:80, gae2-accesspoint-b-s6j1.ap.spotify.com:4070, gae2-accesspoint-b-k4mf.ap.spotify.com:443, gae2-accesspoint-b-z622.ap.spotify.com:80, gew1-accesspoint-b-g2qd.ap.spotify.com:4070, gew1-accesspoint-b-xjpj.ap.spotify.com:443, guc3-accesspoint-b-92lv.ap.spotify.com:80], dealer=[gae-dealer.spotify.com:443, gew-dealer.spotify.com:443, guc-dealer.spotify.com:443], spclient=[gae-spclient.spotify.com:443, guc-spclient.spotify.com:443, gew-spclient.spotify.com:443]}
2020-12-29 06:38:30,104 DEBUG TimeProvider:74 - Loaded time offset from NTP: 612ms
2020-12-29 06:38:30,646 INFO Session:120 - Created new session! {deviceId: [My Device ID], ap: gae2-accesspoint-b-z622.ap.spotify.com:80, proxy: false}
2020-12-29 06:38:31,416 INFO Session:311 - Connected successfully!
2020-12-29 06:38:31,692 TRACE Session:1281 - Session.Receiver started
2020-12-29 06:38:31,719 TRACE AsyncProcessor:36 - AsyncProcessor{dealer-worker} has started
2020-12-29 06:38:31,723 TRACE AsyncProcessor:36 - AsyncProcessor{event-service-sender} has started
2020-12-29 06:38:31,725 INFO Session:1363 - Skipping SecretBlock
2020-12-29 06:38:31,725 INFO Session:1335 - Received LicenseVersion: 0
2020-12-29 06:38:31,727 INFO Session:1325 - Received CountryCode: AU
2020-12-29 06:38:31,735 DEBUG TokenProvider:51 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
2020-12-29 06:38:31,755 TRACE Session:722 - Parsed product info: {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=1, 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, 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=0, 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=10000, 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, client-deprecated=1, app-developer=1, 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, 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-au, 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_AU_default_duo-master-1m_15.99_AUD_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=133, player-license=premium}
2020-12-29 06:38:31,756 INFO Session:1363 - Skipping LegacyWelcome
2020-12-29 06:38:31,771 TRACE MercuryClient:140 - Send Mercury request, seq: 1, uri: hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=[My Device ID], method: GET
2020-12-29 06:38:31,773 TRACE MercuryClient:140 - Send Mercury request, seq: 2, uri: hm://event-service/v1/events, method: POST
2020-12-29 06:38:31,842 INFO Session:1363 - Skipping UnknownData_AllZeros
2020-12-29 06:38:31,842 TRACE MercuryClient:183 - Handling packet, cmd: MercuryEvent, seq: -5361727770919436288, flags: 1, parts: 1
2020-12-29 06:38:31,843 DEBUG MercuryClient:218 - Couldn't dispatch Mercury event {seq: -5361727770919436288, uri: hm://pusher/v1/connections/MjZjMTk0NDY5YzdmZWZhOWFjMGUzY2EzOThlODI1MzQ0NzQ3ZjRhZStBUCt0Y3A6Ly9nYWUyLWFjY2Vzc3BvaW50LWItejYyMi5nYWUyLnNwb3RpZnkubmV0OjUwMTMrRjRFNzJBNUNDRkNBMDY5OEJFNEY2MUIxRTVBMzk5MENDMzkwRDdEQ0FCMUVBMDMzQzQyQjE2QzE3QzQ4NTRGMg%3D%3D, code: 200, payload: []}
2020-12-29 06:38:32,016 DEBUG Session:1339 - Received 0x10: A36016156F5ACEB1712DBC439160B46E976E1F49
2020-12-29 06:38:32,016 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 2, flags: 1, parts: 1
2020-12-29 06:38:32,016 DEBUG EventService:35 - Event sent. {body: 812|1|en, result: 200}
2020-12-29 06:38:32,232 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 1, flags: 1, parts: 2
2020-12-29 06:38:32,232 INFO Session:1290 - Skipping unknown command {cmd: 0x75, payload: 000000}
2020-12-29 06:38:32,234 DEBUG TokenProvider:55 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQCYhh...KoLSx0', scopes=[playlist-read], timestamp=1609184312846}}
2020-12-29 06:38:32,272 INFO Session:342 - Authenticated as benturnberg!
2020-12-29 06:38:32,291 WARN FileConfiguration:207 - Please update the `player.preferredAudioQuality` option to either `NORMAL`, `HIGH` or `VERY_HIGH`.
2020-12-29 06:38:32,418 INFO CacheManager:80 - There are 196 cached entries.
2020-12-29 06:38:32,434 TRACE AsyncProcessor:36 - AsyncProcessor{put-state-worker} has started
2020-12-29 06:38:33,116 DEBUG DealerClient:331 - Dealer connected! {host: guc-dealer.spotify.com}
2020-12-29 06:38:33,121 DEBUG DeviceStateHandler:135 - Updated Spotify-Connection-Id: MjZjMTk0NDY5YzdmZWZhOWFjMGUzY2EzOThlODI1MzQ0NzQ3ZjRhZStkZWFsZXIrdGNwOi8vZ3VjMy1kZWFsZXItYi1uemtjLmd1YzMuc3BvdGlmeS5uZXQ6NTcwMCtCNkIzNThCNTVBN0E0NDg0OTE4MzZCRTA3MTlFQjhFMjcyOTBERTEwMDZERkIxRjYwQUFFQ0ZFREJBMUNENTMy
2020-12-29 06:38:33,131 INFO StateWrapper:301 - Notified new device (us)!
2020-12-29 06:38:33,796 INFO DeviceStateHandler:249 - Put state. {ts: 1609184313740, connId: MjZjM...ENTMy, reason: NEW_DEVICE, request: device { device_info { can_play: true volume: 65536 name: "[My Alias]" capabilities { can_be_player: true gaia_eq_connect_id: true supports_logout: true is_observable: true volume_steps: 64 supported_types: "audio/episode" supported_types: "audio/track" command_acks: true supports_playlist_v2: true is_controllable: true supports_transfer_command: true supports_command_request: true supports_gzip_pushes: true } device_software_version: "librespot-java 1.5.3-SNAPSHOT" device_type: COMPUTER spirc_version: "3.2.6" device_id: "[My Device ID]" } player_state { context_restrictions { } playback_speed: 1.0 position_as_of_timestamp: 0 is_system_initiated: true options { shuffling_context: false repeating_context: false repeating_track: false } suppressions { } } } member_type: CONNECT_STATE put_state_reason: NEW_DEVICE has_been_playing_for_ms: 0 client_side_timestamp: 1609184313740}
2020-12-29 06:38:36,268 TRACE DealerClient:97 - Received request. {mid: hm://connect-state/v1/player/command, key: f7c25e66-0bc2-4140-87ab-5ccd74d1b87e, pid: 719062820, sender: [Sender ID], command: {"endpoint":"transfer","data":"CgYIABAAGAASxggIktCSvuouEMtOGQAAAAAAAPA/IAAqrggKABIjN0lKc1hhd3NGcldVN0tDNEtyN2xReTE2MDkxMDU2ODY4NTgaEP20Uu7AwUhMswwYAgTSRsYiHAoUbWVkaWEuc3RhcnRfcG9zaXRpb24SBDk5NzQiEAoKcG9wdWxhcml0eRICNDIiMwoKYXJ0aXN0X3VyaRIlc3BvdGlmeTphcnRpc3Q6MExWclFVaW5QVUJGdlZENXBMcW1XWSIOCglpdGVyYXRpb24SATAiFQoMdHJhY2tfcGxheWVyEgVhdWRpbyI5ChBhbGJ1bV9hcnRpc3RfdXJpEiVzcG90aWZ5OmFydGlzdDowTFZyUVVpblBVQkZ2VkQ1cExxbVdZIhYKEWFsYnVtX2Rpc2NfbnVtYmVyEgExIg8KBXRpdGxlEgZEYXJrZXIiSQoPaW1hZ2VfbGFyZ2VfdXJsEjZzcG90aWZ5OmltYWdlOmFiNjc2MTZkMDAwMGIyNzMyMzI3NmUwNDlkMzBjNjI2ZTk2NTEzMmMiFAoLYXJ0aXN0X25hbWUSBURvdmVzIlYKFmF2YWlsYWJsZV9maWxlX2Zvcm1hdHMSPFsiT0dHX1ZPUkJJU18zMjAiLCJPR0dfVk9SQklTXzE2MCIsIk9HR19WT1JCSVNfOTYiLCJBQUNfMjQiXSIfCg5wcm9tb3Rpb25fdHlwZRINYXV0b19mZWF0dXJlZCI7Cgtjb250ZXh0X3VyaRIsc3BvdGlmeTpzdGF0aW9uOmFsYnVtOjZGMnEzZmtRYnNFMnVjejNjQnI1aXoiGQoLYWxidW1fdGl0bGUSCkxvc3QgU2lkZXMiGgoRYWxidW1fYXJ0aXN0X25hbWUSBURvdmVzIioKIGFjdGlvbnMuc2tpcHBpbmdfcHJldl9wYXN0X3RyYWNrEgZyZXN1bWUiMQoJYWxidW1fdXJpEiRzcG90aWZ5OmFsYnVtOjZyNnV6UlBxd0JCcWFqWkgzYUN6elUiQwoJaW1hZ2VfdXJsEjZzcG90aWZ5OmltYWdlOmFiNjc2MTZkMDAwMDFlMDIyMzI3NmUwNDlkMzBjNjI2ZTk2NTEzMmMiSQoPaW1hZ2Vfc21hbGxfdXJsEjZzcG90aWZ5OmltYWdlOmFiNjc2MTZkMDAwMDQ4NTEyMzI3NmUwNDlkMzBjNjI2ZTk2NTEzMmMiEgoIZHVyYXRpb24SBjM1MTY1MyI6CgplbnRpdHlfdXJpEixzcG90aWZ5OnN0YXRpb246YWxidW06NkYycTNma1Fic0UydWN6M2NCcjVpeiIqCiBhY3Rpb25zLnNraXBwaW5nX25leHRfcGFzdF90cmFjaxIGcmVzdW1lIkoKEGltYWdlX3hsYXJnZV91cmwSNnNwb3RpZnk6aW1hZ2U6YWI2NzYxNmQwMDAwYjI3MzIzMjc2ZTA0OWQzMGM2MjZlOTY1MTMyYxrTGgoVCgASABoAIgAqADIAOgdjb25uZWN0Eo4aCixzcG90aWZ5OnN0YXRpb246YWxidW06NkYycTNma1Fic0UydWN6M2NCcjVpehIAGioKE2NvbnRleHRfZGVzY3JpcHRpb24SE1N1cnZpdmluZyB0aGUgUXVpZXQaGgoLZGVzY3JpcHRpb24SC0FMQlVNIFJBRElPGkoKEGltYWdlX3hsYXJnZV91cmwSNnNwb3RpZnk6aW1hZ2U6YWI2NzYxNmQwMDAwYjI3M2E4N2VhMjNlNTY1ZjJiYzg1ZDQxOTI4NyIiQg9lbmRsZXNzX2NvbnRleHRSD2VuZGxlc3NfY29udGV4dCqhGAoAEgAiTQoAEiM3N3g3SnhyNWpkZDVoaEs3YjZQMkVjMTYwOTEwNTY4Njg1OBoQ6f2jJPZUR06QRFciwggP7CISCghkdXJhdGlvbhIGMjg5NjY2Ik0KABIjM0N4b3pNQ1hJMkJCVDU4dVFZWEs3cTE2MDkxMDU2ODY4NTgaEHb+fTJ2v0O1mCzFTl19d2wiEgoIZHVyYXRpb24SBjIyOTEyMCJuCgASIzROVUpqMXpkUXJOdmRIanVBeEgxaXYxNjA5MTA1Njg2ODU4GhCd4T2xV+RPD5gRxtAeB5u3IhIKCGR1cmF0aW9uEgYzMzA3NzMiHwoOcHJvbW90aW9uX3R5cGUSDWF1dG9fZmVhdHVyZWQiTQoAEiMwNXhBU096SHF4cGJIYzY1Q0xYeU9TMTYwOTEwNTY4Njg1OBoQAu/YwcNYQMuW3AbP93kwciISCghkdXJhdGlvbhIGMzY0NzMzIk0KABIjM2JpNkNFSzRCSFZRVWtLcVkwNnU0TjE2MDkxMDU2ODY4NTgaEGiOBfY1l0Tgow/RoC5pKXEiEgoIZHVyYXRpb24SBjMyNDQ1OSJNCgASIzdKUVFLa1V5MDZpUnpFVGNadEpVYXYxNjA5MTA1Njg2ODU4GhD+TCXf6+5LZ4wo++8t0cSzIhIKCGR1cmF0aW9uEgYyMTIzNjAibgoAEiMwNkFsazNVY3ZMMWt1MHpRQjU5R1NlMTYwOTEwNTY4Njg1OBoQA32HcYSbTQ6D6eRYywudsiISCghkdXJhdGlvbhIGMzM4OTMzIh8KDnByb21vdGlvbl90eXBlEg1hdXRvX2ZlYXR1cmVkIm4KABIjNDNuMnI0MHV2dmtjeXhFRTFSSHFocTE2MDkxMDU2ODY4NTgaEIU21ddJ6k4SjkDmzcRLTHgiEgoIZHVyYXRpb24SBjI4MTM2MCIfCg5wcm9tb3Rpb25fdHlwZRINYXV0b19mZWF0dXJlZCJNCgASIzJ6MzdZUXI2dFNaY1NBcHpHWFVVcjAxNjA5MTA1Njg2ODU4GhBUSebjQ7NK45wLBNq9rIBaIhIKCGR1cmF0aW9uEgYyNDAzNzMiTQoAEiM2NGZIcUtSYjc1WFRIRDNaYmVjUUYyMTYwOTEwNTY4Njg1OBoQnsahJIrcRSOFbswSdgbb1iISCghkdXJhdGlvbhIGMjgwNzYwIk0KABIjM25Wcjc1cng0RkZyWEdrdXdVNUNDZzE2MDkxMDU2ODY4NTgaEG9AFvB6RUtioWHVV2+rt7QiEgoIZHVyYXRpb24SBjQxMzQ3NiJNCgASIzVKN2wyd0U5d3hxb2Q3eElQMGp5QUIxNjA5MTA1Njg2ODU4GhC8MdnQEDJK0KBafIf+VEztIhIKCGR1cmF0aW9uEgYyNjQwNjYiTQoAEiM0VVRwSWU2dmV3VzRaaFFxNUVhV0RNMTYwOTEwNTY4Njg1OBoQoZQHyPa1TjOo2ZEtEPjXmiISCghkdXJhdGlvbhIGMjkyNzQ2Ik0KABIjMzdjZ0hGVUFPQThIY3B2Wkpwc2o4ZTE2MDkxMDU2ODY4NTgaEGZilPo8S098rOqJXuPEtxoiEgoIZHVyYXRpb24SBjI2OTQyNiJuCgASIzJKT2k1aTJMbThWQnB4azNJb3lURXIxNjA5MTA1Njg2ODU4GhBZ/cXlDvJHvr4VzrMzpzZXIhIKCGR1cmF0aW9uEgYyNDg5MzMiHwoOcHJvbW90aW9uX3R5cGUSDWF1dG9fZmVhdHVyZWQiTQoAEiM2QzdabzU3S3ZYU01kTVpEVzVmekQ2MTYwOTEwNTY4Njg1OBoQP2My/luhQZms/3Lb+eyFSCISCghkdXJhdGlvbhIGMjUzNDY2IswFCgASIzdJSnNYYXdzRnJXVTdLQzRLcjdsUXkxNjA5MTA1Njg2ODU4GhD9tFLuwMFITLMMGAIE0kbGIhAKCnBvcHVsYXJpdHkSAjQyIjMKCmFydGlzdF91cmkSJXNwb3RpZnk6YXJ0aXN0OjBMVnJRVWluUFVCRnZWRDVwTHFtV1kiOQoQYWxidW1fYXJ0aXN0X3VyaRIlc3BvdGlmeTphcnRpc3Q6MExWclFVaW5QVUJGdlZENXBMcW1XWSIWChFhbGJ1bV9kaXNjX251bWJlchIBMSIPCgV0aXRsZRIGRGFya2VyIhQKC2FydGlzdF9uYW1lEgVEb3ZlcyJJCg9pbWFnZV9sYXJnZV91cmwSNnNwb3RpZnk6aW1hZ2U6YWI2NzYxNmQwMDAwYjI3MzIzMjc2ZTA0OWQzMGM2MjZlOTY1MTMyYyJWChZhdmFpbGFibGVfZmlsZV9mb3JtYXRzEjxbIk9HR19WT1JCSVNfMzIwIiwiT0dHX1ZPUkJJU18xNjAiLCJPR0dfVk9SQklTXzk2IiwiQUFDXzI0Il0iHwoOcHJvbW90aW9uX3R5cGUSDWF1dG9fZmVhdHVyZWQiGQoLYWxidW1fdGl0bGUSCkxvc3QgU2lkZXMiGgoRYWxidW1fYXJ0aXN0X25hbWUSBURvdmVzIjEKCWFsYnVtX3VyaRIkc3BvdGlmeTphbGJ1bTo2cjZ1elJQcXdCQnFhalpIM2FDenpVIkMKCWltYWdlX3VybBI2c3BvdGlmeTppbWFnZTphYjY3NjE2ZDAwMDAxZTAyMjMyNzZlMDQ5ZDMwYzYyNmU5NjUxMzJjIkkKD2ltYWdlX3NtYWxsX3VybBI2c3BvdGlmeTppbWFnZTphYjY3NjE2ZDAwMDA0ODUxMjMyNzZlMDQ5ZDMwYzYyNmU5NjUxMzJjIhIKCGR1cmF0aW9uEgYzNTE2NTMiOQoAEiMzMHZOdHVRamtuQWJpT0IwSVYyS2FBMTYwOTEwNTY4Njg1OBoQYtelEfgzQbeJflGZhk+IyCI5CgASIzBUd0dzZm45eVNVMFJaNVpXVzk3TEExNjA5MTA1Njg2ODU4GhAdbTS892VJGoVfF5x0XeN6IjkKABIjN2VUaU9ybTJScUFQM01QVElENDMyZDE2MDkxMDU2ODY4NTgaEO3j1lr4IUJMsN63B8J1eKUiOQoAEiM2emhrU3Nxc0FQTkdTTEpjd0VIQjVtMTYwOTEwNTY4Njg1OBoQ19ZpaL18Se2CiK7ZlIo6iCI5CgASIzZtQXFLcjhSZEZJa1kzSlZEN0o1RW4xNjA5MTA1Njg2ODU4GhBy6jRgwi1J9J/OuM4rb/jmIjkKABIjNFZJSnR1NTd1cXBOaXNoaEZ5eW54QTE2MDkxMDU2ODY4NTgaEKIEUy+MV046g9f8wkel9y4iOQoAEiM1UFhXSlJYelBFems2RmUwcWdXTlJlMTYwOTEwNTY4Njg1OBoQv9L3/EuwSN64qiQg0PasmCJaCgASIzJKcEFlWmZUb2txakpkMURpNXU1UmExNjA5MTA1Njg2ODU4GhBZx7WaBepBZLu8xnts6EdUIh8KDnByb21vdGlvbl90eXBlEg1hdXRvX2ZlYXR1cmVkIjkKABIjMmFHVnFzcTc0TTloWmtHRHg2S1owVDE2MDkxMDU2ODY4NTgaEEdhT3zKAkOOtqcvzk3nV7siWgoAEiMxQkl3TWdJWmZXZFhGWk5TUG9OdXMyMTYwOTEwNTY4Njg1OBoQNNh4qlCSS+eji3YsUHYl2iIfCg5wcm9tb3Rpb25fdHlwZRINYXV0b19mZWF0dXJlZCJaCgASIzNpdnNCUzJTa282dWRaN0dXYXJEVHUxNjA5MTA1Njg2ODU4GhBsYOorCzFGcKqj5KN9HRqUIh8KDnByb21vdGlvbl90eXBlEg1hdXRvX2ZlYXR1cmVkIjkKABIjMkdwUTd0eFFBRGp6bExIdGxmZXZtRzE2MDkxMDU2ODY4NTgaEFgxRMyJTUafkKUjY8IBZZoiOQoAEiM3Ymw1VnJNVkhheGJPenJvdUlnSFVVMTYwOTEwNTY4Njg1OBoQ7AH7wM1NSmyYhxjF1v3ldCI5CgASIzAxVHhsSXUydlZydFlaN0lzT2lsWHMxNjA5MTA1Njg2ODU4GhABATGesWhDqYEeKJ87r8dKIjkKABIjMkl6a1dHaVlscTJ3N1RpWDJnRHJINTE2MDkxMDU2ODY4NTgaEFlVYmMCbkUKpV2RmqmBSyMoADAAGiM3SUpzWGF3c0ZyV1U3S0M0S3I3bFF5MTYwOTEwNTY4Njg1OCIAKgAyACICEAA=","options":{"restore_paused":"pause","restore_position":"last_known","restore_track":"only_current","license":"premium"},"from_device_identifier":"[Sender ID]"}}
2020-12-29 06:38:36,272 DEBUG Player:293 - Received command: Transfer
2020-12-29 06:38:36,346 DEBUG Player:365 - Loading context (transfer), uri: spotify:station:album:6F2q3fkQbsE2ucz3cBr5iz
2020-12-29 06:38:36,359 DEBUG DeviceStateHandler:198 - Device is now active. {ts: 1609184316971}
2020-12-29 06:38:36,366 TRACE StateWrapper:1084 - Initialized current track index to 16.
2020-12-29 06:38:36,369 DEBUG Player:225 - Loading session, id: SClyGTDzLji2Y5LWZSPgxw, play: true
2020-12-29 06:38:36,374 INFO PlayerSession:53 - Created new session. {id: SClyGTDzLji2Y5LWZSPgxw}
2020-12-29 06:38:36,376 TRACE MercuryClient:140 - Send Mercury request, seq: 3, uri: hm://event-service/v1/events, method: POST
2020-12-29 06:38:36,376 DEBUG Player:253 - Loading track, id: null, session: SClyGTDzLji2Y5LWZSPgxw, playback: null, play: true
2020-12-29 06:38:36,378 ERROR DealerClient:112 - Failed handling request. {key: f7c25e66-0bc2-4140-87ab-5ccd74d1b87e}
java.lang.IllegalStateException: null
at xyz.gianlu.librespot.player.StateWrapper.getCurrentPlayableOrThrow(StateWrapper.java:558) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.Player.loadTrack(Player.java:254) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.Player.loadSession(Player.java:239) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.Player.handleTransferState(Player.java:370) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.Player.command(Player.java:300) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.state.DeviceStateHandler.notifyCommand(DeviceStateHandler.java:110) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.player.state.DeviceStateHandler.onRequest(DeviceStateHandler.java:176) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.dealer.DealerClient.lambda$handleRequest$1(DealerClient.java:107) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.common.AsyncWorker.lambda$new$0(AsyncWorker.java:20) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at xyz.gianlu.librespot.common.AsyncProcessor.lambda$submit$1(AsyncProcessor.java:40) ~[librespot-player-1.5.3-SNAPSHOT.jar:1.5.3-SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
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-12-29 06:38:36,786 TRACE MercuryClient:183 - Handling packet, cmd: MercuryReq, seq: 3, flags: 1, parts: 1