Playlist playback stopped after a few hours with a broken pipe (os error 32) error / non recoverable websocket/TLS error (using Dealer)

[antoinecellerier]

Description

Playlist playback stopped after a few hours with a broken pipe (os error 32) error
Let me know if more diagnostics can help.

Version

72b6ad9 (post #1356 Dealer merge)

How to reproduce

Steps to reproduce the behavior in librespot e.g.

1. Launch librespot with librespot -c ~/.cache/librespot --cache-size-limit 64G -n "Pi Zero" -b 320 --device hw:CARD=Set,DEV=0 --device-type avr --backend alsa
2. Start playlist - this time was using the web client but not sure it has any impact
3. Wait a few hours
4. Playback stops. Notice non recoverable websocket/TLS error in togs

Log

[2024-12-14T17:26:28Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:2hT7SV5QUhbO0p8T1dkHS6
[2024-12-14T17:26:29Z INFO librespot_playback::player] (202000 ms) loaded
[2024-12-14T17:29:50Z INFO librespot_playback::player] Loading <Porsche 944> with Spotify URI spotify:track:6JSkc4vPxHuTqgSuJ2vMu9
[2024-12-14T17:29:51Z INFO librespot_playback::player] <Porsche 944> (235795 ms) loaded
[2024-12-14T17:33:29Z ERROR librespot_core::session] Connection to server closed.
[2024-12-14T17:33:46Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:46TKHBSVXIOYjfi3pp6X7F
[2024-12-14T17:33:46Z ERROR librespot_core::session] Broken pipe (os error 32)
[2024-12-14T17:33:46Z WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
[2024-12-14T17:33:46Z WARN librespot] Spirc shut down unexpectedly
[2024-12-14T17:33:47Z INFO librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2024-12-14T17:33:47Z INFO librespot_core::session] Authenticated as '****' !
[2024-12-14T17:33:47Z INFO librespot_core::session] Country: "FR"
[2024-12-14T17:33:47Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-12-14T17:33:47Z INFO librespot_connect::spirc] active device is <> with session
[2024-12-14T17:33:48Z ERROR librespot_core::audio_key] Audio key response timeout
[2024-12-14T17:33:48Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
[2024-12-14T17:33:52Z ERROR librespot_audio::fetch::receive] Streamer error requesting range 6356992 +65536: Error { kind: Unknown, error: hyper_util::client::legacy::Error(SendRequest, hyper::Error(IncompleteMessage)) }
[2024-12-14T17:34:00Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: Deadline expired before operation could complete { wait timeout exceeded }
unavailable
[2024-12-14T17:34:06Z WARN librespot_core::dealer] No subscriber for msg.uri: hm://collection/collection/antoinecellerier
[2024-12-14T17:34:06Z WARN librespot_core::dealer] failure during data parsing for hm://collection/collection/antoinecellerier/json: Invalid state { base64 decoding failed: Invalid symbol 123, offset 0. }
end_of_track

Host (what you are running librespot on):

• OS: Linux pizero 6.6.51+rpt-rpi-v8 # 1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux
• Platform: Raspberry Pi Zero 2 W Rev 1.0

[kingosticks]

Is it 100% reproducible for you?

[photovoltex]

If I understand the problem correct, the problem isn't directly the pipe error and more the random stopping of the playback? Could you try #1420 and report back?.

[antoinecellerier]

Is it 100% reproducible for you?

It's only happened once so far over the past 2 days. Will post here if I get another repro.

If I understand the problem correct, the problem isn't directly the pipe error and more the random stopping of the playback? Could you try #1420 and report back?.

Will do.

[antoinecellerier]

Looks like the disconnect happened again after a few hours of playback running #1420. It seems to be keeping track of the session id now but fails to resume playback when reconnecting with a client and hitting play.

[2024-12-15T22:52:23Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:4MFKi6VzidmH1V6TX86ihS
[2024-12-15T22:52:23Z INFO librespot_playback::player] (98000 ms) loaded
[2024-12-15T22:54:01Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:0pKFBjiyiDsp8iUSaBKZD0
[2024-12-15T22:54:02Z INFO librespot_playback::player] (133837 ms) loaded
[2024-12-15T22:56:19Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:65YmXHisEoFpxft1Bl40Bg
[2024-12-15T22:56:25Z ERROR librespot_core::session] Connection to server closed.
[2024-12-15T22:56:26Z ERROR librespot_core::audio_key] Audio key response timeout
[2024-12-15T22:56:26Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
[2024-12-15T22:56:36Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-12-15T22:56:36Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:7jdcPz3QNqvpHn6eODQ04d
[2024-12-15T22:56:36Z WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
[2024-12-15T22:56:36Z WARN librespot] Spirc shut down unexpectedly
[2024-12-15T22:56:37Z ERROR librespot_core::session] Broken pipe (os error 32)
unavailable
[2024-12-15T22:56:38Z ERROR librespot_core::audio_key] Audio key response timeout
[2024-12-15T22:56:38Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
[2024-12-15T22:56:42Z INFO librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2024-12-15T22:56:42Z INFO librespot_core::session] Authenticated as '' !
[2024-12-15T22:56:42Z INFO librespot_core::session] Country: "FR"
end_of_track
[2024-12-15T22:56:48Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-12-15T22:56:48Z INFO librespot_connect::spirc] active device is <> with session <19caa7e645905076bc1db8d5f870ba68>
[2024-12-15T22:56:49Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
[2024-12-16T02:19:43Z ERROR librespot_core::session] Connection to server closed.
[2024-12-16T08:36:49Z WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
[2024-12-16T08:36:49Z WARN librespot] Spirc shut down unexpectedly
[2024-12-16T08:36:49Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-16T08:36:49Z INFO librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2024-12-16T08:36:50Z INFO librespot_core::session] Authenticated as '' !
[2024-12-16T08:36:50Z INFO librespot_core::session] Country: "FR"
[2024-12-16T08:36:50Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-12-16T08:36:50Z INFO librespot_connect::spirc] active device is <> with session <19caa7e645905076bc1db8d5f870ba68>
[2024-12-16T08:39:10Z ERROR librespot_playback::player] Error handling command: Operation aborted { Symphonia Decoder Error: seek error: requested seek timestamp is out-of-range for stream }
[2024-12-16T08:39:10Z ERROR librespot_playback::player] PlayerState::is_playing in invalid state

[photovoltex]

Hmm, if it fails to resume playback then there might be a different underlying problem that seems to be dealer independent. Error wise it seems points to network issues. Do you perhaps have a very specific network setup?

[antoinecellerier]

Nope I'm running fairly standard. The Pi Zero 2W is connected to my ISP's WiFi router. This might indeed be something which is independent from the dealer change ... I was already getting some disconnects previously but I do not have any "WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify" before the switch - which I guess might just be due to new logging.

In case it's helpful, here's another occurrence from this afternoon. This time the broken pipe error message isn't output on the first reconnect but does appear on the second. Playback did resume correctly when I reconnected a client whereas in the two previously shared examples playback wouldn't restart.

[2024-12-16T16:42:54Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:4ItaSa1wiufUpvbyLU5Eru
[2024-12-16T16:42:55Z INFO librespot_playback::player] (133685 ms) loaded
[2024-12-16T16:45:13Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:5OdMYwjQgF7OXSy01xFxVx
[2024-12-16T16:45:13Z INFO librespot_playback::player] (255826 ms) loaded
[2024-12-16T16:46:39Z ERROR librespot_core::session] Connection to server closed.
[2024-12-16T16:49:23Z WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
[2024-12-16T16:49:23Z WARN librespot] Spirc shut down unexpectedly
[2024-12-16T16:49:24Z INFO librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2024-12-16T16:49:24Z INFO librespot_core::session] Authenticated as '' !
[2024-12-16T16:49:24Z INFO librespot_core::session] Country: "FR"
preload_next
[2024-12-16T16:49:28Z INFO librespot_playback::player] Loading <In Metaphor, Solace> with Spotify URI spotify:track:5TtM1IoaHk51lLEaIOagSz
[2024-12-16T16:49:29Z ERROR librespot_core::session] Broken pipe (os error 32)
[2024-12-16T16:49:29Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-12-16T16:49:29Z INFO librespot_connect::spirc] active device is <> with session <6659848d063ac024b37a099db5741684>
[2024-12-16T16:49:30Z ERROR librespot_core::audio_key] Audio key response timeout
[2024-12-16T16:49:30Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
[2024-12-16T16:49:32Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
unavailable
end_of_track
[2024-12-16T18:22:34Z WARN librespot_core::dealer] No subscriber for msg.uri: ap://product-state-update
[2024-12-16T18:22:36Z INFO librespot_connect::spirc] session update: <Ok(SESSION_DELETED)> for self, current session_id 09e9a667e39248b7a1e9b74b7386f527, new session_id 6659848d063ac024b37a099db5741684
[2024-12-16T19:02:59Z WARN librespot_core::session] Connection to server closed.
[2024-12-16T19:06:19Z WARN librespot_core::dealer] No subscriber for msg.uri: ap://product-state-update
[2024-12-16T19:06:24Z WARN librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
[2024-12-16T19:06:24Z WARN librespot] Spirc shut down unexpectedly
[2024-12-16T19:06:24Z INFO librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
[2024-12-16T19:06:24Z INFO librespot_core::session] Authenticated as '' !
[2024-12-16T19:06:24Z INFO librespot_core::session] Country: "FR"
[2024-12-16T19:06:25Z INFO librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2024-12-16T19:06:25Z INFO librespot_connect::spirc] active device is <> with session <6659848d063ac024b37a099db5741684>
[2024-12-16T19:06:29Z WARN librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
[2024-12-16T19:06:29Z INFO librespot_connect::spirc] session update: <Ok(NEW_SESSION)> for self, current session_id 43b3a20343cc47978ba4684f1d876bac, new session_id 36a556d773b7781db28a5dee858288a5
[2024-12-16T19:06:29Z ERROR librespot_connect::spirc] could not parse session_update: Invalid state { Unknown enum variant name: WIFI_BROADCAST_CHANGED at 1:11 }
[2024-12-16T19:10:15Z INFO librespot_playback::player] Loading <In Metaphor, Solace> with Spotify URI spotify:track:5TtM1IoaHk51lLEaIOagSz
[2024-12-16T19:10:15Z INFO librespot_playback::player] <In Metaphor, Solace> (153408 ms) loaded
[2024-12-16T19:12:53Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:34CzCk11KB21nrf0GXbSR5
[2024-12-16T19:12:53Z INFO librespot_playback::player] (121720 ms) loaded

[photovoltex]

Oh that is an "expected" warning... That warning is printed when we close the dealer... So it did what we told it to do, but for some reason it communicates to us that its connection failed. I tried to fix it at the beginning but never found a solution or the actual cause.

The error later for the WIFI_BROADCAST_CHANGED enum is also expected and happens because our current model is probably not up-to-date (might change soon). That could be probably set down to warning.

What is more concerning from my perspective are these error messages:

2024-12-16T16:49:30Z ERROR librespot_core::audio_key] Audio key response timeout
[2024-12-16T16:49:30Z WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
[2024-12-16T16:49:32Z ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream

Anyhow, I see the problem with these error because they easily distract from the actual problem.

Playback did resume correctly when I reconnected a client whereas in the two previously shared examples playback wouldn't restart.

So it doesn't automatically continue playing? That's a bummer.

[antoinecellerier]

Correct. It stops playing which was already happening previously mostly with os error 107 errors. Since updating to dealer those have most disappeared except once when trying to recover from one of the symptoms I was describing earlier it seems. I don't know if this is really correlated.

Looking at the past month or so of logs matching "os error" maybe it's completely unrelated. Feel free to close if this is not actionable ... or suggest things I could be doing to diagnose better.

[2024-11-11T16:32:27Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-16T14:08:54Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-16T14:38:00Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-16T21:22:55Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-18T04:29:24Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-18T06:59:30Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-19T19:04:33Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-20T08:33:34Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-20T22:54:39Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-21T10:37:40Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-21T15:05:09Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-21T15:10:11Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-21T17:08:17Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-23T00:23:19Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-23T00:52:19Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-23T00:53:20Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-23T06:02:25Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-24T10:29:27Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-25T07:55:35Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-26T07:04:43Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-11-30T16:28:47Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-02T05:54:55Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-02T06:01:57Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-05T00:56:04Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-05T05:11:06Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-05T11:30:08Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-06T00:34:09Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-06T03:14:11Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-07T10:23:15Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-07T17:59:17Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-07T18:13:18Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-08T04:49:21Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-08T14:56:23Z ERROR librespot_core::session] Broken pipe (os error 32)
[2024-12-11T11:30:24Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-11T12:47:27Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-12T19:12:58Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-14T06:02:10Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)

Update to 72b6ad9 here

[2024-12-14T17:33:46Z ERROR librespot_core::session] Broken pipe (os error 32)
[2024-12-15T22:56:37Z ERROR librespot_core::session] Broken pipe (os error 32)
[2024-12-16T08:36:49Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
[2024-12-16T16:49:29Z ERROR librespot_core::session] Broken pipe (os error 32)

[photovoltex]

Interesting, will keep it open for now as these errors are printed as actual errors in the log, and so long as they appear as errors we should probably investigate them. If they appear to be unavoidable then they should be downgraded to a warning I would say.

But I'm also open to other approaches.