test(router): wrap the clock stub once so a failing test cannot race the live engine - #621
Merged
Merged
Conversation
…blish the controls' preconditions (celeris#620) Two faults in the celeris#592 rig, both test-only; no engine or router behaviour changes. 1. The clock stub was restored while the server was still serving, so EVERY failure of TestAdaptiveSettledRouteRetime592 also reported a data race. stubNowNano assigned the package var nowNano, and its restore ran from a t.Fatalf's runtime.Goexit while the event loops were still reading the same var through isPromoted -> adaptivePromoted -> routeAsync. Fixed structurally rather than by a cleanup-ordering rule, because a rule only holds until the next test forgets it: nowNano is wrapped exactly once, from a test-file init, before any test can have started a server, and stubbing now only flips atomics. nowNano is never written again for the life of the test binary, so no present or future call site can reintroduce the racing write. stubNowNano also takes *testing.T and releases via t.Cleanup, which runs after every defer in the test body. The rig additionally JOINS the engine on every exit path instead of only cancelling its context: stopEngine (registered after the stub, so LIFO runs it first) waits for StartWithListenerAndContext to return, which both native engines do only after wg.Wait() on their loops. A t.Fatalf no longer leaves two live workers running into the next subtest. Discriminating experiment: with a deliberate t.Fatalf injected into the settled arm, origin/main reports the failure AND "WARNING: DATA RACE" (stubNowNano.func2 at router_async_test.go:286, against isPromoted at router.go:340); this tree reports the failure and no race. 6 injected failures per tree, 4 race reports on main (the detector dedupes by stack), 0 here. 2. The controls' preconditions were jitter-sensitive. Every warm-up in this rig runs against a FAST store, so a promotion during warm-up is runner jitter -- handler.go calls promoteRouteImmediate on a SINGLE inline run over adaptiveBlockingThreshold, so one slow request under -race on a loaded box is enough, and because the rig freezes the promotion clock the TTL that would undo it never fires. That is the "precondition: /kv must still be learning after 100 runs (settled=false promoted=true)" failure in run 34863046623, and it is worse in the settled arm, where the same promotion also clears the fast streak and takes the route off the timed path so it can never settle. Both adaptive warm loops now drive such a promotion back out through the engine's own de-promotion transition (depromote589, the body of isPromoted's expiry branch) and count it on the result line as warm_depromotions. The assertion is not loosened: the preconditions are still asserted afterwards -- reaching one now means the de-promotion itself did not take -- and the controls' claims are untouched, so they still have to invert. Verified in golang:1.27, --cpus 4, seccomp=unconfined, memlock 128 MiB. 20 runs per engine of the full rig under -race on a deliberately loaded box (eight `yes > /dev/null` plus a cold-cache `go build ./...` loop): 120 subtests, workers=2 throughout, 0 skips, 0 data races, 0 precondition failures, both controls CONTROL_OK 20/20 on both engines with the #589 claim failing in all 120, and the settled arm reporting FIXED. One warm-up jitter promotion was caught and undone (iouring/settled, warm_depromotions=1) -- the fault-2 trigger, now handled. Still open, and NOT introduced here: the epoll settled arm's absolute 5 ms /ping bar measures the runner as much as the engine at that load level. It failed 7/20 on this tree (stalled_frac 0.053-0.083) and 2/10 on origin/main under the same load, 0/5 on both when quiet, and the sample count halves (~460 vs ~900) because the test's own client loop is descheduled -- and the async control, whose worker is provably free, reaches 0.094 on the same box and passes only because it is judged on the median.
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
1 participant
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.
Fixes #620. A failure of
TestAdaptiveSettledRouteRetime592no longer reports a phantom data race on top of the real reason.The class fix is structural, not an ordering rule
The issue asked for an ordering fix — register the server shutdown after the stub so it runs before the restore. That works, but only until the next test forgets it. Instead
nowNanois now wrapped exactly once, from aninit(), before any test can have started a server; stubbing only flips atomics. The variable is never assigned again for the life of the test binary, so no present or future call site can reintroduce the racing write. Cost: one atomic load per call, test binary only, on a path that already runs only for promoted routes.All four
stubNowNanocall sites were audited. Three drive the router in-process and had no hazard today; they are converted anyway, because the hazard is oneNew(...)away. The ordering fix is in as well, because the race was also telling us the rig leaked a live engine: the shutdown now genuinely joinsListen.The discriminating control
Same deliberate
t.Fatalfinjected into the settled arm, engine live, on both trees, same container.WARNING: DATA RACEmainTwenty runs per engine, under load
Eight spinners plus a cold-cache
go build ./...loop in the same cgroup, peak load average 14.7. The load bites:/pingmax goes from 2 ms quiet to 72 ms, and the sampler collects about 460 samples per window instead of 900.120 subtests, zero skips, zero data races, zero precondition failures, two workers in all 120. The
#592state assertion held 20/20 on both engines: promoted within the bound, at least eight promoted connections, worst promotion latency 5,489 ms against an 8,000 ms bound. Both controls inverted 40/40.Fault 2 fired during the run, and it was worse than filed
One io_uring run shows
warm_reqs=425 warm_depromotions=1: a warm-up run overran the blocking threshold, promotion cleared the fast streak, and the rig put the route back on the timed path so the streak could re-accumulate. The issue found this innegctrl_learning; it is in fact worse in the settled arm, where the clock is frozen, so onmaina promotion there never expires and the route is off the timed path forever — that run could never have settled and would have burned the whole warm bound before failing. Both adaptive warm loops are fixed.One fault deliberately not fixed here
The epoll settled arm failed 7 of 20 on this branch under that load, all on the same absolute 5 ms
/pingbar. It is pre-existing and it is not measuring the engine:mainunder identical load fails the same way 2 of 10; both trees are 0 of 5 quiet; and decisively,negctrl_async— where every connection is async-dispatched and the worker is provably free — reaches a stalled fraction of 0.094 on the same box, passing only because the controls are judged on the median. A bar that a provably-free worker exceeds is measuring the scheduler, not the fix. Re-basing it changes what the test asserts, which is outside this issue, so it is filed separately.