diff --git a/.github/workflows/rerun-safety-nightly.yml b/.github/workflows/rerun-safety-nightly.yml index 52b7af9ab3d..e8c49d88481 100644 --- a/.github/workflows/rerun-safety-nightly.yml +++ b/.github/workflows/rerun-safety-nightly.yml @@ -46,6 +46,17 @@ # Turbo would replay cached results on the second pass and report green without # executing anything, which is precisely the wrong answer here. `--force` # bypasses the cache so the second pass genuinely re-runs. +# +# ## Why `--only` (#23880) +# +# `--force` applies to every task in the run, and `test` depends on `^build`, so +# each pass also re-executed the whole build closure -- 69 `build` tasks and +# `@objectstack/spec#gen:migration-registry` (`turbo run test --dry=json` at +# 98ba1bf1d2) -- that `Build packages` had just built. `--only` runs the 83 `test` +# tasks and nothing they depend on; all 69 of those builds are in `pnpm build`'s +# own plan, and the spec's `test` script regenerates its migration registry +# itself. It also stops pass 2 from rebuilding `dist/` over whatever pass 1 left +# there, which is a working-tree state this job exists to see, not to repair. name: Rerun Safety on: @@ -77,8 +88,36 @@ jobs: # in 15 minutes and never at this number. Raising it can therefore hide no # hang; all it stops is a slow-but-live run being reported as a failure of # the thing under test. + # + # ⚠️ 170 no longer holds two full passes, and raising it again is not the + # fix (#23880). Measured from the job's own step timestamps: pass 1 took 38 + # minutes on 2026-09-26 (the last green night), 66 on 10-02, and 97-113 on + # every night from 10-12 to 10-16, while the queue-tier suite's measured + # task time (scripts/test-shard-timings.json) grew from 124 to 194 minutes + # between the 09-28 and 10-13 refreshes, the CLI's alone from 733 to 2206 + # seconds. Not a hang: on 10-16 pass 2 was still printing when the job + # timeout cancelled it 67 minutes in. A night finished at all only because + # pass 2 stopped at its first failure; one that did not fail was CANCELLED, + # with no verdict and a conclusion the red-card filer does not read. + # + # So each pass now runs under the time the job has LEFT (JOB_TIMEOUT_MINUTES + # below, which must equal this number, minus PASS_RESERVE_MINUTES for the + # verdict), and a pass that runs out is stopped by `timeout` instead: the + # verdict step still runs, reads the pass's 124/137 exit (or a log with no + # turbo summary) as INCOMPLETE -- NOT MEASURED, and the job concludes + # `failure`, never a silent `cancelled`. That bound decides only WHO reports + # a slow night; how two full passes fit again is a capacity decision + # recorded on #23880. timeout-minutes: 170 + env: + JOB_TIMEOUT_MINUTES: 170 + # The verdict and the steps after it take seconds; the reserve also covers + # `timeout --kill-after=2m`, the grace a pass gets between SIGTERM and SIGKILL. + PASS_RESERVE_MINUTES: 5 steps: + - name: Record the job's deadline + run: echo "JOB_DEADLINE_EPOCH=$(( $(date +%s) + JOB_TIMEOUT_MINUTES * 60 ))" >> "$GITHUB_ENV" + - name: Checkout repository uses: actions/checkout@v7 @@ -142,6 +181,17 @@ jobs: # comment in ci.yml): grouped log order flushes a task's output only when # the task ends, so a solo tail task longer than the budget reads as # frozen while healthy. The guard refuses a turbo run without it. + # + # The time bound (#23880) sits INSIDE the guard, as the command it wraps: + # the guard runs that command in its own process group, so `timeout` is + # that group's leader and its SIGTERM reaches turbo, which stops its tasks. + # Measured locally at 98ba1bf1d2 (guard -> timeout 45s -> turbo over core, + # types and formula): exit 124 came back through the guard, and the log + # ended at "Shutting down Turborepo tasks..." / "Force killed Turborepo + # tasks: @objectstack/core#test" with no `Tasks:` summary. The verdict reads + # 124 (or 137, after --kill-after) as a pass that did not finish. Wrapped + # the other way round, `timeout` would kill only the guard and leave its + # detached group running into the next step. - name: Test suite — pass 1 run: | # Bound vitest's INNER worker pool (#11958). A no-op on a runner with @@ -151,11 +201,23 @@ jobs: # vitest's own "use the default" signal. Needs turbo.json's # globalPassThroughEnv entry or turbo strips it — see the script header. export VITEST_MAX_WORKERS="$(node scripts/vitest-worker-cap.mjs)" + budget=$(( (JOB_DEADLINE_EPOCH - $(date +%s)) / 60 - PASS_RESERVE_MINUTES )) + echo "Pass 1 may run ${budget} minutes before the job's own timeout would end it." status=0 - node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass1.log" --stall-minutes 15 -- \ - pnpm turbo run test --concurrency=4 --force --log-order=stream || status=$? + if [ "$budget" -lt 1 ]; then + : > "$RUNNER_TEMP/rerun-pass1.log" + status=124 + else + node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass1.log" --stall-minutes 15 -- \ + timeout --kill-after=2m "${budget}m" \ + pnpm turbo run test --only --concurrency=4 --force --log-order=stream || status=$? + fi echo "PASS1_EXIT=$status" >> "$GITHUB_ENV" - if [ "$status" -ne 0 ]; then + if [ "$status" -eq 124 ] || [ "$status" -eq 137 ]; then + echo "::warning::Pass 1 ran out of the job's time (exit $status) before it finished." + echo "::warning::That is a capacity reading, not a suite reading; the verdict step" + echo "::warning::reports it as INCOMPLETE and will fail this job." + elif [ "$status" -ne 0 ]; then echo "::warning::Pass 1 exited $status — the suite is red on main. Recorded as the" echo "::warning::BASELINE and NOT failed here: pass 2 runs anyway so the rerun" echo "::warning::property still gets measured tonight. The verdict step owns the" @@ -197,9 +259,18 @@ jobs: # vitest's own "use the default" signal. Needs turbo.json's # globalPassThroughEnv entry or turbo strips it — see the script header. export VITEST_MAX_WORKERS="$(node scripts/vitest-worker-cap.mjs)" + # Whatever pass 1 left of the job's time; see pass 1 for the bound. + budget=$(( (JOB_DEADLINE_EPOCH - $(date +%s)) / 60 - PASS_RESERVE_MINUTES )) + echo "Pass 2 may run ${budget} minutes before the job's own timeout would end it." status=0 - node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass2.log" --stall-minutes 15 -- \ - pnpm turbo run test --concurrency=4 --force --log-order=stream || status=$? + if [ "$budget" -lt 1 ]; then + : > "$RUNNER_TEMP/rerun-pass2.log" + status=124 + else + node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass2.log" --stall-minutes 15 -- \ + timeout --kill-after=2m "${budget}m" \ + pnpm turbo run test --only --concurrency=4 --force --log-order=stream || status=$? + fi echo "PASS2_EXIT=$status" >> "$GITHUB_ENV" # ⭐ THE VERDICT, and the job's exit status (#18590). diff --git a/.github/workflows/scheduled-full-run-card.yml b/.github/workflows/scheduled-full-run-card.yml index 1e3b9bfac60..6f3461efbeb 100644 --- a/.github/workflows/scheduled-full-run-card.yml +++ b/.github/workflows/scheduled-full-run-card.yml @@ -72,7 +72,14 @@ on: workflow_run: # Byte-exact workflow NAMES (the `name:` at the top of each file), not # paths. Quoted because `Lint & Type Check` starts a YAML alias unquoted. - workflows: ['CI', 'Lint & Type Check'] + # + # `Rerun Safety` (rerun-safety-nightly.yml, #23880) runs once a night, and + # its scheduled runs from 2026-09-17 to 10-16 concluded `success` once in + # thirty nights with no filer at all. It gets its own card by the same + # identity rule, in its own cadence's words: every name listed here must + # have an entry in `CARD_CADENCES` (scripts/ci/scheduled-full-run.mjs), + # which refuses a name it does not hold rather than default one. + workflows: ['CI', 'Lint & Type Check', 'Rerun Safety'] types: [completed] permissions: {} diff --git a/scripts/ci/scheduled-full-run.mjs b/scripts/ci/scheduled-full-run.mjs index 5638b8c52ae..c33af68bc2e 100644 --- a/scripts/ci/scheduled-full-run.mjs +++ b/scripts/ci/scheduled-full-run.mjs @@ -211,8 +211,50 @@ export function concurrencyVerdict(groupExpression, { workflow = 'W' } = {}) { // ⛔ The marker is PLAIN TEXT, never an HTML comment. This platform's body // sanitizer is measured to eat short angle-bracket fragments, and a de-dup key // that can be swallowed files a duplicate an hour. -const MARKER_PREFIX = 'os-hourly-full-run'; -const TITLE_PREFIX = 'hourly full run: red on main'; +// +// Both prefixes carry the watched workflow's CADENCE (#23880): the card for a +// nightly workflow must not call itself hourly. For an hourly workflow they +// spell exactly what they always did -- `hourly full run: red on main` and +// `os-hourly-full-run` -- so an open card filed before the cadence existed is +// still found by its title and by its marker, and refreshed, never duplicated. +const markerPrefix = (cadence) => `os-${cadence}-full-run`; +const titlePrefix = (cadence) => `${cadence} full run: red on main`; + +// THE CADENCE OF EACH WATCHED WORKFLOW, by its byte-exact `name:` -- the same +// spelling `scheduled-full-run-card.yml` lists in `workflow_run.workflows`. +// CLOSED on purpose: a workflow missing here is REFUSED by `cardIdentity`, +// never defaulted, because a defaulted cadence prints the wrong one on the card +// and the card is the only reader of that run. Adding a workflow to the card's +// watched list therefore means adding its cadence here in the same change. +export const CARD_CADENCES = Object.freeze({ + CI: 'hourly', + 'Lint & Type Check': 'hourly', + 'Rerun Safety': 'nightly', +}); + +// The words each cadence puts in the body. The `hourly` entry is the text the +// body has always carried, byte for byte. +const CADENCE_WORDS = Object.freeze({ + hourly: Object.freeze({ + every: 'every hour', + previous: 'an hour ago', + about: (name) => [ + `\`${name}\` runs the FULL battery on \`main\` every hour (#16467). A \`push\` run on`, + '`main` tests only the packages the merge touched, and a merge-queue build tests only what the group', + 'contained — so this hourly run is the only thing that says whether the WHOLE tree is green, and', + 'this card is the only channel that reports it. Nothing is blocked by it.', + ], + }), + nightly: Object.freeze({ + every: 'every night', + previous: 'the night before', + about: (name) => [ + `\`${name}\` runs on \`main\` once a night, and no pull request, merge-queue build or other`, + 'scheduled run takes its measurement -- so this nightly run is the only thing that reports it, and', + 'this card is the only channel that carries it. Nothing is blocked by it.', + ], + }), +}); // ONE CARD PER WORKFLOW, not one card for both, and that is a decision rather // than an oversight. `CI` and `Lint & Type Check` are two different batteries @@ -229,10 +271,19 @@ export function cardIdentity(workflowName) { .replace(/[^a-z0-9]+/g, '-') .replace(/^-+|-+$/g, ''); if (slug === '') throw new Error(`cardIdentity: '${name}' slugs to nothing, so it cannot be an identity`); + if (!Object.hasOwn(CARD_CADENCES, name)) { + throw new Error( + `cardIdentity: '${name}' has no cadence in CARD_CADENCES (${Object.keys(CARD_CADENCES).join(', ')}). ` + + 'Add it there in the same change that makes scheduled-full-run-card.yml watch it -- a defaulted ' + + 'cadence would print the wrong one on the only card that reports this run.' + ); + } + const cadence = CARD_CADENCES[name]; return { workflowName: name, - title: `${TITLE_PREFIX} (${name})`, - marker: `${MARKER_PREFIX}-${slug}`, + cadence, + title: `${titlePrefix(cadence)} (${name})`, + marker: `${markerPrefix(cadence)}-${slug}`, labels: ['bug', 'domain:devx', 'priority:p1'], }; } @@ -298,8 +349,9 @@ export async function fileOrRefreshCard({ identity, body, listPage, createIssue, } // The card body. The run link and the commit range are the whole product: a red -// hourly run says "main broke somewhere in the last hour", and the commits -// between the previous GREEN scheduled run and this one are that hour. +// scheduled run says "main broke somewhere since the last green one" -- the last +// hour for an hourly workflow, the last night for a nightly one -- and the +// commits between the previous GREEN scheduled run and this one are that span. export function renderBody({ identity, runUrl, @@ -316,6 +368,13 @@ export function renderBody({ // opposite directions. rangeNote = null, }) { + // The cadence's words. `cardIdentity` refuses a workflow with no cadence; an + // identity built by hand without one is refused here for the same reason. + const words = CADENCE_WORDS[identity?.cadence]; + if (!words) { + throw new Error(`renderBody: the identity carries no known cadence ('${identity?.cadence}') -- build it with cardIdentity`); + } + const heading = `## What landed since the last green ${identity.cadence} run`; const range = previousGreen ? `\`${String(previousGreen.head_sha).slice(0, 10)}\` (run ${previousGreen.run_id}, the last green ` + `\`${identity.workflowName}\` schedule run) .. \`${String(headSha).slice(0, 10)}\`` @@ -324,7 +383,7 @@ export function renderBody({ const suspects = previousGreen ? commits.length > 0 ? [ - `## What landed since the last green hourly run`, + heading, '', `Range: ${range}${compareUrl ? ` — [compare](${compareUrl})` : ''}`, commitsTruncated @@ -335,17 +394,17 @@ export function renderBody({ '', ] : [ - `## What landed since the last green hourly run`, + heading, '', `Range: ${range}`, '', - '⚠️ Nothing landed in that range. The same tree was green an hour ago and is red now, so', + `⚠️ Nothing landed in that range. The same tree was green ${words.previous} and is red now, so`, 'this is a FLAKE, an infrastructure fault, or a suite that depends on wall-clock time or on', 'something outside the repository. ⛔ Do not go looking for the commit that broke it.', '', ] : [ - `## What landed since the last green hourly run`, + heading, '', '⚠️ No commit range could be named for this red run.', rangeNote ?? '', @@ -356,19 +415,16 @@ export function renderBody({ return [ `${identity.marker} — machine-findable marker for this generated card. ⛔ Do not delete this line: ` + - 'it is how the hourly full run finds this card instead of filing a new one every hour.', + `it is how the ${identity.cadence} full run finds this card instead of filing a new one ${words.every}.`, '', `# ${identity.title}`, '', `_Swept ${sweptAt} · [run log](${runUrl}) · commit \`${headSha}\` · conclusion \`${conclusion}\`._`, '', - `\`${identity.workflowName}\` runs the FULL battery on \`main\` every hour (#16467). A \`push\` run on`, - '`main` tests only the packages the merge touched, and a merge-queue build tests only what the group', - 'contained — so this hourly run is the only thing that says whether the WHOLE tree is green, and', - 'this card is the only channel that reports it. Nothing is blocked by it.', + ...words.about(identity.workflowName), '', - '⛔ The remedy is never to narrow, skip or delete the failing check to make the hourly run green.', - 'Fix what it names and let the next hourly run refresh this card; a card nobody reopens is closed by', + `⛔ The remedy is never to narrow, skip or delete the failing check to make the ${identity.cadence} run green.`, + `Fix what it names and let the next ${identity.cadence} run refresh this card; a card nobody reopens is closed by`, 'the next green run being uneventful, not by editing this one.', '', ...suspects, @@ -632,7 +688,7 @@ async function releaseGate(argv) { // remedy is to find what stopped registering, never to lower the number. const SELF_TEST_BATTERIES = Object.freeze({ 'scheduled-full-run concurrency isolation': 20, - 'scheduled-full-run card identity and de-dup': 23, + 'scheduled-full-run card identity and de-dup': 34, 'release gate: the selection rule on the recorded 2026-10-12 listing': 8, 'release gate: the selection rule on synthetic runs': 17, 'release gate: release.yml wiring': 6, @@ -899,6 +955,94 @@ async function selfTest() { if (found?.number !== 42) throw new Error('de-dup: a multi-page scan lost the card'); }); + // -- The cadence (#23880): each cadence, the back-compat pins for the card + // already open under the hourly identity, and the refusal of a workflow + // the closed map does not name. + const rerun = cardIdentity('Rerun Safety'); + const OPEN_CI_TITLE = 'hourly full run: red on main (CI)'; + const OPEN_CI_MARKER = 'os-hourly-full-run-ci'; + const OPEN_CI_MARKER_LINE = + 'os-hourly-full-run-ci — machine-findable marker for this generated card. ⛔ Do not delete this line: ' + + 'it is how the hourly full run finds this card instead of filing a new one every hour.'; + const bodiesOf = (identityUnderTest) => [ + renderBody({ identity: identityUnderTest, runUrl: 'u', headSha: 'a', conclusion: 'failure', sweptAt: 't', + previousGreen: { run_id: 4, head_sha: 'b' }, commits: [{ sha: 'c', title: 'x' }] }), + renderBody({ identity: identityUnderTest, runUrl: 'u', headSha: 'a', conclusion: 'failure', sweptAt: 't', + previousGreen: { run_id: 4, head_sha: 'b' }, commits: [] }), + renderBody({ identity: identityUnderTest, runUrl: 'u', headSha: 'a', conclusion: 'failure', sweptAt: 't', rangeNote: 'n' }), + ]; + await check(() => { + if (ci.cadence !== 'hourly' || ci.title !== OPEN_CI_TITLE || ci.marker !== OPEN_CI_MARKER) { + throw new Error(`cadence: the CI identity moved (${ci.cadence}, '${ci.title}', '${ci.marker}') -- the open card would be duplicated`); + } + }); + await check(() => { + for (const b of bodiesOf(ci)) { + if (b.split('\n')[0] !== OPEN_CI_MARKER_LINE) throw new Error(`cadence: the CI marker line moved: '${b.split('\n')[0]}'`); + } + }); + await check(async () => { + // The open CI card exactly as it was filed before the cadence existed. + const open = { number: 23885, title: OPEN_CI_TITLE, body: `${OPEN_CI_MARKER_LINE}\n# ${OPEN_CI_TITLE}` }; + const found = await findExistingCard({ identity: cardIdentity('CI'), listPage: page([issue(7), open]) }); + if (found?.number !== 23885) throw new Error(`cadence: the open CI card was not found by its title (${found?.number})`); + }); + await check(async () => { + const renamed = { number: 23885, title: 'renamed by a human', body: `${OPEN_CI_MARKER_LINE}\n` }; + const found = await findExistingCard({ identity: cardIdentity('CI'), listPage: page([renamed]) }); + if (found?.number !== 23885) throw new Error('cadence: the open CI card was not found by its marker alone'); + }); + await check(() => { + if (lint.cadence !== 'hourly' || lint.title !== 'hourly full run: red on main (Lint & Type Check)') { + throw new Error(`cadence: Lint & Type Check is not hourly ('${lint.title}')`); + } + }); + await check(() => { + if ( + rerun.cadence !== 'nightly' || + rerun.title !== 'nightly full run: red on main (Rerun Safety)' || + rerun.marker !== 'os-nightly-full-run-rerun-safety' + ) { + throw new Error(`cadence: Rerun Safety is not nightly ('${rerun.title}', '${rerun.marker}')`); + } + }); + await check(() => { + for (const b of bodiesOf(rerun)) { + if (/hourly|every hour|an hour ago/.test(b)) throw new Error(`cadence: a nightly card body says hourly:\n${b}`); + if (!b.includes('every night') || !b.includes('## What landed since the last green nightly run')) { + throw new Error(`cadence: a nightly card body lacks its own cadence words:\n${b}`); + } + } + if (!bodiesOf(rerun)[1].includes('green the night before')) throw new Error('cadence: the nightly flake reading is not nightly'); + }); + await check(() => { + for (const b of bodiesOf(ci)) { + if (/nightly|every night|the night before/.test(b)) throw new Error(`cadence: an hourly card body says nightly:\n${b}`); + } + }); + await check(() => { + let message = ''; + try { + cardIdentity('Spec Coverage'); + } catch (error) { + message = error.message; + } + if (!message.includes('CARD_CADENCES')) { + throw new Error(`cadence: a workflow outside the map was not refused by name (${message || 'accepted'})`); + } + }); + await check(() => { + const { cadence: _dropped, ...handBuilt } = ci; + if (!threw(() => renderBody({ identity: handBuilt, runUrl: 'u', headSha: 'a', conclusion: 'failure', sweptAt: 't' }))) { + throw new Error('cadence: renderBody defaulted the cadence of an identity that carries none'); + } + }); + await check(() => { + if (matchesCard(issue(1, { title: ci.title, body: ci.marker }), rerun) || matchesCard(issue(1, { title: rerun.title, body: rerun.marker }), ci)) { + throw new Error("cadence: the nightly and hourly identities matched each other's cards"); + } + }); + // -- THE ACCEPTANCE SHAPE, driven end to end against a mutable board: one red // run files exactly one card, and the NEXT red run refreshes that card and // files no second one. This is the property the filer exists for, and a diff --git a/scripts/rerun-safety-verdict.mjs b/scripts/rerun-safety-verdict.mjs index 6275d799aaa..824354c8be3 100644 --- a/scripts/rerun-safety-verdict.mjs +++ b/scripts/rerun-safety-verdict.mjs @@ -34,13 +34,78 @@ // being clean. Pass 2 now runs whatever pass 1 did, and this script compares // the two, so a red trunk costs the instrument its baseline -- not its reading. // +// ## What a pass's log says, and the two facts it used to blur (#23880) +// +// Turbo states two different facts about a task, in two different spellings: +// +// FAILED `Failed: @objectstack/dogfood#test` (the summary footer) and +// `@objectstack/dogfood#test: ERROR command (...) exited (1)` +// (the per-task error line). Turbo prints these only for a task +// that exited non-zero ON ITS OWN. +// INTERRUPTED `@objectstack/cli:test: ELIFECYCLE Test failed.` with no +// ERROR line and no footer entry. Without `--continue`, turbo ends +// the run at its first failed task and stops every task still +// running; pnpm then prints ELIFECYCLE for each of them in the very +// words a real failure uses. An interrupted task did not fail. It +// was not allowed to finish, so it is UNMEASURED in that pass. +// +// This script used to take the union of all three spellings as the failing +// set, on the theory that the footer under-reports. Read against the job logs +// of the nights #23880 covers, the "under-reporting" was that interruption +// every time -- the extra ELIFECYCLE lines land 0.1-0.5 s after the real +// failure's, and one of the interrupted suites logs `Received SIGINT`: +// +// night pass turbo's footer (FAILED) ELIFECYCLE only (INTERRUPTED) +// 10-02 1 @objectstack/dogfood @objectstack/cli +// 10-02 2 @objectstack/core driver-sql, spec, lint +// 10-13 2 @objectstack/runtime http-conformance, verify +// 10-14 1 @objectstack/dogfood @objectstack/cli +// 10-14 2 @objectstack/core spec, lint +// 10-15 2 @objectstack/runtime verify, cli, organizations +// +// So `@objectstack/cli#test`, printed as a pass-1 failure on every one of those +// nights, was the suite turbo stopped when dogfood failed; and the "different +// package set each night" on pass 2 was each night's first real failure plus +// whatever happened to be running beside it. +// +// Three more facts are read for the same reason -- so the verdict never claims +// more than the passes measured: +// +// FINISHED turbo's closing ` Tasks: N successful, M total`. A pass log +// without it did not finish -- stopped by its time budget, the +// job timeout or a crash -- and nothing it had not finished was +// measured. `M` counts the tasks turbo STARTED, so a pass that +// stopped at its first failure shows a smaller `M` than one that +// ran to the end (10-14: pass 1 started 143, pass 2 only 49). +// A pass the workflow's time bound stopped exits 124 or 137 +// (`timeout`). Measured once, locally: that log ended at +// `Force killed Turborepo tasks: ...` with no summary at all. +// A turbo that did print one on its way down could name the +// tasks the signal killed in its footer, so for such a pass the +// exit code decides, and only a task whose own vitest run +// reported a failed test or suite counts as failed. +// RAN a task that printed vitest's `Test Files` line finished its +// suite in that pass. A pass-1 failure that pass 2 never finished +// was NOT re-measured; it did not "recover". +// TIMEOUT-ONLY a failed task whose every failed test is vitest's +// `Error: Test timed out in Nms`. Every real failure on the nights +// above has this shape. A working-tree leak fails an assertion, not +// a clock, so a timeout-only task that fails only on pass 2 points +// at load before it points at a leak, and the verdict says how to +// tell the two apart. +// +// A leading ISO timestamp and ANSI colour codes are stripped from every line, so +// a log downloaded from the Actions API (which stamps each line, and keeps +// vitest's colours) reads the same as the stall guard's own tee. +// // ## What it does NOT do // // It does not make the job green. A red pass 1 still fails the job: the // workflow's own header calls that deliberate ("if pass 1 is red the suite is // simply broken on main and that is worth failing on"), and nothing here // relaxes it. What changes is only that the job now also reports whether the -// second pass agreed with the first. +// second pass agreed with the first, and how much of the suite either pass +// actually covered. // // ## Usage // @@ -50,168 +115,347 @@ // // Exit status: 0 only for RERUN-SAFE; 75 for a stall (EX_TEMPFAIL, the same // code run-with-stall-guard uses and for the same reason -- rerun it); 1 for -// every verdict that is a real red. +// every verdict that is a real red, INCOMPLETE included. import { readFileSync } from 'node:fs'; import { isEntrypoint } from './invoked-as.mjs'; const STALL_EXIT_CODE = 75; // EX_TEMPFAIL -- matches run-with-stall-guard.mjs +// What `timeout` (coreutils) exits with when it stopped the command at the +// deadline, and what it exits with when the command then needed SIGKILL. +const BUDGET_EXIT_CODES = Object.freeze([124, 137]); // --------------------------------------------------------------------------- -// Reading a pass's failing task set out of its log +// Reading one pass out of its log // --------------------------------------------------------------------------- -// -// Three spellings carry the same fact, and the union of them is the answer. -// None alone is sufficient, which is why all three are read: -// -// 1. `Failed: @objectstack/cli#test` -- turbo's summary footer. Under- -// reports: on the 2026-09-08 run it named `@objectstack/verify#test` -// alone while `plugin-auth`, `runtime` and `client` had each printed -// ELIFECYCLE in the same run. -// 2. `@objectstack/cli#test: ERROR command (...) exited (1)` -- turbo's -// per-task error line, already `pkg#task` shaped. -// 3. `@objectstack/plugin-auth:test: ELIFECYCLE Test failed.` -- the -// STREAMING prefix (`pkg:task:`), which is how a task that failed while -// turbo was still running others announces itself. -// -// A leading ISO timestamp is tolerated so that a log downloaded from the -// Actions API (which stamps every line) reads the same as the guard's own tee. -const TS = String.raw`(?:\d{4}-\d{2}-\d{2}T[\d:.]+Z\s+)?`; - -const FAILED_FOOTER_RE = new RegExp(`^${TS}\\s*Failed:\\s+(.+?)\\s*$`, 'gm'); -const TASK_ERROR_RE = new RegExp(`^${TS}\\s*(\\S+?)#(\\S+?):\\s+ERROR\\s+command\\b`, 'gm'); -const ELIFECYCLE_RE = new RegExp(`^${TS}\\s*(\\S+?):([A-Za-z0-9:_-]+?):\\s+ELIFECYCLE\\b`, 'gm'); +// The ESC-[...m colour sequences vitest prints, spelled with the escape -- never +// as the raw control byte (scripts/check-nul-bytes.mjs has the reason). +const ANSI_RE = /\u001b\[[0-9;]*[A-Za-z]/g; +const ISO_PREFIX_RE = /^\d{4}-\d{2}-\d{2}T[\d:.]+Z\s/; + +const FAILED_FOOTER_RE = /^\s*Failed:\s+(.+?)\s*$/; +const TASK_ERROR_RE = /^\s*(\S+?)#(\S+?):\s+ERROR\s+command\b/; +const TASKS_SUMMARY_RE = /^\s*Tasks:\s+(\d+)\s+successful,\s+(\d+)\s+total\b/; +// turbo's streaming prefix: `:: `. +const TASK_LINE_RE = /^(\S+?):([A-Za-z0-9_-]+(?::[A-Za-z0-9_-]+)*?):\s(.*)$/; + +const ELIFECYCLE_RE = /^\s*ELIFECYCLE\b/; +const VITEST_TEST_FILES_RE = /^\s*Test Files\s/; +// The rule characters around vitest's summary headers are U+23AF. +const VITEST_FAILED_TESTS_RE = /^\s*⎯+\s*Failed Tests (\d+)\s*⎯+\s*$/; +const VITEST_FAILED_SUITES_RE = /^\s*⎯+\s*Failed Suites (\d+)\s*⎯+\s*$/; +// Anchored at the start of the task's output on purpose: the github-actions +// reporter repeats the message inside a `::error file=...` annotation, and that +// copy must not count as a second timed-out test. +const VITEST_TIMEOUT_RE = /^\s*Error: Test timed out in \d+ms\b/; + +function cleanLines(logText) { + return String(logText ?? '') + .split(/\r?\n/) + .map((line) => line.replace(ANSI_RE, '').replace(ISO_PREFIX_RE, '')); +} /** - * The normalized `pkg#task` ids named as FAILING anywhere in one pass's log. + * Everything one pass's log states about its tasks. Every list is a sorted + * array of `pkg#task` ids so two passes compare and print stably. * - * Returned as a sorted array so two passes' sets compare and print stably. + * failing turbo reported the task as failed (footer or ERROR line) + * interrupted ELIFECYCLE only: turbo stopped it after another task failed + * ran the task's vitest run printed its `Test Files` line + * timeoutOnly failing tasks whose every failed test hit vitest's timeout + * finished turbo printed its closing `Tasks:` summary + * started that summary's `M total` (null when unfinished) + * successful that summary's `N successful` (null when unfinished) */ -export function failingTasks(logText) { - const out = new Set(); - - for (const m of logText.matchAll(FAILED_FOOTER_RE)) { - // turbo separates several ids with commas and/or whitespace. - for (const id of m[1].split(/[,\s]+/)) { - const trimmed = id.trim(); - if (trimmed.includes('#')) out.add(trimmed); +export function readPass(logText) { + const failing = new Set(); + const elifecycle = new Set(); + const ran = new Set(); + const counters = new Map(); + const counter = (id) => { + if (!counters.has(id)) counters.set(id, { failedTests: 0, failedSuites: 0, timeouts: 0 }); + return counters.get(id); + }; + let summary = null; + + for (const line of cleanLines(logText)) { + let m = FAILED_FOOTER_RE.exec(line); + if (m) { + // turbo separates several ids with commas and/or whitespace. + for (const id of m[1].split(/[,\s]+/)) { + const trimmed = id.trim(); + if (trimmed.includes('#')) failing.add(trimmed); + } + continue; + } + m = TASK_ERROR_RE.exec(line); + if (m) { + failing.add(`${m[1]}#${m[2]}`); + continue; + } + m = TASKS_SUMMARY_RE.exec(line); + if (m) { + summary = { successful: Number(m[1]), started: Number(m[2]) }; + continue; } + m = TASK_LINE_RE.exec(line); + if (!m) continue; + const id = `${m[1]}#${m[2]}`; + const output = m[3]; + if (ELIFECYCLE_RE.test(output)) { + elifecycle.add(id); + continue; + } + if (VITEST_TEST_FILES_RE.test(output)) ran.add(id); + const tests = VITEST_FAILED_TESTS_RE.exec(output); + if (tests) counter(id).failedTests += Number(tests[1]); + const suites = VITEST_FAILED_SUITES_RE.exec(output); + if (suites) counter(id).failedSuites += Number(suites[1]); + if (VITEST_TIMEOUT_RE.test(output)) counter(id).timeouts += 1; } - for (const m of logText.matchAll(TASK_ERROR_RE)) out.add(`${m[1]}#${m[2]}`); - for (const m of logText.matchAll(ELIFECYCLE_RE)) out.add(`${m[1]}#${m[2]}`); - return [...out].sort(); + const timeoutOnly = [...failing].filter((id) => { + const c = counters.get(id); + return Boolean(c) && c.failedTests > 0 && c.failedSuites === 0 && c.timeouts === c.failedTests; + }); + // Failing tasks whose own vitest run REPORTED a failed test or suite. When a + // signal stops the whole run, turbo reports every task it killed as failed; + // only these failed on their own. + const reported = [...failing].filter((id) => { + const c = counters.get(id); + return Boolean(c) && c.failedTests + c.failedSuites > 0; + }); + + return { + failing: [...failing].sort(), + interrupted: [...elifecycle].filter((id) => !failing.has(id)).sort(), + ran: [...ran].sort(), + timeoutOnly: timeoutOnly.sort(), + reported: reported.sort(), + finished: summary !== null, + started: summary?.started ?? null, + successful: summary?.successful ?? null, + }; +} + +/** The tasks turbo reported as FAILED in one pass's log (interruptions excluded). */ +export function failingTasks(logText) { + return readPass(logText).failing; } // --------------------------------------------------------------------------- // The verdict // --------------------------------------------------------------------------- +const without = (list, ...others) => list.filter((t) => !others.some((o) => o.includes(t))); + +// A red pass is PARTIAL unless its own summary accounts for every task it +// started AND it started as many as the other pass did. Without `--continue` +// turbo stops scheduling at the first failure, so the tasks it never started +// appear in no count of that pass at all -- only the other pass's `M total` +// can show them missing. +function stoppedShort(pass, maxStarted) { + if (!pass.finished || pass.exit === 0) return false; + if (pass.interrupted.length > 0) return true; + if (pass.started === null || pass.successful === null) return true; + return pass.successful + pass.failing.length < pass.started || pass.started < maxStarted; +} + +function timeoutAdvice(ids, timeoutOnly) { + return ids + .filter((id) => timeoutOnly.includes(id)) + .map((id) => { + const [pkg, task] = id.split('#'); + return ( + `${id}: every failed test hit vitest's test timeout -- load-shaped. A leak fails an ` + + `assertion, not a clock: run \`pnpm --filter ${pkg} run ${task}\` twice in one tree on ` + + 'its own; a leak fails the second run there, a load timeout does not.' + ); + }); +} + +function coverageNotes(pass1, pass2, maxStarted) { + const notes = []; + for (const [n, p] of [[1, pass1], [2, pass2]]) { + if (!stoppedShort(p, maxStarted)) continue; + notes.push( + p.started !== null && p.started < maxStarted + ? `Pass ${n} stopped at its first failure (turbo runs without --continue) after starting ` + + `${p.started} of the ${maxStarted} tasks the longer pass started; every task it did not ` + + 'finish is unmeasured in that pass.' + : `Pass ${n} stopped at its first failure (turbo runs without --continue); the tasks still ` + + 'running then were interrupted and are unmeasured in that pass.', + ); + } + return notes; +} + /** - * The five verdicts, and the one question each answers. + * The verdicts, and the one question each answers. + * + * `coverage` is the field this whole script exists for -- `full`, `partial` or + * `none` -- because "rerun safety is failing" and "rerun safety was never (or + * only partly) measured" are different facts the exit code alone cannot carry. + * `measured` is `coverage !== 'none'`. * - * `measured` is the field this whole script exists for: it is the difference - * between "rerun safety is failing" and "rerun safety was never measured", - * which the job's exit code alone has never been able to express. + * Each pass is `{ exit, ...readPass(log) }`. */ -export function verdict({ pass1Exit, pass2Exit, pass1Failing, pass2Failing }) { - if (pass1Exit === STALL_EXIT_CODE || pass2Exit === STALL_EXIT_CODE) { - return { - code: 'STALL', - measured: false, - exit: STALL_EXIT_CODE, - headline: 'STALLED -- frozen output, killed by run-with-stall-guard', - detail: [ - 'This is NOT a rerun-safety verdict: a stall says nothing about', - 'working-tree pollution. Rerun the workflow; if it stalls again at the', - 'same file, note the occurrence on #4250.', - ], - }; - } - - const newlyFailing = pass2Failing.filter((t) => !pass1Failing.includes(t)); - const recovered = pass1Failing.filter((t) => !pass2Failing.includes(t)); - - if (pass1Exit === 0 && pass2Exit === 0) { - return { - code: 'RERUN_SAFE', - measured: true, - exit: 0, - headline: 'RERUN-SAFE -- the second pass agreed with the first', - detail: ['Both passes of the full suite were green in one working tree.'], - }; - } - - if (pass1Exit === 0 && pass2Exit !== 0) { - return { - code: 'RERUN_UNSAFE', - measured: true, - exit: 1, - headline: 'RERUN-UNSAFE -- the suite passes once and fails on a second run', - detail: [ - 'Something under test writes state into the working tree and reads it', - 'back on the next run. Ordinary CI cannot see this -- every other job is', - 'a fresh clone, so every other job is always run #1.', - `Newly failing on pass 2: ${newlyFailing.join(', ') || '(none named in the log)'}`, - 'See the on-disk state reported above, and #4065 for the pattern.', - ], - }; - } - - if (pass1Exit !== 0 && pass2Exit === 0) { - return { - code: 'BASELINE_FLAKY', - measured: true, - exit: 1, - headline: 'SUITE BROKEN ON MAIN (pass 1 only) -- and it passed on rerun', - detail: [ - 'Pass 1 failed and pass 2 was green in the same tree, so this is NOT the', - '#4065 rerun-unsafe pattern -- it is order-dependence or flake, pointing', - 'the opposite way down the same axis.', - `Failed on pass 1, green on pass 2: ${recovered.join(', ') || '(none named in the log)'}`, - ], - }; +export function verdict({ pass1, pass2 }) { + const result = (code, coverage, exit, headline, detail) => ({ + code, + coverage, + measured: coverage !== 'none', + exit, + headline, + detail, + }); + + if (pass1.exit === STALL_EXIT_CODE || pass2.exit === STALL_EXIT_CODE) { + return result('STALL', 'none', STALL_EXIT_CODE, 'STALLED -- frozen output, killed by run-with-stall-guard', [ + 'This is NOT a rerun-safety verdict: a stall says nothing about', + 'working-tree pollution. Rerun the workflow; if it stalls again at the', + 'same file, note the occurrence on #4250.', + ]); + } + + // A pass stopped by its time budget did not finish even when turbo, on its + // way down, printed a summary: the exit code is the authority there. + const byBudget = (p) => BUDGET_EXIT_CODES.includes(p.exit); + const unfinished = [[1, pass1], [2, pass2]].filter(([, p]) => !p.finished || byBudget(p)); + if (unfinished.length > 0) { + const named = unfinished.map(([n, p]) => + byBudget(p) + ? `Pass ${n} (exit ${p.exit}) was stopped by its share of the job's time before it finished.` + : `Pass ${n} (exit ${p.exit}) printed no turbo summary: it was stopped before it finished (job timeout or crash).`, + ); + const found = [[1, pass1], [2, pass2]].flatMap(([n, p]) => { + const own = byBudget(p) ? p.reported : p.failing; + const killed = byBudget(p) ? without(p.failing, p.reported) : []; + const when = unfinished.some(([u]) => u === n) ? ' before it stopped' : ''; + return [ + ...(own.length > 0 ? [`Failed in pass ${n}${when}: ${own.join(', ')}`] : []), + ...(killed.length > 0 ? [`Stopped mid-run in pass ${n} by the time bound (unmeasured): ${killed.join(', ')}`] : []), + ]; + }); + return result('INCOMPLETE', 'none', 1, 'INCOMPLETE -- a pass did not finish, so the rerun property was NOT MEASURED', [ + ...named, + 'Running out of time is a capacity reading, not a suite reading: compare the', + 'two pass steps\' durations with the job\'s timeout before reading anything', + 'into the failures below.', + ...found, + ]); + } + + const maxStarted = Math.max(pass1.started ?? 0, pass2.started ?? 0); + const coverage = + stoppedShort(pass1, maxStarted) || stoppedShort(pass2, maxStarted) ? 'partial' : 'full'; + const notes = coverageNotes(pass1, pass2, maxStarted); + + const newlyFailing = without(pass2.failing, pass1.failing); + const recovered = pass1.failing.filter((t) => pass2.ran.includes(t) && !pass2.failing.includes(t)); + const notRemeasured = without(pass1.failing, pass2.failing, pass2.ran); + const interruptedNote = [[1, pass1], [2, pass2]] + .filter(([, p]) => p.interrupted.length > 0) + .map( + ([n, p]) => + `Interrupted by turbo in pass ${n} after another task failed (not failures, unmeasured): ${p.interrupted.join(', ')}`, + ); + const notRemeasuredNote = + notRemeasured.length > 0 + ? [`Failed on pass 1 and never finished by pass 2 (NOT re-measured, not recovered): ${notRemeasured.join(', ')}`] + : []; + const advice = timeoutAdvice(newlyFailing, pass2.timeoutOnly); + + if (pass1.exit === 0 && pass2.exit === 0) { + return result('RERUN_SAFE', coverage, 0, 'RERUN-SAFE -- the second pass agreed with the first', [ + 'Both passes of the full suite were green in one working tree.', + ]); + } + + if (pass1.exit === 0 && pass2.exit !== 0) { + return result('RERUN_UNSAFE', coverage, 1, 'RERUN-UNSAFE -- the suite passes once and fails on a second run', [ + 'Something under test writes state into the working tree and reads it', + 'back on the next run. Ordinary CI cannot see this -- every other job is', + 'a fresh clone, so every other job is always run #1.', + `Newly failing on pass 2: ${newlyFailing.join(', ') || '(none named in the log)'}`, + ...advice, + ...interruptedNote, + ...notes, + 'See the on-disk state reported above, and #4065 for the pattern.', + ]); + } + + if (pass1.exit !== 0 && pass2.exit === 0) { + return result('BASELINE_FLAKY', coverage, 1, 'SUITE BROKEN ON MAIN (pass 1 only) -- and it passed on rerun', [ + 'Pass 1 failed and pass 2 was green in the same tree, so this is NOT the', + '#4065 rerun-unsafe pattern -- it is order-dependence or flake, pointing', + 'the opposite way down the same axis.', + `Failed on pass 1, green on pass 2: ${pass1.failing.join(', ') || '(none named in the log)'}`, + ...interruptedNote, + ...notes, + ]); } if (newlyFailing.length > 0) { - return { - code: 'RERUN_UNSAFE_ON_BROKEN_BASELINE', - measured: true, - exit: 1, - headline: 'RERUN-UNSAFE, on top of a suite that is already broken on main', - detail: [ + return result( + 'RERUN_UNSAFE_ON_BROKEN_BASELINE', + coverage, + 1, + 'RERUN-UNSAFE, on top of a suite that is already broken on main', + [ 'Both passes failed, but pass 2 failed tasks that pass 1 did not. The', - 'extra ones are the rerun-safety finding; the shared ones are ordinary', + 'extra ones are the rerun-safety CANDIDATES; the shared ones are ordinary', 'breakage on main and belong to whoever owns them.', `Newly failing on pass 2: ${newlyFailing.join(', ')}`, - `Failing in both passes: ${pass1Failing.filter((t) => pass2Failing.includes(t)).join(', ') || '(none)'}`, + ...advice, + `Failing in both passes: ${pass1.failing.filter((t) => pass2.failing.includes(t)).join(', ') || '(none)'}`, + ...notRemeasuredNote, + ...interruptedNote, + ...notes, ], - }; + ); } - return { - code: 'BASELINE_BROKEN', - measured: true, - exit: 1, - headline: 'SUITE BROKEN ON MAIN -- rerun property measured, and it is CLEAN', - detail: [ - 'Both passes failed the same set of tasks, so the second pass agreed with', - 'the first: no task failed only on the rerun. The red belongs to ordinary', - 'breakage on main, NOT to working-tree pollution -- do not go hunting for', - 'state leaks on the strength of this run.', - `Failing in both passes: ${pass1Failing.join(', ') || '(none named in the log)'}`, - ...(recovered.length > 0 ? [`Failed on pass 1 only: ${recovered.join(', ')}`] : []), - ], - }; + const headline = + coverage === 'full' + ? 'SUITE BROKEN ON MAIN -- rerun property measured, and it is CLEAN' + : 'SUITE BROKEN ON MAIN -- no task failed only on the rerun, as far as pass 2 got'; + return result('BASELINE_BROKEN', coverage, 1, headline, [ + 'No task failed in pass 2 that had not already failed in pass 1. The red', + 'belongs to ordinary breakage on main, NOT to working-tree pollution -- do', + 'not go hunting for state leaks on the strength of this run.', + `Failing in both passes: ${pass1.failing.filter((t) => pass2.failing.includes(t)).join(', ') || '(none)'}`, + ...(recovered.length > 0 ? [`Failed on pass 1 only, green on pass 2: ${recovered.join(', ')}`] : []), + ...notRemeasuredNote, + ...interruptedNote, + ...notes, + ]); } // --------------------------------------------------------------------------- // Reporting // --------------------------------------------------------------------------- -export function renderVerdict(v, { pass1Exit, pass2Exit, pass1Failing, pass2Failing }) { +const COVERAGE_WORDS = Object.freeze({ full: 'MEASURED', partial: 'PARTIALLY MEASURED', none: 'NOT MEASURED' }); + +function passLine(n, p) { + const failed = p.failing + .map((id) => (p.timeoutOnly.includes(id) ? `${id} (timeout-only)` : id)) + .join(', '); + const lines = [` pass ${n} exit ${p.exit}, failing tasks: ${failed || '(none)'}`]; + if (p.interrupted.length > 0) lines.push(` interrupted by turbo (unmeasured): ${p.interrupted.join(', ')}`); + lines.push( + p.finished + ? ` turbo: ${p.successful} successful of ${p.started} started` + : ' turbo: no closing summary -- this pass did not finish', + ); + if (BUDGET_EXIT_CODES.includes(p.exit)) lines.push(' stopped by its share of the job\'s time'); + return lines; +} + +export function renderVerdict(v, { pass1, pass2 }) { const lines = []; lines.push('='.repeat(72)); lines.push(`Rerun Safety verdict: ${v.code}`); @@ -220,9 +464,9 @@ export function renderVerdict(v, { pass1Exit, pass2Exit, pass1Failing, pass2Fail lines.push(''); for (const d of v.detail) lines.push(` ${d}`); lines.push(''); - lines.push(` rerun property: ${v.measured ? 'MEASURED' : 'NOT MEASURED'}`); - lines.push(` pass 1 exit ${pass1Exit}, failing tasks: ${pass1Failing.join(', ') || '(none)'}`); - lines.push(` pass 2 exit ${pass2Exit}, failing tasks: ${pass2Failing.join(', ') || '(none)'}`); + lines.push(` rerun property: ${COVERAGE_WORDS[v.coverage]}`); + lines.push(...passLine(1, pass1)); + lines.push(...passLine(2, pass2)); lines.push('='.repeat(72)); return lines.join('\n'); } @@ -239,10 +483,14 @@ export function renderVerdict(v, { pass1Exit, pass2Exit, pass1Failing, pass2Fail const SELF_TEST_BATTERIES = Object.freeze({ 'parse: turbo Failed: footer': 1, 'parse: turbo per-task ERROR line': 1, - 'parse: streaming ELIFECYCLE prefix': 1, - 'parse: union under-reporting footer (2026-09-08 shape)': 1, + 'parse: an ELIFECYCLE line alone is INTERRUPTED, never failing': 2, + 'parse: 2026-10-14 pass 1 -- dogfood failed, cli interrupted by fail-fast': 5, + 'parse: 2026-10-15 pass 2 -- runtime failed; verify, cli, organizations interrupted': 3, 'parse: an API-downloaded log with ISO timestamps reads the same': 1, - 'parse: a green log names no failing task': 1, + 'parse: a green log names no failing task and is finished': 2, + 'parse: timeout-only needs EVERY failed test to be a timeout': 2, + 'parse: the ::error annotation copy is not a second timeout': 1, + 'parse: a log without turbo\'s closing summary did not finish': 2, 'verdict: both green -> RERUN_SAFE, measured, exit 0': 1, 'verdict: pass1 green + pass2 red -> RERUN_UNSAFE, exit 1': 1, 'verdict: pass1 red + pass2 green -> BASELINE_FLAKY, measured': 1, @@ -250,17 +498,97 @@ const SELF_TEST_BATTERIES = Object.freeze({ 'verdict: both red, pass2 worse -> RERUN_UNSAFE_ON_BROKEN_BASELINE': 1, 'verdict: a stall in pass 1 -> STALL, NOT MEASURED, exit 75': 1, 'verdict: a stall in pass 2 -> STALL, NOT MEASURED, exit 75': 1, - 'verdict: every non-stall verdict reports measured=true': 1, - 'render: the verdict line names MEASURED or NOT MEASURED': 1, + 'verdict: a pass that did not finish -> INCOMPLETE, NOT MEASURED, exit 1': 4, + 'verdict: every finished, non-stall verdict reports measured=true': 1, + 'verdict: 2026-10-14 end to end -- no interrupted task is newly failing, coverage PARTIAL': 4, + 'verdict: a pass-1 failure pass 2 never finished is not re-measured, never recovered': 1, + 'render: the verdict line names MEASURED, PARTIALLY MEASURED or NOT MEASURED': 1, + 'render: a timeout-only newly failing task carries the twice-on-its-own instruction': 1, }); -const SELF_TEST_BATTERY_FLOOR = 15; +const SELF_TEST_BATTERY_FLOOR = 23; // Set by `selfTest()` only after its verdict is printed, and read at the // dispatch: a `return` above that line prints nothing and still exits 0 -- a // self-test that never finished, reported as one that passed. let selfTestReachedVerdict = false; +// Fixture spellings. The colour codes and the U+23AF rules are written as +// escapes, exactly as the job log carries them once decoded. +const ESC = '\u001b'; +const RULE = '⎯'.repeat(7); +const failedTestsHeader = (prefix, n) => + `${prefix} ${ESC}[31m${RULE}${ESC}[39m${ESC}[1m${ESC}[41m Failed Tests ${n} ${ESC}[49m${ESC}[22m${ESC}[31m${RULE}${ESC}[39m`; +const timedOut = (prefix) => `${prefix} ${ESC}[31m${ESC}[1mError${ESC}[22m: Test timed out in 5000ms.`; +const testFiles = (prefix, failed, passed) => + `${prefix} ${ESC}[2m Test Files ${ESC}[22m ${ESC}[1m${ESC}[31m${failed} failed${ESC}[39m${ESC}[22m${ESC}[2m | ${ESC}[22m${ESC}[1m${ESC}[32m${passed} passed${ESC}[39m`; +const elifecycle = (pkg) => `${pkg}:test: ELIFECYCLE Test failed. See above for more details.`; +const taskError = (pkg) => `${pkg}#test: ERROR command (/w/${pkg}) /x/pnpm run test exited (1)`; +const tasksSummary = (ok, total) => ` Tasks: ${ok} successful, ${total} total`; + +// The 2026-10-14 night (run 38509291145), cut to the lines this script reads. +const NIGHT_1014_PASS1 = [ + '@objectstack/dogfood:test: ✓ shared-showcase test/showcase-public-read-owd.dogfood.test.ts (3 tests) 1876ms', + failedTestsHeader('@objectstack/dogfood:test:', 1), + '@objectstack/dogfood:test: FAIL isolated test/activity-text-predicate.dogfood.test.ts > [#21154] ... > control: the unmasking reader filters and groups by every column of a pinned parent, as before', + timedOut('@objectstack/dogfood:test:'), + testFiles('@objectstack/dogfood:test:', 1, 256), + '@objectstack/dogfood:test: ::error file=/w/packages/qa/dogfood/test/activity-text-predicate.dogfood.test.ts,title=[isolated] test/activity-text-predicate.dogfood.test.ts::Error: Test timed out in 5000ms.', + elifecycle('@objectstack/dogfood'), + elifecycle('@objectstack/cli'), + '##[error]command (/w/packages/qa/dogfood) /x/pnpm run test exited (1)', + taskError('@objectstack/dogfood'), + '', + tasksSummary(141, 143), + 'Cached: 0 cached, 143 total', + ' Time: 1h38m20.709s ', + 'Failed: @objectstack/dogfood#test', +].join('\n'); + +const NIGHT_1014_PASS2 = [ + failedTestsHeader('@objectstack/core:test:', 1), + '@objectstack/core:test: FAIL local src/security/auth-gate.test.ts > auth-gate (ADR-0069 session gate) > BOUNDARY', + timedOut('@objectstack/core:test:'), + testFiles('@objectstack/core:test:', 1, 96), + elifecycle('@objectstack/core'), + '@objectstack/lint:test: ✓ src/validate-expressions.field-conditional-formatting.test.ts (41 tests) 489ms', + elifecycle('@objectstack/spec'), + elifecycle('@objectstack/lint'), + taskError('@objectstack/core'), + tasksSummary(24, 49), + 'Failed: @objectstack/core#test', +].join('\n'); + +// The 2026-10-15 night's pass 2 (run 38679312462), API-downloaded: stamped. +const NIGHT_1015_PASS2 = [ + failedTestsHeader('@objectstack/runtime:test:', 1), + timedOut('@objectstack/runtime:test:'), + testFiles('@objectstack/runtime:test:', 1, 382), + '@objectstack/verify:test: 2026-10-15T06:47:11.224Z INFO Received SIGINT - initiating graceful shutdown', + elifecycle('@objectstack/runtime'), + elifecycle('@objectstack/verify'), + elifecycle('@objectstack/cli'), + elifecycle('@objectstack/organizations'), + taskError('@objectstack/runtime'), + tasksSummary(132, 142), + 'Failed: @objectstack/runtime#test', +] + .map((line, i) => `2026-10-15T06:47:${String(10 + i).padStart(2, '0')}.0000000Z ${line}`) + .join('\n'); + +// A synthetic pass: `failing` tasks fail on their own, `ran` tasks finish +// green, and the summary accounts for every task unless `started` says more. +function logOf({ failing = [], interrupted = [], ran = [], started = 10, finished = true } = {}) { + const lines = []; + for (const id of [...ran, ...failing]) lines.push(testFiles(`${id.split('#')[0]}:test:`, failing.includes(id) ? 1 : 0, 3)); + for (const id of [...failing, ...interrupted]) lines.push(elifecycle(id.split('#')[0])); + for (const id of failing) lines.push(taskError(id.split('#')[0])); + if (finished) lines.push(tasksSummary(started - failing.length - interrupted.length, started)); + if (finished && failing.length > 0) lines.push(`Failed: ${failing.join(', ')}`); + return lines.join('\n'); +} +const passOf = (exit, log) => ({ exit, ...readPass(log) }); + function selfTest() { const registered = new Map(); const registerCase = (label) => registered.set(label, (registered.get(label) ?? 0) + 1); @@ -276,42 +604,43 @@ function selfTest() { }; // -- parsing ------------------------------------------------------------- - check( - 'parse: turbo Failed: footer', - failingTasks('Failed: @objectstack/cli#test\n').join() === '@objectstack/cli#test', - ); + check('parse: turbo Failed: footer', failingTasks('Failed: @objectstack/cli#test\n').join() === '@objectstack/cli#test'); check( 'parse: turbo per-task ERROR line', - failingTasks( - '@objectstack/verify#test: ERROR command (/w/packages/verify) /x/pnpm run test exited (1)\n', - ).join() === '@objectstack/verify#test', - ); - check( - 'parse: streaming ELIFECYCLE prefix', - failingTasks('@objectstack/plugin-auth:test: ELIFECYCLE Test failed.\n').join() === - '@objectstack/plugin-auth#test', + failingTasks(`${taskError('@objectstack/verify')}\n`).join() === '@objectstack/verify#test', ); { - // The measured 2026-09-08 shape: the footer names verify alone while three - // more packages announced failure in the stream. - const log = [ - '@objectstack/verify:test: ELIFECYCLE Test failed. See above for more details.', - '@objectstack/plugin-auth:test: ELIFECYCLE Test failed. See above for more details.', - '@objectstack/runtime:test: ELIFECYCLE Test failed. See above for more details.', - '@objectstack/client:test: ELIFECYCLE Test failed. See above for more details.', - '@objectstack/verify#test: ERROR command (/w/packages/verify) /x/pnpm run test exited (1)', - 'Failed: @objectstack/verify#test', - ].join('\n'); - const got = failingTasks(log); + const p = readPass(`${elifecycle('@objectstack/plugin-auth')}\n`); + check('parse: an ELIFECYCLE line alone is INTERRUPTED, never failing', p.failing.length === 0, `failing ${p.failing}`); + check( + 'parse: an ELIFECYCLE line alone is INTERRUPTED, never failing', + p.interrupted.join() === '@objectstack/plugin-auth#test', + `interrupted ${p.interrupted}`, + ); + } + { + const p = readPass(NIGHT_1014_PASS1); + const label = 'parse: 2026-10-14 pass 1 -- dogfood failed, cli interrupted by fail-fast'; + check(label, p.failing.join() === '@objectstack/dogfood#test', `failing ${p.failing}`); + check(label, p.interrupted.join() === '@objectstack/cli#test', `interrupted ${p.interrupted}`); + check(label, p.timeoutOnly.join() === '@objectstack/dogfood#test', `timeoutOnly ${p.timeoutOnly}`); + check(label, p.ran.join() === '@objectstack/dogfood#test', `ran ${p.ran}`); + check(label, p.finished && p.started === 143 && p.successful === 141, `summary ${p.successful}/${p.started}`); + } + { + const p = readPass(NIGHT_1015_PASS2); + const label = 'parse: 2026-10-15 pass 2 -- runtime failed; verify, cli, organizations interrupted'; + check(label, p.failing.join() === '@objectstack/runtime#test', `failing ${p.failing}`); check( - 'parse: union under-reporting footer (2026-09-08 shape)', - got.length === 4 && got.includes('@objectstack/client#test') && got.includes('@objectstack/runtime#test'), - `got ${got.join(', ')}`, + label, + p.interrupted.join() === '@objectstack/cli#test,@objectstack/organizations#test,@objectstack/verify#test', + `interrupted ${p.interrupted}`, ); + check(label, p.timeoutOnly.join() === '@objectstack/runtime#test' && p.started === 142, `timeoutOnly ${p.timeoutOnly}`); } { const stamped = - '2026-09-17T04:46:54.4228362Z @objectstack/cli#test: ERROR command (/w/packages/cli) /x/pnpm run test exited (1)\n' + + `2026-09-17T04:46:54.4228362Z ${taskError('@objectstack/cli')}\n` + '2026-09-17T04:46:54.4229431Z Failed: @objectstack/cli#test\n'; check( 'parse: an API-downloaded log with ISO timestamps reads the same', @@ -319,22 +648,54 @@ function selfTest() { `got ${failingTasks(stamped).join(', ')}`, ); } - check( - 'parse: a green log names no failing task', - failingTasks(' Tasks: 140 successful, 140 total\n Time: 39m50.01s\n').length === 0, - ); + { + const p = readPass(' Tasks: 140 successful, 140 total\n Time: 39m50.01s\n'); + check('parse: a green log names no failing task and is finished', p.failing.length === 0 && p.interrupted.length === 0); + check('parse: a green log names no failing task and is finished', p.finished && p.started === 140); + } + { + const mixed = [ + failedTestsHeader('@objectstack/core:test:', 2), + timedOut('@objectstack/core:test:'), + '@objectstack/core:test: AssertionError: expected 4 to be 2', + taskError('@objectstack/core'), + ].join('\n'); + check('parse: timeout-only needs EVERY failed test to be a timeout', readPass(mixed).timeoutOnly.length === 0); + const suite = [ + `@objectstack/core:test: ${RULE} Failed Suites 1 ${RULE}`, + failedTestsHeader('@objectstack/core:test:', 1), + timedOut('@objectstack/core:test:'), + taskError('@objectstack/core'), + ].join('\n'); + check('parse: timeout-only needs EVERY failed test to be a timeout', readPass(suite).timeoutOnly.length === 0); + } + { + const annotated = [ + failedTestsHeader('@objectstack/core:test:', 2), + timedOut('@objectstack/core:test:'), + '@objectstack/core:test: AssertionError: expected 4 to be 2', + '@objectstack/core:test: ::error file=/w/a.test.ts,title=a::Error: Test timed out in 5000ms.', + taskError('@objectstack/core'), + ].join('\n'); + check('parse: the ::error annotation copy is not a second timeout', readPass(annotated).timeoutOnly.length === 0); + } + { + // What a pass looks like when its budget's SIGTERM reached turbo. + const cut = readPass(`${testFiles('@objectstack/core:test:', 0, 96)}\nShutting down Turborepo tasks...\n`); + check('parse: a log without turbo\'s closing summary did not finish', cut.finished === false && cut.started === null); + check('parse: a log without turbo\'s closing summary did not finish', readPass('').finished === false); + } // -- the verdict table --------------------------------------------------- const V = (p1, p2, f1 = [], f2 = []) => - verdict({ pass1Exit: p1, pass2Exit: p2, pass1Failing: f1, pass2Failing: f2 }); + verdict({ + pass1: passOf(p1, logOf({ failing: f1, ran: ['a#test', 'b#test', 'c#test'] })), + pass2: passOf(p2, logOf({ failing: f2, ran: ['a#test', 'b#test', 'c#test'] })), + }); { const v = V(0, 0); - check( - 'verdict: both green -> RERUN_SAFE, measured, exit 0', - v.code === 'RERUN_SAFE' && v.measured === true && v.exit === 0, - v.code, - ); + check('verdict: both green -> RERUN_SAFE, measured, exit 0', v.code === 'RERUN_SAFE' && v.coverage === 'full' && v.exit === 0, v.code); } { const v = V(0, 1, [], ['@objectstack/core#test']); @@ -357,8 +718,8 @@ function selfTest() { const v = V(1, 1, same, same); check( 'verdict: both red, same set -> BASELINE_BROKEN, measured, CLEAN', - v.code === 'BASELINE_BROKEN' && v.measured === true && v.headline.includes('CLEAN'), - v.code, + v.code === 'BASELINE_BROKEN' && v.coverage === 'full' && v.headline.includes('CLEAN'), + `${v.code} ${v.coverage}`, ); } { @@ -387,25 +748,110 @@ function selfTest() { ); } { - // The property the whole change turns on: a red baseline no longer costs - // the reading. Every non-stall combination must report measured=true. + // The shape measured locally (guard -> timeout -> turbo, stopped at 45 s): + // exit 124 through the guard, and the log ends at turbo's shutdown lines. + const pass1 = passOf(1, NIGHT_1014_PASS1); + const cut = passOf( + 124, + [ + testFiles('@objectstack/core:test:', 0, 96), + 'Shutting down Turborepo tasks...', + 'Force killed Turborepo tasks: @objectstack/core#test', + ].join('\n'), + ); + const v = verdict({ pass1, pass2: cut }); + check( + 'verdict: a pass that did not finish -> INCOMPLETE, NOT MEASURED, exit 1', + v.code === 'INCOMPLETE' && v.coverage === 'none' && v.measured === false && v.exit === 1, + `${v.code} ${v.coverage}`, + ); + check( + 'verdict: a pass that did not finish -> INCOMPLETE, NOT MEASURED, exit 1', + v.detail.some((d) => d.includes('Pass 2 (exit 124)') && d.includes("share of the job's time")) && + v.detail.includes('Failed in pass 1: @objectstack/dogfood#test'), + v.detail.join(' | '), + ); + } + { + // A budget stop that turbo still summarised: every task it killed is in + // its footer, and only the one whose vitest run reported a failure failed. + const budgetStopped = passOf( + 124, + [ + failedTestsHeader('@objectstack/core:test:', 1), + timedOut('@objectstack/core:test:'), + taskError('@objectstack/core'), + taskError('@objectstack/runtime'), + tasksSummary(40, 42), + 'Failed: @objectstack/core#test, @objectstack/runtime#test', + ].join('\n'), + ); + const v = verdict({ pass1: passOf(1, NIGHT_1014_PASS1), pass2: budgetStopped }); + check( + 'verdict: a pass that did not finish -> INCOMPLETE, NOT MEASURED, exit 1', + v.code === 'INCOMPLETE' && v.coverage === 'none', + `${v.code} ${v.coverage}`, + ); + check( + 'verdict: a pass that did not finish -> INCOMPLETE, NOT MEASURED, exit 1', + v.detail.includes('Failed in pass 2 before it stopped: @objectstack/core#test') && + v.detail.includes('Stopped mid-run in pass 2 by the time bound (unmeasured): @objectstack/runtime#test'), + v.detail.join(' | '), + ); + } + { + // Every FINISHED, non-stall combination still reports a reading. const combos = [V(0, 0), V(0, 1, [], ['a#test']), V(1, 0, ['a#test'], []), V(1, 1, ['a#test'], ['a#test']), V(1, 1, ['a#test'], ['a#test', 'b#test'])]; check( - 'verdict: every non-stall verdict reports measured=true', + 'verdict: every finished, non-stall verdict reports measured=true', combos.every((v) => v.measured === true), combos.map((v) => `${v.code}=${v.measured}`).join(' '), ); } + { + const v = verdict({ pass1: passOf(1, NIGHT_1014_PASS1), pass2: passOf(1, NIGHT_1014_PASS2) }); + const label = 'verdict: 2026-10-14 end to end -- no interrupted task is newly failing, coverage PARTIAL'; + const newly = v.detail.find((d) => d.startsWith('Newly failing on pass 2:')) ?? ''; + check(label, v.code === 'RERUN_UNSAFE_ON_BROKEN_BASELINE', v.code); + // The pre-#23880 reading named core, lint AND spec here. + check(label, newly === 'Newly failing on pass 2: @objectstack/core#test', newly); + check(label, v.coverage === 'partial' && v.measured === true, v.coverage); + check( + label, + v.detail.some((d) => d.includes('Interrupted by turbo in pass 1') && d.includes('@objectstack/cli#test')), + v.detail.join(' | '), + ); + } + { + const v = verdict({ pass1: passOf(1, NIGHT_1014_PASS1), pass2: passOf(1, NIGHT_1014_PASS2) }); + check( + 'verdict: a pass-1 failure pass 2 never finished is not re-measured, never recovered', + v.detail.some((d) => d.startsWith('Failed on pass 1 and never finished by pass 2') && d.includes('@objectstack/dogfood#test')) && + !v.detail.some((d) => d.includes('green on pass 2')), + v.detail.join(' | '), + ); + } // -- rendering ----------------------------------------------------------- { - const args = { pass1Exit: 1, pass2Exit: 1, pass1Failing: ['a#test'], pass2Failing: ['a#test'] }; - const text = renderVerdict(verdict(args), args); - const stall = { pass1Exit: STALL_EXIT_CODE, pass2Exit: 0, pass1Failing: [], pass2Failing: [] }; - const stallText = renderVerdict(verdict(stall), stall); + const full = { pass1: passOf(1, logOf({ failing: ['a#test'] })), pass2: passOf(1, logOf({ failing: ['a#test'] })) }; + const partial = { pass1: passOf(1, NIGHT_1014_PASS1), pass2: passOf(1, NIGHT_1014_PASS2) }; + const stall = { pass1: passOf(STALL_EXIT_CODE, ''), pass2: passOf(0, logOf()) }; + const text = (args) => renderVerdict(verdict(args), args); check( - 'render: the verdict line names MEASURED or NOT MEASURED', - text.includes('rerun property: MEASURED') && stallText.includes('rerun property: NOT MEASURED'), + 'render: the verdict line names MEASURED, PARTIALLY MEASURED or NOT MEASURED', + text(full).includes('rerun property: MEASURED') && + text(partial).includes('rerun property: PARTIALLY MEASURED') && + text(stall).includes('rerun property: NOT MEASURED'), + ); + } + { + const args = { pass1: passOf(1, NIGHT_1014_PASS1), pass2: passOf(1, NIGHT_1014_PASS2) }; + const out = renderVerdict(verdict(args), args); + check( + 'render: a timeout-only newly failing task carries the twice-on-its-own instruction', + out.includes('pnpm --filter @objectstack/core run test') && out.includes('@objectstack/core#test (timeout-only)'), + out, ); } @@ -487,12 +933,7 @@ function main(argv) { const t2 = read(pass2Log); if (t1 === null || t2 === null) return 2; - const args = { - pass1Exit, - pass2Exit, - pass1Failing: failingTasks(t1), - pass2Failing: failingTasks(t2), - }; + const args = { pass1: passOf(pass1Exit, t1), pass2: passOf(pass2Exit, t2) }; const v = verdict(args); console.log(renderVerdict(v, args)); if (v.exit !== 0) { @@ -502,10 +943,10 @@ function main(argv) { return v.exit; } -// This module EXPORTS `failingTasks` / `verdict` / `renderVerdict` so the -// workflow's verdict step and any future reader can use them, so its top level -// must not run on import -- an importer would otherwise be ended mid-import by -// the dispatch below (`pnpm check:entry-guard`). +// This module EXPORTS `readPass` / `failingTasks` / `verdict` / `renderVerdict` +// so the workflow's verdict step and any future reader can use them, so its top +// level must not run on import -- an importer would otherwise be ended +// mid-import by the dispatch below (`pnpm check:entry-guard`). if (isEntrypoint(import.meta.url)) { process.exitCode = main(process.argv.slice(2)); }