From e23a603951eb34fa86f4611921d987612b772c0f Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 24 Aug 2026 21:19:20 +0000 Subject: [PATCH 1/2] =?UTF-8?q?fix(ci):=20stall=20guard=20must=20observe?= =?UTF-8?q?=20streaming=20output=20=E2=80=94=20pin=20--log-order=3Dstream?= =?UTF-8?q?=20under=20every=20guard-wrapped=20turbo?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The guard measures output flushes; turbo's CI default is grouped log order, which flushes a task's output only when the task ends. A shard whose tail is one task longer than --stall-minutes was therefore killed as a stall while perfectly healthy. Pin --log-order=stream at all four guard-wrapped turbo call sites, and make the guard refuse a turbo invocation without the flag so the class cannot regress silently (self-test pins both directions). Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015ahemw8RcTgqtxrj15PEZx --- .github/workflows/ci.yml | 15 +++- .github/workflows/rerun-safety-nightly.yml | 8 +- scripts/run-with-stall-guard.mjs | 98 ++++++++++++++++++++++ 3 files changed, 117 insertions(+), 4 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 11d29a27fb..fef3f452af 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -537,6 +537,17 @@ jobs: # a process whose event loop is alive, and a named "no report = blocked # loop" verdict for one that is sync-spinning. The next #4250 occurrence # identifies its own culprit instead of costing a diagnosis. + # + # --log-order=stream is MANDATORY under the guard, not a preference. The + # guard measures output FLUSHES; turbo's default in CI is grouped log + # order, which flushes a task's output only when the task ENDS — so a + # shard whose tail is one task longer than --stall-minutes was killed BY + # CONSTRUCTION, healthy or not (measured: a healthy cli:test killed at + # exit 75 with 173/173 files passing in the flush the kill forced). The + # guard now refuses to wrap a turbo run without this flag. Cost is + # interleaved logs; the completeness guard below reads the per-line + # `:test:` prefixes stream order emits (a pinned parseSummaries + # branch), so attribution survives. - name: Run this shard's tests env: NODE_OPTIONS: --report-on-signal --report-signal=SIGUSR2 --report-directory=${{ runner.temp }}/stall-reports @@ -549,7 +560,7 @@ jobs: mkdir -p "$RUNNER_TEMP/stall-reports" node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 \ --report-dir "$RUNNER_TEMP/stall-reports" -- \ - pnpm turbo run test $FILTERS --concurrency=4 --summarize + pnpm turbo run test $FILTERS --concurrency=4 --summarize --log-order=stream # --summarize above costs nothing at runtime and writes # `.turbo/runs/.json`: one per-task record with the execution window @@ -1121,7 +1132,7 @@ jobs: mkdir -p "$RUNNER_TEMP/stall-reports" node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/dogfood.log" --stall-minutes 10 \ --report-dir "$RUNNER_TEMP/stall-reports" -- \ - pnpm turbo run test --filter=@objectstack/dogfood -- --shard=${{ matrix.shard }}/3 + pnpm turbo run test --filter=@objectstack/dogfood --log-order=stream -- --shard=${{ matrix.shard }}/3 # Dogfood boots real apps in-process, so a native/OOM abort is likelier # here than in the unit suites — and a shard that dies silently looks like diff --git a/.github/workflows/rerun-safety-nightly.yml b/.github/workflows/rerun-safety-nightly.yml index 5ff48d2837..41e5b73acc 100644 --- a/.github/workflows/rerun-safety-nightly.yml +++ b/.github/workflows/rerun-safety-nightly.yml @@ -83,10 +83,14 @@ jobs: # #4314) bounds a frozen-output hang at 15 min instead of letting a # nightly nobody watches sit until the 120-min timeout; on a stall it # exits 75 and its banner in the log names the last output line. + # --log-order=stream is mandatory under the guard (see the Test Core + # 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. - name: Test suite — pass 1 run: | node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass1.log" --stall-minutes 15 -- \ - pnpm turbo run test --concurrency=4 --force + pnpm turbo run test --concurrency=4 --force --log-order=stream # Informational only. A stray `.objectstack/` is how the #4065 class shows # up on disk, so printing what pass 1 left behind turns a pass-2 failure @@ -110,7 +114,7 @@ jobs: run: | 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 || status=$? + pnpm turbo run test --concurrency=4 --force --log-order=stream || status=$? if [ "$status" -eq 0 ]; then exit 0 elif [ "$status" -eq 75 ]; then diff --git a/scripts/run-with-stall-guard.mjs b/scripts/run-with-stall-guard.mjs index c02a217b57..b138783119 100644 --- a/scripts/run-with-stall-guard.mjs +++ b/scripts/run-with-stall-guard.mjs @@ -26,6 +26,22 @@ // child's real exit status is propagated by construction, so there is no pipe // to guard. Do not reintroduce `| tee`. // +// ## The instrument's one precondition: the wrapped command must STREAM +// +// The guard measures output FLUSHES, so it is only a liveness instrument when +// the wrapped pipeline flushes while work is running. Turbo's default log +// order in CI is GROUPED — a task's output is buffered and flushed only when +// the task ENDS — which turns "one task still running" into "zero bytes", and +// a shard whose tail is a single task longer than --stall-minutes into a +// guaranteed kill of a HEALTHY suite (measured twice in one day: exit 75 with +// `Test Files 173 passed (173)` arriving in the very flush the kill forced, +// stamped ~40ms after it). That red reproduces on rerun, so it reads as "not +// a flake, therefore the diff" — the exact false trail #4250's triage line +// warns against. So the precondition is ENFORCED, not documented: a wrapped +// command that invokes turbo without `--log-order=stream` is refused at +// startup (exit 1, before anything runs). pnpm's recursive runner streams +// with per-package prefixes (measured), so non-turbo callers are untouched. +// // ## Stall forensics (before the kill) // // A declared stall triages itself instead of leaving a mystery for a human: @@ -130,6 +146,36 @@ if (!logPath || command.length === 0 || !Number.isFinite(stallMinutes) || stallM process.exit(1); } +// The precondition check from the header: a turbo invocation under this guard +// must pin `--log-order=stream`, or the guard's instrument (output flushes) +// measures buffering artifacts instead of liveness and kills healthy suites by +// construction. Deliberately NOT exported — importing this file would execute +// it (it is an entrypoint, not a library); the self-test pins both directions +// through real subprocess invocations instead. +function turboLogOrderViolation(argv) { + const runsTurbo = argv.some( + (tok) => !tok.startsWith('-') && (tok === 'turbo' || tok.endsWith('/turbo')), + ); + if (!runsTurbo) return false; + const streams = argv.some( + (tok, i) => + tok === '--log-order=stream' || (tok === '--log-order' && argv[i + 1] === 'stream'), + ); + return !streams; +} + +if (turboLogOrderViolation(command)) { + console.error( + 'run-with-stall-guard: REFUSING to wrap a turbo invocation without --log-order=stream.\n' + + " This guard measures output flushes. Turbo's default log order in CI is grouped —\n" + + ' a task flushes only when it ENDS — so a task running longer than --stall-minutes\n' + + ' emits zero bytes and is killed as a stall while perfectly healthy (a deterministic\n' + + ' red on an innocent diff; it happened, twice in one day, with every test passing).\n' + + ' Add --log-order=stream to the turbo command so the guard observes real liveness.', + ); + process.exit(1); +} + const stallMs = stallMinutes * 60_000; const log = createWriteStream(logPath, { flags: 'w' }); @@ -525,6 +571,58 @@ async function selfTest() { code === 0 && !out.includes('STALL'), `exit ${code}`); } + // -- 3b. The turbo log-order precondition, both directions. -- + // Grouped log order flushes a task's output only when the task ends, so + // a guard-wrapped turbo without --log-order=stream kills a healthy solo + // tail task BY CONSTRUCTION (the 2026-08-24 healthy-kill pair: exit 75 + // with 173/173 files passing in the flush the kill forced). The wrap is + // refused before anything spawns. Refusal shapes use a bare `turbo` + // that never runs; accepted turbo-shapes use a nonexistent path so the + // verdict is "failed to start", never a real turbo against this repo. + { + const refused = await runGuard( + ['--log', join(dir, 'lo1.log'), ...WINDOW, '--', 'turbo', 'run', 'test'], + {}, { marker: dir }, + ); + check('a guard-wrapped turbo without --log-order=stream is refused', + refused.code === 1 && refused.out.includes('REFUSING'), `exit ${refused.code}`); + check('the refusal happens before anything runs (no stall verdict, no spawn)', + !refused.out.includes('STALL') && !refused.out.includes('failed to start')); + + const viaPnpm = await runGuard( + ['--log', join(dir, 'lo2.log'), ...WINDOW, '--', + 'pnpm', 'turbo', 'run', 'test', '--concurrency=4', '--log-order=grouped'], + {}, { marker: dir }, + ); + check('an explicit --log-order=grouped is refused too', + viaPnpm.code === 1 && viaPnpm.out.includes('REFUSING'), `exit ${viaPnpm.code}`); + + const streamed = await runGuard( + ['--log', join(dir, 'lo3.log'), ...WINDOW, '--', + '/nonexistent/turbo', 'run', 'test', '--log-order=stream'], + {}, { marker: dir }, + ); + check('--log-order=stream lifts the refusal (reaches spawn)', + !streamed.out.includes('REFUSING') && streamed.out.includes('failed to start'), + streamed.out.trim().split('\n')[0]); + + const spaced = await runGuard( + ['--log', join(dir, 'lo4.log'), ...WINDOW, '--', + '/nonexistent/turbo', 'run', 'test', '--log-order', 'stream'], + {}, { marker: dir }, + ); + check('the split `--log-order stream` spelling is accepted as well', + !spaced.out.includes('REFUSING') && spaced.out.includes('failed to start')); + + const flagValue = await runGuard( + ['--log', join(dir, 'lo5.log'), ...WINDOW, '--', + 'sh', '-c', 'echo turbo-adjacent ok', 'sh', '--tag=turbo'], + {}, { marker: dir }, + ); + check('`turbo` inside a flag value does not trip the refusal', + flagValue.code === 0 && !flagValue.out.includes('REFUSING'), `exit ${flagValue.code}`); + } + // -- 4. Idle hang: event loop alive, nothing will ever settle. -- // The "await-type" stall — a promise that never resolves. { From d81806a4fd7674e5472c4c27f22ab5b85f9b7ecc Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 24 Aug 2026 22:07:52 +0000 Subject: [PATCH 2/2] chore(ci): refresh test-shard-timings from a full cold re-measure MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Regenerated per the dataset's own provenance recipe (4-vCPU box, --concurrency=4 --summarize, generator merge across six run summaries with disjoint filter sets — every test task a genuine MISS, zero cached). cli 392.11s -> 458.15s on this box (>601s alive-at-kill on the CI runner), the ~2x under-weight that was skewing every shard split. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015ahemw8RcTgqtxrj15PEZx --- scripts/test-shard-timings.json | 153 +++++++++++++++++--------------- 1 file changed, 79 insertions(+), 74 deletions(-) diff --git a/scripts/test-shard-timings.json b/scripts/test-shard-timings.json index d106492c82..e92006521c 100644 --- a/scripts/test-shard-timings.json +++ b/scripts/test-shard-timings.json @@ -1,86 +1,91 @@ { "note": "GENERATED by scripts/measure-test-shard-timings.mjs -- do not hand-edit. Per-package `turbo run test` durations in seconds, the balancing input for the Test Core shard split (scripts/partition-test-shards.mjs). See `provenance.refresh` to regenerate.", "provenance": { - "measuredAt": "2026-08-21", + "measuredAt": "2026-08-24", "summaries": [ - "3ICjPcWZuu9pHEf6IHQBTzfZbgE.json" + "3INZWsDPxzZHTiHyMLtMaW3QzzS.json", + "3INauIhwAvRiujuKKwByt4oUHia.json", + "3INblkezuMcTpRYH7dacKvoCrKN.json", + "3INcmCJVPcuFrxIblRK7pEmTaM9.json", + "3INddg5OSvLXaJIzH4NoHlu5lUk.json", + "3INdx8H55OYIsI3ezcpzRBx3GDO.json" ], "mergeRule": "median across summaries", "refresh": "node scripts/measure-test-shard-timings.mjs ... --out scripts/test-shard-timings.json (summaries: the `test-core-run-summary--of-6` artifacts of any green merge_group run, or a local `pnpm exec turbo run test --concurrency=4 --summarize`)" }, - "secondsPerTestFileFallback": 1.726, + "secondsPerTestFileFallback": 1.522, "packages": { - "@objectstack/cli": 392.11, - "@objectstack/client": 48.41, - "@objectstack/client-react": 9.85, - "@objectstack/cloud-connection": 39.2, - "@objectstack/connector-mcp": 14.68, - "@objectstack/connector-openapi": 3.24, - "@objectstack/connector-rest": 16.84, - "@objectstack/connector-slack": 15.31, - "@objectstack/core": 16.4, - "@objectstack/downstream-contract": 9.89, - "@objectstack/driver-memory": 32.22, - "@objectstack/driver-mongodb": 38.6, - "@objectstack/driver-sql": 115.34, - "@objectstack/driver-sqlite-wasm": 34.84, - "@objectstack/driver-turso": 70.3, - "@objectstack/embedder-openai": 4.09, - "@objectstack/example-crm": 32.97, - "@objectstack/example-embed-objectql": 15.57, - "@objectstack/example-showcase": 70.12, - "@objectstack/example-todo": 33.77, - "@objectstack/formula": 17.88, - "@objectstack/hono": 6.89, - "@objectstack/http-conformance": 32.74, - "@objectstack/knowledge-memory": 2.91, - "@objectstack/knowledge-ragflow": 3.36, - "@objectstack/lint": 49.06, - "@objectstack/mcp": 23.73, - "@objectstack/metadata": 38.35, - "@objectstack/metadata-core": 9.23, - "@objectstack/metadata-fs": 30.52, - "@objectstack/metadata-protocol": 219.07, - "@objectstack/objectql": 323.79, - "@objectstack/observability": 3.31, - "@objectstack/platform-objects": 24.38, - "@objectstack/plugin-approvals": 46.71, - "@objectstack/plugin-audit": 42.55, - "@objectstack/plugin-auth": 122.76, - "@objectstack/plugin-dev": 17.14, - "@objectstack/plugin-email": 36.28, - "@objectstack/plugin-hono-server": 25.14, - "@objectstack/plugin-pinyin-search": 19.39, - "@objectstack/plugin-reports": 20.15, - "@objectstack/plugin-security": 74.91, - "@objectstack/plugin-sharing": 61.26, - "@objectstack/plugin-webhooks": 22.03, - "@objectstack/rest": 183.99, - "@objectstack/runtime": 321.05, - "@objectstack/sdui-parser": 6.29, - "@objectstack/service-analytics": 70.2, - "@objectstack/service-automation": 84.66, - "@objectstack/service-cache": 2.55, - "@objectstack/service-cluster": 4.45, - "@objectstack/service-cluster-redis": 6.41, - "@objectstack/service-datasource": 30.74, - "@objectstack/service-i18n": 11.69, - "@objectstack/service-job": 7.6, - "@objectstack/service-knowledge": 19.21, - "@objectstack/service-messaging": 27.18, - "@objectstack/service-package": 5.68, - "@objectstack/service-queue": 19.8, - "@objectstack/service-realtime": 5.61, - "@objectstack/service-settings": 38.41, - "@objectstack/service-sms": 12.94, - "@objectstack/service-storage": 40.29, - "@objectstack/spec": 570.53, - "@objectstack/trigger-api": 2.55, - "@objectstack/trigger-record-change": 32.52, - "@objectstack/trigger-schedule": 16.27, - "@objectstack/types": 9.09, - "@objectstack/verify": 61.75, - "create-objectstack": 16.18 + "@objectstack/cli": 458.15, + "@objectstack/client": 32.29, + "@objectstack/client-react": 8.12, + "@objectstack/cloud-connection": 33.64, + "@objectstack/connector-mcp": 9.95, + "@objectstack/connector-openapi": 10.31, + "@objectstack/connector-rest": 8.29, + "@objectstack/connector-slack": 9.52, + "@objectstack/core": 15.1, + "@objectstack/downstream-contract": 9.88, + "@objectstack/driver-memory": 51.03, + "@objectstack/driver-mongodb": 40.03, + "@objectstack/driver-sql": 203.97, + "@objectstack/driver-sqlite-wasm": 57.96, + "@objectstack/driver-turso": 76.52, + "@objectstack/embedder-openai": 3.51, + "@objectstack/example-crm": 27.7, + "@objectstack/example-embed-objectql": 19.6, + "@objectstack/example-showcase": 22.87, + "@objectstack/example-todo": 30.46, + "@objectstack/formula": 12.39, + "@objectstack/hono": 5.07, + "@objectstack/http-conformance": 40.88, + "@objectstack/knowledge-memory": 1.39, + "@objectstack/knowledge-ragflow": 1.44, + "@objectstack/lint": 86.66, + "@objectstack/mcp": 34.44, + "@objectstack/metadata": 43.03, + "@objectstack/metadata-core": 9.38, + "@objectstack/metadata-fs": 30.54, + "@objectstack/metadata-protocol": 278.86, + "@objectstack/objectql": 222.2, + "@objectstack/observability": 2.17, + "@objectstack/platform-objects": 18.78, + "@objectstack/plugin-approvals": 31.07, + "@objectstack/plugin-audit": 36.37, + "@objectstack/plugin-auth": 221.71, + "@objectstack/plugin-dev": 14.67, + "@objectstack/plugin-email": 39.1, + "@objectstack/plugin-hono-server": 25.18, + "@objectstack/plugin-pinyin-search": 14.4, + "@objectstack/plugin-reports": 33.34, + "@objectstack/plugin-security": 114.92, + "@objectstack/plugin-sharing": 62.69, + "@objectstack/plugin-webhooks": 25.97, + "@objectstack/rest": 236.68, + "@objectstack/runtime": 264.23, + "@objectstack/sdui-parser": 1.62, + "@objectstack/service-analytics": 103.62, + "@objectstack/service-automation": 128.89, + "@objectstack/service-cache": 1.86, + "@objectstack/service-cluster": 3.72, + "@objectstack/service-cluster-redis": 3.61, + "@objectstack/service-datasource": 32.19, + "@objectstack/service-i18n": 10.05, + "@objectstack/service-job": 8.44, + "@objectstack/service-knowledge": 15.21, + "@objectstack/service-messaging": 28.44, + "@objectstack/service-package": 7.54, + "@objectstack/service-queue": 16.03, + "@objectstack/service-realtime": 3.66, + "@objectstack/service-settings": 41.61, + "@objectstack/service-sms": 11.02, + "@objectstack/service-storage": 29.28, + "@objectstack/spec": 403.65, + "@objectstack/trigger-api": 1.72, + "@objectstack/trigger-record-change": 23.53, + "@objectstack/trigger-schedule": 13.49, + "@objectstack/types": 5.69, + "@objectstack/verify": 83.98, + "create-objectstack": 15.5 }, "skippedAsCached": [] }