diff --git a/.github/workflows/npm-publish.yml b/.github/workflows/npm-publish.yml index 9438be6eb..cfcdc3d2d 100644 --- a/.github/workflows/npm-publish.yml +++ b/.github/workflows/npm-publish.yml @@ -142,18 +142,20 @@ jobs: NODE_AUTH_TOKEN: ${{ secrets.NPM_TOKEN }} run: npm publish --provenance --access public + # The poll, its budget (READBACK_TIMEOUT_SECONDS, default 300) and the + # failure diagnostics live in the script, not inline here — a workflow + # body cannot be exercised by the suite, and this loop went red on two + # good publishes (cli 0.1.65 run 35498255344, 0.1.66 run 35804128707) + # before anyone could test it. TASK-100. + # + # $GITHUB_WORKSPACE, not a relative path: this job sets + # working-directory to the package dir, and the script is at the repo + # root. It is cwd-independent, so the workspace path is the only + # unambiguous way to reach it. - name: Read it back from the registry if: steps.cmp.outputs.action == 'publish' shell: bash env: NAME: ${{ steps.cmp.outputs.name }} WANT: ${{ steps.cmp.outputs.repo_v }} - run: | - set -euo pipefail - for i in 1 2 3 4 5 6; do - got=$(npm view "$NAME@$WANT" version 2>/dev/null || true) - [ "$got" = "$WANT" ] && { echo "✓ $NAME@$WANT is live"; exit 0; } - sleep 10 - done - echo "::error::$NAME@$WANT not visible on the registry after publish" - exit 1 + run: bash "$GITHUB_WORKSPACE/scripts/verify-npm-publish-readback.sh" diff --git a/backend/__tests__/unit/scripts/npmPublishReadback.test.js b/backend/__tests__/unit/scripts/npmPublishReadback.test.js new file mode 100644 index 000000000..c5077bfa4 --- /dev/null +++ b/backend/__tests__/unit/scripts/npmPublishReadback.test.js @@ -0,0 +1,263 @@ +/** + * Guards scripts/verify-npm-publish-readback.sh, the registry poll that closes + * the "version moved but nobody published" loop. + * + * Earned 2026-09-23 (TASK-100). cli 0.1.65 (run 35498255344) and 0.1.66 (run + * 35804128707) both published fine — the registry moved, `npx` returned the new + * version — and this step went red anyway because it gave up after ~60s while + * npm's own documentation puts propagation at "a few minutes". The loop lived + * inline in the workflow, where nothing in the suite could reach it, and its + * failure said only which version it had been looking for: not whether the + * registry was slow, stale, or unreadable with the token in use. + * + * So this file asserts three things, each of which was the defect: + * 1. a slow propagation succeeds (the retry loop actually retries); + * 2. the budget is honoured, and its default is minutes rather than seconds; + * 3. exhaustion reports what the registry DID serve, and exits non-zero — + * a read-back that cannot say what it saw is the same false negative one + * layer down. + * + * The stub `npm` answers by argument shape, so the assertions above are about + * this script's decisions, not about the network. The wiring half is asserted + * against the workflow text because a workflow body cannot be executed here. + */ + +const { execFileSync } = require('child_process'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +const REPO_ROOT = path.resolve(__dirname, '..', '..', '..', '..'); +const SCRIPT = path.join(REPO_ROOT, 'scripts', 'verify-npm-publish-readback.sh'); +const WORKFLOW = path.join(REPO_ROOT, '.github', 'workflows', 'npm-publish.yml'); + +const NAME = '@commonlyai/cli'; +const WANT = '0.1.68'; +const REGISTRY_SERVES = '0.1.67'; + +/** + * A stub `npm` whose behaviour is driven by env, so each test states the + * registry's condition rather than mocking this script's internals. + * STUB_NAME the package name (so the two `version` shapes differ) + * STUB_FAILS_UNTIL=n the first n `@` lookups 404 + * STUB_NEVER_PUBLISHED=1 every such lookup 404s + * STUB_LATEST what `dist-tags` and `` lookups serve + * STUB_SLEEP_SECONDS how long each `npm view` takes + * The call log and attempt counter are files next to the stub: the attempt + * count is the assertion, so it must come from outside this script's output. + */ +const stubSource = [ + '#!/usr/bin/env bash', + "printf '%s\\n' \"$*\" >> \"$STUB_LOG.calls\"", + 'sleep "${STUB_SLEEP_SECONDS:-0}"', + 'if [ "$1" != "view" ]; then', + ' echo "stub: unexpected npm call: $*" >&2', + ' exit 1', + 'fi', + 'target="$2"; verb="${3:-}"; fourth="${4:-}"', + 'if [ "$verb" = "dist-tags" ] && [ "$fourth" = "--json" ]; then', + " printf '{\"latest\":\"%s\"}\\n' \"${STUB_LATEST:-0.0.0}\"", + ' exit 0', + 'fi', + 'if [ "$verb" = "version" ] && [ "$target" = "$STUB_NAME" ]; then', + ' echo "${STUB_LATEST:-0.0.0}"', + ' exit 0', + 'fi', + 'if [ "$verb" = "version" ]; then', + ' n=$(( $(cat "$STUB_LOG.attempts" 2>/dev/null || echo 0) + 1 ))', + ' echo "$n" > "$STUB_LOG.attempts"', + ' if [ "${STUB_NEVER_PUBLISHED:-0}" = "1" ] || [ "$n" -le "${STUB_FAILS_UNTIL:-0}" ]; then', + ' echo "npm error code E404" >&2', + ' echo "npm error 404 No match found for version" >&2', + ' exit 1', + ' fi', + ' echo "${STUB_LATEST:-0.0.0}"', + ' exit 0', + 'fi', + 'echo "stub: unexpected npm call: $*" >&2', + 'exit 1', + '', +].join('\n'); + +const withStub = () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'readback-stub-')); + fs.writeFileSync(path.join(dir, 'npm'), stubSource, { mode: 0o755 }); + return { dir, log: path.join(dir, 'npm-log') }; +}; + +// `timeout` is load-bearing: the defect this file now guards against is a loop +// that cannot terminate, and without a kill-timeout the suite HANGS on it — +// which reads as an infrastructure problem rather than a failed assertion. +const runScript = (env, { timeoutMs = 30000 } = {}) => { + try { + const stdout = execFileSync('bash', [SCRIPT], { + encoding: 'utf8', + stdio: ['ignore', 'pipe', 'pipe'], + timeout: timeoutMs, + env: { ...process.env, ...env }, + }); + return { status: 0, stdout, stderr: '', signal: null }; + } catch (err) { + return { + status: err.status ?? null, + stdout: err.stdout || '', + stderr: err.stderr || '', + signal: err.signal ?? null, + }; + } +}; + +const attempts = (log) => Number(fs.readFileSync(`${log}.attempts`, 'utf8').trim()); + +const withEnv = (dir, log, extra) => ({ + PATH: `${dir}:${process.env.PATH}`, + STUB_LOG: log, + STUB_NAME: NAME, + NAME, + WANT, + ...extra, +}); + +describe('npm publish read-back', () => { + test('a slow propagation succeeds: the retry loop outlasts the old 60s window', () => { + const { dir, log } = withStub(); + // Five 404s then success. The previous inline loop allowed six attempts but + // slept AFTER the sixth, so this is the boundary that made 0.1.65/0.1.66 red. + const result = runScript(withEnv(dir, log, { + STUB_FAILS_UNTIL: '5', + STUB_LATEST: WANT, + READBACK_INTERVAL_SECONDS: '0', + READBACK_TIMEOUT_SECONDS: '30', + })); + + expect(result.status).toBe(0); + expect(result.stdout).toMatch(new RegExp(`${WANT} is live`)); + expect(attempts(log)).toBe(6); + }); + + test('the budget is honoured: with a 2s budget and a 1s interval it stops at 3 attempts', () => { + const { dir, log } = withStub(); + const result = runScript(withEnv(dir, log, { + STUB_NEVER_PUBLISHED: '1', + STUB_LATEST: REGISTRY_SERVES, + READBACK_INTERVAL_SECONDS: '1', + READBACK_TIMEOUT_SECONDS: '2', + })); + + expect(result.status).toBe(1); + expect(attempts(log)).toBe(3); + }); + + test('the budget is a clock: interval 0 with a non-zero budget still terminates', () => { + // Vera 71347, reproduced: `elapsed` advanced only by INTERVAL_SECONDS, so at + // interval 0 it never reached the timeout — 789 attempts in 8s, still + // reporting 0s, killed by an external alarm. In the release job that is not a + // red step but a run held to the six-hour limit. The assertion is that the + // script EXITS 1 (not that it is fast): the kill-timeout turns a hang into a + // failure, and attempts > 1 proves the loop actually ran more than once. + const { dir, log } = withStub(); + const started = Date.now(); + const result = runScript( + withEnv(dir, log, { + STUB_NEVER_PUBLISHED: '1', + READBACK_INTERVAL_SECONDS: '0', + READBACK_TIMEOUT_SECONDS: '2', + }), + { timeoutMs: 15000 }, + ); + + expect(result.signal).toBeNull(); + expect(result.status).toBe(1); + expect(attempts(log)).toBeGreaterThan(1); + expect(Date.now() - started).toBeLessThan(12000); + }); + + test('the reported elapsed is a clock, not the sum of the intervals', () => { + // With interval 0 the old arithmetic reported `0s after publish` no matter + // how long the poll took, because it only ever added INTERVAL_SECONDS. A + // 1.2s stub makes the two disagree by construction. + const { dir, log } = withStub(); + const result = runScript(withEnv(dir, log, { + STUB_SLEEP_SECONDS: '1.2', + STUB_LATEST: WANT, + READBACK_INTERVAL_SECONDS: '0', + READBACK_TIMEOUT_SECONDS: '30', + })); + + expect(result.status).toBe(0); + expect(attempts(log)).toBe(1); + expect(result.stdout).toMatch(/is live \(attempt 1, [1-9]\d*s after publish\)/); + }); + + test('exhaustion names what the registry serves and exits non-zero', () => { + const { dir, log } = withStub(); + const result = runScript(withEnv(dir, log, { + STUB_NEVER_PUBLISHED: '1', + STUB_LATEST: REGISTRY_SERVES, + READBACK_INTERVAL_SECONDS: '0', + READBACK_TIMEOUT_SECONDS: '0', + })); + + expect(result.status).toBe(1); + // The version that never appeared, the one the registry actually serves, + // and npm's own last error — the three facts the old message withheld. + expect(result.stdout).toContain(`::error::${NAME}@${WANT}`); + // The banner a human reads first: what follows it is the registry's + // actual state, and it is the line that turns a red run into a + // diagnosis instead of a mystery. + expect(result.stdout).toContain(`--- what the registry serves for ${NAME} ---`); + expect(result.stdout).toMatch(new RegExp(`dist-tags: .*${REGISTRY_SERVES}`)); + expect(result.stdout).toMatch(new RegExp(`latest: +${REGISTRY_SERVES}`)); + expect(result.stdout).toContain('E404'); + expect(attempts(log)).toBe(1); + }); + + test('a missing WANT is refused rather than polling for nothing', () => { + const { dir, log } = withStub(); + const bare = runScript(withEnv(dir, log, { WANT: '' })); + + expect(bare.status).not.toBe(0); + expect(`${bare.stdout}${bare.stderr}`).toMatch(/WANT is required/); + expect(fs.existsSync(`${log}.attempts`)).toBe(false); + }); + + test('the default budget is minutes, not the ~60s that produced the false negative', () => { + const source = fs.readFileSync(SCRIPT, 'utf8'); + const timeout = /READBACK_TIMEOUT_SECONDS:-(\d+)/.exec(source); + const interval = /READBACK_INTERVAL_SECONDS:-(\d+)/.exec(source); + + expect(timeout).not.toBeNull(); + expect(Number(timeout[1])).toBeGreaterThanOrEqual(300); + // A floor on the interval too: a tight loop spends the same budget + // hammering the registry's API, and npm rate-limits. + expect(interval).not.toBeNull(); + expect(Number(interval[1])).toBeGreaterThanOrEqual(5); + }); +}); + +describe('the workflow calls that script under the publish gate', () => { + const workflow = () => fs.readFileSync(WORKFLOW, 'utf8'); + + test('the read-back step runs the script, and still only after a publish', () => { + const body = workflow(); + const step = body.slice(body.indexOf(' - name: Read it back from the registry')); + + expect(step).toContain('scripts/verify-npm-publish-readback.sh'); + expect(step).toContain("if: steps.cmp.outputs.action == 'publish'"); + // The values the script polls for come from the compare step, not literals. + expect(step).toContain('NAME: ${{ steps.cmp.outputs.name }}'); + expect(step).toContain('WANT: ${{ steps.cmp.outputs.repo_v }}'); + // The interpreter is named: the file's exec bit does not survive every + // checkout or archive path, and a bare path would fail there. + expect(step).toMatch(/run: bash "\$GITHUB_WORKSPACE/); + }); + + test('the inline loop that gave up after ~60s is gone, not shadowed', () => { + const body = workflow(); + expect(body).not.toMatch(/for i in 1 2 3 4 5 6/); + expect(body).not.toMatch(/not visible on the registry after publish/); + // Exactly one read-back step: a second, older loop left behind would win + // or lose by ordering, and both outcomes are silent. + expect(body.match(/name: Read it back from the registry/g)).toHaveLength(1); + }); +}); diff --git a/scripts/verify-npm-publish-readback.sh b/scripts/verify-npm-publish-readback.sh new file mode 100755 index 000000000..2ca5c81eb --- /dev/null +++ b/scripts/verify-npm-publish-readback.sh @@ -0,0 +1,85 @@ +#!/usr/bin/env bash +# +# Poll the registry until it serves exactly the version this run just published. +# +# Earned 2026-09-23 (TASK-100). cli 0.1.65 (run 35498255344) and cli 0.1.66 (run +# 35804128707) both published FINE — `npm view version` moved, `npx +# @commonlyai/cli --version` returned the new version — and the workflow went red +# anyway, because the read-back gave up after ~60s. The registry's own docs put +# propagation at "a few minutes", so a fixed one-minute window turns a good +# publish into a red run. That is worse than a miss: a check that is red on a +# known-good outcome is the stale signal reviewers learn to ignore, and the next +# red — the one that means the publish never landed — gets read the same way. +# +# The cost of the wider window is paid only by the pushes that actually publish +# (most pushes are "registry already equal" and never reach here), so it is at +# most ~4 extra minutes on a release, and zero on everything else. +# +# On exhaustion this names what the registry DID serve (dist-tags and latest) +# alongside the version that never appeared. A read-back that can only report +# the value it was looking for cannot distinguish "propagation is still slow" +# from "the publish silently did not happen" or "the token has no read access" — +# the same false negative one layer down. +# +# Env: +# NAME package name, e.g. @commonlyai/cli (required) +# WANT the version just published (required) +# READBACK_TIMEOUT_SECONDS total wall-clock budget, default 300 +# READBACK_INTERVAL_SECONDS gap between polls, default 10 +# +# The budget is measured on a CLOCK, not by adding up the gaps. Summing the +# intervals made the budget depend on an env var the caller controls: at +# READBACK_INTERVAL_SECONDS=0 the loop could never reach the timeout (789 +# attempts in 8s, still reporting 0s, killed by an external alarm — Vera 71347), +# and at any interval it undercounted by every `npm view` round-trip, so the +# "after 300s" in the failure line was not what happened. Both matter here: this +# runs inside a release job, where a loop that cannot terminate is not a red step +# but a run held to the six-hour limit. +# +# Exits 0 once the registry serves NAME@WANT; 1 if the budget runs out. Never +# exits 0 on a value it did not read. + +set -euo pipefail + +: "${NAME:?NAME is required (package name, e.g. @commonlyai/cli)}" +: "${WANT:?WANT is required (the version just published)}" +TIMEOUT_SECONDS="${READBACK_TIMEOUT_SECONDS:-300}" +INTERVAL_SECONDS="${READBACK_INTERVAL_SECONDS:-10}" + +# `npm view` reads the package named on the command line, so this is +# cwd-independent on purpose: the publish job runs it with working-directory set +# to the package dir, and a test harness runs it from anywhere. +stderr_file=$(mktemp) +trap 'rm -f "$stderr_file"' EXIT + +started_at=$(date +%s) +attempt=0 +while :; do + attempt=$((attempt + 1)) + got=$(npm view "$NAME@$WANT" version 2>"$stderr_file" || true) + elapsed=$(( $(date +%s) - started_at )) + + if [ "$got" = "$WANT" ]; then + echo "✓ $NAME@$WANT is live (attempt $attempt, ${elapsed}s after publish)" + exit 0 + fi + + if [ "$elapsed" -ge "$TIMEOUT_SECONDS" ]; then + break + fi + + echo "· $NAME@$WANT not visible yet (attempt $attempt, ${elapsed}s; got '${got:-}') — retrying in ${INTERVAL_SECONDS}s" + sleep "$INTERVAL_SECONDS" +done + +echo "::error::$NAME@$WANT is not visible on the registry after ${TIMEOUT_SECONDS}s (${attempt} attempt(s)). The publish step reported success, so check what the registry is actually serving below before re-running." +echo "--- what the registry serves for $NAME ---" +echo "dist-tags: $(npm view "$NAME" dist-tags --json 2>&1 | tr -d '\n' || true)" +echo "latest: $(npm view "$NAME" version 2>&1 | tr -d '\n' || true)" +echo "--- last error from: npm view $NAME@$WANT version ---" +if [ -s "$stderr_file" ]; then + cat "$stderr_file" +else + echo "(npm view wrote nothing to stderr — read error, or an empty response)" +fi +exit 1