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

Playback stops 30 seconds before the song ends, every half an hour

Open ethanredmond2 opened this issue 2 years ago • 13 comments

Describe the bug About every half an hour, playback stops exactly 30 seconds before the song ends. This happens regardless of the song or playlist. Pressing play/pause doesn't update the play icon, scrubbing left and right doesn't make audio play. Skipping to the next song plays the next song fine.

This has happened consistently many times a day, over the last month.

To Reproduce Play any playlist. About half an hour in, playback stops 30 seconds before the song ends.

Expected behavior Playback should continue to the end of the song.

Screenshots

Playback stopped

System (please complete the following information):

  • OS: Ubuntu 20.04, I've had colleagues report the same problem on Ubuntu 22.04
  • Terminal: GNOME Terminal
  • Version: ncspot 0.12.0
  • Installed from: https://github.com/hrkfdn/ncspot/releases/tag/v0.12.0

Additional context I never had this problem with ncspot when I was in the UK or when I was in Auckland, New Zealand. This problem started happening after I moved to Christchurch, New Zealand.

I recognize this will be a difficult bug to fix because it's so obscure, let me know if there's anything I can do to help. I've included my config.toml file here in case that's useful: config.txt

P.S. I much prefer ncspot as an alternative to the spammy official Spotify client. Ncspot's less distracting, less of a product, and more of a tool. It's a music player, not a music discoverer. It's exactly what I need as a developer, which is why I love it :heart:

ethanredmond2 avatar Feb 20 '23 01:02 ethanredmond2

I've noticed the same thing. I don't think this is dependent on the OS or terminal as mine are very different from the ones in the original issue. I use ncspot in very different environments (at campus with VPN, at campus without VPN, at home with VPN and at home without VPN) and this happens across all of them as far as I remember.

For me, it's not as consistent. It surely doesn't happen every half an hour. More like every 2 to 3 hours. I do think it happens around the 30 second mark as well. I can also confirm that nothing can start the playback again (scrolling the slider, play/pause).

I only just now realized that I've had shuffle disabled for the last few days and this issue hasn't really happened during that time. I wouldn't say I'm a 100% sure it is triggered by enabling shuffle, but it's the only thing that I can think of that changed over the last few days. Maybe @ethanredmond2 can confirm if their shuffle is on/off most of the time or while this happened? From the consistent 30 second time before the end, I would suspect that is could have to do with the preloading not working correctly when the playback is shuffled? This is just a wild guess...

System:

  • OS: Arch Linux (latest updates)
  • Terminal: Alacritty
  • version: 0.12.0
  • Installed from: Arch community repository

ThomasFrans avatar Feb 22 '23 20:02 ThomasFrans

(It's definitely a preloading issue :smile:)

From the librespot Player code:

const PRELOAD_NEXT_TRACK_BEFORE_END_DURATION_MS: u32 = 30000;

ThomasFrans avatar Feb 22 '23 20:02 ThomasFrans

Hey Thomas, it's good to know it happens for someone else too! I always have shuffle on so it definitely could be that, I even put it in my config.toml! I'll try turning it off for today and post back here if playback stops less. I also always have repeat on, often listening to the same playlist for hours.

Well spotted on the preloading! That does look like it could be the culprit! :laughing:

I have slightly more scientific results after some testing. I put a 4 hour long playlist on shuffle and got these times by taking a screenshot every time playback stopped, so I could calculate the time between stops:

10:07 / 10:07 am - stopped 10:40 / 10:40 am - stopped - 33 mins since last stop

(took a break)

15:04 / 3:04 pm - stopped 15:37 / 3:37 pm - stopped - 33 mins since last stop 16:13 / 4:13 pm - stopped - 36 mins since last stop

(took a break)

17:25 / 5:25 pm - stopped 18:00 / 6:00 pm - stopped - 35 mins since last stop 18:34 / 6:34 pm - stopped - 34 mins since last stop

image

Something that might affect the frequency of stops could be the playlist length? For example, if it preloads the next ten songs, plays through them and then stops, that would be roughly 30 mins. In that case, it should only happen for playlists longer than ten songs. It's just a wild theory but I'll try listening to a short playlist on shuffle to confirm if that's the case.

Thank you for helping! Let me know your thoughts :)

ethanredmond2 avatar Feb 23 '23 00:02 ethanredmond2

