Repository navigation
epoll: an async route's closing response is sent whole; the EBUSY timed-wait arm reaches its wait; the port 0 hold tests name the extra socket (Refs #1068, #890, #1107, #1108, #1104) - #1106
Merged
Conversation
…loop looks between asyncClosed and endDispatch (failing first; Refs #1068, Refs #890) serveAsync declares a conn closed (asyncClosed) after a request that ends it, and only then takes asyncInMu to mark its goroutine gone (endDispatch). A drainDetachQueue that reads the conn between the two sees a closed conn whose goroutine still counts as running, calls closeConn, and the handler's detachMu is free, so closeConn closes the descriptor with the rest of the response unsent. The entry that makes the loop look is the one the goroutine enqueued for the remainder of its partial flush. Two test hooks hold the goroutine in that gap. With them the test fails every time on this tree, with the byte counts of the CI failures: 2634119 of 3145728 body bytes (TestBackloggedPeerIsClosed, refused write) and 2634100 of 8388608 (TestStreamedResponseIsDelivered, Connection: close; CI saw 2681685 and 2634069, the bytes the runner's socket buffers took).
…under one lock, so the loop cannot close it over a queued remainder (Refs #1068, Refs #890) drainDetachQueue reads asyncClosed and then asyncRun under asyncInMu, and treats a conn that is closed with its goroutine still running as a close asked from outside while a handler runs: closeConn, which goes through at once when detachMu is free. serveAsync stored asyncClosed before it took asyncInMu to clear asyncRun, so the entry the goroutine enqueued for the remainder of its partial flush could be drained in between, and the descriptor was closed with that remainder unsent: the client read EOF at the bytes the socket buffers had taken (2634119 of 3145728 in TestBackloggedPeerIsClosed, 2681685 of 8388608 in TestStreamedResponseIsDelivered/*/async-route/close). asyncClosed is now stored inside the asyncInMu section that clears asyncRun, at the end-of-conn exit and at the two exits (a failed H2 upgrade flush, an error after Detach) that stored it the same way. The loop reads asyncClosed first, so a true it sees was stored inside the section, and the asyncInMu it then takes waits for the section to end: it finds the goroutine gone and closes through closeWhenFlushed, which sends the remainder first. io_uring has no such gap: its async exit does not flush into the socket before it declares the close (a request that ends the conn hands its staged bytes to the worker, whose closeConn defers the close behind them).
…s its clients so the loop reaches that wait (Refs #890) The arm injects EBUSY into the loop's timed wait (mode 3b), which the loop takes only when it finds no completion ready and no send to wait for. 32 keep-alive clients that send the next request the moment they are answered keep that from happening for the whole 3 s window, and the test's apparatus guard ("the injected EBUSY never reached a submit-and-wait-timeout wait") failed: 9 times in the Coverage workflow's -race -covermode=atomic build since the test landed (3 of them on main), never in the Unit job. On a worker with a CPU to itself the arm ran 79 000 requests and met the timed wait 0 times (--cpus 4, the CI runner's 4 vCPUs: 31 of 40 runs failed). The arm's clients now pause 20 ms after each answer (runKeepAliveLoadPaced; the unpaced runKeepAliveLoad is unchanged), which leaves the worker idle between requests, where the timed wait is the one it takes. The other two arms keep the unpaced load, which reaches their waits at every pass. What the test asserts is unchanged.
…nd bound to the port (diagnostic only; Refs #1104) TestPort0HoldIsReleasedWhenListenFails895 failed once on main's CI ("1 sockets still bound to port 37483 after Listen failed") and passed on the re-run of the same tree; the failure message does not say whose socket it counted, and the two explanations in the issue (the engine's own descriptor released late, or a socket of something else in the test binary) differ exactly in that. The census now keeps, for every port, each socket's descriptor, whether it listens, is connected (and to whom) or is only bound, and its SO_REUSEPORT, and the hold tests (the Listen-failed one and the Listen-returned one, in both engines) print them with the count. No assertion changes. This is not a fix: the failure has not been reproduced (0 of 35 000 runs of the test alone under load), so the next occurrence says what the extra socket is.
|
Caution Review failedThe pull request is closed.
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
…ing line (failing first; Refs #890) TestNICIRQReportAddsNoLoop1036 failed in CI ("default: the listening line does not say loops=2", a log with the pinning lines and no listening line) on PR #1105's Coverage run and on this PR's Unit run. Listen publishes the address (Engine.Addr) and only then logs "epoll engine listening", and start909, which the NIC interrupt, loop count and pinning tests start their engines with, returned as soon as the address was there, so a test that read the log on return could read it before the line was written. The test holds the line's write until it has looked at whether start909 has returned: it has, every time, on this tree.
…g line (Refs #890) Waits, within the 10 s it already allows the address, for "epoll engine listening" to be in the log. The NIC interrupt, loop count and pinning tests read the log on return; they no longer race the line Listen logs after it publishes the address. A test helper only; the engine is unchanged.
This was referenced Oct 25, 2026
…outine to it; test hygiene from the review (Refs #1068, Refs #1107, Refs #1108) abortAsyncHandler stores asyncClosed first, lets go of detachMu, formats and logs the panic with its stack, and only then calls endDispatch. A pipelining client whose first response was partly sent (the remainder queued, an entry for it in the detach queue) and whose second request's handler panics, or calls runtime.Goexit, past every recovery, had that first response cut when the loop drained an entry in the window: a closed conn whose goroutine is running, and detachMu free, so closeConn went through. The same defect class as the serveAsync exits. drainDetachQueue now asks dispatchBusy before closeConn for a closed conn whose goroutine still runs: a goroutine that is running a request (not parked, not detached) owes the loop a hand-back, and dispatchBusy records the close as owed (closeOwed), as closeConn does for a handler that holds detachMu. The goroutine's exit enqueues the conn again, and that entry finds it gone and closes through closeWhenFlushed. Detached conns (WS/SSE) still close at once. The lock moves of the serveAsync exits stay: they keep a goroutine's own closing exit from showing as running at all. - test: TestAbortedGoroutineDoesNotLoseTheQueuedRemainder1068 (new hook testHookAbortAsyncLogged). Without the dispatchBusy line: 40 of 40 FAIL, received 2383751 of 5242880; with it: 60 of 60 PASS. - test: the hooks of both tests assert that bytes were still queued while the goroutine was held, so an arm cannot pass on a host whose socket buffers take the whole response. - test: start909's engine start no longer calls t.Fatal from the helper's goroutine in TestStart909ReturnsOnlyOnceTheListeningLineIsLogged (launch909 returns errors). - test: the EBUSY arm's comment counts 9 failures, as the PR does.
FumingPower3925
changed the title
… one asyncInMu section (Refs #1068, Refs #890, Refs #1107, Refs #1108, Refs #1104) drainDetachQueue read asyncRun under asyncInMu and then asked dispatchBusy, which took the lock again. An aborted goroutine that reached endDispatch between the two reads was taken for gone by the second, closeConn (a direct close, not closeWhenFlushed) cut the queued remainder, and the goroutine's own entry found the conn closed. The branch now reads asyncRun and the busy test (dispatchBusyLocked, the body of dispatchBusy) and records closeOwed in one section; what it does with the answer is unchanged. The second store of asyncClosed in abortAsyncHandler moves under the lock with endDispatch, as at the serveAsync exits (the first store stays early on purpose). TestAbortedGoroutineFinishingBetweenTheDrainsReads1068 holds the loop, after its decision, until the goroutine has finished: with the two reads put back it fails 10 of 10 (received 2383751 of 5242880), with the guard removed both abort tests fail 10 of 10, with the fix all pass (20 of 20 each, -race). The abort scenario is a helper of the two tests.
…goroutine was held (Refs #1068) The abort hook waits only 500 ms for the loop's drain and nothing asserted that it came, so a loop that did not look left a passing test that tested nothing. Both abort tests now fail when the drain hook has not run by the time the hold ends. With the two reads put back only the between-reads test fails (10 of 10); with the drain guard removed both do (10 of 10); with the fix all three 1068 tests pass 20 of 20 under -race.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Refs #1068, Refs #890, Refs #1107, Refs #1108, Refs #1104. Lane FLAKES-C (v1.6.0). Draft; nine commits, each reviewable alone.
TestBackloggedPeerIsClosed/*/async-*andTestStreamedResponseIsDelivered/*/async-route/closefailed on CI with a response that stops at the same byte count every time (2634119 of 3145728,2681685 of 8388608) and then EOF. Mechanism and fix below.TestRunSurvivesARingWaitEBUSY884/submit-and-wait-timeoutfailed its own guard ("the injected EBUSY never reached a submit-and-wait-timeout wait") 9 times, all in the Coverage workflow. Its clients now pause between requests so the loop reaches that wait.TestNICIRQReportAddsNoLoop1036failed here and on epoll: the loop thread no longer reads a descriptor after a dispatch goroutine's Hijack has closed it (Refs #936) #1105's Coverage run.start909returned as soon as the engine published its address, butListenlogsepoll engine listeningafter that, so the test could read the log before the line existed.start909now waits for the line; the failing-first test holds the line's write and looks at whetherstart909has returned (it had, 5 of 5, before the change; 30 of 30 now wait). Not reproduced naturally in 100 runs under load.This PR does not touch the
serverFDForhelper of #1081 (that fix is #1083's).1. The epoll truncation
serveAsync(the dispatch goroutine) ends a conn after a request that ends it (Connection: close, an error, a refused write) by storingasyncClosedand then takingasyncInMuto clearasyncRun(endDispatch).drainDetachQueuereadsasyncClosed, thenasyncRununderasyncInMu; a conn that is closed with its goroutine still running is taken for a close asked from outside while a handler runs, and it callscloseConn, which goes through at once whendetachMuis free. Here it is free: the goroutine released it after its flush. The entry that makes the loop look is the one the goroutine enqueued, a few lines earlier, for the remainder of its own partial flush.closeConnthen closes the descriptor with that remainder unsent: the client reads EOF at the bytes the socket buffers had taken (hence the constant offset).Fix, two parts. (1)
asyncClosedis stored inside theasyncInMusection that clearsasyncRun. The loop loadsasyncClosedfirst, so atrueit sees was stored inside the section, and theasyncInMuit then takes waits for the section to end: it finds the goroutine gone and takescloseWhenFlushed, which sends the remainder first. The two other exits ofserveAsyncthat stored it the same way (failed H2-upgrade flush, error after Detach) are moved too, for consistency only: nothing is queued there that a close could cut, and the new test covers only the final exit (the one with a queued remainder). (2) After review:abortAsyncHandler(a panic orruntime.Goexitthat escapes every recovery) has the same gap in a wider form: it storesasyncClosedfirst (deliberately, #844), lets go ofdetachMu, logs the panic with its stack, and only then callsendDispatch; a pipelining client whose first response was partly sent could lose it when the second request's handler panicked. Its early store cannot move, sodrainDetachQueuenow decides, in oneasyncInMusection, whether the goroutine runs and is busy (dispatchBusyLocked, the body ofdispatchBusy) and records the owed close there, and skipscloseConnfor a closed conn whose goroutine is busy (an earlier head readasyncRunand calleddispatchBusyin two sections, and a goroutine finishing between the reads was closed over; found in review): the close is recorded as owed, the goroutine's exit enqueues the conn again, and that entry closes it throughcloseWhenFlushed. This iscloseConn's own rule for a handler that holdsdetachMu; detached conns (WS/SSE) still close at once. It is oneifin the drain, and it also covers the serveAsync exits independently of the lock moves, which stay so that a goroutine's own closing exit never shows as running.io_uring has no such gap: its async exit does not flush into the socket before it declares the close (a request that ends the conn hands its staged bytes to the worker, and
closeConnthere defers the close behind them), and its drain callscloseConnfor every closed conn.Evidence (golang:1.27.3 linux/arm64 container,
-race):TestAsyncRouteCloseSendsTheQueuedRemainder1068holds the goroutine between the two stores (two test hooks) with a client that reads nothing. With only the lock move reverted: 20 of 20 FAIL,refused-writearmreceived 2634119 of 3145728 body bytes(the number in test: TestBackloggedPeerIsClosed failed once under -race in CI (epoll/adaptive async-route, 2 of 4 responses) #1068's log),connection-closearmreceived 2634100 of 8388608. With the fix: 30 of 30 PASS (and 50 of 50 earlier, before the second arm).--cpus 2plus two busy loops,test/serverrace binary of main 713b40d,-run 'TestStreamedResponseIsDelivered/(epoll|adaptive)/async-route/close$' -count=1500: epoll arm failed 2 of 1500 withreceived 2681685 of 8388608 body bytes (2681856 bytes in all), then EOF, the CI byte count. After the fix, same command on the epoll arm,-count=6000: 0 failures (if the rate were 2/1500, P(0 of 6000) = 3.3e-4; Fisher one-sided p = 0.04 for the two samples, so supporting evidence only; the deterministic test is the proof).TestBackloggedPeerIsClosed/(epoll|adaptive)/async-(route|loop)$,-count=500, same shape: 0 failures before and 0 after. The natural rate there is below what this shape shows; therefused-writearm of the new test is its evidence.TestBackloggedPeerIsClosedfailed in 5 job executions (CI workflow),TestStreamedResponseIsDeliveredin 8 (5 CI, 3 Coverage;epoll/async-route/closeandadaptive/async-route/close), every one in anasync-routeorasync-looparm of epoll or adaptive, none on io_uring or std. test: TestBackloggedPeerIsClosed failed once under -race in CI (epoll/adaptive async-route, 2 of 4 responses) #1068's body reads the log as "2 of 4 responses"; that is the passing adaptive line above it. The failure is a truncated first response.Abort path:
TestAbortedGoroutineDoesNotLoseTheQueuedRemainder1068(failing first; new hooktestHookAbortAsyncLogged): request 2 is on the wire while handler 1 runs, handler 1 answers 5 MiB to a client with a 16 KiB receive buffer that reads nothing, handler 2 panics, the abort is held after its log, and an entry is queued for the loop to drain in that window. Without thedispatchBusyline: 40 of 40 FAIL (received 2383751 of 5242880 body bytes); with it: 60 of 60 PASS.TestAbortedGoroutineFinishingBetweenTheDrainsReads1068(same scenario, the drain held after its decision until the goroutine has left) fails 10 of 10 with the two reads put back, and passes 20 of 20 with the fix. The abort scenario queues its own entry for the loop from inside the hook to force the window (the entry for the remainder is normally drained before the second handler has panicked). The secondasyncClosedstore inabortAsyncHandlernow sits under the lock withendDispatch; the first stays early on purpose. Both abort tests also fail if the loop never looked while the goroutine was held. Both tests' hooks also assert that bytes were still queued while the goroutine was held, so an arm cannot pass on a host whose socket buffers take the whole response.Mutants: without the drain guard only: both abort tests 10 of 10 FAIL, serveAsync test passes (the lock move covers it). With the two reads put back: only the between-reads test fails (10 of 10). Without the final-exit lock move only: both pass (the drain guard covers the same gap: the two fixes overlap on purpose). Without both (10 runs): serveAsync test 10 of 10 FAIL, abort test 10 of 10 FAIL.
Hooks:
testHookAsyncExitClosed,testHookDrainAsyncClosedandtestHookAbortAsyncLogged, atomic pointers loaded once per ending request / per drained closed conn / per abort.2. TestRunSurvivesARingWaitEBUSY884 / submit-and-wait-timeout
The loop takes the timed wait only when it finds no completion ready and no send to wait for. 32 clients that send the next request the moment they are answered keep that from happening: on a worker with a CPU of its own the arm ran 79 000 requests in 3 s and met the timed wait 0 times. All 9 CI failures are in the Coverage workflow (
-race -covermode=atomic), 3 of them on main (runs 39068951624, 39334596754, 39460416507), none in the Unit job.Reproduction: iouring race+atomic-cover test binary of main, 8 MiB memlock (one worker),
--cpus 4(the runner has 4 vCPUs), no spinners,-run TestRunSurvivesARingWaitEBUSY884/submit-and-wait-timeout: 31 of 40 FAIL;--cpus 2with or without spinners and--cpus 1with 3 spinners did not reproduce (0 of 140). After the change: 0 of 200 at--cpus 4(one-sided 95% bound 1.5%); the whole test 0 of 30 at--cpus 1+ 3 spinners and 0 of 60 at--cpus 2+ 2 spinners, so the pause creates no new failure mode. The timed arm's clients pause 20 ms after each answer (runKeepAliveLoadPaced;runKeepAliveLoadis unchanged); the other two arms keep the unpaced load. The assertions are unchanged.3. #1104 (diagnostic only)
census895(both engines) now keeps each socket's descriptor, whether it listens, is connected (and to whom) or is only bound, and its SO_REUSEPORT; the two hold tests print them with the count. No assertion changes. Not reproduced: 0 of 35 000 runs of the iouring test alone (--cpus 2, two busy loops, 8 MiB memlock); on CI it failed once in about 1 100 executions since #992 (1/1100 = 9.1e-4). The kernel does not let the hold'sbind(0)land on a port that has a leftover server-side socket in the process (0 of 20 000 binds in an 8-port range with one such socket, SO_REUSEPORT, no SO_REUSEADDR asResolvePort0binds), so a leftover from an earlier test is not the explanation by itself. The issue stays open.4. start909 (#1108)
TestStart909ReturnsOnlyOnceTheListeningLineIsLogged(the engine start islaunch909, which returns errors, so a failure in the helper's goroutine reports its reason and cannot hang the test) gates the write of the listening line (agatedLogaroundlockedBuf;start909takes alogSinknow) and, 300 ms in, checks thatstart909has not returned. Before the change it had returned in every run (5 of 5, log empty); with the change 30 of 30 pass. The CI failure itself: run 40204211270 attempt 1 (this PR's first head) and run 40138430871 attempt 2 (#1105). Both failed with the log holding the pinning lines and no listening line. Callers: the NIC interrupt, loop count and pin tests (start909has seven call sites in five files).Behaviour note
In the narrow window above the conn now closes through
closeWhenFlushedinstead of at once, so a client that reads nothing can hold such a conn for the closing drain bound (#876: WriteTimeout, orclosingDrainFloorwhen WriteTimeout is 0) before it is reaped. Before, the same client got its response cut.Performance (RULE 74)
No benchmark row runs the changed lines. They run only for a request that ENDS its connection on an epoll async route (Connection: close, an error, a refused write, a panic): one existing atomic store moved inside an existing lock section plus one nil-pointer hook check per such request, and, in the drain, three field reads (
asyncParked,asyncDetachUnlocked, thecloseOwedwrite) inside theasyncInMusection the branch already took, only whenasyncClosedis set. Nothing runs per request on a keep-alive conn. #1105's timing read (the loop thread's read of a descriptor after a Hijack) is on a different path and unaffected. A waiver of a dedicated cluster timing for this PR is requested; the cumulative final perf checkpoint F4 covers it.Test plan
go vetepoll, iouring (and-tags validation); golangci-lint v2.14 (also--build-tags validation): 0 issuesgo test -raceepoll, iouring (8 MiB memlock) and ./test/server packages on this head (see CI)drainRead,hijackConn,closeOnReadEndand one hunk ofdrainDetachQueuein the same file;git merge-treeof this head with epoll: the loop thread no longer reads a descriptor after a dispatch goroutine's Hijack has closed it (Refs #936) #1105's head (3b2ac0b) merges without conflict.-runlists) names the new test or the changed ones.