From ee6a9e69aa319b869016f6b389664048b54d9a99 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 18:56:09 -0400 Subject: [PATCH 01/13] ci: let the consumer SBOM outlast the registry it waits on Every release-triggered supply-chain run has failed since bestax-migrate 2.3.2, each time on the one matrix leg whose version the release names. The decision logic was right every time: the step resolved `@allxsmith/eslint-plugin-bestax@1.0.1` and `expect=1.0.1` correctly, then `npm install` returned ETARGET three times over half a minute and the leg gave up. Two things were wrong with the retry, and the step's own comment already predicted the failure it could not survive. `--prefer-online`, because npm caches the packument it fetched on the way in. Every attempt could re-read the same pre-publish document out of `~/.npm` and fail identically, which is what the logs show: the same ETARGET at each interval, no new registry read. Sleeping between attempts that all consult one cached document only proves the cache agrees with itself. A deadline instead of a fixed attempt count, because the thing being waited on is not this job. The `release` event fires when the GitHub release is created, and the version becomes installable when the registry finishes serving it. Nothing here can hurry that, so the budget has to be generous rather than clever. The old one spent well under a minute. The legs no release names are unaffected: they resolve `latest`, which always had something to resolve, so they still succeed on the first attempt and never reach the deadline. --- .github/workflows/supply-chain.yml | 28 +++++++++++++++++++++------- 1 file changed, 21 insertions(+), 7 deletions(-) diff --git a/.github/workflows/supply-chain.yml b/.github/workflows/supply-chain.yml index 8d3168fc3..952c3bb17 100644 --- a/.github/workflows/supply-chain.yml +++ b/.github/workflows/supply-chain.yml @@ -393,16 +393,30 @@ jobs: # item 1 would trade "the SBOM names the wrong version" for "the # released package has no SBOM at all", which is a worse deal — the # released leg is the one the release actually cares about. - for attempt in 1 2 3; do - if npm install --ignore-scripts "$SPEC"; then - break - fi - if [ "$attempt" = 3 ]; then - echo "::error::npm install $SPEC failed three times" + # + # `--prefer-online` is what makes a retry mean anything. npm caches + # the packument it fetched on the way in, so without it a retry can + # re-read the same pre-publish document out of `~/.npm` and fail with + # an identical ETARGET; the sleeps then only prove the cache agrees + # with itself. This forces every attempt to revalidate against the + # registry. + # + # A deadline rather than a fixed attempt count, because the thing + # being waited on is not this job. The `release` event fires when the + # GitHub release is created, and the version becomes installable when + # the registry finishes serving it: a different clock, and nothing + # here can hurry it. The budget was well under a minute when every + # release-triggered run began failing at this step. + deadline=$(( SECONDS + 600 )) + attempt=0 + until npm install --prefer-online --ignore-scripts "$SPEC"; do + attempt=$(( attempt + 1 )) + if [ "$SECONDS" -ge "$deadline" ]; then + echo "::error::npm install $SPEC did not succeed within the propagation budget. If that version never published, the release step earlier in the pipeline is where to look; if it did publish, the registry took longer to serve it than this budget allows." exit 1 fi echo "npm install $SPEC failed (attempt $attempt); retrying" - sleep $((attempt * 10)) + sleep 20 done # A scan directory holding ONLY the lockfile (#530 item 5). syft used From 7d60f849d7729985fbe4a70cc602f7ec4e878b9e Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 20:49:55 -0400 Subject: [PATCH 02/13] ci: point the retry comment at the investigation behind it The sentence explaining why the budget grew carried its reason but not its evidence. Every other comment in this step hands a reader an issue number for the history (#412, #526, #530); this one paraphrased a run list instead. The claim itself stays. It is past tense and stays true: the budget was well under a minute, and the release-triggered runs did begin failing here. What it was missing is the hop. --- .github/workflows/supply-chain.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/supply-chain.yml b/.github/workflows/supply-chain.yml index 952c3bb17..43f309eb7 100644 --- a/.github/workflows/supply-chain.yml +++ b/.github/workflows/supply-chain.yml @@ -406,7 +406,7 @@ jobs: # GitHub release is created, and the version becomes installable when # the registry finishes serving it: a different clock, and nothing # here can hurry it. The budget was well under a minute when every - # release-triggered run began failing at this step. + # release-triggered run began failing at this step (#716). deadline=$(( SECONDS + 600 )) attempt=0 until npm install --prefer-online --ignore-scripts "$SPEC"; do From 6fa599f58b1176a63e861172cd701afe1dadc55b Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 21:17:10 -0400 Subject: [PATCH 03/13] ci: move the retry policy where a test can reach it Rule 9 of .github/CLAUDE.md puts logic worth testing outside YAML, and this logic earned it the hard way: the shell loop was wrong in two ways at once and stayed wrong on every release-triggered run for over a week, because nothing existed that could fail when it was wrong. That is not incidental to this job. consumer-sbom runs on release, schedule and workflow_dispatch, so no PR event reaches it, and the pinned-install path fires only on a real release. A test sibling is not one more check here, it is the only check. scripts/npm-install-retry.mjs holds the policy with every outside dependency injected, so the budget, the stopping condition and the log can be driven without a registry, a subprocess or a real wait. The assertions are about what the policy spends and when it stops rather than wall-clock time, and one of them fails for any policy that counts attempts instead of reading a clock, which is the regression that started this. Writing them found a real wart: a budget shorter than one interval slept a full interval anyway, to make an attempt whose result the loop had already decided to discard. So a leg that waiting could never fix reported its failure an interval later than it knew it. The stopping condition now refuses a wait that would land past the deadline. Two things the extraction buys beyond testability. The spec reaches npm as an argument array rather than a shell word, so nothing gives it a second reading. And the exhaustion message runs through forLog, which is what that helper's own header asks for: the message is printed as an ::error:: workflow command, a workflow command ends at a newline, and the spec arrives from argv. --- .github/workflows/supply-chain.yml | 35 ++-- scripts/npm-install-retry.mjs | 188 ++++++++++++++++++++++ scripts/npm-install-retry.test.mjs | 246 +++++++++++++++++++++++++++++ 3 files changed, 445 insertions(+), 24 deletions(-) create mode 100644 scripts/npm-install-retry.mjs create mode 100644 scripts/npm-install-retry.test.mjs diff --git a/.github/workflows/supply-chain.yml b/.github/workflows/supply-chain.yml index 43f309eb7..640b0fdb8 100644 --- a/.github/workflows/supply-chain.yml +++ b/.github/workflows/supply-chain.yml @@ -394,30 +394,17 @@ jobs: # released package has no SBOM at all", which is a worse deal — the # released leg is the one the release actually cares about. # - # `--prefer-online` is what makes a retry mean anything. npm caches - # the packument it fetched on the way in, so without it a retry can - # re-read the same pre-publish document out of `~/.npm` and fail with - # an identical ETARGET; the sleeps then only prove the cache agrees - # with itself. This forces every attempt to revalidate against the - # registry. - # - # A deadline rather than a fixed attempt count, because the thing - # being waited on is not this job. The `release` event fires when the - # GitHub release is created, and the version becomes installable when - # the registry finishes serving it: a different clock, and nothing - # here can hurry it. The budget was well under a minute when every - # release-triggered run began failing at this step (#716). - deadline=$(( SECONDS + 600 )) - attempt=0 - until npm install --prefer-online --ignore-scripts "$SPEC"; do - attempt=$(( attempt + 1 )) - if [ "$SECONDS" -ge "$deadline" ]; then - echo "::error::npm install $SPEC did not succeed within the propagation budget. If that version never published, the release step earlier in the pipeline is where to look; if it did publish, the registry took longer to serve it than this budget allows." - exit 1 - fi - echo "npm install $SPEC failed (attempt $attempt); retrying" - sleep 20 - done + # The policy itself is in scripts/npm-install-retry.mjs with a + # node --test sibling, per rule 9: no PR event reaches this job and + # the pinned path fires only on a real release, so those tests are + # the only thing that can fail when the policy is wrong. The shell + # loop they replace was wrong in two ways at once — retrying without + # `--prefer-online`, so npm could answer from the packument it had + # just cached, and spending a fixed attempt count rather than a + # duration — on every release-triggered run for over a week, with + # nothing able to catch it (#716). + node "$GITHUB_WORKSPACE/scripts/npm-install-retry.mjs" \ + --spec "$SPEC" --dir "$RUNNER_TEMP/consumer" # A scan directory holding ONLY the lockfile (#530 item 5). syft used # to be pointed at the consumer tree and recursively walked every file diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs new file mode 100644 index 000000000..235bef0f0 --- /dev/null +++ b/scripts/npm-install-retry.mjs @@ -0,0 +1,188 @@ +/** + * Install one published spec, outlasting the registry that has to serve it. + * + * `consumer-sbom` pins the released leg to an exact version, and an exact + * version is the one thing `latest` never was: unresolvable for a while after + * `npm publish` returns. The `release` event fires when the GitHub release is + * created, the version becomes installable when the registry finishes + * propagating it, and nothing in CI can hurry the second clock. + * + * This lived as a shell loop in supply-chain.yml and was wrong in two ways at + * once, on every release-triggered run for over a week, with nothing able to + * catch it (#716): + * + * - it retried without `--prefer-online`, so npm answered attempts two and + * three from the `~/.npm` packument attempt one had just cached. The + * sleeps proved the cache agreed with itself and nothing more. + * - it spent a fixed attempt count rather than a duration, and the count + * bought well under a minute. + * + * It is here rather than in the workflow because rule 9 of .github/CLAUDE.md + * puts logic worth testing outside YAML, and this logic is worth testing for a + * specific reason: `consumer-sbom` runs on `release`, `schedule` and + * `workflow_dispatch`, so no PR event reaches it, and the released-leg path + * fires ONLY on a real release. The test sibling is the only thing that can + * fail when this policy is wrong. The version it replaces had no such thing, + * which is exactly how it stayed broken. + * + * What this deliberately does NOT do is treat a version that will never exist + * differently from one that has not propagated yet. Both return the same + * `ETARGET / No matching version found`: the packument resolves and the + * version is absent, with nothing to say whether it is absent forever. Since + * the error cannot distinguish them, waiting is the only correct response, and + * the message on exhaustion names the release step as the place to look. + */ +import { spawnSync } from 'node:child_process'; +import { pathToFileURL } from 'node:url'; +import { forLog } from './consumer-sbom-meta.mjs'; + +// Ten minutes because the budget has to cover a clock nobody here controls, +// and no run has ever measured how long that clock actually takes: every one +// of them gave up long before propagation finished. Generous rather than +// clever, and cheap — this fires per release event, not per PR. +export const DEFAULT_BUDGET_SECONDS = 600; +export const DEFAULT_SLEEP_SECONDS = 20; + +/** + * Retry `run` until it succeeds or the budget is spent. + * + * Every dependency that touches the outside world is injected so the policy + * can be driven without a registry, a subprocess, or a real wait: `run` + * reports success, `now` is the clock, `sleep` is the delay. + * + * The deadline is read only BETWEEN attempts, so an install that hangs rather + * than failing is bounded by the job timeout instead of this budget. That was + * true of the shell loop too, and it is not something a retry policy can fix. + */ +export async function installWithRetry({ + spec, + budgetSeconds = DEFAULT_BUDGET_SECONDS, + sleepSeconds = DEFAULT_SLEEP_SECONDS, + run, + now = () => Date.now(), + sleep, + log = console.log, +} = {}) { + const deadline = now() + budgetSeconds * 1000; + let attempt = 0; + for (;;) { + attempt += 1; + if (await run(spec)) return { ok: true, attempts: attempt }; + // Checked after the attempt rather than before it, so the budget always + // buys at least one try however small it is set. + // + // The second half stops a wait that would land past the deadline. Without + // it a budget shorter than one interval still sleeps a full one, to make + // an attempt whose result the loop has already decided to discard — so a + // leg that cannot be fixed by waiting reports its failure an interval + // later than it knew it. + const wait = sleepSeconds * 1000; + if (now() >= deadline || now() + wait > deadline) { + return { ok: false, attempts: attempt }; + } + log(`npm install ${spec} failed (attempt ${attempt}); retrying`); + await sleep(wait); + } +} + +/** + * One real `npm install`, inheriting stdio so the runner log keeps npm's own + * diagnosis of each failure. + * + * An argument array, never a shell string: the spec reaches this from argv, + * and a shell would give anything in it a second reading. + */ +export function runNpmInstall(spec, cwd) { + const result = spawnSync( + 'npm', + ['install', '--prefer-online', '--ignore-scripts', spec], + { cwd, stdio: 'inherit' } + ); + return result.status === 0; +} + +export function parseArgs(argv) { + const flags = {}; + for (let i = 0; i < argv.length; i += 2) { + const key = argv[i]; + if (!key.startsWith('--')) + throw new Error(`unexpected argument ${forLog(key)}`); + if (i + 1 >= argv.length) throw new Error(`${key} needs a value`); + flags[key.slice(2)] = argv[i + 1]; + } + // Unknown flags are rejected rather than ignored, for the reason the sibling + // script gives: every optional flag here weakens the policy by being absent, + // so a typo would silently restore the behaviour this replaced. + const known = ['spec', 'dir', 'budget-seconds', 'sleep-seconds']; + for (const name of Object.keys(flags)) { + if (!known.includes(name)) { + throw new Error(`unknown flag --${name}`); + } + } + for (const name of ['spec', 'dir']) { + if (!flags[name]) throw new Error(`--${name} is required`); + } + return flags; +} + +/** + * Read a positive integer flag, rejecting anything else. + * + * A non-numeric budget silently becoming the default is the same class of + * quiet downgrade as an ignored flag, so it is an error instead. + */ +export function positiveInteger(value, name, fallback) { + if (value === undefined) return fallback; + if (!/^[0-9]+$/.test(String(value)) || Number(value) === 0) { + throw new Error( + `--${name} must be a positive integer, got ${forLog(value)}` + ); + } + return Number(value); +} + +export async function main(argv = process.argv.slice(2)) { + let flags; + let budgetSeconds; + let sleepSeconds; + try { + flags = parseArgs(argv); + budgetSeconds = positiveInteger( + flags['budget-seconds'], + 'budget-seconds', + DEFAULT_BUDGET_SECONDS + ); + sleepSeconds = positiveInteger( + flags['sleep-seconds'], + 'sleep-seconds', + DEFAULT_SLEEP_SECONDS + ); + } catch (error) { + console.log(`::error::${error.message}`); + return 2; + } + + const { ok, attempts } = await installWithRetry({ + spec: flags.spec, + budgetSeconds, + sleepSeconds, + run: spec => runNpmInstall(spec, flags.dir), + sleep: ms => new Promise(resolve => setTimeout(resolve, ms)), + }); + + if (!ok) { + console.log( + `::error::npm install ${forLog(flags.spec)} did not succeed within the ` + + `propagation budget (${budgetSeconds}s, ${attempts} attempts). If that ` + + `version never published, the release step earlier in the pipeline is ` + + `where to look; if it did publish, the registry took longer to serve ` + + `it than this budget allows.` + ); + return 1; + } + return 0; +} + +if (import.meta.url === pathToFileURL(process.argv[1] ?? '').href) { + process.exitCode = await main(); +} diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs new file mode 100644 index 000000000..0de87d52f --- /dev/null +++ b/scripts/npm-install-retry.test.mjs @@ -0,0 +1,246 @@ +/** + * Guards on the retry policy in npm-install-retry.mjs. + * + * These carry the same unusual weight as the consumer-sbom-meta tests, and for + * the same reason: `consumer-sbom` runs on `release`, `schedule` and + * `workflow_dispatch`, so no PR exercises it, and the pinned-install path + * fires ONLY on a real release event. There is no run to read. This file is + * the coverage. + * + * The shape being pinned is the one that was wrong in the shell loop this + * replaced (#716): it spent a fixed attempt count rather than a duration, and + * it retried in a way that could never see a new answer. A count is the thing + * a test can catch and a duration is not, so the assertions here are about + * what the policy spends and when it stops, never about wall-clock time. The + * clock is injected for exactly that reason. + * + * `--prefer-online` is asserted on the real argv rather than the policy, + * because it is the half of the fix a driven test cannot observe: a stub `run` + * succeeds or fails on command and never consults a cache. + * + * `.mjs` and `node --test` rather than jest: root-level scripts with no + * package of their own, matching consumer-sbom-meta.test.mjs. + */ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { + installWithRetry, + parseArgs, + positiveInteger, + main, + DEFAULT_BUDGET_SECONDS, + DEFAULT_SLEEP_SECONDS, +} from './npm-install-retry.mjs'; +import fs from 'node:fs'; +import path from 'node:path'; +import os from 'node:os'; + +// A clock that only moves when the policy sleeps, so a ten-minute budget costs +// a test nothing and the assertions stay about spend rather than timing. +function harness({ succeedOnAttempt = Infinity, budgetSeconds, sleepSeconds }) { + const state = { t: 0, attempts: 0, sleeps: [], logs: [] }; + return { + state, + promise: installWithRetry({ + spec: 'pkg@1.0.0', + budgetSeconds, + sleepSeconds, + run: () => { + state.attempts += 1; + return state.attempts >= succeedOnAttempt; + }, + now: () => state.t, + sleep: ms => { + state.sleeps.push(ms); + state.t += ms; + return Promise.resolve(); + }, + log: line => state.logs.push(line), + }), + }; +} + +test('a spec that resolves first time costs one attempt and no sleep', async () => { + const h = harness({ + succeedOnAttempt: 1, + budgetSeconds: 600, + sleepSeconds: 20, + }); + assert.deepEqual(await h.promise, { ok: true, attempts: 1 }); + assert.equal(h.state.sleeps.length, 0); + assert.equal(h.state.logs.length, 0); +}); + +test('a spec that propagates mid-wait is installed, not abandoned', async () => { + // The whole point of the change: the old loop died here. + const h = harness({ + succeedOnAttempt: 5, + budgetSeconds: 600, + sleepSeconds: 20, + }); + assert.deepEqual(await h.promise, { ok: true, attempts: 5 }); + assert.equal(h.state.sleeps.length, 4); +}); + +test('the budget is spent in full before giving up', async () => { + const h = harness({ budgetSeconds: 600, sleepSeconds: 20 }); + const result = await h.promise; + assert.equal(result.ok, false); + // Bounded by the budget and the sleep, and it is the DURATION that decides: + // a policy that stopped at a fixed count would fail this whichever count it + // picked, which is the regression this file exists to catch. + assert.equal(h.state.t >= 600 * 1000, true); + assert.equal(result.attempts, 31); +}); + +test('a smaller sleep spends the same budget on more attempts', async () => { + // Pins that the stopping condition reads the clock and not the tally. + const slow = await harness({ budgetSeconds: 600, sleepSeconds: 20 }).promise; + const fast = await harness({ budgetSeconds: 600, sleepSeconds: 5 }).promise; + assert.equal(fast.attempts > slow.attempts, true); +}); + +test('a budget smaller than one interval still buys an attempt, and no wait', async () => { + // Two guarantees in one case. The deadline is read after the attempt, so no + // budget can produce zero tries and report "did not succeed" having never + // asked. And the wait is skipped when it would land past the deadline, + // rather than spending a full interval on an attempt the loop has already + // decided to discard. + const h = harness({ budgetSeconds: 1, sleepSeconds: 20 }); + assert.deepEqual(await h.promise, { ok: false, attempts: 1 }); + assert.equal(h.state.sleeps.length, 0); +}); + +test('the last wait never lands past the deadline', async () => { + const h = harness({ budgetSeconds: 600, sleepSeconds: 20 }); + await h.promise; + const spent = h.state.sleeps.reduce((a, b) => a + b, 0); + assert.equal(spent <= 600 * 1000, true, 'slept past the budget'); +}); + +test('a failed attempt names itself in the log, in order', async () => { + const h = harness({ + succeedOnAttempt: 3, + budgetSeconds: 600, + sleepSeconds: 20, + }); + await h.promise; + assert.deepEqual(h.state.logs, [ + 'npm install pkg@1.0.0 failed (attempt 1); retrying', + 'npm install pkg@1.0.0 failed (attempt 2); retrying', + ]); +}); + +test('the defaults are the ones the workflow relies on', () => { + // The workflow passes no budget, so a change to either of these changes + // production behaviour with no diff in supply-chain.yml to notice it. + assert.equal(DEFAULT_BUDGET_SECONDS, 600); + assert.equal(DEFAULT_SLEEP_SECONDS, 20); +}); + +test('parseArgs requires the two flags that have no safe default', () => { + assert.throws(() => parseArgs(['--dir', '/tmp']), /--spec is required/); + assert.throws(() => parseArgs(['--spec', 'pkg@1.0.0']), /--dir is required/); +}); + +test('parseArgs rejects an unknown flag rather than ignoring it', () => { + // A typo that silently restored the old behaviour is the failure mode. + assert.throws( + () => + parseArgs(['--spec', 'p@1.0.0', '--dir', '/tmp', '--budget-second', '5']), + /unknown flag --budget-second/ + ); +}); + +test('parseArgs rejects a flag with no value', () => { + assert.throws( + () => parseArgs(['--spec', 'p@1.0.0', '--dir']), + /--dir needs a value/ + ); +}); + +test('a non-numeric budget is an error, not a silent default', () => { + assert.equal(positiveInteger(undefined, 'budget-seconds', 600), 600); + assert.equal(positiveInteger('30', 'budget-seconds', 600), 30); + assert.throws( + () => positiveInteger('soon', 'budget-seconds', 600), + /positive integer/ + ); + assert.throws( + () => positiveInteger('0', 'budget-seconds', 600), + /positive integer/ + ); + assert.throws( + () => positiveInteger('-5', 'budget-seconds', 600), + /positive integer/ + ); +}); + +test('a usage error exits 2, distinct from an exhausted budget', async () => { + // 1 means "the registry never served it" and 2 means "this was called + // wrong". A caller that cannot tell those apart cannot act on either. + assert.equal(await main(['--spec', 'pkg@1.0.0']), 2); + assert.equal( + await main(['--nonsense', 'x', '--spec', 'p@1.0.0', '--dir', '/tmp']), + 2 + ); +}); + +test('an exhausted budget exits 1 and says where to look', async () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'npm-retry-')); + const lines = []; + const realLog = console.log; + console.log = line => lines.push(String(line)); + try { + // A spec no registry can serve, and a budget small enough that the real + // npm is asked exactly once. + const code = await main([ + '--spec', + '@allxsmith/this-package-does-not-exist@0.0.0-nope', + '--dir', + dir, + '--budget-seconds', + '1', + ]); + assert.equal(code, 1); + } finally { + console.log = realLog; + fs.rmSync(dir, { recursive: true, force: true }); + } + const error = lines.find(l => l.startsWith('::error::')); + assert.ok(error, 'an exhausted budget must annotate the run'); + assert.match(error, /did not succeed within the propagation budget/); + assert.match(error, /the release step earlier in the pipeline/); +}); + +test('the spec is neutralised before it reaches a workflow command', async () => { + // forLog, for the reason its own header gives: the failure message is + // printed as `::error::…`, a workflow command is newline-terminated, and + // the spec arrives from argv. A raw interpolation would let a crafted spec + // forge a second command out of the complaint about it. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'npm-retry-')); + const lines = []; + const realLog = console.log; + console.log = line => lines.push(String(line)); + try { + await main([ + '--spec', + 'pkg@1.0.0\n::error::forged', + '--dir', + dir, + '--budget-seconds', + '1', + ]); + } finally { + console.log = realLog; + fs.rmSync(dir, { recursive: true, force: true }); + } + const error = lines.find(l => l.startsWith('::error::npm install')); + assert.ok(error, 'the exhaustion message must still be emitted'); + assert.equal( + error.includes('\n'), + false, + 'the annotation must stay one line, or the spec can forge a command' + ); + assert.match(error, /\\n::error::forged/); +}); From fc38a680e78830786a4363523b2c47b862096b0b Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 21:40:37 -0400 Subject: [PATCH 04/13] test: cover the flag whose absence caused the outage The test header claimed `--prefer-online` was asserted on the real argv. It was not. runNpmInstall was exported and no test called it, so deleting the flag left every case green and reinstated the original bug under a larger budget than it had before. Claiming coverage that does not exist is worse than the gap, because it stops anyone looking for it. The argv is now read off an injected spawn and compared whole, and the flag list is exported data so removing it fails even if the call site is rewritten. Verified by building that mutant: it fails one named case and nothing else. Three more, all found by the same review reading the file rather than the diff. The retry line interpolated the spec raw while the exhaustion message two functions away routed it through forLog. The retry line is the one printed on every attempt, so it was the likelier carrier of a crafted spec into a workflow command, not the safer one. Both go through forLog, and the assertion now walks every emitted line for a raw newline instead of checking one message. A spawn that never started was reported as a failed attempt, so a missing npm would spend the whole budget and then blame propagation for a missing binary. It throws now, and main exits 2 rather than 1: the codes mean different things and a caller acts on them differently. A process that ran and was killed by a signal stays retryable, which is transient in the way this loop exists to absorb. Two cases drove main by shelling out to the real registry, which put the network inside `pnpm test` and handed a crafted spec to whatever npm decided to invoke for it. main takes its runner, clock, sleep and log as injectable dependencies now, and nothing in the suite spawns anything. That last one had a sting worth recording: an instant sleep with a real clock does not skip the wait, it busy-loops until the budget elapses for real. One case was spending the better part of a minute to assert something instant. With the clock injected the file runs in a tenth of a second. --- scripts/npm-install-retry.mjs | 87 +++++++++++--- scripts/npm-install-retry.test.mjs | 176 ++++++++++++++++++++--------- 2 files changed, 194 insertions(+), 69 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index 235bef0f0..16093d1aa 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -43,6 +43,17 @@ import { forLog } from './consumer-sbom-meta.mjs'; export const DEFAULT_BUDGET_SECONDS = 600; export const DEFAULT_SLEEP_SECONDS = 20; +/** + * The arguments every attempt carries, as data so a test can assert them. + * + * `--prefer-online` is load-bearing and its absence is invisible: drop it and + * the retries still run, still log, still respect the budget, and still cannot + * see a new answer, which is half of what kept #716 broken for a week. A + * driven test cannot catch that — a stub runner never consults a cache — so + * the list is pinned here instead of spelled inline at the call. + */ +export const INSTALL_ARGS = ['install', '--prefer-online', '--ignore-scripts']; + /** * Retry `run` until it succeeds or the budget is spent. * @@ -80,7 +91,10 @@ export async function installWithRetry({ if (now() >= deadline || now() + wait > deadline) { return { ok: false, attempts: attempt }; } - log(`npm install ${spec} failed (attempt ${attempt}); retrying`); + // forLog here as well as on the exhaustion message. This line prints on + // every attempt rather than once, so it is the likelier of the two to + // carry a crafted spec into a workflow command, not the safer one. + log(`npm install ${forLog(spec)} failed (attempt ${attempt}); retrying`); await sleep(wait); } } @@ -91,13 +105,25 @@ export async function installWithRetry({ * * An argument array, never a shell string: the spec reaches this from argv, * and a shell would give anything in it a second reading. + * + * `spawn` is injected so a test can read the argv this builds. That is the + * only way to catch a dropped `--prefer-online`, since the flag's effect is a + * cache decision inside npm rather than anything the caller observes. + * + * A spawn that never started is thrown rather than returned as a failed + * attempt. No amount of waiting installs anything when `npm` is not on PATH, + * so retrying it would spend the whole budget and then blame propagation for + * a missing binary. A process that started and was killed by a signal stays + * retryable: that is transient in the way this loop exists to absorb. */ -export function runNpmInstall(spec, cwd) { - const result = spawnSync( - 'npm', - ['install', '--prefer-online', '--ignore-scripts', spec], - { cwd, stdio: 'inherit' } - ); +export function runNpmInstall(spec, cwd, spawn = spawnSync) { + const result = spawn('npm', [...INSTALL_ARGS, spec], { + cwd, + stdio: 'inherit', + }); + if (result.error) { + throw new Error(`could not run npm: ${result.error.message}`); + } return result.status === 0; } @@ -141,7 +167,24 @@ export function positiveInteger(value, name, fallback) { return Number(value); } -export async function main(argv = process.argv.slice(2)) { +/** + * Exit codes are read by the workflow step, so they stay distinct: 0 installed, + * 1 the registry never served the spec, 2 this was called wrong or could not + * run npm at all. A caller that cannot tell those apart cannot act on any of + * them. + * + * `deps` exists for the tests. Without it the only way to drive `main` is to + * let it shell out to the real registry, which puts the network inside + * `pnpm test` and hands a crafted spec to whatever npm decides to invoke for + * it. + */ +export async function main(argv = process.argv.slice(2), deps = {}) { + const { + run, + now, + sleep = ms => new Promise(resolve => setTimeout(resolve, ms)), + log = console.log, + } = deps; let flags; let budgetSeconds; let sleepSeconds; @@ -158,20 +201,30 @@ export async function main(argv = process.argv.slice(2)) { DEFAULT_SLEEP_SECONDS ); } catch (error) { - console.log(`::error::${error.message}`); + log(`::error::${error.message}`); return 2; } - const { ok, attempts } = await installWithRetry({ - spec: flags.spec, - budgetSeconds, - sleepSeconds, - run: spec => runNpmInstall(spec, flags.dir), - sleep: ms => new Promise(resolve => setTimeout(resolve, ms)), - }); + let ok; + let attempts; + try { + ({ ok, attempts } = await installWithRetry({ + spec: flags.spec, + budgetSeconds, + sleepSeconds, + run: run ?? (spec => runNpmInstall(spec, flags.dir)), + now, + sleep, + log, + })); + } catch (error) { + // Only runNpmInstall throws, and only when the process never started. + log(`::error::${error.message}`); + return 2; + } if (!ok) { - console.log( + log( `::error::npm install ${forLog(flags.spec)} did not succeed within the ` + `propagation budget (${budgetSeconds}s, ${attempts} attempts). If that ` + `version never published, the release step earlier in the pipeline is ` + diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index 0de87d52f..0316a2c60 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -16,7 +16,13 @@ * * `--prefer-online` is asserted on the real argv rather than the policy, * because it is the half of the fix a driven test cannot observe: a stub `run` - * succeeds or fails on command and never consults a cache. + * succeeds or fails on command and never consults a cache. Deleting the flag + * has to fail something here, or the outage it caused could return under a + * larger budget and every case would stay green. + * + * Nothing here reaches the network or spawns anything. Both the runner and the + * clock are injected, so a ten-minute budget costs no time and a crafted spec + * is never handed to a real subprocess that might give it a second reading. * * `.mjs` and `node --test` rather than jest: root-level scripts with no * package of their own, matching consumer-sbom-meta.test.mjs. @@ -25,15 +31,14 @@ import { test } from 'node:test'; import assert from 'node:assert/strict'; import { installWithRetry, + runNpmInstall, parseArgs, positiveInteger, main, + INSTALL_ARGS, DEFAULT_BUDGET_SECONDS, DEFAULT_SLEEP_SECONDS, } from './npm-install-retry.mjs'; -import fs from 'node:fs'; -import path from 'node:path'; -import os from 'node:os'; // A clock that only moves when the policy sleeps, so a ten-minute budget costs // a test nothing and the assertions stay about spend rather than timing. @@ -125,9 +130,12 @@ test('a failed attempt names itself in the log, in order', async () => { sleepSeconds: 20, }); await h.promise; + // Quoted, because the spec goes through forLog on the way out. The quotes + // are the visible edge of that: an unquoted spec here means the neutralising + // was removed. assert.deepEqual(h.state.logs, [ - 'npm install pkg@1.0.0 failed (attempt 1); retrying', - 'npm install pkg@1.0.0 failed (attempt 2); retrying', + 'npm install "pkg@1.0.0" failed (attempt 1); retrying', + 'npm install "pkg@1.0.0" failed (attempt 2); retrying', ]); }); @@ -187,60 +195,124 @@ test('a usage error exits 2, distinct from an exhausted budget', async () => { }); test('an exhausted budget exits 1 and says where to look', async () => { - const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'npm-retry-')); const lines = []; - const realLog = console.log; - console.log = line => lines.push(String(line)); - try { - // A spec no registry can serve, and a budget small enough that the real - // npm is asked exactly once. - const code = await main([ - '--spec', - '@allxsmith/this-package-does-not-exist@0.0.0-nope', - '--dir', - dir, - '--budget-seconds', - '1', - ]); - assert.equal(code, 1); - } finally { - console.log = realLog; - fs.rmSync(dir, { recursive: true, force: true }); - } + const code = await main( + ['--spec', 'pkg@1.0.0', '--dir', '/tmp', '--budget-seconds', '1'], + { + run: () => false, + sleep: () => Promise.resolve(), + log: l => lines.push(l), + } + ); + assert.equal(code, 1); const error = lines.find(l => l.startsWith('::error::')); assert.ok(error, 'an exhausted budget must annotate the run'); assert.match(error, /did not succeed within the propagation budget/); assert.match(error, /the release step earlier in the pipeline/); }); -test('the spec is neutralised before it reaches a workflow command', async () => { - // forLog, for the reason its own header gives: the failure message is - // printed as `::error::…`, a workflow command is newline-terminated, and - // the spec arrives from argv. A raw interpolation would let a crafted spec - // forge a second command out of the complaint about it. - const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'npm-retry-')); +test('every attempt carries --prefer-online, and the spec comes last', () => { + // Row 1 of the third review: the flag whose absence caused the outage was + // the one thing no test read. It cannot be observed through the policy, + // because a stub runner never consults a cache, so it is read off the argv + // the real runner builds. + const calls = []; + const spawn = (cmd, args, opts) => { + calls.push({ cmd, args, opts }); + return { status: 0 }; + }; + assert.equal(runNpmInstall('pkg@1.0.0', '/somewhere', spawn), true); + assert.deepEqual(calls, [ + { + cmd: 'npm', + args: ['install', '--prefer-online', '--ignore-scripts', 'pkg@1.0.0'], + opts: { cwd: '/somewhere', stdio: 'inherit' }, + }, + ]); + // Pinned as data too, so dropping it from the constant fails here even if + // the call site is rewritten. + assert.equal(INSTALL_ARGS.includes('--prefer-online'), true); + assert.equal(INSTALL_ARGS.includes('--ignore-scripts'), true); +}); + +test('a non-zero npm exit is a failed attempt, not a crash', () => { + const spawn = () => ({ status: 1 }); + assert.equal(runNpmInstall('pkg@1.0.0', '/tmp', spawn), false); +}); + +test('a signal-killed npm stays retryable', () => { + // status null with no spawn error: the process ran and was killed. That is + // the transient case this loop exists to absorb, so it must not be fatal. + const spawn = () => ({ status: null, signal: 'SIGKILL' }); + assert.equal(runNpmInstall('pkg@1.0.0', '/tmp', spawn), false); +}); + +test('an npm that never started is fatal, not retried for ten minutes', async () => { + // Retrying a missing binary spends the whole budget and then blames + // propagation for something propagation cannot explain. + const spawn = () => ({ error: new Error('spawn npm ENOENT') }); + assert.throws( + () => runNpmInstall('pkg@1.0.0', '/tmp', spawn), + /could not run npm/ + ); + const lines = []; - const realLog = console.log; - console.log = line => lines.push(String(line)); - try { - await main([ - '--spec', - 'pkg@1.0.0\n::error::forged', - '--dir', - dir, - '--budget-seconds', - '1', - ]); - } finally { - console.log = realLog; - fs.rmSync(dir, { recursive: true, force: true }); - } - const error = lines.find(l => l.startsWith('::error::npm install')); - assert.ok(error, 'the exhaustion message must still be emitted'); + const code = await main(['--spec', 'pkg@1.0.0', '--dir', '/tmp'], { + run: () => { + throw new Error('could not run npm: spawn npm ENOENT'); + }, + sleep: () => Promise.resolve(), + log: l => lines.push(l), + }); assert.equal( - error.includes('\n'), - false, - 'the annotation must stay one line, or the spec can forge a command' + code, + 2, + 'a missing npm is an environment failure, not a slow registry' + ); + assert.ok( + lines.some(l => l.includes('could not run npm')), + 'the annotation must name the real cause' + ); +}); + +test('the spec is neutralised in both places it is printed', async () => { + // forLog, for the reason its own header gives: these print as `::error::` + // and `npm install …` lines, a workflow command ends at a newline, and the + // spec arrives from argv. The retry line is the one printed on EVERY + // attempt, and it was the one still interpolating raw. + const crafted = 'pkg@1.0.0\n::error::forged'; + const lines = []; + // The clock is injected alongside the sleep. An instant sleep with a real + // clock does not skip the wait, it busy-loops until the budget elapses in + // wall-clock time — which is how this case first took the better part of a + // minute to assert something instant. + let clock = 0; + const code = await main( + ['--spec', crafted, '--dir', '/tmp', '--budget-seconds', '60'], + { + run: () => false, + now: () => clock, + sleep: ms => { + clock += ms; + return Promise.resolve(); + }, + log: l => lines.push(String(l)), + } + ); + assert.equal(code, 1); + assert.ok( + lines.length > 1, + 'the budget must have bought at least one retry line' + ); + for (const line of lines) { + assert.equal( + line.includes('\n'), + false, + `a printed line carried a raw newline and could forge a command: ${JSON.stringify(line)}` + ); + } + assert.ok( + lines.some(l => /failed \(attempt 1\); retrying/.test(l)), + 'the retry line is the one printed on every attempt, so it must be covered' ); - assert.match(error, /\\n::error::forged/); }); From 81635a5920e0d86b4d9dcecf41c75a92f23aefd6 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 22:03:13 -0400 Subject: [PATCH 05/13] test: make the overshoot case test the guard it was written for MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The case asserting that the last wait never lands past the deadline used a budget the interval divides exactly, so the final sleep landed ON the deadline whether the guard existed or not. It passed with the guard deleted. It was asserting arithmetic. A budget with a remainder is the only shape that separates the two policies, so it now uses one, and pins the attempt count as well as the time slept: without the guard a sleep overshoots to sixty seconds on a fifty-second budget and buys a fourth attempt nobody was waiting for. Confirmed by mutant, which now kills this case rather than only the incidental assertion in a neighbour. Three others from the same read. Not every spawn-level failure is permanent. spawnSync reports resource failures the same way it reports a missing binary, and EAGAIN from a fork or EMFILE is exactly the transient class this budget exists to absorb — the shell loop retried them by accident of treating every failure alike. Only the codes a wait cannot fix are fatal now. One more case had the trap the last commit fixed elsewhere: it injected sleep but not the clock, so its runtime depended on the code under test. It was instant only because the overshoot guard stopped it after one attempt, and busy-looped for a real second under the mutant that removed that guard. The clock is injected. And a comment claimed the exit codes are read by the workflow step. They are not: it is a plain run: under bash -e and both codes simply fail it. The distinction is still worth keeping, because the number sits in the log next to the message and sends a human to different places, so the false half of the sentence went rather than the codes. --- scripts/npm-install-retry.mjs | 35 ++++++++++++++----- scripts/npm-install-retry.test.mjs | 56 +++++++++++++++++++++++++++--- 2 files changed, 78 insertions(+), 13 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index 16093d1aa..ca17fccfa 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -54,6 +54,13 @@ export const DEFAULT_SLEEP_SECONDS = 20; */ export const INSTALL_ARGS = ['install', '--prefer-online', '--ignore-scripts']; +/** + * Spawn failures no wait can fix: npm absent, or present and not runnable. + * Everything else `spawnSync` reports as an error is a busy machine, and a + * busy machine is what the budget is for. + */ +export const FATAL_SPAWN_CODES = new Set(['ENOENT', 'EACCES', 'EPERM']); + /** * Retry `run` until it succeeds or the budget is spent. * @@ -110,11 +117,18 @@ export async function installWithRetry({ * only way to catch a dropped `--prefer-online`, since the flag's effect is a * cache decision inside npm rather than anything the caller observes. * - * A spawn that never started is thrown rather than returned as a failed + * A spawn that could never start is thrown rather than returned as a failed * attempt. No amount of waiting installs anything when `npm` is not on PATH, - * so retrying it would spend the whole budget and then blame propagation for - * a missing binary. A process that started and was killed by a signal stays - * retryable: that is transient in the way this loop exists to absorb. + * so retrying would spend the whole budget and then blame propagation for a + * missing binary. + * + * Only the permanent codes though. `spawnSync` also reports resource failures + * this way — `EAGAIN` from a fork, `EMFILE` — and those are precisely the + * transient class this loop exists to absorb, which the shell loop happened to + * retry by treating every non-zero result the same. Narrowing to the codes a + * wait cannot fix keeps the fast failure for a missing binary without + * converting a busy runner into a red release. A process that started and was + * killed by a signal stays retryable for the same reason. */ export function runNpmInstall(spec, cwd, spawn = spawnSync) { const result = spawn('npm', [...INSTALL_ARGS, spec], { @@ -122,7 +136,10 @@ export function runNpmInstall(spec, cwd, spawn = spawnSync) { stdio: 'inherit', }); if (result.error) { - throw new Error(`could not run npm: ${result.error.message}`); + if (FATAL_SPAWN_CODES.has(result.error.code)) { + throw new Error(`could not run npm: ${result.error.message}`); + } + return false; } return result.status === 0; } @@ -168,10 +185,12 @@ export function positiveInteger(value, name, fallback) { } /** - * Exit codes are read by the workflow step, so they stay distinct: 0 installed, + * Exit codes stay distinct for a reader rather than for a caller: 0 installed, * 1 the registry never served the spec, 2 this was called wrong or could not - * run npm at all. A caller that cannot tell those apart cannot act on any of - * them. + * run npm at all. Nothing branches on them — the step is a plain `run:` under + * `bash -e`, so 1 and 2 both simply fail it — but the number is in the log + * next to the message, and "called wrong" and "the registry never served it" + * send a human to different places. * * `deps` exists for the tests. Without it the only way to drive `main` is to * let it shell out to the real registry, which puts the network inside diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index 0316a2c60..d75f05092 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -32,6 +32,7 @@ import assert from 'node:assert/strict'; import { installWithRetry, runNpmInstall, + FATAL_SPAWN_CODES, parseArgs, positiveInteger, main, @@ -117,10 +118,19 @@ test('a budget smaller than one interval still buys an attempt, and no wait', as }); test('the last wait never lands past the deadline', async () => { - const h = harness({ budgetSeconds: 600, sleepSeconds: 20 }); - await h.promise; + // A budget the interval does NOT divide. With 600 and 20 the final sleep + // lands exactly ON the deadline, so the overshoot guard changes nothing and + // this case passed with the guard deleted — it was asserting arithmetic, not + // behaviour. 50 and 20 leave a remainder, which is the only shape that can + // tell the two policies apart. + const h = harness({ budgetSeconds: 50, sleepSeconds: 20 }); + const result = await h.promise; const spent = h.state.sleeps.reduce((a, b) => a + b, 0); - assert.equal(spent <= 600 * 1000, true, 'slept past the budget'); + assert.equal(spent, 40 * 1000, 'stopped at the last wait that fits'); + assert.equal(spent <= 50 * 1000, true, 'slept past the budget'); + // Without the guard this is 4: a fourth attempt bought by a sleep that + // overshot to 60s on a 50s budget. + assert.equal(result.attempts, 3); }); test('a failed attempt names itself in the log, in order', async () => { @@ -196,11 +206,20 @@ test('a usage error exits 2, distinct from an exhausted budget', async () => { test('an exhausted budget exits 1 and says where to look', async () => { const lines = []; + // The clock is injected as well as the sleep. Without it this case's runtime + // depends on the code under test: it is instant only because the production + // overshoot guard stops after one attempt, and it busy-looped for a real + // second under the mutant that removed that guard. + let clock = 0; const code = await main( ['--spec', 'pkg@1.0.0', '--dir', '/tmp', '--budget-seconds', '1'], { run: () => false, - sleep: () => Promise.resolve(), + now: () => clock, + sleep: ms => { + clock += ms; + return Promise.resolve(); + }, log: l => lines.push(l), } ); @@ -250,7 +269,9 @@ test('a signal-killed npm stays retryable', () => { test('an npm that never started is fatal, not retried for ten minutes', async () => { // Retrying a missing binary spends the whole budget and then blames // propagation for something propagation cannot explain. - const spawn = () => ({ error: new Error('spawn npm ENOENT') }); + const spawn = () => ({ + error: Object.assign(new Error('spawn npm ENOENT'), { code: 'ENOENT' }), + }); assert.throws( () => runNpmInstall('pkg@1.0.0', '/tmp', spawn), /could not run npm/ @@ -275,6 +296,31 @@ test('an npm that never started is fatal, not retried for ten minutes', async () ); }); +test('a spawn failure a wait could fix stays retryable', () => { + // EAGAIN from a fork and EMFILE are a busy machine, which is what the budget + // is for. Treating every spawn-level error as permanent turned those into a + // red release, and the shell loop retried them by accident of treating all + // failures alike. + for (const code of ['EAGAIN', 'EMFILE']) { + const spawn = () => ({ + error: Object.assign(new Error(`spawn npm ${code}`), { code }), + }); + assert.equal( + runNpmInstall('pkg@1.0.0', '/tmp', spawn), + false, + `${code} must be a failed attempt, not a fatal error` + ); + } +}); + +test('the fatal codes are the ones no wait can fix', () => { + assert.deepEqual([...FATAL_SPAWN_CODES].sort(), [ + 'EACCES', + 'ENOENT', + 'EPERM', + ]); +}); + test('the spec is neutralised in both places it is printed', async () => { // forLog, for the reason its own header gives: these print as `::error::` // and `npm install …` lines, a workflow command ends at a newline, and the From 407feb2a1e10fa2ec1ec727ce0812479a75d684c Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 22:18:35 -0400 Subject: [PATCH 06/13] test: cover the one path that runs on every successful release Everything below main was driven and the entry point's success path was not. All five main() cases asserted a failure code, so changing `return 0` to `return 1` left the suite green while failing every leg of every release and every schedule under bash -e. Confirmed by mutant, which now dies on the new case. Three smaller things from the same read. The FATAL_SPAWN_CODES comment claimed everything outside the set is a busy machine. It is not: a permanent failure with a code the set does not name spends the whole budget and is then reported with a propagation diagnosis it does not deserve. The allowlist is still the right way round, because wasting a budget is recoverable by reading the log while failing a release over a briefly exhausted file table is not, so the comment now states the cost instead of denying it. libuv reports a failed chdir in the child exactly as it reports a missing binary, so a bad --dir arrived as "spawn npm ENOENT" and sent a reader to PATH. The message names the directory now. And nothing passes --budget-seconds or --sleep-seconds, so production runs entirely on the module defaults. That is fine and already pinned by a test, but a reader could reasonably have assumed the workflow sets them, so the header says which it is. --- scripts/npm-install-retry.mjs | 24 +++++++++++++++++++++--- scripts/npm-install-retry.test.mjs | 14 ++++++++++++++ 2 files changed, 35 insertions(+), 3 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index ca17fccfa..33dc7cd26 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -40,6 +40,12 @@ import { forLog } from './consumer-sbom-meta.mjs'; // and no run has ever measured how long that clock actually takes: every one // of them gave up long before propagation finished. Generous rather than // clever, and cheap — this fires per release event, not per PR. +// +// These are what production runs on. The workflow passes neither flag, so +// changing a value here changes every release with no diff in +// supply-chain.yml to notice it, which is why a test pins both. The flags +// exist for the tests and for a hand-run dispatch, not because anything +// configures them. export const DEFAULT_BUDGET_SECONDS = 600; export const DEFAULT_SLEEP_SECONDS = 20; @@ -56,8 +62,14 @@ export const INSTALL_ARGS = ['install', '--prefer-online', '--ignore-scripts']; /** * Spawn failures no wait can fix: npm absent, or present and not runnable. - * Everything else `spawnSync` reports as an error is a busy machine, and a - * busy machine is what the budget is for. + * + * An allowlist of fatal codes rather than a denylist of transient ones, so an + * unrecognised spawn error is retried instead of ending the run. That trade is + * deliberate but it is not free: a permanent failure outside this set + * (`ENOEXEC`, `ENAMETOOLONG`) spends the whole budget and is then reported + * with a propagation diagnosis it does not deserve. Wasting the budget on a + * doomed leg is recoverable by reading the log; failing a release because a + * runner was briefly out of file descriptors is not. */ export const FATAL_SPAWN_CODES = new Set(['ENOENT', 'EACCES', 'EPERM']); @@ -137,7 +149,13 @@ export function runNpmInstall(spec, cwd, spawn = spawnSync) { }); if (result.error) { if (FATAL_SPAWN_CODES.has(result.error.code)) { - throw new Error(`could not run npm: ${result.error.message}`); + // The cwd is named because libuv reports a failed chdir in the child + // exactly as it reports a missing binary: both arrive as ENOENT, and + // "spawn npm ENOENT" alone sends a reader to PATH when the directory + // is what is missing. + throw new Error( + `could not run npm in ${forLog(cwd)}: ${result.error.message}` + ); } return false; } diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index d75f05092..cc7a031ee 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -204,6 +204,20 @@ test('a usage error exits 2, distinct from an exhausted budget', async () => { ); }); +test('main exits 0 when the install succeeds, and says nothing', async () => { + // The entry point's success path. Everything below main was covered and + // this was not, so `return 0` could become `return 1` with the whole suite + // green while every leg of every release failed under `bash -e`. + const lines = []; + const code = await main(['--spec', 'pkg@1.0.0', '--dir', '/tmp'], { + run: () => true, + sleep: () => Promise.resolve(), + log: l => lines.push(l), + }); + assert.equal(code, 0); + assert.deepEqual(lines, [], 'a clean install must annotate nothing'); +}); + test('an exhausted budget exits 1 and says where to look', async () => { const lines = []; // The clock is injected as well as the sleep. Without it this case's runtime From 87f283f5ead21f12c57c0d41a4d4aab460c44cbe Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 22:33:33 -0400 Subject: [PATCH 07/13] test: execute the line that connects the flags to the installer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fixing the network dependency removed the only thing running this line. Two cases used to drive main through the real installer, which is what put the network in pnpm test, so injecting `run` was right — but `run` replaces the installer wholesale and skips the mapping from the parsed flags onto runNpmInstall. Swapping those two arguments failed every release-triggered and every scheduled leg with exit 2, and left the suite green. `run` and `spawn` are separate dependencies now. `run` replaces the installer, which is what most cases want; `spawn` leaves the wiring in the path and stubs only the subprocess. The new case takes the second route and compares the whole argv, so the swap dies. Two diagnostics that were emitted and never read. The directory in the spawn throw was matched by a pattern loose enough to pass without it, which mattered because the reason it is there is that libuv reports a failed chdir and a missing binary identically. And parseArgs's unexpected-argument guard had no case at all, so `--spec --dir /tmp` reading --dir as the spec was unpinned. Two prose corrections. The flags cannot be set by a dispatch: this workflow declares no inputs and the step hardcodes both, so only running the script by hand reaches them. And the first half of the stopping condition is redundant while the interval is positive, which positiveInteger guarantees by rejecting zero — it stays because it is the clause that means what it says, and the comment now admits which one actually fires. --- scripts/npm-install-retry.mjs | 21 ++++++++++++-- scripts/npm-install-retry.test.mjs | 44 ++++++++++++++++++++++++++++-- 2 files changed, 60 insertions(+), 5 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index 33dc7cd26..30c7d9717 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -44,8 +44,9 @@ import { forLog } from './consumer-sbom-meta.mjs'; // These are what production runs on. The workflow passes neither flag, so // changing a value here changes every release with no diff in // supply-chain.yml to notice it, which is why a test pins both. The flags -// exist for the tests and for a hand-run dispatch, not because anything -// configures them. +// exist for the tests and for running the script by hand, not because +// anything configures them: the step hardcodes --spec and --dir, and +// workflow_dispatch on this workflow declares no inputs at all. export const DEFAULT_BUDGET_SECONDS = 600; export const DEFAULT_SLEEP_SECONDS = 20; @@ -106,6 +107,12 @@ export async function installWithRetry({ // an attempt whose result the loop has already decided to discard — so a // leg that cannot be fixed by waiting reports its failure an interval // later than it knew it. + // + // The first half is redundant while `wait` is positive, which + // positiveInteger currently guarantees by rejecting zero. It stays as the + // condition that means what it says: the budget is spent. The second is a + // refinement of it, and would silently allow one extra attempt at exactly + // the deadline if a zero interval ever became reachable. const wait = sleepSeconds * 1000; if (now() >= deadline || now() + wait > deadline) { return { ok: false, attempts: attempt }; @@ -214,10 +221,18 @@ export function positiveInteger(value, name, fallback) { * let it shell out to the real registry, which puts the network inside * `pnpm test` and hands a crafted spec to whatever npm decides to invoke for * it. + * + * `run` and `spawn` are separate on purpose. Injecting `run` replaces the + * installer wholesale, which is what most cases want, but it also skips the + * line that maps the parsed flags onto `runNpmInstall` — so an argument + * swapped there would fail every release with the suite green. Injecting + * `spawn` instead leaves that wiring in the path and stubs only the + * subprocess. */ export async function main(argv = process.argv.slice(2), deps = {}) { const { run, + spawn, now, sleep = ms => new Promise(resolve => setTimeout(resolve, ms)), log = console.log, @@ -249,7 +264,7 @@ export async function main(argv = process.argv.slice(2), deps = {}) { spec: flags.spec, budgetSeconds, sleepSeconds, - run: run ?? (spec => runNpmInstall(spec, flags.dir)), + run: run ?? (spec => runNpmInstall(spec, flags.dir, spawn ?? spawnSync)), now, sleep, log, diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index cc7a031ee..1aea9ea40 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -170,6 +170,19 @@ test('parseArgs rejects an unknown flag rather than ignoring it', () => { ); }); +test('parseArgs rejects a bare value where a flag belongs', () => { + // `--spec --dir /tmp` would otherwise read `--dir` as the spec and leave + // the real dir as a stray positional. + assert.throws( + () => parseArgs(['pkg@1.0.0', '--dir', '/tmp']), + /unexpected argument/ + ); + assert.throws( + () => parseArgs(['--spec', 'pkg@1.0.0', '/tmp']), + /unexpected argument/ + ); +}); + test('parseArgs rejects a flag with no value', () => { assert.throws( () => parseArgs(['--spec', 'p@1.0.0', '--dir']), @@ -218,6 +231,30 @@ test('main exits 0 when the install succeeds, and says nothing', async () => { assert.deepEqual(lines, [], 'a clean install must annotate nothing'); }); +test('main hands the spec and the dir to npm the right way round', async () => { + // The one production line between parseArgs and spawnSync: injecting `run` + // replaces the installer and skips it, so this case stubs `spawn` instead + // and leaves the wiring in the path. Swapping the two arguments here fails + // every release with exit 2 while every other case stays green. + const calls = []; + const code = await main(['--spec', 'pkg@2.3.4', '--dir', '/somewhere'], { + spawn: (cmd, args, opts) => { + calls.push({ cmd, args, opts }); + return { status: 0 }; + }, + sleep: () => Promise.resolve(), + log: () => {}, + }); + assert.equal(code, 0); + assert.deepEqual(calls, [ + { + cmd: 'npm', + args: ['install', '--prefer-online', '--ignore-scripts', 'pkg@2.3.4'], + opts: { cwd: '/somewhere', stdio: 'inherit' }, + }, + ]); +}); + test('an exhausted budget exits 1 and says where to look', async () => { const lines = []; // The clock is injected as well as the sleep. Without it this case's runtime @@ -286,9 +323,12 @@ test('an npm that never started is fatal, not retried for ten minutes', async () const spawn = () => ({ error: Object.assign(new Error('spawn npm ENOENT'), { code: 'ENOENT' }), }); + // The directory is part of the message on purpose: libuv reports a failed + // chdir identically to a missing binary, so `/could not run npm/` alone + // passes with the cwd removed and the reader still sent to PATH. assert.throws( - () => runNpmInstall('pkg@1.0.0', '/tmp', spawn), - /could not run npm/ + () => runNpmInstall('pkg@1.0.0', '/tmp/nowhere', spawn), + /could not run npm in "\/tmp\/nowhere"/ ); const lines = []; From b785bab845d091553ae74cb75cae10766202493c Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 22:55:23 -0400 Subject: [PATCH 08/13] ci: size the budget to the propagation that was measured The budget stopped being a guess. Across the releases preceding this change, the gap between a release going up and the registry writing the new version into the packument is usually under a couple of minutes, and was once an order of magnitude worse. The previous value cleared the typical case and would have expired short of the worst one, which is the false red this whole change exists to prevent. The figures and how they were taken are on #716, because measurements belong on the issue rather than in a comment that nothing re-measures. It is set to clear the worst observed case with margin, on the reasoning that the two mistakes are not symmetric: a generous budget spends extra minutes on a release that was already broken, and a short one reds a release that was fine. The default sleep was the last function nothing could call. As an inline default, dropping its argument left every case green, because every other case injects its own sleep, while turning a few dozen packument reads into a few thousand inside the same budget. Exported and timed now. A retryable spawn failure threw its errno away. stdio inherit carries npm's own diagnosis when npm runs, but a spawn that never started produced nothing to inherit, so EAGAIN gave a column of bare retry lines under a propagation diagnosis that does not fit it. It says the code out loud. And a usage-error case let main fall through to console.log, so two ::error:: workflow commands reached stdout during pnpm test. On a runner those are filed as failure annotations against a green job. Captured and asserted here; the same leak in four other script suites is #723. --- scripts/npm-install-retry.mjs | 48 +++++++++++++++++++++--------- scripts/npm-install-retry.test.mjs | 47 +++++++++++++++++++++++++++-- 2 files changed, 78 insertions(+), 17 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index 30c7d9717..b1ffcde0f 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -36,10 +36,15 @@ import { spawnSync } from 'node:child_process'; import { pathToFileURL } from 'node:url'; import { forLog } from './consumer-sbom-meta.mjs'; -// Ten minutes because the budget has to cover a clock nobody here controls, -// and no run has ever measured how long that clock actually takes: every one -// of them gave up long before propagation finished. Generous rather than -// clever, and cheap — this fires per release event, not per PR. +// The budget covers a clock nobody here controls: the gap between a release +// going up and the registry writing the new version into the packument. That +// gap has now been measured across the releases preceding this change, and it +// is usually under a couple of minutes but was once an order of magnitude +// worse — the numbers and how they were taken are on #716. This is set to +// clear the worst observed case with margin rather than the typical one, +// because the cost of being generous falls only on a release that was already +// broken, and it is cheap either way: this fires per release event, not per +// PR. // // These are what production runs on. The workflow passes neither flag, so // changing a value here changes every release with no diff in @@ -47,7 +52,7 @@ import { forLog } from './consumer-sbom-meta.mjs'; // exist for the tests and for running the script by hand, not because // anything configures them: the step hardcodes --spec and --dir, and // workflow_dispatch on this workflow declares no inputs at all. -export const DEFAULT_BUDGET_SECONDS = 600; +export const DEFAULT_BUDGET_SECONDS = 900; export const DEFAULT_SLEEP_SECONDS = 20; /** @@ -149,7 +154,7 @@ export async function installWithRetry({ * converting a busy runner into a red release. A process that started and was * killed by a signal stays retryable for the same reason. */ -export function runNpmInstall(spec, cwd, spawn = spawnSync) { +export function runNpmInstall(spec, cwd, spawn = spawnSync, log = console.log) { const result = spawn('npm', [...INSTALL_ARGS, spec], { cwd, stdio: 'inherit', @@ -164,6 +169,14 @@ export function runNpmInstall(spec, cwd, spawn = spawnSync) { `could not run npm in ${forLog(cwd)}: ${result.error.message}` ); } + // Said out loud because nothing else will. `stdio: 'inherit'` carries + // npm's own diagnosis when npm runs, but a spawn that failed produced no + // output to inherit, so without this the errno is nowhere and the run + // shows a column of bare retry lines under a propagation diagnosis that + // does not fit. + log( + `npm could not be started (${result.error.code}), treating as a failed attempt` + ); return false; } return result.status === 0; @@ -229,14 +242,19 @@ export function positiveInteger(value, name, fallback) { * `spawn` instead leaves that wiring in the path and stubs only the * subprocess. */ +/** + * The real wait, exported so a test can time it. + * + * As an inline default it was the one function in this module nothing could + * call, and dropping the `ms` argument left every case green while turning a + * few dozen packument reads into a few thousand inside the same budget. + */ +export function defaultSleep(ms) { + return new Promise(resolve => setTimeout(resolve, ms)); +} + export async function main(argv = process.argv.slice(2), deps = {}) { - const { - run, - spawn, - now, - sleep = ms => new Promise(resolve => setTimeout(resolve, ms)), - log = console.log, - } = deps; + const { run, spawn, now, sleep = defaultSleep, log = console.log } = deps; let flags; let budgetSeconds; let sleepSeconds; @@ -264,7 +282,9 @@ export async function main(argv = process.argv.slice(2), deps = {}) { spec: flags.spec, budgetSeconds, sleepSeconds, - run: run ?? (spec => runNpmInstall(spec, flags.dir, spawn ?? spawnSync)), + run: + run ?? + (spec => runNpmInstall(spec, flags.dir, spawn ?? spawnSync, log)), now, sleep, log, diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index 1aea9ea40..1ec821df4 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -32,6 +32,7 @@ import assert from 'node:assert/strict'; import { installWithRetry, runNpmInstall, + defaultSleep, FATAL_SPAWN_CODES, parseArgs, positiveInteger, @@ -149,10 +150,41 @@ test('a failed attempt names itself in the log, in order', async () => { ]); }); +test('the real sleep actually waits', async () => { + // The one function an injected clock cannot cover, and the mutant is quiet: + // dropping the `ms` argument leaves every other case green, because they + // all supply their own sleep, while turning a few dozen packument reads + // into a few thousand inside the same budget. + const start = Date.now(); + await defaultSleep(60); + const waited = Date.now() - start; + assert.equal( + waited >= 50, + true, + `returned after ${waited}ms, expected a wait` + ); +}); + +test('a spawn that failed says so, since it prints nothing itself', async () => { + // stdio inherit carries npm's own diagnosis when npm runs. A spawn-level + // failure produced no output to inherit, so without this line the errno is + // nowhere and the log is a column of bare retry lines. + const lines = []; + const spawn = () => ({ + error: Object.assign(new Error('spawn npm EAGAIN'), { code: 'EAGAIN' }), + }); + assert.equal( + runNpmInstall('pkg@1.0.0', '/tmp', spawn, l => lines.push(l)), + false + ); + assert.equal(lines.length, 1); + assert.match(lines[0], /EAGAIN/); +}); + test('the defaults are the ones the workflow relies on', () => { // The workflow passes no budget, so a change to either of these changes // production behaviour with no diff in supply-chain.yml to notice it. - assert.equal(DEFAULT_BUDGET_SECONDS, 600); + assert.equal(DEFAULT_BUDGET_SECONDS, 900); assert.equal(DEFAULT_SLEEP_SECONDS, 20); }); @@ -210,11 +242,20 @@ test('a non-numeric budget is an error, not a silent default', () => { test('a usage error exits 2, distinct from an exhausted budget', async () => { // 1 means "the registry never served it" and 2 means "this was called // wrong". A caller that cannot tell those apart cannot act on either. - assert.equal(await main(['--spec', 'pkg@1.0.0']), 2); + // + // The log is captured rather than left to fall through to console.log: + // these messages are `::error::` workflow commands, and on a runner an + // uncaptured one is filed as a failure annotation against a green test run. + const lines = []; + const log = l => lines.push(l); + assert.equal(await main(['--spec', 'pkg@1.0.0'], { log }), 2); assert.equal( - await main(['--nonsense', 'x', '--spec', 'p@1.0.0', '--dir', '/tmp']), + await main(['--nonsense', 'x', '--spec', 'p@1.0.0', '--dir', '/tmp'], { + log, + }), 2 ); + assert.equal(lines.length, 2, 'each usage error says why'); }); test('main exits 0 when the install succeeds, and says nothing', async () => { From e82d11df55c710195ff78322128f4923ce523da1 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 23:10:46 -0400 Subject: [PATCH 09/13] ci: let every release measure the propagation it waited on Sizing this budget meant reading publish timestamps out of the registry API afterwards, one release at a time, because no run recorded what it waited for. That is a bad way to hold a number that decides whether a good release goes red, and it is worse than it looks: the measurement is a lower bound on what a runner sees through a CDN edge, and the gap it measures only appeared partway through the releases sampled. The distribution has already shifted once. Raising the number again would not fix that. A leg that waited now reports how long and how many attempts it took, so the next person to weigh this reads it off the runs rather than reconstructing it. A first-attempt success stays silent, since every release that resolves immediately would otherwise log a measurement of zero. Three corrections from the same read. The block documenting main ended up above defaultSleep, because that is where defaultSleep was inserted. It described the wrong function and left main undocumented. Three references to the old budget as a duration decayed the moment the budget changed. The duration is gone rather than updated, so it cannot decay a second time. And the case covering a retryable spawn failure let the diagnosis line that the previous commit added print uncaptured, which is precisely the leak that commit fixed one case over and that #723 exists for. Captured and asserted, so this suite still emits no workflow commands. --- scripts/npm-install-retry.mjs | 38 ++++++++++++++++++++---------- scripts/npm-install-retry.test.mjs | 25 +++++++++++++++----- 2 files changed, 44 insertions(+), 19 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index b1ffcde0f..daf3c2be6 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -99,11 +99,23 @@ export async function installWithRetry({ sleep, log = console.log, } = {}) { - const deadline = now() + budgetSeconds * 1000; + const started = now(); + const deadline = started + budgetSeconds * 1000; let attempt = 0; for (;;) { attempt += 1; - if (await run(spec)) return { ok: true, attempts: attempt }; + if (await run(spec)) { + // Said out loud when it took more than one go, because this is the + // measurement nobody had: sizing the budget meant reading publish + // timestamps out of the registry API afterwards, release by release. + // A leg that waited now reports what it waited for, so the next person + // to weigh this number reads it off the runs instead. + if (attempt > 1) { + const waited = Math.round((now() - started) / 1000); + log(`resolved after ${waited}s and ${attempt} attempts`); + } + return { ok: true, attempts: attempt }; + } // Checked after the attempt rather than before it, so the budget always // buys at least one try however small it is set. // @@ -222,6 +234,17 @@ export function positiveInteger(value, name, fallback) { return Number(value); } +/** + * The real wait, exported so a test can time it. + * + * As an inline default it was the one function in this module nothing could + * call, and dropping the `ms` argument left every case green while turning a + * few dozen packument reads into a few thousand inside the same budget. + */ +export function defaultSleep(ms) { + return new Promise(resolve => setTimeout(resolve, ms)); +} + /** * Exit codes stay distinct for a reader rather than for a caller: 0 installed, * 1 the registry never served the spec, 2 this was called wrong or could not @@ -242,17 +265,6 @@ export function positiveInteger(value, name, fallback) { * `spawn` instead leaves that wiring in the path and stubs only the * subprocess. */ -/** - * The real wait, exported so a test can time it. - * - * As an inline default it was the one function in this module nothing could - * call, and dropping the `ms` argument left every case green while turning a - * few dozen packument reads into a few thousand inside the same budget. - */ -export function defaultSleep(ms) { - return new Promise(resolve => setTimeout(resolve, ms)); -} - export async function main(argv = process.argv.slice(2), deps = {}) { const { run, spawn, now, sleep = defaultSleep, log = console.log } = deps; let flags; diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index 1ec821df4..a9ef58cf6 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -21,8 +21,9 @@ * larger budget and every case would stay green. * * Nothing here reaches the network or spawns anything. Both the runner and the - * clock are injected, so a ten-minute budget costs no time and a crafted spec - * is never handed to a real subprocess that might give it a second reading. + * clock are injected, so the whole budget costs no time however large it is + * set, and a crafted spec is never handed to a real subprocess that might give + * it a second reading. * * `.mjs` and `node --test` rather than jest: root-level scripts with no * package of their own, matching consumer-sbom-meta.test.mjs. @@ -42,8 +43,9 @@ import { DEFAULT_SLEEP_SECONDS, } from './npm-install-retry.mjs'; -// A clock that only moves when the policy sleeps, so a ten-minute budget costs -// a test nothing and the assertions stay about spend rather than timing. +// A clock that only moves when the policy sleeps, so the budget costs a test +// nothing whatever it is set to and the assertions stay about spend rather +// than timing. function harness({ succeedOnAttempt = Infinity, budgetSeconds, sleepSeconds }) { const state = { t: 0, attempts: 0, sleeps: [], logs: [] }; return { @@ -75,6 +77,8 @@ test('a spec that resolves first time costs one attempt and no sleep', async () }); assert.deepEqual(await h.promise, { ok: true, attempts: 1 }); assert.equal(h.state.sleeps.length, 0); + // Silent on the happy path: every release that resolves first time would + // otherwise carry a measurement of zero. assert.equal(h.state.logs.length, 0); }); @@ -147,6 +151,10 @@ test('a failed attempt names itself in the log, in order', async () => { assert.deepEqual(h.state.logs, [ 'npm install "pkg@1.0.0" failed (attempt 1); retrying', 'npm install "pkg@1.0.0" failed (attempt 2); retrying', + // The measurement, emitted only when it took more than one go. This is + // the number that sizing the budget had to be reconstructed from, release + // by release, out of the registry API. + 'resolved after 40s and 3 attempts', ]); }); @@ -358,7 +366,7 @@ test('a signal-killed npm stays retryable', () => { assert.equal(runNpmInstall('pkg@1.0.0', '/tmp', spawn), false); }); -test('an npm that never started is fatal, not retried for ten minutes', async () => { +test('an npm that never started is fatal, not retried to the deadline', async () => { // Retrying a missing binary spends the whole budget and then blames // propagation for something propagation cannot explain. const spawn = () => ({ @@ -400,11 +408,16 @@ test('a spawn failure a wait could fix stays retryable', () => { const spawn = () => ({ error: Object.assign(new Error(`spawn npm ${code}`), { code }), }); + // The log is captured, not left to console.log: the diagnosis line this + // path now emits would otherwise print during `pnpm test`, which is the + // leak #723 is about. + const lines = []; assert.equal( - runNpmInstall('pkg@1.0.0', '/tmp', spawn), + runNpmInstall('pkg@1.0.0', '/tmp', spawn, l => lines.push(l)), false, `${code} must be a failed attempt, not a fatal error` ); + assert.match(lines[0], new RegExp(code)); } }); From c19b7613e49e1cd9cc31f6ac002f5ca66a177cae Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Mon, 21 Sep 2026 23:26:26 -0400 Subject: [PATCH 10/13] ci: say what the measurement is, and cover where it starts The last commit added a figure and described it as how long propagation took. It is not that. It is how long the leg waited, which is an upper bound: the version may have become servable anywhere in the interval before the attempt that noticed, and the number also absorbs each failed attempt's own duration. Good enough to show the budget is nowhere near being spent, or that it nearly was, and too coarse to resize the budget on by itself. Since informing that resize is the entire reason it exists, the comment now says so. Its boundary had no test. The only case asserting the measurement succeeded on the third attempt, so the condition could have moved from the first retry to the second and survived the suite, silently dropping the commonest waited case there is: one failure, one wait, resolved. That case exists now and the mutant dies on it. The exhaustion path reported everything except the elapsed time, which is backwards. That is the run that would justify a larger budget, and it named the budget and the attempts and not what it actually spent. Both exits return the figure and both report it, through one helper so they cannot drift. Also a count this branch made wrong on its own: a comment said the job runs two scripts from scripts/, and it now runs three. The number went rather than getting incremented, per the rule in .github/CLAUDE.md. --- .github/workflows/supply-chain.yml | 6 +++--- scripts/npm-install-retry.mjs | 28 ++++++++++++++++++---------- scripts/npm-install-retry.test.mjs | 23 ++++++++++++++++++++--- 3 files changed, 41 insertions(+), 16 deletions(-) diff --git a/.github/workflows/supply-chain.yml b/.github/workflows/supply-chain.yml index 640b0fdb8..2449becfb 100644 --- a/.github/workflows/supply-chain.yml +++ b/.github/workflows/supply-chain.yml @@ -218,9 +218,9 @@ jobs: echo "::error::agent.json reads block but the agent never reported Initialized — the firewall is not up. Check the agent log for 'Reverted changes' (usually an unresolvable allow-listed host)." exit 1 - # New in #530: this job now runs two scripts from scripts/, per rule 9 — - # the install/stamp logic and the closure guard — so it needs the - # repository on disk. That adds a third-party action to a job that had + # New in #530: this job runs scripts from scripts/, per rule 9 — the + # install policy, the install/stamp logic and the closure guard — so it + # needs the repository on disk. That adds a third-party action to a job that had # none, which is the honest cost rather than something to elide: it is on # the repo-wide pin (rule 1) and `persist-credentials: false` means no # token reaches the runner's git config. The job's `allowed-endpoints` diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index daf3c2be6..68aa06a2e 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -101,20 +101,26 @@ export async function installWithRetry({ } = {}) { const started = now(); const deadline = started + budgetSeconds * 1000; + const elapsed = () => Math.round((now() - started) / 1000); let attempt = 0; for (;;) { attempt += 1; if (await run(spec)) { - // Said out loud when it took more than one go, because this is the - // measurement nobody had: sizing the budget meant reading publish - // timestamps out of the registry API afterwards, release by release. - // A leg that waited now reports what it waited for, so the next person - // to weigh this number reads it off the runs instead. + // Said out loud when it took more than one go, because nothing used to + // record it: sizing the budget meant reading publish timestamps out of + // the registry API afterwards, release by release. + // + // Read it as how long this leg waited, which is an UPPER bound on how + // long propagation took and not the same quantity. The version may have + // become servable at any point in the interval before the attempt that + // saw it, and this figure also absorbs each failed attempt's own + // duration. Good enough to show the budget is nowhere near, or that it + // nearly was; too coarse to resize the budget on its own. + const waited = elapsed(); if (attempt > 1) { - const waited = Math.round((now() - started) / 1000); log(`resolved after ${waited}s and ${attempt} attempts`); } - return { ok: true, attempts: attempt }; + return { ok: true, attempts: attempt, waited }; } // Checked after the attempt rather than before it, so the budget always // buys at least one try however small it is set. @@ -132,7 +138,7 @@ export async function installWithRetry({ // the deadline if a zero interval ever became reachable. const wait = sleepSeconds * 1000; if (now() >= deadline || now() + wait > deadline) { - return { ok: false, attempts: attempt }; + return { ok: false, attempts: attempt, waited: elapsed() }; } // forLog here as well as on the exhaustion message. This line prints on // every attempt rather than once, so it is the likelier of the two to @@ -289,8 +295,9 @@ export async function main(argv = process.argv.slice(2), deps = {}) { let ok; let attempts; + let waited; try { - ({ ok, attempts } = await installWithRetry({ + ({ ok, attempts, waited } = await installWithRetry({ spec: flags.spec, budgetSeconds, sleepSeconds, @@ -310,7 +317,8 @@ export async function main(argv = process.argv.slice(2), deps = {}) { if (!ok) { log( `::error::npm install ${forLog(flags.spec)} did not succeed within the ` + - `propagation budget (${budgetSeconds}s, ${attempts} attempts). If that ` + + `propagation budget (${waited}s of ${budgetSeconds}s, ${attempts} ` + + `attempts). If that ` + `version never published, the release step earlier in the pipeline is ` + `where to look; if it did publish, the registry took longer to serve ` + `it than this budget allows.` diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index a9ef58cf6..d0187685f 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -75,7 +75,7 @@ test('a spec that resolves first time costs one attempt and no sleep', async () budgetSeconds: 600, sleepSeconds: 20, }); - assert.deepEqual(await h.promise, { ok: true, attempts: 1 }); + assert.deepEqual(await h.promise, { ok: true, attempts: 1, waited: 0 }); assert.equal(h.state.sleeps.length, 0); // Silent on the happy path: every release that resolves first time would // otherwise carry a measurement of zero. @@ -89,7 +89,7 @@ test('a spec that propagates mid-wait is installed, not abandoned', async () => budgetSeconds: 600, sleepSeconds: 20, }); - assert.deepEqual(await h.promise, { ok: true, attempts: 5 }); + assert.deepEqual(await h.promise, { ok: true, attempts: 5, waited: 80 }); assert.equal(h.state.sleeps.length, 4); }); @@ -118,7 +118,7 @@ test('a budget smaller than one interval still buys an attempt, and no wait', as // rather than spending a full interval on an attempt the loop has already // decided to discard. const h = harness({ budgetSeconds: 1, sleepSeconds: 20 }); - assert.deepEqual(await h.promise, { ok: false, attempts: 1 }); + assert.deepEqual(await h.promise, { ok: false, attempts: 1, waited: 0 }); assert.equal(h.state.sleeps.length, 0); }); @@ -138,6 +138,23 @@ test('the last wait never lands past the deadline', async () => { assert.equal(result.attempts, 3); }); +test('the measurement starts at the first retry, not the second', async () => { + // The boundary of `attempt > 1`. With only a succeeds-on-3 case above it, + // `attempt > 2` survives the suite while silently dropping the modal case: + // one failure, one wait, then resolved. + const h = harness({ + succeedOnAttempt: 2, + budgetSeconds: 900, + sleepSeconds: 20, + }); + const result = await h.promise; + assert.deepEqual(result, { ok: true, attempts: 2, waited: 20 }); + assert.deepEqual(h.state.logs, [ + 'npm install "pkg@1.0.0" failed (attempt 1); retrying', + 'resolved after 20s and 2 attempts', + ]); +}); + test('a failed attempt names itself in the log, in order', async () => { const h = harness({ succeedOnAttempt: 3, From b4384db832297752f125e03e4e60c3c77fd720d8 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Tue, 22 Sep 2026 00:06:02 -0400 Subject: [PATCH 11/13] ci: pin the spend an exhausted leg reports, and stop mislabelling it Two corrections to the figure added two commits ago, both of them about the same few lines. The exhaustion return was unpinned. The only failure-path assertion used a one-second budget, where the true elapsed genuinely is zero, so reporting a hardcoded zero was indistinguishable from computing it and an exhausted release could have said "0s of 900s" forever. Both that case and the one driving main now use a budget with room for real waits, and the mutant dies on both. And the label was wrong a second time. Calling it an upper bound on propagation assumed it started at the publish; it starts when this script starts, which on a real run was some twenty-five seconds later, after job setup, with propagation already under way. So it misses time at the front and bounds nothing. Rather than qualify a sentence that has now been wrong twice, the claim is gone. What it says is what the figure is: how long this leg waited, comparable against the budget because both start at the same instant, with one-interval granularity. Plus the part that decides how to use it, which is that it lives only in the run log, so it is a rolling window and not a record. --- scripts/npm-install-retry.mjs | 17 +++++++++++------ scripts/npm-install-retry.test.mjs | 16 +++++++++++++++- 2 files changed, 26 insertions(+), 7 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index 68aa06a2e..e3661ab06 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -110,12 +110,17 @@ export async function installWithRetry({ // record it: sizing the budget meant reading publish timestamps out of // the registry API afterwards, release by release. // - // Read it as how long this leg waited, which is an UPPER bound on how - // long propagation took and not the same quantity. The version may have - // become servable at any point in the interval before the attempt that - // saw it, and this figure also absorbs each failed attempt's own - // duration. Good enough to show the budget is nowhere near, or that it - // nearly was; too coarse to resize the budget on its own. + // Read it as how long this leg waited, and nothing more. It is not a + // measurement of propagation: it starts when this script starts, which + // is already some way into the job and later still than the publish, and + // it has one-interval granularity because the version may have become + // servable anywhere in the wait before the attempt that noticed. What it + // is good for is the comparison the message makes — waited against the + // budget, both measured from the same instant — which shows whether the + // budget is nowhere near being spent or nearly was. + // + // It also only lives in the run log, so it is a rolling window rather + // than a record: read it while the runs still exist. const waited = elapsed(); if (attempt > 1) { log(`resolved after ${waited}s and ${attempt} attempts`); diff --git a/scripts/npm-install-retry.test.mjs b/scripts/npm-install-retry.test.mjs index d0187685f..fc5eef77d 100644 --- a/scripts/npm-install-retry.test.mjs +++ b/scripts/npm-install-retry.test.mjs @@ -133,6 +133,12 @@ test('the last wait never lands past the deadline', async () => { const spent = h.state.sleeps.reduce((a, b) => a + b, 0); assert.equal(spent, 40 * 1000, 'stopped at the last wait that fits'); assert.equal(spent <= 50 * 1000, true, 'slept past the budget'); + // The elapsed figure on the FAILURE return, which needs a budget where the + // true answer is not zero. The small-budget case above cannot pin this: + // there the real elapsed is 0, so `waited: 0` is indistinguishable from the + // figure never being computed, and an exhausted release would report + // `0s of 900s` forever. + assert.equal(result.waited, 40, 'an exhausted leg must report what it spent'); // Without the guard this is 4: a fourth attempt bought by a sleep that // overshot to 60s on a 50s budget. assert.equal(result.attempts, 3); @@ -329,7 +335,10 @@ test('an exhausted budget exits 1 and says where to look', async () => { // second under the mutant that removed that guard. let clock = 0; const code = await main( - ['--spec', 'pkg@1.0.0', '--dir', '/tmp', '--budget-seconds', '1'], + // A budget with room for real waits, so the message pins a spend that is + // not zero. With a one-second budget the true elapsed IS zero, and then + // `0s` proves nothing about whether the figure was computed at all. + ['--spec', 'pkg@1.0.0', '--dir', '/tmp', '--budget-seconds', '50'], { run: () => false, now: () => clock, @@ -345,6 +354,11 @@ test('an exhausted budget exits 1 and says where to look', async () => { assert.ok(error, 'an exhausted budget must annotate the run'); assert.match(error, /did not succeed within the propagation budget/); assert.match(error, /the release step earlier in the pipeline/); + assert.match( + error, + /\(40s of 50s, 3 attempts\)/, + 'the message carries the spend' + ); }); test('every attempt carries --prefer-online, and the spec comes last', () => { From bb02bef6fd290f2b4e9587bdb5306e8445d0b452 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Tue, 22 Sep 2026 00:19:16 -0400 Subject: [PATCH 12/13] ci: stop the comment crediting a comparison this line does not print The sentence sat above the success log line and described it as printing the spend against the budget. It prints the spend alone. Only the exhaustion message prints both, and the comment now says which is which. Fifth correction to this comment block, against one defect in the policy it describes, so the pattern is worth naming in the history: the prose around this change has been considerably less reliable than the change. Also drops a redundant fallback. main passed `spawn ?? spawnSync` into runNpmInstall, which already defaults the same parameter to the same value. Two fallbacks for one thing only make a reader work out which one wins. --- scripts/npm-install-retry.mjs | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/scripts/npm-install-retry.mjs b/scripts/npm-install-retry.mjs index e3661ab06..ead48068c 100644 --- a/scripts/npm-install-retry.mjs +++ b/scripts/npm-install-retry.mjs @@ -115,9 +115,10 @@ export async function installWithRetry({ // is already some way into the job and later still than the publish, and // it has one-interval granularity because the version may have become // servable anywhere in the wait before the attempt that noticed. What it - // is good for is the comparison the message makes — waited against the - // budget, both measured from the same instant — which shows whether the - // budget is nowhere near being spent or nearly was. + // is good for is comparing against the budget, which starts at the same + // instant, to see whether the budget is nowhere near being spent or + // nearly was. This line prints the spend alone; the exhaustion message + // is the one that prints both. // // It also only lives in the run log, so it is a rolling window rather // than a record: read it while the runs still exist. @@ -306,9 +307,7 @@ export async function main(argv = process.argv.slice(2), deps = {}) { spec: flags.spec, budgetSeconds, sleepSeconds, - run: - run ?? - (spec => runNpmInstall(spec, flags.dir, spawn ?? spawnSync, log)), + run: run ?? (spec => runNpmInstall(spec, flags.dir, spawn, log)), now, sleep, log, From 81407fd9ea264f95942f5f33ba14f598c26f8f14 Mon Sep 17 00:00:00 2001 From: Alex Smith Date: Tue, 22 Sep 2026 00:36:09 -0400 Subject: [PATCH 13/13] ci: credit the install policy to the change that adds it Deleting the stale count from this comment left the sentence attributing the install policy to #530, which introduced the other two scripts. The policy arrives here. Each is credited to what added it now. --- .github/workflows/supply-chain.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/supply-chain.yml b/.github/workflows/supply-chain.yml index 2449becfb..d2c385143 100644 --- a/.github/workflows/supply-chain.yml +++ b/.github/workflows/supply-chain.yml @@ -219,8 +219,8 @@ jobs: exit 1 # New in #530: this job runs scripts from scripts/, per rule 9 — the - # install policy, the install/stamp logic and the closure guard — so it - # needs the repository on disk. That adds a third-party action to a job that had + # install/stamp logic and the closure guard, and the install policy since + # #716 — so it needs the repository on disk. That adds a third-party action to a job that had # none, which is the honest cost rather than something to elide: it is on # the repo-wide pin (rule 1) and `persist-credentials: false` means no # token reaches the runner's git config. The job's `allowed-endpoints`