Skip to content

fix: drop a silent accesspoint connection on an unanswered audio key, and 140 s after its last PongAck - #441

Open
leodurandfr wants to merge 2 commits into
devgianlu:masterfrom
leodurandfr:fix/ap-dead-connection
Open

leodurandfr wants to merge 2 commits into
devgianlu:masterfrom
leodurandfr:fix/ap-dead-connection

Conversation

@leodurandfr

Copy link
Copy Markdown
Contributor

When the network path under the accesspoint connection goes away without a FIN or an RST, every track load fails on its audio key until the pong ack check notices, which takes 120 to 240 s after the last PongAck. This PR replaces such a connection as soon as an audio key goes unanswered, and bounds the pong ack check to 140 s.

What goes wrong

  • KeyProvider.Request waits 15 s for an answer and fails (failed retrieving audio key: context deadline exceeded). Nothing closes the connection on that timeout and the player does not retry a load, so the next load's key request goes out on the same dead connection and fails the same way. The 15 s timeout was added in 117b929 for Shannon connection is not re-established on failure #88, so that a request on a broken connection fails instead of waiting forever; it does not replace the connection.
  • The accesspoint pings and the device answers, so the device has no ping of its own to probe the connection with. All it can do is bound the wait for the next PongAck. The check runs on a 120 s ticker and drops the connection once the last PongAck is more than 120 s old, so a silent connection is dropped at the second tick after its last PongAck, 120 to 240 s later (240 to 360 s after a reconnection that has carried no PongAck yet, since a reconnection sets the last PongAck 120 s in the future). The bound is also the expected ping interval itself, with no margin, so a PongAck that comes a moment late drops a working connection whenever a tick falls in between.

Measured on a Raspberry Pi 5 with two links on the same LAN, by disconnecting the wired one (nmcli device disconnect eth0) while Wi-Fi kept LAN and internet access, with skips sent from the Spotify macOS app as a Connect remote. The build was v0.10.5 with #420, #421 and the two fixes I am sending separately (HTTP/2 health check, dealer pong timeout), but not this PR:

