Connection drops invalidate session

[nc7s]

Describe the bug
Run ncspot, start playing for a while, and it will stop playing, with the error message "Stream drop error: PortAudio not initialized".

Expected behavior
Continued playing.

Screenshots

System (please complete the following information):

• OS: macOS 11.6
• Terminal: iTerm2 3.4.10
• Version: 0.9.0
• Installed from: brew

Backtrace/Debug log
ncspot-debug.log
ncspot-debug-2.log
ncspot-debug-3.log

[hrkfdn]

Does this also happen with versions <0.9.0?

[nc7s]

Does this also happen with versions <0.9.0?

I'll try on one.

[nc7s]

@hrkfdn Happens all the way down to 0.6.0. Reading the log I found that when it threw the error, a disconnection happened. May relate to #264.

[hrkfdn]

Thanks for checking. I am wondering if the last PortAudio releases caused this.

[hrkfdn]

I have pushed a small fix that could help. Could you recompile ncspot and see if that fixes it for you? So far I'm only able to reproduce this error when closing ncspot, so the scenario may not be the same, but it prints the same error.

My guess is that this happens when ncspot tries to renew the session. Stopping the player before shutting down seems to alleviate this problem with the PortAudio backend.

[nc7s]

Not really - it does what it's told i.e. stop playing when connection is down, but nothing more.

Reading the log again one thing came to my attention that, when a session went out, two following tries would fail, saying librespot session invalidated. Guess it's really a problem down there.

[hrkfdn]

How long does it usually take for your session to expire? Are you able to provoke it somehow, e.g. by reconnecting to the internet? Reason I'm asking is because I can't reproduce this problem locally, I only saw the same error when I closed ncspot and a song was playing and the previously committed fix seems to help with that at least.

[nc7s]

Less than half a song 🤷‍♂️ Someone pointed out that proxy timeout makes long connections close, hence the error. But the official iOS app isn't affected.

[hellquist]

FWIW I have recently (as of today) starting getting these error messages. macOS, ncspot 0.9.0 installed via Homebrew. Have had ncspot installed for months without issues previously. Have been able to listen for hours on end. Now it won't make it past half a tune, ending playback with that same error message printed.

[nc7s]

@hellquist Sorry to hear that. Do you connect through a proxy too?

[hellquist]

@hellquist Sorry to hear that. Do you connect through a proxy too?

Actually I may have spoken too soon. I did two separate update runs for "everything" (i.e. both Homebrew and also general apps) and ensured I rebooted properly between both. Today it has been playing for a hour so far without generating the error. But no, I don't have a proxy connection.

[acburdine]

Unfortunately, I'm seeing the same issue as @hellquist. I just started using ncspot today, and this error is occurring in whatever song I attempt to play 😞 I don't think I've made it through a complete song yet

System Info:
OS: macOS Monterey, v12.2
Terminal: iTerm2, v3.4.14
ncspot v0.9.5, installed via Brew
portaudio v19.7.0, installed via Brew
tmux, v3.2a, installed via Brew

I did a full brew upgrade of the things I had installed, as well as an update to the latest macOS Monterey (v12.2), with a reboot after each, and I'm still seeing the same problem. I'm also not using a proxy connection (to my knowledge at least). I'll do some additional testing to see if the fact I'm running ncspot inside of a tmux session is contributing to the problem.

I'll look and see if I can find/generate the debug logs - I'll attach them to this comment once I find them.

Edit: Ran and got a few debug logs, this is what I was able to gather:

debug.log

