roderickvd
commented
8 months ago Probably regression in dev, many parts of this threading code were touched. I would start with debugging the select! statements to see if there's any branches available in this state.
Describe the bug When transferring playback to librespot, (using rpostify
transfer_playbackmethod with force_play set to true) and when queue is empty, librespot hangs. Whole application which is using tokio also hangs. All tokio tasks are freezed. But when i play some other playlist from other spotify client (on the same device) everything starts to work, including hanging tokio tasks from rest of my app.**Log**
``` 2023-07-26 17:25:28.870 DEBUG [librespot_core::token] new TokenProvider 2023-07-26 17:25:28.870 TRACE [librespot_core::token] Requested token in scopes "user-read-playback-state,user-modify-playback-state,user-read-currently-playing,playlist-read-private" unavailable or expired, requesting new token. 2023-07-26 17:25:28.871 TRACE [librespot_connect::spirc] Received connection ID update: "..." 2023-07-26 17:25:28.960 TRACE [librespot_core::token] Got token: Token { access_token: "...", expires_in: 3600s, token_type: "Bearer", scopes: [ "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "playlist-read-private", ], timestamp: Instant { t: 286398.3243512s, }, } 2023-07-26 17:25:28.962 INFO [rspotify_http::reqwest] Making request RequestBuilder { method: PUT, url: Url { scheme: "https", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("api.spotify.com")), port: None, path: "/v1/me/player", query: None, fragment: None }, headers: {"authorization": "Bearer ...", "content-type": "application/json"} } 2023-07-26 17:25:28.963 DEBUG [reqwest::connect] starting new connection: https://api.spotify.com/ 2023-07-26 17:25:28.968 TRACE [mio::poll] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE 2023-07-26 17:25:29.001 TRACE [librespot_connect::spirc] Received update frame: Frame { ... } 2023-07-26 17:25:29.002 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusStop] 2023-07-26 17:25:29.014 TRACE [librespot_connect::spirc] Received update frame: Frame { ... } 2023-07-26 17:25:29.015 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusStop] 2023-07-26 17:25:29.030 TRACE [librespot_connect::spirc] Received update frame: Frame { ... } 2023-07-26 17:25:29.031 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusStop] 2023-07-26 17:25:29.155 TRACE [want] signal: Want 2023-07-26 17:25:29.155 TRACE [want] signal found waiting giver, notifying 2023-07-26 17:25:29.156 TRACE [want] poll_want: taker wants! 2023-07-26 17:25:29.339 TRACE [mio::poll] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE 2023-07-26 17:25:29.713 TRACE [want] signal: Want 2023-07-26 17:25:29.713 TRACE [want] signal: Want 2023-07-26 17:25:29.744 TRACE [librespot_connect::spirc] Received update frame: Frame { ... } 2023-07-26 17:25:29.745 TRACE [mio::poll] deregistering event source from poller 2023-07-26 17:25:29.751 TRACE [librespot_connect::spirc] State: State { context_uri: Some( "spotify:playlist:5ub9pMNnK8O0XiC6M9dZcO", ), index: Some( 4294967295, ), position_ms: Some( 0, ), status: Some( kPlayStatusPlay, ), position_measured_at: Some( 0, ), context_description: Some( "", ), shuffle: Some( false, ), repeat: Some( false, ), last_command_ident: None, last_command_msgid: None, playing_from_fallback: Some( true, ), row: Some( 0, ), playing_track_index: Some( 0, ), track: [], ad: MessageField( None, ), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: Some( { 29: UnknownValues { fixed32: [], fixed64: [], varint: [ 0, ], length_delimited: [], }, }, ), }, cached_size: CachedSize { size: 0, }, }, } 2023-07-26 17:25:29.751 DEBUG [librespot_playback::player] command=EmitSessionConnectedEvent("...", "2w41y2m4f4xbwt9m8zf5kklyq") 2023-07-26 17:25:29.752 TRACE [want] signal: Closed 2023-07-26 17:25:29.752 DEBUG [librespot_playback::player] command=EmitSessionClientChangedEvent("...", "", "spotify", "PC laptop") 2023-07-26 17:25:29.752 TRACE [librespot_connect::spirc] Frame has 0 tracks 2023-07-26 17:25:29.752 DEBUG [librespot_playback::player] command=EmitVolumeChangedEvent(50) 2023-07-26 17:25:29.752 INFO [unitra_digital_rs::player::spotify_player] Spotify event: SessionConnected { connection_id: "...", user_name: "..." } 2023-07-26 17:25:29.753 INFO [librespot_connect::spirc] No more tracks left in queue 2023-07-26 17:25:29.753 DEBUG [librespot_playback::player] command=EmitAutoPlayChangedEvent(false) 2023-07-26 17:25:29.753 INFO [unitra_digital_rs::player::spotify_player] Spotify event: SessionClientChanged { client_id: "...", client_name: "", client_brand_name: "spotify", client_model_name: "PC laptop" } 2023-07-26 17:25:29.753 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusStop] 2023-07-26 17:25:29.753 DEBUG [librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false) 2023-07-26 17:25:29.754 INFO [unitra_digital_rs::player::spotify_player] Spotify event: VolumeChanged { volume: 50 } 2023-07-26 17:25:29.754 DEBUG [librespot_playback::player] command=EmitShuffleChangedEvent(false) 2023-07-26 17:25:29.754 INFO [unitra_digital_rs::player::spotify_player] Spotify event: AutoPlayChanged { auto_play: false } 2023-07-26 17:25:29.754 DEBUG [librespot_playback::player] command=EmitRepeatChangedEvent(false) 2023-07-26 17:25:29.754 INFO [unitra_digital_rs::player::spotify_player] Spotify event: FilterExplicitContentChanged { filter: false } 2023-07-26 17:25:29.754 DEBUG [librespot_playback::player] command=SetAutoNormaliseAsAlbum(false) 2023-07-26 17:25:29.754 DEBUG [librespot_core::spclient] new SpClient 2023-07-26 17:25:29.755 INFO [unitra_digital_rs::player::spotify_player] Spotify event: ShuffleChanged { shuffle: false } 2023-07-26 17:25:29.755 DEBUG [librespot_playback::player] command=Stop 2023-07-26 17:25:29.755 INFO [librespot_core::spclient] Resolved "gew4-spclient.spotify.com:443" as spclient access point 2023-07-26 17:25:29.755 INFO [unitra_digital_rs::player::spotify_player] Spotify event: RepeatChanged { repeat: false } 2023-07-26 17:25:29.755 TRACE [librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token. 2023-07-26 17:25:29.798 TRACE [librespot_core::token] Got token: Token { access_token: "...", expires_in: 3600s, token_type: "Bearer", scopes: [ "playlist-read", ], timestamp: Instant { t: 286399.1653843s, }, } 2023-07-26 17:25:29.799 DEBUG [librespot_core::spclient] Client token unavailable or expired, requesting new token. 2023-07-26 17:25:29.799 DEBUG [librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken 2023-07-26 17:25:29.801 TRACE [mio::poll] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE 2023-07-26 17:25:29.817 DEBUG [rustls::client::hs] No cached session for DnsName("clienttoken.spotify.com") 2023-07-26 17:25:29.818 DEBUG [rustls::client::hs] Not resuming any session 2023-07-26 17:25:29.858 DEBUG [rustls::client::hs] Using ciphersuite TLS13_AES_256_GCM_SHA384 2023-07-26 17:25:29.859 DEBUG [rustls::client::tls13] Not resuming 2023-07-26 17:25:29.862 DEBUG [rustls::client::tls13] TLS1.3 encrypted extensions: [Protocols([ProtocolName(6832)])] 2023-07-26 17:25:29.863 DEBUG [rustls::client::hs] ALPN protocol is Some(b"h2") 2023-07-26 17:25:29.866 TRACE [want] signal: Want 2023-07-26 17:25:29.867 TRACE [want] signal found waiting giver, notifying 2023-07-26 17:25:29.868 TRACE [want] poll_want: taker wants! 2023-07-26 17:25:29.869 TRACE [want] signal: Want 2023-07-26 17:25:29.943 TRACE [librespot_core::spclient] Got client token: GrantedTokenResponse { token: "...", expires_after_seconds: 1216800, refresh_after_seconds: 1209600, domains: [TokenDomain { domain: "spotify.com", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }, TokenDomain { domain: "spotify.net", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }], special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } } 2023-07-26 17:25:29.943 DEBUG [librespot_core::http_client] Requesting https://gew4-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:playlist:5ub9pMNnK8O0XiC6M9dZcO?autoplay=false&product=0&country=PL&salt=1187217049 2023-07-26 17:25:29.951 TRACE [mio::poll] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE 2023-07-26 17:25:29.967 DEBUG [rustls::client::hs] No cached session for DnsName("gew4-spclient.spotify.com") 2023-07-26 17:25:29.967 DEBUG [rustls::client::hs] Not resuming any session 2023-07-26 17:25:30.005 DEBUG [rustls::client::hs] Using ciphersuite TLS13_AES_256_GCM_SHA384 2023-07-26 17:25:30.006 DEBUG [rustls::client::tls13] Not resuming 2023-07-26 17:25:30.007 DEBUG [rustls::client::tls13] TLS1.3 encrypted extensions: [Protocols([ProtocolName(6832)])] 2023-07-26 17:25:30.008 DEBUG [rustls::client::hs] ALPN protocol is Some(b"h2") 2023-07-26 17:25:30.009 TRACE [want] signal: Want 2023-07-26 17:25:30.010 TRACE [want] signal found waiting giver, notifying 2023-07-26 17:25:30.010 TRACE [want] poll_want: taker wants! 2023-07-26 17:25:30.011 TRACE [want] signal: Want 2023-07-26 17:25:30.559 INFO [librespot_connect::spirc] Resolved 50 tracks from <"spotify:playlist:5ub9pMNnK8O0XiC6M9dZcO"> APP HANGS HERE After playing something in browser client 2023-07-26 17:25:48.376 TRACE [librespot_connect::spirc] Received update frame: Frame { ... } 2023-07-26 17:25:48.591 TRACE [librespot_connect::spirc] State: State { ... } 2023-07-26 17:25:48.593 DEBUG [librespot_playback::player] command=EmitSessionClientChangedEvent("...", "Web Player (Firefox)", "spotify", "web_player") 2023-07-26 17:25:48.594 TRACE [librespot_connect::spirc] Frame has 81 tracks 2023-07-26 17:25:48.594 INFO [unitra_digital_rs::player::spotify_player] Spotify event: SessionClientChanged { client_id: "...", client_name: "Web Player (Firefox)", client_brand_name: "spotify", client_model_name: "web_player" } 2023-07-26 17:25:48.594 DEBUG [librespot_playback::player] command=SetAutoNormaliseAsAlbum(false) 2023-07-26 17:25:48.594 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] 2023-07-26 17:25:48.595 DEBUG [librespot_playback::player] command=Load(SpotifyId("spotify:track:5dk1wOmZVukUhwl5kKr7aS"), true, 0) 2023-07-26 17:25:48.595 INFO [unitra_digital_rs::player::spotify_player] Spotify event: Loading { play_request_id: 0, track_id: SpotifyId("spotify:track:5dk1wOmZVukUhwl5kKr7aS"), position_ms: 0 } 2023-07-26 17:25:48.595 TRACE [librespot_connect::spirc] ==> kPlayStatusPlay 2023-07-26 17:25:48.596 TRACE [librespot_connect::spirc] Sending status to server: [kPlayStatusPlay] 2023-07-26 17:25:48.596 DEBUG [librespot_core::http_client] Requesting https://gew4-spclient.spotify.com:443/metadata/4/track/ab58439402b545f69a4e7904c4087106?product=0&country=PL&salt=3008804426 2023-07-26 17:25:48.597 DEBUG [librespot_core::http_client] Requesting https://gew4-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:playlist:3ge0VgLDkhkJ8P9e0veife?autoplay=false&product=0&country=PL&salt=3264726966 2023-07-26 17:25:48.597 TRACE [want] signal: Want 2023-07-26 17:25:48.598 TRACE [want] signal: Want 2023-07-26 17:25:48.743 TRACE [librespot_metadata] Received metadata: Track { .... } ```Host (what you are running
librespoton):Additional context Maybe something is wrong with how i'm using tokio(i'm new to rust), but until this strange bug everything was working just fine.