Skip to content

test(hooks): pin the guard counter's wait on its settings, not on the clock - #417

Merged
kevintseng merged 1 commit into
mainfrom
test/guard-timing-no-clock
Sep 22, 2026
Merged

kevintseng merged 1 commit into
mainfrom
test/guard-timing-no-clock

Conversation

@kevintseng

@kevintseng kevintseng commented Sep 22, 2026

Copy link
Copy Markdown
Contributor

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:

CI run Where Locked hook minus unlocked hook (limit 1000 ms)
35662878699, attempt 1 pull request 413, macOS Node 24 1130 ms and 1064 ms (the same commit passed on rerun)
35666125081, attempt 1 main after that merge, macOS Node 22 1025 ms
35670770428 pull request 415, macOS Node 22 1005 ms

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

  • The wall-clock bound is removed, together with the timing bookkeeping it needed.
  • Every other check of the held-lock tests stays: the unlocked reference run works, the hook is not killed at the 12 s limit (a counter that fell back to the database's own 30 s wait still fails there), exits 0, prints the warning, and says on stderr that the fire was not counted.
  • Two new tests pin what the bound stood for, without a clock: the counter's wait is at most a quarter of the general hook wait and at most 500 ms (the ratio alone would let both constants be raised together), and the connection recordGuardFires opens ends up with that wait as its busy_timeout, read back off the connection.
  • The two held-lock test titles now say what they assert.

Evidence

  • npm run verify GREEN 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) reports new=0.
  • Break-tests on the real test file (string write-back on 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.
  • Reviews: three independent reviewers (fresh-eyes, code review, silent-failure), all PASS_WITH_CONCERNS; none found a wrong result. Their findings were fixed in the commit: a ratio-only pin let both constants be raised together, a value read back from the connection is stronger than the statement passed, two titles kept a retired claim, a comment mixed two measured quantities, and the message was imprecise. One finding is not fixed here (next section).

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 import everywhere else, so it would be mixed for one line); and the effective array 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, but hook-time-budgets.test.ts already 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 connection openHookDb opens against the smallest declared hook budget; the read-back test applies the same idea to the one connection openHookDb never 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 after recordGuardFires, 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 that hook-time-budgets.test.ts uses 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.

… 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.
@kevintseng
kevintseng merged commit 78551cd into main Sep 22, 2026
14 checks passed
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.

1 participant