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.

Sign up for GitHub

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

Jump to bottom

Librespot hangs application on empty queue #1192

Open
dzubybb opened this issue Jul 26, 2023 · 1 comment
Open

Librespot hangs application on empty queue #1192

dzubybb opened this issue Jul 26, 2023 · 1 comment
Labels
bug

Comments

@dzubybb
Copy link

dzubybb commented Jul 26, 2023 •
edited
Loading

Describe the bug
When transferring playback to librespot, (using rpostify transfer_playback method 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 librespot on):

  • OS: windows

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.
@dzubybb dzubybb added the bug label Jul 26, 2023
@roderickvd
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@roderickvd @dzubybb