error: Os { code: 61, kind: ConnectionRefused, message: "Connection refused" } - how to investigate?

[michaelherger]

I'm posting this to the Discussion section rather than the Issues, as I understand I'm using librespot in a somewhat different way. My spotty application uses librespot to play single tracks. It would be called for each individual track, rather than sit in the background and be instructed by Connect what to play. This is largely taken from the play.rs example.

Every now and then a track would not play. And I'd like to understand why that would be, and how I could investigate the issue. So here's the log of one such failed playback:

[2024-09-18T22:49:11Z INFO  spotty] spotty v1.9.9 - using librespot 0.5.0-dev e24fc72 (Built on 2024-09-13, Build ID: tLAjJEvy, Profile: debug)
[2024-09-18T22:49:11Z TRACE spotty] Command line argument(s):
[2024-09-18T22:49:11Z TRACE spotty] 		n "Squeezebox"
[2024-09-18T22:49:11Z TRACE spotty] 		c "/Users/me/Library/Caches/Squeezebox/spotty"
[2024-09-18T22:49:11Z TRACE spotty] 		single-track "spotify://track:6Z1C9gQnScliphROi2DabV"
[2024-09-18T22:49:11Z TRACE spotty] 		bitrate "320"
[2024-09-18T22:49:11Z TRACE spotty] 		disable-discovery
[2024-09-18T22:49:11Z TRACE spotty] 		disable-audio-cache
[2024-09-18T22:49:11Z TRACE spotty] 		verbose
[2024-09-18T22:49:11Z TRACE spotty] Using cached credentials.
[2024-09-18T22:49:11Z DEBUG librespot_core::session] new Session
[2024-09-18T22:49:11Z DEBUG librespot_core::session] new Session
[2024-09-18T22:49:11Z DEBUG librespot::component] new ApResolver
[2024-09-18T22:49:11Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2024-09-18T22:49:11Z INFO  librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2024-09-18T22:49:11Z ERROR spotty::spotty] Failed to create session: Error { kind: Unavailable, error: Os { code: 61, kind: ConnectionRefused, message: "Connection refused" } }
[2024-09-18T22:49:11Z DEBUG librespot_core::session] drop Session
[2024-09-18T22:49:11Z DEBUG librespot::component] drop ApResolver

I understand this is an error coming from the OS? Error 61 - Connection refused. If I google around for this I find references to "server was not there" or similar. Pretty often when this happens simply re-trying the same track again would indeed work as expected. So a failed server connection is more likely than an invalid or unavailable track.

So I thought, let's be stubborn and stupidly have the application try again in case of failure. And voilà:

[2024-09-19T04:44:10Z INFO  spotty] spotty v1.9.9 - using librespot 0.5.0-dev 9f5ee35 (Built on 2024-09-19, Build ID: hT3BcW8z, Profile: debug)
[2024-09-19T04:44:10Z TRACE spotty] Command line argument(s):
[2024-09-19T04:44:10Z TRACE spotty] 		n "Squeezebox"
[2024-09-19T04:44:10Z TRACE spotty] 		c "/Users/me/Library/Caches/Squeezebox/spotty"
[2024-09-19T04:44:10Z TRACE spotty] 		single-track "spotify://track:7z7kvUQGwlC6iOl7vMuAr9"
[2024-09-19T04:44:10Z TRACE spotty] 		bitrate "320"
[2024-09-19T04:44:10Z TRACE spotty] 		disable-discovery
[2024-09-19T04:44:10Z TRACE spotty] 		disable-audio-cache
[2024-09-19T04:44:10Z TRACE spotty] 		verbose
[2024-09-19T04:44:10Z TRACE spotty] Using cached credentials.
[2024-09-19T04:44:10Z DEBUG librespot_core::session] new Session
[2024-09-19T04:44:10Z DEBUG librespot_core::session] new Session
[2024-09-19T04:44:10Z DEBUG librespot::component] new ApResolver
[2024-09-19T04:44:10Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2024-09-19T04:44:10Z INFO  librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2024-09-19T04:44:11Z ERROR spotty::spotty] Failed to create session (play_track) - re-trying: Error { kind: Unavailable, error: Os { code: 61, kind: ConnectionRefused, message: "Connection refused" } }
[2024-09-19T04:44:11Z DEBUG librespot_core::session] new Session
[2024-09-19T04:44:11Z DEBUG librespot_core::session] drop Session
[2024-09-19T04:44:11Z DEBUG librespot::component] drop ApResolver
[2024-09-19T04:44:11Z DEBUG librespot::component] new ApResolver
[2024-09-19T04:44:11Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2024-09-19T04:44:11Z INFO  librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2024-09-19T04:44:11Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[2024-09-19T04:44:11Z INFO  librespot_core::session] Authenticated as 'meofcourse' !

So this seems to be an intermittent problem on Spotify's end.

But my code certainly is extremely ugly, hacky:

            let mut session = Session::new(session_config.clone(), None);
            if let Err(error) = session.connect(last_credentials.clone(), false).await {
                error!("Failed to create session (play_track) - re-trying: {:?}", error);

                session = Session::new(session_config, None);
                if let Err(error) = session.connect(last_credentials, false).await {
                    error!("Failed to create session (play_track): {:?}", error);
                    return;
                }
            }

How could this be handled in a nicer fashion (aka. correctly)?

[kingosticks]

We have the same use-case in Mopidy-Spotify (using gst-plugin-spotify) and users have reported the same problem. I've never managed to recreate it myself and I've racked up a lot of playtime. Do you get any packet loss if you leave ap-gew4.spotify.com pinging?

[michaelherger]

My hack is working pretty well. 27 failures worked around so far. No unexpected end of streaming in close to 12h. I'd prefer my hack over blacklisting, as sooner or later lists are always wrong...

[kingosticks]

Let's implement some retrying then. It would also "fix" (avoid) the rare, but annoying, "bytes remaining on stream" error.

[kingosticks]

W.r.t ping/pong, I spent time yesterday verifying that's happening and it mostly did, except in one case I found the connection was reset just after we supposedly sent the pong but before we got their pong-ack back. Which led me to think...could we be victim to nagles algorithm? Everything with networking eventually hits that ... But then I wasn't able to reproduce that failure mode so it might just have been a coincidence.

[roderickvd]

I don't know. Wouldn't that also hit the official clients then?

Just to check - it's the same on 0.4 and 0.5 now right? If not, and it's worse on 0.5, then the only wild guess I can take there is that maybe it's due to me having changed the Tokio scheduler from single to multi CPU. Yeah, far fetched.

[kingosticks]

They might be using TCP nodelay. Ooo should be able to strace their client and see that easily...!

Correct, I don't think we have any data showing it's worse with v5.