CI: `Test Core` stalls mid-suite with frozen log output — three occurrences in one day, each costing a manual diagnosis + rerun

[os-zhuang]

现象

Test Core 进入一种输出冻结但 job 不结束的状态：日志停在某个测试文件，之后既没有新行、也没有失败，job 一直挂在 in_progress，直到有人取消或 timeout 兜底。

一天之内命中三次，分属不同 PR、不同停摆位置：

时间	Run / Job	最后一条输出所在文件	处置
~11:34Z	run 30539038818 / job 90859196790	metadata-validation-sweep.test.ts	人工取消 + rerun
（同日早些）	—	metadata-validation-sweep.test.ts 附近	人工取消 + rerun
16:34Z	run 30562022449 / job 90937246030	src/protocol-unknown-query-param.test.ts	人工取消 + rerun

第三次的取证比较硬：两次相隔 9 分钟的 get_job_logs 返回逐字节相同的内容 —— 同一 flush 时间戳 16:42:31.7491868Z、同一末行、original_length 同为 19071。累计静默 22 分钟、总运行 30 分钟。取消后 rerun 的 attempt 2 用 11 分 41 秒正常通过，同一 commit、同一套件、零改动。

为什么值得单独立项

1. 它不是慢，是停。 正常 11-12 分钟，停摆时静默 20+ 分钟且日志长度不再增长 —— 两者可以用「flush 时间戳 + original_length 是否推进」机械区分，不需要猜。
2. chore(ci): nightly rerun-safety gate, job timeouts, compiled-tests-in-dist guard #4156 的 job timeout 只兜底，不止损。 有 timeout 意味着不会挂 6 小时，但每次仍然是：等到超时（或人工发现）→ 判断是不是自己 diff 的锅 → 取消 → rerun → 再等一轮。三次事故 = 三次人工诊断。
3. 它把「CI 红」的信噪比压低了。 停摆表现为「一直没结论」，与「测试真的很慢」在 UI 上无法区分，所以默认反应是继续等 —— 这正是最贵的反应。

值得查的方向（未验证，仅按现象排序）

• 两个停摆点（metadata-validation-sweep、protocol-unknown-query-param）都是起真实 ObjectQL engine / 大量 registry 注册的用例，日志里最后可见的都是引擎初始化序列（ObjectQL Engine Instance Created → Driver connected → initialization complete 反复多次）。怀疑与每用例新建引擎实例后未释放的句柄（driver 连接 / 定时器）有关 —— 句柄不释放会让 vitest 的进程池在收尾时等待而非退出。
• 若确实是句柄泄漏，--reporter=verbose 配合 detectOpenHandles 一类的排查，或给 suite 级别加 teardown 断言，比继续加 timeout 更能根治。
• 另一个可能是 CI runner 侧的 I/O 卡顿，但同一 commit rerun 就好、且三次分属不同 runner，指向套件的可能性更大。

建议的最小动作

不要求立刻根治。最低成本的改进是让停摆自己说话：给 Test Core 一个显著短于当前兜底值的 timeout（比如正常时长的 2-3 倍），这样它会以「超时失败」而不是「一直在跑」的形式呈现 —— 把一次需要人工判读日志时间戳的诊断，变成一条明确的红。

相关

• chore(ci): nightly rerun-safety gate, job timeouts, compiled-tests-in-dist guard #4156 —— 加入 job timeout 的那次改动（兜底存在，但不解决信噪比）
• 本次三例的 PR 上下文：fix(driver-memory): persistence opt-in again + move the remaining suites to in-memory SQLite (#4065) #4100（第一次）、fix(spec,service-automation): reconcile the CRUD/screen/map declared config with what the executors read (#4045) #4228（第三次）

[os-zhuang]

根因排查综合分析(2026-07-31)

止损已全部落地(#4309 Test Core 看门狗、#4316 铺至 Dogfood/nightly),这里是对根因的系统排查。结论先行:"每用例新建引擎后句柄未释放"的假说与 objectql 单测的实际情况不符;真正可疑的机制是 vitest fork worker 里的 kernel 信号处理器 + 资源竞争,且本机无法复现停摆 —— 所以 #4341 把取证自动化装进了看门狗,让下一次真实停摆自己交出栈。

排除项(逐一验证过)

假说	验证结果
引擎/driver 句柄不释放拖住 vitest 收尾	两个停摆点用例:metadata-validation-sweep 根本不建真引擎(mock engine);protocol-unknown-query-param 的内联 memory driver 的 connect/disconnect 是纯 no-op。裸 new ObjectQL() 不持有任何事件循环句柄(lifecycle 扫描器只在 plugin 路径启动,且定时器全部 unref 并有 stop();logger 是无线程的 console/stream 写)
测试内 await 挂死	vitest 默认 5s test / 10s hook 超时会先杀 —— 能永久冻结的只有:模块加载期挂起(无超时)、runner/池级死锁、同步阻塞(超时定时器和 JS 同在被冻的事件循环上,永远不会 fire)、GC 死亡螺旋
日志"停在某文件"→ 该文件有问题	归因很弱:vitest 多 worker 并行,最后一行只是"谁恰好在打印"。两次停摆的共性是同一个包(objectql)的 vitest 进程,不是同一个文件

发现项(数字都来自实测)

1. 一次 objectql 套件运行 boot 47 个 kernel,每轮 48 次 SIGTERM 截获。 ObjectKernelConfig.gracefulShutdown 默认 true,plugin.integration / plugin.step2 的每个用例都在 fork worker 里注册 SIGINT/SIGTERM/SIGQUIT 处理器且从不 shutdown。vitest 默认 isolate 模式每跑完一个文件就 SIGTERM 回收 worker —— 于是每次回收都在跑"多个 running kernel 并发异步优雅停机、先完成者 process.exit 截断其余"的竞赛(实测 47 次 graceful shutdown 有 3 次没跑完)。静态分析里每条路径最终都会 exit,25 次隔离循环也没复现 —— 不能断言这就是停摆根因,但它是站得离事故最近的机器,且对测试毫无价值。
2. logLevel: 'silent' 是个从未存在过的配置键(真实形状 logger.level;CI typecheck 不覆盖这些测试文件,死键得以存活)。47 个 kernel 全程 info 级输出,占包日志近一半 —— 正是两次停摆日志顶部的"ObjectQL Engine Instance Created → Driver connected → initialization complete 反复多次"。
3. 本机(充足资源)全量套件多次运行无停摆 —— 冻结需要 CI 的 4 vCPU + turbo 并发 4 包 × 每包 4 fork 的资源竞争环境。5-10% 的单日命中率 × 环境依赖,继续本地撞运气不经济。

#4341 的策略:让下一次停摆自己交出证据

看门狗在杀进程前增加两步取证(已用合成停摆验证):

• /proc 双采样分类:冻结组内每个进程标注 ON-CPU(同步自旋/GC 抖动)或 idle(等待永不 settle 的东西)+ CPU 增量 + RSS;
• SIGUSR2 收栈:CI 测试进程全部以 --report-on-signal 启动;事件循环存活的 node 进程会写出诊断报告(精确 JS 栈 + libuv 句柄清单),摘要进 step 日志、全文上传 artifact;沉默即判词 —— 实测确认 report-on-signal 由事件循环服务,同步阻塞进程必然不出报告,配合 CPU 分类恰好把"await 型 vs 自旋型"切开。

后续(按取证结果走)

• 下一次停摆若是 await 型 → 报告里直接是冻结栈,照栈修;
• 若是 自旋/GC 型 → 结合 RSS 数字,方向是 worker 内存上限/并发度(maxForks、--concurrency)的配比;
• 独立小改进(不阻塞本 issue):ObjectKernel 的信号处理器对第二次信号目前只 warn 不退出,常规约定是"第一次优雅、第二次立即退出",值得单独提一笔。

---

Generated by Claude Code

[os-zhuang]

第四、五次:同一分支上确定性复现,但机制与前三次不同

守卫说明写着"同一文件停摆两次就补记到这里",照做。不过这两次的根因取到了,和已记录的三次不是一回事,所以分开写。

时间	Run / Job	停摆点	被杀的任务
06:46:02Z	run 30610017310 / attempt 1	::endgroup::(cli 套件 628 测试跑完之后)	@objectstack/driver-mongodb#test
07:08:51Z	run 30610017310 / attempt 2	逐字节相同的位置	@objectstack/driver-mongodb#test

同一 commit(7d4313e)、同一停摆点、连续两次 —— 不是随机的。

根因:一个没有上界的网络等待,而 catch 接不住"卡住"

driver-mongodb 的三个套件用 mongodb-memory-server 起真 mongod,它会在模块加载期从 fastdl.mongodb.org 抓一个 ~123 MB 的二进制。三处都是同构的顶层 await:

try {
  sharedMongod = await MongoMemoryServer.create({ instance: { launchTimeout: 60_000 } });
} catch (err) { /* warn + describe.skipIf 跳过 */ }

mongodb-driver.test.ts 的文件头注释把意图写得很清楚:"In sandboxed / offline CI that download can fail; when it does we skip this suite rather than failing the whole package's test run (and, with it, the monorepo Test Core job)."

但 try/catch 只能表达"下载失败",表达不了"下载卡住"。 卡住时 promise 永不 settle,套件既不跑也不跳,就地停住——正是本 issue 描述的现象。取证:两次 attempt 的日志里,这个包一行测试输出都没有,也没有那句 skip 警告,说明 create() 既没 resolve 也没 reject。

另外 instance.launchTimeout: 60_000 不管用:它约束的是二进制已在磁盘上之后 spawn mongod 的阶段,比抓取晚一步。

不是某个 diff 的锅,是缓存未命中就会撞上

同一个任务在 main(run 30608331534,06:05:21Z)是 cache miss, executing 真跑的,日志里有完整的 Downloading MongoDB "8.2.6": 0% → 98.2% → 100% (122.6mb),通过。40 分钟后同样的抓取在 PR runner 上一个字节的进度都没打印就永久挂住。

也就是说:网络侧在变,而等待没有上界。任何改动 @objectstack/spec 的 PR 都会让全仓缓存失效(Cached: 3 cached, 129 total)、让这个任务真跑,于是必然撞上——不能靠重跑绕过去。

已在 #4322 里修掉(354caba)

新增 packages/plugins/driver-mongodb/src/test-mongod.ts:给这个等待加 120s 截止时间,让"卡住"落进套件本来就有的 skip 分支。降级结果和可见性都不变(warn + 跳过套件),只是从"永远不发生"变成"有界发生";二进制可达时(开发机、以及 CI 下载正常时)真实覆盖一点没少。

验证:成功路径本地 160/160 照过;用 mock 一个永不 settle 的 create() 确认到点返回 undefined 而非挂死;helper 不会进 dist(tsup 入口只有 src/index.ts,不引用它,而 mongodb-memory-server 是 devDependency)。

与前三次的关系

前三次停在 metadata-validation-sweep.test.ts / protocol-unknown-query-param.test.ts,本 issue 的怀疑方向是 ObjectQL 引擎用例的句柄泄漏——那条线索本次没有任何新证据,依然开着。这两次只是同一个症状(Test Core 停摆)的另一个来源,修掉之后不影响原方向的排查。

顺带一提,守卫本身这次表现完全符合预期:两次都在 10 分钟静默后给出带包名的明确红,让根因几分钟内就定位了——如果还是老的"挂到 job timeout",这次诊断会贵得多。

---

Generated by Claude Code