Skip to content

Commit 80c29a1

Browse files
test(client): pay the auth-envelope suite's cold start at module scope, outside every clocked window (#20272)
Fixes #20242 Clause-②: no The first case of `packages/client/src/auth-login-register-envelope.test.ts` paid the worker's one-time cold start inside vitest's 5000 ms `testTimeout`. It timed out on `Test Core (5/6)` (run `36320810893`, head `3d14f9e75`), on a PR whose diff does not reach this suite. This PR moves that cost out of every clocked window. No budget changes. The diff is one test file, +81 / -2. ## Premise check (done first, on `origin/main` at `fdb26698f`) Holds. Every case builds a fresh `ObjectQL` over a new `SqliteWasmDriver(':memory:')`, runs `syncSchemas`, constructs a real `AuthManager`, and performs a real better-auth sign-up. The file set no timeout and had no warm-up. `premise_still_valid: true`. ## Where the first case's time went Phase probe (a throwaway file, never committed): four successive scenarios in one worker, idle, 4 vCPU, at `fdb26698f`. | phase | first scenario | later scenarios | |:---|---:|---:| | `getAuthInstance()` (better-auth's lazily imported module graph) | 510 ms | 10-11 ms | | `engine.init()` (sql.js compiles its WASM once) | 85 ms | 1-2 ms | | `syncSchemas()` | 182 ms | 81-100 ms | | the sign-up | 261 ms | 117-127 ms | So about 850 ms of the first case's window was one-time cost that no other case pays. Idle, the first case took 855-964 ms, against 222-249 ms for the two other cases doing the same single sign-up. The failing CI run's own totals point the same way. Against this tree idle (`--maxWorkers=2`), its client package read `tests 38.71s` vs `23.39s` and `import 202.17s` vs `102.68s`. Test bodies ran about 1.5x slower there, while the first case ran more than 5x slower. The term that crossed the budget was cold loading, not the behaviour the case asserts. ## The route, and why it is neither of the two the dispatch offered The dispatch offered (a) a `beforeAll` warm-up with its own explicit timeout, or (b) an explicit per-case timeout. Both keep the cost inside a clock. `@vitest/runner@4.1.11`, as installed in this tree, wraps hooks and test bodies in `withTimeout(...)`, while `collectTests()` awaits `runner.importFile(filepath, "collect")` bare (`dist/chunk-artifact.js`). The repo already recorded what (a) costs. `scripts/check-test-source-alias.mjs`'s clocked-window section describes a cold load moved into a `beforeAll` (hookTimeout 10000) that then hit 20.26 s on a merge-queue shard. Its rule, repeated in AGENTS.md (Build & Test), is "clocked windows measure behaviour, never loading". `packages/cli/src/commands/datasource/envelope-unwrap.test.ts` is the in-repo precedent for the same class. So the cost is now paid by a module-scope `await`, during collection, which no vitest clock covers. What the warm-up runs: one whole throwaway scenario, the file's own `registered()`, not a list of loads. A load-only warm-up (engine plus `getAuthInstance()`) left the next scenario at 344-409 ms against 212-269 ms, because the sign-up path has first-use costs of its own. The full scenario left none: 258-284 ms against 214-289 ms. Naming the file's own arrangement also avoids a specifier list that could drift. ## What changed - One module-scope `await registered(); await closeEngines();`. - The old `afterEach` body becomes `closeEngines`, byte-for-byte the same loop, reused by the warm-up. - A header section with the measurements above. - `⑦`, a placement pin. It reads this file's own text and asserts exactly one column-0 `await registered();` and no `before*` hook. So "do not move it into a hook" is an assertion. No assertion in cases ①-⑥ changed. There is no skip, no retry, no quarantine and no timeout anywhere. The warm-up shares nothing a case asserts on. Its engine and manager are its own and are closed before collection ends. Every case still builds a fresh engine, a fresh `AuthManager` and a fresh first sign-up. What it leaves warm is process-level: the module registry, sql.js's compiled WASM and the JIT. The first case used to leave exactly that to the fourteen after it. Before the fix every other case was already a "warm" case, so no case now runs in a state no case ran in before. ## Before / after at CI's own budget The failure reproduces at the real 5000 ms budget under CPU contention: 24 CPU-bound `node -e 'for(;;){}'` loops on 4 vCPU, their PIDs recorded and killed by trap. On the unmodified base tree (`fdb26698f`) this load gave CI's exact signature, `1 failed | 14 passed`, on the first case, `Test timed out in 5000ms`, in 2 of 2 runs. Measured as 10 interleaved pairs: an ABLATED leg (the fix deleted), then the FIX leg (the committed file), same command, same load. The box is shared and its background load drifts, so interleaving puts the drift on both sides equally. ``` ./node_modules/.bin/vitest run --maxWorkers=2 --reporter=verbose src/auth-login-register-envelope.test.ts ``` | N = 10 each, 5000 ms, 24 busy loops | runs red | first-case timeouts | first case | where every failure landed | |:---|---:|---:|---:|:---| | ablated (module-scope warm-up deleted) | 10 / 10 | **9 / 10** | 4788-5402 ms | first case x9, `⑦` pin x10, one `⑤` case x1 (pair 10) | | fix (`a05c2e2da`) | 1 / 10 | **0 / 10** | 1461-2804 ms | both `⑤` cases, pair 10 only | Pair 10 ran on a heavier box: vitest wall 196-203 s against 129-141 s for pairs 1-9. Unlocked work belonging to another worktree was running beside it (read from the process table, not killed). There, the ablated leg failed the first case plus one `⑤` case. A separate, unpaired series of 10 fix runs under the same 24 loops shows the same split. Runs 1-5, at the calibration's box load (wall 130-151 s), were 5 of 5 green. Runs 6-10, with that extra unlocked load present (wall 185-200 s), were 5 of 5 red, every one on the two `⑤` cases (5002-5124 ms) and none on the first case (case 1 there: 1851-2936 ms). Idle, after the fix, 10 of 10 runs are green (16 tests). The first case takes 238-352 ms, level with its same-work siblings at 197-291 ms. ## Margin, and its basis Each case's window now holds only its own behaviour: a fresh-engine sync plus real scrypt sign-ups and logins. The heaviest cases are the first two in `⑤`, each doing two sign-ups and a login. | basis | heaviest per-case window | margin to 5000 ms | |:---|---:|---:| | idle, this box, after the fix | 502-689 ms | 7.3x | | CI's failing run: test bodies about 1.5x idle (package totals above) | about 0.75-1.0 s (inferred, not measured) | about 5x | | 24 busy loops, pairs 1-9 (the load that reproduces CI's failure 9 / 10 when ablated) | 3031-4108 ms | 1.2-1.6x | | 24 busy loops plus the extra unlocked load (pair 10, unpaired runs 6-10) | 5002-5138 ms | reached | So this does not raise a number that the next slower runner will exceed: no number was raised. The fix takes about 850 ms idle of one-time loading out of the first case's window. Under the synthetic CPU starvation that reproduces the failure, that is more than 3 s. The first case, with 0 timeouts in 20 loaded fix runs, is no longer where the file fails. What a much slower runner reaches next is the `⑤` cases' own behaviour. On this box that took about 1.4x more load than the load that reproduces CI's failure. That is a real per-case cost the case exists to pay, and it is recorded in Acceptance notes rather than papered over. ## Ablation (commit first, restore proven) The fix was committed (`a05c2e2da`) before any mutation. Each ablated leg went through `node scripts/ablation-replace.mjs --file ABS_PATH --anchor 'await registered();\nawait closeEngines();\n' --delete -- ...` (WRAP mode, restore armed on EXIT, INT and TERM). For every leg the tool reported: anchor x1 -> x0, blob `261d72a2e` -> `dbec8e3fc`, and "ok mutation landed". The wrapped command itself printed `warm-up lines=0` read off the disk before vitest started. After every leg, and at the end of each chunk, the restore was proven by blob hash (`git hash-object` of the file == `git rev-parse HEAD:PATH` == `261d72a2e`, an empty hash reading as failure) and by `git diff HEAD` = 0 bytes. That is 14 of 14 proofs. The tree was clean before and after. The test file is run from source, so no `dist/` preflight applies. ## Verification All at `6b7a46bbc` (after merging `origin/main`; the branch delta against it is exactly this one file, +81 / -2). Every command's exit code was captured before any pipe. - The dependency closure was built first: `pnpm turbo run build --filter='@objectstack/client...' --concurrency=2`, 33 of 33 tasks. - `pnpm --filter @objectstack/client exec vitest run --maxWorkers=2 src/auth-login-register-envelope.test.ts`: `Tests 16 passed (16)`, exit 0. - `pnpm --filter @objectstack/client exec vitest run --maxWorkers=2`: `Test Files 50 passed (50)`, `Tests 637 passed (637)`, exit 0. - `pnpm --filter @objectstack/client typecheck`: exit 0, `check:test-typecheck: OK`, 0 files / 0 errors. `tsc -p tsconfig.test.json --listFilesOnly` does compile this file (1 hit), so that green covers it. - `node scripts/pm/dispatch-gates.mjs --repo objectstack-ai/objectstack --ran`: `52 derived famil(ies) accounted for — 50 run, 2 NOT-MEASURED`, and every one of the 50 run exited 0. - NOT MEASURED: `check:dual-build-cjs-loads` and `check:type-check-debt`. Both exited 3 (PREREQUISITE NOT MET) because they need every package's `dist/`, i.e. the whole `./packages/*` build. This is a declared narrowing, and CI runs both. - Why this diff cannot move either: the one file is a test, which no build emits (the client `dist/` check is under Changeset below), and `@objectstack/client` is in neither type-check debt ledger. Its own test-layer ledger is empty and was re-measured just above at 0 errors. - `check:skill-examples` first exited 3 because `packages/client-react/dist` was absent. After `pnpm turbo run build --filter=@objectstack/client-react` the same command exited 0: 259 prose examples across 3 surfaces. - `node scripts/check-issue-citations.mjs --base origin/main` (the real board check): exit 0. 4 citations judged, all resolve. - `pnpm lint` (`eslint . --no-inline-config`, the whole repo, not a narrowing): exit 0. - Control-byte self-scan of the changed file: no hits. ## Changeset `skip-changeset`. The diff is one `*.test.ts` file. `@objectstack/client`'s `files[]` is `dist`, `README.md`, `CHANGELOG.md`. After `pnpm turbo run build --filter='@objectstack/client...'`, strings unique to this test file (`closeEngines`, the `⑦` title) have 0 hits under `packages/client/dist/`, while the positive control `ObjectStackClient` hits all 4 emitted artifacts (`index.js`, `index.mjs`, `index.d.ts`, `index.d.mts`). No published byte changes. ## Acceptance notes - **Census (triage note 3): other `packages/client` suites that build a fresh engine plus a real sign-up per case.** None of them is edited here. - `src/auth-get-session-envelope.test.ts`: 7 cases, all 7 through `signedIn()` / `anonymous()` on a fresh `SqliteWasmDriver` engine with `syncSchemas` and a real `AuthManager`. Timeout posture: vitest default 5000 ms, no warm-up. Its first case pays the same cold start this PR moves; same exposure. - `src/auth-rotated-session-token.test.ts`: 7 cases, all 7 through `signedIn()`. Timeout posture: an explicit `60_000` on all 7 cases. The cold start still sits in its first case's window, widened rather than moved, which is the posture `check:test-source-alias`'s header says relocates the cliff. - `src/organization-invitation-resend-team-placement.test.ts`: 11 cases, 5 of them through `arrange()` (fresh engine, real `AuthManager`, real sign-up). Default 5000 ms. Its `beforeAll`/`afterAll` only set and restore `OS_TENANCY_POSTURE` and load nothing. The first case, `①`, calls `arrange()` and so pays the cold start. - `src/organization-invite-role-default.test.ts`: 6 cases, 3 through `arrange()`, same shape and posture as the one above; its first case `①` pays the cold start. - The `client.hono` / `client.batch-transaction` / `client.data-prefix` / `client.environment-scoping` / `client.metadata-prefix` suites build a `SqliteWasmDriver` engine but perform no sign-up. `client.test.ts` has no real `AuthManager` (its sign-up cases are fetch-level). Out of this shape. - **Residual in this file:** the first two `⑤` cases each build two scenarios (`registered()` then `signedIn()`, i.e. two sign-ups plus a login), which makes them the file's heaviest windows. Under 24 busy loops plus extra unlocked load they reached 5002-5138 ms (6 of 20 loaded fix runs). CI has not shown them failing. If it ever does, the lever is that case's own work, because `signedIn()` already contains a registration. ⛔ Not a timeout. Noted, not filed. - When a case times out, vitest does not cancel its body. The orphaned sign-in then ran against an engine `afterEach` had already closed, and logged `[ObjectQL] No driver available for object 'sys_session'` (seen only in loaded runs where a `⑤` case had already timed out). It is noise after a timeout, not a second failure. Noted, not filed. - The measurement box was shared. The verify lock serialises locked runs only, and another worktree's unlocked build and gate work ran beside pair 10 and the unpaired runs 6-10. The interleaved design is what keeps the before/after comparison fair under that drift. --- _Generated by [Claude Code](https://claude.ai/code/session_01UYBdGBzWSrAMzpW8ah3GbP)_ Co-authored-by: Claude <noreply@anthropic.com>
1 parent 398e907 commit 80c29a1