12:16:52  eth0 disconnected
12:17:37  next
12:17:52  failed load spotify:track:77lPC0YqxUODd674qz9LmV ... failed retrieving audio key: context deadline exceeded
12:18:23  failed load spotify:track:0xLIu53VONIKcPKcwtBBkd ... failed retrieving audio key: context deadline exceeded   (the player's own advance)
12:18:32  next
12:18:48  failed load spotify:track:25AT3BJHt4jtL3JYoZbqVK ... failed retrieving audio key: context deadline exceeded
12:19:20  did not receive last pong ack from accesspoint, 173s passed
12:19:20  authenticated AP                                   (71 ms later)
12:19:48  next
12:19:48  loaded track "PARADIGM"                           (0.25 s after the skip)

/status reported buffering for 130 s, from the first skip to the first load after the new connection. The new connection authenticated in 71 ms, so that time went into waiting for the old one to be dropped.

Changes

  1. fix: drop an accesspoint connection that leaves an audio key unanswered. A key request left unanswered for 5 s drops the connection it was written to, so recvLoop's reconnection replaces it, and the request is sent once more with 15 s to be answered. librespot gives up on an audio key after 1.5 s (audio_key.rs); 5 s still leaves a live connection plenty of time, and a false alarm costs one reconnection. A load whose key never comes now fails after about 20 s instead of 15 s.
    • Accesspoint.SendConn returns the ConnID the packet was written to, and DropConn(id) closes that connection only if it is still the current one, so a request that gives up late cannot close the replacement. DropConn takes connMu with TryRLock: only a connection in progress holds it for writing, and that one is already replacing the connection, so the caller never waits out a backoff.
    • A packet written to a connection this side has just closed waits for the replacement and is sent on it. Without this, the retry sent right after the drop often reached the closed socket before recvLoop noticed, and failed as a send error. recvLoop's own Pong is written directly, since recvLoop is what does the replacing.
    • Each attempt is a new request with its own sequence number, so a late answer to the first one cannot be taken for the second.
    • A request ended by its caller (a load cancelled by a skip) drops nothing and is not retried.
    • NewAudioKeyProvider takes the four methods it uses as an interface, which *ap.Accesspoint satisfies, so the retry can be tested against a fake.
  2. fix: drop a silent accesspoint connection 140 s after its last PongAck. The connection is dropped 120 s plus a 20 s margin after its last PongAck, a new connection counting as one. A timer armed for that deadline replaces the ticker, so the tick phase no longer adds up to another 120 s. librespot runs the same exchange with a deadline per step and a 20 s safety margin on each (session.rs). The check now drops the connection its deadline belongs to through DropConn; the old closeConn could wait for a reconnection in progress and then close the connection that reconnection had just made.

The second commit uses DropConn from the first. The first builds and passes the tests on its own, and so does the second on top of it.

On the device

Same setup and cut, on the same build plus this PR's two commits:

13:02:04  eth0 disconnected
13:02:35  next
13:02:40.635  no aes key for file 5ea630077ebb962bd493e9e65bcfd8047b8a2967 after 5s, retrying on a new accesspoint connection
13:02:40.650  failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP ... connection refused
13:02:40.704  authenticated AP
13:02:40.823  loaded track "Tell Me How"
without with
loads after the first skip 3 failed, buffering for 130 s loaded 5.8 s after the skip
accesspoint connection replaced 149 s after the cut (pong ack check, 173 s after the last PongAck) 37 s after the cut, at the first unanswered key
later skips during the cut failed until the connection was replaced loaded 0.26 s and 0.37 s after the skip

This run did not exercise the 140 s PongAck deadline, since the key retry replaced the connection first. Over the 51 minutes the build then ran on the device, on accesspoint connections that lived up to 21 minutes, the PongAck check never fired, so 140 s was not tighter than the accesspoint's actual ping interval there.

An expected side benefit, not measured: before this PR, the device's journal logged did not receive last pong ack from accesspoint, 120s passed six times between 2026-11-04 and 2026-11-07. Two came 87 s and 12 s after the wired link was disconnected on purpose. The other four came with no change to the wired link in the journal (one came three minutes after the Wi-Fi link was reconnected), and a new connection authenticated within 0.4 s each time. PongAcks are not logged, so whether those four connections were still alive cannot be told; if they were, the 20 s margin removes those reconnections.

Tested

  • Unit tests (test_unit), each seen failing with its part undone:
    • TestKeyRequestIsRetriedOnANewConnectionWhenTheFirstWentSilent: the key comes on the second connection, the first one is dropped. With the single 15 s attempt it fails with aes key request timed out: context deadline exceeded.
    • TestKeyRequestEndedByItsCallerKeepsTheConnection: a caller's deadline drops nothing and sends nothing again.
    • TestDropConnClosesOnlyTheConnectionItNames, TestDropConnDoesNotWaitForAReconnection.
    • TestSendAfterDropConnWaitsForTheReplacement: drops the connection of a running recvLoop and sends at once, 300 times. Without the wait it fails on the first drop with io: read/write on closed pipe.
    • TestSilentConnectionIsDroppedSoonAfterItsLastPongAck: a fake accesspoint end pings every 120 s and acknowledges each Pong for 10 minutes, during which the connection must stay open, then goes silent; the connection must be closed at most 140 s after its last PongAck. With the old ticker it fails with a silent connection was dropped 3m59s after its last PongAck, want at most 2m20s; with the margin set to -30 s, its live half fails, so it also guards against a bound tighter than the ping cadence.
  • gofmt -l ., go vet -tags "test_unit test_integration" ./..., go build ./... and go test -count=1 -tags "test_unit test_integration" ./... are clean at each commit. Not run under -race: the race detector does not run on this kernel (arm64 with a 47-bit address space).

🤖 Generated with Claude Code

leodurandfr and others added 2 commits November 7, 2026 14:52
Measured on a device after a network change (its wired link disconnected,
wifi still up): three track loads in a row failed with "failed retrieving
audio key: context deadline exceeded", and nothing played for 130 s. The
key requests went out on the accesspoint connection bound to the address
that had gone, which nothing answered and nothing closed until the pong
ack check fired, 173 s after the last PongAck. A new connection then
authenticated within 70 ms and the next load succeeded.

Request waited 15 s for an answer and failed. Nothing closed the
connection on that timeout and the player does not retry a load, so every
load failed the same way until the pong ack check noticed.

A key request left unanswered for 5 s now drops the connection it was
written to, so that recvLoop's reconnection replaces it, and is sent once
more with 15 s to be answered. That covers the reconnection, since writing
the retry waits for connMu while a reconnection holds it. The first wait
is shorter because a retry follows: a live accesspoint answers in a round
trip (librespot gives up on a key after 1.5 s), and a false alarm costs
one reconnection.

- The connection is named by the ConnID that SendConn returns, so a
  request that gives up after its connection was replaced does not close
  the replacement. DropConn only closes the socket, which has no
  handshake, and takes connMu with TryRLock: only a connection in progress
  (Connect, or recvLoop's reconnection) holds it for writing, and it is
  already replacing the connection. So the caller never waits out a
  backoff, and no lock order is set against recvLoop.
- A packet written to a connection this side closed (by DropConn or
  closeConn) is sent again once that connection is replaced. recvLoop only
  takes connMu for the reconnection after its read has failed, so the
  retry, sent right after the drop, would otherwise often reach the closed
  socket, fail as a send error, and fail the load the old way. recvLoop's
  own Pong is written directly, since recvLoop is what does the replacing.
- Each attempt is a new request with its own sequence number and response
  channel, so a late answer to the first attempt reaches only that
  attempt's channel, which nothing reads any more.
- A request ended by its caller, such as a load cancelled by a skip, says
  nothing about the connection: it drops nothing and is not retried.
  Handing the request to the pump also stops when the caller's context
  ends, because the pump's write waits for any reconnection in progress.
- NewAudioKeyProvider takes the four methods it uses as an interface,
  which *ap.Accesspoint satisfies, so the retry can be tested against a
  fake accesspoint.

Tests: a fake accesspoint for the key provider, whose connection is either
live or silent until DropConn replaces it, and a fake accesspoint end over
net.Pipe for DropConn. The tests do not compile against the parent, which
has no SendConn or DropConn. Each was then seen failing on this commit
with the matching part undone:
- the parent's single 15 s attempt, with no drop:
  TestKeyRequestIsRetriedOnANewConnectionWhenTheFirstWentSilent fails with
  "aes key request timed out: context deadline exceeded";
- dropping and giving up on the caller's cancellation:
  TestKeyRequestEndedByItsCallerKeepsTheConnection fails with "Should be
  empty, but was [0 1]";
- RLock in place of TryRLock: TestDropConnDoesNotWaitForAReconnection
  fails;
- no ConnID check: TestDropConnClosesOnlyTheConnectionItNames fails;
- the parent's SendConn: TestSendAfterDropConnWaitsForTheReplacement,
  which drops the connection of a running recvLoop and sends at once, 300
  times, fails on the first drop with "failed writing packet: io:
  read/write on closed pipe". It passes 20 runs in a row with the fix, and
  10 with GOMAXPROCS=1.

Floor: gofmt -l . (empty), go vet -tags "test_unit test_integration"
./..., go test -count=1 -tags "test_unit test_integration" ./..., all
passing. Not run under -race: the race detector does not run on the build
host (TSan rejects its 47-bit arm64 address space).

On a device, with this and the next commit backported to v0.10.5, after
the same network change: the first key request after the cut logged "no
aes key for file ... after 5s, retrying on a new accesspoint connection",
a new connection authenticated within 70 ms, and the track loaded 5.8 s
after the skip that asked for it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
The pong ack check ran on a 120 s ticker and closed the connection once
the last PongAck was more than 120 s old, and a new connection set that
PongAck 120 s in the future. So a connection that went silent was dropped
at the second tick after its last PongAck, 120 s to 240 s later, or 240 s
to 360 s after a reconnection that had not carried one yet. Measured on a
device after a network change: the check fired 173 s after the last
PongAck it had recorded, and the three track loads tried before then
failed on audio keys that never came.

In this protocol the accesspoint pings and the device answers, so the
device cannot probe a connection itself: it can only bound the wait for
the next PongAck. The check expected one at least every 120 s and allowed
nothing past that, so a PongAck that came even a moment late dropped a
working connection whenever a tick fell in between. librespot
(core/src/session.rs) adds a 20 s safety margin to each of its keep-alive
deadlines.

The connection is now dropped 120 s plus a 20 s margin after its last
PongAck, a new connection counting as one. A timer armed for that
deadline replaces the ticker, so the phase of a tick no longer adds up to
another 120 s. The check drops the connection its deadline belongs to
through DropConn, so it can no longer close a replacement. It used to do
that: closeConn waited for a reconnection in progress, then closed the
connection that reconnection had just made.

Tests: TestSilentConnectionIsDroppedSoonAfterItsLastPongAck uses a fake
accesspoint end that pings every 120 s and acknowledges each Pong for 10
minutes, during which the connection must stay open. The fake then goes
silent, and the connection must be closed at most 140 s after its last
PongAck. With the parent's ticker (and pongAckMargin declared so the test
compiles), it fails with "a silent connection was dropped 3m59s after its
last PongAck, want at most 2m20s". With the margin set to -30 s, its live
half fails ("a connection whose pongs were acknowledged was dropped after
1m31s"), so it also guards a bound tighter than the ping cadence.
TestPongAckTickerStopsWhenConnNil now sleeps past the new deadline, so it
still exercises the check firing with no connection.

Floor: gofmt -l . (empty), go vet -tags "test_unit test_integration"
./..., go test -count=1 -tags "test_unit test_integration" ./..., all
passing. Not run under -race: the race detector does not run on the build
host.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant