138 lines
8.5 KiB
Markdown
138 lines
8.5 KiB
Markdown
# WorkBuddy daemon 异常终止导致会话中断 · 取证报告
|
||
|
||
> 取证时间：2026-10-09 06:2x–06:4x（本地 UTC+8）
|
||
> 环境：win32 x64 ／ WorkBuddy 5.7.6 ／ Electron 37.10.3 ／ Node 22.21.1 ／ V8 13.8.258.32-electron.0
|
||
> 现象：后台自动化会话运行中途被判 `terminated`，未正常收尾，并遗留域锁未被释放
|
||
> 本报告全部结论取自日志与崩溃报告原文，可复现；**未坐实的推断已单独标注**
|
||
|
||
---
|
||
|
||
## 一、结论（三句）
|
||
|
||
1、daemon 进程内存在一分钟内涨近三倍（160MB → 444MB → 957MB，rss 1162MB）后被**强制终止**，日志里没有任何优雅退出或崩溃堆栈。
|
||
|
||
2、父进程随即拉起新一代 daemon（`ppid` 可证）；旧 daemon 托管的 `cli` 子进程随之以退出码 1 结束，正在其上运行的会话被判 `terminated`。
|
||
|
||
3、本应拦截这一关的**内存守护（guardian）全程失效** —— 它靠 `wmic` 采集进程指标，而本机 `wmic` 不存在，每 10 秒失败一次。
|
||
|
||
---
|
||
|
||
## 二、时间线（本地时间，取自 `daemon.log` 原文）
|
||
|
||
- **16:50:33**（＝本地次日 00:50:33）—— `[DaemonMemWatch] pid=53940 heapUsed=160MB heapTotal=202MB rss=340MB`。
|
||
- **16:51:33** —— `pid=53940 heapUsed=444MB heapTotal=509MB rss=618MB`。
|
||
- **16:52:33** —— `pid=53940 heapUsed=957MB heapTotal=1030MB rss=1162MB`。**三分钟三倍，斜率外推下一分钟破 2GB。**
|
||
- **16:53:22** —— 旧 daemon 最后一条正常业务日志（`[skills-fetch] response`）。
|
||
- **16:53:38.273** —— 新进程首个标记：`[CodeCache] enabled {"processName":"daemon"}`。
|
||
- **16:53:38.288** —— `[DaemonLog] session started {"pid":73936,"ppid":72748,...}`。
|
||
- **16:53:39.584** —— 会话 `a257d30f` 被状态同步器置为 `terminated`。
|
||
- **16:53:54.262** —— 新 daemon 记下第一条：`ChildProcessCrash: Child process gone (cli): reason=exit:1, exitCode=1`。
|
||
|
||
**关键间距**：`16:53:22` 到 `16:53:38` 之间有 **16 秒空白** —— 旧进程没有留下任何 shutdown／exit／error 记录，属被直接终止。
|
||
|
||
---
|
||
|
||
## 二之二、内存暴涨的形态（关键：两轮暴涨，一轮被救回、一轮没赶上）
|
||
|
||
`[DaemonMemWatch]` 每分钟一读，逐条摘录：
|
||
|
||
- 第一轮：`16:20 heap=309MB` → `16:21 526MB` → `16:22 551MB` → `16:23 592MB` → `16:24 **609MB**`（峰）→ **`16:25 掉回 132MB`**。
|
||
- 平稳期：`16:26–16:41` 稳定在 **132–135MB**，17 分钟几乎不动。
|
||
- 第二轮：`16:42 149MB` → `16:44 185MB` → `16:48 143MB` → `16:50 160MB` → `16:51 **444MB**` → `16:52 **957MB**` → `16:53:38` 被杀。
|
||
|
||
**要点一：不是缓慢泄漏。** 16:25 从 609MB 掉回 132MB，说明 V8 能回收 —— 它是**突发分配**，只是第二次没来得及回收进程就被终止了。
|
||
|
||
**要点二：与「会话活跃」严格同步。** 事件计数（`Conversation event push summary` 的 `received`）在 `16:45／16:46／16:47` 三条**完全相同**（1622136），即该时段零事件，同期内存 175–185MB 平稳；`16:48` 起事件转为递增（+1117 → +3323 → +9097 → +16869 → +18727 每分钟），内存同步起飞。`16:48:08` 正是一个后台会话的启动时刻。
|
||
|
||
**要点三：不是队列积压。** `pendingEvents: 0`、`maxPendingEvents: 112` 全程不变，事件并没有堆在推送队列里。
|
||
|
||
**换算比例**：16:51 段约 **31KB／事件**、16:52 段约 **27KB／事件** —— 两段一致，但**这是相关关系，不是已证因果**（见第六节）。
|
||
|
||
**要点四（后续对照，2026-10-09 06:32–06:43 补测，两轮）**：另起一个后台会话（跑闸门、复制工具、改文件）做对照，两次结果**都削弱了"某个特定动作触发暴涨"的假设**：
|
||
|
||
- 06:32–06:38：事件速率与暴涨组同量级（`+20758`／`+11422` 每分钟），内存只在 **116–202MB 锯齿**。
|
||
- 06:38–06:43（20 秒一条采样）：`heap` 走 **191 → 193 → 260 → 196 → 205MB**；期间该会话**同样写了大文件**（`mcn-workbench.html` 133459 → 135041 B，另有 146341 B 的 dom dump），内存峰值仍只到 **260MB**，且 `06:40:58` **被 GC 收回 64MB**。
|
||
|
||
⇒ **事件速率不是充分因，连"写大文件"也不是**。三次观测的峰值分别是 **609MB（收回）／957MB（未收回）／260MB（收回）** —— 差异像**随机振幅**，不是某个动作的必然结果。据此把问题重新定性为：**daemon 内存在高振幅锯齿，能否回收取决于 GC 时机；957MB 那次是"没赶上"的尾部事件**，而不是"某个操作必然撑爆它"。验证方法见 `daemon-内存观察-复现单.md`。
|
||
|
||
---
|
||
|
||
## 三、证据与复现命令
|
||
|
||
### 1、内存暴涨
|
||
|
||
```
|
||
grep "DaemonMemWatch" <logs>/daemon.log | tail -30
|
||
```
|
||
|
||
### 2、守护失效（每 10 秒一次）
|
||
|
||
```
|
||
grep "guardian:sample" <logs>/daemon.log | tail -20
|
||
```
|
||
|
||
原文：`[guardian:sample] batch pidusage failed: Error: spawn wmic ENOENT`
|
||
频次：旧进程最后 46 行日志里出现 **11 次**，即持续失败、无一成功。
|
||
|
||
### 3、进程换代与父子关系
|
||
|
||
```
|
||
grep "DaemonLog] session started" <logs>/daemon.log
|
||
```
|
||
|
||
原文：`[DaemonLog] session started {"pid":73936,"ppid":72748,"nodeVersion":"v22.21.1","electron":...}`
|
||
|
||
### 4、崩溃报告（换代是常态的直接证据）
|
||
|
||
目录：`<logs>/Crash-Log/`
|
||
命名规则：`crash-report-<进程名>-<pid>-<launchedAt 本地时刻>.json`
|
||
（时间戳取报告内 `launchedAt` 字段，**不是崩溃时刻**）
|
||
|
||
现有 **14 份**，daemon 的跨 **09-28 ／ 10-01×2 ／ 10-02×2 ／ 10-06×2 ／ 10-08 ／ 10-09** —— 至少 6 个日子发生过换代。另有 `crash-report-main-*` 5 份、`crash-report-sidecar-*` 1 份。
|
||
|
||
每份报告体例一致（示例为 10-09 那次），条目形如：
|
||
|
||
```
|
||
{
|
||
"timestamp": "2026-10-09T00:53:54.262+08:00",
|
||
"type": "child_process_crash",
|
||
"errorMessage": "Child process gone (cli): reason=exit:1, exitCode=1",
|
||
"childProcess": { "name": "cli", "exitCode": 1, "disposition": "unexpected_crash" }
|
||
}
|
||
```
|
||
|
||
`.processed-crashes.json` 里的数字是**已处理条数**（53940=12、73936=4），**不是**崩溃次数。
|
||
|
||
### 5、连带关系
|
||
|
||
`53940` 名下 12 条崩溃条目，时间点全部落在会话起止附近（其中 `23:32:00` 那条，正好等于一次执行会话排期的触发时刻）。
|
||
|
||
---
|
||
|
||
## 四、影响面
|
||
|
||
- **任何正在跑的会话都可能被换代打断**，形态是"跑着跑着变 terminated"，且来不及做收尾动作。
|
||
- 本次实际损失：一个四步目标的第 4 步执行会话在做完界面产物后 1 秒被终止，产物虽已落盘，但**验证与上报全部丢失**；更严重的是它持有的**域锁无人释放**，形成孤儿锁，导致后续 10 棒检查会话连续空转（01:29–05:59）。
|
||
- 崩溃报告中 `cli exit:1` 是**结果不是原因** —— 它是随 daemon 一起被带走的，排查时不要被这一行带偏。
|
||
|
||
---
|
||
|
||
## 五、建议
|
||
|
||
1、**修 guardian 的采样方式** —— 把 `wmic` 依赖换掉（Windows 11 已弃用／移除 wmic，改用 PowerShell CIM 或 Node 原生接口）。这是本次事件中唯一明确、可修、且与现象直接相关的缺陷。
|
||
|
||
2、**daemon 被杀前留痕** —— 现在从"最后一条业务日志"到"新进程启动"之间是 16 秒真空，外部无法判断是 OOM、被父进程杀、还是 native crash，建议补一条落盘的退出原因。
|
||
|
||
3、**daemon 内存上限与自愈** —— 内存从 76MB 涨到 1GB+ 无任何预警；建议在阈值处先落日志、再重启，并且**重启前给在跑的会话留收尾窗口**（或至少在重启后主动标记受影响的会话，而不是让它们静默停在 terminated）。
|
||
|
||
---
|
||
|
||
## 六、未坐实项（如实标注）
|
||
|
||
**「到底是谁占了那些内存」我没有坐实。**
|
||
|
||
- 会话自己的 SDK 日志（`logs/<日期>/sdk/conversations/<sessionId>.log`）**只有 499 行、约 199 条事件**（覆盖该会话全部 331 秒），**解释不了 4.9 万条**的 `received` 增量 ⇒ 说明存在一条**不进会话 SDK 日志的事件通道**，我没能定位它的落点。
|
||
- 因此第二节末尾那个「27–31KB／事件」只能算**相关**，不能算因果 —— 内存里完全可能有其它占用与事件速率同步起伏。
|
||
- 要定这个因，唯一可靠的办法是**复现 ＋ 抓 V8 堆快照**（heap snapshot），看增长集中在哪个对象类型。本报告不对此下结论。
|
||
- 另注：`toolThrottleFramesByTool` 里 `Bash` 32206 ／ `Write` 30346 ／ `Edit` 13162 是个**有界指标**（反映被节流的工具帧数），不要把它当内存占用读。
|