ncspot icon indicating copy to clipboard operation
ncspot copied to clipboard
verified publisher icon hrkfdn

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

Open cuboid101 opened this issue 1 year ago • 12 comments

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):

  • OS: Arch Linux
  • Terminal: Kitty
  • master
  • Installed from: AUR

cuboid101 avatar May 28 '24 08:05 cuboid101

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

gfarrell avatar Jul 24 '24 11:07 gfarrell

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

brtholomy avatar Sep 26 '24 22:09 brtholomy

Also happening on Windows 11 via the Terminal.

lukebarone avatar Sep 27 '24 18:09 lukebarone

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.

brtholomy avatar Oct 03 '24 23:10 brtholomy

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.*.

EmilLaursen avatar Oct 26 '24 09:10 EmilLaursen

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.

hrkfdn avatar Oct 26 '24 09:10 hrkfdn

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

EmilLaursen avatar Oct 26 '24 17:10 EmilLaursen

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 avatar Oct 26 '24 22:10 brtholomy

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...

brtholomy avatar Oct 26 '24 22:10 brtholomy

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.

EmilLaursen avatar Nov 01 '24 18:11 EmilLaursen

Hi! Not sure if this is related, but I'm having a similar bug.

I cannot resume when I pause a playback for a long time.

  • OS: Arch Linux
  • Version: ncspot 1.2.1
  • Installed from: Flathub

An easy way to reproduce this is:

  1. Open ncspot
  2. Start a playlist
  3. Pause at some time
  4. Wait for a while (1-2 hours, possibly a suspension)
  5. Try to resume, and the bug will reproduce

I don't have the logs for now, but will post them once the bug is reproduced on a verbose run.

caesarw avatar Dec 23 '24 16:12 caesarw

1.2.0 (a5953d9) seems to have fixed it. thank you for ncspot.

brtholomy avatar Dec 23 '24 20:12 brtholomy