fix(iouring): never arm a second recv on a connection that already has one (#484) - #560
Conversation
…s one (#484) The WebSocket backpressure pause submits an ASYNC_CANCEL for the armed recv and marks the connection paused. The cancel has not landed yet. A handler that drains below the low watermark before it does makes drainDetachQueue take the resume branch, which called prepareRecv unconditionally — leaving two recvs in flight on one socket. Both target cs.buf, the per-connection buffer, so the kernel's second write lands on top of the first one's unread bytes. The WebSocket parser then reads a length field at the wrong offset and reports a garbage connection index. Multishot is immune: each completion carries its own provided-ring buffer, so two in-flight recvs cannot overwrite each other. prepareRecv now declines the second arm and reports success. "A recv is armed for this conn" is the postcondition every caller acts on, so a false would make them set needsRecv and retry from the dirty list forever. The driver path has carried the same guard since it was written. The dirty-list retry gets an explicit recvArmed check of its own because it calls pickRecvTarget, which MUTATES cs.recvIntoBody: computing a target for an arm that is about to be declined would route the in-flight recv's CQE through the direct-body path. Second defect in the same window: a pause withdrawn before the cancel lands leaves -ECANCELED arriving with recvPaused already false, so handleRecv fell through to the generic negative-result path and closed a healthy connection. recvCancelPending marks a cancel this worker asked for so that CQE re-arms instead. Every other cancelConnOps caller nils w.conns[fd] or sets closing first, so no other cancellation reaches this branch. Measured on the io_uring single-shot variant, 24 runs each, 4 workers, memlock 128 MiB. Runs reporting frame corruption: 2 of 24 before, 0 of 24 after. Total single-shot failures 8 of 24 before, 4 of 24 after; the remaining four report closeTimeout, protocol errors and one frame-count mismatch, all with parseErr zero, which is a different signature. recv_arming_test.go fails on a control build with the guard removed (ring pending 1 to 2) and passes with it.
Correcting the measurement table in the descriptionThe before/after table above is wrong and I am withdrawing it. The mechanism, the fix and the unit-test negative control all stand; the failure-rate numbers do not. The trap. Re-measured properly, 24 runs of the single-shot variant on a clean tree carrying only this change, capturing every test log line:
So the two signatures separate cleanly. I do not yet have a clean-tree baseline measured the same way, because the containers holding the earlier logs were removed before I noticed the summary-line problem. A 24-run baseline on The |
Like-for-like baseline, and what it does and does not show24 runs of the single-shot variant on a clean
So the corruption signature does not reproduce on either clean tree at this sample size. The two runs that showed it were on the ledger-instrumented build, where the detector's stderr writes changed the timing enough to widen the window — the same instrumentation moved the multishot failure rate from 0 of 24 to 5 of 24. I am not going to claim a failure-rate improvement from a signature that the baseline never produced. What the measurement does support, and what this PR rests on:
The Race check: the full websocket suite under |
Race baseline: the
|
Targeted control on the pause/cancel test: pre-existing, and no worse here
Same assertion on both, That was the last thing gating this PR. Summary of what the merge rests on:
The |
…t the BP that opens the #484 window Adds four engine-wide witnesses to the io_uring worker and exports them through engine.EngineMetrics, plus a per-conn recvOutstanding count: RecvResumeWhileCancelPending resume processed with recvCancelPending set RecvResumeWhileRecvInFlight ...and the cancelled recv still armed (the exact celeris#484 window; the pending flag alone also counts resumes after a cancel that MISSED, so it over-approximates ~1000x) RecvArmDeclined prepareRecv declined an arm (recvArmed) RecvDoubleArmed a second recv SQE placed on one conn (recvOutstanding reached 2), any site RecvCQEUnaccounted terminal recv CQE for a live conn with recvOutstanding == 0: a kernel-held recv the bookkeeping never counted. The only witness independent of cs.recvArmed. Direct atomic adds, not per-iteration batches: the batch flush runs before drainDetachQueue and is skipped when the loop returns, and these are per-event invariants where one event refutes. The WS484 oracle reads them after settle() and hard-asserts RecvDoubleArmed == 0 and RecvCQEUnaccounted == 0 on io_uring. Two new socketpair tests drive the real call sites (drainDetachQueue pause -> resume before any reap -> -ECANCELED re-arm -> data CQE), and the stale bookkeeping case the guard cannot see. Measured (docker golang:1.27, kernel 7.0.12-linuxkit, 4 cpus, memlock 128 MiB, workers=4 in every run, single-shot io_uring subtest ALONE, 96 conns x 4 bursts x 16000 frames, no -race). N=12 per build per BP; control = guard turned into a count + dirty-list guard reverted: BP build windows(InFlight) doubleArmed cqeUnaccounted parseErr PASS 8 control 12 in 9/12 runs 6441 0 11 (8 runs) 3/12 8 fixed 12 in 7/12 runs 0 0 0 12/12 16 control 6 in 5/12 2818 0 4 (4 runs) 7/12 16 fixed 9 in 3/12 0 0 0 12/12 32 control 9 in 3/12 6322 0 7 (3 runs) 9/12 32 fixed 4 in 3/12 0 0 0 12/12 256 control 0 in 0/12 0 0 0 12/12 256 fixed 0 in 0/12 0 0 0 12/12 1e6 both 0 0 0 0 24/24 8 stale 4 in 4/12 0 131760 4 (4 runs) 0/12 Chosen BP = 8. At the fixture default (256) neither build enters the window in 24 runs, so the pre-existing 0/24 vs 0/24 had no power. On the fixed tree at BP=8 the window is entered 12 times and RecvDoubleArmed and RecvCQEUnaccounted stay 0 with parseErr 0; on the control every window entry places a second recv and the twin recvs stay doubled for the rest of the connection (doubleArmed is amplified, armDeclined equals the window count) and 8 of 12 runs corrupt frames. The stale-bookkeeping build (recvArmed cleared after the pause cancel) corrupts frames in 4 of 12 runs with RecvDoubleArmed 0 in all of them and RecvCQEUnaccounted ~11000 per run: the kernel-side witness sees what the userspace guard cannot. Unit tests under -race: fixed tree 3/3 pass; control fails TestPrepareRecvRefusesSecondArm (pending 1->2) and TestResumeBeforeCancelLandsPlacesNoSecondRecv (doubleArmed 1); the stale build fails the honest window test and passes the witness test.
…t the BP that opens the #484 window (#597) Adds four engine-wide witnesses to the io_uring worker and exports them through engine.EngineMetrics, plus a per-conn recvOutstanding count: RecvResumeWhileCancelPending resume processed with recvCancelPending set RecvResumeWhileRecvInFlight ...and the cancelled recv still armed (the exact celeris#484 window; the pending flag alone also counts resumes after a cancel that MISSED, so it over-approximates ~1000x) RecvArmDeclined prepareRecv declined an arm (recvArmed) RecvDoubleArmed a second recv SQE placed on one conn (recvOutstanding reached 2), any site RecvCQEUnaccounted terminal recv CQE for a live conn with recvOutstanding == 0: a kernel-held recv the bookkeeping never counted. The only witness independent of cs.recvArmed. Direct atomic adds, not per-iteration batches: the batch flush runs before drainDetachQueue and is skipped when the loop returns, and these are per-event invariants where one event refutes. The WS484 oracle reads them after settle() and hard-asserts RecvDoubleArmed == 0 and RecvCQEUnaccounted == 0 on io_uring. Two new socketpair tests drive the real call sites (drainDetachQueue pause -> resume before any reap -> -ECANCELED re-arm -> data CQE), and the stale bookkeeping case the guard cannot see. Measured (docker golang:1.27, kernel 7.0.12-linuxkit, 4 cpus, memlock 128 MiB, workers=4 in every run, single-shot io_uring subtest ALONE, 96 conns x 4 bursts x 16000 frames, no -race). N=12 per build per BP; control = guard turned into a count + dirty-list guard reverted: BP build windows(InFlight) doubleArmed cqeUnaccounted parseErr PASS 8 control 12 in 9/12 runs 6441 0 11 (8 runs) 3/12 8 fixed 12 in 7/12 runs 0 0 0 12/12 16 control 6 in 5/12 2818 0 4 (4 runs) 7/12 16 fixed 9 in 3/12 0 0 0 12/12 32 control 9 in 3/12 6322 0 7 (3 runs) 9/12 32 fixed 4 in 3/12 0 0 0 12/12 256 control 0 in 0/12 0 0 0 12/12 256 fixed 0 in 0/12 0 0 0 12/12 1e6 both 0 0 0 0 24/24 8 stale 4 in 4/12 0 131760 4 (4 runs) 0/12 Chosen BP = 8. At the fixture default (256) neither build enters the window in 24 runs, so the pre-existing 0/24 vs 0/24 had no power. On the fixed tree at BP=8 the window is entered 12 times and RecvDoubleArmed and RecvCQEUnaccounted stay 0 with parseErr 0; on the control every window entry places a second recv and the twin recvs stay doubled for the rest of the connection (doubleArmed is amplified, armDeclined equals the window count) and 8 of 12 runs corrupt frames. The stale-bookkeeping build (recvArmed cleared after the pause cancel) corrupts frames in 4 of 12 runs with RecvDoubleArmed 0 in all of them and RecvCQEUnaccounted ~11000 per run: the kernel-side witness sees what the userspace guard cannot. Unit tests under -race: fixed tree 3/3 pass; control fails TestPrepareRecvRefusesSecondArm (pending 1->2) and TestResumeBeforeCancelLandsPlacesNoSecondRecv (doubleArmed 1); the stale build fails the honest window test and passes the witness test.
…ng (celeris#596) (#602) cs.recvCancelPending was never retired when the backpressure pause's ASYNC_CANCEL MISSED -- the recv completed with data before the cancel ran, or nothing was armed -- so the flag stopped describing "a cancel is in flight for this conn's recv". The resume branch reads it to witness the celeris#484 window, and counted every resume after the first missed cancel: RecvResumeWhileCancelPending 11179 / 10721 / 9769 at MaxBackpressureBuffer=8 and 5975 / 6045 / 5996 at 16, against a real RecvResumeWhileRecvInFlight of 0 or 1 (origin/main bef00fc, WS #484 oracle, io_uring single-shot, 3 runs per BP). The issue's premise -- "the cancel's -ENOENT CQE is tagged udProvide and dropped" -- is not what the kernel does. Probed on 7.0.12: with IORING_ASYNC_CANCEL_ALL a cancel that matched nothing completes as res == 0, a SUCCESS, so CQE_SKIP_SUCCESS suppressed the completion entirely and there was no CQE to drop. The miss was unobservable, not merely discarded. Mechanism: * the pause's cancel is now submitted REPORTED (prepCancelUserDataReported, no CQE_SKIP_SUCCESS) and tagged udRecvCancel -- a conn-bound tag, so it passes the generation gate -- instead of the udProvide "drop it" sentinel. One extra CQE per backpressure pause; nothing on the per-request path changes. * handleRecvCancel retires the cancel when it cancelled nothing (res <= 0, covering both res == 0 and -ENOENT) and leaves it outstanding when it did (res > 0, or -EALREADY), because then the recv's own -ECANCELED is coming and handleRecv's re-arm branch (the #484 fix #560 guards) still needs it. * recvCancelPending becomes a COUNT. A conn that pauses, resumes and pauses again before the ring drains has two cancels in flight and they resolve in either order; as a bool the one that MISSED cleared the state the one that HIT still needed, and that -ECANCELED then fell through handleRecv's generic negative-result path and closed a healthy connection mid-stream. That is not theoretical: the bool-valued intermediate version failed the oracle once in 12 runs at BP=8 with parseErr=1 (io.ErrUnexpectedEOF, conn 66). Exactly one retirement per cancel, either from its own completion or from the -ECANCELED it caused. Measured with the merged oracle (TestBackpressureInboundSequenceIntegrity, io_uring single-shot only, N=12 per BP): BP=8 RecvResumeWhileCancelPending 0 in all 12 runs (was ~10^4) BP=16 0 in 11 runs, 1 in the twelfth -- the run that also reported RecvResumeWhileRecvInFlight=1, i.e. the two witnesses now agree both RecvDoubleArmed=0, RecvCQEUnaccounted=0, parseErr=0, 24/24 PASS framesSent is unchanged within noise (control 5.69/6.04/5.61M vs fix 5.81/5.99/5.63/5.66/5.66M at BP=8). Rigs, both of which fail with the fix reverted: * TestMissedPauseCancelClearsCancelPending -- the miss, written without naming udRecvCancel so the body also runs on origin/main, where it fails on the state assertion. * TestMissedCancelDoesNotRetireASecondOutstandingCancel -- two cancels outstanding, miss resolving first; with retireRecvCancel reduced to bool semantics it reaches closeConn on a healthy conn. * TestResumeBeforeCancelLandsPlacesNoSecondRecv, extended to assert that a cancel which HIT does not retire the state its -ECANCELED needs.
Fixes #484
The defect
The WebSocket backpressure pause submits an
ASYNC_CANCELfor the armed recv and marks the connection paused. The cancel has not landed yet. A handler that drains below the low watermark before it does makesdrainDetachQueuetake the resume branch, which calledprepareRecvunconditionally — leaving two recvs in flight on one socket.Both target
cs.buf, the per-connection buffer, so the kernel's second write lands on top of the first one's unread bytes. The WebSocket parser then reads a length field at the wrong offset and reports a garbage connection index:Multishot is immune, which is why the bug only ever showed on the default single-shot path: each completion carries its own provided-ring buffer, so two in-flight recvs cannot overwrite each other.
How it was found
A detector in
prepareRecvthat logs whenever it is asked to arm a recv on a connection that already has one:paused=truewhile the arm is in progress pins the call site to exactly one place: the resume branch assignscs.recvPaused = desiredafter arming, so the log still sees the old value. The SQ-ring-full path that skips the cancel fired 0 times in the same runs, so a full submission queue is not involved.The change
prepareRecvdeclines the second arm and reports success. "A recv is armed for this conn" is the postcondition every caller acts on, so returning false would make them setneedsRecvand retry from the dirty list forever. The driver path atengine/iouring/driver.gohas carried the same guard since it was written.recvArmedcheck of its own, because it callspickRecvTarget, which mutatescs.recvIntoBody. Computing a target for an arm that is about to be declined would route the in-flight recv's CQE through the direct-body path.connState.recvCancelPending. A pause withdrawn before the cancel lands used to leave-ECANCELEDarriving withrecvPausedalready false, sohandleRecvfell through to the generic negative-result path and closed a healthy connection. The flag marks a cancel this worker asked for so that CQE re-arms instead. Every othercancelConnOpscaller nilsw.conns[fd]or setsclosingfirst, so no other cancellation can reach this branch.Measurement
io_uring single-shot variant run on its own, which reproduces far more readily than the three-variant test. 24 runs each, 4 workers,
memlock128 MiB,seccomp=unconfined.The four remaining failures all report
parseErr=0. They carrycloseTimeoutand per-connection protocol errors, plus one frame-count mismatch — a different signature from the corruption this PR removes. Those are being characterized separately and will get their own issue; this PR does not claim to address them.engine/iouring/recv_arming_test.gofails on a control build with the guard removed (ring pending 1→2) and passes with it.