Skip to content

Commit d3e58c1

Browse files
test(formula): judge each distinct sweep refusal once, and give the validateExpression sweep a measured budget (#30919)
<!-- claude-projects-attribution: {"github_login":"marchtian"} --> _Requested by **田騏** · [project thread](https://claude.ai/code/project/chan_01VmuUhXU9SSUzqJYyXSmYSi?thread=cmsg_01VmuUhXU9SSUzqJYyXSmYSiNjyvCdXYygFqntMNR7S2dW)_ Fixes #30901 Clause-②: no Metadata-protocol: none ## 维护者速读 - 改了什么:formula 包里那条「validateExpression 扫描」用例,重复的拒绝结果只判一次(3,865 条里只有 199 条不同),并给它一个按实测定的 16 秒超时,注释里写明读数和算法;生产代码、其它用例、分片计划都没动。 - 为什么改:这条用例在 main 推送的 `Test Core (4/8)` 上跑了 5034 ms,撞上 vitest 默认 5 秒超时变红,下一次推送又绿;本地空闲只要 0.8 秒,是分片负载把它推过了线。 - 风险与回滚:只改一个测试文件,不发布任何东西;断言一条没少,变异实验证明它照样会红。回滚就是 revert 这一个 PR。 - 先看:`packages/formula/src/expression-refusal-codes.test.ts` 里的 `refusalKey` 与 `VALIDATE_SWEEP_BUDGET_MS` 注释块,以及扫描用例里 `judged` 那几行。 - 两分钟验证:`pnpm --filter @objectstack/formula exec vitest run src/expression-refusal-codes.test.ts --reporter=verbose`,应看到 42 条全过,扫描用例约 0.5–0.7 秒(改前约 0.8 秒)。 - 需要你做的:无,席位落地。 ## What changes `packages/formula/src/expression-refusal-codes.test.ts`, the case *every refusal validateExpression reports on the sweep carries a code from its set, with params the message interpolates* (line 870 on `origin/main`): 1. **Cut: each distinct refusal is judged once.** The sweep makes 5,760 `validateExpression` calls (3 roles x 128 inputs x 15 schemas) and gets 3,865 refusals, but only 199 distinct ones. The case ran its five assertions again on every duplicate, about 25,000 `expect` calls. Every assertion reads only the refusal itself (`code`, `params`, `message`, `source`, the four fields `refusal()` in `validate.ts` builds), so a refusal equal to one already judged would get the same verdict again. It is now keyed with `inspect`, not `JSON.stringify`, so an `undefined` or `NaN` param is still told apart, and judged once. `refusals` still counts every refusal (the `> 100` control is unchanged), and `provoked` still has to reach every code. 2. **Budget: the case takes an explicit `VALIDATE_SWEEP_BUDGET_MS = 16_000`.** It uses the rule from `packages/cli/test/hook-timeout-override-refusal.test.ts`: 3x the slowest reading, rounded up to the next second. The slowest reading is the CI failure's 5034 ms, so 3 x 5034 = 15102, rounded up to 16000. The readings and the rule are in the comment above the constant. What was not cut, and why: - **The sweep's breadth.** About 70% of the case's CPU goes to `buildTypedEnv` (`cel-engine.ts`), which builds a fresh typed CEL environment for each call. That is production code, outside this card's file surface. The inputs are the claim: the docblock says "a new arm reached by an old input is judged", so dropping inputs would weaken the case. - **No `beforeAll` and no module-scope precompute.** The two sweeps share nothing. The `collectCelRootIdentifiers` sweep (line 895) walks 40 sources through a different producer and measured 5 to 37 ms everywhere, so it needs neither a cut nor a budget. Moving the `validateExpression` sweep into a hook would not remove its work. The work would run under the hook's 10 s default, which is a timeout raise by another name. No production file, no shard plan file, no other test file is touched. There is no global `testTimeout`, no skip and no retry. ## Tests <details><summary>The formula case: before / after, local and CI</summary> | Reading | Before (`origin/main` 98f640d) | After (this branch) | |---|---|---| | Local, 4 vCPU, this file alone, 3 runs | 786 / 830 / 757 ms | 592 / 534 / 645 ms | | Local, pinned to one CPU shared with two busy loops, 3 runs | 3063 / 2542 / 2603 ms | 2035 / 2137 / 1961 ms | | CI `Test Core` jobs (`main` push / merge group, 2026-11-03..06, a sample of 7 that ran formula) | 429, 1161, 2122, 2177, 2968, 3065, **5034 (timed out)** | not yet measured (this PR's own run) | The CI failure was job 127808107135 (`main` push run 42192379976 on `d55acb7828`, `Test Core (4/8)`): `Test timed out in 5000ms`, case duration 5034 ms. The case is synchronous, so vitest judges it only after the body returns, and 5034 ms is the full run, not a cut-off. In the same run the second sweep took 37 ms. Profile (`--cpu-prof`, the sweep x3): `validateExpression` 1189 ms inclusive, of which `buildTypedEnv` 830 ms (`typeSoundnessIssue`, `firstTypeMismatch`, `firstDateTextVerdict`). No dynamic import or module load happens inside the clocked window. </details> <details><summary>Mutation: the deduplicated sweep still goes red</summary> Done after the fix was committed (`7a6ff9240d`), with `node scripts/ablation-replace.mjs`. In `packages/formula/src/validate.ts` the line `return { source, message, code, params } as ExprValidationError;` was changed to add a param `ghost: 'never-in-the-message'` to `unbound-root` refusals only. `unbound-root` is a code the sweep reaches from only a few of its 5,760 calls. - anchor x1 -> x0, blob `8931039644aa` -> `afa0bba73789` (mutation landed) - `vitest run src/expression-refusal-codes.test.ts -t "validateExpression reports on the sweep"`: **1 failed**, `AssertionError: expected 'unbound root \`pge\` — beyond the recor…' to contain 'never-in-the-message'` - restored: blob == HEAD (`8931039644aa`), `git diff HEAD` empty No build was needed: the test imports `./validate` from `src`. </details> <details><summary>Package suite, typecheck, lint</summary> - `pnpm --filter @objectstack/formula test`: Test Files 65 passed (65), Tests 1703 passed (1703) - `pnpm --filter @objectstack/formula typecheck`: exit 0, `check:test-typecheck: OK — 3 file(s) / 7 error(s) / 4 pinned signature(s) held` (the ledger is unchanged) - `pnpm exec eslint packages/formula/src/expression-refusal-codes.test.ts`: exit 0 - Publishes nothing: `files` is `dist`, `README.md`, `CHANGELOG.md`. After `pnpm --filter @objectstack/formula build`, `grep -rl 'VALIDATE_SWEEP_BUDGET_MS|refusalKey' dist` finds 0 files, and the positive control `validateExpression` finds 4. So `skip-changeset`. </details> ## Acceptance notes The measurement this card owns. It is a sample, and the queries are named so it can be repeated. <details><summary>Per-shard wall time, `Test Core (N/8)`, 2026-11-03 10:00Z .. 2026-11-06 10:30Z</summary> Source: `GET /repos/objectstack-ai/objectstack/actions/workflows/224644133/runs?event=push|merge_group&created=>=2026-11-03T10:00:00Z` (980 runs: 320 `main` push, 660 merge group), then `GET /actions/runs/{id}/jobs` for each completed run. Wall = `completed_at - started_at` of each successful shard job, setup and build included. The population pools path-filtered `main` push runs with full-plan merge-group runs (sampled push run 42181191624 planned 37 of 84 items, and its shard 1/8 got one item), so a push run's shard reads low. Restrict to full-plan runs before re-deriving the cli slicing from these numbers. | Shard | n | median s | p90 s | max s | |---|---|---|---|---| | 1/8 | 749 | 948 | 1160 | 1604 | | 2/8 | 722 | 734 | 1051 | 1542 | | 3/8 | 658 | 859 | 1060 | 1599 | | **4/8** | 620 | **1189** | **1504** | 2098 | | 5/8 | 626 | 612 | 822 | 1979 | | 6/8 | 617 | 624 | 886 | 1606 | | 7/8 | 616 | 622 | 898 | 1431 | | 8/8 | 598 | 627 | 785 | 1972 | Shard 4 runs at **1.53x** the mean of the eight medians (776 s). The plan predicts all eight bins equal (`1553/1556/1551/1552/1552/1553/1556/1554s` in job 127808107135). The gap comes from the CLI. Shards 1 and 4 each carry one `@objectstack/cli` slice, and the dataset weighs the whole package at 1432.04 s (716 s a slice). In 6 sampled push runs the two slices measured 607-959 s (1/2) and 627-1070 s (2/2), so 1234-2002 s for the package, median 1782 s. Shard 4 also runs `plugin-approvals` (289 s), `verify` (340 s) and `driver-memory` (183 s) beside the slice. Its formula run is the contended one. The dataset was refreshed 2026-11-02 by `shard-timings-refresh.yml` (scheduled, weekly). Its generator needs turbo run summaries that only the scheduled runs keep, so this PR **does not touch `scripts/test-shard-timings.json`**, and a hand edit is forbidden. The next scheduled refresh is the place the CLI weight moves. </details> <details><summary>Every 5 s timeout in Test Core over the same window</summary> All 29 failed `Test Core (N/8)` jobs were read (`GET /actions/jobs/{id}/logs`). Ten failed with `Test timed out in 5000ms`: - 9 x `packages/cli/test/validate-build-gate-parity.test.ts` › *the command sources use no call shape this scan cannot read*, all in `Test Core (4/8)`. This is #30785's case. - 1 x the formula case above, in `Test Core (4/8)`. The other 19 are not timeouts. 18 are `@objectstack/spec` assertion failures in `scripts/liveness/check-liveness.test.ts` on shards 1 and 2. The 19th is shard-4 job 127654182380, whose log stops in the middle of the `verify` suite, so its cause was not measured. #30873's rest case is not among these 29 jobs (its red was on a run outside this window's failed set). </details> <details><summary>The population: cases on the 5 s default that run 2-5 s in CI (sample)</summary> Sample: all 44 successful shard jobs of 6 `main` push runs spread over the window (41615880546, 41887304051, 41996918981, 42086692390, 42136924584, 42181191624), plus the failing job above. vitest prints every case over 300 ms, which gives 3,162 (package, file, case) rows. 402 of them peaked at 2-5 s. Each was classified from its source with the TypeScript AST (the `it`/`test` call's own timeout argument, its enclosing `describe`'s, or the package config's `testTimeout`): 157 carry a per-case timeout, 16 inherit one from a `describe`, 180 sit in a package with a raised `testTimeout` (`spec` 60 s, `plugin-auth` 10 s, ...), 18 are `it.each` rows that all carry one. **31 are on the 5 s default.** The ones that run closest to the line, beyond #30785's and #30873's: | Case | CI ms (n, median, max) | Local idle | |---|---|---| | `packages/plugins/plugin-hono-server/src/adapter-tls-listener.test.ts` › drains on close exactly as the plain listener does | n=2, 4228, 4239 | 4209 (twice) | | `packages/plugins/plugin-hono-server/src/adapter-drain.test.ts` › lets an in-flight request complete instead of aborting it | n=2, 3303, 3321 | 3230 (twice) | | `packages/client/src/auth-rotated-session-token.test.ts` › login → enable → verifyTotp → disable → deleteUser, no hand-repaired credential | n=5, 1424, 3427 | — | | `packages/cli/src/utils/unmanaged-tables.integration.test.ts` › the boot this sweep reads from really did compose the deployment | n=5, 2892, 3295 | — | | `packages/metadata-protocol/src/reference-sites.derivation.test.ts` › two derivations of the same schemas agree exactly | n=2, 2548, 3210 | — | | `packages/plugins/plugin-security/src/org-admin-assignment-boundary.posture.test.ts` › posture 'single' / 'isolated' / 'group': a column the caller's field rules hide is never named in the refusal… | n=3, 1989-2228, 2554-2949 | — | | `packages/cli/test/released-port-production-spawn.pin.test.ts` › the census reaches the live tree: every way of spawning the CLI, and the draw, are found | n=6, 2301, 2629 | — | | `packages/plugins/plugin-sharing/src/share-link-password.test.ts` › a refused upgrade write does not block the read… | n=4, 2078, 2605 | — | | `packages/drivers/driver-sql/src/logger-receiver-detach.test.ts` › sql-driver.ts and the modules split out of it contain none of them | n=2, 2470, 2499 | — | The two `plugin-hono-server` drain cases are not load-driven. They take the same 3.2 s and 4.2 s on an idle box, every run. `close()` calls `closeIdleConnections()` while the request is still in flight, so the socket that goes idle after it waits for the client's keep-alive to end. That is a hypothesis from reading `adapter.ts`, not measured. None is fixed here, because each one sits in another package and outside this claim's file surface. The seat filed them as one class card, #30920, led by the two drain cases. The shard-4/8 reading is on the on-hold shard card #25870 (with the pooling caveat above), for its re-derivation after the weekly refresh. </details> ## Verification Gates derived by `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack` for the final diff, run at ``4588caea1c` (the merge of `origin/main`)`: <details><summary>48 commands, each exit code taken before any pipe</summary> ```text 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 (first pass: exit 3, no dist/; rerun after a full build) 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 (first pass: exit 3, no dist/; rerun after a full build) 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 ``` `--ran` reconciliation: `✓ dispatch-gates --ran: 48 derived famil(ies) accounted for — 48 run, 0 NOT-MEASURED (a DERIVED zero — all 48 recorded an exit code and none of them is 3).` </details> CI: this PR's check-runs are the evidence for every family CI runs. `Test Core` reruns the formula suite. 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- signed: domain:devx#2 · marchtian · session_017ihL2ebbZkr2QAEG1x7UC8 --> --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 26c965c commit d3e58c1

1 file changed

Lines changed: 44 additions & 1 deletion

File tree

‎packages/formula/src/expression-refusal-codes.test.ts‎

Lines changed: 44 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
* red at the type check, and a code nobody pinned goes red here.
2121
*/
2222

23+
import { inspect } from 'node:util';
2324
import { describe, expect, it } from 'vitest';
2425
import { celEngine, collectCelRootIdentifiers, type CelRootIdentifiersResult } from './cel-engine';
2526
import { templateEngine } from './template-engine';
@@ -855,6 +856,40 @@ function expectLocatorsRead(said: { code: string; params: unknown; source: strin
855856
}
856857
}
857858

859+
/**
860+
* A refusal's identity in the sweep: the whole refusal, which is its `code`,
861+
* `params`, `message` and `source` (`refusal()` in `validate.ts` builds exactly
862+
* those four). `inspect` and not `JSON.stringify`, because JSON writes an
863+
* `undefined` param as absent and `NaN` as `null`, and two refusals that differ
864+
* only there must still be judged apart.
865+
*/
866+
function refusalKey(said: ExprValidationError): string {
867+
return inspect(said, { depth: Infinity, breakLength: Infinity, maxArrayLength: Infinity, maxStringLength: Infinity });
868+
}
869+
870+
/**
871+
* The validateExpression sweep's budget. The case is synchronous: 5,760
872+
* validateExpression calls (3 roles x 128 inputs x 15 schemas), most of the
873+
* time in building a typed CEL environment for each call. Its work is the
874+
* sweep's breadth, which is the claim, so the breadth stays; only re-judging
875+
* duplicate refusals was cut (see the case). Readings of the case, in ms:
876+
*
877+
* - CI, `main` push run 42192379976, job `Test Core (4/8)` (127808107135), a
878+
* contended shard: 5034, `Test timed out in 5000ms.` A synchronous body
879+
* runs to its end before vitest judges it, so 5034 is the whole run.
880+
* The six other `Test Core` jobs sampled from the same three days: 429
881+
* to 3065.
882+
* - Local, 4 vCPU, this file alone: 757 to 830 before the cut, 534 to 645
883+
* after it. Pinned to one CPU shared with two busy loops: 2542 to 3063
884+
* before, 1961 to 2137 after.
885+
*
886+
* The rule follows `packages/cli/test/hook-timeout-override-refusal.test.ts`:
887+
* 3x the slowest reading, rounded up to the next second. 3 x 5034 = 15102, so
888+
* the budget is 16000. If the sweep's inputs or schemas grow, re-measure and
889+
* re-size.
890+
*/
891+
const VALIDATE_SWEEP_BUDGET_MS = 16_000;
892+
858893
describe('expression refusal codes — the closed set', () => {
859894
it('has a pin for every code, and no pin for a code outside the set', () => {
860895
expect(Object.keys(PINS).sort()).toEqual([...EXPRESSION_REFUSAL_CODES].sort());
@@ -869,13 +904,21 @@ describe('expression refusal codes — the closed set', () => {
869904

870905
it('every refusal validateExpression reports on the sweep carries a code from its set, with params the message interpolates', () => {
871906
const provoked = new Set<string>();
907+
const judged = new Set<string>();
872908
let refusals = 0;
873909
for (const role of ['predicate', 'value', 'template'] as const) {
874910
for (const input of SWEEP_INPUTS) {
875911
for (const schema of SWEEP_SCHEMAS) {
876912
const r = validateExpression(role, input, schema);
877913
for (const said of [...r.errors, ...r.warnings]) {
878914
refusals++;
915+
// At 98f640d581 the sweep's 3,865 refusals are 199 distinct
916+
// ones, and every assertion below reads only the refusal itself
917+
// — so one that equals a refusal already judged gets that verdict
918+
// again, and is judged once.
919+
const key = refusalKey(said);
920+
if (judged.has(key)) continue;
921+
judged.add(key);
879922
expect(VALIDATE_CODES.has(said.code), `${said.code} from ${JSON.stringify(input)}`).toBe(true);
880923
expect(typeof said.params).toBe('object');
881924
expect(said.params).not.toBeNull();
@@ -890,7 +933,7 @@ describe('expression refusal codes — the closed set', () => {
890933
// producer owns, so a code whose arm stopped being reachable shows up too.
891934
expect(refusals).toBeGreaterThan(100);
892935
expect([...provoked].sort()).toEqual([...VALIDATE_CODES].sort());
893-
});
936+
}, VALIDATE_SWEEP_BUDGET_MS);
894937

895938
it('every refusal collectCelRootIdentifiers reports on the sweep carries a code from its set', () => {
896939
const provoked = new Set<string>();

0 commit comments

Comments
 (0)