Skip to content

Commit e75e343

Browse files
os-steveclaude
andauthored
fix(ci): stall guard reads real liveness — --log-order=stream under every guard-wrapped turbo, guard refuses grouped, shard timings re-measured (#11868)
* fix(ci): stall guard must observe streaming output — pin --log-order=stream under every guard-wrapped turbo 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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015ahemw8RcTgqtxrj15PEZx * chore(ci): refresh test-shard-timings from a full cold re-measure 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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015ahemw8RcTgqtxrj15PEZx --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 1f9f93a commit e75e343

4 files changed

Lines changed: 196 additions & 78 deletions

File tree

.github/workflows/ci.yml

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -537,6 +537,17 @@ jobs:
537537
# a process whose event loop is alive, and a named "no report = blocked
538538
# loop" verdict for one that is sync-spinning. The next #4250 occurrence
539539
# identifies its own culprit instead of costing a diagnosis.
540+
#
541+
# --log-order=stream is MANDATORY under the guard, not a preference. The
542+
# guard measures output FLUSHES; turbo's default in CI is grouped log
543+
# order, which flushes a task's output only when the task ENDS — so a
544+
# shard whose tail is one task longer than --stall-minutes was killed BY
545+
# CONSTRUCTION, healthy or not (measured: a healthy cli:test killed at
546+
# exit 75 with 173/173 files passing in the flush the kill forced). The
547+
# guard now refuses to wrap a turbo run without this flag. Cost is
548+
# interleaved logs; the completeness guard below reads the per-line
549+
# `<pkg>:test:` prefixes stream order emits (a pinned parseSummaries
550+
# branch), so attribution survives.
540551
- name: Run this shard's tests
541552
env:
542553
NODE_OPTIONS: --report-on-signal --report-signal=SIGUSR2 --report-directory=${{ runner.temp }}/stall-reports
@@ -549,7 +560,7 @@ jobs:
549560
mkdir -p "$RUNNER_TEMP/stall-reports"
550561
node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 \
551562
--report-dir "$RUNNER_TEMP/stall-reports" -- \
552-
pnpm turbo run test $FILTERS --concurrency=4 --summarize
563+
pnpm turbo run test $FILTERS --concurrency=4 --summarize --log-order=stream
553564
554565
# --summarize above costs nothing at runtime and writes
555566
# `.turbo/runs/<id>.json`: one per-task record with the execution window
@@ -1121,7 +1132,7 @@ jobs:
11211132
mkdir -p "$RUNNER_TEMP/stall-reports"
11221133
node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/dogfood.log" --stall-minutes 10 \
11231134
--report-dir "$RUNNER_TEMP/stall-reports" -- \
1124-
pnpm turbo run test --filter=@objectstack/dogfood -- --shard=${{ matrix.shard }}/3
1135+
pnpm turbo run test --filter=@objectstack/dogfood --log-order=stream -- --shard=${{ matrix.shard }}/3
11251136
11261137
# Dogfood boots real apps in-process, so a native/OOM abort is likelier
11271138
# here than in the unit suites — and a shard that dies silently looks like

.github/workflows/rerun-safety-nightly.yml

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -83,10 +83,14 @@ jobs:
8383
# #4314) bounds a frozen-output hang at 15 min instead of letting a
8484
# nightly nobody watches sit until the 120-min timeout; on a stall it
8585
# exits 75 and its banner in the log names the last output line.
86+
# --log-order=stream is mandatory under the guard (see the Test Core
87+
# comment in ci.yml): grouped log order flushes a task's output only when
88+
# the task ends, so a solo tail task longer than the budget reads as
89+
# frozen while healthy. The guard refuses a turbo run without it.
8690
- name: Test suite — pass 1
8791
run: |
8892
node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass1.log" --stall-minutes 15 -- \
89-
pnpm turbo run test --concurrency=4 --force
93+
pnpm turbo run test --concurrency=4 --force --log-order=stream
9094
9195
# Informational only. A stray `.objectstack/` is how the #4065 class shows
9296
# up on disk, so printing what pass 1 left behind turns a pass-2 failure
@@ -110,7 +114,7 @@ jobs:
110114
run: |
111115
status=0
112116
node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/rerun-pass2.log" --stall-minutes 15 -- \
113-
pnpm turbo run test --concurrency=4 --force || status=$?
117+
pnpm turbo run test --concurrency=4 --force --log-order=stream || status=$?
114118
if [ "$status" -eq 0 ]; then
115119
exit 0
116120
elif [ "$status" -eq 75 ]; then

scripts/run-with-stall-guard.mjs

Lines changed: 98 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,22 @@
2626
// child's real exit status is propagated by construction, so there is no pipe
2727
// to guard. Do not reintroduce `| tee`.
2828
//
29+
// ## The instrument's one precondition: the wrapped command must STREAM
30+
//
31+
// The guard measures output FLUSHES, so it is only a liveness instrument when
32+
// the wrapped pipeline flushes while work is running. Turbo's default log
33+
// order in CI is GROUPED — a task's output is buffered and flushed only when
34+
// the task ENDS — which turns "one task still running" into "zero bytes", and
35+
// a shard whose tail is a single task longer than --stall-minutes into a
36+
// guaranteed kill of a HEALTHY suite (measured twice in one day: exit 75 with
37+
// `Test Files 173 passed (173)` arriving in the very flush the kill forced,
38+
// stamped ~40ms after it). That red reproduces on rerun, so it reads as "not
39+
// a flake, therefore the diff" — the exact false trail #4250's triage line
40+
// warns against. So the precondition is ENFORCED, not documented: a wrapped
41+
// command that invokes turbo without `--log-order=stream` is refused at
42+
// startup (exit 1, before anything runs). pnpm's recursive runner streams
43+
// with per-package prefixes (measured), so non-turbo callers are untouched.
44+
//
2945
// ## Stall forensics (before the kill)
3046
//
3147
// 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
130146
process.exit(1);
131147
}
132148

