test(hooks): pin the guard counter's wait on its settings, not on the clock - #417
Merged
Merged
Conversation
… clock The held-lock guard tests asserted that a hook run under a held write lock takes less than a second longer than an unlocked run. The counter's designed wait is 200 ms, but on hosted CI runners the whole test took 0.7 to 1.0 s on green runs on main, and the bound has failed three times at random within two hours, each time on a macOS runner: 1130 and 1064 ms over the unlocked run (macOS Node 24, pull request 413; the same commit passed on a rerun), 1025 ms (macOS Node 22, main after that merge) and 1005 ms (macOS Node 22, pull request 415), each against the 1000 ms limit. None of those changes touched the counter or the lock handling of the guard hooks. The timing bound is removed. The tests keep everything else they checked: the hook finishes, prints the warning and says on stderr that the fire was not counted, and a counter that fell back to the database's own 30 s wait is still killed at the 12 s limit. What the bound stood for is pinned on what sets the wait instead: GUARD_COUNTER_WAIT_MS is at most a quarter of HOOK_BUSY_TIMEOUT_MS and at most half a second (the ratio alone would let both be raised together), and the connection recordGuardFires opens ends up with that constant as its busy_timeout, read back off the connection rather than from the clock. The two held-lock test titles now say what they assert. Not covered any more: a second database write on the guard-fired path that waits the general HOOK_BUSY_TIMEOUT_MS. The old bound caught it, and so did nothing else; it costs latency, not the warning (the hooks have 5 s), and it needs a self-calibrated comparison rather than a constant. Tracked separately.
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.
Refs #416. Test-only change to
tests/hooks/guard-check.test.ts.The held-lock guard tests asserted that a hook run under a held write lock takes less than a second longer than an unlocked run. That bound has failed at random on a macOS runner three times within two hours, on changes that did not touch the counter or the lock handling of the guard hooks:
The counter's designed wait is 200 ms. On hosted runners the whole test took 0.7 to 1.0 s on green runs on main; on the maintainer's laptop the three held-lock tests take about 0.35 to 0.41 s. So the bound left no margin, and it has now cost a required-check failure on two pull requests and a red run on main.
What changes
recordGuardFiresopens ends up with that wait as itsbusy_timeout, read back off the connection.Evidence
npm run verifyGREEN on the tree of the commit (tree dc7a30d5ca85; 261 test files, 4452 tests passed, 9 skipped). The verification audit that flagged the first version of the second pin (a test reading source text, class C6) reportsnew=0.scripts/hooks/_shared.js, sha256 restored each time): the counter constant raised to 2000: exactly the constant pin goes red; the counter using the general wait: exactly the read-back pin goes red (the three held-lock behaviour tests stay green, so the pin is what carries this); the counter's pragma line removed: five red (three held-lock tests killed at the 12 s limit, the read-back pin, the pipe-buffer test); both constants raised together (2000 and 8000): exactly the constant pin goes red. The fresh-eyes reviewer repeated the first three independently.Simplification pass
A read-only pass over the diff found three candidates, all cosmetic, none applied: applying any of them means another commit, another full verification and receipt, and a restart of the whole CI matrix (the Windows legs alone take half an hour), for a pull request whose point is to stop CI failing at random. They are a three-line comment paragraph that the new test titles now repeat; two dynamic imports of the same module that could be one static import (this file uses
await importeverywhere else, so it would be mixed for one line); and theeffectivearray of which only the last element is read (one variable would do). It also found one wording nit: the comment on the absolute cap illustrates the ratio's gap with 2000 and 8000, buthook-time-budgets.test.tsalready keeps the general wait below 3000 ms, so a reachable pair would be 700 and 2800 (the ratio passes, the cap fails).Kept on purpose, each checked for a consumer or an overlap: the ratio and the cap are the same number today (500) but each is the only check for a different regression once a constant moves (the ratio catches the counter adopting the general wait; the cap catches the ratio's gap); the unlocked reference run (it separates "the lock broke the hook" from "the hook is broken", in a file whose held-lock tests have already flaked three times); the two new tests stay two (arithmetic on two exports against a spy on a real connection); and neither pin duplicates a check in
hook-time-budgets.test.ts(that file checks the connectionopenHookDbopens against the smallest declared hook budget; the read-back test applies the same idea to the one connectionopenHookDbnever opens).Not covered any more (tracked in #416)
A second database write on the guard-fired path that waits the general
HOOK_BUSY_TIMEOUT_MS(a fire ledger or a cooldown added afterrecordGuardFires, say). The old bound caught it and no other test does. It costs latency, not the warning: the hooks have 5 s, so one extra 2 s wait leaves the warning intact. A fix is a design of its own: it needs a reference measured in the same run rather than a constant, and under the exclusive lock thathook-time-budgets.test.tsuses readers are blocked, so a seeded guard never fires there. #416 has the reviewer's mutation and the direction.Not yet run on hosted runners
The two new tests read no clock, so they cannot fail on timing. This pull request's own CI is their first hosted run.