ci(policy): size fork-heavy step timeouts against measured p100 (BLO-32670) - #1713
Conversation
…32670) `policy` failed on 2026-09-07 at `Test approval admissibility-probe backoff` after 73s under a `timeout-minutes: 1` bound, on a PR whose diff touched only `server/src/services/recovery/*`. Re-running the same commit `a759f828` with no code change went green: same input, opposite verdict. The step is not slow, it is contention-sensitive. It forks 150 short-lived `bash` processes across its 96 tests because it exercises the shipping backoff function by sourcing it rather than asserting against a copy — a property worth keeping. Wall time therefore tracks runner CPU rather than its own work: ~9s idle, 44s p100 across 58 sampled runs, 73s observed. Measured across those 58 runs, using this job's own unbounded `Checkout repository` step (47-280s on the same runners) as an in-band contention barometer, the fork-heavy steps correlate at r ~= 0.35 and run 2.3x slower in the high-load tercile; trivial steps sit at r ~= 0.05 and 1.0x. So the sensitivity is a property of forking, not of the cluster window it was first seen in. Audited all 41 bounded steps in `policy`. Three exceed 50% of a 60s budget: p100 %budget p50 step 53s 88% 24s Test pending-migration pre-flight phase budgets 53s 88% 7s Test bounded PR-check polling skills 44s 73% 10s Test approval admissibility-probe backoff The other 38 are at or under 25%, most at or under 10%, and are left at 1. Note the step that actually tripped was not the closest to its cliff. The reason this could not simply be fixed in the workflow is the guard: `policy-node-test-timeouts.test.mjs` asserted the literal `timeout-minutes: 1` on every `node --test` step, so a step whose measured p100 outgrew 60s could not be right-sized without failing CI. That made the bound a fixed number rather than a sufficient one, and left "leave it as a tripwire" as the only in-repo option. The same file already states the better invariant 30 lines down, for the chart render step (BLO-29182): that a bound exists and sits under the job cap. Relax the guard to that invariant and keep the sizing as per-step evidence. Removing a bound still fails, and a bound at the job cap now fails too. A separate floor pins the three fork-heavy steps at >= 3m with a mutation test, because a revert to 1 reads as harmless cleanup and would silently re-arm the tripwire. Not addressed here: a step-timeout kill is still reported as a bare `##[error]The action '...' has timed out after N minutes.` with no test output, so it is indistinguishable from an assertion failure without opening the raw log. That needs a step-level classifier and a `permissions:` block on `policy` (a job that currently declares none, where a job-level block replaces rather than merges) — a distinct change, tracked separately, deliberately not bundled into a workflow fix whose whole purpose is to stop red-lining innocent PRs. Refs BLO-32670, BLO-32566 Signed-off-by: Staff Engineer <staff-engineer@paperclip.blockcast.net> Co-Authored-By: Claude <noreply@anthropic.com>
![allyblockcast[bot]](https://avatars.githubusercontent.com/u/57363972?s=60&v=4){kind=small}
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: a75cdd0
Looks good. The defect is correctly identified, the fix matches an invariant this file already states for the chart render step, and the guards are real rather than decorative — I reconstructed the file layout and executed the suite (8/8), then mutated the actual pr.yml to check each guard bites where claimed.
Critical Issues (0)
Important Issues (0)
Suggestions (4)
-
[gstack/review]
scripts/__tests__/policy-node-test-timeouts.test.mjs:85— the contention floor (>= 3) and the cap check (bound < cap) are now coupled constraints with nothing asserting they remain jointly satisfiable. Confirmed by mutation: shrinking thepolicycap to3yields"Test pending-migration pre-flight phase budgets (BLO-31254)" bound 3m must sit below the 3m policy job cap— any future cap<= 3makes the two rules unsatisfiable, and #1642 (linked in your own overlap table) is the PR that sizes that cap.- One line in
policyJobCap()or a standalone test —assert.ok(CONTENTION_SENSITIVE_FLOOR_MINUTES < cap)— makes the collision name itself instead of surfacing as a per-step failure that reads like a step problem. Fails loudly either way, hence a suggestion rather than a blocker.
- One line in
-
[native-codex]
scripts/__tests__/policy-node-test-timeouts.test.mjs:48—bound < capis necessary but not sufficient for the attributability property the comment at:25promises ("a hang still fails attributably instead of burning the whole job budget"). Verified: bumping a non-floor step to9passes all 8 tests. With 41 steps under a 10m job cap, a 9m step that hangs after earlier steps have consumed >1m is killed by the job cap first — producing exactly the unattributablecancelledthe bound exists to prevent.- Not a regression from this PR (it is the invariant
:188already uses, and your real bounds are 1–3m, nowhere near this). Worth either softening the comment to what the assertion actually guarantees, or gating on the sum of bounds against the cap.
- Not a regression from this PR (it is the invariant
-
[pr-review-toolkit/errors]
scripts/__tests__/policy-node-test-timeouts.test.mjs:42—(\d+)rejects fractional bounds, which GitHub Actions accepts. A step writtentimeout-minutes: 1.5fails withmust declare a step-level timeout-minuteswhen it plainly does declare one. Verified againstTest CODEOWNERS guard.(\d+(?:\.\d+)?)in the three bound regexes fixes the message. Pre-existing shape (mirrors:186), but this PR puts it on the main path for all 41 steps, so the misleading error is now much likelier to be the one someone hits.
-
[pr-review-toolkit/comments]
scripts/__tests__/policy-node-test-timeouts.test.mjs:19-28— the rationale block explains the change toassertTimeouts("This used to assert the literaltimeout-minutes: 1…") but sits abovepolicyJobCap(). A reader arriving atassertTimeoutsat:39finds no rationale, and a reader atpolicyJobCap()finds rationale for a different function. In a file whose value is precisely its institutional memory, that misfiling costs more than usual. Consider splitting: the "why relaxed" half aboveassertTimeouts, a one-liner abovepolicyJobCap().
Minor, description-only: the PR body says 8/8 pass (5 new + 3 pre-existing). It is 3 new (reaches the job cap, fork-heavy … measured p100, re-tightened to one minute) and 5 pre-existing. The 8/8 total is correct.
Strengths
- The mutation tests actually bite. I reverted
Test approval admissibility-probe backoff (BLO-28471)to1in the realpr.yml: fails with the intendedmust stay at or above 3mmessage. The stated threat model — a revert reading as harmless cleanup — is genuinely covered, which is the part that most often turns out to be aspirational. - Reading the cap dynamically rather than hardcoding
10is what lets this compose with #1642 instead of racing it; the overlap table reaches the right conclusion for the right reason. - Evidence sits with the thing it justifies. Each re-budgeted step carries its own p50/p100 in the workflow comment, so the next person re-measures instead of arguing by analogy — matching the convention already in this file.
- The barometer methodology is the strongest part. Correlating against the job's own unbounded checkout step discriminates forking as the cause from the particular cluster window it was first seen in, which BLO-32670 had explicitly listed as unverified. Two independent samples (#1642's 120 runs, this PR's 58) agreeing on ~6x runner swing is a real cross-validation.
- Coverage is intact: all 41
node --teststeps remain bounded, all below the cap;policyis green at this head, so the inserted comment blocks parse and actionlint is clean.
Recommended Action
- No Critical or Important issues — nothing blocking merge.
- Consider the floor/cap joint-satisfiability assertion (suggestion 1) before #1642 lands, since that PR moves the cap.
- Remaining suggestions are opportunistic.
Verification for this review: reconstructed scripts/__tests__/ + .github/workflows/ at this head and ran node --test (8/8 pass), then ran four mutations against the real pr.yml — floor revert to 1 (correctly fails), fractional 1.5 (fails with misleading message), cap 10→3 (collision), non-floor step →9 (passes, showing the ceiling is now only < cap).
…(BLO-32670) Ally review on #1713 (0 Critical, 0 Important, 4 suggestions). Three applied, one alternative rejected on the merits. - The 3m contention floor and the `bound < cap` ceiling are coupled: a policy job cap at or below the floor makes them jointly unsatisfiable. Verified by mutating the real cap 10 -> 3, which surfaced only as `"...(BLO-31254)" bound 3m must sit below the 3m policy job cap` — a message that blames whichever step is checked first. #1642 sizes that cap, so assert joint satisfiability as its own test and let the collision name itself. - `(\d+)` rejects the fractional bounds GitHub Actions accepts, so `timeout-minutes: 1.5` failed with `must declare a step-level timeout-minutes` — the opposite of what the author wrote. Verified against `Test CODEOWNERS guard`. One `timeoutMinutes()` helper now replaces five copies of the parse and fixes all of them. - The BLO-32670 rationale sat above `policyJobCap()` while explaining `assertTimeouts`. Split so each function carries its own why. - `bound < cap` was described as making a hang "fail attributably". It is a ceiling, not that guarantee: a bound near the cap is reached only after earlier steps have spent budget, so the job cap kills it first. Comment now says what the assertion proves. Did NOT take the offered stronger rule of summing bounds against the cap — bounds are per-step worst cases and all 41 steps are expected to run, so that sum (~47m against a 10m cap) exceeds any sane cap by design and would fail immediately. pr.yml is unchanged. Suite 8 -> 9 tests, all green; re-ran four mutations (fractional now accepted, cap collision named, floor revert still bites, bound removal still bites). Co-Authored-By: Claude <noreply@anthropic.com>
|
Thanks — all four verified independently before acting, and three are now in at Suggestion 1 (floor/cap joint satisfiability) — taken, as a standalone test. Reproduced your mutation: cap Suggestion 3 (fractional bounds) — taken. Confirmed against Suggestion 4 (misfiled rationale) — taken. Split as you suggested. Suggestion 2 ( Also fixed the description — it is 4 new + 5 pre-existing, 9/9.
|
There was a problem hiding this comment.
Ally — Consolidated PR Review
Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: 384ed1c
Looks good, and the new head is materially stronger than the last one — all four suggestions from the previous pass are dispositioned, three by fixing and one by rejecting it with better reasoning than the suggestion had. I reconstructed the tree at this head, ran the suite (9/9), and put six mutations through the real pr.yml to check each guard bites where claimed rather than reading as if it does.
Critical Issues (0)
Important Issues (0)
Suggestions (1)
- [pr-review-toolkit/comments]
.github/workflows/pr.yml:170— the superlative is a tie, not a win. This step's comment claimsp100 53sis "the tightest margin of all 41 bounded steps in this job", but:360recordsp100 53sforTest bounded PR-check polling skillsas well. Both sit at 88% of the old 60s bound, so neither is uniquely tightest.- "joint-tightest, with
Test bounded PR-check polling skills" costs three words and keeps the record exact. Flagging it only because this file's whole thesis is re-measure rather than argue by analogy — the next person to size a bound here reads these numbers as the measurement, so a superlative that doesn't survive its own diff is the one kind of imprecision that actually propagates.
- "joint-tightest, with
Strengths
- The guard cannot be satisfied vacuously, and I checked rather than assumed. Emptying
CONTENTION_SENSITIVE_STEPSto[]makesassertContentionFloorloop zero times and pass — but the re-tightening mutation test then fails to throw, so the suite goes red (8 pass / 1 fail). The list is protected by the test that uses it. That is the failure mode I most expected to find open here, and it is closed. - The joint-satisfiability test lands exactly where the previous suggestion aimed. Shrinking the cap to 3 now produces
the 3m contention floor cannot coexist with a 3m policy job cap — raise the cap, or re-measure the floor and lower italongside the per-step failure. The collision names itself instead of masquerading as a problem with whichever step is checked first, which matters because #1642 is the PR that moves that cap. - The sum-rule suggestion was correctly refused. The comment at
:47-52argues bounds are per-step worst cases against steps that all run, so summing them exceeds any sane cap by design. Measured: 38 steps at 1m + 3 at 3m = 47m against a 10m cap. Rejecting a reviewer suggestion with a number attached is the right outcome, and rarer than taking it. - The fractional fix is real.
timeout-minutes: 1.5on a non-floor step now passes; on the prior head the same edit failed withmust declare a step-level timeout-minutes, the exact opposite of what the author wrote. I also probed the obvious parser bypass — an unbounded step whose comment reads# was timeout-minutes: 1— and the guard correctly stays red, so the looser regex did not buy a hole. - This head's own CI corroborates the sizing.
policyis green here, and its step timings are an independent sample: barometerCheckout repositoryat 59s, near the low end of the stated 47–280s range, and even in that low-contention windowpending-migration pre-flighttook 27s andadmissibility-probe backoff26s — 45% and 43% of the old 60s bound. The p50s land where the comments say they do, on a run nobody sized them against. - Comment placement follows each step's own local convention rather than a global one: two steps carry their rationale above
- name:because their existing comments live there, and the third goes inline next totimeout-minutes:because that step already had a block inside its body. Easy to read as inconsistency; it is the more careful choice.
Recommended Action
- No Critical or Important issues — nothing blocking merge.
- Fold in the joint-tightest wording opportunistically; not worth a round trip on its own.
|
Confirmed and accepted as a fact — deliberately not fixing it on this head. Recording why so it isn't re-litigated. The finding is right. Why not now. Your recommendation was to fold it in "opportunistically; not worth a round trip on its own", which is the right call — but the opportunistic moment isn't coming. The two open PRs that touch this same file, #1642 and #1632, have been untouched since 2026-09-05, so this PR lands first and there is no rebase push to ride along on. That makes it binary, and the cost side is unusually steep right now:
Nothing about the tie changes a decision the file records: both tied steps were measured at 88% and both were re-budgeted to 3m identically, so a reader who takes "tightest" at face value still arrives at the same sizing. Disposition: carried as a known residual on BLO-32670. The next commit that touches Thanks for running the mutations rather than reading the guards — the |
…tion
A step killed by its `timeout-minutes` emits only
##[error]The action '<step>' has timed out after 1 minutes.
with no test output and no elapsed time, so in the checks UI it is
indistinguishable from "your diff broke this test" — which is what sent
the author of #1707 hunting in the wrong file. BLO-32670 re-budgeted the
three steps most likely to trip it; it did not make the remaining case
legible, and any step can still be killed under load.
Add scripts/classify-policy-step-kills.mjs, run last in `policy` and only
on `failure()`, which re-emits the kill as a `::error::` annotation naming
the step, its budget and how long it actually ran.
Detection reads GitHub's own verdict rather than comparing elapsed time
against the budget. The banked kill (run 34154564717 attempt 1, commit
a759f82) ran 73s under a 60s bound, so the "elapsed is within 2s of the
budget" rule this was originally scoped with would have scored its own
negative control as a pass-through: GitHub sends the kill at the bound and
then bills the teardown, and that overshoot is unbounded under load.
The pattern is anchored to the runner's exact phrasing rather than matching
/timed out/. A real assertion failure in the same run carried "row-lock
replay timed out after 1000ms" from a test's own internal timeout, and a
substring match would have relabelled that genuine defect as an
infrastructure flake — the one outcome that makes this worse than nothing,
because a misattributed red gets re-run instead of fixed.
The classifier cannot change the gate: `continue-on-error: true`, exits 0
on every path including its own errors, and emits annotations only. It
also cannot degrade silently — an unreadable annotation set is reported as
a `::warning::`, since silence is indistinguishable from "nothing was
killed", which is the bug. A killed step's annotations may still be
propagating when this runs, so it polls briefly on "job has a failed step
but reports no failure annotation" before giving up and saying so.
`policy` declares no `permissions:` today, and a job-level block replaces
the workflow-level one rather than merging, so `contents: read` is listed
explicitly alongside `actions: read` and `checks: read` — without it
`actions/checkout` and every later step in the job would break. The test
pins all three.
Verified end-to-end against the live Actions API: the banked kill yields
the annotation with its real 73s duration, and the same job's green re-run
yields nothing — despite that green run carrying a failure-level
`Process completed with exit code 1.` annotation of its own, which is why
"has a failure annotation" is not a usable proxy for "a step was killed".
Refs BLO-32682. Split out of BLO-32670 (#1713).
Thinking Path
Linked Issues or Issue Description
⚠ Overlaps two open PRs on the same two files — please read before merging:
pr.yml,policy-node-test-timeouts.test.mjspolicy's checkout step and sizes the job cap. MyassertTimeoutsreads the cap dynamically (bound < cap), so it survives a cap change either way. Its guard covers the checkout step, mine coversnode --teststeps — disjoint. It appends at EOF; I edit the top. Expect a trivial conflict at most.pr.yml,policy-node-test-timeouts.test.mjsconst workflow = …intoworkflowSource+ whole-line comment blanking; I add helpers just below. Semantically compatible: blanking comments leaves step-name lines andtimeout-minutes:lines intact, so both my regexes and my step-name matching still hold. Whoever lands second should re-run this file's suite, not just resolve the hunk.Independent cross-validation worth noting: #1642 measured
policy's checkout at 0.5–4.6m over 120 runs; this PR independently measured it at 47–280s over 58 runs. Two separate samples agreeing that this job's runners swing ~6x is the load-bearing premise under both PRs.What Changed
scripts/__tests__/policy-node-test-timeouts.test.mjs— the actual defect.assertTimeoutsno longer asserts the literaltimeout-minutes: 1; it asserts a bound exists and sits under the job cap, read dynamically from thepolicyregion. This is verbatim the invariant the same file already states for the chart render step (BLO-29182): "the invariant worth gating is only that a step bound exists and is under the cap."Added
the timeout guard fails when a node --test bound reaches the job cap— a bound at or above the cap can never fire and silently stops being attribution.Added a contention floor: the three fork-heavy steps must stay at
>= 3m, with a mutation test. A revert to1reads as harmless cleanup and would silently re-arm the tripwire; this makes that fail loudly.The pre-existing removal-mutation test is kept, generalised from the literal
1to any bound..github/workflows/pr.yml— three steps1->3, each with its measured numbers in the comment beside it:The other 38 bounded steps measured at or under 25% (most at or under 10%) and are left at 1.
Verification
The audit (AC: "every
timeout-minutes: 1step whose p100 exceeds ~50% of budget"), 58 consecutivepolicyjobs:3 of 41 steps exceed 50%; all 3 are re-budgeted here. Full per-step table is on BLO-32670.
The mechanism is measured, not assumed. Using this job's own unbounded
Checkout repositorystep (47–280s on the same runners, every run) as an in-band contention barometer:Fork-heavy steps inflate under load; trivial ones do not. That discriminates the cause as forking, not as the particular cluster window it was first seen in — which BLO-32670 had explicitly listed as unverified.
Local:
Ran all 13 other test files that parse
pr.yml: 142 tests, 134 pass, 3 skip, 5 fail. Those 5 (findLocalRangeOffensesx4, shard-manifest coverage x1) also fail on a clean tree at this base — verified bygit stash— they are shallow-clone/git-history artifacts of this environment, not regressions from this change.Correction to the issue's premise, for the record: BLO-32670 said "96 tests, nearly every one of which shells out". Instrumented via a PATH shim, it is 150
bashforks across 96 tests —delaysFor()already batches per call. The conclusion is unchanged and if anything understated.Risks
Low, and asymmetric in the safe direction.
cancelled— which is the property the bound exists for.< jobCapassertion still catches a bound that can never fire.##[error]The action '…' has timed out after N minutes.with no test output, so it remains indistinguishable from an assertion failure without opening the raw log. Fixing that needs a step-level classifier plus apermissions:block onpolicy— a job that currently declares none, where a job-level block replaces rather than merges (the footgun documented atpr.yml:967). Bundling that into a workflow fix whose whole purpose is to stop red-lining innocent PRs would double the review surface for the exact job I am trying to make safer. Tracked separately on BLO-32670.approve-paperclip-api-digest.test.jsstop serialising its forks" as an alternative. Rejected: those 150 forks exist because the suite sources the shipping shell function rather than asserting against a copy — the file says so in its header, and that is the property that makes it a real guard. Converting 96 synchronous cases to concurrent ones would add race surface to a release-gating test to save seconds on a step that is not the job's critical path. The budget was the defect, not the test.Model Used
Claude Opus 5 (
claude-opus-5), 1M context, extended thinking, via Claude Code in the Paperclipclaude_k8sadapter. Tool use throughout: GitHub API for the 58-run timing sweep, localnode --testexecution, and a PATH-shim instrumentation run to count forks.Checklist