fix: dealer reconnect and session loss recovery without playback interruption - #1692
fix: dealer reconnect and session loss recovery without playback interruption#1692antoinecellerier wants to merge 22 commits into
Conversation
There was a problem hiding this comment.
Pull request overview
This PR addresses a hang in the Connect “spirc” task after dealer websocket reconnects by adding an explicit reconnect notification mechanism so consumers can tear down and re-subscribe, and by bounding dealer URL resolution time during reconnect attempts.
Changes:
- Add a
watch-based reconnect “generation” signal plumbed through dealer builder/manager and emitted on reconnect andget_url()failures/timeouts. - Add a 30s timeout around
get_url()during the dealer reconnect loop and retry instead of terminating the dealer task. - Update
SpircTaskto subscribe to the reconnect signal beforedealer.start()and break out of itsselect!loop when a reconnect is observed.
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated 2 comments.
| File | Description |
|---|---|
| core/src/dealer/mod.rs | Adds reconnect watch plumbing and get_url() timeout/handling in the reconnect loop; exposes a reconnect receiver. |
| core/src/dealer/manager.rs | Stores and exposes the reconnect watch sender/receiver; passes sender into dealer launch. |
| connect/src/spirc.rs | Subscribes to reconnect notifications and restarts spirc when dealer reconnects to avoid stale subscription hangs. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
eb172e9 to
34d2fd9
Compare
3388445 to
f69778d
Compare
|
Works great for me thanks!. I switched ISP before the weekend and since then librespot would loose connection at least once every 15 minute. Very odd behavior that so far I have not been able to pinpoint to a specific cause (perhaps something to do with poor multicast support of the supplied router?). This PR fixed it! |
|
I think I’ve encountered an asymmetrical issue when switching between accounts that seems specific to this PR. If the device has credentials (username) defined in the config, it becomes impossible to switch back to that "Owner" account after a "Guest" (Discovery/Zeroconf) session has been active or is active (the "Owner" can join the jam but not take over the session). The error it shows is:
to reproduce the error:
The only way to recover is to manually restart the service. Curiously the "Guest" does not experience the same issues when the "Owner" is playing, it can happily take over. It seems the new recovery logic might be preventing a clean shutdown of the Dealer task during an account handover? It is curious it only happens in this specific situation though. Other than this, I haven't experienced any problems (thanks again!) |
|
@artenverho Thanks for the detailed report! Copilot has likely identified the root cause and I've pushed 3 fixup commits. The problem: When Account B takes over via Discovery, Fixes pushed (as fixup commits, not yet squashed):
Could you test with these changes and let me know if the account switching issue is resolved? |
|
Sorry took a few days to find the time for testing. At first glance it seems to solve the issue! I will need to do some more long term testing but switching between users is now seamless again. Thanks! |
|
I wanted to chime in as a long-time librespot user who ran into a very weird, persistent issue where the connection would randomly drop, the music would stop and a reconnect would be needed. This persisted across various installations, standalone librespot or included in other pachages. It arrived a few months ago, but couldnt be pinpointed to any specific changes. Anyhow, this PR seems to have solved all of my issues, so thank you 👍 |
…ithout playback interruption
Pin the fork with the librespot-org/librespot#1692 port (in-place dealer reconnect, prompt spirc-task exit on session TCP loss) and react to the spirc exit in the player event loop: recover immediately when idle, defer until buffered audio stalls when playing, and guard the delayed EnsurePlaybackContinues dispatch against the replaced player.
When the dealer websocket connection drops and reconnects internally,
spirc's tokio::select! loop remains blocked on subscription streams
(connection_id_update, connect_state_update, etc.) that will never
receive new messages. The mpsc senders in the SubscriberMap are not
cleaned up on reconnect, so spirc hangs indefinitely — requiring a
manual process restart.
A second failure mode occurs when the dealer cannot reconnect because
get_url() (which resolves the dealer endpoint and fetches an auth
token via the session) hangs forever on a dead session TCP connection,
with no timeout.
Root cause analysis
-------------------
The dealer's run() loop (core/src/dealer/mod.rs) coordinates
reconnecting: when the websocket drops, it calls get_url() to resolve
a new dealer endpoint, then connect(). However:
1. The subscription channels (mpsc::UnboundedSender<Message>) stored
in DealerShared::message_handlers survive reconnects. Spirc's
.next() calls on the receiver side never return None because the
senders are still alive in the map — they just never send again.
2. get_url() calls session.apresolver().resolve("dealer") and
session.login5().auth_token(), both of which need the session's
TCP connection. When that connection is dead ("Connection to server
closed"), these calls hang forever with no timeout.
Before fix — log evidence of hangs requiring manual restart
-----------------------------------------------------------
Feb 17 01:12 — "Websocket peer does not respond."
[63.5 hour gap — process completely unresponsive]
Feb 19 16:44 — Manual restart: "librespot 0.8.0 ..."
Feb 23 08:41 — "Websocket peer does not respond."
[32.2 hour gap — process completely unresponsive]
Feb 24 16:51 — Manual restart: "librespot 0.8.0 ..."
Dec 15 20:53-21:07 — Rapid reconnect storm: 12 "peer does not
respond" in 50 minutes, with "starting dealer failed: Websocket
couldn't be started because: Handshake not finished" errors.
Feb 22 — Session TCP died at 05:55, spirc didn't notice for 7+
hours (no dealer reconnect signal), finally shut down at 22:11.
Fix
---
Add a watch::Sender<u64> generation counter shared between the dealer
and its consumers. The dealer increments it when:
- It successfully reconnects after a connection loss
- get_url() times out (30s RECONNECT_URL_TIMEOUT)
- get_url() returns an error
Spirc subscribes to a watch::Receiver before dealer.start() to avoid
a lost-wakeup race (watch retains state, unlike Notify which loses
notifications if no one is awaiting). In its select! loop, spirc
watches for changes and breaks out, triggering the existing "Spirc
shut down unexpectedly" -> auto-reconnect path in main.rs.
The get_url() error handling also fixes a pre-existing issue where
get_url() failures would propagate via ? and terminate the dealer
background task entirely, rather than retrying.
Changes:
- core/src/dealer/mod.rs: Add watch channel plumbing to Dealer,
Builder, create_dealer! macro, and run(). Add 30s timeout on
get_url(). Handle get_url() errors with retry+signal instead of
fatal ? propagation. Signal consumers on reconnect.
- core/src/dealer/manager.rs: Store watch::Sender in
DealerManagerInner, pass to Builder::launch(), expose
reconnect_receiver() for consumers.
- connect/src/spirc.rs: Subscribe to reconnect watch before
dealer.start(). Add select! branch to break on dealer reconnect.
After fix — 9 days of logs showing automatic recovery
-----------------------------------------------------
Websocket failures now recover in 2-7 seconds automatically:
Mar 01 15:45 — "Websocket connection failed: Connection reset"
Mar 01 15:45 — "Dealer reconnected; notifying consumers."
Mar 01 15:45 — "Dealer reconnected; restarting spirc to refresh subscriptions."
Mar 01 15:46 — "Spirc shut down unexpectedly"
Mar 01 15:46 — "active device is <> with session <...>" [7s recovery]
Mar 03 10:21 — "Websocket peer does not respond."
Mar 03 10:21 — "Dealer reconnected; notifying consumers."
Mar 03 10:21 — "restarting spirc to refresh subscriptions."
Mar 03 10:21 — "active device is <> with session <...>" [7s recovery]
Mar 06 09:42 — "Websocket peer does not respond."
Mar 06 09:42 — "Error while connecting: Network is unreachable"
Mar 06 09:43 — [retries for ~1 min while network recovers]
Mar 06 09:43 — "Dealer reconnected; notifying consumers."
Mar 06 09:43 — "active device is <> with session <...>" [91s recovery]
Summary over 9 days post-fix (Feb 28 - Mar 8):
- 0 manual restarts needed (vs 2 in 7 days before fix)
- 9 dealer reconnect events, all recovered in 2-91 seconds
- 14 session TCP closures also recovered (via existing path)
- 0 get_url() timeouts fired (websocket errors caught first)
- Process running continuously for 9+ days
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Symptoms observed in logs:
WARN librespot_core::dealer Websocket peer does not respond.
WARN librespot_connect::spirc unexpected shutdown
WARN librespot Spirc shut down unexpectedly
When the dealer websocket drops (peer timeout or TLS close_notify),
SpircTask broke out of its event loop so main.rs could tear down and
recreate the entire Spirc. This caused playback to stop on every
transient websocket drop — even though the dealer already
auto-reconnects the websocket.
The subscription streams survive reconnects because they are registered
on the shared DealerShared instance. After reconnect, the server pushes
a new connection_id which handle_connection_id_update already handles.
Changes: reconnect_rx.changed() logs and continues instead of breaking.
handle_connection_id_update errors are non-fatal (logged, not breaking).
After fix — 6 days of logs (Mar 14-20) showing ~20 dealer reconnects
handled in-place without restarting spirc or stopping playback:
Mar 16 05:06 — "Dealer reconnected; awaiting new connection_id."
Mar 16 05:06 — "re-registering with active playback state: Paused { ... }"
[no restart, no "Spirc shut down unexpectedly"]
Mar 18 12:14 — "Dealer reconnected; awaiting new connection_id."
Mar 18 12:14 — "re-registering with active playback state: Playing { ... }"
[playback continued uninterrupted]
Mar 19 — 9 dealer reconnects in one day, all handled in-place
Summary: 0 spirc restarts from dealer reconnects (vs ~1/day before fix).
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Symptoms observed in logs — the TCP session dies, then cleanup fails: ERROR librespot_core::session Connection to server closed. WARN librespot_connect::spirc unexpected shutdown ERROR librespot_core::session Broken pipe (os error 32) ERROR librespot_core::session Transport endpoint is not connected (os error 107) WARN librespot Spirc shut down unexpectedly When SpircTask exits because session.is_invalid(), the post-loop cleanup called handle_disconnect() (which sets play_status to Stopped and tries to notify Spotify), delete_connect_state_request(), and dealer().close(). All of these fail because the TCP connection is dead, and setting play_status to Stopped needlessly kills the Player. Now we detect session.is_invalid() and skip all server communication in the post-loop cleanup. The Player runs in a separate thread and continues playing from its audio buffer. main.rs will create a new session and Spirc. After fix — the "Broken pipe" and "Transport endpoint is not connected" errors no longer appear after session loss. The Player continues playing while the session reconnects (see next commit for state restoration evidence). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
When SpircTask exits due to session loss, it now saves its
ConnectState, SpircPlayStatus, and play_request_id into a
SavedPlaybackState. main.rs captures this and passes it to
Spirc::with_saved_state() when creating the replacement Spirc.
The restored SpircTask starts with the saved state. On the first
connection_id_update, it updates the playback position to account for
elapsed time and re-registers with Spotify showing the correct track
and position. The Player is never interrupted.
After fix — 6 days of logs (Mar 14-20) showing 5 TCP session losses
all recovered with playback state preserved:
Mar 18 11:49 — "Connection to server closed."
Mar 18 11:52 — "session lost, saving playback state for recovery:
Playing { nominal_start_time: 1773834169899, ... }"
Mar 18 11:52 — "Spirc shut down with saved playback state, reconnecting"
Mar 18 11:52 — "Spirc[1] restoring saved playback state"
Mar 18 11:52 — "re-registering with active playback state:
Playing { nominal_start_time: 1773834169899, ... }"
[3 second recovery, playback never stopped]
Mar 19 12:21-12:37 — Two session losses during active playback,
both recovered in ~2 seconds with Playing state preserved.
Summary over 6 days post-fix (Mar 14-20):
- 0 "Spirc shut down unexpectedly" (vs ~2-3/day before fix)
- 0 process restarts needed
- 5 session TCP losses, all recovered with state preserved
- ~20 dealer reconnects, all handled in-place
- Process running continuously (Spirc counter reached Spirc[4])
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Temporary diagnostics (all log lines prefixed "DIAG") to root-cause the device-select auto-resume: selecting the device in the Spotify app resumes old playback even when the controller app shows nothing playing. The current INFO logs don't identify the controlling client (session client_* is librespot's own identity; the controller is only request.sent_by_device_id, a GUID, logged at debug). These logs: - Build a device_directory (GUID -> "name [brand model / type]") from the cluster device maps in handle_cluster_update and handle_connection_id_update. - handle_connect_state_request: log every command + sent_by_device_id + resolved controller name. - handle_connection_id_update: log active device (+name), cluster vs our session_id, and transfer_data size on registration. - handle_cluster_update: log reason, active device (+name), changed devices. - handle_transfer: log will_start_playing, raw is_paused, position, ctx_uri, current track, and play_origin feature/device identifier. Revert once the trigger is confirmed. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
…ently vanish The device disappeared from Spotify Connect after running fine for days, with no crash and no manual-restart-worthy error. The logs show the spirc event loop silently stopped re-registering us. What the logs establish ----------------------- - After the last successful registration at 04:15:05, every subsequent dealer reconnect produced only the dealer-side `Dealer reconnected; notifying consumers` — never the spirc-side `awaiting new connection_id` (the reconnect watch, which is independent of dealer message routing) nor a `DIAG registered`. So the spirc select! loop stopped running after 04:15:05. - No `session lost, saving playback state` and no `Spirc[N] restoring` appeared, so the spirc task neither exited nor was restarted — it was alive but frozen. - The dealer background task kept logging reconnects, so the tokio runtime was healthy; only the spirc task was stuck. - A device stays visible in Spotify only while its connect-state is registered against the current dealer connection_id, refreshed on each reconnect. With the loop frozen, re-registration stopped, the registration went stale, and Spotify dropped the device (~13h of silence until observed). - The in-place reconnect redesign had removed the earlier break-and-restart safety net, so nothing recovered the frozen loop. Log evidence ------------ Healthy reconnect (loop responsive) — signal + re-registration both happen: 04:15:05 WARN dealer] Dealer reconnected; notifying consumers. 04:15:05 INFO spirc] Dealer reconnected; awaiting new connection_id. 04:15:05 INFO spirc] DIAG registered: active_device=<> (none), cluster_session=<b38b...>, our_session=<20e2...>, transfer_data=3021 bytes 04:15:05 INFO spirc] active device is <> with session <b38b...> Every reconnect after that produced *only* the dealer-side notification — no `awaiting new connection_id` and no `DIAG registered`, i.e. the spirc loop never ran again: 04:27:12 WARN dealer] Websocket connection failed: WebSocket protocol error: Connection reset without closing handshake 04:27:12 WARN dealer] Dealer reconnected; notifying consumers. 14:30:13 WARN dealer] Websocket connection failed: IO error: Connection reset by peer (os error 104) 14:30:13 WARN dealer] Dealer reconnected; notifying consumers. 14:47:00 WARN dealer] Dealer reconnected; notifying consumers. 21:24:56 WARN dealer] Dealer reconnected; notifying consumers. Leading hypothesis for the freeze --------------------------------- Not yet proven: a blocked async task isn't externally introspectable (gdb/strace only show the runtime parked in epoll), so the exact stuck await is inferred, not confirmed. The most likely cause is a handler `.await` that blocked indefinitely on an spclient HTTP request over a half-open connection. hyper's legacy Client ships without request/response timeouts, and the spclient retry loop (TryTimes(10) + flush_accesspoint) only reacts to requests that *return* an error — a request that hangs never returns, so the retries never fire. Every other persistent connection has liveness handling (session AP TCP ping/pong, connection handshake timeout, audio-key timeout, dealer websocket ping/pong); the request/response HTTP pool is the one gap. Consistent with this, `ss` showed the AP session (:4070) still ESTAB with empty queues (its keepalive would have caught a dead session within ~80s), pointing at an spclient :443 request as the stuck call. Fix --- Both changes are defensive and hold regardless of whether the above hypothesis is the exact trigger: 1. core/src/http_client.rs: add REQUEST_TIMEOUT (30s) around the response-headers await in request() and the body-collect await in request_body(). On elapse we return Error::deadline_exceeded, which spclient's retry loop already treats as retryable (flush access point + retry). Only control-plane requests (spclient, apresolve, login5) go through here; audio streaming uses request_stream / request_fut and is untouched. This bounds any such hang so the loop can't be blocked forever. 2. connect/src/spirc.rs: reconnect watchdog. On reconnect_rx.changed() arm a 30s deadline (skipped if we registered in the last 5s, to absorb the case where the connection_id push is handled before the reconnect signal). A successful handle_connection_id_update records last_registration_at and disarms. If the deadline elapses without re-registration, force a spirc restart via SavedPlaybackState — exactly like the session-lost path — so main.rs rebuilds the session/dealer, gets a fresh connection_id, and re-registers, while the Player keeps playing from its buffer. This recovers device registration even if the loop stalls or fails to re-register for some other reason. Existing behaviour is preserved: session-TCP-death save/restore, in-place dealer reconnect (no restart / no playback interruption in the common case, since the normal connection_id push disarms the watchdog), connect_established gating, the shutdown path, and the 5-per-10-min restart rate limit. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
get_url() got a timeout in the previous commit, but connect() (TCP/TLS/ websocket handshake) could still hang indefinitely on a blackholed host, silently stalling reconnection with no signal to consumers. Bound it with the same 30s step timeout, and select against dealer closure so close() isn't blocked by an in-flight handshake. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The saved-state early return skipped the dealer close that the normal shutdown path performs. The abandoned dealer's run task then kept reconnecting its websocket every 10s forever, pinning the old Session (via the get_url closure) and leaving a duplicate live dealer connection for the same device that could swallow Spotify pushes — one leak per reconnect cycle on a flaky network. Close it in a spawned task rather than inline: a graceful close can take tens of seconds on a dead connection and must not delay the restart. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Tolerating a failed handle_connection_id_update after the first successful registration left no retry path: no further connection_id push arrives without another dealer reconnect, and the watchdog may not be armed (e.g. the reconnect was judged already-handled). The device would silently stay unregistered. Arm the reconnect watchdog on failure so a restart recovers the registration if no later push succeeds first. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…check Whether a reconnect still needed re-registration was judged by wall clock: a registration within the last 5s suppressed the watchdog. That races — a registration made on the old websocket just before it died would suppress recovery for a genuinely new connection, and if that connection's connection_id push never arrived the device silently stayed unregistered. Instead, bump the reconnect generation on the receive task before any message of the new connection is dispatched, and record the generation each successful registration was made under. On a reconnect signal, the watchdog is skipped only if we already registered under that exact generation. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…limit Watchdog-forced and session-loss restarts return saved playback state and previously counted against RECONNECT_RATE_LIMIT like any unexpected shutdown: persistent re-registration failure could exit(1) the process within minutes, killing playback that was still running. When the rate limit is exceeded but there is playback to preserve, delay the next reconnect attempt by 2 minutes and keep trying instead of exiting. Restarts without saved state keep the old exit behavior, so pathological restart loops still terminate. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The 30s whole-body timeout on request_body also covered full-payload downloads (spclient request_url, audio previews), which can legitimately take longer than 30s on slow links. Read the body frame by frame and apply the timeout to the gap between frames instead: transfers that keep making progress complete, while a half-open connection still errors out within 30s. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Consumers subscribe through DealerManager::reconnect_receiver; the Dealer-level accessor had no callers. Dropping it removes the reconnect_tx field, the extra create_dealer! parameter, and the sender pre-clone at both launch sites — the sender now flows straight to run(). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The Pi 3B soak device disappeared from Spotify Connect and got stuck in an endless dealer reconnect loop that never recovered on its own — one `Timed out connecting to dealer.` every ~40s (30s RECONNECT_STEP_TIMEOUT + 10s RECONNECT_INTERVAL), 42 consecutive attempts over 28 minutes with zero successes, ended only by manually disabling IPv6 on the device. What the logs establish ----------------------- 14:54:02 WARN dealer] Websocket peer does not respond. 14:54:33 ERROR dealer] Timed out connecting to dealer. 14:55:13 ERROR dealer] Timed out connecting to dealer. [... every ~40s, 42 attempts, zero successes, until manual recovery ...] - No `Failed to resolve dealer URL` / `Timed out resolving dealer URL` ever appeared: get_url() succeeded every cycle. Only the TCP/TLS/ websocket connect() step timed out. - No `session lost, saving playback state` appeared: the AP session stayed valid, so the session-lost recovery path never triggered. - The spirc reconnect watchdog never armed either — it arms on the dealer's *successful*-reconnect notification, which requires a connect() to succeed first. Nothing escalated; the device silently stayed unregistered. Live diagnosis on the stuck device ---------------------------------- `ss -tnp` on the still-running process showed the smoking gun — a never-completing IPv6 SYN, while the AP session sat healthy on IPv4: ESTAB 192.168.8.125:41816 104.199.65.9:4070 (AP session, IPv4) SYN-SENT [2a0d:e487:...]:54410 [2600:1901:1:510::]:443 (dealer attempt, IPv6) The network had a blackholed IPv6 path (router advertised a default route via RA, but v6 traffic was silently dropped): $ getent ahosts gew1-dealer.spotify.com # AAAA first, A second 2600:1901:1:a98:: STREAM gew1-dealer-ssl.spotify.com 35.186.224.33 STREAM $ curl -6 https://gew1-dealer.spotify.com/ # times out after 10s curl: (28) Connection timed out after 10002 milliseconds $ curl -4 https://gew1-dealer.spotify.com/ # fine: 401 in 0.23s $ ping -6 2600:1901:1:510:: # 100% packet loss Root cause ---------- socket::connect() used TcpStream::connect((host, port)), which tries the resolved addresses *sequentially*, each bounded only by the OS SYN timeout (~130s on Linux). With the AAAA record first and its SYNs blackholed, the v6 attempt alone exceeds the dealer's 30s step timeout, so the IPv4 fallback is never reached — and every retry starts over at v6. get_url() kept succeeding because apresolve goes through the hyper HTTP client (pooled connections), masking the problem. This is an interaction with the earlier step-timeout commit: without it the sequential connect would have hung ~130s on v6 and then succeeded via v4. That commit fixed a worse failure (indefinite hang mid- handshake, no signal to consumers); this one makes the two compose. Confirmation: disabling IPv6 on the device (sysctl disable_ipv6=1) made the *still-running* process recover on its next retry cycle — v6 now fails instantly with ENETUNREACH and the sequential fallback reaches v4: 15:22:10 ERROR dealer] Timed out connecting to dealer. 15:22:21 WARN dealer] Dealer reconnected; notifying consumers. 15:22:21 INFO spirc] Dealer reconnected; awaiting new connection_id. 15:22:21 WARN spirc] session lost, saving playback state for recovery: Stopped 15:22:23 INFO spirc] DIAG registered: [...] transfer_data=2402 bytes (The AP session had also died silently; the dealer reconnect event is what woke spirc to notice it — after which the existing save/restore path re-registered the device.) Fix --- Resolve addresses explicitly with lookup_host() and give each address its own bounded attempt (CONNECT_ATTEMPT_TIMEOUT, 3s), returning the first success and the last error if all fail. Apply the same loop to the proxy path, which relied on the same OS-timeout behaviour. 3s per address is long enough for any healthy SYN (well under 1s in practice) and short enough that blackholed-v6 + working-v4 completes within both the AP connection's existing 5s outer timeout (v6 gives up at 3s, v4 connects at ~3.2s) and the dealer's 30s step timeout. Full happy-eyeballs racing isn't warranted here. Verification ------------ - cargo test -p librespot-core passes, including tests/connect.rs which performs a real AP connection through the changed code path. - Healthy-network check: the fixed binary was built and started on the same Pi 3B after a reboot restored its IPv6 (the router issued a new prefix; v6 to the dealer then worked). It authenticated, connected the dealer (over IPv6), and registered normally — no regression on a working dual-stack network. - Incident reproduction: with the fixed binary running and its dealer websocket established over IPv6, the original blackhole was recreated on the device with an nftables rule that silently drops all outbound IPv6 TCP to port 443 (SYNs vanish with no RST, exactly like the incident — unlike a blackhole route, which returns an immediate error and never exercises the timeout): nft add table ip6 blackholetest nft add chain ip6 blackholetest output '{ type filter hook output priority 0 ; }' nft add rule ip6 blackholetest output tcp dport 443 drop This both kills the established v6 websocket (ping check trips) and makes the reconnect's AAAA-first attempt hang in SYN-SENT, the exact incident condition. Where the unfixed binary looped for 28 minutes until manual intervention, the fixed binary recovered in 4 seconds: 16:01:29 WARN dealer] Websocket peer does not respond. 16:01:32 WARN dealer] Dealer reconnected; notifying consumers. 16:01:32 INFO spirc] Dealer reconnected; awaiting new connection_id. 16:01:33 INFO spirc] DIAG registered: [...] transfer_data=2402 bytes `ss -tn` confirmed the new dealer websocket was established over IPv4 (35.186.224.x:443), i.e. the v6 attempt was abandoned at the 3s bound and the fallback address was used. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The restored SpircTask only called get_player_event_channel() after
client_token(), connect() and login5() — several seconds of awaits.
Player events emitted in that window went to no subscriber and were
lost: on a Pi 3B, a track load whose audio key rode the dying AP
connection failed 4s into the new session's setup, its Unavailable
event was dropped, and spirc sat in LoadingPlay forever, registered
as "playing at 0:00" while silent. EndOfTrack in the same window
loses the play queue the same way.
Subscribe first thing after restoring state: subscription is just a
player command, needs no session, and the player-events select arm is
not gated on connect_established, so buffered events are handled as
soon as the task loop starts.
Field-validated on a second device (Pi Zero 2W, different network,
2026-07-23): an AP connection died while the current track — fully
buffered and playing since 13:33:11.6, 164.8s long — had ~20s left,
and the preloaded next track's audio key rode the dead connection.
Both decisive events fired inside the ~13s restore window, before
session setup finished: the doomed preload's failure, and EndOfTrack
for the current track at ~13:35:56 (13:33:11.602 + 164.823s). The
early subscription buffered them; on loop start the restored spirc
replayed them, skipped the tracks whose loads had died with the old
session, and loaded the next viable track on the new session — audio
resumed ~10s after the old track ran out:
13:35:45 WARN librespot_connect::spirc] session lost, saving playback state for recovery: Playing { nominal_start_time: 1784813591602, preloading_of_next_track_triggered: true }
13:35:46 INFO librespot_connect::spirc] Spirc[2] restoring saved playback state
13:35:48 WARN librespot_playback::player] Unable to load key, continuing without decryption: Operation aborted { audio key response timeout }
13:35:56 ERROR librespot_playback::player] Unable to read audio file: Symphonia Decoder Error: end of stream
13:35:58 INFO librespot_core::session] Authenticated as 'antoinecellerier' !
13:35:59 INFO librespot_connect::spirc] re-registering with active playback state: LoadingPlay { position_ms: 0 }
13:36:00 INFO librespot_playback::player] Loading <Anomalie bleue> with Spotify URI <spotify:track:6z4n862KhNJNWDYSn4aLL5>
13:36:06 INFO librespot_playback::player] <Anomalie bleue> (232178 ms) loaded
The saved state was Playing; it advancing to LoadingPlay before
re-registration is the buffered EndOfTrack being handled. Without this
fix both events die with the old subscriber's channel and the device
re-registers as Playing a track that has already ended — registered,
silent, and stuck exactly as described above.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
A saved LoadingPlay/LoadingPause means the old session died mid-load; that load's audio-key request rode the dead AP connection and will fail — possibly before the new spirc subscribes to player events, in which case nothing ever advances the state. Don't trust it: clear the stale play_request_id (so the old load's late events are ignored) and re-issue the load on the new, authenticated session. The Player cancels the old loader when the new Load command arrives; if the old load had already started playing, the Load path just seeks and continues. Playing/Paused restores are untouched — running audio is never interrupted. Seen on a Pi 3B: audio key timed out on the dying AP connection, the player continued without decryption, the load failed with a decode error during the spirc restart window, and the restored spirc sat in LoadingPlay forever — registered and healthy, playing nothing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
HttpClientError's status mapping sends 502 BAD_GATEWAY into the catch-all Error::unknown arm, so SpClient::request_with_options — which retries only ErrorKind::Unavailable and DeadlineExceeded — gives up after a single attempt, while an identical 503 gets up to 10 back-to-back tries (RequestStrategy::TryTimes(10)). Seen on a Pi 3B during the 2026-07-14 Spotify platform outage (https://community.spotify.com/t5/Ongoing-Issues/Downtime-July-14th-2026-Issues-with-the-Spotify-app/idi-p/7500300): every Connect takeover died on a single, unretried 502 from the context-resolve endpoint, hours apart: 12:17:33 ERROR librespot_connect::spirc] Unknown error { Response status code: 502 Bad Gateway } 14:38:12 ERROR librespot_connect::spirc] Unknown error { Response status code: 502 Bad Gateway } ("Unknown error" is ErrorKind::Unknown's Display prefix: the 502 came back as Unknown, hit request_with_options' `_ => break` arm, and was the first and only attempt.) Throughout the same outage, 503s on other endpoints at least got the internal retries before surfacing: 12:00:09 ERROR librespot_playback::player] Unable to load audio item: Error { kind: Unavailable, error: StatusCode(503) } A 502 from the edge is as transient as a 503; map it to Error::unavailable so it gets the same bounded, per-call retry. Note for review: this affects all spclient endpoints, not just context-resolve. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
When a context fetch fails, ContextResolver marks that exact
ResolveContext unavailable for RETRY_UNAVAILABLE (1 hour), and add()
drops every re-add of it in that window with only a debug!() log —
invisible at the default log level. There is no distinction between "a
404 said this context doesn't exist" and "one 502 during an outage":
after a single failed fetch, even a deliberate user action (taking the
device over again, sending a new load) is silently ignored for up to an
hour. Nothing else retries, so the failure is effectively final.
Seen on a Pi 3B during the 2026-07-14 Spotify outage (see previous
commit): a takeover's context-resolve 502'd once at 12:17:33 and the
playlist context was blacklisted. When the next takeover arrived after
the window had expired, it got exactly one fresh resolve — which 502'd
again (the outage was still ongoing), re-blacklisting the context for
another hour. The device played the single track embedded in the
transfer data and died at the end of it:
14:38:01 INFO spirc] DIAG connect-state command 'endpoint: transfer' from 24f51d66[...] (yoga [spotify PC desktop / COMPUTER])
14:38:12 ERROR spirc] Unknown error { Response status code: 502 Bad Gateway }
14:40:32 INFO spirc] Not playing next track because there are no more tracks left in queue.
14:40:32 WARN spirc] failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
Net effect during an outage: one resolve attempt per context per hour,
no matter how often the user retries, with nothing in the logs
explaining why retries do nothing.
Add ContextResolver::add_forced(), which removes the unavailable entry
before adding, and use it for the user-initiated resolve paths only:
transfer (context and autoplay) and the load command. A deliberate user
action always gets a fresh resolve attempt — bounded by how fast a
human taps, so this cannot turn into request churn. Automatic re-adds
(dealer context updates, playlist modifications, autoplay refill) keep
honoring the blacklist, which is what prevents event-driven loops on a
persistently failing context. Also raise add()'s drop log from debug to
info, including how long ago resolving failed and when it will be
retried — the silent drop is the main reason this took hours to
diagnose.
Unit tests cover the blacklist drop and expiry, the forced bypass, and
that queue dedup is unaffected (tokio start_paused time to step over
the 1-hour window).
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
transfer_state is consumed only on the successful-resolve path
(ContextResolver::try_finish -> finish_transfer). When the resolve
fails, handle_next_context just logged the error: the pending transfer
leaked, and play_status — which only leaves LoadingPlay/LoadingPause
via a Playing/Paused/Stopped player event that will never come — kept
reporting a load that could never finish. The device stayed active in
the cluster, indistinguishable from one that is about to play.
Seen on a Pi 3B during the 2026-07-14 Spotify outage: a takeover from a
desktop client raced the outage — the transfer arrived, the cluster
made the Pi the active device, and six seconds later the context
resolve 502'd. That error was the last log line for 2 hours 21 minutes:
12:17:26 INFO spirc] DIAG connect-state command 'endpoint: transfer' from 24f51d66[...] (yoga [spotify PC desktop / COMPUTER])
12:17:26 INFO spirc] DIAG transfer: will_start_playing=true, [...] ctx_uri=Some("spotify:playlist:37i9dQZF1EIhMHNZW8S7ky"), current_track=<spotify:track:6ek9SiEj5a65WIs2EV7qiM>
12:17:27 INFO spirc] DIAG cluster update: [...] active_device=<b7d79087[...]> (Pi 3B+)
12:17:33 ERROR spirc] Unknown error { Response status code: 502 Bad Gateway }
14:38:01 INFO spirc] DIAG connect-state command 'endpoint: transfer' [...]
Live inspection of the stuck process showed nothing locally wrong
except the state machine: the AP session was ESTAB, the dealer
websocket was exchanging ping/pong (verified via ss byte counters over
a 40s window), and the process handled events — it was registered,
healthy, silent, and claiming to load forever.
On resolve failure, take the pending transfer_state; if there was one,
or playback is stuck in LoadingPlay/LoadingPause, stop playback and
push the Stopped state so controllers see reality and a retried
takeover or load (which now bypasses the unavailable-context blacklist,
see previous commit) starts from a clean slate. Failures of automatic
context updates while something is playing take the early return
instead: stopping there would interrupt healthy playback over a
background refresh that didn't matter to the audio.
Deliberately no became_inactive(): staying registered (active but
Stopped) keeps the device tappable in clients and preserves volume;
dropping the registration would require a re-discover to recover.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
During a transfer, the current track's load runs concurrently with the
context resolve (handle_transfer queues the resolve and immediately
calls load_track). If the load fails first, the player's Unavailable
event reaches spirc before any context exists: handle_unavailable ->
mark_unavailable ends with fill_up_next_tracks(), whose first step is
get_context() -> StateError::NoContext, so the whole handler errors and
the run loop drops the event. The skip to the next track never happens
— the player's "Skipping to next track" log is only its own wording;
the actual queue advance is spirc's handle_next() after
handle_unavailable(), which is exactly what died.
Seen on a Pi 3B during the 2026-07-14 Spotify outage, one second after
a takeover arrived and while its context resolve was still in flight
(it 502'd six seconds later, see previous commit):
12:17:27 ERROR player] Unable to load audio item: Error { kind: FailedPrecondition, error: ExpectedEntry("data") }
12:17:27 ERROR player] Skipping to next track, unable to load track <SpotifyUri("spotify:track:6ek9SiEj5a65WIs2EV7qiM")>: ()
12:17:27 ERROR spirc] could not dispatch player event: Invalid state { context is not available. type: Default }
(The FailedPrecondition is spclient's extended-metadata response
missing its "data" entry — another face of the same outage.) With the
event gone, play_status stayed LoadingPlay and the device sat silent.
Same family as the lost-events-during-restart fixes (see "subscribe to
player events before session setup" / "re-issue in-flight loads"), one
layer deeper: here the event is delivered fine and then dropped by its
own handler.
When handling an Unavailable event fails with NoContext while a resolve
is pending (transfer in flight or contexts queued), remember the track
and handle it again right after try_finish sets up the resolved context
— at that point mark_unavailable and the skip work. Re-running
mark_unavailable is idempotent: the next/prev removal loops no-op and a
duplicate unavailable_uri entry is harmless. The deferred list is
cleared whenever intent changes (new transfer, load command,
disconnect) or the resolve fails for good (previous commit); and if the
resolve fails, that path already stops the stuck load, so nothing is
lost by dropping the deferral. Any other error from the handler still
propagates as before.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
303026b to
b08a5f7
Compare
What's new since the previous revisionThe branch has been soaking continuously on real devices since the last push. The soak surfaced four distinct field failures the previous revision couldn't recover from — each diagnosed live on the stuck device and fixed in its own commit, with the log evidence and diagnosis written into the commit message — plus one hang found by code review along the way. The earlier review fixups were squashed and the branch rebased onto current
The write-ups below state each problem and fix; the full field evidence is collapsed. New failure modes1. Spirc event loop frozen by an unbounded HTTP request (5adf966) Field evidence: Pi Zero ×2 (2026-07-28), Pi 3B (2026-08-18) — the hypothesized mechanism caught livePi Zero 2W, twice in one evening (22:04 and 23:45 UTC): a TCP reset tore down the dealer websocket and the spclient connection together, so the in-place reconnect succeeded but the re-registration PUT failed with The request-timeout half was validated 2026-08-18 on the Pi 3B: during an evening of ISP flaps, the re-registration PUT hung on a half-open connection — the 30s timeout cut it loose ( 2. Websocket handshake hang during reconnect (bb76d15) Field evidence: Pi 3B ×3 (2026-08-18/19)Three connect attempts during ISP outages hit the step bound ( 3. IPv6 blackhole defeating the reconnect timeout (5fb097a) Field evidence: Pi Zero (2026-08-03), Pi 3B ×6 — including a DNS-hijacking router incidentPi Zero 2W, 2026-08-03: a ~90s WAN outage sent one dealer reconnect attempt at an address that blackholed it, and the per-address bound cut it off after exactly 3s ( It fired six more times on the Pi 3B (2026-08-16/18/19), most tellingly during a 2026-08-16 router incident that hijacked DNS: the dealer connect was first refused on a self-signed certificate (native-tls correctly declining the interception page), then a follow-up attempt was routed to a blackholed private address and bounded at 3s ( The original incident also validated the recovery machinery end-to-end: restoring connectivity made the stuck (unfixed) process recover by itself on its next retry cycle. 4. Player events lost during the spirc restart window → registered-but-silent (a411289, bd93e18) Field evidence: Pi Zero (2026-07-23), Pi 3B ×3 (2026-08-15/16)The trigger pattern: the load's audio-key request rides the dying AP connection and times out (the player then "continues without decryption", upstream behavior), so the load is doomed before the restore begins. Pi Zero 2W (different network), 2026-07-23: an AP connection died while the current track had ~20s left, and both decisive events — the doomed preload's failure and the current track's The second fix (bd93e18) validated three times on the Pi 3B (2026-08-15 ×2, 2026-08-16): each time a session died with a takeover load in flight (twice with the audio-key-timeout signature), the restored spirc logged Related: HTTP body reads now time out on stall rather than total transfer time (ceff4a8), so slow-but-progressing transfers aren't killed while genuine stalls still are. 5. Context-resolve failure during a transfer → wedged, unrecoverable for an hour (6b84d8a, 999ffab, c3b1843, b08a5f7)
A design note for reviewers: the absence of automatic retry/backoff here is a product decision, not an oversight. Failing while Spotify is down is acceptable; what these commits guarantee is that the device never ends up in a locally unrecoverable state and that every fresh user action gets a full, honest attempt. (Known, accepted: a session-lost restart still drops queued resolves and Field soakTwo devices on different networks: the Pi Zero 2W provided the long steady-state baseline, while the Pi 3B caught a week of rolling ISP/router failure — DNS outages, TLS connections cut mid-handshake, certificate interception, blackholed routes — and became the stress test the Zero never provided.
("Stall" = a track not followed by its end-of-track, the next load, or an explicit stop. Zero across both soaks.)
Known gaps (documented, not fixed here)Both are upstream-inherited: nothing on this branch touches the code involved. 1. Idle session death is detected late. Occurrence dataSeen 23 times in 19 days on the Zero; 15 episodes over 5 minutes, the longest 10h19m, ~64h cumulative — dealer connected, session dead underneath. The 3B shows the same pattern, e.g. 2026-08-15: session dead from 03:03 until a dealer ping failure surfaced it at 05:00, the device idling registered throughout. 2. Silent server-side eviction with every local signal green (found 2026-08-22; needs one more captured occurrence to design the fix). The Pi Zero dropped out of the Connect picker while everything looked healthy locally: AP session and dealer websocket ESTABLISHED, pings answered every 30s, three successful re-registrations since — each returning a server-parsed Forensics from the live processCluster updates ran 6–275/day through 2026-08-20, then none for 42 hours — spanning a 27-hour websocket during which the cluster's player session visibly changed, so pushes were provably being dropped before they reached the device. Byte counts on the live socket showed nothing but 24-byte pongs, including while a phone opened the app. The three ineffective re-registrations: two dealer reconnects and one full One path stays fatal by design. Hardening and review follow-ups
Temporaryda004f1 adds DIAG-prefixed logging (controller identity, transfer contents, cluster updates) used to diagnose the incidents above. It will be reverted before merge, per its commit message. CIBoth failures on the current run pre-date this branch:
Rebase bookkeeping (2026-08-22)Rebased onto |
|
@antoinecellerier I have to add a personal comment, as this is not really my PR to review nor anything. But as a maintainer of another project I feel the urge to speak up. Posting these pages of AI generated documents is a major problem for open source projects. It's not helpful, because you overwhelm the poor guys who are already struggling to find spare time to work on their side projects. A lot of these reports are just noise. Reading what you just posted will take anyone several minutes - I bet you didn't read it yourself. Now imagine they have other, similar reports to review. Sometimes there are several of them in a day. Then the devs have easily spent an hour just reading and digesting all that stuff, before they even try to get to the code or the suggested changes. Hey, and many of them actually have other things in their life to deal with on the side. Like a paid job, a family, pets, or (imagine!) other hobbies! So please keep things short. Read everything before you post. If you don't understand what you're about to post, don't post. If it takes you several minutes just to read it, shorten it. Do yourself and all of the community a favour and stop posting books nobody wants to or can read. |
Fair enough. Thanks for the feedback. This ended up being more of a mouthful than I initially anticipated it would be when starting a few months back. If there is interest in merging any of it I will do work to chunk it up in smaller pieces. Else it'll just sit here as a research log in case it's useful to anyone else. |
The problem is that just the discussion alone is so verbose (20 pages A4 and counting!), you risk that nobody will actually read it. Some will merge the PR and figure it helped their issue. But maintainers have to be more careful. |
When the dealer websocket connection drops or the session TCP connection dies,
librespot either hangs indefinitely or restarts spirc — stopping playback in
both cases. This PR fixes all observed failure modes so the process recovers
automatically without interrupting audio.
Symptoms before fix
Hang on dealer websocket drop (fixed in 4b7662f):
Spirc's
tokio::select!loop blocked on subscription streams that would neverreceive new messages. The mpsc senders in
SubscriberMapweren't cleaned up onreconnect, so spirc hung indefinitely — requiring a manual process restart.
Unnecessary spirc restart on dealer reconnect (fixed in 29e814a):
After 4b7662f added reconnect notification, spirc broke out of its event loop
on every dealer websocket reconnect to "refresh subscriptions" — even though
the subscription streams survive reconnects on the shared
DealerShared.Playback killed on session TCP loss (fixed in c87079b + c77d8cb):
When the session TCP connection dies,
handle_disconnect()explicitly setSpircPlayStatus::Stoppedand tried to notify Spotify (which failed anyway).The Player was still playing from its buffer, but the new SpircTask started
with a blank
ConnectStateandSpircPlayStatus::Stopped.Commits
4b7662f —
fix: dealer websocket reconnect leaving spirc hung on stale channelsAdd a
watch::Sender<u64>generation counter shared between the dealer and itsconsumers. The dealer increments it on successful reconnect,
get_url()timeout(30s), or
get_url()error. Spirc subscribes beforedealer.start()and breaksout of its event loop on change, triggering the existing auto-reconnect path in
main.rs.Also fixes
get_url()failures propagating via?and terminating the dealerbackground task entirely, rather than retrying.
Changes:
core/src/dealer/mod.rs: watch channel plumbing, 30s timeout onget_url(),retry+signal on errors, signal consumers on reconnect
core/src/dealer/manager.rs: Storewatch::Sender, exposereconnect_receiver()connect/src/spirc.rs: Subscribe to reconnect watch, addselect!branch29e814a —
fix: handle dealer reconnect in-place without restarting spircThe subscription streams survive reconnects because they're registered on the
shared
DealerShared— the new websocket dispatches through the samemessage_handlersmap. After reconnect, the server pushes a newconnection_idwhich
handle_connection_id_update()already handles correctly.Changes:
reconnect_rx.changed(): log and continue instead ofbreakhandle_connection_id_updateerror: log instead ofbreakc87079b —
fix: skip server cleanup on session loss to keep playback aliveWhen
session.is_invalid(), skiphandle_disconnect()(which setsSpircPlayStatus::Stopped),delete_connect_state_request(), anddealer().close()— all of which fail on a dead TCP connection anyway.The Player continues playing from its buffer independently.
c77d8cb —
fix: save and restore playback state across session reconnectsSpircTasksaves itsConnectState,SpircPlayStatus, andplay_request_idinto a
SavedPlaybackStatebefore exiting on session loss.main.rscapturesthis and passes it to
Spirc::with_saved_state()when creating the replacement.The restored SpircTask updates the playback position on the first
connection_id_updateand re-registers with Spotify showing the correct track.Changes:
connect/src/model.rs: AddSavedPlaybackStatestructconnect/src/spirc.rs:Spirc::with_saved_state(), save state on sessionloss, restore on creation, update position in
handle_connection_id_updatesrc/main.rs: Capture saved state from spirc_task, pass to new SpircEvidence after fix
4b7662f — 9 days of logs (Feb 28 - Mar 8):
29e814a + c87079b + c77d8cb — 6 days of logs (Mar 14-20):
Dealer reconnects handled in-place (~20 events, zero spirc restarts):
Session TCP losses recovered with state preserved (5 events):
Summary (Mar 14-20):
Use of AI
This PR was created with GitHub Copilot CLI. Copilot assisted with root cause
analysis, implementation, code review, log analysis, and PR description. I'll
admit to not having any knowledge of Rust which means I'm not able to review
Rust specifics. At a high level the changes seem to make conceptual sense to me
and have proven to have positive effects. Do let me know if this is garbage.