Skip to content

Commit 63a9bcb

Browse files
test(plugin-audit): seed the comment gate's window with fewer docs and reuse the leaf gate's at-rest reads (test budget, slice 20) (#28398)
<!-- claude-projects-attribution: {"github_login":"os-tesla"} --> _Requested by **Tesla** · [project thread](https://claude.ai/code/project/chan_01AXsQkLFKRdQCqQ3RTr6Jao?thread=cmsg_01AXsQkLFKRdQCqQ3RTr6JaoMehpns1xDy9YL8qPyWdBPt)_ Part of #23181 (slice 20, `@objectstack/plugin-audit`). The card is a series and stays open. Clause-②: no Metadata-protocol: none Test-only diff: `skip-changeset`. Two files under `packages/plugins/plugin-audit/src/`, both `*.integration.test.ts`; `@objectstack/plugin-audit`'s `files[]` ships `dist`, `README.md` and `CHANGELOG.md` only. ## 维护者速读 - 改了什么:plugin-audit 包 2 个集成测试文件。`comment-parent-pair` 把 2,600 条评论改为每个文档 10 条(260 个文档,而非 2,600 个),评论总数不变;`parent-record-read-leaf` 的各用例复用同一份系统读出的静止数据(行数变了就重读);两个文件都在模块顶层先付首次内核启动,并在第 2 行加 `// test-budget:` 声明。只动测试文件。 - 为什么改:卡 #23181 要求单个测试文件不超过 10 s;这两个文件在最近一次计时刷新里分别是 28.07 s 和 35.78 s,是 server 车道里最慢的两个不在卡单上的文件。 - 风险与回滚:不改断言、超时与分层;38 个用例名前后一致、全绿;评论文件自己打印的读数(静止 2,607 行、成员 A 可读 2,303 行、管理员 2,605 行)前后逐字节相同。回滚即 revert 本 PR。 - 先看:`comment-parent-pair.integration.test.ts` 的 `COMMENTS_PER_DOC` 注释(为什么窗口按评论行计、不按文档计);`parent-record-read-leaf.integration.test.ts` 的 `atRestOf`(复用的依据与行数守卫)。 - 两分钟验证:`pnpm --filter @objectstack/plugin-audit exec vitest run --maxWorkers=2 src/comment-parent-pair.integration.test.ts`,预期 20 个用例全绿,`tests` 耗时约为 main 上的 40%。 - 需要你做的:无,席位落地。 ## What changes The newest per-file reading is still the weekly shard-timings refresh of 2026-10-26 (run 40275747937, refresh PR #25960's window, hourly runs 40200279306 to 40272142430); the next scheduled refresh is 2026-11-02. Of the `domain:server` files over 10 s there that PR #28081's acceptance notes list for a later slice, the two slowest are in one package: `src/parent-record-read-leaf.integration.test.ts` 35.78 s and `src/comment-parent-pair.integration.test.ts` 28.07 s, both in run 40204927516. Profile (local, before): each file spends about 6 s of its clock seeding 2,600 `e5_doc` / `e7_doc` records. The records themselves cost about 0.15 s; the rest is the real CRUD mirror, which writes one `sys_audit_log` row and one `sys_activity` row per record (2,600 + 2,600 single-row creates, about 2.2 ms per record). The engine runs plugin hooks unconditionally (no opt-out reaches the audit writers, by design), so the mirror's cost cannot be skipped, only not paid where nothing reads it. **`comment-parent-pair`: comments ten to a doc.** The window this file proves the leaf lifts was over comment rows: the thread probe's candidate pre-scan reads `sys_comment` (`READ_SCAN_LIMIT` in `comment-access-hooks.ts`), never parent records. So the 2,600 comments now sit on 260 docs (230 of member A's, 30 of member B's), and only 260 records pay the mirror rows, which nothing in this file reads. Every comment count is unchanged: member A may read 2,303, the administrator 2,605, as the file's own `E7-COMMENT-READING` line prints on both sides. The three withheld docs (`a0` to `a2`) still exist, and the delegated case's withheld set is computed from the fixture, not assumed. **`parent-record-read-leaf`: at-rest reads reused.** Its cases made 68 system reads of a whole object (ground truth reads five per call, across 12 calls, plus 8 direct), most over tables of 2,600 to 7,000 rows, and the E5 describe writes nothing after its `beforeAll`. They now go through `atRestOf`, which reads each object once and reuses it; every reuse counts the object first and re-reads on a moved count, so a later case that adds or removes rows is never judged against an older ground truth. Its 2,600 records stay as they are: there the mirror's activity and ledger rows ARE the subject, written "as their producers write them" (the file's header), so this fixture is not shrunk. **Module-scope first boots (both files).** One module-scope line boots and shuts down a kernel with no fixture object before any hook runs (AGENTS.md: clocked windows measure behaviour, never loading). **Budget headers (ruling record 6181973363, letter B).** CI read these files at about 3.3 (comments) and 3.0 (leaf) times their local clock before, so both stay over 10 s on CI by that ratio, and each seeds a real-mirror fixture past the window on a real SQL driver: one line at line 2, N = the slowest CI reading x 1.25, rounded up to the next 10 s. | file | change | slowest CI reading (s) | budget | |:--|:--|--:|--:| | `src/comment-parent-pair.integration.test.ts` | ten comments per doc + module-scope first boot + header | 28.07 | 40 | | `src/parent-record-read-leaf.integration.test.ts` | at-rest reuse + module-scope first boot + header | 35.78 | 50 | ## Tests Per file, vitest's own clock (`tests` in the Duration line, what the refresh lane reads) and process wall, 3 isolated runs each, `--maxWorkers=2`, on a shared 4 vCPU container; before = `3ba52069`, after = `f267df4f` (`b905c57b` adds only the two header lines). | file | before r1/r2/r3 (s) | after r1/r2/r3 (s) | wall before / after (s) | |:--|:--|:--|:--| | comment-parent-pair | 9.56 / 7.84 / 8.41 | 3.67 / 3.88 / 3.59 | 30.9, 27.9, 26.0 / 23.7, 22.9, 22.5 | | parent-record-read-leaf | 14.39 / 11.54 / 10.44 | 9.19 / 9.31 / 9.17 | 37.1, 32.7, 27.7 / 29.0, 28.3, 28.7 | In `parent-record-read-leaf` the cases' own sum fell from 6.3 s to 3.0 s; what is left is the seeding above. The wall is mostly the package's import graph (transform about 13 s, import about 17 s per isolated run), which collection pays and no clock in the refresh lane reads. Whole package on `b905c57b`: `Test Files 68 passed (68)`, `Tests 1097 passed (1097)`. Name census over the two files' JSON reports, before (`3ba52069`) and after: 38 test names on both sides, 0 lost, 0 new, 0 with a changed status. After merging `origin/main` (`acf8e821`, no change under `plugin-audit`) the two files re-ran green: `Test Files 2 passed (2)`, `Tests 38 passed (38)`. <details><summary>Header parse</summary> Both lines parse through `readTestBudget` (`scripts/measure-test-shard-timings.mjs`): budgets 40 and 50 at line 2, class `spawns the real producer once per single-cause fixture`. </details> No ablation: no tested behaviour changed. ## Acceptance notes - `comment-parent-pair` may still read just over 10 s on CI after this (local 3.7 s against the 3.3 ratio above), which is why it carries a header; the next refresh is the reading that says. - `parent-record-read-leaf`'s floor is its mirror-written fixture (about 6 s locally). Shrinking it toward the 2,000-row window was not done: an earlier fix to this file (one case per reader) recorded "never a smaller fixture" as its rule. - The rest of PR #28081's list for later slices is unchanged by this PR: `@objectstack/metadata` (`src/serializers/typescript-serializer-annotation.test.ts` 23.74 s), `@objectstack/plugin-pinyin-search` (`src/boot-reconcile.integration.test.ts` 17.47 s), `@objectstack/plugin-security` and `@objectstack/plugin-auth` (two files each, 13.38 to 16.02 s). - Branch `claude/project-thread-6vedk4` is the card thread's platform-assigned branch; claim 6541983967 names it. ## Verification Local, on `acf8e821`: `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack` derived 52 families; each run with its exit captured by redirect before any pipe. 50 exit 0; `pnpm check:dual-build-cjs-loads` and `pnpm check:i18n` exit 3 (PREREQUISITE NOT MET: packages outside plugin-audit's closure have no `dist`, and the CLI is not built), NOT MEASURED here and CI's. `--ran`: `52 derived famil(ies) accounted for — 50 run, 2 NOT-MEASURED (2 DERIVED from a recorded exit 3)`, exit 0. Scoped lint, the root `lint` script's own command over `packages/plugins/plugin-audit`: exit 0. `pnpm --filter @objectstack/plugin-audit typecheck`: VERDICT command-exit 0 (`check:test-typecheck: OK`, 0 errors held). --- _Generated by [Claude Code](https://claude.ai/code/session_01L9qibz25B8NfvsjxU1ttwC)_ --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 75ecaf4 commit 63a9bcb

2 files changed

Lines changed: 55 additions & 12 deletions

File tree

‎packages/plugins/plugin-audit/src/comment-parent-pair.integration.test.ts‎

Lines changed: 22 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
2+
// test-budget: 40 — spawns the real producer once per single-cause fixture: three in-process kernel boots on a real SQL driver, the first seeding 2,600 comments on 260 docs through the real writers to sit past the 2,000-row window the comment gate replaced; slowest CI reading 28.07 s (run 40204927516, refresh PR #25960's window (hourly runs 40200279306 to 40272142430)) x 1.25, rounded up; read before this file seeded its comments ten to a doc and paid its first boot at module scope
23

34
/**
45
* [ADR-0139 E7] The comment-thread read gate on the LEAF path, over
@@ -55,9 +56,19 @@ const DELEGATED_A = { ...MEMBER_A, onBehalfOf: { userId: 'u_delegator' } };
5556
/** The delegator's own leg on `e7_doc` admits every record but these (by name). */
5657
const WITHHELD_FROM_DELEGATOR = ['a0', 'a1', 'a2'];
5758

58-
/** Past the 2,000-row candidate window the leaf replaces. */
59-
const DOCS_OF_A = 2_300;
60-
const DOCS_OF_B = 300;
59+
/**
60+
* Past the 2,000-row candidate window the leaf replaces: 2,300 comments member
61+
* A may read, 300 member B may. The window was over COMMENT rows (the thread
62+
* probe's candidate pre-scan reads `sys_comment`, `READ_SCAN_LIMIT` in
63+
* `comment-access-hooks.ts`), never over parent records, so the comments sit
64+
* ten to a doc. [#23181] One comment per doc wrote 2,600 docs, and each doc
65+
* write pays the CRUD mirror's ledger row and activity row, which nothing in
66+
* this file reads: about 6 s of the file's clock, against well under 1 s for
67+
* the comments themselves.
68+
*/
69+
const COMMENTS_PER_DOC = 10;
70+
const DOCS_OF_A = 230;
71+
const DOCS_OF_B = 30;
6172
const BATCH = 200;
6273

6374
const READ_OPS = new Set(['find', 'findOne', 'count', 'aggregate']);
@@ -145,6 +156,12 @@ const commentOn = (object: string, id: string, body: string): Row => ({
145156
author_id: 'u_fixture',
146157
});
147158

159+
// [#23181] Pay the first kernel boot at module scope, never in a hook: vitest
160+
// clocks a hook as it clocks a test, and the first boot is the slow one. The
161+
// throwaway kernel registers no fixture object, writes nothing and is shut down
162+
// before any hook runs.
163+
await (await bootKernel(new SqliteWasmDriver({ filename: ':memory:' }))).kernel.shutdown();
164+
148165
describe('[ADR-0139 E7] the comment-thread read gate over the stamped parent pair', () => {
149166
let kernel: ObjectKernel;
150167
let engine: ObjectQL;
@@ -209,7 +226,8 @@ describe('[ADR-0139 E7] the comment-thread read gate over the stamped parent pai
209226
for (let i = 0; i < DOCS_OF_A; i++) docs.push({ name: `a${i}`, owner: MEMBER_A.userId });
210227
for (let i = 0; i < DOCS_OF_B; i++) docs.push({ name: `b${i}`, owner: MEMBER_B.userId });
211228
const docIds = await insertInBatches(engine, DOC, docs);
212-
await insertInBatches(engine, COMMENT, docIds.map((id, i) => commentOn(DOC, id, `c${i}`)));
229+
await insertInBatches(engine, COMMENT, docIds.flatMap((id, i) =>
230+
Array.from({ length: COMMENTS_PER_DOC }, (_, k) => commentOn(DOC, id, `c${i * COMMENTS_PER_DOC + k}`))));
213231

214232
ids.gone = String((await engine.insert(DOC, { name: 'gone', owner: MEMBER_A.userId }, { context: SYS })).id);
215233
ids.vault = String((await engine.insert(VAULT, { name: 'vault' }, { context: SYS })).id);

‎packages/plugins/plugin-audit/src/parent-record-read-leaf.integration.test.ts‎

Lines changed: 33 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
2+
// test-budget: 50 — spawns the real producer once per single-cause fixture: two in-process kernel boots on a real SQL driver, the first seeding 2,600 records through the real CRUD mirror (each pays its activity row and its ledger row) to sit past the 2,000-row window the leaf gate replaced; slowest CI reading 35.78 s (run 40204927516, refresh PR #25960's window (hourly runs 40200279306 to 40272142430)) x 1.25, rounded up; read before this file reused its at-rest reads and paid its first boot at module scope
23

34
/**
45
* [ADR-0139 E5] The parent-record read gates on the LEAF path, through a real
@@ -180,6 +181,12 @@ async function insertInBatches(engine: ObjectQL, object: string, rows: Row[]): P
180181
}
181182
}
182183

184+
// [#23181] Pay the first kernel boot at module scope, never in a hook: vitest
185+
// clocks a hook as it clocks a test, and the first boot is the slow one. The
186+
// throwaway kernel registers no fixture object, writes nothing and is shut down
187+
// before any hook runs.
188+
await (await bootKernel(new SqliteWasmDriver({ filename: ':memory:' }))).kernel.shutdown();
189+
183190
describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
184191
let kernel: ObjectKernel;
185192
let engine: ObjectQL;
@@ -201,12 +208,30 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
201208
const ledgerOrganizationBound: boolean[] = [];
202209
const ids: Record<string, string> = {};
203210

211+
/**
212+
* [#23181] Every row of an object at rest, as the system reads it — read once
213+
* and reused. No case in this describe writes after `beforeAll`, so each such
214+
* read answered the same rows: the cases made nearly seventy of them, most
215+
* over tables of thousands of rows. Each reuse counts the object first and
216+
* re-reads on a moved count, so a case that adds or removes rows is never
217+
* judged against an older ground truth.
218+
*/
219+
const atRestCache = new Map<string, { count: number; rows: Row[] }>();
220+
const atRestOf = async (object: string): Promise<Row[]> => {
221+
const count = await engine.count(object, {}, { context: SYS });
222+
const hit = atRestCache.get(object);
223+
if (hit && hit.count === count) return hit.rows;
224+
const rows: Row[] = await engine.find(object, { limit: 100_000, context: SYS });
225+
atRestCache.set(object, { count, rows });
226+
return rows;
227+
};
228+
204229
/** Every row at rest, and the ground truth of who may read which, judged by the stand-in's own rules. */
205230
const truth = async (object: string, reader: any): Promise<string[]> => {
206-
const atRest: Row[] = await engine.find(object, { limit: 100_000, context: SYS });
231+
const atRest = await atRestOf(object);
207232
const live = new Map<string, Map<string, Row>>();
208233
for (const parent of [DOC, VAULT, GATED, FAR]) {
209-
const records: Row[] = await engine.find(parent, { limit: 100_000, context: SYS });
234+
const records = await atRestOf(parent);
210235
live.set(parent, new Map(records.map((r) => [String(r.id), r])));
211236
}
212237
const holder = Array.isArray(reader?.systemPermissions) && reader.systemPermissions.includes(LEDGER_AUDIT_CAPABILITY);
@@ -298,12 +323,12 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
298323
}, 30_000);
299324

300325
it('control: the fixture is past the window, and every row came from its producer', async () => {
301-
const activity: Row[] = await engine.find(ACTIVITY, { limit: 100_000, context: SYS });
326+
const activity = await atRestOf(ACTIVITY);
302327
expect(activity.length).toBeGreaterThan(PARENT_GATE_SCAN_LIMIT);
303328
expect(activity.filter((r) => r.object_name === DOC && r.type === 'created').length).toBe(DOCS_OF_A + DOCS_OF_B + 1);
304329
expect(activity.some((r) => r.object_name === DOC && r.record_id === ids.gone && r.type === 'deleted')).toBe(true);
305330
expect((await truth(ACTIVITY, MEMBER_A)).length).toBeGreaterThan(PARENT_GATE_SCAN_LIMIT);
306-
const ledger: Row[] = await engine.find(LEDGER, { limit: 100_000, context: SYS });
331+
const ledger = await atRestOf(LEDGER);
307332
expect(ledger.filter((r) => r.action === 'config_change').length).toBe(ROWS_ABOUT_NO_RECORD);
308333
});
309334

@@ -328,7 +353,7 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
328353
});
329354

330355
it('no row is served whose parent the reader may not read, or that no longer exists', async () => {
331-
const all: Row[] = await engine.find(ACTIVITY, { limit: 100_000, context: SYS });
356+
const all = await atRestOf(ACTIVITY);
332357
const byId = new Map(all.map((r) => [String(r.id), r]));
333358
for (const id of await served(ACTIVITY, MEMBER_A)) {
334359
const row = byId.get(id)!;
@@ -379,7 +404,7 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
379404
const named = { object_name: { $in: NAMED } };
380405
// The same rows, in a spelling the gate does not read as naming its parents: it keeps every branch.
381406
const spelledOut = { $or: NAMED.map((object_name) => ({ object_name })) };
382-
const atRest: Row[] = await engine.find(ACTIVITY, { limit: 100_000, context: SYS });
407+
const atRest = await atRestOf(ACTIVITY);
383408
const parentOf = new Map(atRest.map((r) => [String(r.id), r.object_name]));
384409
const gateConjunct = (where: any) => where.$and[1];
385410
seenWhere[ACTIVITY].length = 0;
@@ -431,7 +456,7 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
431456
// per parent object through the engine middleware chain, with the
432457
// delegated context. Asked here for every parent pair at rest, so no
433458
// window cuts it; the leaf must serve exactly the rows it admits.
434-
const atRest: Row[] = await engine.find(ACTIVITY, { limit: 100_000, context: SYS });
459+
const atRest = await atRestOf(ACTIVITY);
435460
const pairs = new Map<string, Set<string>>();
436461
for (const row of atRest) {
437462
const parent = parseParentRecord(row, ACTIVITY);
@@ -488,7 +513,7 @@ describe('[ADR-0139 E5] the parent-record read gates on the leaf path', () => {
488513
return Math.round((performance.now() - t0) * 10) / 10;
489514
};
490515
const reading = {
491-
rowsAtRest: (await engine.find(ACTIVITY, { limit: 100_000, context: SYS })).length,
516+
rowsAtRest: (await atRestOf(ACTIVITY)).length,
492517
leafMs: {
493518
memberFind: await time(() => served(ACTIVITY, MEMBER_A)),
494519
memberCount: await time(() => engine.count(ACTIVITY, {}, { context: MEMBER_A })),

0 commit comments

Comments
 (0)