Skip to content

fix(server): Start and StartWithListener return after Shutdown on io_uring and epoll - #600

Merged
FumingPower3925 merged 2 commits into
mainfrom
fix/595-start-returns-on-shutdown
Sep 14, 2026
Merged

fix(server): Start and StartWithListener return after Shutdown on io_uring and epoll#600
FumingPower3925 merged 2 commits into
mainfrom
fix/595-start-returns-on-shutdown

Conversation

@FumingPower3925

Copy link
Copy Markdown
Contributor

Fixes #595. Measured, not argued: the rig that found the defect is the rig that judges the fix, and the negative control was run.

Mechanism

Two mechanisms, both named in code comments.

(1) server.go: Start (was server.go:359) and StartWithListener (was :710) handed Engine.Listen a context.Background(). iouring/epoll Listen park on <-ctx.Done() (engine/iouring/engine.go:263, epoll engine.go:144) and their Engine.Shutdown is a documented no-op, so nothing could wake that Listen. Fix: all four Start* entry points now call the new Server.listenContext(parent) which derives a cancellable context (from context.Background() for Start/StartWithListener, from the CALLER's ctx for StartWithContext/StartWithListenerAndContext so caller-cancel behaviour is byte-for-byte unchanged) and publishes its CancelFunc under lifecycleMu. Server.Shutdown calls the new cancelListen() AFTER eng.Shutdown(ctx) — after, never before, because on std Engine.Shutdown IS the drain and Listen's own ctx.Done branch calls e.Shutdown(context.Background()); cancelling first would let Listen win the sync.Once and strip the caller's deadline. cancelListen also latches shutdownCalled, so a Shutdown racing prepare() makes the next listen context start out already cancelled instead of parking forever.

(2) engine/iouring/worker.go: with (1) alone the io_uring in-flight request died as a connection reset. A response produced by a handler that was still running when the ctx was cancelled has only been PREPARED — flushSend writes the SEND SQE and sets cs.sending, but the submit that hands it to the kernel happens further down the SAME loop iteration, after the top-of-loop ctx.Err() check — so the old immediate w.shutdown() closed the fd with the response still sitting in the SQ ring. Fix: on a cancelled ctx the run loop keeps pumping the ordinary iteration (which submits those SQEs and reaps their CQEs) until Worker.hasPendingSends() is false, bounded by the new shutdownSendDrainNanos = 250 ms via w.shutdownDrainDeadline. hasPendingSends scans liveConns; conns with detachMu (detached streams AND async-dispatch conns, whose buffers are written off-thread) are inspected under TryLock — never a blocking Lock — so a parked dispatch goroutine cannot wedge shutdown; a conn whose mutex is held counts as pending and is bounded by the same deadline. Shutdown path only: the ctx.Err() branch already existed, hasPendingSends is never called on the hot path, and the only struct growth is one int64 field on Worker. Also refreshed the iouring Engine.Shutdown godoc to state that Listen's parent context is now always cancellable.

Verification

New rig: start_shutdown_return_linux_test.go (//go:build linux, package celeris_test). Per engine it starts a server, drives a 300 ms in-flight GET /slow, calls Shutdown with a 2 s budget, asserts Start returns within budget+1 s (wait capped at 5 s so a pre-fix control FAILS instead of hanging) and that the in-flight body is "done". Matrix = {io_uring, epoll, std, adaptive} x {Start, StartWithListener} + one AsyncHandlers=true io_uring cell.

Command (from the worktree): docker run --rm --cpus 4 --security-opt seccomp=unconfined --ulimit memlock=134217728:134217728 -v :/src -w /src -v /Users/fuming/go/pkg/mod:/go/pkg/mod -v gocache484:/root/.cache/go-build golang:1.27 go test -race -run 'TestStartWithListenerReturnsAfterShutdown|TestStartReturnsAfterShutdown|TestStartReturnsAfterShutdownAsyncIOUring' -v -count=10 -timeout 900s .

Result (scratchpad/logs/fix-10runs-v3.log): 110/110 PASS (10 runs x 11 test/subtest lines), 0 FAIL, "ok github.com/goceleris/celeris 34.791s". Engine really ran multi-worker io_uring: 20/20 io_uring cells logged "io_uring engine listening ... tier=high workers=4 sqpoll=false send_zc=true". Start-return latency after Shutdown across the 80 matrix cells of the earlier 10-run log: min 300.18 ms, max 556.69 ms (std ~550 ms, native ~300 ms), all well inside the 3 s bound.

Negative control

Run with the same container command, code reverted by patch (git apply -R; the earlier git-stash attempt is described under not_verified).

C1 — pure origin/main code (both server.go and worker.go reverted), -count=3, scratchpad/logs/control-C1-main.log: 6/6 io_uring cells and 6/6 epoll cells FAIL with "celeris#595: Start did not return within 5s of Shutdown"; 6/6 std and 6/6 adaptive cells PASS — exactly the engine split the issue predicts. FAIL github.com/goceleris/celeris 65.501s.

C2 — server.go fix in place, io_uring drain reverted, -count=3, scratchpad/logs/control-C2-worker-reverted.log: Start now returns on every engine, but 6/6 io_uring cells FAIL with 'in-flight request failed: Get "http://127.0.0.1:PORT/slow": read: connection reset by peer'; epoll/std/adaptive pass. Async variant, same revert, -count=5, scratchpad/logs/control-async-nodrain.log: 5/5 FAIL with the same reset. With the drain: 0/10 and 0/10 failures respectively.

Regression risk

Low-to-moderate, concentrated in the io_uring shutdown window. (a) Server.Shutdown now cancels the listen context; a caller that called Shutdown and then expected Start to keep serving will no longer get that (that is the fix). (b) Shutdown called before Start now latches shutdownCalled, so a subsequent Start on that same Server returns immediately instead of serving — documented in the Shutdown godoc; no existing test exercises that order. (c) The io_uring worker may keep accepting and serving for up to 250 ms after cancellation (the drain window) instead of tearing down instantly, and connections accepted inside that window carry an already-cancelled conn context; worst-case shutdown latency per worker grows by ~250 ms plus at most one adaptiveTimeout (<=100 ms). (d) hasPendingSends takes cs.detachMu with TryLock on the shutdown path only — no blocking acquire, so no new deadlock edge. No hot-path allocation, syscall or branch was added.

Not verified

  1. arm64 / real cluster: everything was measured on darwin-hosted docker (linuxkit 7.0.12, 4 CPUs). No arm64 run, no nightly/soak, no refapp end-to-end SIGTERM test (probatorium was not touched).
  2. A handler still COMPUTING on an async dispatch goroutine when Shutdown fires is still not waited for on io_uring — the drain only covers responses already queued or in flight (the test's async cell passes because the response reaches the detach queue inside the window). w.shutdown() joins asyncWG only after the fds are closed; making that a true async drain is a separate change.
  3. Pre-existing unrelated defect found while testing, NOT fixed: adaptive + StartWithListener cannot start at all. adaptive.New re-applies WithDefaults and resolvePort turns the default into "[::]:8080", then the sub-engine's Validate rejects the pair: create engine: epoll sub-engine: config validation: ambiguous configuration: Addr="[::]:8080" but Listener is bound to "127.0.0.1:45269". The test works around it by setting cfg.Addr to the listener's address (documented in the test); worth its own issue.
  4. WARNING — shared git stash across worktrees: my first control run used git stash push, and the pops returned ANOTHER agent's work (a celeris#594 change to resource/config.go) into this worktree. I did not keep or commit it: it is back in the shared stash as stash@{0} with the message "celeris#594 resource/config.go — NOT MINE, popped by accident from the shared stash in worktree wf_768c660d-c9f-4; restored untouched". That agent must git stash pop stash@{0} (or apply it) to recover. All later controls used patch files (scratchpad/fix595-final.patch, scratchpad/worker-drain.patch), never the stash.
  5. Not measured: throughput/latency benchmarks (the change is shutdown-path only, so no benchmark was run).

Adversarial review

Skeptic 1 — refuted: False, mergeable: True

I could not refute the core claim. The named mechanism is addressed exactly at the cited lines and the controls are real.

MECHANISM CHECK — holds. git show origin/fix/595-start-returns-on-shutdown:server.go confirms all four Start* entry points now go through listenContext(); Start (:371) and StartWithListener (:769) no longer pass context.Background(), and StartWithContext/StartWithListenerAndContext derive from the caller's ctx, so caller-cancel is preserved. engine/epoll/engine.go:144 is <-ctx.Done(); wg.Wait(); return nil and its Shutdown godoc ALREADY asserted "The Server calls Listen with its managed context and cancels it during Server.Shutdown" — a claim that was false before this commit. The fix makes an existing documented invariant true rather than breaking one. The cancel-after-eng.Shutdown ordering is justified by real code: engine/std/engine.go:132-133 is case <-ctx.Done(): return e.Shutdown(context.Background()) guarded by a sync.Once at :49, so cancelling first would indeed strip the caller's deadline.

CONTROLS — real, numbered, and they flip on the engine split the issue predicts (C1: 6/6 iouring + 6/6 epoll FAIL "Start did not return within 5s", std/adaptive pass; C2: drain reverted → 6/6 iouring "connection reset by peer", 5/5 async). The rig caps the wait at 5 s so the pre-fix control fails rather than hanging — the right shape.

HOT PATH — verified zero cost. hasPendingSends is called only from the ctx.Err() != nil branch at the top of run(); the only struct growth is one int64 on Worker. I checked the false-positive risk that would make the drain always burn 250 ms: sendBuf/writeBuf are truncated to [:0] in completeSend (worker.go:2694-2696) and bodyBuf/sendBody are nil'd on every completion branch, so an idle keep-alive conn reads not-pending. sendBody is not in connSendPending but is always covered by cs.sending.

HYGIENE — clean. git show --name-status = exactly 4 files; no scratchpad, no logs, no fmt.Print/println/DEBUG in added lines. The build tag is correct and non-trapping: //go:build linux + _linux_test.go (GOOS, not the _arm_test.go GOARCH trap), matching the existing root-level async_promote_integration_linux_test.go. gofmt on the two changed Go files is clean. The stash hazard the report self-discloses is confirmed (stash@{0} really does hold another agent's celeris#594 work) but nothing from it is in this commit.

WHAT I DID FIND — three real gaps, none blocking:

  1. hasPendingSends misses the H2 async write queue. internal/conn/h2.go:471 WriteQueuePending() is a lock-free atomic bool holding frames enqueued by handler goroutines; the run loop drains it into cs.writeBuf at worker.go:939-947, but connSendPending only sees sending || sendBuf || writeBuf || bodyBuf. An h2c response enqueued but not yet drained is invisible, so the drain can exit immediately and reset it — the exact failure the second mechanism set out to fix, left uncovered for H2. The new docstring ("reports whether any live connection still has response bytes queued for the ring") overclaims. The whole test matrix is HTTP/1.1 (Go's default client over plain http), so nothing catches it.

  2. The drain keeps ACCEPTING for the window, by design ("The loop keeps accepting for that window ... a connection that arrives inside it is answered rather than reset"). But Server.Shutdown's own godoc, immediately above the changed code, says hooks fire "After the engine stops accepting new connections and drains in-flight requests". On the native engines eng.Shutdown is a no-op, so Shutdown returns and OnShutdown hooks run while the worker is still accepting and serving for up to 250 ms. A hook that closes a DB pool can now race a request accepted after Shutdown returned. And conns accepted inside the window are torn down at the deadline anyway — the reset is moved, not removed. Pre-fix this was worse (the engine never stopped at all), so it is not a regression, but the stated contract is still not met.

  3. The "bounded by 250 ms" claim is checked only at loop top, and the loop's wait is SubmitAndWaitTimeout(w.adaptiveTimeout())adaptiveTimeout() returns 1 second when w.listenFD < 0 (paused accept / adaptive standby). Worst case is ~1.25 s per worker, not the report's "250 ms plus at most one adaptiveTimeout (<=100 ms)". Still inside the 3 s test bound and not a hang, but the stated bound is wrong.

Also unverified as the report admits: no arm64, and the actual reported symptom (probatorium refapp SIGTERM) was never re-run end-to-end — the fix is proven only against a synthetic in-repo rig. And I could not independently re-run vet/golangci-lint (read-only, no docker).

Skeptic 2 — refuted: False, mergeable: True

Could not refute. The rig demonstrably flipped and the negative controls exist with numbers I read myself from the on-disk logs, not just from the report. control-C1-main.log (origin/main code, -count=3) yields exactly 6 "Start did not return within 5s of Shutdown on io_uring" + 6 on epoll, with std (540ms) and adaptive (300ms) passing — the exact engine split issue #595 predicts — and control-C2-worker-reverted.log independently isolates the second mechanism (6/6 io_uring "connection reset by peer", epoll/std/adaptive pass; async variant 5/5 FAIL), while fix-10runs-v3.log is 110 PASS / 0 FAIL. The test caps its wait at 5s (startWaitCap) so the pre-fix control FAILS instead of hanging, meaning the control could not have silently passed. The fix addresses the mechanism at the cited lines: Start (old :359) and StartWithListener (old :710) went from eng.Listen(context.Background()) to a published cancellable context. No surrounding invariant is broken — the epoll engine's PRE-EXISTING Shutdown godoc already asserted "The Server calls Listen with its managed context and cancels it during Server.Shutdown", which was false before this commit, so the fix makes code match a documented invariant rather than violating one. The cancel-AFTER-eng.Shutdown ordering is load-bearing and correct: I confirmed engine/std/engine.go Shutdown wraps the drain in e.once.Do and Listen's ctx.Done branch calls e.Shutdown(context.Background()), so cancelling first really would strip the caller's deadline. Per-request hot-path cost is zero: every added line sits inside the pre-existing if ctx.Err() != nil branch, hasPendingSends is called only from there, and the sole struct growth is one int64 on Worker (no size/layout assertion exists in the package). Tool claims check out — I independently reproduced GOOS=linux go build ./... and go vet ./... clean, and gofmt -l is clean on all four committed files. Nothing illicit is committed: git diff --name-status shows exactly 4 files, git ls-tree finds no scratchpad/log/patch paths, the diff contains no fmt.Print/println/log.Print/DEBUG lines, no stray build tags (the one //go:build linux on the new test is correct for a linux-only engine test), and the worktree is identical to the pushed commit apart from an untracked scratchpad/ dir. Adaptive-suite failures are convincingly pre-existing: 4 failures patched vs 4 unpatched in the same container, 3 names identical.

…#595)

Mechanism: Start and StartWithListener handed Engine.Listen a
context.Background(). The native engines park Listen on <-ctx.Done()
(engine/iouring/engine.go, epoll likewise) and their Engine.Shutdown is a
documented no-op, so nothing could ever wake that Listen: Server.Shutdown
returned but Start never did, and a refapp using Start + SIGTERM had to be
killed. The Start* entry points now own a cancellable context (derived from
the caller's where there is one, so caller-cancel semantics are unchanged)
whose CancelFunc Shutdown calls AFTER the engine's graceful phase — after,
never before, or on std Listen's own ctx.Done branch would win
Engine.Shutdown's sync.Once with a background context and strip the caller's
deadline. A Shutdown racing Start latches shutdownCalled so the listen
context starts out cancelled instead of parking forever.

Second mechanism (io_uring only): a response produced by a handler still
running when the context was cancelled was only PREPARED — flushSend writes
the SEND SQE and sets cs.sending, but the submit happens further down the
same loop iteration, AFTER the ctx.Err() check — so the old immediate
teardown closed the fd with the response still in the SQ ring and the client
got a reset. The run loop now keeps pumping until no send is queued or in
flight (Worker.hasPendingSends, detachMu conns inspected under TryLock so a
parked dispatch goroutine cannot wedge shutdown), bounded by
shutdownSendDrainNanos = 250 ms. Shutdown path only; no per-request cost.

Measured in the container (golang:1.27, --cpus 4, seccomp=unconfined,
memlock 128M, io_uring tier=high workers=4), go test -race -count=10:
110/110 PASS across io_uring/epoll/std/adaptive x Start/StartWithListener
plus an AsyncHandlers io_uring cell; Start returned 300-557 ms after
Shutdown (budget 2 s, cap 3 s).

Negative controls, same rig:
- origin/main code, -count=3: 6/6 io_uring and 6/6 epoll cells FAIL
  "Start did not return within 5s of Shutdown"; std and adaptive pass.
- server fix only, io_uring drain reverted, -count=3: 6/6 io_uring cells
  FAIL "in-flight request failed: ... read: connection reset by peer";
  async cell 5/5 FAIL the same way. With the drain: 0 failures.
@FumingPower3925 FumingPower3925 added this to the v1.6.0 milestone Sep 13, 2026
@FumingPower3925

Copy link
Copy Markdown
Contributor Author

CI hold: TestBackpressurePauseDoesNotCancelInflightSend/io_uring failed on this branch's first run with read error x1: cannot allocate memory (protoErr=1 of 96 conns, framesSent=3,668,046). The last eight CI runs on main all passed, so I am not calling this pre-existing without evidence.

Two candidate causes, and they are separable: (a) this branch keeps the io_uring run loop pumping for up to 250 ms after context cancellation (shutdownSendDrainNanos), which submits more SQEs during teardown, and the GitHub runner caps io_uring hard through RLIMIT_MEMLOCK; (b) a low-rate flake of the same capped-runner ENOMEM class.

Measuring before merging: a re-run for a second CI sample, then a local A/B of this branch against main in a memlock-capped container (the CI shape), N=12 per arm, single-shot and multishot tallied separately. Held until that discriminates.

@FumingPower3925

Copy link
Copy Markdown
Contributor Author

CI re-run: 10/10 checks pass, including TestBackpressurePauseDoesNotCancelInflightSend. So the branch now stands at one failure and one pass, against eight consecutive passes on main. That is not enough to attribute or exonerate (one run discriminates nothing here; I have been wrong twice before by reading a single marginal cell).

Still held for the A/B, which is cheap and mechanical: this branch against main, same container, --ulimit memlock=8388608 to reproduce the CI shape where io_uring is capped to one worker, N=24 per arm, single-shot and multishot tallied separately, counting cannot allocate memory occurrences. The hypothesis under test is specific: shutdownSendDrainNanos keeps the run loop submitting SQEs for up to 250 ms after cancellation, and a one-worker ring has the least room to absorb that. A structural difference will show; if both arms show the same rate, the failure is the capped-runner flake class and this merges.

@FumingPower3925

Copy link
Copy Markdown
Contributor Author

A/B done. This branch does not cause the failure; the test is flaky under the memory-capped shape on main too.

Four arms, same container, same command, N=24 each, both subtests tallied (48 subtest results per arm):

arm memlock top-level FAIL ENOMEM
main (42d1643) 8 MiB 4 / 24 1
this branch 8 MiB 4 / 24 2
main 128 MiB 1 / 24 0
this branch 128 MiB 1 / 24 0

At 8 MiB the engine logs workers=1, which is the CI shape the memlock cap produces. The failure rate is identical between arms at both settings, and the one-versus-two ENOMEM split is a single run out of twenty-four. The shutdownSendDrainNanos hypothesis is refuted: the 250 ms post-cancel drain window makes no difference to this test under the pressure that produces the failure.

Command:

docker run --rm --cpus 4 --security-opt seccomp=unconfined --ulimit memlock=$ML:$ML \
  -v "$SRC":/src -w /src -v "$HOME/go/pkg/mod":/go/pkg/mod -v gocache484:/root/.cache/go-build \
  golang:1.27 go test -count=24 -timeout 120m -v \
  -run 'TestBackpressurePauseDoesNotCancelInflightSend' ./middleware/websocket/

Unblocking this PR. The 4-in-24 rate on main under the capped shape is a separate, pre-existing CI reliability problem and is filed on its own.

@FumingPower3925
FumingPower3925 merged commit 8d8f2a5 into main Sep 14, 2026
10 checks passed
@FumingPower3925
FumingPower3925 deleted the fix/595-start-returns-on-shutdown branch September 14, 2026 05:45
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.

Server.Start / StartWithListener never return after Shutdown on io_uring and epoll: Listen blocks on a Background context and Engine.Shutdown is a no-op

1 participant