search

hrkfdn / ncspot

Cross-platform ncurses Spotify client written in Rust, inspired by ncmpc and the likes.
BSD 2-Clause "Simplified" License
5.06k stars 211 forks source link

Music being unable to play after ncspot's been open for a certain anount of time. #1461

Open cueboid opened 5 months ago

cueboid commented 5 months ago

Describe the bug After ncspot has been open for a certain amount of time, possibly exceeding 5 hours, any music that I attempt to play will be stuck at 0 seconds. This can be fixed be restarting ncspot.

To Reproduce Wait for possibly over 5 hours.

Expected behavior The music is supposed to play.

System (please complete the following information):

gfarrell commented 3 months ago

I get this all the time. The number of tracks / amount of time seems fairly random, but 100% of the time, within a few hours of playback (sometimes just 20 minutes), ncspot just won't play music and I have to kill it and reopen to get it to work.

Version: 1.1.0 (installed from the AUR) [built 7/3/2024] OS: archlinux Terminal: kitty and alacritty both exhibit this

brtholomy commented 1 month ago

same. unpredictable when, but always does it.

noticed that it won't continue on the same track, but sometimes will restart if a different track is selected.

Version: 1.1.0 via AUR on Arch running in Terminator

lukebarone commented 1 month ago

Also happening on Windows 11 via the Terminal.

brtholomy commented 1 month ago

looking at a recent backtrace, my guess is it's here: https://github.com/hrkfdn/ncspot/blob/main/src/spotify_api.rs#L101

something to do with the token refresh

  11: main
  12: <unknown>
  13: __libc_start_main
  14: <unknown>

panicked at src/spotify_api.rs:101:31:
called `Result::unwrap()` on an `Err` value: SendError { .. }

but this might not be right, since it doesn't actually crash, just freeze.

EmilLaursen commented 1 week ago

Happens consistently, as I let ncspot stay open for days. I managed to get some debug logging of when it happens:

