Repository navigation
tests: test/server start retry takes a fresh port; the shutdown gate test waits for the engine (Refs #1104) - #1135
Merged
Merged
Conversation
…ound (Refs #1104) TestStalledSSEEndsWithShutdown855/std/h2c/budget failed once in CI with "startErr=listen tcp 127.0.0.1:38797: bind: address already in use": the SSE starter picks a free port, closes it and has Start bind it, parallel cells of the test run in the same process, and the test/server ENOMEM change had narrowed the loop that used to retry any error for three seconds to a ring ENOMEM only. retryRingENOMEM now also retries an address already in use, up to ten times (each try picks a fresh port; a port that stays taken is a real conflict), for every starter that goes through it: the SSE 855 starter, startTCPReady889 and the start-shutdown rig.
…ne has the conns and the requests (Refs #1104) TestShutdownPoolWaitGateRequestsInProgressAndIdleConns885 slept a fixed 1.3 s and then began the shutdown, assuming the engine had accepted the silent conns and read the requests of the keep-alive, download and upload conns. On a loaded runner (-race and -cover, 24 HTTP/2 downloads of 16 MiB running) it had not, and the gate's first pass, 250 ms in, closed a conn the loop had not read yet: three resets at 257 ms in CI. It now waits, up to 20 s, until the engine counts every conn open and every whole request handled (waitEngineBusy1104).
|
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 |
…s over a baseline (Refs #1104)
…n it (Refs #1104) startPicked1104 is the pick, close and Start the SSE 855 and h2upgrade-matrix starters did inline, in one place (behaviour unchanged). The test makes two starters pick the same port at the same moment: one server fails to bind it, and the other's /ping answers the loser's readiness probe, so both starters return the same address (10 of 10 runs fail).
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
…shutdown rig tells its own /ping (Refs #1104) startPicked1104 now hands the picked listener to the server (StartWithListener): the port is never free between pick and bind, so a second starter that picks the same port gets another one and a readiness probe can only be answered by the server that owns the port. The h2upgrade readiness waits for the engine to publish its address, since a dial alone proves nothing against a listener the server holds from the start. The start-shutdown rig must keep Start for its plain-Start arm, so its /ping returns a per-server token that waitReadyErr compares; an answer from another server is not ready and Start's bind error is what the retry sees. retryRingENOMEM and startRetryingRingENOMEM are renamed retryStart1104 and startRetrying1104, the log line says what was retried, and the new bound test pins exactly 10 tries.
…retry comments (Refs #1104) On the sync arm the loop counts the upload once it has read its headers and first 64 KiB, so the request count to wait for is 32, which also covers the upload having been read (the case the gate defect cuts). The one extra unit seen in some runs is already present before the download and the upload are sent and its source was not found, so the request wait stays a lower bound while the conn wait is exact. The comments of the retry tests and of isAddrInUse describe the start-shutdown rig's case, not the superseded diagnosis.
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.
Flakes lane, package F: the two test/server flakes seen on #1132's first CI run. Refs #1104
Method: the first flake has a failing-first test (a collision of two starters on one port) and a fix; the second test's wait is a test change with no reproduction, and the gate defect behind it is tracked separately. The second flake also turned up a defect in the epoll gate, written up under "Findings" with a deterministic test (not committed: it fails on main).
1.
TestStalledSSEEndsWithShutdown855/std/h2c/budget: two servers on one portThe CI log (run 40457371765, attempt 1, "Unit root shard b") shows two parallel std cells starting servers on the SAME port, 0.5 ms apart:
celeris starting addr=127.0.0.1:38797 engine=std,std engine listening addr=127.0.0.1:38797, then a secondceleris starting addr=127.0.0.1:38797, and at the end of the cellSTALL855 cell=std/h2c/budget ... startErr=listen: ...:38797: bind: address already in use startReturned=0s. Both cells had picked the port withnet.Listen(":0")and closed it, which hands it out again at once; one server bound it, the other'sStartfailed. The loser's readiness probe (waitReady761,GET /ping) was answered by the WINNER (every cell registers/ping), so the starter returned success, the bind error surfaced only when the test readstartErrat the end, and a retry on that error could never have fired. (An earlier version of this PR retried the error inside the starter's loop; the reviewer's probe showed that path is never reached in this order:waitReady761returned nil in 300 of 300 starts of a second server on a port a first one held.)startTCPReady889(readiness = a TCP dial, answered by the winner's listener) and the start-shutdown rig (same/pingprobe) have the same hole.Not established: that #1113 introduced it. #1113 narrowed the SSE starter's retry from any error (15 x 200 ms) to a ring ENOMEM only, but the old loop had the same hole and would not have seen this run's error either. The body of the first version said "regression from #1113"; that claim is withdrawn.
Fix, per starter:
startTCPReady889(and a new sharedstartPicked1104): the picked listener is handed to the server (StartWithListener), so the port is never free between the pick and the bind. A second starter that picks the same port gets another one, and a readiness probe can only be answered by the server that owns the port. The h2upgrade readiness now waits for the engine to publish its address (Server.Addr()) and then dials, since a dial alone proves nothing against a listener the server holds from the start. The retry on a ring ENOMEM stays (a fresh server and listener per try). The Adaptive engine needsConfig.Addrto be its listener's address; the helper sets it.Startfor its plain-Startarm (that arm is the test), so it cannot hand a listener there. Its/pingnow returns a per-server token andwaitReadyErrcompares it: another server's answer is not ready, and the loser's bind error is what the retry loop sees (address already in use, retried up tomaxAddrInUseTries= 10 times on fresh ports).Failing-first test (commit 1):
TestTwoStartsRacingForOnePortEndOnPortsOfTheirOwn1104makes two starters pick the same port at the same moment (a hook,listenForStart1104), 4 s bound, 40 rounds: each must end with a server that answers as itself on a port of its own. On the pick-close-Startcode it fails 10 of 10 runs (-race -count=10):server 0 at 127.0.0.1:N answered "server-0-1", want "server-0-0"andboth starters ended on 127.0.0.1:N. After commit 2 it passes.TestWaitReadyErrDoesNotTakeAnotherServersAnswer1104pins the token check (another server's/pingbody does not count; Start's bind error is returned), andTestRetryStartRetriesAnAddressInUse1104pins the retry bound as exactly 10 tries.Verification (
golang:1.27.3,--cpus 2, 8 MiB memlock,-race): the new and changed tests-count=10(82 s): the race test, the token test, the retry tests,TestIsRingENOMEM1104,TestEnableH2UpgradeMatrix889,TestUpgradeNeedsTheUpgradeConnectionToken889,TestStartReturnsAfterShutdown,TestStartWithListenerReturnsAfterShutdown;TestStalledSSEEndsWithShutdown855-count=10(296 s). All pass; none skips. Failure rate of the original flake: unknown (it did not occur in 10 of 10 runs on main either); the evidence is the deterministic collision test.retryRingENOMEMandstartRetryingRingENOMEMare renamedretryStart1104andstartRetrying1104(they retry a ring ENOMEM and a taken port) and the log line says so.Not changed here: the eight other starters that pick, close and call
Start()(package G, see Findings).2.
TestShutdownPoolWaitGateRequestsInProgressAndIdleConns885/sync: three resets at 257 msThe CI log (Coverage job,
-race -cover, 4 vCPU) shows three failures in one run, all 257 to 258 ms after the shutdown began:connection with no byte sent 0: read ... connection reset by peer at 257ms, want a FIN,the rest of the upload, sent 258ms into the shutdown: write ... connection reset by peer: a request in progress was cut, andthe download's head: read ... connection reset by peer. 250 ms ispoolWaitGrace: the gate's first pass (poolWaitGate->closeIdleH1, epoll, #1116) closed conns it should have left, in the same pass.I could not reproduce it:
-race -cover -count=20at--cpus 2passed 20 of 20 (156 s), and again 20 of 20 with four busy loops competing for the two CPUs (303 s). The numbers below are for the mechanism, not the rate.Is the RST legitimate? The reset is what TCP does for a close(2) of a socket with unread bytes, but the close is a defect of the gate for the conns that held a request.
closeIdleH1treats a conn as "accepted and has sent nothing" whencs.detectedis false andcs.detectN == 0, which means the LOOP has read no byte of it. A conn accepted in the same loop pass has not been read yet (the first read comes with the nextepoll_wait), and a loop that is behind (24 HTTP/2 downloads of 16 MiB under-race -cover) can have the request of an upload, a download or a keep-alive sitting unread in the kernel's receive queue when the pass runs. The pass closes it (closeConn), cutting the request in progress, and with enough unread bytes the close is a reset.closeIdleH1checks the send queue (TIOCOUTQ) and the conn's own pending state, but not the receive queue (TIOCINQ), andrefusesRecvwould never read that request afterwards.Deterministic reproduction (an
internal/engine/epolltest, kept as local evidence only, not in this PR; it fails on main): a handler on a loop thread blocks, 32 clients connect and send a request while the loop cannot accept them, then the handler does what the loop does when the gate is up (acceptAll,refuseRecv = true,closeIdleH1).--cpus 2,-race,-count=10, main: 10 of 10 runs fail; 11 to 21 of the 32 conns (those on the held loop) are closed by the gate pass with their request unread (EOF rather than a reset because the request is small). The io_uring twin (#1123,shutdown_gate_884.go) arms its recv before the gate sees a conn, so the window differs; not analysed further.The gate defect is tracked separately: lane L20 (branch
l20-gate-unread) fixescloseIdleH1andrefusesRecvwith its own regression test (this reproduction). This PR does not touch the gate.What this PR's test change does, and does not do. The test slept a fixed 1.3 s and then began the shutdown, assuming the engine had accepted and read everything.
waitEngineBusy1104now waits, up to 20 s, until the engine counts exactly what the test opened and sent, over a baseline taken before the first dial (settledEngineMetrics1104: metrics unchanged for 100 ms after the server's readiness probe, whose keep-alive conn stays open in the default transport's pool and whose request is counted after its response, which is the surplus the review found when the baseline was absolute):+34 conns(24 HTTP/2, 6 keep-alive, 2 silent, the download, the upload on the sync arm or the promoted conn on the async arm) and+32requests on both arms (24 HTTP/2 GETs, 6 pings, the download's GET, and the upload on the sync arm or the promoted conn's ping on the async one). The loop counts the upload's request once it has read its headers and first 64 KiB, so waiting for it also covers the upload having been read (an instrumented run of 6 shows +30 requests after the keep-alive step, +31 after the download's GET is sent, +32 after the upload: sync). The conn count is exact, +34 in every run. The request count is a lower bound: it ends at 32 or 33 on both arms, and the one extra unit is already there after the keep-alive step, before the download and the upload are sent (sync +30 or +31 then, async +31 or +32), so it is neither of them; I did not find its source, which is why the request wait is>=and the conn wait exact. The wait cannot hang: it has a 20 s bound and a message with the numbers.With this wait the test no longer exercises the gate defect: it begins the shutdown only when the engine has the conns and the requests, so it passes with the defect present. The flake is therefore masked, not gone, until L20 lands; once it does, the wait is no longer needed for the gate's sake and can be dropped (it keeps the test independent of how far behind the loop is). I cannot show the test failing before the wait (no reproduction); with it,
-race -count=5passes (42 s) and-race -cover -count=3passes (27 s).The silent conn's reset is not explained. A conn that sent nothing has no unread byte, so a close(2) of it is a FIN; I could not reproduce a reset for it. It was in the same pass as the two that explain themselves; all three at 257 to 258 ms suggest a shared loop-level cause I did not find.
Findings, not fixed here
l20-gate-unread, another builder), which uses the saved deterministic test; this PR does not touch the gate or that test. Once L20 lands,waitEngineBusy1104is no longer needed for the gate's sake (the gate will not close a conn whose request is unread) and can be dropped; it stays until then to make the test independent of how far behind the loop is. The finding as written:closeIdleH1should skip a conn with unread receive-queue bytes (unix.IoctlGetInt(cs.fd, unix.TIOCINQ) != 0), andrefusesRecvshould keep reading a conn that has not been read yet but holds the bytes of a first request that arrived before the gate (a request in progress is answered withConnection: close, asstd's Shutdown answers an active conn). One check in the pass plus one in the predicate; a product change outside this lane's files, with the deterministic test above as its failing-first test.isRingENOMEMintest/server(test/server: start helpers retry the io_uring ring-setup ENOMEM (shared predicate; Refs #1104) #1113) matchesio_uring not available on this systemunconditionally, so on a host without io_uring every starter waits the 30 s window before failing (the test/integration and iouring PRs scope that clause withengineMayUseIOUring). Not changed here.test/serverfiles still pick a port, close it and callStart():startServerConfig761(large_response, used by many parallel tests),startServer421(auto_head_options_engines_421),bodylimit_default_889,chunked_promotion_889,detect_split_first_segment_870,h2_stream_context_836,h2upgrade_disabled_964andserver_sync_goexit_848:491. Seven of them probe/pingand so share the hole this PR closes for the SSE, h2upgrade and start-shutdown starters; they never failed on it. They go throughstartPicked1104,startServerConfig761first.Release note
None (tests only).