From a75cdd00711e8254fe0c0fbc8ff92342c68c5a01 Mon Sep 17 00:00:00 2001 From: Staff Engineer Date: Mon, 7 Sep 2026 23:14:34 +0000 Subject: [PATCH 1/2] ci(policy): size fork-heavy step timeouts against measured p100 (BLO-32670) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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 Co-Authored-By: Claude --- .github/workflows/pr.yml | 22 ++++- .../policy-node-test-timeouts.test.mjs | 90 ++++++++++++++++++- 2 files changed, 105 insertions(+), 7 deletions(-) diff --git a/.github/workflows/pr.yml b/.github/workflows/pr.yml index 261e9a607952..36e94a0d75cf 100644 --- a/.github/workflows/pr.yml +++ b/.github/workflows/pr.yml @@ -166,10 +166,13 @@ jobs: # 21.8s local to 32-73s on CI. Keep this bound honest by re-measuring # rather than by analogy -- but if you add a test here that waits on a new # budget, it lands on the bound directly, so check the total. + # BLO-32670: 3, not 1. Measured p100 53s across 58 sampled runs (p50 24s) + # — 88% of the old one-minute bound, the tightest margin of all 41 + # bounded steps in this job. It had not tripped yet; it was next. - name: Test pending-migration pre-flight phase budgets (BLO-31254) if: ${{ !cancelled() }} run: node --test ./scripts/check-pending-migration-preflight-phases.test.js - timeout-minutes: 1 + timeout-minutes: 3 # BLO-29008: executes the two-tier convergence gate's shell against # recorded cluster states. The gate fails OPEN if its string accumulation @@ -180,10 +183,20 @@ jobs: run: node --test ./scripts/check-docker-two-tier-convergence.test.js timeout-minutes: 1 + # BLO-32670: 3, not 1. This suite forks 150 short-lived `bash` processes + # across its 96 tests, because it exercises the shipping backoff function + # by sourcing it rather than by asserting against a copy. That makes its + # wall time track runner CPU contention rather than its own work: ~9s on + # an idle host, 44s p100 across 58 sampled runs, and 73s observed on + # 2026-09-07 — which tripped the old one-minute bound and failed `policy` + # on a PR whose diff touched only `server/src/services/recovery/*`. + # Sizing an ~9s task at 60s reads as 7x headroom; against a p100 that is + # already 5x the median it was not. The bound still catches a hang, far + # inside the 10m job cap — it is no longer a duration tripwire. - name: Test approval admissibility-probe backoff (BLO-28471) if: ${{ !cancelled() }} run: node --test ./scripts/approve-paperclip-api-digest.test.js - timeout-minutes: 1 + timeout-minutes: 3 - name: Test pnpm setup retry wrapper (BLO-28813) if: ${{ !cancelled() }} @@ -344,7 +357,10 @@ jobs: # blocks against a stubbed `gh` and asserts the exit codes. if: ${{ !cancelled() }} run: node --test ./scripts/skill-bounded-pr-check-polling.test.mjs - timeout-minutes: 1 + # BLO-32670: 3, not 1. Measured p100 53s across 58 sampled runs against + # a p50 of 7s — a 7.6x spread, the widest in this job, because the + # fenced blocks fork a stubbed `gh` per case. + timeout-minutes: 3 # BLO-31405: the chart render suite deliberately does NOT run here. It has # its own `helm_chart` job below; see the comment there before adding it diff --git a/scripts/__tests__/policy-node-test-timeouts.test.mjs b/scripts/__tests__/policy-node-test-timeouts.test.mjs index 0152f32c28ce..7eab5f7e3c77 100644 --- a/scripts/__tests__/policy-node-test-timeouts.test.mjs +++ b/scripts/__tests__/policy-node-test-timeouts.test.mjs @@ -16,10 +16,38 @@ function nodeTestSteps() { return policySteps().filter((step) => step.includes("node --test")); } -function assertTimeouts(steps) { +// BLO-32670. This used to assert the literal `timeout-minutes: 1` on every +// step, which made the bound a fixed number rather than a sufficient one: a +// step whose measured p100 outgrew 60s could not be right-sized without failing +// this test, so the only in-repo remedy was to leave it as a tripwire. It fired +// exactly that way on 2026-09-07, red-lining a PR that had not touched the +// script under test. The invariant worth gating is the one already written for +// the chart render step below — that a bound EXISTS and sits under the job cap, +// so a hang still fails attributably instead of burning the whole job budget. +// Sizing is per-step evidence, and belongs with the step; see the workflow +// comments and the contention-sensitive floor asserted further down. +function policyJobCap() { + const cap = Number(jobRegion("policy").match(/\n timeout-minutes: (\d+)\n/)?.[1]); + assert.ok(cap > 0, "policy must declare a job-level timeout-minutes"); + return cap; +} + +function stepName(step) { + return step.split("\n")[0].trim(); +} + +function assertTimeouts(steps, cap = policyJobCap()) { assert.ok(steps.length > 0, "policy must contain node --test steps"); for (const step of steps) { - assert.match(step, /\n timeout-minutes: 1\n/, "each policy node --test step must have a one-minute bound"); + const bound = Number(step.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + assert.ok( + bound > 0, + `policy node --test step "${stepName(step)}" must declare a step-level timeout-minutes`, + ); + assert.ok( + bound < cap, + `"${stepName(step)}" bound ${bound}m must sit below the ${cap}m policy job cap`, + ); } } @@ -28,8 +56,62 @@ test("every policy node --test step has a step-level timeout", () => { }); test("the timeout guard fails when a node --test bound is removed", () => { - const mutated = nodeTestSteps().map((step) => step.replace("\n timeout-minutes: 1\n", "\n")); - assert.throws(() => assertTimeouts(mutated), /one-minute bound/); + const mutated = nodeTestSteps().map((step) => step.replace(/\n {8}timeout-minutes: \d+\n/, "\n")); + assert.throws(() => assertTimeouts(mutated), /must declare a step-level timeout-minutes/); +}); + +test("the timeout guard fails when a node --test bound reaches the job cap", () => { + const cap = policyJobCap(); + const mutated = nodeTestSteps().map((step) => + step.replace(/\n {8}timeout-minutes: \d+\n/, `\n timeout-minutes: ${cap}\n`), + ); + assert.throws(() => assertTimeouts(mutated, cap), /must sit below the/); +}); + +// BLO-32670. Three of the 41 bounded steps in `policy` measured a p100 above +// 50% of the old 60s budget over 58 sampled runs; the other 38 were all at or +// under 25%. These three are the fork-heavy ones — they shell out per case, so +// their wall time tracks runner CPU contention rather than their own work, +// which is why they inflate while their neighbours (dominated by deliberate +// sleeps) barely move. Against the in-band contention barometer — this job's +// own unbounded `Checkout repository` step, which ranges 47s to 280s on the +// same runners — they correlate at r ~= 0.35 and run 2.3x slower in the +// high-load tercile, where trivial steps sit at r ~= 0.05 and 1.0x. +// +// Pinned as a floor, not an exact value, so raising one further stays a +// one-line change. What must fail loudly is a revert to 1: that reads as +// harmless cleanup, restores the tripwire, and the next red `policy` again +// lands on whichever PR happens to be in the contention window. +const CONTENTION_SENSITIVE_FLOOR_MINUTES = 3; +const CONTENTION_SENSITIVE_STEPS = [ + "Test approval admissibility-probe backoff (BLO-28471)", + "Test pending-migration pre-flight phase budgets (BLO-31254)", + "Test bounded PR-check polling skills", +]; + +function assertContentionFloor(steps) { + for (const name of CONTENTION_SENSITIVE_STEPS) { + const step = steps.find((candidate) => stepName(candidate) === name); + assert.ok(step, `policy must still contain the contention-sensitive step "${name}"`); + const bound = Number(step.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + assert.ok( + bound >= CONTENTION_SENSITIVE_FLOOR_MINUTES, + `"${name}" is fork-heavy and measured a p100 above 50% of a one-minute budget, so its bound must stay at or above ${CONTENTION_SENSITIVE_FLOOR_MINUTES}m — found ${bound}m`, + ); + } +} + +test("fork-heavy policy steps keep a bound sized against their measured p100", () => { + assertContentionFloor(policySteps()); +}); + +test("the contention floor fails when a fork-heavy step is re-tightened to one minute", () => { + const mutated = policySteps().map((step) => + CONTENTION_SENSITIVE_STEPS.includes(stepName(step)) + ? step.replace(/\n {8}timeout-minutes: \d+\n/, "\n timeout-minutes: 1\n") + : step, + ); + assert.throws(() => assertContentionFloor(mutated), /must stay at or above/); }); test("policy continues after a bounded test failure unless cancelled", () => { From 384ed1ccf3ec7fe7d6ea03fc5cd5d8dace4c98b6 Mon Sep 17 00:00:00 2001 From: Staff Engineer Date: Mon, 7 Sep 2026 23:53:29 +0000 Subject: [PATCH 2/2] test(policy): name the floor/cap collision, accept fractional bounds (BLO-32670) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- .../policy-node-test-timeouts.test.mjs | 77 +++++++++++++------ 1 file changed, 55 insertions(+), 22 deletions(-) diff --git a/scripts/__tests__/policy-node-test-timeouts.test.mjs b/scripts/__tests__/policy-node-test-timeouts.test.mjs index 7eab5f7e3c77..a531ab5cc3d0 100644 --- a/scripts/__tests__/policy-node-test-timeouts.test.mjs +++ b/scripts/__tests__/policy-node-test-timeouts.test.mjs @@ -16,18 +16,20 @@ function nodeTestSteps() { return policySteps().filter((step) => step.includes("node --test")); } -// BLO-32670. This used to assert the literal `timeout-minutes: 1` on every -// step, which made the bound a fixed number rather than a sufficient one: a -// step whose measured p100 outgrew 60s could not be right-sized without failing -// this test, so the only in-repo remedy was to leave it as a tripwire. It fired -// exactly that way on 2026-09-07, red-lining a PR that had not touched the -// script under test. The invariant worth gating is the one already written for -// the chart render step below — that a bound EXISTS and sits under the job cap, -// so a hang still fails attributably instead of burning the whole job budget. -// Sizing is per-step evidence, and belongs with the step; see the workflow -// comments and the contention-sensitive floor asserted further down. +// BLO-32670. GitHub Actions accepts fractional minutes. Matching only `(\d+)` +// makes `timeout-minutes: 1.5` read as declaring no bound at all, so the guard +// rejects such a step with the exact opposite of what its author wrote. Parse +// the fraction and let the numeric comparisons below do the work. +const TIMEOUT_MINUTES = String.raw`timeout-minutes: (\d+(?:\.\d+)?)`; + +function timeoutMinutes(text, indent) { + return Number(text.match(new RegExp(`\\n {${indent}}${TIMEOUT_MINUTES}\\n`))?.[1]); +} + +// Sizing is per-step evidence and belongs with the step; this reads only the +// ceiling that every step bound has to sit under. function policyJobCap() { - const cap = Number(jobRegion("policy").match(/\n timeout-minutes: (\d+)\n/)?.[1]); + const cap = timeoutMinutes(jobRegion("policy"), 4); assert.ok(cap > 0, "policy must declare a job-level timeout-minutes"); return cap; } @@ -36,10 +38,25 @@ function stepName(step) { return step.split("\n")[0].trim(); } +// BLO-32670. This used to assert the literal `timeout-minutes: 1` on every +// step, which made the bound a fixed number rather than a sufficient one: a +// step whose measured p100 outgrew 60s could not be right-sized without failing +// this test, so the only in-repo remedy was to leave it as a tripwire. It fired +// exactly that way on 2026-09-07, red-lining a PR that had not touched the +// script under test. The invariant worth gating is the one already written for +// the chart render step below — that a bound EXISTS and sits under the job cap. +// +// `bound < cap` is a ceiling, not a guarantee of attributability at every value +// under it: a bound close to the cap is still reached only after earlier steps +// have spent part of the job budget, so the job cap kills it first and the +// failure is a bare `cancelled` again. It holds here because the real bounds are +// 1-3m against a 10m cap. Summing the bounds against the cap would be the wrong +// stronger rule — bounds are per-step worst cases and every step is expected to +// run, so that sum exceeds any sane cap by design. function assertTimeouts(steps, cap = policyJobCap()) { assert.ok(steps.length > 0, "policy must contain node --test steps"); for (const step of steps) { - const bound = Number(step.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + const bound = timeoutMinutes(step, 8); assert.ok( bound > 0, `policy node --test step "${stepName(step)}" must declare a step-level timeout-minutes`, @@ -56,14 +73,16 @@ test("every policy node --test step has a step-level timeout", () => { }); test("the timeout guard fails when a node --test bound is removed", () => { - const mutated = nodeTestSteps().map((step) => step.replace(/\n {8}timeout-minutes: \d+\n/, "\n")); + const mutated = nodeTestSteps().map((step) => + step.replace(new RegExp(`\\n {8}${TIMEOUT_MINUTES}\\n`), "\n"), + ); assert.throws(() => assertTimeouts(mutated), /must declare a step-level timeout-minutes/); }); test("the timeout guard fails when a node --test bound reaches the job cap", () => { const cap = policyJobCap(); const mutated = nodeTestSteps().map((step) => - step.replace(/\n {8}timeout-minutes: \d+\n/, `\n timeout-minutes: ${cap}\n`), + step.replace(new RegExp(`\\n {8}${TIMEOUT_MINUTES}\\n`), `\n timeout-minutes: ${cap}\n`), ); assert.throws(() => assertTimeouts(mutated, cap), /must sit below the/); }); @@ -93,7 +112,7 @@ function assertContentionFloor(steps) { for (const name of CONTENTION_SENSITIVE_STEPS) { const step = steps.find((candidate) => stepName(candidate) === name); assert.ok(step, `policy must still contain the contention-sensitive step "${name}"`); - const bound = Number(step.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + const bound = timeoutMinutes(step, 8); assert.ok( bound >= CONTENTION_SENSITIVE_FLOOR_MINUTES, `"${name}" is fork-heavy and measured a p100 above 50% of a one-minute budget, so its bound must stay at or above ${CONTENTION_SENSITIVE_FLOOR_MINUTES}m — found ${bound}m`, @@ -101,6 +120,20 @@ function assertContentionFloor(steps) { } } +// BLO-32670. The floor and the `bound < cap` ceiling are coupled constraints: a +// policy job cap at or below the floor makes them jointly unsatisfiable. Without +// this the collision surfaces as a per-step "must sit below the 3m policy job +// cap" failure, which reads as a problem with whichever step is checked first +// rather than with the pair of rules. #1642 is the PR that sizes that cap, so +// name the collision here instead of letting it land on a step. +test("the contention floor and the policy job cap stay jointly satisfiable", () => { + const cap = policyJobCap(); + assert.ok( + CONTENTION_SENSITIVE_FLOOR_MINUTES < cap, + `the ${CONTENTION_SENSITIVE_FLOOR_MINUTES}m contention floor cannot coexist with a ${cap}m policy job cap — raise the cap, or re-measure the floor and lower it`, + ); +}); + test("fork-heavy policy steps keep a bound sized against their measured p100", () => { assertContentionFloor(policySteps()); }); @@ -108,7 +141,7 @@ test("fork-heavy policy steps keep a bound sized against their measured p100", ( test("the contention floor fails when a fork-heavy step is re-tightened to one minute", () => { const mutated = policySteps().map((step) => CONTENTION_SENSITIVE_STEPS.includes(stepName(step)) - ? step.replace(/\n {8}timeout-minutes: \d+\n/, "\n timeout-minutes: 1\n") + ? step.replace(new RegExp(`\\n {8}${TIMEOUT_MINUTES}\\n`), "\n timeout-minutes: 1\n") : step, ); assert.throws(() => assertContentionFloor(mutated), /must stay at or above/); @@ -170,20 +203,20 @@ test("the chart render suite runs in exactly one job, and that job is helm_chart // BLO-29182 observed this exact invocation hang, and its fix bounded the copy // that used to live in `policy`. Removing that copy has to carry the bound with -// it, or the one `node --test` step known to hang is unbounded again — a hung -// step would burn the whole job budget instead of failing attributably. The -// margin (4 min against a 73s p100) lives in the workflow comment; the -// invariant worth gating is only that a step bound exists and is under the cap. +// it, or the one `node --test` step known to hang is unbounded again, and burns +// the whole job budget instead of failing as itself. The margin (4 min against a +// 73s p100) lives in the workflow comment; the invariant worth gating is only +// that a step bound exists and is under the cap. test("the chart render step is bounded, and inside its job's budget (BLO-29182)", () => { const region = jobRegion("helm_chart"); - const jobCap = Number(region.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + const jobCap = timeoutMinutes(region, 4); assert.ok(jobCap > 0, "helm_chart must declare a job-level timeout-minutes"); const step = region .split("\n - name: ") .slice(1) .find((candidate) => candidate.includes(CHART_SUITE)); assert.ok(step, `helm_chart must contain the ${CHART_SUITE} step`); - const stepBound = Number(step.match(/\n timeout-minutes: (\d+)\n/)?.[1]); + const stepBound = timeoutMinutes(step, 8); assert.ok(stepBound > 0, "the chart render step must declare a step-level timeout-minutes"); assert.ok(stepBound < jobCap, `step bound ${stepBound}m must sit below the ${jobCap}m job cap`); });