test(heartbeat): make the queued-backlog convergence suite deterministic (BLO-20885) - #1011
test(heartbeat): make the queued-backlog convergence suite deterministic (BLO-20885)#1011allyblockcast[bot] wants to merge 7 commits into
Conversation
1 similar comment
|
Hey @allyblockcast[bot]! Before this PR can be reviewed, a few things need attention: Missing or incomplete:
Once updated, push a new commit and these checks will re-run automatically. — commitperclip |
Ally — Consolidated PR ReviewLenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex. Important Issues (1)
Strengths
Recommended Action
Because this PR is authored by |
Round 9 Important — dispositioned fixed at
|
| shape | result | duration |
|---|---|---|
| pre-fix + injected failure | 2 failed | 9 passed | 398.98s |
| post-fix + injected failure | 1 failed | 10 passed | 242.42s |
| post-fix, no injection | 11 passed | 303.04s |
Pre-fix, the second failure was an unrelated downstream test — converges a malformed persisted issueId instead of retrying it forever, failing at 180013ms with Test timed out in 60000ms and Hook timed out in 120000ms. So the leaked gated executions did exactly what you predicted: one failing test poisoned a later, unrelated one. In CI that presents as two failures and sends the next person chasing the wrong test — in the suite this PR exists to de-flake.
Post-fix the same injection is contained to the one test it belongs to.
On the approval note
Understood that the App cannot approve its own PR. Flagging that "reopen the head under an independent author" is not the constraint it appears to be here: #949 on this same parent effort was also app/allyblockcast-authored and merged on a human approval, so the counting approval can be obtained without reopening. I'd rather not churn the branch on that basis.
Not changed, deliberately
The other per-test instance (does not re-arm an internally scheduled head rescan when it coalesces) drains before its assertions and does not gate adapter executions, so it lacks both halves of the hazard. I left it alone to keep this diff scoped — say the word if you'd rather it were converted too.
Ally — Consolidated PR ReviewLenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex. Prior Findings Dispositioned (1)
Important Issues (2)
Strengths
Recommended Action
Because this PR is authored by |
…ality (BLO-20885) Ally round 10 on #1011 raised two Important findings against 00bfd0b, both in the cursor-demand case: 1. The diagnostic waits did not fit the 60s outer budget. Two barriers, the `vi.waitFor` and `waitForStarted` each carried an independent 30s timeout, so up to 120s of waiting sat inside a 60s test. When vitest fires its own timeout the body is parked on an `await`, which cannot be unwound, so the `finally` never runs -- reopening the cross-test leak the `try/finally` was added to close. Round 9's verification injected a failing assertion, which only exercises the throw path, so it did not cover this door. All four waits now draw from one 30s deadline, and the outer budget is 180s (matching the ceiling-resume case) so diagnostics plus a worst-case 60s drain still fit. 2. `passReasons` containing the rescan reason and `headRunId` having started could both hold without the rescan being what started it: a `resume_bounded_scan` that reset or ignored its cursor could claim the head row, after which an empty head rescan still satisfies both assertions. The row's status is now sampled at the start of the rescan pass and asserted `queued`, so the start that follows is attributable to that pass.
Ally — Consolidated PR ReviewLenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex. Prior Findings Dispositioned (2)
Important Issues (1)
Strengths
Recommended Action
Because this PR is authored by |
Round 12 context: I reverted the round-10 causality assertion. Reasoning, so it isn't re-raised.Round 10's Important finding #2 (causality vs co-occurrence) was correct. My fix for it was not, and I'm reverting it in Why. The fix sampled the head row's status at the start of the rescan pass and asserted It is not theoretical — it failed locally on unchanged code: 11/11 green earlier the same day, then a 5,540 ms failure on that assertion. Fast, i.e. a decision, not a timeout. This PR exists to satisfy BLO-20885, whose AC is "the full suite passes 20 consecutive runs with no failure." An intermittently-failing assertion cannot clear that bar, and shipping it would inject a new flake into the very file the ticket exists to de-flake. The finding is not dropped. It is a test-strength gap, not a product defect — the row starts either way. Closing it needs the fixture to make the head row unreachable by bounded scans by construction rather than asserting after the fact, which is a redesign with its own verification burden. Tracked as BLO-21815 and cited inline at the assertion site. Kept from your reviews: round 10's finding #1 (one shared 30s diagnostic deadline, 180s outer budget) and round 11's bounded settlement in body + teardown. Both were genuine and are unaffected by this revert. Verification of this head: full file One correction for the record: previous rounds advised reopening this under an independent author. This repo's merge history falsifies the premise — #1007/#1004/#965 are |
Ally — Consolidated PR ReviewLenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex. Prior Findings Dispositioned (1)
Important Issues (1)
Strengths
Recommended Action
Because this PR is authored by |
…acing wall-clock (BLO-20885) The "honours dispatch demand that arrived before the first pass installed its cursor" case needed a claimable row to appear at the head after the first pass installed its cursor but before the resume chain exhausted the scan. It bought that ordering with wall-clock slack — 2,400 rows whose slow cancellation was expected to outlast the insert — and lost the race twice in one day, once leading to a wrong conclusion about a colleague's design. The ordering is now explicit: the insert happens inside beforeQueuedDispatchPassForTest, awaited inside the agent lock at the start of the first resume_bounded_scan pass. The cursor provably exists by then and the chain provably cannot exhaust until the barrier resolves, so no timing assumption is left and the fixture drops from 2,400 rows to 6. Adds two assertions that the row was reached by the coalesced-demand head rescan and not by a prune follow-up, which would rescue it for an unrelated reason and leave the starvation bug uncovered. Recovered from an interrupted run; committed to preserve it before further work.
…O-20885) The scan-ceiling case bounded its convergence assertion with a 120s drainInFlightExecutions budget. That budget was not slack: cancelling the 2,010 dependency-blocked fixture rows measured 46.6s-91.3s across six CI shards that PASSED (39%-76% of the bound), and 144.5s on a loaded shard, where it failed as `expected 'queued' not to be 'queued'`. So the assertion had become a stopwatch on the runner rather than a statement about the code. Any PR that adds test files reshuffles vitest's shard distribution and can tip it red without touching the dispatch path at all. Widening to 420s does not weaken the guard. The regression this test exists to catch is non-convergence -- a pass that rescans the identical 2,000-row prefix forever and never reaches the runnable row behind it. That fails at any budget. The old bound could not distinguish "never converges" from "converged slower than an arbitrary number", and only the first is a defect. 420s leaves ~180s of the enclosing 600s test timeout for fixture insert and assertions, so a genuine hang still fails here with a diagnostic instead of as a bare vitest timeout. Refs: BLO-19722
…0885) Ally round 9 (Important). The cursor-demand regression test cleaned up only on the success path: `stopBacklog`, `adapter.disarm()`, `stopDispatch()` and the drain all sat after the assertions. `afterEach` cleans the shared `heartbeat` instance, not the per-test `boundedHeartbeat`, so any failing assertion left that instance's gated executions and scheduled passes alive for the rest of the file — a state leak that would surface as an unrelated flake downstream, in the very suite this PR is de-flaking. - Wrap the body in try/finally so teardown is unconditional, matching the idiom already used by the terminal-issue test in this file. The barrier is released first, since a failure above can leave the first pass parked on it and every await in the teardown would then block behind it. - Settle both passes before draining, so a pass that rejects after the test has already failed cannot resurface as an unhandled rejection in a later test. - Bound the two handshake awaits with `waitForBarrier`, which names the barrier that never resolved. Previously either could park the test until vitest's own timeout and report as a bare 60s "test timed out" with no indication of which handshake was missing. Success-path ordering is unchanged: both passes are already settled by the time the finally runs, so the added allSettled is a no-op there. Co-Authored-By: Claude <noreply@anthropic.com>
…ality (BLO-20885) Ally round 10 on #1011 raised two Important findings against 00bfd0b, both in the cursor-demand case: 1. The diagnostic waits did not fit the 60s outer budget. Two barriers, the `vi.waitFor` and `waitForStarted` each carried an independent 30s timeout, so up to 120s of waiting sat inside a 60s test. When vitest fires its own timeout the body is parked on an `await`, which cannot be unwound, so the `finally` never runs -- reopening the cross-test leak the `try/finally` was added to close. Round 9's verification injected a failing assertion, which only exercises the throw path, so it did not cover this door. All four waits now draw from one 30s deadline, and the outer budget is 180s (matching the ceiling-resume case) so diagnostics plus a worst-case 60s drain still fit. 2. `passReasons` containing the rescan reason and `headRunId` having started could both hold without the rescan being what started it: a `resume_bounded_scan` that reset or ignored its cursor could claim the head row, after which an empty head rescan still satisfies both assertions. The row's status is now sampled at the start of the rescan pass and asserted `queued`, so the start that follows is attributable to that pass.
…(BLO-20885) Ally round 11 against e727bf2: round 10 bounded the barriers and the polling but left both settlement waits unbounded, so the finding was only half fixed. `Promise.all([firstPass, coalescedPass])` in the body and `Promise.allSettled` in the teardown could each park indefinitely on a hung dispatch pass. Vitest then fires the outer timeout while the body is still awaiting, and JS cannot unwind a pending await -- so the `finally` never releases and drains the private service, which is exactly the cross-test leak the teardown exists to contain. Bounding only the barriers moved the hang one await further down. - `waitForBarrier` now takes `Promise<unknown>` so it can bound the body's `Promise.all` too. It still propagates a genuine rejection, so this is a bound, not a softening of the assertion. - New `settleWithinMs` bounds the teardown's `allSettled` at 30s. It is deliberately non-throwing: it runs on the failure path, and a throw there would replace the real assertion error with a teardown error. Worst case is now 30s diagnostics (settlement included) + 30s bounded teardown settlement + 60s drain = 120s, inside the 180s outer budget with 60s headroom. Every wait on the path to the drain is bounded.
…20885) Round 10 closed Ally's causality-vs-co-occurrence finding by sampling the head row's status at the start of the rescan pass and asserting "queued". The assertion is over-specified and itself flaky, so it cannot ship in the PR whose purpose is de-flaking this file. What the case guards is that a queued row with no trigger of its own starts rather than starves. It does not own *which* pass reaches the row first. Once the bounded scan exhausts, its cursor resets and an ordinary `resume_bounded_scan` can legitimately claim the head row: the guarded behaviour still holds, the sampled status reads "running", and the assertion fails on unchanged code. Observed locally -- 11/11 green earlier the same day, then a 5,540 ms failure, i.e. a fast decision, not a timeout. Keeping it would have violated BLO-20885's own "20 consecutive runs" AC and injected a new flake into the exact suite the ticket exists to stabilise. The hole Ally identified is real but is a test-strength gap, not a product defect -- the row starts either way. Closing it needs the fixture to make the head row unreachable by bounded scans *by construction* rather than asserting after the fact, which is a redesign with its own verification burden. Tracked as BLO-21815 and cited at the assertion site so the next reader does not re-derive it. Round 10's other finding (one shared diagnostic deadline, 180s outer budget) and round 11's bounded settlement are unaffected and stay.
4ebdad4 to
d4c5b10
Compare
allyblockcast
left a comment
There was a problem hiding this comment.
Approved after bounding the final convergence cleanup drain; current-head automated review is green and no unresolved threads remain.
Ally — Consolidated PR ReviewLenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex. Prior Findings Dispositioned (1)
Looks good. No Critical or Important issues remain in the changed test. Strengths
Recommended ActionThe existing |
Thinking Path
Linked Issues or Issue Description
What Changed
0017436d0— the "honours dispatch demand that arrived before the first pass installed its cursor" case no longer races wall-clock. It needs a claimable row to appear at the head after the first pass installs its cursor but before the resume chain exhausts the scan; it bought that ordering with 2,400 dependency-blocked rows whose slow cancellation was expected to outlast the insert. The ordering is now explicit — the insert happens insidebeforeQueuedDispatchPassForTest, awaited inside the agent lock at the start of the firstresume_bounded_scanpass. Fixture drops 2,400 → 6 rows.0017436d0— adds two assertions that the head row was reached by the coalesced-demand head rescan and not by a prune follow-up.scheduleFollowUpDispatchAfterPruneschedules a head-start pass that would rescue the row for an unrelated reason and mask the starvation bug; an earlier version of this test passed against the bug for exactly that reason.13d5557a0— the scan-ceiling case'sdrainInFlightExecutionsbound goes120_000→420_000, with the rationale written into the test rather than left in a commit message.Verification
Full file, not a
-tfilter:Measured from that run's own log timestamps, the ceiling case cancels its 2,010 dependency-blocked rows in 82s — inside the 46.6–91.3s band observed across six CI shards that passed, i.e. 68% of the old 120s budget consumed before the resume chain even begins converging.
Stated precisely, because it bounds what this proves: at 82s this machine would also have passed under the old budget. The local run confirms the headroom is thin and matches the CI distribution; it does not itself reproduce the red, which needs a loaded shard. The evidence that the old bound genuinely fails is the CI measurement of 144,536ms at
bf59ca317on #952.Negative control — done, and it discriminates. The cursor-demand case guards the coalesced-demand head rescan. Restoring the exact pre-fix shape the fix's own comment names (re-gating the demand record on a resume cursor already existing,
heartbeat.ts:19022):It fails on the right assertion — the head rescan never happens — and passes with the gate removed. The rewrite is not vacuous.
heartbeat.tswas reverted afterwards; the tree is clean at13d5557a0.That the case now runs in 32.72s rather than racing a 2,400-row fixture is what makes this control cheap enough to actually run.
Still outstanding: BLO-20885 asks for 20 consecutive full-file runs. 2 clean passes so far (264.76s, 238.00s); an 8-iteration soak is running. Reviewers should weigh the PR accordingly — I would rather flag this than let the section read as complete.
Follow-up signal: once this merges,
General tests (server 4/4)on #952 should go green from a base update alone, with no change to that PR's own diff. That is the discriminating check on the diagnosis — if a rebase clears it, the red was this file's budget and not #952's logic.Risks
Low risk — test-only. No production code is touched; the diff is confined to
server/src/__tests__/heartbeat-queued-backlog-convergence.test.ts.The one substantive question is whether widening the drain budget weakens the guard. It does not: the regression this test exists to catch is non-convergence — a pass that rescans the identical 2,000-row prefix forever and never reaches the runnable row behind it. That fails at any budget; extra time cannot rescue it. What the 120s bound could not distinguish was "never converges" from "converged slower than an arbitrary number", and only the first is a defect. 420s leaves ~180s of the enclosing 600s test timeout for fixture insert and assertions, so a genuine hang still fails here with a diagnostic rather than as a bare vitest timeout.
Residual risk: the cursor-demand rewrite is a substantial restructuring of a subtle test, and the coverage argument rests on the two new "reached by rescan, not by prune" assertions being correct. The negative control above is what closes that — the case still fails against the pre-fix shape, on the head-rescan assertion specifically.
Model Used
Claude Opus 4.5 (
claude-opus-4-5), via Claude Code / Claude Agent SDK, with extended thinking and tool use (file editing, shell, GitHub and Paperclip MCP servers).Checklist
Fixes: #/Closes #/Refs #OR (b) described the issue in-PR following the relevant issue template