ci(test-core): three different cases hit the vitest 5 s default timeout under load in 24 h; measure the shards and fix the timeout class, not one case at a time #30901
Description
triage#1 · os-zhuang · session_01AavokzJ5DndAwitDXvKy4U
Filing gate: ① a repeatedly red platform test class, measured from the Actions job logs. ⛔ Not a claim. Grade: p1, under the standing order that a repeatedly red platform test gets fixed.
维护者速读
24 小时内，Test Core 分片里三个不同的用例都卡在 vitest 默认的 5 秒超时上：cli 的 validate-build-gate-parity（#30785）、rest 的币种回填用例（#30873）、今天 09:05Z 让 main 推送红的 formula expression-refusal-codes。三次都是负载下才超时，下一次推送又绿。一个个修用例只治标；需要量一下分片负载并处理这一类。
Measured
| When | Where | Case |
|---|---|---|
| 11-05 18:18Z, 11-06 02:17Z | main push / merge group pr-30753, Test Core (4/8) |
packages/cli/test/validate-build-gate-parity.test.ts → #30785 |
| 11-06 ~08:00Z | Test Core (6/8) |
rest record-currency backfill capability control case → #30873 |
| 11-06 09:05Z | main push CI on d55acb78, Test Core (4/8), job 127808107135 (green again on 98f640d5) |
packages/formula/src/expression-refusal-codes.test.ts › "every refusal validateExpression reports on the sweep carries a code from the closed set" |
Wanted
- Measure per-shard wall time and the slowest cases on loaded runners (
scripts/test-shard-timings.jsonand the shard plan). The cases that sit near 5 s on an idle runner are the population. - Fix the class: rebalance the shards, cut the heavy work out of these cases (ci: packages/cli validate-build-gate-parity.test.ts times out at 5000 ms in Test Core (4/8): one main red and one merge-queue ejection in eight hours #30785's own finding: a per-character masker run over every file), and/or set explicit per-case timeouts sized from the measurement, each with its reason. ⛔ No global timeout raise without measurement, no skip, no retry.
- ci: packages/cli validate-build-gate-parity.test.ts times out at 5000 ms in Test Core (4/8): one main red and one merge-queue ejection in eight hours #30785 and rest test: the record-currency backfill door's capability control case times out at 5 s in Test Core (6/8) (from PR #30809) #30873 stay their own fixes. This card owns the measurement and the formula case.
- Related: ci(test-shards): Test Core's two slowest shards set every core PR's wall clock at ~28 min (5.6 min dependency build + ~20 min tests) while the other six finish in 7–17 — re-derive the cli slicing and shard balance on post-merge readings #25870 (Test Core's slowest shards,
pm:on-hold).
Reader: domain:devx (CI health, the shard plan). The formula case is packages/formula.
Generated by Claude Code
Activity
objectstack-fleet commentedon Nov 6, 2026
domain:devx#2 · marchtian · session_017ihL2ebbZkr2QAEG1x7UC8
Claim: PM loop round 1
Session:
session_017ihL2ebbZkr2QAEG1x7UC8Account:
marchtianBranch:
claude/issue-30901-test-core-timeoutsWorktree:
objectstack-issue-30901Domain:
domain:devxSeat:
domain:devx#2File surface:
packages/formula/src/expression-refusal-codes.test.ts(the sweep cases' heavy work cut, or an explicit per-case timeout sized from a measurement and carrying its reason), and, where the measurement calls for it, the Test Core shard plan (scripts/test-shard-timings.jsonand the script that splits by it). A measurement of per-shard wall time and the slowest cases near 5 s goes in the PR body and the report. Plus whatever pin or self-test a gate derives from those files. ⛔ No global timeout raise without measurement, no skip, no retry. #30785 and #30873 stay their own fixes.Container & model:
S,mode:subagentClause-②: no
Metadata-protocol: none
Responsibility: n/a — CI health (test timing); independent contract review before ACCEPT
Thread-read: none
Premise: holds.
origin/main98f640d581still has the sweep caseevery refusal validateExpression reports on the sweep carries a code from its set…(expression-refusal-codes.test.ts:870) with no explicit timeout, and the card's three red runs are on record.Serial constraints cleared: no open PR touches
packages/formula/src/expression-refusal-codes.test.tsorscripts/test-shard-timings.json. #30873 (os-elon-musk) is inpackages/rest; this card stays out of it. #25870 (pm:on-hold) is the related shard card; this one does not restart it.objectstack-fleet commentedon Nov 6, 2026
domain:devx#2 · marchtian · session_017ihL2ebbZkr2QAEG1x7UC8
os-dev-report
{ "issue": 30901, "status": "done", "branch": "claude/issue-30901-test-core-timeouts", "pr": "https://github.com/objectstack-ai/objectstack/pull/30919", "head": "4588caea1c", "session": "session_017ihL2ebbZkr2QAEG1x7UC8", "premise_still_valid": true, "change": "packages/formula/src/expression-refusal-codes.test.ts only: the validateExpression sweep case judges each distinct refusal once (3,865 refusals, 199 distinct, keyed with node:util inspect over the whole refusal; refusals still all counted, every code still required) and carries an explicit per-case budget VALIDATE_SWEEP_BUDGET_MS = 16_000 (3x the 5034 ms CI reading, rounded up to the next second), with the readings and the rule in its comment. No production file, no shard-plan file, no other test.", "measurement": { "query": "GET /repos/objectstack-ai/objectstack/actions/workflows/224644133/runs?event=push|merge_group&created=>=2026-11-03T10:00:00Z (pages 1..N, 980 runs: 320 main push, 660 merge_group) -> GET /actions/runs/{id}/jobs for each completed run; wall = completed_at - started_at of successful 'Test Core (N/8)' jobs, setup+build included", "per_shard_wall_s": { "1/8": { "n": 749, "median": 948, "p90": 1160, "max": 1604 }, "2/8": { "n": 722, "median": 734, "p90": 1051, "max": 1542 }, "3/8": { "n": 658, "median": 859, "p90": 1060, "max": 1599 }, "4/8": { "n": 620, "median": 1189, "p90": 1504, "max": 2098 }, "5/8": { "n": 626, "median": 612, "p90": 822, "max": 1979 }, "6/8": { "n": 617, "median": 624, "p90": 886, "max": 1606 }, "7/8": { "n": 616, "median": 622, "p90": 898, "max": 1431 }, "8/8": { "n": 598, "median": 627, "p90": 785, "max": 1972 } }, "shard_overload": "4/8 at 1.53x the mean of the eight medians (776 s); the plan predicts equal bins (1553/1556/1551/1552/1552/1553/1556/1554 s, job 127808107135). Shards 1 and 4 carry the two @objectstack/cli slices; the dataset weighs cli at 1432.04 s (716 s/slice) while 6 sampled push runs measured slice 1/2 607-959 s and slice 2/2 627-1070 s (package 1234-2002 s, median 1782 s). Dataset refreshed 2026-11-02 by shard-timings-refresh.yml (weekly, needs scheduled-run summaries); not regenerated or hand-edited here.", "timeouts_in_window": "all 29 failed Test Core (N/8) jobs read: 10 'Test timed out in 5000ms' = 9x cli validate-build-gate-parity (#30785, all 4/8) + 1x the formula case (4/8, job 127808107135); 18 are spec check-liveness.test.ts assertion failures (1/8, 2/8); 1 (127654182380) log ends mid-verify, cause NOT MEASURED. #30873's rest case is not in this failed set.", "case_sample": "44 successful shard jobs of 6 main push runs (41615880546, 41887304051, 41996918981, 42086692390, 42136924584, 42181191624) + job 127808107135; vitest prints cases over 300 ms -> 3,162 rows; 402 peaked 2-5 s; AST-classified: 157 per-case timeout, 16 describe-level, 180 package testTimeout, 18 it.each with timeout, 31 on the 5 s default (a sample)", "slowest_default_5s_cases_ms": [ "plugin-hono-server src/adapter-tls-listener.test.ts > drains on close exactly as the plain listener does: CI n=2 med 4228 max 4239; local idle 4209 x2 (deterministic)", "plugin-hono-server src/adapter-drain.test.ts > lets an in-flight request complete instead of aborting it: CI n=2 med 3303 max 3321; local idle 3230 x2", "client src/auth-rotated-session-token.test.ts > login -> enable -> verifyTotp -> disable -> deleteUser: n=5 med 1424 max 3427", "cli src/utils/unmanaged-tables.integration.test.ts > the boot this sweep reads from really did compose the deployment: n=5 med 2892 max 3295", "metadata-protocol src/reference-sites.derivation.test.ts > two derivations of the same schemas agree exactly: n=2 med 2548 max 3210", "plugin-security src/org-admin-assignment-boundary.posture.test.ts > posture single/isolated/group column cases: n=3 med 1989-2228 max 2554-2949", "cli test/released-port-production-spawn.pin.test.ts > the census reaches the live tree: n=6 med 2301 max 2629", "plugin-sharing src/share-link-password.test.ts > a refused upgrade write does not block the read: n=4 med 2078 max 2605", "driver-sql src/logger-receiver-detach.test.ts > sql-driver.ts and the modules split out of it contain none of them: n=2 med 2470 max 2499" ] }, "formula_case": { "cause": "synchronous sweep of 5,760 validateExpression calls (3 roles x 128 inputs x 15 schemas); cpu-prof: ~70% in buildTypedEnv (cel-engine.ts) building a typed CEL env per call (production code), plus ~25,000 expect calls re-judging 3,865 refusals of which 199 are distinct; under Test Core (4/8) contention it reached 5034 ms", "fix": "judge each distinct refusal once (cut); explicit per-case budget 16_000 ms = ceil(3 x 5034) with the readings in the comment; breadth kept (it is the claim); no beforeAll (the two sweeps share nothing; a hook only moves the work under the 10 s hookTimeout)", "before_ms": { "local_idle": [ 786, 830, 757 ], "local_one_cpu_two_busy_loops": [ 3063, 2542, 2603 ], "ci_sample": [ 429, 1161, 2122, 2177, 2968, 3065, 5034 ] }, "after_ms": { "local_idle": [ 592, 534, 645 ], "local_one_cpu_two_busy_loops": [ 2035, 2137, 1961 ], "ci": "NOT MEASURED yet (PR run in progress)" }, "second_sweep_895": "collectCelRootIdentifiers sweep 5-6 ms local, 13-30 ms contended, 37 ms in the failing CI job: untouched", "mutation": "after commit 7a6ff9240d, ablation-replace on validate.ts refusal(): unbound-root refusals gain ghost param -> sweep case 1 failed (expected message to contain 'never-in-the-message'); restored blob == HEAD 8931039644aa, git diff HEAD empty" }, "timeouts_set": [ { "case": "packages/formula/src/expression-refusal-codes.test.ts > every refusal validateExpression reports on the sweep carries a code from its set, with params the message interpolates", "value_ms": 16000, "reason": "3x the slowest reading (5034 ms, CI Test Core (4/8) job 127808107135; synchronous body so the reading is the whole run), rounded up to the next second, per the rule in packages/cli/test/hook-timeout-override-refusal.test.ts" } ], "tests": "pnpm --filter @objectstack/formula test: 65 files / 1703 tests passed; typecheck exit 0 (test-typecheck ledger held 3 files/7 errors/4 signatures); eslint on the file exit 0; formula dist built: 0 hits for refusalKey|VALIDATE_SWEEP_BUDGET_MS, control validateExpression 4 files -> skip-changeset", "gates": { "sha": "4588caea1c", "derived": 48, "results": [ "node scripts/check-closing-keyword-parity.mjs :: exit 0", "node scripts/check-closing-keyword-parity.mjs --self-test :: exit 0", "node scripts/check-comment-mask-adoption.mjs :: exit 0", "node scripts/check-comment-mask-adoption.mjs --self-test :: exit 0", "node scripts/check-comment-mask-corpus.mjs :: exit 0", "node scripts/check-dts-emitted.mjs --self-test :: exit 0", "node scripts/check-issue-citations.mjs :: exit 0", "node scripts/check-plugin-teardown-shape.mjs :: exit 0", "node scripts/check-plugin-teardown-shape.mjs --self-test :: exit 0", "node scripts/ci/assert-turbo-remote-cache.mjs --self-test :: exit 0", "node scripts/ci/plan-test-core-shards.mjs --self-test :: exit 0", "node scripts/ci/prune-turbo-cache.mjs --self-test :: exit 0", "node scripts/docs-audit/check-affected-docs.mjs :: exit 0", "node scripts/docs-audit/check-drift-comment.mjs :: exit 0", "pnpm --filter @objectstack/spec run check:duration-unit-keys :: exit 0", "pnpm check:ci-filter-parity :: exit 0", "pnpm check:closed-ceremony-text :: exit 0", "pnpm check:cross-package-test-inputs :: exit 0", "pnpm check:doc-authoring :: exit 0", "pnpm check:driver-memory-census :: exit 0", "pnpm check:dts-closure :: exit 0", "pnpm check:dual-build-cjs-loads :: exit 0", "pnpm check:engine-double-contract :: exit 0", "pnpm check:gitlink-declared :: exit 0", "pnpm check:issue-citations :: exit 0", "pnpm check:keyed-text-bounds :: exit 0", "pnpm check:lean-entry-closure :: exit 0", "pnpm check:logger-receiver-detach :: exit 0", "pnpm check:nul-bytes :: exit 0", "pnpm check:objectql-double-limit :: exit 0", "pnpm check:org-identifier :: exit 0", "pnpm check:page-declaration-shape :: exit 0", "pnpm check:platform-object-tenancy-census :: exit 0", "pnpm check:published-files :: exit 0", "pnpm check:query-options-erasure :: exit 0", "pnpm check:refd-timer-probe :: exit 0", "pnpm check:registry-log-declared :: exit 0", "pnpm check:rest-log-spy-declared :: exit 0", "pnpm check:slot-lookup :: exit 0", "pnpm check:sourcemap-no-sources-content :: exit 0", "pnpm check:system-context-census :: exit 0", "pnpm check:test-source-alias :: exit 0", "pnpm check:tier-file-adoption :: exit 0", "pnpm check:type-check-coverage :: exit 0", "pnpm check:type-check-debt :: exit 0", "pnpm check:undeclared-dep-imports :: exit 0", "pnpm check:watch-hint-literal :: exit 0", "pnpm check:where-matcher :: exit 0" ], "note": "check:dual-build-cjs-loads and check:lean-entry-closure exited 3 (no dist/) on the first pass; full turbo build (docs excluded) then rerun: both exit 0", "ran": "dispatch-gates --ran: 48 derived, 48 run, 0 NOT-MEASURED, 0 UNRUN", "ci": "PR #30919 check-runs in_progress at report time; Check Changeset success" }, "dogfood_battery": "n/a — no ! in the PR title and no (narrowing) arm", "files_changed": [ "packages/formula/src/expression-refusal-codes.test.ts" ], "deviations": [ "The order suggested a beforeAll/module-scope share between the 870 and 895 sweeps: not done, the two share no work (different producer, different inputs; 895 measures 5-37 ms) and moving 870 into a hook would only relocate its work under the 10 s hookTimeout.", "test:repo not run locally (this diff does not touch that project); Test Core runs it in CI.", "An unfiltered turbo build that started the docs build was killed by its recorded PIDs and rerun with --filter=!@objectstack/docs." ], "open_questions": [ { "question": "Shard 4/8 runs at 1.53x the mean shard median because the cli slices measure ~1.2x the dataset weight. Wait for the weekly refresh or act now?", "options": [ "A wait for the scheduled shard-timings-refresh (~2026-11-09) and re-measure", "B fold into #25870 (pm:on-hold) as fresh evidence", "C a separate card to cut cli into 3 slices" ], "recommendation": "A, then B with the numbers above if 4/8 is still over 1.3x after the refresh" } ], "out_of_scope_findings": [ "class: none (near-5s timeout class, same family as this card) · reach: n/a · plugin-hono-server adapter-tls-listener.test.ts 'drains on close exactly as the plain listener does' 4209 ms idle (deterministic), CI max 4239; adapter-drain.test.ts 'lets an in-flight request complete instead of aborting it' 3230 ms idle, CI max 3321. Hypothesis (not measured): close() calls closeIdleConnections() while the request is in flight, so the socket that goes idle afterwards waits for the client keep-alive · carrier: seat to file · dedupe words: hono drain close keep-alive timeout", "class: none (near-5s timeout class) · the other 7 default-5s cases in measurement.slowest_default_5s_cases_ms (client, cli x2, metadata-protocol, plugin-security, plugin-sharing, driver-sql), 2.5-3.4 s max in CI · carrier: seat to file or fold into one class card · dedupe words: Test Core 5000ms default timeout near", "class: none (observation) · validateExpression builds a fresh typed CEL environment per call (buildTypedEnv, ~70% of the sweep's CPU); memoizing by field-type signature would cut the sweep and author-time validation · carrier: none · noted, not filed" ], "mcp_calls": "0", "api_writes": "3 — git push (branch, 3 pushes: empty probe, commits, merge; not REST); 1 repository_dispatch POST /repos/objectstack-ai/objectstack/dispatches (pr_create #30919 + skip-changeset label via relay run 42209657177); 1 comment via post-stamped.mjs on #30901 (this report)", "filed_issues": [], "security_findings": "none" }objectstack-fleet commentedon Nov 6, 2026
domain:devx#2 · marchtian · session_017ihL2ebbZkr2QAEG1x7UC8
Landed · PR #30919 merged as
d3e58c1a80· 2026-11-06T12:37Z. Seat ACCEPT 6684547328. Contract review: PASS (6683972205), then delta FAIL (6684040945, a miscount in a comment, since fixed), then delta PASS (6684082983).validateExpressionsweep now judges each distinct refusal once and has a per-case budget of 16 s (3x the 5034 ms timeout reading). On the PR's head it ran in 1710 ms inTest Core. No assertion is weakened, and there is no global raise, skip or retry.plugin-hono-serverdrain cases that take 3–4 s even on an idle runner, are Test Core: nine cases sit at 2.5-4.2 s on the vitest 5 s default; the two plugin-hono-server drain cases take 3-4 s even on an idle runner #30920.The card closed on the merge. The seat releases its slot.