149+
// The precondition check from the header: a turbo invocation under this guard
150+
// must pin `--log-order=stream`, or the guard's instrument (output flushes)
151+
// measures buffering artifacts instead of liveness and kills healthy suites by
152+
// construction. Deliberately NOT exported — importing this file would execute
153+
// it (it is an entrypoint, not a library); the self-test pins both directions
154+
// through real subprocess invocations instead.
155+
function turboLogOrderViolation(argv) {
156+
const runsTurbo = argv.some(
157+
(tok) => !tok.startsWith('-') && (tok === 'turbo' || tok.endsWith('/turbo')),
158+
);
159+
if (!runsTurbo) return false;
160+
const streams = argv.some(
161+
(tok, i) =>
162+
tok === '--log-order=stream' || (tok === '--log-order' && argv[i + 1] === 'stream'),
163+
);
164+
return !streams;
165+
}
166+
167+
if (turboLogOrderViolation(command)) {
168+
console.error(
169+
'run-with-stall-guard: REFUSING to wrap a turbo invocation without --log-order=stream.\n' +
170+
" This guard measures output flushes. Turbo's default log order in CI is grouped —\n" +
171+
' a task flushes only when it ENDS — so a task running longer than --stall-minutes\n' +
172+
' emits zero bytes and is killed as a stall while perfectly healthy (a deterministic\n' +
173+
' red on an innocent diff; it happened, twice in one day, with every test passing).\n' +
174+
' Add --log-order=stream to the turbo command so the guard observes real liveness.',
175+
);
176+
process.exit(1);
177+
}
178+
133179
const stallMs = stallMinutes * 60_000;
134180
const log = createWriteStream(logPath, { flags: 'w' });
135181

@@ -525,6 +571,58 @@ async function selfTest() {
525571
code === 0 && !out.includes('STALL'), `exit ${code}`);
526572
}
527573

574+
// -- 3b. The turbo log-order precondition, both directions. --
575+
// Grouped log order flushes a task's output only when the task ends, so
576+
// a guard-wrapped turbo without --log-order=stream kills a healthy solo
577+
// tail task BY CONSTRUCTION (the 2026-08-24 healthy-kill pair: exit 75
578+
// with 173/173 files passing in the flush the kill forced). The wrap is
579+
// refused before anything spawns. Refusal shapes use a bare `turbo`
580+
// that never runs; accepted turbo-shapes use a nonexistent path so the
581+
// verdict is "failed to start", never a real turbo against this repo.
582+
{
583+
const refused = await runGuard(
584+
['--log', join(dir, 'lo1.log'), ...WINDOW, '--', 'turbo', 'run', 'test'],
585+
{}, { marker: dir },
586+
);
587+
check('a guard-wrapped turbo without --log-order=stream is refused',
588+
refused.code === 1 && refused.out.includes('REFUSING'), `exit ${refused.code}`);
589+
check('the refusal happens before anything runs (no stall verdict, no spawn)',
590+
!refused.out.includes('STALL') && !refused.out.includes('failed to start'));
591+
592+
const viaPnpm = await runGuard(
593+
['--log', join(dir, 'lo2.log'), ...WINDOW, '--',
594+
'pnpm', 'turbo', 'run', 'test', '--concurrency=4', '--log-order=grouped'],
595+
{}, { marker: dir },
596+
);
597+
check('an explicit --log-order=grouped is refused too',
598+
viaPnpm.code === 1 && viaPnpm.out.includes('REFUSING'), `exit ${viaPnpm.code}`);
599+
600+
const streamed = await runGuard(
601+
['--log', join(dir, 'lo3.log'), ...WINDOW, '--',
602+
'/nonexistent/turbo', 'run', 'test', '--log-order=stream'],
603+
{}, { marker: dir },
604+
);
605+
check('--log-order=stream lifts the refusal (reaches spawn)',
606+
!streamed.out.includes('REFUSING') && streamed.out.includes('failed to start'),
607+
streamed.out.trim().split('\n')[0]);
608+
609+
const spaced = await runGuard(
610+
['--log', join(dir, 'lo4.log'), ...WINDOW, '--',
611+
'/nonexistent/turbo', 'run', 'test', '--log-order', 'stream'],
612+
{}, { marker: dir },
613+
);
614+
check('the split `--log-order stream` spelling is accepted as well',
615+
!spaced.out.includes('REFUSING') && spaced.out.includes('failed to start'));
616+
617+
const flagValue = await runGuard(
618+
['--log', join(dir, 'lo5.log'), ...WINDOW, '--',
619+
'sh', '-c', 'echo turbo-adjacent ok', 'sh', '--tag=turbo'],
620+
{}, { marker: dir },
621+
);
622+
check('`turbo` inside a flag value does not trip the refusal',
623+
flagValue.code === 0 && !flagValue.out.includes('REFUSING'), `exit ${flagValue.code}`);
624+
}
625+
528626
// -- 4. Idle hang: event loop alive, nothing will ever settle. --
529627
// The "await-type" stall — a promise that never resolves.
530628
{

scripts/test-shard-timings.json

Lines changed: 79 additions & 74 deletions
Original file line numberDiff line numberDiff line change
@@ -1,86 +1,91 @@
11
{
22
"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.",
33
"provenance": {
4-
"measuredAt": "2026-08-21",
4+
"measuredAt": "2026-08-24",
55
"summaries": [
6-
"3ICjPcWZuu9pHEf6IHQBTzfZbgE.json"
6+
"3INZWsDPxzZHTiHyMLtMaW3QzzS.json",
7+
"3INauIhwAvRiujuKKwByt4oUHia.json",
8+
"3INblkezuMcTpRYH7dacKvoCrKN.json",
9+
"3INcmCJVPcuFrxIblRK7pEmTaM9.json",
10+
"3INddg5OSvLXaJIzH4NoHlu5lUk.json",
11+
"3INdx8H55OYIsI3ezcpzRBx3GDO.json"
712
],
813
"mergeRule": "median across summaries",
914
"refresh": "node scripts/measure-test-shard-timings.mjs <run-summary.json>... --out scripts/test-shard-timings.json (summaries: the `test-core-run-summary-<n>-of-6` artifacts of any green merge_group run, or a local `pnpm exec turbo run test --concurrency=4 --summarize`)"
1015
},
11-
"secondsPerTestFileFallback": 1.726,
16+
"secondsPerTestFileFallback": 1.522,
1217
"packages": {
13-
"@objectstack/cli": 392.11,
14-
"@objectstack/client": 48.41,
15-
"@objectstack/client-react": 9.85,
16-
"@objectstack/cloud-connection": 39.2,
17-
"@objectstack/connector-mcp": 14.68,
18-
"@objectstack/connector-openapi": 3.24,
19-
"@objectstack/connector-rest": 16.84,
20-
"@objectstack/connector-slack": 15.31,
21-
"@objectstack/core": 16.4,
22-
"@objectstack/downstream-contract": 9.89,
23-
"@objectstack/driver-memory": 32.22,
24-
"@objectstack/driver-mongodb": 38.6,
25-
"@objectstack/driver-sql": 115.34,
26-
"@objectstack/driver-sqlite-wasm": 34.84,
27-
"@objectstack/driver-turso": 70.3,
28-
"@objectstack/embedder-openai": 4.09,
29-
"@objectstack/example-crm": 32.97,
30-
"@objectstack/example-embed-objectql": 15.57,
31-
"@objectstack/example-showcase": 70.12,
32-
"@objectstack/example-todo": 33.77,
33-
"@objectstack/formula": 17.88,
34-
"@objectstack/hono": 6.89,
35-
"@objectstack/http-conformance": 32.74,
36-
"@objectstack/knowledge-memory": 2.91,
37-
"@objectstack/knowledge-ragflow": 3.36,
38-
"@objectstack/lint": 49.06,
39-
"@objectstack/mcp": 23.73,
40-
"@objectstack/metadata": 38.35,
41-
"@objectstack/metadata-core": 9.23,
42-
"@objectstack/metadata-fs": 30.52,
43-
"@objectstack/metadata-protocol": 219.07,
44-
"@objectstack/objectql": 323.79,
45-
"@objectstack/observability": 3.31,
46-
"@objectstack/platform-objects": 24.38,
47-
"@objectstack/plugin-approvals": 46.71,
48-
"@objectstack/plugin-audit": 42.55,
49-
"@objectstack/plugin-auth": 122.76,
50-
"@objectstack/plugin-dev": 17.14,
51-
"@objectstack/plugin-email": 36.28,
52-
"@objectstack/plugin-hono-server": 25.14,
53-
"@objectstack/plugin-pinyin-search": 19.39,
54-
"@objectstack/plugin-reports": 20.15,
55-
"@objectstack/plugin-security": 74.91,
56-
"@objectstack/plugin-sharing": 61.26,
57-
"@objectstack/plugin-webhooks": 22.03,
58-
"@objectstack/rest": 183.99,
59-
"@objectstack/runtime": 321.05,
60-
"@objectstack/sdui-parser": 6.29,
61-
"@objectstack/service-analytics": 70.2,
62-
"@objectstack/service-automation": 84.66,
63-
"@objectstack/service-cache": 2.55,
64-
"@objectstack/service-cluster": 4.45,
65-
"@objectstack/service-cluster-redis": 6.41,
66-
"@objectstack/service-datasource": 30.74,
67-
"@objectstack/service-i18n": 11.69,
68-
"@objectstack/service-job": 7.6,
69-
"@objectstack/service-knowledge": 19.21,
70-
"@objectstack/service-messaging": 27.18,
71-
"@objectstack/service-package": 5.68,
72-
"@objectstack/service-queue": 19.8,
73-
"@objectstack/service-realtime": 5.61,
74-
"@objectstack/service-settings": 38.41,
75-
"@objectstack/service-sms": 12.94,
76-
"@objectstack/service-storage": 40.29,
77-
"@objectstack/spec": 570.53,
78-
"@objectstack/trigger-api": 2.55,
79-
"@objectstack/trigger-record-change": 32.52,
80-
"@objectstack/trigger-schedule": 16.27,
81-
"@objectstack/types": 9.09,
82-
"@objectstack/verify": 61.75,
83-
"create-objectstack": 16.18
18+
"@objectstack/cli": 458.15,
19+
"@objectstack/client": 32.29,
20+
"@objectstack/client-react": 8.12,
21+
"@objectstack/cloud-connection": 33.64,
22+
"@objectstack/connector-mcp": 9.95,
23+
"@objectstack/connector-openapi": 10.31,
24+
"@objectstack/connector-rest": 8.29,
25+
"@objectstack/connector-slack": 9.52,
26+
"@objectstack/core": 15.1,
27+
"@objectstack/downstream-contract": 9.88,
28+
"@objectstack/driver-memory": 51.03,
29+
"@objectstack/driver-mongodb": 40.03,
30+
"@objectstack/driver-sql": 203.97,
31+
"@objectstack/driver-sqlite-wasm": 57.96,
32+
"@objectstack/driver-turso": 76.52,
33+
"@objectstack/embedder-openai": 3.51,
34+
"@objectstack/example-crm": 27.7,
35+
"@objectstack/example-embed-objectql": 19.6,
36+
"@objectstack/example-showcase": 22.87,
37+
"@objectstack/example-todo": 30.46,
38+
"@objectstack/formula": 12.39,
39+
"@objectstack/hono": 5.07,
40+
"@objectstack/http-conformance": 40.88,
41+
"@objectstack/knowledge-memory": 1.39,
42+
"@objectstack/knowledge-ragflow": 1.44,
43+
"@objectstack/lint": 86.66,
44+
"@objectstack/mcp": 34.44,
45+
"@objectstack/metadata": 43.03,
46+
"@objectstack/metadata-core": 9.38,
47+
"@objectstack/metadata-fs": 30.54,
48+
"@objectstack/metadata-protocol": 278.86,
49+
"@objectstack/objectql": 222.2,
50+
"@objectstack/observability": 2.17,
51+
"@objectstack/platform-objects": 18.78,
52+
"@objectstack/plugin-approvals": 31.07,
53+
"@objectstack/plugin-audit": 36.37,
54+
"@objectstack/plugin-auth": 221.71,
55+
"@objectstack/plugin-dev": 14.67,
56+
"@objectstack/plugin-email": 39.1,
57+
"@objectstack/plugin-hono-server": 25.18,
58+
"@objectstack/plugin-pinyin-search": 14.4,
59+
"@objectstack/plugin-reports": 33.34,
60+
"@objectstack/plugin-security": 114.92,
61+
"@objectstack/plugin-sharing": 62.69,
62+
"@objectstack/plugin-webhooks": 25.97,
63+
"@objectstack/rest": 236.68,
64+
"@objectstack/runtime": 264.23,
65+
"@objectstack/sdui-parser": 1.62,
66+
"@objectstack/service-analytics": 103.62,
67+
"@objectstack/service-automation": 128.89,
68+
"@objectstack/service-cache": 1.86,
69+
"@objectstack/service-cluster": 3.72,
70+
"@objectstack/service-cluster-redis": 3.61,
71+
"@objectstack/service-datasource": 32.19,
72+
"@objectstack/service-i18n": 10.05,
73+
"@objectstack/service-job": 8.44,
74+
"@objectstack/service-knowledge": 15.21,
75+
"@objectstack/service-messaging": 28.44,
76+
"@objectstack/service-package": 7.54,
77+
"@objectstack/service-queue": 16.03,
78+
"@objectstack/service-realtime": 3.66,
79+
"@objectstack/service-settings": 41.61,
80+
"@objectstack/service-sms": 11.02,
81+
"@objectstack/service-storage": 29.28,
82+
"@objectstack/spec": 403.65,
83+
"@objectstack/trigger-api": 1.72,
84+
"@objectstack/trigger-record-change": 23.53,
85+
"@objectstack/trigger-schedule": 13.49,
86+
"@objectstack/types": 5.69,
87+
"@objectstack/verify": 83.98,
88+
"create-objectstack": 15.5
8489
},
8590
"skippedAsCached": []
8691
}

0 commit comments

Comments
 (0)