[2022-02-02][14:35:13] [tokio_util::codec::framed_impl] [TRACE] attempting to decode a frame
[2022-02-02][14:35:13] [librespot_playback::player] [INFO] <Song 1> (254206 ms) loaded
[2022-02-02][14:35:13] [librespot_playback::player] [TRACE] == Starting sink ==
[2022-02-02][14:35:13] [ncspot] [TRACE] event received: Playing(SystemTime { tv_sec: 1643830513, tv_nsec: 414128000 })
[2022-02-02][14:38:57] [ncspot::queue] [DEBUG] Preloading track <Song 2> as requested by librespot
[2022-02-02][14:38:57] [ncspot::spotify_worker] [DEBUG] Preloading SpotifyId { id: 140415676814507524167959893441172430954, audio_type: Track }
[2022-02-02][14:38:57] [librespot_playback::player] [DEBUG] command=Preload(SpotifyId { id: 140415676814507524167959893441172430954, audio_type: Track })
[2022-02-02][14:38:57] [librespot_playback::player] [DEBUG] Preloading track
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] flushing framed transport
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] writing; remaining=83
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] framed transport flushed
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] flushing framed transport
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] framed transport flushed
[2022-02-02][14:38:57] [tokio_util::codec::framed_impl] [TRACE] Got an error, going to errored state
[2022-02-02][14:38:57] [librespot_core::session] [DEBUG] Invalidating session[1]
[2022-02-02][14:38:57] [librespot::component] [DEBUG] new ChannelManager
[2022-02-02][14:38:57] [librespot_core::session] [DEBUG] drop Dispatch
[2022-02-02][14:38:57] [librespot_playback::player] [ERROR] Unable to load audio item: MercuryError
[2022-02-02][14:38:57] [mio::poll] [TRACE] deregistering event source from poller
[2022-02-02][14:38:57] [librespot_core::session] [ERROR] Connection reset by peer (os error 54)
[2022-02-02][14:38:57] [librespot_playback::player] [DEBUG] drop PlayerInternal[1]
[2022-02-02][14:38:57] [librespot_playback::player] [DEBUG] PlayerInternal thread finished.
[2022-02-02][14:38:57] [ncspot::spotify_worker] [WARN] Librespot player event channel died, terminating worker
[2022-02-02][14:38:57] [ncspot::spotify] [ERROR] worker thread died, requesting restart
[2022-02-02][14:38:57] [ncspot::spotify_worker] [DEBUG] Worker thread is shutting down, stopping player
[2022-02-02][14:38:57] [librespot_playback::player] [ERROR] Player Commands Error: channel closed
[2022-02-02][14:38:57] [librespot_core::session] [DEBUG] drop Session[1]
[2022-02-02][14:38:57] [librespot::component] [DEBUG] drop AudioKeyManager
[2022-02-02][14:38:57] [librespot::component] [DEBUG] drop ChannelManager
[2022-02-02][14:38:57] [librespot::component] [DEBUG] drop MercuryManager
[2022-02-02][14:38:57] [librespot_playback::player] [DEBUG] Shutting down player thread ...
[2022-02-02][14:38:57] [ncspot::spotify] [DEBUG] No HTTP proxy set
[2022-02-02][14:38:57] [ncspot::spotify] [DEBUG] opening spotify session
[2022-02-02][14:38:57] [mio::poll] [TRACE] registering event source with poller: token=Token(33554432), interests=READABLE | WRITABLE
[2022-02-02][14:38:57] [want] [TRACE] signal: Want
[2022-02-02][14:38:57] [want] [TRACE] signal found waiting giver, notifying
[2022-02-02][14:38:57] [want] [TRACE] poll_want: taker wants!
[2022-02-02][14:38:57] [want] [TRACE] signal: Want
[2022-02-02][14:38:57] [want] [TRACE] signal: Want
[2022-02-02][14:38:57] [librespot_core::session] [INFO] Connecting to AP "ap-guc3.spotify.com:4070"
[2022-02-02][14:38:57] [mio::poll] [TRACE] registering event source with poller: token=Token(33554433), interests=READABLE | WRITABLE
[2022-02-02][14:38:57] [mio::poll] [TRACE] deregistering event source from poller
[2022-02-02][14:38:57] [want] [TRACE] signal: Closed
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] flushing framed transport
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] writing; remaining=262
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] framed transport flushed
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] attempting to decode a frame
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] frame decoded from buffer
[2022-02-02][14:38:58] [librespot_core::session] [INFO] Authenticated as "acburdine" !
[2022-02-02][14:38:58] [librespot_core::session] [DEBUG] new Session[2]
[2022-02-02][14:38:58] [librespot_playback::mixer::softmixer] [INFO] Mixing with softvol and volume control: Log(60.0)
[2022-02-02][14:38:58] [ncspot::spotify] [DEBUG] worker thread ready.
[2022-02-02][14:38:58] [librespot_playback::player] [DEBUG] new Player[2]
[2022-02-02][14:38:58] [tokio_util::codec::framed_impl] [TRACE] flushing framed transport
[2022-02-02][14:38:58] [librespot_playback::convert] [INFO] Converting with ditherer: tpdf
[2022-02-02][14:38:58] [librespot_playback::audio_backend::portaudio] [INFO] Using PortAudio sink with format: S16

the stderr log only shows the "Stream drop error: PortAudio not initialized"

the timing of when the error occurred makes it seem like it coincided with preloading of the next track? could be a coincidence, but that would explain why it occurs near the end of the song. I'll do some more debugging and see what I can find out.

[acburdine]

after playing around with it some more, this does seem to be related more closely to an issue in librespot, rather than an issue with ncspot itself - seeing Connection reset by peer errors in the logs. My guess is whatever comes out of librespot-org/librespot#609 will fix/improve the issue 🤔

Edit: It's definitely an issue with librespot - I found out my ISP is routing traffic through a NAT, making my external IP change every so few minutes. This causes the connection to Spotify to disconnect, which pauses the stream playback.

[nc7s]

Checked back and saw 0.12 playing full songs, but switching proxies still cut it down. Hopefully the librespot overhaul would solve this.

[nc7s]

Also noticed that rather than crashing it now just stops playing. Maybe go further and make it recover from this sort of errors and carry on? Would love to implement this myself, but need to find some time.

[hrkfdn]

As of #1057 there is a reconnect command that could help with this