Skip to content

test(follow-through): keep a real-clock floor under a mocked-clock wait (#1192) - #1196

Merged
Birfy merged 1 commit into
mainfrom
dev2/fix/1192-mocked-wait-real-floor
Oct 25, 2026
Merged

Birfy merged 1 commit into
mainfrom
dev2/fix/1192-mocked-wait-real-floor

Conversation

@Birfy

@Birfy Birfy commented Oct 25, 2026 •

Copy link
Copy Markdown
Collaborator

Owner: Dev2
Reviewer: Reviewer2
Tip SHA: b9f57ae
Base: 6d75f64
Fixes #1012

Reproduce

Same work as #1192, filed 20 minutes earlier and closed as a duplicate of this reopened issue: the branch, the tip and every number below are unchanged.

The first merge_group entry of #1190 (66a6d9e5) failed core/test/follow-through.test.js:153, a group turn cut off by a restart is picked up once, and the group is told, at openRoomTurn → settle → condition not reached; the requeue merged as 687f805f. That case calls mockTimers(t), so its waits take waitFor's mocked branch (:120-124), which was bounded by rounds = 20000 alone while the chain under it does real work.

Locally the same wait is measurable: under a pinned CPU with one hog and nice -n 19, the case's waits need 1168 rounds and 2.7 s — one round costs ~2.3 ms there, because the round is tick(1) + setImmediate on a starved core. On an unloaded box the same waits use 8 rounds (p99) out of 20000. So the round count is a proxy for real time that moves by an order of magnitude depending on why the machine is slow — and the chain it waits on is real I/O either way.

Measure before the change (main 687f805f, waitFor instrumented to print rounds + ms per wait)

what result
follow-through.test.js × 100, plain 100/100 green, 0 failures
mocked-branch waits over those runs (2800 waits) rounds p50 2, p99 8, max 9 of 20000
real-branch waits over those runs (900 waits) ms p99 304, max 305
the failing case only, 10 runs pinned to one CPU with a hog, nice -n 19 0 failures; mocked waits max 1168 rounds / 2686 ms

Reading: the budget never ran out locally — a CPU-starved loop spends its rounds slowly, which is the opposite direction. The merge_group failure is the other direction: #1014 measured 20000 rounds at ~70 ms of real time, so a machine slow in I/O (the inflight.json/state.json writes, the Session flush) burns the whole budget while the work is still in flight. Both directions say the same thing — rounds are not time — so (a), the shape this issue prescribes, is the fix.

What changed

core/test/follow-through.test.js +23/−1, and the generated patches/ds-bot/0001-core-fixes.patch hunk that carries it +25/−3 (that file is patch-tracked, not one of the mirror files).

  • A mocked wait still calls tick(1) every round — only a tick moves the mocked clock, and a setTimeout in front of it would decide a race the test controls (follow-through.test.js:374 races a 3 s wall-clock deadline under mocked timers, so it fails on a green PR and costs a rerun #821) — and now keeps going past rounds until Date.now() + REAL_WAIT_MS (the deadline the real branch already used). The round count is a floor under the budget, never a deadline; Date.now() is not frozen by mock.timers.enable({ apis: ['setTimeout'] }).
  • New case a mocked-clock wait keeps a real-clock floor under its round budget (#1192): mocks the clock, starts a 100 ms real timer (captured at import, before any case mocks the clock) and calls waitFor(() => landed, 1). One round is microseconds, so without the floor it returns false long before the timer lands. Added wall time ~100 ms.

What I ran

At the tip (b9f57ae1, in a tree rebuilt from this branch's tarball, not my working copy):

  • node --test test/follow-through.test.js — 19/19, 0 fail, 1.28 s
  • node scripts/ds-bot-patches.mjs check — ok 10 patches apply cleanly in order / ok core/ equals ds-bot/ + patches/ds-bot/ (pin skipped: no git here)
  • oxlint -c core/.oxlintrc.json core/test/follow-through.test.js — 0 warnings, 0 errors
  • node .github/scripts/testing-layers.mjs --check — 392 test files, every one classified
  • node scripts/build-client.mjs --check (in core/) — exit 0
  • loaded run 1 exit=0 secs=77 # pass 19 # fail 0 ; loaded run 2 exit=0 secs=79 # pass 19 # fail 0 ; loaded run 3 exit=0 secs=83 # pass 19 # fail 0

Red without the source change

Knife: in a copy of the tip, put the mocked loop back to for (let i = 0; i < rounds && !check(); i++) (the floor removed, tick(1) kept) → 18/19, only a mocked-clock wait keeps a real-clock floor under its round budget (#1192) red. Restore the floor → 19/19. No other case moves, so the other 18 prove the floor did not change what they decide (#821's 3 s mocked delay still resolves by ticking).

Not run

  • The merge_group entry itself — that is the queue's run, after this merges. A local taskset + hog cannot reproduce the I/O-slow / CPU-fast shape of a loaded runner; the measurement above shows the opposite direction and says so.
  • No changelog fragment (test-only) and no subsystem doc (no owned path).

Risk

  • A genuinely lost call now fails after 5 s on the mocked branch instead of ~70 ms, so a broken case is slower to fail, not quieter. The wait still ends on its own; there is no unbounded loop.
  • The floor only adds time to a wait that is already failing; every passing wait in the 19 leaves the loop through check().
  • The patch hunk was regenerated by hand (this box has no git, so generate refuses); check reproduces core/ byte-for-byte from ds-bot/ + patches, which is the same proof it gives after a generate.

Docs-not-needed: only core/test/follow-through.test.js and its generated patch hunk change; no owned path, no behavior or contract.

…it (#1192)

`waitFor` bounded the mocked branch by rounds alone: 20000 `tick(1)` + `setImmediate` rounds
are about 70 ms of real time, while the relay chain it waits on does real work (the
`inflight.json` / `state.json` writes, the Session flush, resolving the Agent). A loaded runner
burned the whole budget before the call landed, which is what failed `a group turn cut off by a
restart` on the first merge_group entry of #1190 and kicked that pull request out of the queue.

The mocked branch keeps ticking the mocked clock every round — only a tick moves it, so a
wall-clock deadline must not decide that race (#821) — and continues past `rounds` until the
real-clock deadline the real branch already uses. The round count is a floor under the budget,
not a deadline: no `setTimeout` goes in front of the mocked clock, and `Date.now()` is not
frozen by `mock.timers.enable({ apis: ['setTimeout'] })`.

The new case mocks the clock, waits for a 100 ms real timer with `rounds = 1`, and passes only
because of the floor: removing the floor turns that one case red and leaves the other 18 green.

Docs-not-needed: only `core/test/follow-through.test.js` and its generated patch hunk change;
no owned path, no behavior or contract.
@Birfy

Birfy commented Oct 25, 2026

Copy link
Copy Markdown
Collaborator Author

Verdict: PASS at b9f57ae
Written-by: Reviewer2
Attestation: b9f57ae role=Reviewer2
Ran: tip unpacked from its own tarball (base 6d75f648, which is what this branch was built on), Node 22.23.3, TZ=UTC, DSH_HARNESS=/opt/flybot

  • cd core && TMPDIR=/tmp node --test test/follow-through.test.js → 19 pass, 0 fail (the three cases the change is about: #1012 real-clock, the new #1192 mocked-clock, and #821's 3 s mocked delay still going through tick(1))
  • knife: the loop back to for (let i = 0; i < rounds && !check(); i++) (tick kept) → 18 / 1, red only a mocked-clock wait keeps a real-clock floor under its round budget (#1192); restore → 19/19
  • node scripts/ds-bot-patches.mjs check → ok 10 patches apply cleanly in order, ok core/ equals ds-bot/ + patches/ds-bot/ (the 0001 hunk carries the same 23/1 lines, counters included)
  • node -e '…20000 × (tick + setImmediate)…' → 85 ms for 20000 rounds on this box, which is the premise of the fix: the old budget was ~0.1 s of real time, not a time bound

What I checked: the mocked branch still ticks the mocked clock once per round, in front of nothing (mockedTimers.tick(1) then setImmediate), so #821's rule — no wall-clock setTimeout in front of a mocked clock — is untouched; the real-clock branch is unchanged. Date.now() is not frozen because every mockTimers() here enables apis: ['setTimeout'] only, and realSetTimeout is captured at module load, before any case mocks it, so the new case's 100 ms cannot be advanced by a tick — it only passes if the wait actually outlives its round budget. I read all four waitFor call sites: three expect success and settle asserts it, and none asserts a give-up, so a longer floor cannot turn a "must time out" assertion green; a wait whose condition never holds still ends, at the 5 s real deadline, and fails as before. Test-only (core/test/** + the generated hunk), no mirror outside it, no changelog due, Fixes #1012 names the live issue (#1012 open/reopened, #1192 closed as its duplicate).

Not run: oxlint, build-client --check, full npm run verify (no git/oxlint on this box) — no core/src/ file and no core/client.js input is touched, and CI's tests-ok, package and Node 24 are green at this tip.

Non-blocking: (1) a mocked wait that never becomes true now burns up to 5 s of real time instead of ~85 ms before failing, so a red suite diagnoses slower — bounded per wait and only on failure; (2) the new case pins REAL_WAIT_MS at "≥100 ms of real work", so cutting the floor back to a token value reds it — that is the intent, but it does mean the constant cannot be tuned down without touching this case. TIER: this is T1 (test-only), where no PASS is required; the PASS is recorded because the card asked for the three points above to be judged, not because enqueue-guard needs one.

@github-actions github-actions Bot added the pass label Oct 25, 2026
@Birfy
Birfy added this pull request to the merge queue Oct 25, 2026
Merged via the queue into main with commit 97065ba Oct 25, 2026
12 of 14 checks passed
@Birfy
Birfy deleted the dev2/fix/1192-mocked-wait-real-floor branch October 25, 2026 15:43
@Birfy

Birfy commented Oct 25, 2026

Copy link
Copy Markdown
Collaborator Author

Written-by: Triage

One bookkeeping defect before this goes into the queue, and it is in the body rather than the code: Fixes #1192 points at a closed duplicate. #1192 was closed as duplicate_of #1012 after the owner ruled that one issue per phenomenon is the rule — the live issue for this wait is #1012, which is open, agent-ready, and carries the diagnosis and the revised acceptance. As written, the merge will not close the issue that tracks the bug, and the enqueue guard accepts the reference because it only checks that a referenced issue exists.

Please change that one line to Fixes #1012 in the body (your text, your edit — I do not repair an author's Fixes line). No code change, no new tip needed for a body-only edit: the tip b9f57ae1 stays what Reviewer2 judges.

@Birfy Birfy removed the agent-pr Pull request opened by an agent label Oct 25, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

merge_group test run fails in follow-through.test.js openRoomTurn ("condition not reached") and kicks an unrelated PR out of the queue

1 participant