From a9e61579a3ab3f956075ece6d4d0fa9c77ce1e74 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 20 Oct 2026 21:42:06 +0000 Subject: [PATCH] fix(release): re-derive release-verify-npm's read-back budget from the 18.0.0 reading The 18.0.0 publish read red with every package on npm: @objectstack/console became readable at 12:57:59.327Z, 16m22s after the first read and 21 s after the 15-minute budget ran out. The budget is re-derived with the 17.3.0 margin (900 s / 427 s = 2.11x) over the 18.0.0 spread: 982 s x 2.11 = 34m30s, so RETRY_BUDGET_MS is 35 minutes. It stays one flat number: on 18.0.0 the largest tarball (spec, 42 MB packed) settled six minutes before console (9.4 MB), so size does not predict who settles last. It still fails closed. main() now takes the verifier's probe and sleep seams, so battery 14 pins its exit code and its ::error:: naming on npm's replayed clock: the 18.0.0 window reds under the old 900 s, goes green under the production budget, and an absent package exits 1 named after the whole budget. Claude-Session: https://claude.ai/code/session_01FM29ZqLTrnPNXxijioZwMp Co-authored-by: Claude --- scripts/release-verify-npm.mjs | 217 ++++++++++++++++++++++++++++++--- 1 file changed, 198 insertions(+), 19 deletions(-) diff --git a/scripts/release-verify-npm.mjs b/scripts/release-verify-npm.mjs index 296d7621445..7f259d67ff6 100644 --- a/scripts/release-verify-npm.mjs +++ b/scripts/release-verify-npm.mjs @@ -42,15 +42,44 @@ * * ## Where the retry budget comes from * - * Not a guess -- npm's own `time` field on that release. The burst took - * ~8 minutes to commit end to end, and the spread from the FIRST read - * (`cli`, 10:53:25, which is when this verification starts) to the LAST commit - * (`runtime`, 11:00:32) is 7m07s. `RETRY_BUDGET_MS` is 15 minutes: a little - * over twice the observed spread, because burst latency scales with whatever - * else the registry is absorbing and the cost of being wrong in the short - * direction is a false red on a good release. The cost in the other direction - * is that a GENUINELY broken publish is reported 15 minutes later -- paid once, - * by a job that has already spent longer than that building. + * Not a guess -- npm's own `time` field, read on the releases that set it. The + * spread runs from the FIRST read (when this verification starts) to the LAST + * package npm commits, and the budget is that spread times one margin. + * + * **17.3.0** (run 8330, job 100996109699). The burst took ~8 minutes to commit + * end to end, and the spread from the first read (`cli`, 10:53:25) to the last + * commit (`runtime`, 11:00:32) is 7m07s. The budget was set at 15 minutes: a + * little over twice the observed spread (900 s / 427 s = 2.11x), because burst + * latency scales with whatever else the registry is absorbing and the cost of + * being wrong in the short direction is a false red on a good release. + * + * **18.0.0** (run 39421537775, job 118624531794) is the first reading past it. + * Verification started at 12:41:37Z and spent its 900 s over 19 rounds; the + * step ended red at 12:57:38Z with 1 of 73 packages unread, + * `@objectstack/console`, whose npm `time` is 12:57:59.327Z -- 21 s later, and + * 16m22s after the first read. All 73 were on npm; the false red skipped that + * job's GitHub Releases, its ADR-0087 D4 asset and the runtime image. Same + * margin, new spread: 982 s x 2.11 = 34m30s, so `RETRY_BUDGET_MS` is 35 + * minutes (2.14x the 18.0.0 spread). + * + * It is ONE number for the whole group, not an allowance per package scaled by + * its size, because size did not predict which package settled last. On + * 18.0.0 `console`'s packed tarball is 9,399,458 bytes (36 MB unpacked) and + * `spec`'s is 42,118,133 bytes (193 MB unpacked), yet `spec` was readable at + * +10m04s, six minutes before `console`. On 17.5.0 the order was the other way + * round (`console` 08:05:24Z, `spec` last at 08:09:33Z), and on 17.3.0 the + * last package was `runtime`. Scaled by size, the slowest package of 18.0.0 + * would have drawn a SMALLER allowance than one that settled six minutes before + * it -- and the allowance would need the size of a package the registry cannot + * serve yet. + * + * The budget is a CEILING, not a wait: the loop returns on the first round + * that finds the last target, so a good publish pays only its own settle time + * (18.0.0, replayed on this schedule, goes green at +17m15s -- battery 14). + * Only a GENUINELY broken publish spends all 35 minutes before it is reported. + * Whoever raises it re-checks the caller: the publish job declares no + * `timeout-minutes`, so GitHub's 360-minute job default bounds this step + * together with everything before it (17m23s on 18.0.0, build included). * * ## ⛔ It still fails CLOSED, and that is the whole point * @@ -128,7 +157,7 @@ * ONE round (a budget of 0 — the parameter battery 2 already drives) and prints * one JSON line: `state` is `published`, `unpublished` (some package is * definitively absent) or `unknown` (nothing is absent, but a read failed). - * One round, not fifteen minutes of backoff, because the direction of error is + * One round, not the verifier's whole backoff budget, because the direction of error is * the safe one: a cold read answers `unpublished` and the backfill waits for * the next landing, while a false `published` is impossible — every package * has to answer present. The exit status is 0 for all three answers; it is @@ -195,7 +224,7 @@ const AUDIT_STEP_NAME = 'Audit the release that main actually carries'; // must not red. A battery BELOW its floor means cases stopped running; the // remedy is to find what stopped registering. const SELF_TEST_BATTERIES = Object.freeze({ - '1. The backoff schedule is bounded and spends its whole budget': 8, + '1. The backoff schedule is bounded and spends its whole budget': 10, '2. The #15321 false red: a cold read seven seconds after the commit': 6, '3. The masked defect: runtime never lands, and cli is fine': 6, '4. Absence after the budget is a HARD failure, never softened': 5, @@ -208,11 +237,12 @@ const SELF_TEST_BATTERIES = Object.freeze({ '11. The 17.5.0 publish window, replayed on npm\'s own clock': 7, '12. The audit step backfills only a version whose whole group is on npm, and no publish or image build of it is in flight': 34, '13. The backfill builds from the version commit\'s tree, as the publish does': 13, + '14. The 18.0.0 publish window: console readable at +16m22s, past the old 900 s': 14, }); // DELETING an entry silences that battery's floor exactly as effectively as // zeroing it, so the roster's own size is pinned too. -const SELF_TEST_BATTERY_FLOOR = 13; +const SELF_TEST_BATTERY_FLOOR = 14; // The key an assertion is filed under when no battery is open. It is not a // declared battery, so it reds by the same set difference rather than silently @@ -282,8 +312,11 @@ function batteryFloorFailures() { // Constants // --------------------------------------------------------------------------- -/** See "Where the retry budget comes from" in the header — 7m07s observed, 15m budgeted. */ -export const RETRY_BUDGET_MS = 15 * 60 * 1000; +/** + * See "Where the retry budget comes from" in the header — spreads of 7m07s + * (17.3.0) and 16m22s (18.0.0) observed; 35m budgeted, the 17.3.0 margin over 18.0.0. + */ +export const RETRY_BUDGET_MS = 35 * 60 * 1000; /** First wait after the first round comes back short. */ export const FIRST_DELAY_MS = 5 * 1000; @@ -697,10 +730,21 @@ export function formatSuccess(result) { // --------------------------------------------------------------------------- /** - * @param {{ argv?: string[], env?: NodeJS.ProcessEnv }} [options] + * `probe` and `sleep` are the verifier's own seams, threaded through so the + * self-test pins THIS function's exit code and its `::error::` naming on a + * replayed clock — no network, no real wait — under the production budget. + * + * @param {{ argv?: string[], env?: NodeJS.ProcessEnv, + * probe?: (name: string, version: string) => Promise, + * sleep?: (ms: number) => Promise }} [options] * @returns {Promise} process exit code */ -export async function main({ argv = process.argv.slice(2), env = process.env } = {}) { +export async function main({ + argv = process.argv.slice(2), + env = process.env, + probe = (name, version) => probeVersion(name, version), + sleep = realSleep, +} = {}) { const probeMode = argv.includes('--probe'); const what = probeMode ? 'probe the fixed group' : 'verify the publish'; if (probeMode && argv.includes('--dry-run')) { @@ -733,7 +777,7 @@ export async function main({ argv = process.argv.slice(2), env = process.env } = } if (probeMode) { - const answer = await probeGroup({ targets, probe: (name, version) => probeVersion(name, version) }); + const answer = await probeGroup({ targets, probe }); // stdout is the answer and nothing else; the log line goes to stderr. process.stdout.write(`${JSON.stringify({ version: env.RELEASE_VERSION, ...answer })}\n`); console.error(formatProbe(env.RELEASE_VERSION, answer)); @@ -753,7 +797,8 @@ export async function main({ argv = process.argv.slice(2), env = process.env } = const result = await verifyAllPublished({ targets, - probe: (name, version) => probeVersion(name, version), + probe, + sleep, log: (line) => console.log(line), }); @@ -1381,6 +1426,18 @@ export async function selfTest() { const OBSERVED_SPREAD_MS = (7 * 60 + 7) * 1000; t('the budget outlasts the 7m07s spread measured on the 17.3.0 burst', RETRY_BUDGET_MS > OBSERVED_SPREAD_MS, `${RETRY_BUDGET_MS} > ${OBSERVED_SPREAD_MS}`); + // The 18.0.0 reading: the first read at 12:41:37Z, `console` committed at + // 12:57:59.327Z. The budget has to sit through it with the margin 17.3.0 + // was given (900 s over 427 s), not merely outlast it. + const SPREAD_18_0_0_MS = Date.parse('2026-10-20T12:57:59.327Z') - Date.parse('2026-10-20T12:41:37Z'); + const MARGIN_17_3_0 = (15 * 60 * 1000) / OBSERVED_SPREAD_MS; + t('the budget outlasts the 16m22s spread measured on the 18.0.0 burst', RETRY_BUDGET_MS > SPREAD_18_0_0_MS, `${RETRY_BUDGET_MS} > ${SPREAD_18_0_0_MS}`); + t( + 'and keeps the 17.3.0 margin (2.11x) over it', + RETRY_BUDGET_MS >= SPREAD_18_0_0_MS * MARGIN_17_3_0, + `${RETRY_BUDGET_MS} >= ${Math.round(SPREAD_18_0_0_MS * MARGIN_17_3_0)} (${(RETRY_BUDGET_MS / SPREAD_18_0_0_MS).toFixed(2)}x)`, + ); + const tiny = backoffDelays(7000, { firstMs: 5000, capMs: 60000 }); t('a budget smaller than two waits is truncated, not overspent', tiny.reduce((a, b) => a + b, 0) === 7000, JSON.stringify(tiny)); } @@ -2214,6 +2271,127 @@ export async function selfTest() { } } + // ── 14. The 18.0.0 window ───────────────────────────────────────────────── + battery('14. The 18.0.0 publish window: console readable at +16m22s, past the old 900 s'); + { + // npm's own `time` field for 18.0.0 (run 39421537775, job 118624531794): + // the first package of the group, the anchor, the largest tarball, and the + // package the 900 s budget ran out on, readable 16m22s after the first read. + const STARTED = Date.parse('2026-10-20T12:41:37Z'); + const LANDED = { + '@objectstack/sdui-parser': '2026-10-20T12:40:32.440Z', + '@objectstack/cli': '2026-10-20T12:44:06.409Z', + '@objectstack/spec': '2026-10-20T12:51:40.837Z', + '@objectstack/console': '2026-10-20T12:57:59.327Z', + }; + const CONSOLE = '@objectstack/console'; + const GROUP = Object.keys(LANDED).sort().map((name) => ({ name, version: '18.0.0' })); + // npm's clock, driven by the stub sleep: a round reads the registry at + // STARTED plus every wait taken so far. Probing is taken as instant, so + // each round reads no later than the real step's did — a green here is + // one the real step would also have seen. + const replay = (landed) => { + const waits = []; + const reads = []; + let waited = 0; + return { + waits, + reads, + sleep: async (ms) => { waits.push(ms); waited += ms; }, + probe: async (name) => { + const now = STARTED + waited; + reads.push({ name, now }); + return landed[name] !== undefined && now >= Date.parse(landed[name]); + }, + }; + }; + const consoleReads = (r) => r.reads.filter((x) => x.name === CONSOLE).map((x) => x.now); + const at = (ms) => new Date(ms).toISOString(); + + // OLD BUDGET — 900 s, as a parameter: the run's own red, reproduced. + const old = replay(LANDED); + const oldResult = await verifyAllPublished({ targets: GROUP, probe: old.probe, sleep: old.sleep, budgetMs: 15 * 60 * 1000 }); + t('OLD BUDGET (900 s) reds on 18.0.0, a release that WAS complete', oldResult.ok === false, JSON.stringify(oldResult.missing)); + t('...naming @objectstack/console@18.0.0 and nothing else', oldResult.missing.length === 1 && oldResult.missing[0].name === CONSOLE, JSON.stringify(oldResult.missing)); + t('...after 19 rounds over 900 s, as the run\'s annotation reads', oldResult.rounds === 19 && oldResult.waitedMs === 900_000, `rounds=${oldResult.rounds} waited=${oldResult.waitedMs}`); + t( + '...its last read of console came BEFORE console landed', + Math.max(...consoleReads(old)) < Date.parse(LANDED[CONSOLE]), + `${at(Math.max(...consoleReads(old)))} < ${LANDED[CONSOLE]}`, + ); + + // THIS BUDGET — the production default, never passed in, so restoring the + // old constant reds the cases below. + const now = replay(LANDED); + const result = await verifyAllPublished({ targets: GROUP, probe: now.probe, sleep: now.sleep }); + t('THIS BUDGET sits through the 16m22s spread and goes GREEN', result.ok === true, JSON.stringify(result)); + t('...on a round the old budget never reached', result.waitedMs > 900_000, `waited=${result.waitedMs}`); + const reads = consoleReads(now); + t( + '...the FIRST round after console landed, not by spending the budget', + reads.length >= 2 && reads[reads.length - 2] < Date.parse(LANDED[CONSOLE]) && reads[reads.length - 1] >= Date.parse(LANDED[CONSOLE]) + && result.waitedMs < RETRY_BUDGET_MS, + reads.slice(-2).map(at).join(' .. '), + ); + t('...at +17m15s, the figure the header quotes', result.waitedMs === (17 * 60 + 15) * 1000, `waited=${result.waitedMs}`); + + // main() itself, over a fixture workspace of the same four packages: its + // exit code and its `::error::` line are what the publish step reads. + const ws = mkdtempSync(join(tmpdir(), 'release-verify-npm-18-')); + try { + writeFileSync(join(ws, 'pnpm-workspace.yaml'), "packages:\n - 'packages/*'\n"); + for (const { name, version } of GROUP) { + const dir = join(ws, 'packages', name.split('/')[1]); + mkdirSync(dir, { recursive: true }); + writeFileSync(join(dir, 'package.json'), `${JSON.stringify({ name, version }, null, 2)}\n`); + } + const runMain = async (landed) => { + const r = replay(landed); + const out = []; + const err = []; + const { log, error } = console; + console.log = (...a) => { out.push(a.join(' ')); }; + console.error = (...a) => { err.push(a.join(' ')); }; + let code; + try { + code = await main({ argv: ['--root', ws], env: { RELEASE_VERSION: '18.0.0' }, probe: r.probe, sleep: r.sleep }); + } catch (e) { + code = `threw: ${e instanceof Error ? e.message : String(e)}`; + } finally { + console.log = log; + console.error = error; + } + return { code, out: out.join('\n'), err: err.join('\n'), waits: r.waits }; + }; + + const pass = await runMain(LANDED); + t('main() exits 0 on the 18.0.0 replay, under the production budget', pass.code === 0, `code=${pass.code} ${pass.err.split('\n')[0]}`); + t('...and its notice says the whole group settled', /::notice::all 4 published package\(s\) are readable on npm/.test(pass.out), pass.out.split('\n').slice(-1)[0]); + + const withoutConsole = Object.fromEntries(Object.entries(LANDED).filter(([name]) => name !== CONSOLE)); + const absent = await runMain(withoutConsole); + const annotation = absent.err.split('\n')[0]; + t('ABSENT: main() exits NON-ZERO when console never lands', absent.code === 1, `code=${absent.code}`); + t( + '...its ::error:: line names @objectstack/console@18.0.0, 1 of 4', + annotation.startsWith('::error::') && annotation.includes(`${CONSOLE}@18.0.0`) && annotation.includes('1 of 4'), + annotation.slice(0, 160), + ); + t( + '...and names none of the three that landed', + !['@objectstack/cli@', '@objectstack/spec@', '@objectstack/sdui-parser@'].some((n) => absent.err.includes(n)), + absent.err.split('\n').filter((l) => l.includes('@objectstack/')).join(' | '), + ); + t( + '...concluded only after the WHOLE budget was spent', + absent.waits.reduce((a, b) => a + b, 0) === RETRY_BUDGET_MS, + `${absent.waits.reduce((a, b) => a + b, 0)} of ${RETRY_BUDGET_MS}`, + ); + } finally { + rmSync(ws, { recursive: true, force: true }); + } + } + // The floor runs BEFORE the verdict below, so a success line can only be // printed by a run in which every declared battery registered its cases. for (const message of batteryFloorFailures()) cases.push({ name: message, ok: false }); @@ -2226,7 +2404,8 @@ export async function selfTest() { } console.log( `OK release-verify-npm self-test: ${cases.length} cases pass across ` - + `${Object.keys(SELF_TEST_BATTERIES).length} batteries (the #15321 false red reproduced and absorbed, ` + + `${Object.keys(SELF_TEST_BATTERIES).length} batteries (the #15321 false red reproduced and absorbed, the 18.0.0 ` + + '16m22s spread red under the old 900 s and green under the production budget, ' + 'the masked partial publish caught, absence still fatal, the release audit backfilling ' + 'only a version whose whole group is on npm and whose publish and image build are not in flight, and that backfill built ' + 'from the version commit\'s tree).',