(Oops, didn't think "Close with comment" was a button :laughing: )

Ok, so I've done some more tests, first I tried playing a playlist with 5 songs on shuffle, and recorded these stop times:

15:06 / 3:06 pm - stopped 15:45 / 3:45 pm - stopped - 39 mins since last stop 16:22 / 4:22 pm - stopped - I paused ncspot, then played it 16:55 / 4:55 pm - stopped - 33 mins since last started 17:27 / 5:27 pm - stopped - 32 mins since last stop

I think ncspot has to be continuously playing for about half an hour to reproduce this bug, it doesn't seem to happen in the hours that I'm playing and pausing my music.

It also looks like the number of songs in the playlist doesn't make a difference to playback stopping.

Next I tried playing a playlist where each song is less than a minute long to see if it stops after 5 minutes instead of 30 minutes. I played Eluvium's Shuffle Drone album, each song is about 32 seconds long. Interestingly, it never stopped over a period of two hours playing continuously.

Finally, I played a playlist with shuffle turned off, but ncspot still stopped, although it seemed to stop a bit less:

12:53 / 12:53 pm - start 13:56 / 1:56 pm - stopped - 63 mins since started 14:32 / 2:32 pm - stopped - 36 mins since last stop 15:49 / 3:49 pm - stopped - 77 mins since last stop 16:19 / 4:19 pm - stopped - 30 mins since last stop

ethanredmond2 avatar Feb 24 '23 07:02 ethanredmond2

Just had this happen again, and I noticed that when the screen refreshes, the duration in the statusbar is still updated. The songs also don't go to the next one anymore. Instead, the song keeps playing past its duration (so it shows 3:20/2:56 and so on for example). And again it happened at exactly 30 seconds before the end of the song.

ThomasFrans avatar Mar 01 '23 17:03 ThomasFrans

I can confirm this issue too. Sometimes I can have music playing for several hours and then the song might stop playing before the end and other times the seconds keep counting up even past the song's actual duration

Bettehem avatar Mar 02 '23 05:03 Bettehem

Thanks to everyone for investigating this. Does anyone happen to have some logs while this is happening? They could give an indication on whether it's happening during track preload, an expired Spotify session, etc.

hrkfdn avatar Mar 02 '23 10:03 hrkfdn

I followed the steps in the readme to write logs to a debug.log file, then played a playlist (not on shuffle) and waited for playback to stop.

Playback stopped 30s before a song ends just like before, I've included the part I thought was most relevant, let me know if you want to see the whole log:

...
[2023-03-03][12:21:00] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 193, y: 54 }, text="9", style=Style { effects: EnumSet(), color_pair: ColorPair { front: Rgb(241, 241, 241), back: Rgb(0, 0, 0) } }
[2023-03-03][12:21:00] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 193, y: 54 }, text="9", style=Style { effects: EnumSet(), color_pair: ColorPair { front: Rgb(241, 241, 241), back: Rgb(0, 0, 0) } }
[2023-03-03][12:21:00] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 193, y: 54 }, text="9", style=Style { effects: EnumSet(), color_pair: ColorPair { front: Rgb(241, 241, 241), back: Rgb(0, 0, 0) } }
[2023-03-03][12:21:00] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 193, y: 54 }, text="9", style=Style { effects: EnumSet(), color_pair: ColorPair { front: Rgb(241, 241, 241), back: Rgb(0, 0, 0) } }
[2023-03-03][12:21:00] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:21:00] [ncspot::queue] [DEBUG] Preloading track Great Good Fine Ok - Take It or Leave It as requested by librespot
[2023-03-03][12:21:00] [ncspot::spotify_worker] [DEBUG] Preloading SpotifyId { id: 74454823551350006965678659091191506281, audio_type: Track }
[2023-03-03][12:21:00] [librespot_playback::player] [DEBUG] command=Preload(SpotifyId { id: 74454823551350006965678659091191506281, audio_type: Track })
[2023-03-03][12:21:00] [librespot_playback::player] [DEBUG] Preloading track
[2023-03-03][12:21:00] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:21:00] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:21:00] [librespot_core::session] [DEBUG] Invalidating session[1]
[2023-03-03][12:21:00] [librespot_playback::player] [ERROR] Unable to load audio item: MercuryError
[2023-03-03][12:21:00] [librespot_playback::player] [DEBUG] drop PlayerInternal[1]
[2023-03-03][12:21:00] [ncspot::spotify_worker] [WARN] Librespot player event channel died, terminating worker
[2023-03-03][12:21:00] [librespot_playback::player] [DEBUG] PlayerInternal thread finished.
[2023-03-03][12:21:00] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2023-03-03][12:21:00] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2023-03-03][12:21:00] [librespot_playback::player] [ERROR] Player Commands Error: channel closed
[2023-03-03][12:21:00] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2023-03-03][12:21:00] [librespot_core::session] [DEBUG] drop Session[1]
[2023-03-03][12:21:00] [librespot::component] [DEBUG] drop AudioKeyManager
[2023-03-03][12:21:00] [librespot::component] [DEBUG] drop ChannelManager
[2023-03-03][12:21:00] [librespot::component] [DEBUG] drop MercuryManager
[2023-03-03][12:21:00] [librespot_core::session] [DEBUG] drop Dispatch
[2023-03-03][12:21:00] [mio::poll] [TRACE] deregistering event source from poller
[2023-03-03][12:21:00] [librespot_core::session] [ERROR] Connection reset by peer (os error 104)
[2023-03-03][12:21:00] [ncspot::spotify] [DEBUG] opening spotify session
[2023-03-03][12:21:00] [ncspot::spotify] [DEBUG] No HTTP proxy set
[2023-03-03][12:21:00] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:21:00] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:21:00] [mio::poll] [TRACE] registering event source with poller: token=Token(16777217), interests=READABLE | WRITABLE
[2023-03-03][12:21:00] [want] [TRACE] signal: Want
[2023-03-03][12:21:00] [want] [TRACE] signal found waiting giver, notifying
[2023-03-03][12:21:00] [want] [TRACE] poll_want: taker wants!
[2023-03-03][12:21:00] [want] [TRACE] signal: Want
[2023-03-03][12:21:00] [want] [TRACE] signal: Want
[2023-03-03][12:21:00] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gue1.spotify.com:4070
[2023-03-03][12:21:00] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2023-03-03][12:21:00] [librespot_core::session] [INFO] Connecting to AP "ap-gae2.spotify.com:4070"
[2023-03-03][12:21:00] [mio::poll] [TRACE] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
[2023-03-03][12:21:00] [mio::poll] [TRACE] deregistering event source from poller
[2023-03-03][12:21:00] [want] [TRACE] signal: Closed
[2023-03-03][12:21:01] [librespot_core::session] [INFO] Authenticated as "***************" !
[2023-03-03][12:21:01] [librespot_core::session] [DEBUG] new Session[2]
[2023-03-03][12:21:01] [librespot_playback::mixer::softmixer] [INFO] Mixing with softvol and volume control: Log(60.0)
[2023-03-03][12:21:01] [librespot_playback::mixer::mappings] [DEBUG] Input volume 58985 mapped to: 50.14%
[2023-03-03][12:21:01] [ncspot::spotify] [INFO] Initializing audio backend pulseaudio
[2023-03-03][12:21:01] [ncspot::spotify] [DEBUG] worker thread ready.
[2023-03-03][12:21:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1
[2023-03-03][12:21:01] [librespot_playback::player] [DEBUG] new Player[2]
[2023-03-03][12:21:01] [librespot_playback::convert] [INFO] Converting with ditherer: tpdf
[2023-03-03][12:21:01] [librespot_playback::audio_backend::pulseaudio] [INFO] Using PulseAudioSink with format: S16
[2023-03-03][12:21:01] [librespot_core::session] [INFO] Country: "NZ"
[2023-03-03][12:23:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1
[2023-03-03][12:25:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1
[2023-03-03][12:27:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1

There's no more output to the log file from here, other than Session[2] strong=3 weak=1 every two minutes. Nothing plays from ncspot either.

If I press R to refresh the screen, it updates the time in the corner to 10:40 / 3:09 as mentioned by others above and outputs this to the log file:

[2023-03-03][12:27:28] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 185, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 185, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 190, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [TRACE] output_to_backend: pos=XY { x: 192, y: 54 }, t>
[2023-03-03][12:27:28] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished

image

After skipping to the next song by pressing Shift+>, I got this output in the logs:

[2023-03-03][12:31:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1
[2023-03-03][12:33:01] [librespot_core::session] [DEBUG] Session[2] strong=3 weak=1
[2023-03-03][12:34:23] [ncspot::spotify] [INFO] loading track: Track((Great Good Fine Ok - Take It or Leave It (Some("1HH9T6jsitwm9Cvs9jUeTf"))))
[2023-03-03][12:34:23] [ncspot::spotify_worker] [INFO] player loading track: SpotifyId { id: 74454823551350006965678659091191506281, audio_type: Track }
[2023-03-03][12:34:23] [librespot_playback::player] [DEBUG] command=Load(SpotifyId { id: 74454823551350006965678659091191506281, audio_type: Track }, true, 0)
[2023-03-03][12:34:23] [librespot::component] [DEBUG] new MercuryManager
[2023-03-03][12:34:23] [cursive_buffered_backend] [DEBUG] output_all_to_backend started

... bunch of output_to_backend lines ...

[2023-03-03][12:34:24] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:34:24] [librespot_playback::player] [INFO] Loading <Take It or Leave It> with Spotify URI <spotify:track:1HH9T6jsitwm9Cvs9jUeTf>
[2023-03-03][12:34:24] [librespot_audio::fetch] [DEBUG] Downloading file 380dc72e56d55b291e8e4a997d6476efa474156a
[2023-03-03][12:34:24] [librespot::component] [DEBUG] new ChannelManager
[2023-03-03][12:34:24] [librespot::component] [DEBUG] new AudioKeyManager
[2023-03-03][12:34:25] [librespot_playback::player] [INFO] <Take It or Leave It> (183468 ms) loaded
[2023-03-03][12:34:25] [librespot_playback::player] [TRACE] == Starting sink ==
[2023-03-03][12:34:25] [ncspot] [TRACE] event received: Playing(SystemTime { tv_sec: 1677800065, tv_nsec: 23031502 })
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:34:25] [ncspot::mpris] [DEBUG] mpris PropertiesChanged: status Playing, track: Some(Track((Great Good Fine Ok - Take It or Leave It (Some("1HH9T6jsitwm9Cvs9jUeTf")))))
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][12:34:25] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][12:34:26] [cursive_buffered_backend] [DEBUG] output_all_to_backend started

About 30 minutes later the bug happened again, playback stopped 30s before the end of the song. I got this in the debug.log file:

[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][13:00:57] [ncspot::queue] [DEBUG] Preloading track Bleachers - Rollercoaster as requested by librespot
[2023-03-03][13:00:57] [ncspot::spotify_worker] [DEBUG] Preloading SpotifyId { id: 251582428402559328267279685788408402749, audio_type: Track }
[2023-03-03][13:00:57] [librespot_playback::player] [DEBUG] command=Preload(SpotifyId { id: 251582428402559328267279685788408402749, audio_type: Track })
[2023-03-03][13:00:57] [librespot_playback::player] [DEBUG] Preloading track
[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend started

... bunch of output_to_backend lines ...

[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][13:00:57] [librespot_core::session] [DEBUG] Invalidating session[2]
[2023-03-03][13:00:57] [librespot_core::session] [DEBUG] drop Dispatch
[2023-03-03][13:00:57] [mio::poll] [TRACE] deregistering event source from poller
[2023-03-03][13:00:57] [librespot_core::session] [ERROR] Connection reset by peer (os error 104)
[2023-03-03][13:00:57] [librespot_playback::player] [ERROR] Unable to load audio item: MercuryError
[2023-03-03][13:00:57] [librespot_playback::player] [DEBUG] drop PlayerInternal[2]
[2023-03-03][13:00:57] [ncspot::spotify_worker] [WARN] Librespot player event channel died, terminating worker
[2023-03-03][13:00:57] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2023-03-03][13:00:57] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2023-03-03][13:00:57] [librespot_playback::player] [ERROR] Player Commands Error: channel closed
[2023-03-03][13:00:57] [librespot_core::session] [DEBUG] drop Session[2]
[2023-03-03][13:00:57] [librespot::component] [DEBUG] drop AudioKeyManager
[2023-03-03][13:00:57] [librespot::component] [DEBUG] drop ChannelManager
[2023-03-03][13:00:57] [librespot::component] [DEBUG] drop MercuryManager
[2023-03-03][13:00:57] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2023-03-03][13:00:57] [librespot_playback::player] [DEBUG] PlayerInternal thread finished.
[2023-03-03][13:00:57] [ncspot::spotify] [DEBUG] opening spotify session
[2023-03-03][13:00:57] [ncspot::spotify] [DEBUG] No HTTP proxy set
[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend started
[2023-03-03][13:00:57] [cursive_buffered_backend] [DEBUG] output_all_to_backend finished
[2023-03-03][13:00:57] [mio::poll] [TRACE] registering event source with poller: token=Token(16777218), interests=READABLE | WRITABLE
[2023-03-03][13:00:57] [want] [TRACE] signal: Want
[2023-03-03][13:00:57] [want] [TRACE] signal found waiting giver, notifying
[2023-03-03][13:00:57] [want] [TRACE] poll_want: taker wants!
[2023-03-03][13:00:57] [want] [TRACE] signal: Want
[2023-03-03][13:00:57] [want] [TRACE] signal: Want
[2023-03-03][13:00:57] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gue1.spotify.com:443
[2023-03-03][13:00:57] [librespot_core::session] [INFO] Connecting to AP "ap-gae2.spotify.com:4070"
[2023-03-03][13:00:57] [mio::poll] [TRACE] registering event source with poller: token=Token(33554433), interests=READABLE | WRITABLE
[2023-03-03][13:00:57] [mio::poll] [TRACE] deregistering event source from poller
[2023-03-03][13:00:57] [want] [TRACE] signal: Closed
[2023-03-03][13:00:58] [librespot_core::session] [INFO] Authenticated as "******************" !
[2023-03-03][13:00:58] [librespot_core::session] [DEBUG] new Session[3]
[2023-03-03][13:00:58] [librespot_playback::mixer::softmixer] [INFO] Mixing with softvol and volume control: Log(60.0)
[2023-03-03][13:00:58] [librespot_playback::mixer::mappings] [DEBUG] Input volume 58985 mapped to: 50.14%
[2023-03-03][13:00:58] [ncspot::spotify] [INFO] Initializing audio backend pulseaudio
[2023-03-03][13:00:58] [ncspot::spotify] [DEBUG] worker thread ready.
[2023-03-03][13:00:58] [librespot_core::session] [DEBUG] Session[3] strong=3 weak=1
[2023-03-03][13:00:58] [librespot_playback::player] [DEBUG] new Player[3]
[2023-03-03][13:00:58] [librespot_playback::convert] [INFO] Converting with ditherer: tpdf
[2023-03-03][13:00:58] [librespot_playback::audio_backend::pulseaudio] [INFO] Using PulseAudioSink with format: S16
[2023-03-03][13:00:58] [librespot_core::session] [INFO] Country: "NZ"

ethanredmond2 avatar Mar 02 '23 23:03 ethanredmond2

Hello, this has still been happening consistently on 0.13.0, I just wanted to ask if there's been any progress or if it's not possible for it to be fixed.

Alternatively, is there anything I can do to try fixing it myself? I haven't worked with rust before but I could give it a go.

ethanredmond2 avatar May 16 '23 05:05 ethanredmond2

I am still experiencing this issue but for me it seemingly happens so inconsistently and rarely that I might not be able to help with this much :/ From what I've learned, pull requests are always welcome so if you have the time, you could try fixing it yourself too :)

Bettehem avatar May 16 '23 09:05 Bettehem

Just in case if somebody wonders about prevalence of this bug: today I encountered it like 15 times in a row. Annoying as hell.

This is my log. It indicates clearly that it's related to preloading next track. I compiled ncspot from commit ff01074666ef749a4a3b1643b8ff36c278281f10.

[2023-06-24][20:57:34] [ncspot::queue] [DEBUG] Preloading track Skalpel - High as requested by librespot
[2023-06-24][20:57:34] [ncspot::spotify_worker] [DEBUG] Preloading SpotifyId { id: 21709308172842466444649610959641113790
, audio_type: Track }
[2023-06-24][20:57:34] [librespot_playback::player] [DEBUG] command=Preload(SpotifyId { id: 21709308172842466444649610959
641113790, audio_type: Track })
[2023-06-24][20:57:34] [librespot_playback::player] [DEBUG] Preloading track
[2023-06-24][20:57:34] [librespot_core::session] [DEBUG] Invalidating session[1]
[2023-06-24][20:57:34] [librespot_playback::player] [ERROR] Unable to load audio item: MercuryError
[2023-06-24][20:57:34] [librespot_core::session] [DEBUG] drop Dispatch
[2023-06-24][20:57:34] [mio::poll] [TRACE] deregistering event source from poller
[2023-06-24][20:57:34] [librespot_core::session] [ERROR] Connection reset by peer (os error 104)
[2023-06-24][20:57:34] [librespot_playback::player] [DEBUG] drop PlayerInternal[1]
[2023-06-24][20:57:34] [librespot_playback::player] [DEBUG] PlayerInternal thread finished.
[2023-06-24][20:57:34] [ncspot::spotify_worker] [WARN] Librespot player event channel died, terminating worker
[2023-06-24][20:57:34] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2023-06-24][20:57:34] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2023-06-24][20:57:34] [librespot_playback::player] [ERROR] Player Commands Error: channel closed
[2023-06-24][20:57:34] [librespot_core::session] [DEBUG] drop Session[1]
[2023-06-24][20:57:34] [librespot::component] [DEBUG] drop AudioKeyManager
[2023-06-24][20:57:34] [librespot::component] [DEBUG] drop ChannelManager
[2023-06-24][20:57:34] [librespot::component] [DEBUG] drop MercuryManager
[2023-06-24][20:57:34] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2023-06-24][20:57:34] [ncspot::spotify] [DEBUG] opening spotify session
[2023-06-24][20:57:34] [ncspot::spotify] [DEBUG] No HTTP proxy set
[2023-06-24][20:57:34] [mio::poll] [TRACE] registering event source with poller: token=Token(16777217), interests=READABL
E | WRITABLE
[2023-06-24][20:57:34] [want] [TRACE] signal: Want
[2023-06-24][20:57:34] [want] [TRACE] signal found waiting giver, notifying
[2023-06-24][20:57:34] [want] [TRACE] poll_want: taker wants!
[2023-06-24][20:57:34] [want] [TRACE] signal: Want
[2023-06-24][20:57:34] [want] [TRACE] signal: Want
[2023-06-24][20:57:34] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:4070
[2023-06-24][20:57:34] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2023-06-24][20:57:34] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2023-06-24][20:57:34] [librespot_core::apresolve] [WARN] Ignoring blacklisted access point ap-gue1.spotify.com:80
[2023-06-24][20:57:34] [librespot_core::session] [INFO] Connecting to AP "ap-gew1.spotify.com:4070"
[2023-06-24][20:57:44] [mio::poll] [TRACE] deregistering event source from poller
[2023-06-24][20:57:44] [want] [TRACE] signal: Closed
[2023-06-24][21:05:08] [ncspot::ui::listview] [DEBUG] releasing scroller
[2023-06-24][21:05:09] [ncspot::spotify] [INFO] stop()

