Skip to content

gate-lease: an uncontended run logs "acquired after" when its lock call is slow, failing the "two concurrent runs serialize" test under load #2369

Description

@cliffhall

Problem

scripts/gate-lease.test.mjs"two concurrent runs serialize: the second starts after the first ends" fails intermittently when the machine is loaded — for example while other sessions' local:gate runs are executing — and so turns the mandatory pre-push gate red on a diff that touches nothing under scripts/.

Observed on 2026-09-14 in a worktree for #2208, whose gate queued 4m31s behind another session's gate and then failed at test:scripts while two other gates were still running on the machine:

✖ two concurrent runs serialize: the second starts after the first ends (926.784042ms)
  AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
  2 !== 1
      at TestContext.<anonymous> (scripts/gate-lease.test.mjs:222:10)

Line 222 is the assertion that exactly one gate-lease: acquired after … line was logged. Two were. The same file passed 20/20 on each of three isolated re-runs immediately afterwards.

Cause

Each test uses its own freshDir() lease directory, so the real gates are not contending for this lock — the failure is timing, not overlap.

In runUnderLease (scripts/gate-lease.mjs:412-425), waited is the wall time of the whole acquireLease call, including a successful first properLockfile.lock(), and the "acquired after" line is logged when waited >= pollMs. The test passes pollMs: 25. So on a loaded machine the uncontended first run's mkdir + holder-record work can take ≥25ms, and it logs acquired after 0s exactly as the genuinely-waiting second run does.

The same measurement drives the (waited … first) suffix on the released after line (:471), so this is not only a test defect: a real gate that never queued can report gate-lease: acquired after 0s. / released after 43s (waited 0s first) whenever its lock call is slow, which misreports the thing the message exists to tell you.

Expected

"Acquired after" / "waited first" are reported only when the run actually waited on a holder — i.e. acquireLease failed at least once and looped — independent of how long an uncontended acquire takes. The test's acquired after count is then deterministic under any load.

A likely shape: have acquireLease report whether it looped (it already tracks announced), and gate both messages on that rather than on waited >= pollMs. Per #1596, the fix is to measure the right thing, not to widen pollMs in the test.

Reproduce

Load the machine (e.g. run npm run local:gate in two other worktrees with INSPECTOR_SKIP_GATE_LEASE=1, or any CPU/IO stressor), then loop node --test scripts/gate-lease.test.mjs until it fails at :222. Alternatively, inject a ≥pollMs delay into the fs passed to properLockfile.lock for the first run only — that reproduces it deterministically and makes a good regression test.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingv2Issues and PRs for v2

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions