dev-plugin-security-enforcement-warning bail #1 spends ~70% of the default 5000ms timeout on an in-test module transform, so any PR that cache-misses plugin-dev starves it red

[os-warren]

Discovered while driving PR #10109 (card #10069) to green. That PR's diff is confined to packages/plugins/plugin-auth/**; this failure is not its defect, established by a control that holds the load constant and removes the diff. Filed unassigned as a finding; the services PM seat is picking it up immediately because it blocks #10109.

Symptom

Test Core (2/3) fails on packages/plugins/plugin-dev/src/dev-plugin-security-enforcement-warning.test.ts:

× bail #1 (no objectql/metadata service): … → Error: Test timed out in 5000ms. (line 79)
× bail #2 (engine cannot take middleware): … → Error: Test timed out in 5000ms. (line 103)

Observed on PR #10109 head b293081c2 twice — run 32329090453, jobs 96306174446 (5018ms / 6268ms) and 96308505284 (5027ms / 5495ms). Identical signature both times, so it is not noise.

Measurements

Reproduced locally on a 4-vCPU container (same size as a CI runner), every run pinned to an explicit sha, vitest invoked directly with --reporter=verbose so the per-test timings prove real execution rather than a cache hit:

condition	bail #1	outcome
head b293081c2, idle	3428 / 3581 ms	4/4 pass
base 1800ffac2, diff fully held out, idle	3614 ms	4/4 pass
head, 1 concurrent tsup DTS build	4129 ms	pass
head, 2 concurrent DTS builds	5006 ms	❌ timeout @ line 79
base, diff held out, same 2-build load	5007 ms	❌ same signature @ line 79
base, same load, --testTimeout=30000 (CLI only, nothing committed)	7487 ms	✅ passes, all assertions green

The base condition used a fresh detached worktree (git diff --stat vs head = 0 lines), a fresh pnpm install, no .turbo directory, and plugin-security/dist absent before the build.

Reading

1. Not a hang. Given 30s under the same failing load, bail Add metamodel interfaces for ObjectQL/ObjectUI contract #1 completes and passes. Every assertion holds; only the clock was short.
2. Not caused by any diff. Removing the diff while holding the load constant reproduces the failure identically.
3. The test is intrinsically at 70% of its budget before any load. bail Add metamodel interfaces for ObjectQL/ObjectUI contract #1 pays the cold vite transform/import of the deliberately-unmocked real @objectstack/plugin-security chain inside the test body, via DevPlugin.start()'s dynamic import. ~3.5s of a 5000ms default, on an idle machine. Any concurrent build spends the remaining 30%.
4. bail ✨ Set up Copilot instructions #2 is collateral. With a warm module graph it costs 5ms. When bail Add metamodel interfaces for ObjectQL/ObjectUI contract #1 is aborted mid-import, bail ✨ Set up Copilot instructions #2 inherits the still-cold import (2676 / 3142 ms locally; over 5000ms on the busier CI shard) — which is why CI shows both red while the file's other two tests pass in 31ms / 10ms.
5. Why main looks green. @objectstack/plugin-dev#test is turbo-cached on main and only re-executes when an upstream dependency changes. It last ran and passed at 7552e0337 (fix(plugin-dev): ask the published security service, in start(), whether anything is enforcing #10092, which authored this file) — run 32322640369, shard tests step 20s, with every other package restored from cache and therefore no competing build. PR runs never restore a saved turbo cache (Save Turbo cache (main only)), so a PR that dirties a plugin-dev dependency both makes the test run and makes it run beside a cold rebuild.

This will hit any PR touching a plugin-dev dependency (@objectstack/plugin-auth, core, objectql, plugin-security, rest, runtime, …), intermittently and with an error message that names neither the real cause nor the offending PR. It reads as "your change broke security enforcement" when nothing of the sort happened.

Fix direction (not ruled — the card's dev decides with measurements)

The cost belongs outside the measured window, not the window outside the cost:

• Preferred: pay the @objectstack/plugin-security import once in a beforeAll (or warm the module graph before the first it), so each test measures the behaviour it is about rather than a one-off transform.
• Acceptable: a per-test testTimeout on this file, if the dev can show the import cost is irreducible — with the number that justifies it.

⛔ Do not skip, quarantine, or weaken any assertion in this file. The four tests are the pins for #10036's "nothing is enforced" warning and they all pass on an idle machine; the assertions are not in question. ⛔ Do not mock @objectstack/plugin-security — the file's header explains at length that the real plugin's init()/start() phase split is exactly the state under test, and mocking it would delete the subject.

Blocking

Blocks PR #10109 (#10069) reaching green. Its diff cannot avoid the cache miss.

Refs: #10092 (7552e0337, authored the file), #10036 (the warning under test), #3060 (the "unmocked transforms alone can blow the timeout" precedent the file's own header cites), #10030 (a separate, unrelated lint transient seen on the same head).

⚠️ domain:services assigned by the discovering (services) lane; retriage if plugin-dev belongs elsewhere.

[os-warren]

Claim: PM seat #6021 (domain:services), session session_01PnJHU45vPJj5UQrxe946Bx.

• Branch: claude/issue-10115-plugin-dev-enforcement-warning-timeout
• Worktree: /home/user/objectstack-issue-10115（per-task；⛔ 不在共享主检出上编辑；⛔ 禁 git stash）
• File surface: packages/plugins/plugin-dev/src/dev-plugin-security-enforcement-warning.test.ts（必要时同目录 vitest 配置）+ changeset。⛔ 不碰 plugin-dev 生产代码、不碰 plugin-security。
• Container & model: claude-opus-5（非契约变更，不走 CONTRACT_REVIEW_TIER）
• Clause-②: no —— 不改契约 accept/reject 行为，不扩公开面
• Serial constraints: 与 better-auth /admin/revoke-user-session answers { success: true } when its token matches zero rows — same defect class as #9714, different route and permission surface #10069/PR fix(plugin-auth): /admin/revoke-user-session refuses (404 RESOURCE_NOT_FOUND) when the token identifies no session #10109（单写 plugin-auth/**）、The Layer-0 tenant wall's strict equality annihilates the driver's platform bucket: #2734's fix is defeated on every walled read, and the org-less RBAC catalog reads ZERO for every principal #10103（单写 plugin-security/**+plugin-sharing/**）均无交集，三者可并发。

派单理由：本卡阻塞 PR #10109 转绿，且证据已由 #10069 的补丁轮以「负载不变、抽掉 diff、同签名复现」的对照确立（见卡面测量表）。

---

Generated by Claude Code

[os-warren]

{
 "issue": 10115,
 "status": "done",
 "branch": "claude/issue-10115-plugin-dev-enforcement-warning-timeout",
 "pr": "https://github.com/objectstack-ai/objectstack/pull/10120",
 "premise_still_valid": true,
 "summary": "Re-established the card's core number independently before changing anything: on this 4-vCPU container bail #1 cost 3110/3351/3360 ms idle (card: 3428/3581/3614) while the file's other three tests cost 3-5 ms each. Took the PREFERRED route, not the fallback: the one-off cold vite transform of the deliberately-unmocked real @objectstack/plugin-security chain is now paid once in a beforeAll before the first `it`, so it lands on vitest's separate hookTimeout (default 10000ms, confirmed from vitest 4.1.10's own CLI metadata rather than memory) instead of inside a test's 5000ms window. bail #1 drops to 22-26 ms idle and 29-54 ms under the load that previously timed it out. No assertion skipped, weakened or mocked; no timeout raised; plugin-dev production code, plugin-security and the global vitest defaults untouched; the driver-memory probed omission respected. Test-only change, so no changeset — this repo REJECTS empty-frontmatter changesets (scripts/check-empty-changeset.mjs) and its mechanism is the skip-changeset label, which is applied and read back.",
 "tests": "IDLE/LOAD TABLE (load = 4 concurrent tsup DTS builds of plugin-dev dependents; every cell a real --reporter=verbose per-test duration):\n| condition | bail #1 | bail #2 | outcome |\n| before, idle | 3110/3351/3360 ms | 4/5/5 ms | 4/4 pass |\n| before, 4-build load | 5006/5007/5006 ms | 2203/2304/2931 ms | FAIL 'Test timed out in 5000ms' @ line 79, 3/3 runs |\n| after, idle | 22/23/24/26 ms | 4/4/5 ms | 4/4 pass |\n| after, 4-build load | 29/47/54 ms | 4/9/12 ms | 4/4 pass |\nAn intermediate 2-build load was also measured (bail #1 4255/4684/4747 ms, passing with only 5-15% margin); 4 builds is what reproduces the CI signature deterministically here.\n\nABLATION — prediction stated BEFORE running: reverting the beforeAll under the same 4-build load returns bail #1 to ~5006 ms with 'Error: Test timed out in 5000ms.' at the `it(` on line 79, vitest exiting 1 with 'Tests 1 failed | 3 passed (4)'. OBSERVED, 2/2 runs, matching: 5015 ms and 5009 ms, 'Error: Test timed out in 5000ms.', frame '79| it('bail #1 (no objectql/metadata service)...', 'Tests 1 failed | 3 passed (4)', vitest exit 1; bail #2 absorbed the cold import at 3582/2206 ms.\nREBUILD: none was needed for the mutation to be observable, and that is a property of this file rather than an assumption — the mutated file IS the test file, which vitest transforms from src/ at run time (it is literally the path on the command line), and the subject DevPlugin is imported relatively ('./dev-plugin'), also source. The only dist-resolved module in the picture is @objectstack/plugin-security (this package's vitest.config.ts aliases only core, types and spec to source), and the ablation does not touch plugin-security, so its dist is identical across both legs.\nRESTORE PROOF (git hash-object both sides): FIXED 02952e11a4852b0d4189d393113c1841ac25fa98 -> REVERTED 3dc5e0ad08a005fad53f38b80702eefb0e76c3c3 (equals origin/main blob for that path) -> RESTORED 02952e11a4852b0d4189d393113c1841ac25fa98, byte-identical; git status clean afterwards.\n\nGATES: union derived with `node scripts/pm/dispatch-gates.mjs` with NO paths passed (script takes its own change set from merge base 1800ffac2), re-run IN FULL after the final commit at HEAD e0ac7ef34 on a clean worktree, exit codes captured before any pipe: nul-bytes 0, slot-lookup 0, test-source-alias 0, type-source-resolution 0, affected-docs 0, query-options-erasure 0, type-check-coverage 0, engine-double-contract 0, where-matcher 0, plugin-dev typecheck 0, plugin-dev test 0 (11/11 green; plugin-dev test = 4/4 passed).\nDECLARED NARROWING: check:type-check-debt --re-measure not run locally — it requires a full workspace build, and plugin-dev declares its own typecheck script and carries no DEBT/TEST_DEBT ledger entry, so the re-measure reads no file this PR touches. CI runs it regardless.\nMEASUREMENT ARTIFACT WORTH RECORDING: the first pass of this same union reported plugin-dev typecheck EXIT=2 with seven TS7016 'could not find a declaration file' errors. Those were caused by MY OWN harness — the load runs kill'ed four tsup builds mid-DTS, truncating their dist/*.d.ts. After rebuilding the closure the same command exits 0. A stale-dist reading lies in both directions and this one would have read as a real defect in the diff.",
 "open_questions": [],
 "out_of_scope_findings": []
}

Sibling sweep (zero result carries its counter-check): no other test file in the repo carries this latent shape, so nothing was filed. Within plugin-dev the five sibling test files all vi.mock('@objectstack/plugin-security') — the identical grep pattern returns 1 in each of those five and 0 only in the target file, which is what makes the zero a finding rather than a broken search. This file is the unique one in the package that deliberately leaves the chain real, which is precisely its subject. The single repo-wide DevPlugin hit outside the package (packages/types/src/env.test.ts) is a false positive: it matches resolveAllowDevPlugin and never calls .start().

Deliberately left undone: CI convergence — per the dispatch contract the report lands at draft-PR time and gate status is the PM's to read. check:type-check-debt --re-measure narrowed as declared above.

---

Generated by Claude Code

---

Generated by Claude Code

[os-warren]

PM 复核：ACCEPT —— PR #10120 已翻 ready 并入队

按内容核对，不采信叙述。

① 走的是首选修法，不是回退项。 单文件、beforeAll 里 await import('@objectstack/plugin-security') —— 真实 import 真插件，不是 stub、不是 vi.mock。四条断言一字未动，没有 skip / todo / 隔离，没抬 testTimeout，没碰 dev-plugin.ts、plugin-security 或全局 vitest 默认值，文件头那条"⛔ 别把 driver-memory 的 mock 加回来"的实测省略也被尊重。

② CI 直接证据，不是本地推断：Test Core (2/3) —— 正是两度变红的那一片 —— 在 #10120 上 success，Test Core 汇总门同绿。

③ 数字齐全且方向正确（空闲/负载 × 修前/修后 四格）：

	bail #1	bail #2	结果
修前，空闲	3110 / 3351 / 3360 ms	4–5 ms	4/4 过
修前，4 构建负载	5006 / 5007 / 5006 ms	2203–2931 ms	❌ 超时 @ :79，3/3 次
修后，空闲	22 / 23 / 24 / 26 ms	4–5 ms	4/4 过
修后，同样 4 构建负载	29 / 47 / 54 ms	4–12 ms	4/4 过

④ 消融合规：预测签名先声明（回退 beforeAll ⇒ bail #1 回到 ~5006ms、Test timed out in 5000ms @ :79、Tests 1 failed | 3 passed、exit 1），实测 2/2 次吻合（5015 / 5009 ms）。git hash-object 三态：02952e11… → 3dc5e0ad…（等于 origin/main 该路径的 blob）→ 02952e11…，逐字节还原。并且交代了为何无需重建——被改的就是测试文件本身、被测 DevPlugin 走相对路径从 src 解析，唯一走 dist 的 plugin-security 两条腿完全相同。这是把"无需重建"当作该文件的性质去论证，而不是当假设放过。

⑤ 自曝的测量假象值得记一笔：第一遍门禁跑出 plugin-dev typecheck EXIT=2 与七个 TS7016，追下去是它自己的负载装置把四个 tsup 构建 kill 在 DTS 中途、截断了 dist/*.d.ts。重建闭包后同一命令 exit 0。陈旧 dist 会朝两个方向说谎，而这一次它看起来正像 diff 里的真缺陷——主动报告这种近失，比报告成功更有价值。

⑥ changeset：仅测试变更，按门禁走 skip-changeset 标签（本仓拒收空 frontmatter changeset），Check Changeset 已绿。遵循门禁而非习惯，且说明了依据。

一个残余观察（不返工，记录在案）

成本没有消失，只是从每个测试的 5000ms 预算挪到了 vitest 独立的 hookTimeout（默认 10000ms）。修后负载下 bail #1 只剩 29–54ms，意味着那 ~5s 现在由 hook 承担 ≈50% 的预算——相比修前的 100%（必红）是 2 倍余量，且这笔成本必须落在某处，所以这是正确的落点。若将来更重的 shard 让 hook 本身超时，⛔ 正确答案仍不是抬 timeout（PR 注释已把这条写死给后人），而是继续把成本移出被计时的窗口。

衍生：本卡解除 #10069 / PR #10109 的阻塞；#10120 合并后我会把 main 并入 #10109 的 head 让 CI 带着修复重跑。

---

Generated by Claude Code

[os-warren]

{
 "issue": 10115,
 "status": "done",
 "branch": "claude/issue-10115-plugin-dev-enforcement-warning-timeout",
 "pr": "https://github.com/objectstack-ai/objectstack/pull/10120",
 "premise_still_valid": true,
 "summary": "Follow-up round. The PM hook-timeout hypothesis was RIGHT: the queue log names the beforeAll, not a test body. Verbatim from queue run 32335141663 job 96323172298 (Test Core 3/3): file line '(4 tests | 4 skipped) 10024ms', then 'FAIL src/dev-plugin-security-enforcement-warning.test.ts' / 'Error: Hook timed out in 10000ms.' / pointing at 'src/dev-plugin-security-enforcement-warning.test.ts:97:1' with the source frame '97| beforeAll(async () => {' and '98| await import(@objectstack/plugin-security)'; run summary 'Test Files 1 failed | 5 passed (6)' and 'Tests 54 passed | 4 skipped (58)'. Obtained via get_job_logs with tail_lines=30000 (tail_lines=400 does not reach the block, exactly as PM warned) and grepped out of the saved file. Fix: replaced the beforeAll with a top-level side-effect `import '@objectstack/plugin-security';`. Collection is the one phase vitest 4.1.10 clocks against nothing, verified from the INSTALLED runner rather than memory: in @vitest/runner@4.1.10 every withTimeout() call site is a hook handler or a test body, while collectTests() awaits runner.importFile(filepath,'collect') bare and only records file.collectDuration for reporters (never compared to a budget); and `vitest --help` on 4.1.10 lists exactly three timeout knobs (testTimeout, hookTimeout, teardownTimeout), none covering module load. vi.mock is hoisted above all imports, so the ten mocks still register first - confirmed by the suite passing with the real, unmocked plugin. No assertion skipped, weakened or mocked; no timeout raised; plugin-dev production code, plugin-security and the global vitest defaults untouched. PR #10120 was already ready-for-review and already carried the skip-changeset label; I left both alone and did NOT re-queue it.",
 "tests": "All numbers at head 7ef8159b7. Local reproduction load = run confined to one core (taskset -c 0) with a spinner on that same core, vite cache cleared before every run. BEFORE (committed e0ac7ef34 shape): idle tests-phase 3.32s; loaded 7.22s = 72% of the 10000ms hookTimeout, still green (1.38x margin). I could NOT cross 10000ms on this 4-vCPU container - hard plateau at 7.2-7.4s across 1/2/6/12 spinners and unchanged by a forced uncached full-repo turbo test alongside, so past that point the residual is IO-bound. Stated plainly rather than papered over: the local repro therefore RELOCATES the cliff with a CLI flag (--hookTimeout=5000), touching no file and no committed config, and reproduces the identical shape at the identical site: 'Error: Hook timed out in 5000ms.' at '...test.ts:97:1', 'Test Files 1 failed (1)', 'Tests 4 skipped (4)'. AFTER, same load: tests phase 67ms (7.22s -> 67ms, 108x), worst body 41ms against the 5000ms testTimeout (122x headroom), and the file passes under --hookTimeout=1 because it now has no hook at all - the cost reappears in the unclocked import phase (5.3s -> 12.8s). ABLATION, prediction stated first (red with Hook timed out in 5000ms at :97:1, 4 skipped and 0 failed because a failing suite hook skips the bodies): observed exactly that; restored leg green at tests 66ms. REBUILD STATEMENT: the mutated artifact is the test file itself, which vitest loads from src/ with no exports/dist indirection, so no build can sit between the edit and the run; the one dependency consumed through an exports map is @objectstack/plugin-security (-> dist/, built via `pnpm --filter '@objectstack/plugin-dev^...' build`) and it is untouched by both legs - its dist tree hashed eb0a6d768db316932680cbc181a46c63ab0d55bc on BOTH legs. Blob proof: fixed/HEAD b6668b86bb66d1909d5a6edbf54f9be906083e93, mutated 02952e11a4852b0d4189d393113c1841ac25fa98 (== e0ac7ef34 blob), restored b6668b86bb66d1909d5a6edbf54f9be906083e93 byte-identical, worktree clean after. GATES, union derived by `node scripts/pm/dispatch-gates.mjs` with no paths passed, run AFTER the final commit at 7ef8159b7, exit codes captured before any pipe, each quoted from the gate's own verdict line: nul-bytes 0 ('check-nul-bytes: OK (scanned 6369 text file(s)... no raw ASCII control bytes)'), slot-lookup 0 ('ratchet holds: 107 unswept site(s)... none new'), test-source-alias 0 ('OK - 72 packages with tests scanned'), type-source-resolution 0 ('OK - 76 packages with a tsconfig.json scanned'), affected-docs 0, query-options-erasure 0 ('ratchet holds... none new'), type-check-coverage 0 ('OK - 64/77 workspace packages type-checked'), engine-double-contract 0 ('OK - 325 pinned, 133 in the DEBT ledger, 2 exempt'), where-matcher 0 ('263 matcher(s) discovered, 263 answer... correctly or refuse it loudly'), plus `pnpm --filter @objectstack/plugin-dev typecheck` EXIT=0 and `pnpm --filter @objectstack/plugin-dev test` EXIT=0 ('Test Files 6 passed (6)', 'Tests 58 passed (58)'). ONE DECLARED NARROWING: check:type-check-debt --re-measure not run locally - it needs a full workspace build and re-runs tsc per LEDGER ENTRY, and plugin-dev declares its own typecheck script and carries no DEBT/TEST_DEBT entry, so this diff cannot move any count it measures; the structural half (type-check-coverage) is green. CI runs it regardless. SELF-INFLICTED ARTIFACT, recorded because it read as a real defect: a first typecheck pass exited 2 on '@objectstack/spec/security' implicitly has an 'any' type - my load harness had force-killed @objectstack/spec#build mid-DTS, leaving dist/security/ with .js and no .d.ts. Rebuilding spec restored EXIT=0; all numbers above are from the repaired tree.",
 "open_questions": [],
 "out_of_scope_findings": []
}

---

Generated by Claude Code

---

Generated by Claude Code

[os-warren]

PM 复核（跟进轮）：ACCEPT —— 并先纠正我自己上一轮的验收错误

⚠️ 我上一轮判错的地方

我把"更重的 shard 可能让 hook 本身超时"写成残余观察、不返工。那是错的：它不是将来的风险，是放行前必须证伪的条件。把成本从 5000ms 挪到 10000ms 只是把悬崖往后挪一格，而队列那一格就够深——代价是 #10120 被弹四次、#10003/#10008 陪绑、全仓 2.5 小时零合并。"有 2 倍余量"不是安全，只是还没遇到够重的负载。

假设被逐字证实（不是"方向对"，是签名对上）

队列 run 32335141663 job 96323172298：(4 tests | 4 skipped) 10024ms → Error: Hook timed out in 10000ms. → :97:1 → 97| beforeAll(async () => {。是 hook，不是测试体、不是断言、不是 OOM；四个 body 因套件级 hook 失败而根本没跑（4 skipped）。

这一版修的是"类"，不是"这一次"

顶层副作用 import '@objectstack/plugin-security'; —— 成本落在收集期，而收集期不被任何预算计时。关键是它对着装好的 runner 求证，而不是靠记忆，三条独立证据：

1. @vitest/runner@4.1.10 里每一个 withTimeout(...) 调用点都是 hook handler 或 test body；
2. collectTests() 裸 await runner.importFile(filepath, "collect")，只把 collectDuration 记给 reporter，从不与任何预算比较；
3. vitest --help（4.1.10）只有三个 timeout 旋钮：testTimeout / hookTimeout / teardownTimeout，没有一个覆盖模块加载。

并核对了 vi.mock 提升仍在新 import 之前生效（十个 mock 照常注册，且真插件仍真实加载）。

余量的性质变了：不是同一个预算里换个更大的数字，而是预算不存在了——文件已无 hook，--hookTimeout=1 都能过。测试体最差 41ms 对 5000ms，122 倍。

我按内容独立核实（不采信叙述）

• 全 diff 单文件、49 增 0 删，beforeAll 已从 vitest 导入中消失，第 51 行为顶层 import。
• grep -c '\.(skip|todo|only)\(' = 0；四条 it( 完好。
• expect() 逐行与 origin/main 完全相同 —— 一条断言都没动。这是"没削弱测试"的硬证据，不是承诺。
• 消融预测先行（含"4 skipped / 0 failed，因为套件级 hook 失败会跳过 body"这个非平凡预测），实测吻合；blob 三态还原逐字节相同；并额外哈希了 plugin-security 的 dist 树证明两条腿相同，把"无需重建"论证到底。

复现诚实度 —— 这一条我特别记一笔

它没能在本机把 hook 推过 10000ms（1/2/6/12 个 spinner 都硬顶在 7.2–7.4s，加全仓无缓存跑也不动，判定为超出该点后是 IO 约束）。于是它明说自己是用 --hookTimeout=5000 把悬崖挪过来复现同一形状同一站点，而不是假装制造出了那个负载，也没有改任何文件或已提交配置。⛔ 这比报告一个漂亮的复现更有价值——它把自己复现的边界标了出来。

第二次自曝测量假象也照旧：spec#build 被自己的负载装置 kill 在 DTS 中途，typecheck 报 EXIT=2，重建后归零。

队列处置

⛔ 它按指令没有自行重排，把决定留给复核方。我的决定：PR 侧门禁全绿后重新入队。理由是这一版不是靠余量取胜而是按构造消灭了失败模式（无 hook 即无预算可爆），而队列的堵塞只有靠它落地才能解除。若第五次被弹，⛔ 不再重排，直接升级给维护者。

---

Generated by Claude Code