[2024-10-23][05:15:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:17:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:19:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:21:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:23:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:25:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:27:58] [librespot_core::session] [DEBUG] Session[8] strong=3 weak=2
[2024-10-23][05:27:58] [librespot_core::session] [DEBUG] Invalidating session[8]
[2024-10-23][05:27:58] [librespot::component] [DEBUG] new ChannelManager
[2024-10-23][05:27:58] [librespot_core::session] [DEBUG] drop Dispatch
[2024-10-23][05:27:58] [mio::poll] [TRACE] deregistering event source from poller
[2024-10-23][05:27:58] [librespot_core::session] [ERROR] Connection reset by peer (os error 104)
[2024-10-23][05:27:58] [ncspot::spotify_worker] [INFO] Librespot session invalidated, terminating worker
[2024-10-23][05:27:58] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2024-10-23][05:27:58] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2024-10-23][05:27:58] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2024-10-23][05:27:58] [librespot_playback::player] [DEBUG] command=Stop
[2024-10-23][05:27:58] [librespot_playback::player] [DEBUG] drop PlayerInternal[8]
[2024-10-23][05:27:58] [librespot_core::session] [DEBUG] drop Session[8]
[2024-10-23][05:27:58] [librespot::component] [DEBUG] drop ChannelManager
[2024-10-23][05:27:58] [librespot::component] [DEBUG] drop MercuryManager
[2024-10-23][05:27:58] [librespot_playback::player] [DEBUG] PlayerInternal thread finished.
[2024-10-23][05:27:58] [ncspot::application] [TRACE] event received: Stopped
[2024-10-23][05:27:58] [ncspot::spotify] [INFO] Initializing audio backend pulseaudio
[2024-10-23][05:27:58] [rspotify_http::ureq] [INFO] Making request Request(GET https://api.spotify.com/v1/tracks/trololo, [authorization: Bearer XXX])
[2024-10-23][05:27:58] [ncspot::spotify] [DEBUG] opening spotify session
[2024-10-23][05:27:58] [ncspot::spotify] [DEBUG] No HTTP proxy set
[2024-10-23][05:27:58] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-23][05:27:58] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-23][05:27:58] [ureq::stream] [DEBUG] connecting to api.spotify.com:443 at 35.186.224.24:443
[2024-10-23][05:27:58] [mio::poll] [TRACE] registering event source with poller: token=Token(XXX), interests=READABLE | WRITABLE
[2024-10-23][05:27:58] [rustls::client::hs] [DEBUG] Resuming session
[2024-10-23][05:27:58] [rustls::client::hs] [TRACE] Sending ClientHello Message {
    version: TLSv1_0,
    payload: Handshake {
        parsed: HandshakeMessagePayload {
            typ: ClientHello,
            payload: ClientHello(
                ClientHelloPayload {
                    client_version: TLSv1_2,
                    random: XXX,
                    session_id: XXX,
                    cipher_suites: [
                        TLS13_AES_256_GCM_SHA384,
                        TLS13_AES_128_GCM_SHA256,
                        TLS13_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_EMPTY_RENEGOTIATION_INFO_SCSV,
                    ],
                    ...
}
[2024-10-23][05:27:58] [rustls::client::hs] [TRACE] We got ServerHello ServerHelloPayload {
    legacy_version: TLSv1_2,
    random: ,
    session_id: ,
    cipher_suite: TLS13_AES_256_GCM_SHA384,
    compression_method: Null,
    extensions: [
        ...,
        SupportedVersions(
            TLSv1_3,
        ),
    ],
}
[2024-10-23][05:27:58] [rustls::client::hs] [DEBUG] Using ciphersuite TLS13_AES_256_GCM_SHA384
[2024-10-23][05:27:58] [rustls::client::tls13] [DEBUG] Resuming using PSK
[2024-10-23][05:27:58] [rustls::conn] [TRACE] Dropping CCS
[2024-10-23][05:27:58] [rustls::client::tls13] [DEBUG] TLS1.3 encrypted extensions: []
[2024-10-23][05:27:58] [rustls::client::hs] [DEBUG] ALPN protocol is None
[2024-10-23][05:27:58] [ureq::stream] [DEBUG] created stream: Stream(RustlsStream)
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] sending request GET https://api.spotify.com/v1/tracks/trololo?market=from_token
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] writing prelude: GET /v1/tracks/trololo?market=from_token HTTP/1.1
Host: api.spotify.com
User-Agent: ureq/2.9.1
Accept: */*
authorization: ***
[2024-10-23][05:27:58] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:4070
[2024-10-23][05:27:58] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2024-10-23][05:27:58] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2024-10-23][05:27:58] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gue1.spotify.com:4070
[2024-10-23][05:27:58] [librespot_core::session] [INFO] Connecting to AP "ap-gew1.spotify.com:443"
[2024-10-23][05:27:58] [ureq::response] [DEBUG] Body entirely buffered (length: 81)
[2024-10-23][05:27:58] [ureq::pool] [DEBUG] adding stream to pool: https|api.spotify.com|443 -> Stream(RustlsStream)
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] response 401 to GET https://api.spotify.com/v1/tracks/trololo?market=from_token
[2024-10-23][05:27:58] [ncspot::spotify_api] [DEBUG] http error: StatusCode(Response[status: 401, status_text: Unauthorized, url: https://api.spotify.com/v1/tracks/trololo?market=from_token])
[2024-10-23][05:27:58] [ncspot::spotify_api] [DEBUG] token unauthorized. trying refresh..
[2024-10-23][05:27:58] [ncspot::spotify_api] [INFO] Token will expire in -PT1320.806620691S, renewing
[2024-10-23][05:27:58] [rspotify_http::ureq] [INFO] Making request Request(GET https://api.spotify.com/v1/tracks/trololo, [authorization: Bearer XXX])
[2024-10-23][05:27:58] [ureq::pool] [DEBUG] pulling stream from pool: https|api.spotify.com|443 -> Stream(RustlsStream)
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] sending request (reused connection) GET https://api.spotify.com/v1/tracks/trololo?market=from_token
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] writing prelude: GET /v1/tracks/trololo?market=from_token HTTP/1.1
Host: api.spotify.com
User-Agent: ureq/2.9.1
Accept: */*
authorization: ***
[2024-10-23][05:27:58] [ureq::response] [DEBUG] Body entirely buffered (length: 81)
[2024-10-23][05:27:58] [ureq::pool] [DEBUG] adding stream to pool: https|api.spotify.com|443 -> Stream(RustlsStream)
[2024-10-23][05:27:58] [ureq::unit] [DEBUG] response 401 to GET https://api.spotify.com/v1/tracks/trololo?market=from_token
[2024-10-23][05:27:58] [mio::poll] [TRACE] registering event source with poller: token=Token(XXX), interests=READABLE | WRITABLE
[2024-10-23][05:27:58] [mio::poll] [TRACE] deregistering event source from poller
[2024-10-23][05:27:58] [mio::poll] [TRACE] deregistering event source from poller
[2024-10-23][05:27:58] [ncspot::spotify_api] [ERROR] Failed to update token
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:53] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] stop()
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] sending command to worker: Stop
[2024-10-25][19:48:54] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] loading track: Track(Track ...)
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] sending command to worker: Load(Track(Track ...), true, 0)
[2024-10-25][19:48:54] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:54] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:56] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:56] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:48:58] [ncspot::spotify] [INFO] stop()
[2024-10-25][19:48:58] [ncspot::spotify] [INFO] sending command to worker: Stop
[2024-10-25][19:48:58] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:48:58] [ncspot::spotify] [INFO] loading track: Track(Track ...)
[2024-10-25][19:48:58] [ncspot::spotify] [INFO] sending command to worker: Load(Track(Track ...), true, 0)
[2024-10-25][19:48:58] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:48:58] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:48:58] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:49:10] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:49:10] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:49:10] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:49:10] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:49:12] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:49:12] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:49:12] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:49:12] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2024-10-25][19:49:13] [ncspot::spotify] [INFO] stop()
[2024-10-25][19:49:13] [ncspot::spotify] [INFO] sending command to worker: Stop
[2024-10-25][19:49:13] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:49:13] [ncspot::spotify] [INFO] loading track: Track(Track ...)
[2024-10-25][19:49:13] [ncspot::spotify] [INFO] sending command to worker: Load(Track(Track ...), true, 0)
[2024-10-25][19:49:13] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:49:13] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2024-10-25][19:49:13] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished

At first we get Reset By Peer, and player thread shuts down. Refresh is attempted but fails:

[2024-10-23][05:27:58] [ncspot::spotify_api] [ERROR] Failed to update token

I try to play music some time later, but it obviously fails with:

[2024-10-25][19:48:54] [ncspot::spotify] [INFO] stop()
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] sending command to worker: Stop
[2024-10-25][19:48:54] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] loading track: Track(Track ...)
[2024-10-25][19:48:54] [ncspot::spotify] [INFO] sending command to worker: Load(Track(Track ...), true, 0)
[2024-10-25][19:48:54] [ncspot::spotify] [ERROR] can't send command to spotify worker: channel closed, dropping command

This was ncspot 1.1.2 installed using the arch package manager and linux kernel 6.11.*.

hrkfdn commented 1 week ago

Thanks for the logs! It would be interesting to know if the issue persists with 1.2.0 as librespot has improved session handling, I believe.

EmilLaursen commented 1 week ago

I am using ncspot 1.2.0 (bfa5653) now. Will return if I see any issues.

brtholomy commented 1 week ago

Just built 1.2.0. ran with debug output. Looks like same or similar issue. it paused itself:

[2024-10-26][14:48:03] [librespot_core::session] [TRACE] keep-alive state: ExpectingPongAck, timeout in 20.0
[2024-10-26][14:48:03] [librespot_core::session] [TRACE] Received PongAck
[2024-10-26][14:48:03] [librespot_core::session] [TRACE] keep-alive state: ExpectingPing, timeout in 80.0
[2024-10-26][14:48:58] [ncspot::spotify] [INFO] pause()
[2024-10-26][14:48:58] [ncspot::spotify] [INFO] sending command to worker: Pause
[2024-10-26][14:48:58] [librespot_playback::player] [DEBUG] command=Pause
[2024-10-26][14:48:58] [librespot_playback::player] [TRACE] == Stopping sink ==
[2024-10-26][14:49:37] [ncspot::application] [TRACE] event received: Paused(334.641s)
[2024-10-26][14:49:37] [ncspot::spotify] [DEBUG] Sending mpris command: EmitPlaybackStatus
[2024-10-26][14:49:55] [librespot_core::session] [DEBUG] Shutdown: Invalidating session
[2024-10-26][14:49:55] [librespot::component] [DEBUG] new ChannelManager
[2024-10-26][14:49:55] [librespot_core::session] [DEBUG] drop Dispatch
[2024-10-26][14:49:55] [ncspot::spotify_worker] [INFO] Librespot session invalidated, terminating worker
[2024-10-26][14:49:55] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2024-10-26][14:49:55] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2024-10-26][14:49:55] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2024-10-26][14:49:55] [librespot_playback::player] [DEBUG] command=Stop
brtholomy commented 1 week ago

i'm not a network guy, but i wonder if a renewed DHCP lease might interfere with the pinging. i'm on Starlink, and the lease is only 5 minutes. journalctl says it renewed at exactly the same time as that pause:

Oct 26 14:48:58 box systemd[1]: Started Network Manager Script Dispatcher Service.
Oct 26 14:48:58 box systemd[1]: Starting Network Manager Script Dispatcher Service...
EmilLaursen commented 1 week ago

I am using ncspot 1.2.0 (bfa5653) now. Will return if I see any issues.

FWIW, I have not experienced any issues after moving to 1.2.0. Thank you for ncspot.