1 file changed

Lines changed: 81 additions & 2 deletions

File tree

‎packages/client/src/auth-login-register-envelope.test.ts‎

Lines changed: 81 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -48,8 +48,61 @@
4848
// instrument's negative control, criterion 3(a)).
4949
// - `⑥ the raw keys survive the lift` — callers were pushed onto `.user` /
5050
// `.token` by the very misdeclaration this card fixes.
51+
// - `⑦ the cold start stays outside every clocked window` — pins WHERE the
52+
// first scenario's one-time cost is paid (next section).
53+
//
54+
// ## [#20242] Why one throwaway scenario runs at MODULE SCOPE
55+
//
56+
// The first scenario in a worker pays a one-time cost no later one sees.
57+
// Measured on `fdb26698f`, idle, 4 vCPU, successive scenarios in one worker,
58+
// first → later:
59+
// `getAuthInstance()` 510 → 10-11 ms better-auth's lazily imported
60+
// module graph (the dominant term)
61+
// `engine.init()` 85 → 1-2 ms sql.js compiles its WASM once
62+
// `syncSchemas()` 182 → 81-100 ms
63+
// the sign-up 261 → 117-127 ms
64+
// That cost used to land INSIDE whichever `it()` ran first: 855-964 ms idle,
65+
// against 222-249 ms for the two other cases doing the same single sign-up.
66+
// On a loaded `Test Core` shard (head `3d14f9e75`) it crossed vitest's
67+
// 5000 ms `testTimeout` while the fourteen other cases passed. That run's
68+
// client-package totals against this tree idle (`--maxWorkers=2`) are
69+
// `tests` 38.71 s vs 23.39 s and `import` 202 s vs 103 s: the test bodies
70+
// ran about 1.5x slower, and the first case more than 5x. So the term that
71+
// crossed the budget was cold LOADING, not the behaviour the case asserts.
72+
//
73+
// The fix changes WHERE that cost is paid, not how long anything may take.
74+
// `@vitest/runner@4.1.11` wraps hooks and test bodies in `withTimeout(...)`,
75+
// while `collectTests()` awaits `runner.importFile(filepath, 'collect')`
76+
// bare. So a module-scope `await` is paid during COLLECTION, which no clock
77+
// covers. This is the repo's convention: "clocked windows measure behaviour,
78+
// never loading" (AGENTS.md, Build & Test; `check:test-source-alias`). A
79+
// hook with its own timeout would only move the cliff to a budget a heavier
80+
// shard can exhaust.
81+
//
82+
// Why a WHOLE throwaway scenario (`registered()`) rather than only the loads
83+
// above: warming just the engine and `getAuthInstance()` left the next
84+
// scenario at 344-409 ms against 212-269 ms, because the sign-up path has
85+
// first-use costs of its own. Running the arrangement every case runs pays
86+
// them all, without a list of specifiers that could drift.
87+
//
88+
// ⛔ It shares nothing a case asserts on. Its engine and manager are its own
89+
// and are closed before any case starts. Every case still builds a fresh
90+
// engine, a fresh `AuthManager` and a fresh first sign-up (`scenario`). What
91+
// it leaves warm is process-level: the module registry, sql.js's compiled
92+
// WASM and the JIT. The first case used to leave exactly that to every later
93+
// case.
94+
//
95+
// ⛔ Do not move it into a hook, and do not answer a recurrence by raising a
96+
// timeout. A case's window now holds only its own work: a fresh-engine sync
97+
// and real scrypt sign-ups and logins. That is 222-574 ms idle, and 525-1708
98+
// ms under eight CPU-bound busy loops on this box. Twenty-four busy loops
99+
// reproduced CI's `Test timed out in 5000ms` on the cold case (2 runs of 2),
100+
// and there the heaviest cases (two sign-ups plus a login) took 3.7-4.5 s.
101+
// That residual is behaviour, which is what a clock is for.
51102