But it seems like upstream won't do anything soon about that: https://github.com/librespot-org/librespot/issues/1151

zborro avatar Jun 24 '23 19:06 zborro

I am using this dirty bash code with ncspot -d /tmp/ncspot.debug to get around this problem and the problem of disconnecting after a song ends:

DEBUG_FILE="/tmp/ncspot.debug"
SOCKET_PATH="/home/$USER/.cache/ncspot/ncspot.sock"
              
wait_for_files() {
  while [ ! -S "$SOCKET_PATH" ] || [ ! -f "$DEBUG_FILE" ]; do
    sleep 1
  done
}
              
check_debug_file() {
  local time prevtime
  time=$(date +"%H:%M")
  prevtime=$(date -d "-1 minute" +"%H:%M")
              
  grep -E "$prevtime|$time" "$DEBUG_FILE" |
    grep -q '\[ERROR\] Connection reset by peer (os error 104)'
}
              
send_command() {
  echo "$1" | nc -W 1 -U "$SOCKET_PATH" > /dev/null
  sleep 0.3
}
              
while true; do
  wait_for_files
              
  if check_debug_file; then
    echo "Connection reset by peer"
    send_command "reconnect"
    sleep 3
    send_command "next"
  fi

  true > "$DEBUG_FILE"
              
  response=$(nc -W 1 -U "$SOCKET_PATH")
              
  if [[ $response == *"\"FinishedTrack\""* ]]; then
    sleep 1
    response=$(nc -W 1 -U "$SOCKET_PATH")
    if [[ $response == *"\"FinishedTrack\""* ]]; then
      echo "Disconnected/Finished Track"
      send_command "reconnect"
      sleep 3
      send_command "playpause"
      send_command "previous"
    fi
  fi
              
  sleep 5
done

rodrgz avatar Jul 01 '23 06:07 rodrgz

https://github.com/librespot-org/librespot/pull/1129 -- this change could actually be interesting

hrkfdn avatar Jul 01 '23 15:07 hrkfdn