fix(#4250, #4260): distinguish a timed-out npm audit from a JSON parse failure, retry with backoff (#4251)

* fix(#4250): distinguish a timed-out npm audit from a JSON parse failure

npm-audit-baseline.cjs's runPackageLockAudit, and the near-identical
auditProductionVulns helper in npm-integrity-gate.test.cjs, both grabbed
e.stdout whenever an npm audit child process exited non-zero -- without
checking whether the process was actually killed by its 180s timeout.
A timeout-killed process's stdout is truncated mid-write, not complete
JSON, so JSON.parse threw a misleading "Unexpected end of JSON input"
instead of naming npm's registry timeout as the real cause.

Root-caused live during a CI investigation: npm's own status page
reported degraded service, and the registry's bulk-advisories endpoint
was returning 503/hanging, causing npm audit to sit until the timeout
fired.

Adds a shared isTimeoutKill(error) predicate (checks execFileSync's
documented killed/signal fields) and checks it first in both catch
blocks, throwing a clear, actionable error before ever reaching
JSON.parse. The pre-existing "non-zero exit with complete JSON"
recovery path is unchanged and still covered by regression tests.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* chore(#4250): add changeset for npm-audit timeout fix

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* fix(#4250): share the timeout-kill error message and cover auditProductionVulns

Two independent review passes (standards + spec) on the first commit found
real gaps: the timeout-kill error message was duplicated verbatim between
runPackageLockAudit and the near-identical auditProductionVulns helper in
tests/npm-integrity-gate.test.cjs (this repo's own Generative Fix Divergence
anti-pattern -- shared logic across parallel surfaces with no parity check),
and auditProductionVulns picked up the same production fix with zero test
coverage of its own.

Extracts buildTimeoutKillError(cwd), used by both callers so the message
cannot independently drift. Gives auditProductionVulns the same injectable
execFileSyncImpl seam runPackageLockAudit already had, and adds the matching
regression tests (timeout-kill throws the clear error; the pre-existing
non-zero-exit-with-complete-JSON path still recovers correctly).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* chore(#4250): backfill changeset PR number to #4251

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* diag(#4250): surface captured stderr in the timeout-kill error

The killed child process's stderr is buffered in-memory by execFileSync
and attached to the thrown error, but nothing surfaced it -- the timeout
message named the timeout but discarded the one piece of data that could
show WHY npm was still running when it fired (DNS stall, TLS handshake
stall, a registry-side retry loop, all look identical without it).

buildTimeoutKillError now takes the killed error and includes its stderr
(or an explicit 'no stderr was captured' note) in the message. This is a
diagnostic improvement for the next CI occurrence, not a behavior fix --
local reproduction has directly ruled out npm version (installed the
exact CI-bundled 11.17.0 and ran it against this repo: 0.49s, clean),
general npm registry reachability (0.4-1.4s locally, repeatedly), and
npm ci speed (2m, succeeded) as explanations for the 180s CI hangs.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* fix(#4260): bounded retry with backoff for npm audit calls, finish the extraction

The audit backend has real, independent latency variance from the rest of
the npm registry -- measured (see #4260): a bulk-advisories POST took
43.41s vs 0.20s for a plain registry fetch on the same host, and the same
endpoint returned no response at all (000) twice in the same window,
while status.npmjs.org reported fully operational throughout. Against
that, runPackageLockAudit and its near-duplicate auditProductionVulns
each made exactly one attempt with no retry -- any single bad moment
failed a REQUIRED CI gate on a transport hiccup, not a real advisory.

Replaces the single 180s attempt with runNpmAuditWithRetry: up to 3
attempts at 60s each (comfortably above the worst measured working
latency) with exponential backoff between them. Only a confirmed
timeout-kill is retried; a genuine non-timeout failure still fails
immediately, and exhausting all attempts still fails the gate -- per
#4260's own caveat, silently disarming a required security check on a
transport error is worse than occasionally re-running CI.

Also finishes the extraction #4260 flagged as stopped halfway:
auditProductionVulns (tests/npm-integrity-gate.test.cjs) duplicated
runPackageLockAudit's entire candidate loop, recovery branch, and timeout
classification, differing only in npm args and precondition check. It is
now a thin wrapper delegating to the newly-exported runInstalledTreeAudit,
which shares runNpmAuditWithRetry with runPackageLockAudit -- one
implementation instead of two that could independently drift.

buildTimeoutKillError now reports attempt count and still surfaces
captured stderr from the last kill.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* chore(#4260): update changeset for retry/backoff scope

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

* test(#4260): budget for two sequential retry-audit calls, close coverage gaps

Two review passes on the retry/backoff commit found real gaps:

- TEST_TIMEOUT_MS budgeted only one retry-audit call's worst case (210s),
  but checkTreeAgainstBaseline makes two sequential calls (HEAD tree via
  auditProductionVulns, baseline tree via runPackageLockAudit) -- combined
  worst case is ~372s. If both genuinely exhausted retries, node:test's
  own timeout would fire first and mask buildTimeoutKillError's clear
  message, undercutting #4250's own fix in that edge case. Recomputed
  using the same backoff formula the production code uses, so it can't
  independently drift.

- buildTimeoutKillError's default-attempts(1) singular-phrasing branch had
  zero direct test coverage (nothing calls it with a single attempt
  anymore) -- a real mutation-testing risk. Added direct tests for both
  phrasing branches plus the no-error-object case.

- runInstalledTreeAudit's null-guard skip paths (missing package.json,
  missing node_modules) had no tests, unlike runPackageLockAudit's
  matching paths. Added for parity.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

---------

Co-authored-by: sim <sim@local>
Co-authored-by: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
Tom Boucher
2026-09-04 10:02:17 -04:00
committed by GitHub
parent 97ce61dee2
commit 18e5cfff8a
4 changed files with 476 additions and 126 deletions

View File

@@ -20,8 +20,13 @@ const {
diffNewVulnerablePackages,
evaluateAuditDiff,
runPackageLockAudit,
runInstalledTreeAudit,
runNpmAuditWithRetry,
extractBaselineTree,
resolveBaselineRef,
isTimeoutKill,
buildTimeoutKillError,
AUDIT_BACKOFF_BASE_MS,
NULL_SHA,
} = require('../scripts/npm-audit-baseline.cjs');
@@ -294,3 +299,204 @@ describe('runPackageLockAudit', () => {
}
});
});
// ─── runInstalledTreeAudit (filesystem-only skip conditions, no registry) ──
describe('runInstalledTreeAudit', () => {
test('missing package.json -> null', () => {
const dir = createTempDir('gsd-audit-installed-empty-');
try {
assert.strictEqual(runInstalledTreeAudit(dir), null);
} finally {
cleanup(dir);
}
});
test('package.json present but no node_modules -> null', () => {
const dir = createTempDir('gsd-audit-installed-nomodules-');
try {
fs.writeFileSync(path.join(dir, 'package.json'), '{"name":"nomodules"}');
assert.strictEqual(runInstalledTreeAudit(dir), null);
} finally {
cleanup(dir);
}
});
});
// ─── isTimeoutKill ───────────────────────────────────────────────────────────
describe('isTimeoutKill', () => {
test('killed: true -> true', () => {
assert.strictEqual(isTimeoutKill({ killed: true }), true);
});
test('signal set (e.g. SIGTERM) -> true', () => {
assert.strictEqual(isTimeoutKill({ signal: 'SIGTERM' }), true);
});
test('both killed and signal set -> true', () => {
assert.strictEqual(isTimeoutKill({ killed: true, signal: 'SIGTERM' }), true);
});
test('neither killed nor signal set (normal non-zero exit) -> false', () => {
assert.strictEqual(isTimeoutKill({ killed: false, signal: null, status: 1, stdout: '{}' }), false);
});
test('killed: false explicitly -> false', () => {
assert.strictEqual(isTimeoutKill({ killed: false }), false);
});
test('null/undefined error -> false, does not throw', () => {
assert.strictEqual(isTimeoutKill(null), false);
assert.strictEqual(isTimeoutKill(undefined), false);
});
test('plain object with no killed/signal keys at all -> false', () => {
assert.strictEqual(isTimeoutKill({}), false);
});
});
// ─── buildTimeoutKillError ───────────────────────────────────────────────────
describe('buildTimeoutKillError', () => {
test('default attempts (1) uses singular ms-based phrasing, not "N attempts"', () => {
const err = buildTimeoutKillError('/some/dir', { stderr: 'some stderr text' });
assert.match(err.message, /npm audit timed out after \d+ms/);
assert.doesNotMatch(err.message, /attempts/);
assert.match(err.message, /some stderr text/);
});
test('attempts > 1 uses plural "N attempts" phrasing with backoff mention', () => {
const err = buildTimeoutKillError('/some/dir', { stderr: '' }, 3);
assert.match(err.message, /npm audit timed out after 3 attempts/);
assert.match(err.message, /exponential backoff/);
});
test('no error object at all still produces a message, no crash', () => {
const err = buildTimeoutKillError('/some/dir', undefined);
assert.match(err.message, /npm audit timed out after \d+ms/);
assert.match(err.message, /no stderr was captured/);
});
});
// ─── runPackageLockAudit -- timeout-kill classification (#4250) ─────────────
describe('runPackageLockAudit — timeout-kill retry classification (#4250, #4260)', () => {
function makeFixtureDir(t) {
const dir = createTempDir('gsd-audit-baseline-timeout-');
t.after(() => cleanup(dir));
fs.writeFileSync(path.join(dir, 'package.json'), '{"name":"fixture"}');
fs.writeFileSync(path.join(dir, 'package-lock.json'), '{"lockfileVersion":3}');
return dir;
}
function makeKilledError() {
return Object.assign(new Error('command timed out'), {
killed: true,
signal: 'SIGTERM',
stdout: '{"auditReportVersion":2,"vulnerabi', // deliberately truncated, non-empty
stderr: 'npm http fetch GET 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk (attempt 1) 178234ms',
});
}
test('a timeout-killed execFileSync call on every attempt throws a clear timeout error after exhausting retries, not a JSON parse error', (t) => {
const dir = makeFixtureDir(t);
const execFileSyncImpl = () => { throw makeKilledError(); };
const sleepImpl = () => {};
assert.throws(
() => runPackageLockAudit(dir, { execFileSyncImpl, sleepImpl }),
(err) => {
assert.match(err.message, /npm audit timed out after \d+ attempts/);
assert.match(err.message, /status\.npmjs\.org/);
assert.doesNotMatch(err.message, /Unexpected end of JSON input/);
assert.match(err.message, /Captured stderr before the last kill/);
assert.match(err.message, /npm http fetch GET/);
return true;
},
);
});
test('a timeout-killed call with no captured stderr still produces a clear message (no crash on missing stderr)', (t) => {
const dir = makeFixtureDir(t);
const killedError = Object.assign(new Error('command timed out'), {
killed: true,
signal: 'SIGTERM',
// no stdout, no stderr at all
});
const execFileSyncImpl = () => { throw killedError; };
const sleepImpl = () => {};
assert.throws(
() => runPackageLockAudit(dir, { execFileSyncImpl, sleepImpl }),
(err) => {
assert.match(err.message, /npm audit timed out after \d+ attempts/);
assert.match(err.message, /no stderr was captured/);
return true;
},
);
});
test('retry recovers: timeouts on the first attempts followed by a successful final attempt succeeds', (t) => {
const dir = makeFixtureDir(t);
const completeJson = JSON.stringify({ metadata: { vulnerabilities: { high: 0 } }, vulnerabilities: {} });
let calls = 0;
const execFileSyncImpl = () => {
calls += 1;
if (calls < 3) throw makeKilledError();
return completeJson;
};
const sleepImpl = () => {};
const result = runPackageLockAudit(dir, { execFileSyncImpl, sleepImpl });
assert.deepStrictEqual(result.metadata.vulnerabilities, { high: 0 });
assert.strictEqual(calls, 3);
});
test('a normal non-zero exit with complete stdout JSON still recovers correctly (no regression)', (t) => {
const dir = makeFixtureDir(t);
const completeJson = JSON.stringify({ metadata: { vulnerabilities: { high: 1 } }, vulnerabilities: { foo: {} } });
const nonZeroExitError = Object.assign(new Error('npm audit found vulnerabilities'), {
status: 1,
stdout: completeJson,
});
const execFileSyncImpl = () => { throw nonZeroExitError; };
const result = runPackageLockAudit(dir, { execFileSyncImpl });
assert.deepStrictEqual(result.metadata.vulnerabilities, { high: 1 });
});
test('a real successful call (no throw) still works via the injected impl', (t) => {
const dir = makeFixtureDir(t);
const completeJson = JSON.stringify({ metadata: { vulnerabilities: {} }, vulnerabilities: {} });
const execFileSyncImpl = () => completeJson;
const result = runPackageLockAudit(dir, { execFileSyncImpl });
assert.deepStrictEqual(result.metadata.vulnerabilities, {});
});
});
// ─── runNpmAuditWithRetry — backoff timing (#4260) ──────────────────────────
describe('runNpmAuditWithRetry — backoff timing (#4260)', () => {
test('a timeout-then-recover attempt sequence sleeps once with the base backoff value', (t) => {
const dir = createTempDir('gsd-audit-baseline-backoff-');
t.after(() => cleanup(dir));
const completeJson = JSON.stringify({ metadata: { vulnerabilities: {} }, vulnerabilities: {} });
let calls = 0;
const execFileSyncImpl = () => {
calls += 1;
if (calls === 1) {
throw Object.assign(new Error('command timed out'), { killed: true, signal: 'SIGTERM' });
}
return completeJson;
};
const sleepCalls = [];
const sleepImpl = (ms) => sleepCalls.push(ms);
const parsed = runNpmAuditWithRetry(dir, ['audit', '--json'], { execFileSyncImpl, sleepImpl });
assert.deepStrictEqual(parsed.metadata.vulnerabilities, {});
assert.deepStrictEqual(sleepCalls, [AUDIT_BACKOFF_BASE_MS * 1]);
});
});

View File

@@ -201,86 +201,38 @@ const { test, describe } = require('node:test');
const assert = require('node:assert/strict');
const path = require('node:path');
const fs = require('node:fs');
const { execFileSync } = require('node:child_process');
const {
evaluateAuditDiff,
runPackageLockAudit,
runInstalledTreeAudit,
extractBaselineTree,
resolveBaselineRef,
AUDIT_ATTEMPT_TIMEOUT_MS,
AUDIT_MAX_ATTEMPTS,
AUDIT_BACKOFF_BASE_MS,
} = require('../scripts/npm-audit-baseline.cjs');
const { cleanup } = require('./helpers.cjs');
const { cleanup, createTempDir } = require('./helpers.cjs');
const ROOT = path.resolve(__dirname, '..');
const SDK = path.join(ROOT, 'sdk');
const AUDIT_TIMEOUT_MS = 180_000;
const TEST_TIMEOUT_MS = AUDIT_TIMEOUT_MS + 30_000;
function auditProductionVulns(cwd) {
if (!fs.existsSync(path.join(cwd, 'package.json'))) {
return null; // signal "skip" to caller
}
if (!fs.existsSync(path.join(cwd, 'node_modules'))) {
return null; // signal "skip" to caller
}
const isWindows = process.platform === 'win32';
const npmCandidates = isWindows ? ['npm.cmd', 'npm'] : ['npm'];
const args = ['audit', '--omit=dev', '--json'];
let out;
let lastErr = null;
for (const npmCmd of npmCandidates) {
try {
out = execFileSync(
npmCmd,
args,
{
cwd,
encoding: 'utf-8',
stdio: ['ignore', 'pipe', 'pipe'],
timeout: AUDIT_TIMEOUT_MS,
shell: isWindows,
}
);
lastErr = null;
break;
} catch (e) {
// `npm audit` exits non-zero when advisories are present; the JSON is
// still on stdout in that case. Recover and let the assertion classify —
// but only when stdout actually CARRIES the JSON. A killed or aborted
// audit exits non-zero with EMPTY stdout (npm writes plain-text errors
// to stderr); accepting the empty string here used to surface as
// `SyntaxError: Unexpected end of JSON input` at the parse below, hiding
// the real cause. Keep the candidate loop going and let the explicit
// empty-output throw below name npm's stderr instead.
const recovered = e && typeof e.stdout !== 'undefined' && e.stdout !== null
? (Buffer.isBuffer(e.stdout) ? e.stdout.toString('utf-8') : String(e.stdout))
: '';
if (recovered.trim()) {
out = recovered;
lastErr = null;
break;
}
lastErr = e;
}
}
if (!out || !out.trim()) {
const detail = lastErr
? [lastErr.stdout, lastErr.stderr, String(lastErr.message)].filter(Boolean).join('\n').slice(0, 500)
: '(no error captured)';
throw new Error(
`npm audit --json produced no output. ` +
`Detail from the failed invocation:\n${detail}`
);
}
if (lastErr) throw lastErr;
const parsed = JSON.parse(out);
// `null` is reserved for the "node_modules missing → skip" signal above.
// Any other unexpected JSON shape is a real failure of the audit harness
// (npm changed its output format, audit aborted before metadata, etc.) —
// throw so the test fails loudly instead of skipping silently.
if (parsed && parsed.metadata && parsed.metadata.vulnerabilities) {
return parsed;
}
throw new Error(`Unexpected npm audit JSON shape in ${cwd}: missing metadata.vulnerabilities`);
// Worst case for ONE retry-audit call: every attempt times out, with
// exponential backoff between each (AUDIT_MAX_ATTEMPTS - 1 gaps) -- computed
// with the SAME formula scripts/npm-audit-baseline.cjs uses internally, so
// this can't independently drift from the real backoff schedule.
let totalBackoffMs = 0;
for (let attempt = 1; attempt < AUDIT_MAX_ATTEMPTS; attempt += 1) {
totalBackoffMs += AUDIT_BACKOFF_BASE_MS * (2 ** (attempt - 1));
}
const SINGLE_AUDIT_WORST_CASE_MS = (AUDIT_ATTEMPT_TIMEOUT_MS * AUDIT_MAX_ATTEMPTS) + totalBackoffMs;
// checkTreeAgainstBaseline makes up to TWO sequential retry-audit calls
// (auditProductionVulns for HEAD, runPackageLockAudit for the baseline) --
// budget for both exhausting retries simultaneously, or node:test's own
// timeout fires first and masks buildTimeoutKillError's clear message.
const TEST_TIMEOUT_MS = (SINGLE_AUDIT_WORST_CASE_MS * 2) + 30_000;
function auditProductionVulns(cwd, opts = {}) {
return runInstalledTreeAudit(cwd, opts);
}
describe('#3588: npm audit --omit=dev introduces no NEW advisories vs baseline (#4196)', () => {
@@ -329,5 +281,71 @@ describe('#3588: npm audit --omit=dev introduces no NEW advisories vs baseline (
checkTreeAgainstBaseline(t, SDK, 'sdk', 'sdk/ is not an auditable npm package or sdk/node_modules/ is missing');
});
});
describe('auditProductionVulns — timeout-kill retry classification (#4250, #4260)', () => {
function makeFixtureDir(t) {
const dir = createTempDir('gsd-audit-baseline-timeout-');
t.after(() => cleanup(dir));
fs.mkdirSync(path.join(dir, 'node_modules'), { recursive: true });
fs.writeFileSync(path.join(dir, 'package.json'), '{"name":"fixture"}');
return dir;
}
function makeKilledError() {
return Object.assign(new Error('command timed out'), {
killed: true,
signal: 'SIGTERM',
stdout: '{"auditReportVersion":2,"vulnerabi', // deliberately truncated, non-empty
stderr: 'npm http fetch GET 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk (attempt 1) 178234ms',
});
}
test('a timeout-killed execFileSync call on every attempt throws a clear timeout error after exhausting retries, not a JSON parse error', (t) => {
const dir = makeFixtureDir(t);
const execFileSyncImpl = () => { throw makeKilledError(); };
const sleepImpl = () => {};
assert.throws(
() => auditProductionVulns(dir, { execFileSyncImpl, sleepImpl }),
(err) => {
assert.match(err.message, /npm audit timed out after \d+ attempts/);
assert.match(err.message, /status\.npmjs\.org/);
assert.doesNotMatch(err.message, /Unexpected end of JSON input/);
assert.match(err.message, /Captured stderr before the last kill/);
assert.match(err.message, /npm http fetch GET/);
return true;
},
);
});
test('retry recovers: timeouts on the first attempts followed by a successful final attempt succeeds', (t) => {
const dir = makeFixtureDir(t);
const completeJson = JSON.stringify({ metadata: { vulnerabilities: { high: 0 } }, vulnerabilities: {} });
let calls = 0;
const execFileSyncImpl = () => {
calls += 1;
if (calls < 3) throw makeKilledError();
return completeJson;
};
const sleepImpl = () => {};
const result = auditProductionVulns(dir, { execFileSyncImpl, sleepImpl });
assert.deepStrictEqual(result.metadata.vulnerabilities, { high: 0 });
assert.strictEqual(calls, 3);
});
test('a normal non-zero exit with complete stdout JSON still recovers correctly (no regression)', (t) => {
const dir = makeFixtureDir(t);
const completeJson = JSON.stringify({ metadata: { vulnerabilities: { high: 1 } }, vulnerabilities: { foo: {} } });
const nonZeroExitError = Object.assign(new Error('npm audit found vulnerabilities'), {
status: 1,
stdout: completeJson,
});
const execFileSyncImpl = () => { throw nonZeroExitError; };
const result = auditProductionVulns(dir, { execFileSyncImpl });
assert.deepStrictEqual(result.metadata.vulnerabilities, { high: 1 });
});
});
});
}