52103
import { describe, it, expect, afterEach } from 'vitest';
104+
import { readFileSync } from 'node:fs';
105+
import { fileURLToPath } from 'node:url';
53106
import { ObjectQL } from '@objectstack/objectql';
54107
import { SqliteWasmDriver } from '@objectstack/driver-sqlite-wasm';
55108
import { AuthManager } from '@objectstack/plugin-auth';
@@ -261,12 +314,21 @@ const principalFor = async (manager: AuthManager, token: string | undefined) =>
261314
return session?.user?.id ?? null;
262315
};
263316

264-
afterEach(async () => {
317+
/** Close every engine a scenario opened: after each case, and after the warm-up. */
318+
const closeEngines = async (): Promise<void> => {
265319
while (engines.length) {
266320
const engine = engines.pop();
267321
await (engine as unknown as { close?: () => Promise<void> })?.close?.().catch(() => {});
268322
}
269-
});
323+
};
324+
325+
// [#20242] The first scenario's one-time cost, paid during COLLECTION, which
326+
// no vitest clock covers (header, last section). ⛔ It stays at module scope,
327+
// and `⑦` below pins that.
328+
await registered();
329+
await closeEngines();
330+
331+
afterEach(closeEngines);
270332

271333
describe('[#17234] auth.login / auth.register deliver the SessionResponse envelope they declare', () => {
272334
describe('① the declared envelope is delivered', () => {
@@ -487,4 +549,21 @@ describe('[#17234] auth.login / auth.register deliver the SessionResponse envelo
487549
expect(raw.redirect).toBe(false);
488550
});
489551
});
552+
553+
describe('⑦ the cold start stays outside every clocked window', () => {
554+
it('pays the first scenario at module scope, and no hook carries it', () => {
555+
// [#20242] Read off this file's own text, so "do not move it into a
556+
// hook" is an assertion rather than a sentence nobody reads.
557+
const code = readFileSync(fileURLToPath(import.meta.url), 'utf8');
558+
559+
// Exactly one warm-up call, and it opens its own line at column 0. So it
560+
// sits in no function body, which is what "paid during collection"
561+
// reduces to. Comment lines start with `//` and cannot match.
562+
expect(code.match(/^await registered\(\);$/gm) ?? []).toHaveLength(1);
563+
564+
// ⛔ No `before*` hook may come back to carry it: vitest clocks a hook
565+
// with `hookTimeout` exactly as it clocks a test body with `testTimeout`.
566+
expect(code).not.toMatch(/^\s*before(All|Each)\s*\(/m);
567+
});
568+
});
490569
});

0 commit comments

Comments
 (0)