diff --git a/.github/workflows/publish.yml b/.github/workflows/publish.yml index 5a5a5b2bdc..af24a46e19 100644 --- a/.github/workflows/publish.yml +++ b/.github/workflows/publish.yml @@ -24,6 +24,10 @@ jobs: # bumps, and the fallback publish's own sibling wait (20 min) — this cap # covers that with headroom while still failing out of a registry outage # instead of holding the runner for hours. + # Empirical floors (WCI-1858/WCI-2113): healthy-day green 43 min (Nov 3), + # storm-recovery green 78 min (Oct 29) — 22 min under this cap. A cap-kill + # costs a full re-release (prepare-release recomputes +1 for every package + # each run, so there is no bitgo-only redo). Do not trim this number. timeout-minutes: 100 # Restricts @bitgo-beta/@bitgo-alpha publishing to protected branches via # a deployment branch policy on this environment, so the job cannot run @@ -99,6 +103,7 @@ jobs: run: git commit -am "Auto updated ${{ env.preid }} branch" --no-verify || echo "No changes to commit" - name: Lerna Publish (siblings) + id: lerna-siblings # The lerna exit code is not a reliable failure signal: a Rekor TLOG 409 is # usually a duplicate submission of provenance whose registry write already # completed, and npm can report failure for versions it then publishes fine. @@ -106,25 +111,74 @@ jobs: # endpoint and only republishes (bumping the version on staged conflicts) # for packages that genuinely never landed. Set RECOVERY_MODE=false in that # script's env to restore fail-fast behavior. + # The tee'd log records what lerna actually published so Verify Publish can + # skip its propagation wait for versions that never existed. GitHub's + # default run shell (bash -e) has NO pipefail — shell: bash opts into + # -eo pipefail so lerna's exit code survives the pipe and the step + # outcome stays failure under continue-on-error. continue-on-error: true - run: yarn lerna publish from-package --preid ${{ env.preid }} --dist-tag ${{ env.preid }} --force-publish --yes --loglevel silly + shell: bash + run: >- + yarn lerna publish from-package --preid ${{ env.preid }} --dist-tag ${{ env.preid }} + --force-publish --yes --loglevel silly 2>&1 | tee /tmp/lerna-siblings-publish.log env: NPM_CONFIG_PROVENANCE: true + - name: Warn on failed siblings publish + # outcome is the real result; conclusion is masked to success by + # continue-on-error, which is why the step badge cannot be trusted. + if: steps.lerna-siblings.outcome == 'failure' + run: >- + echo "::warning::Lerna siblings publish failed (continue-on-error). Verify Publish + will republish whatever is missing. See the Lerna Publish (siblings) step log for + the per-package errors." + - name: Lerna Publish (bitgo) + id: lerna-bitgo # Non-fatal for the same reason as the siblings step; a bitgo failure here # (e.g. its prepack sibling-visibility wait timing out) is retried by # Verify Publish with BITGO_GENERATE_SHRINKWRAP enabled. + # This step usually fails with EUNCOMMIT on storm days: an aborted siblings + # wave leaves its rewritten package.jsons uncommitted, and lerna refuses a + # dirty tree. That instant skip is DESIRABLE — fixing it would run a 20-min + # prepack against dependencies that are not on npm yet. Verify Publish's + # fallback publishes bitgo after the settle has republished its deps. On + # healthy days this step publishes bitgo itself, shrinkwrap included. continue-on-error: true + # shell: bash for -eo pipefail — see the siblings step: without it the + # tee'd pipeline masks lerna's failure (the green-badge trap). + shell: bash run: | bitgo_name=$(jq -r '.name' modules/bitgo/package.json) - yarn lerna publish from-package --include-private "$bitgo_name" --preid ${{ env.preid }} --dist-tag ${{ env.preid }} --force-publish --yes --loglevel silly + yarn lerna publish from-package --include-private "$bitgo_name" --preid ${{ env.preid }} --dist-tag ${{ env.preid }} --force-publish --yes --loglevel silly 2>&1 | tee /tmp/lerna-bitgo-publish.log env: NPM_CONFIG_PROVENANCE: true BITGO_GENERATE_SHRINKWRAP: true + - name: Warn on failed bitgo publish + if: steps.lerna-bitgo.outcome == 'failure' + run: >- + echo "::warning::Lerna bitgo publish failed (continue-on-error). Verify Publish + will publish bitgo via its fallback path after the settle pass." + - name: Verify Publish run: npx tsx ./scripts/verify-release.ts ${{ env.preid }} env: NPM_CONFIG_PROVENANCE: true RECOVERY_MODE: true + LERNA_SIBLINGS_PUBLISH_LOG: /tmp/lerna-siblings-publish.log + LERNA_BITGO_PUBLISH_LOG: /tmp/lerna-bitgo-publish.log + + - name: Upload lerna publish logs on failure + # The tee'd logs are the ground truth for what lerna actually published + # (Verify parses them); the step log is the only other copy and is + # painful to grep at --loglevel silly volumes. Runs after Verify so it + # also captures the case where only Verify Publish failed. + if: failure() + uses: actions/upload-artifact@v7 + with: + name: lerna-publish-logs + path: | + /tmp/lerna-siblings-publish.log + /tmp/lerna-bitgo-publish.log + retention-days: 7 diff --git a/scripts/tests/verify-release.test.ts b/scripts/tests/verify-release.test.ts index 49e9442b1b..ca7b119da3 100644 --- a/scripts/tests/verify-release.test.ts +++ b/scripts/tests/verify-release.test.ts @@ -10,10 +10,14 @@ import { type WorkspaceModule, isRecoverablePublishConflict, getDistTagsWithRetry, + parseLernaPublishedPackages, + parseLernaAttemptedPackages, publishWithRecovery, propagateVersionToDependents, + readLernaPublishSets, readPackageJson, settleInDependencyOrder, + shouldShortPollConflict, topoOrder, verifyPackage, } from '../../scripts/verify-release'; @@ -185,6 +189,150 @@ describe('waitForPackageVersions', function () { }); }); +describe('parseLernaPublishedPackages', function () { + it('extracts scoped and unscoped names from lerna step logs', function () { + const log = [ + 'lerna sill argv { ... }', + 'lerna notice \u{1f4e6} @bitgo-beta/blake2b-wasm@3.0.4-beta.2426', + '2026-11-03T09:01:38Z lerna success published @bitgo-beta/bitgo 14.2.1-beta.2223', + 'lerna success published @bitgo-beta/statics 15.1.1-beta.2193', + 'lerna success published bitgo 54.3.0', + 'lerna success published 24 packages', + 'lerna success published 1 package', + 'lerna WARN Unable to determine published version, assuming "@bitgo-beta/sdk-test" unpublished.', + ].join('\n'); + const names = parseLernaPublishedPackages(log); + assert.deepEqual([...names].sort(), ['@bitgo-beta/bitgo', '@bitgo-beta/statics', 'bitgo']); + }); + + it('returns an empty set when nothing was published', function () { + assert.equal(parseLernaPublishedPackages('lerna ERR! EUNCOMMIT ...').size, 0); + }); + + it('parseLernaAttemptedPackages dedupes retries and tolerates unscoped names', function () { + const log = [ + 'lerna verb publish @bitgo-beta/a', + 'lerna verb publish @bitgo-beta/a', // retry duplicates dedupe + 'lerna verb publish bitgo', + 'lerna verb packed modules/argon2', // packing noise: different verb, must not match + 'lerna success published @bitgo-beta/a 1.0.0', + ].join('\n'); + const attempted = parseLernaAttemptedPackages(log); + assert.deepEqual([...attempted].sort(), ['@bitgo-beta/a', 'bitgo']); + }); +}); + +describe('readLernaPublishSets', function () { + it('unions both lerna step logs into published and attempted sets', function () { + const siblings = makePackageDir({ name: 'x', version: '1.0.0' }); + const bitgo = makePackageDir({ name: 'x', version: '1.0.0' }); + fs.writeFileSync( + path.join(siblings.dir, 'siblings.log'), + [ + 'lerna verb publish @bitgo-beta/a', + 'lerna success published @bitgo-beta/a 1.0.0', + 'lerna verb publish @bitgo-beta/b', + 'lerna verb publish @bitgo-beta/b', // retry: duplicate attempt lines dedupe + 'lerna ERR! TLOG_CREATE_ENTRY_ERROR error creating tlog entry', + 'lerna success published @bitgo-beta/b 1.0.0', + 'lerna verb publish @bitgo-beta/c', + 'lerna ERR! TLOG_CREATE_ENTRY_ERROR error creating tlog entry', + ].join('\n') + '\n' + ); + fs.writeFileSync(path.join(bitgo.dir, 'bitgo.log'), 'lerna success published @bitgo-beta/bitgo 1.0.0\n'); + const log = readLernaPublishSets({ + LERNA_SIBLINGS_PUBLISH_LOG: path.join(siblings.dir, 'siblings.log'), + LERNA_BITGO_PUBLISH_LOG: path.join(bitgo.dir, 'bitgo.log'), + }); + assert.ok(log); + // attempted covers errored-but-dispatched packages: a TLOG 409 usually + // means the registry write completed, so the wait must cover package c + assert.deepEqual([...log.attempted].sort(), [ + '@bitgo-beta/a', + '@bitgo-beta/b', + '@bitgo-beta/bitgo', + '@bitgo-beta/c', + ]); + assert.deepEqual([...log.published].sort(), ['@bitgo-beta/a', '@bitgo-beta/b', '@bitgo-beta/bitgo']); + }); + + it('fails open to undefined when no logs are readable', function () { + assert.equal(readLernaPublishSets({}), undefined); + assert.equal(readLernaPublishSets({ LERNA_SIBLINGS_PUBLISH_LOG: '/nonexistent/log.txt' }), undefined); + }); + + it('fails open to undefined when one configured log is unreadable, even if the other reads', function () { + // regression: a partial read used to return just the readable log's names, + // shrinking the wait list to those packages and skipping the wait for + // every sibling that the missing log carried + const pkg = makePackageDir({ name: 'x', version: '1.0.0' }); + fs.writeFileSync(path.join(pkg.dir, 'bitgo.log'), 'lerna verb publish @bitgo-beta/bitgo\n'); + assert.equal( + readLernaPublishSets({ + LERNA_SIBLINGS_PUBLISH_LOG: '/nonexistent/siblings.log', + LERNA_BITGO_PUBLISH_LOG: path.join(pkg.dir, 'bitgo.log'), + }), + undefined + ); + }); + + it('warns when published names lack verb-publish lines (grammar drift), but still waits for them', function () { + const pkg = makePackageDir({ name: 'x', version: '1.0.0' }); + fs.writeFileSync( + path.join(pkg.dir, 'drifted.log'), + 'lerna success published @bitgo-beta/a 1.0.0\nlerna success published @bitgo-beta/b 1.0.0\n' + ); + const log = readLernaPublishSets({ LERNA_SIBLINGS_PUBLISH_LOG: path.join(pkg.dir, 'drifted.log') }); + assert.ok(log); + // the superset guarantee keeps the published names on the wait list even + // when the verb grammar drifted + assert.deepEqual([...log.attempted].sort(), ['@bitgo-beta/a', '@bitgo-beta/b']); + assert.deepEqual([...log.published].sort(), ['@bitgo-beta/a', '@bitgo-beta/b']); + }); + + it('fails open to undefined when readable logs contain no recognized lines (format drift)', function () { + const pkg = makePackageDir({ name: 'x', version: '1.0.0' }); + fs.writeFileSync(path.join(pkg.dir, 'empty.log'), 'lerna ERR! EUNCOMMIT ...\n'); + assert.equal(readLernaPublishSets({ LERNA_SIBLINGS_PUBLISH_LOG: path.join(pkg.dir, 'empty.log') }), undefined); + }); + + it('keeps a zero-publish, all-errored storm on the attempted wait list', function () { + const pkg = makePackageDir({ name: 'x', version: '1.0.0' }); + fs.writeFileSync( + path.join(pkg.dir, 'storm.log'), + [ + 'lerna verb publish @bitgo-beta/a', + 'lerna ERR! TLOG_CREATE_ENTRY_ERROR error creating tlog entry', + 'lerna verb publish @bitgo-beta/b', + 'lerna ERR! TLOG_CREATE_ENTRY_ERROR error creating tlog entry', + ].join('\n') + '\n' + ); + const log = readLernaPublishSets({ LERNA_SIBLINGS_PUBLISH_LOG: path.join(pkg.dir, 'storm.log') }); + assert.ok(log); + assert.equal(log.published.size, 0); + assert.deepEqual([...log.attempted].sort(), ['@bitgo-beta/a', '@bitgo-beta/b']); + }); +}); + +describe('shouldShortPollConflict', function () { + it('triggers when most of the wait list stayed invisible', function () { + assert.equal(shouldShortPollConflict(104, 114, 114, 114), true); + }); + + it('triggers when lerna published less than half the tree', function () { + assert.equal(shouldShortPollConflict(0, 10, 10, 114), true); + }); + + it('does not trigger on healthy days', function () { + assert.equal(shouldShortPollConflict(1, 114, 114, 114), false); + assert.equal(shouldShortPollConflict(0, 114, 114, 114), false); + }); + + it('does not trigger when the published set is unknown', function () { + assert.equal(shouldShortPollConflict(2, 10, undefined, 114), false); + }); +}); + describe('getDistTagsWithRetry', function () { it('retries with backoff and succeeds once the read recovers', async function () { const sleeps: number[] = []; @@ -633,6 +781,43 @@ describe('verifyPackage', function () { assert.equal(pkg.read().version, '1.0.0-beta.2'); }); + it('caps the conflict poll when conflictPollTimeoutMs is set (mass-stall path)', async function () { + const pkg = makeTarget('1.0.0-beta.1'); + const clock = fakeClock(); + const tlogConflict = new Error( + 'npm error TLOG_CREATE_ENTRY_ERROR (409) an equivalent entry already exists' + ) as Error & { stdout?: string }; + tlogConflict.stdout = tlogConflict.message; + let publishCalls = 0; + let versionChecks = 0; + const { lines, result } = await captureConsoleLog(() => + verifyPackage(pkg.dir, 'beta', false, { + conflictPollTimeoutMs: 60_000, + sleep: clock.sleep, + now: clock.now, + versionExists: async () => { + versionChecks += 1; + return false; + }, + fetchDistTags: async () => ({ beta: '0.9.9-beta.1' }), + runPublish: async () => { + publishCalls += 1; + if (publishCalls === 1) { + throw tlogConflict; + } + return 'published'; + }, + }) + ); + assert.equal(result, true); + assert.equal(publishCalls, 2); + // 1 visibility check + 3 poll checks (60s budget / 30s delay); the default + // 5-minute budget would poll 10 times — this asserts the cap is threaded + // through verifyPackage into publishWithRecovery + assert.equal(versionChecks, 4); + assert.ok(lines.includes('@bitgo-beta/sdk-verify-target matches expected version 1.0.0-beta.2')); + }); + it('publishes a missing package with a diagnostic', async function () { const pkg = makeTarget('1.0.0-beta.1'); let publishCalls = 0; diff --git a/scripts/verify-release.ts b/scripts/verify-release.ts index 5227bd52d1..0345f06e84 100644 --- a/scripts/verify-release.ts +++ b/scripts/verify-release.ts @@ -60,6 +60,121 @@ function isUnpublishedModule(module: { dir: string; json: PackageJson }): boolea let lernaModuleLocations: string[] = []; +// Steps in publish.yml tee their lerna output here; Verify's propagation wait +// trusts this list (fail-open: unreadable or empty logs revert to waiting for +// every package, so the list is an optimization, never a correctness dependency). +const publishedLogEnvVars = ['LERNA_SIBLINGS_PUBLISH_LOG', 'LERNA_BITGO_PUBLISH_LOG']; + +export interface LernaPublishLog { + /** Packages lerna confirmed published (`lerna success published `). */ + published: Set; + /** + * Packages lerna dispatched a publish for (`lerna verb publish `), + * published or errored. A TLOG-409-errored package usually landed on npm anyway + * (the error is a duplicate-provenance false negative), so the propagation + * wait must cover it — otherwise the settle republishes it, hits a conflict, + * and burns a needless version bump plus dependent-bump cascades. + */ + attempted: Set; +} + +/** Extracts the package names lerna actually published from its step log. */ +export function parseLernaPublishedPackages(logText: string): Set { + // Require a version (digit-led) after the name: lerna also logs a count + // summary — `lerna success published 24 packages` — whose bare number must + // not land in the set (it would inflate the size used by + // shouldShortPollConflict's aborted-wave threshold), and \S+ (not + // @-anchored) so unscoped names would match too. + return new Set([...logText.matchAll(/lerna success published (\S+) \d+\./g)].map((m) => m[1])); +} + +/** Extracts every package lerna dispatched a publish for, successful or not. */ +export function parseLernaAttemptedPackages(logText: string): Set { + // `lerna verb publish ` fires per attempt (retries log it again), so + // the Set dedupes; a stray non-package token is harmless — it can never + // match a candidate name. + return new Set([...logText.matchAll(/lerna verb publish (\S+)/g)].map((m) => m[1])); +} + +/** + * Parses both lerna publish logs. Returns undefined when the result cannot be + * trusted — callers must then fall back to waiting for every package + * (fail-open): no log was readable, or a readable log yielded no recognized + * lines at all, which means lerna's output format drifted and every set built + * from it would be wrong. + */ +export function readLernaPublishSets(env: NodeJS.ProcessEnv = process.env): LernaPublishLog | undefined { + const result: LernaPublishLog = { published: new Set(), attempted: new Set() }; + let failedAnyRead = false; + let readAnyLog = false; + for (const envVar of publishedLogEnvVars) { + const logPath = env[envVar]; + if (!logPath) continue; + try { + const logText = readFileSync(logPath, 'utf-8'); + readAnyLog = true; + const logPublished = parseLernaPublishedPackages(logText); + const logAttempted = parseLernaAttemptedPackages(logText); + if ([...logPublished].some((name) => !logAttempted.has(name))) { + // Success lines without matching verb lines mean the `lerna verb publish` + // grammar drifted: attempted would silently shrink to published, + // bringing back the needless-bump behavior without tripping the + // zero-lines drift check. + console.warn( + `Lerna log ${logPath}: published packages without a \`lerna verb publish\` line — output-format drift?` + ); + } + for (const name of logPublished) result.published.add(name); + for (const name of logAttempted) result.attempted.add(name); + } catch (e) { + failedAnyRead = true; + console.warn(`Could not read ${envVar} (${logPath})`, e); + } + } + // A partial read must never shrink the wait list: one unreadable log would + // drop every package it carried from the wait — the exact needless-bump + // failure this change exists to prevent. Fail open whenever any configured + // log is unreadable. + if (failedAnyRead) { + console.warn('Failing open to the full propagation wait: not every configured lerna log was readable.'); + return undefined; + } + if (!readAnyLog) return undefined; + // attempted must be a superset of published: a package with a success line + // but no verb line (partial log, output-format variance) must still get the + // propagation wait — never skipping the wait for something that landed. + for (const name of result.published) { + result.attempted.add(name); + } + if (result.published.size === 0 && result.attempted.size === 0) { + console.warn( + 'Lerna publish logs were readable but contained no recognized publish or attempt lines — ' + + 'possible lerna output-format drift; failing open to the full propagation wait.' + ); + return undefined; + } + return result; +} + +/** + * Decides whether per-package conflict polls should be capped short during the + * settle pass. Both signals mean the registry is degraded: most of the wait + * list never became visible, or lerna's wave aborted before attempting half the + * tree (so the settle will republish most packages and any conflicts must not + * each burn the full poll budget). + */ +export function shouldShortPollConflict( + stillMissingCount: number, + waitListCount: number, + lernaReachedCount: number | undefined, + candidateCount: number +): boolean { + if (waitListCount > 0 && stillMissingCount > waitListCount / 2) { + return true; + } + return lernaReachedCount !== undefined && candidateCount > 0 && lernaReachedCount < candidateCount / 2; +} + // Bump-on-conflict is the default posture: a Rekor/staged conflict does not mean // the registry write failed, and dist-tags lag minutes behind completed writes. // Set RECOVERY_MODE=false to restore fail-fast behavior. @@ -69,6 +184,16 @@ const MAX_RECOVERY_ATTEMPTS = 5; // on npm before bumping it — the write usually completed despite the client error. const CONFLICT_POLL_TIMEOUT_MS = 5 * 60_000; const VERSION_POLL_DELAY_MS = 30_000; +// On mass-stall days (most of the tree invisible, or lerna's wave aborted early) +// the settle republishes most packages; a full 5-minute poll per conflict would +// blow the job cap, so polls are capped to a ~30s budget (at most two checks +// at the 30s delay) on those days. +// The cap applies to every package for the whole settle pass (it is computed +// once, before the settle starts): a package whose write genuinely completed +// but is still propagating gets ~2 checks and then a version bump. That bump +// is the accepted cost on degraded-registry days — bounded beats packages × 5 +// minutes against the job cap, and beta version numbers are cheap. +const MASS_STALL_CONFLICT_POLL_TIMEOUT_MS = 30_000; async function getLernaModuleLocations(): Promise { const modules = await getLernaModules(); @@ -216,6 +341,12 @@ export interface VerifyPackageOptions { versionExists?: PackageVersionExists; fetchDistTags?: (name: string) => Promise>; runPublish?: (cwd: string, preid: string) => Promise; + /** Injectable for tests. */ + sleep?: (delayMs: number) => Promise; + /** Injectable for tests. */ + now?: () => number; + /** Caps publishWithRecovery's per-package conflict poll; used by the settle pass on mass-stall days. */ + conflictPollTimeoutMs?: number; } // Verifies one package against registry truth and, when needed, (re)publishes @@ -247,7 +378,13 @@ export async function verifyPackage( }; const attemptPublish = async (): Promise => { try { - const { stdout, exitCode } = await publishWithRecovery(cwd, json, preid, { runPublish }); + const { stdout, exitCode } = await publishWithRecovery(cwd, json, preid, { + runPublish, + versionExists, + sleep: options.sleep, + now: options.now, + conflictPollTimeoutMs: options.conflictPollTimeoutMs, + }); console.log(stdout); if (exitCode !== 0) { return false; @@ -478,9 +615,28 @@ export async function settleInDependencyOrder( async function verify(preid?: string) { await getLernaModuleLocations(); const modules: WorkspaceModule[] = lernaModuleLocations.map((dir) => ({ dir, json: readPackageJson(dir) })); - const expected = modules - .filter((m) => !isUnpublishedModule(m)) - .map((m) => ({ name: m.json.name, version: m.json.version })); + const candidates = modules.filter((m) => !isUnpublishedModule(m)); + + // Wait only for packages lerna reached (published or errored). Packages a + // storm-aborted wave never dispatched cannot be on npm, so waiting for them + // is pure loss — the settle pass below republishes them immediately instead. + // Errored packages ARE waited for: a TLOG 409 usually means the registry + // write completed anyway, and without the wait the settle would bump them + // (and their dependents) needlessly. The reverse cost is accepted: when the + // errored writes genuinely never landed (Oct 29's storm profile), the wait + // runs its full budget on their names instead of resolving early. Fail-open: + // without a readable publish log the wait covers every package (the log is + // an optimization, never a correctness dependency). + const lernaLog = readLernaPublishSets(); + const waitList = lernaLog ? candidates.filter((m) => lernaLog.attempted.has(m.json.name)) : candidates; + if (lernaLog && waitList.length < candidates.length) { + console.log( + `Lerna reached ${waitList.length} of ${candidates.length} packages ` + + `(${lernaLog.published.size} published); skipping the propagation wait for the other ` + + `${candidates.length - waitList.length} never dispatched (the settle pass republishes them).` + ); + } + const expected = waitList.map((m) => ({ name: m.json.name, version: m.json.version })); // One bounded wait for the whole release: a successful publish can stay // invisible on npm for minutes (occasionally much longer when npm stages a @@ -493,8 +649,19 @@ async function verify(preid?: string) { 'attempting recovery publish for those below.' ); } + // Mass-stall days (most of the wait list invisible, or lerna's wave aborted + // early) mean the settle will republish most packages; cap the per-package + // conflict poll so a degraded registry cannot turn it into (packages × 5 min). + const conflictPollTimeoutMs = shouldShortPollConflict( + stillMissing.length, + expected.length, + lernaLog?.attempted.size, + candidates.length + ) + ? MASS_STALL_CONFLICT_POLL_TIMEOUT_MS + : undefined; const anyFailed = await settleInDependencyOrder(modules, preid ?? 'beta', { - verifyPackage: (dir, preidArg, pinsDirty) => verifyPackage(dir, preidArg, pinsDirty), + verifyPackage: (dir, preidArg, pinsDirty) => verifyPackage(dir, preidArg, pinsDirty, { conflictPollTimeoutMs }), failFast: !RECOVERY_MODE, }); if (anyFailed) {