164 lines
9.0 KiB
Markdown
164 lines
9.0 KiB
Markdown
|
# 宿主缺陷报告 · 会话诊断日志（丢帧 → 会话静默哑掉）
|
|||
|
|
|
|||
|
|
> **提交对象**：WorkBuddy 宿主（桌面版 / DSH 客户端）研发
|
|||
|
|
> **取证环境**：Windows · `CODEBUDDY_CONFIG_DIR=E:\ProgramData\.workbuddy` · 宿主 bundle `cli/dist/codebuddy-lite-wb.mjs`（Sep 21 20:37）
|
|||
|
|
> **取证日期**：2026-10-01 ｜ **取证会话**：`ee3c2d82`（活跃 8 分钟后达 5.0 MB，最终 7.5 MB）
|
|||
|
|
> **性质**：本报告**只做观测与建议**，⛔ 不涉及修改宿主任何文件（我们未改、也不建议本地改 `app.asar`）。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 一、现象（用户可感知面）
|
|||
|
|
|
|||
|
|
1. 长会话**界面停止刷新**、看起来像"卡死"，**没有任何提示**。
|
|||
|
|
2. 后台协作程序向该会话**投递通知**（`ok:true` 记账成功）—— **实际全部落空，无人知晓（假绿）**。
|
|||
|
|
3. 用户与 AI 双方**都收不到"这个会话已经废了"的信号**，只能靠人去猜。
|
|||
|
|
|
|||
|
|
⇒ 根因：**单会话诊断日志写满上限后宿主拒写（丢行），而"丢行"这一事实没有被任何一方观测到。**
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 二、缺陷 ① 🔴 日志 95% 以上是**零信息心跳行**
|
|||
|
|
|
|||
|
|
**实测读数（会话 `ee3c2d82`，20,925 行 / 5.0 MB 时点）**
|
|||
|
|
|
|||
|
|
| 项 | 值 |
|
|||
|
|
|---|---|
|
|||
|
|
| `event-machine:dispatch` 行 | **20,464 / 20,925 = 97.8%** |
|
|||
|
|
| 单行字节 | **249 B** |
|
|||
|
|
| 真正含内容的行 | **461 行（2.2%）** |
|
|||
|
|
| 若只记"真事件" | 该文件应约 **115 KB**，而不是 **5 MB** |
|
|||
|
|
|
|||
|
|
**证据（连续多行，仅时间戳不同）**
|
|||
|
|
|
|||
|
|
```
|
|||
|
|
2026-10-01T04:35:42.629Z event-machine:dispatch {"instanceId":"ci-1k","input":"tool_call_update","requestId":"01a0f5beea0c7d379ed2c7fd0003baf6","output":{"completeAssistantStream":false,"hasUsage":false,"hasTitle":false,"resourceEffectCount":0}}
|
|||
|
|
2026-10-01T04:35:42.8xxZ event-machine:dispatch {"instanceId":"ci-1k","input":"tool_call_update","requestId":"01a0f5beea0c7d379ed2c7fd0003baf6","output":{"completeAssistantStream":false,"hasUsage":false,"hasTitle":false,"resourceEffectCount":0}}
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
🔴 **同一 `requestId` 下，四个布尔位**恒为 `false`、**`requestId` 也不变** ⇒ 这些行**不携带任何新信息**：
|
|||
|
|
**该行的 JSON 里根本没有 update 的载荷**，只有"某帧到达了"这一个事实。**诊断价值 ≈ 0。**
|
|||
|
|
|
|||
|
|
### 🔴 根因已定位到源码行：`STREAM_CHUNK_UPDATES` 漏了 `tool_call_update`
|
|||
|
|
|
|||
|
|
**位置**：`app.asar`（主进程包，偏移 ≈117,230,304），`main/conversations.js`
|
|||
|
|
|
|||
|
|
```js
|
|||
|
|
if (shouldLogEventMachineDispatch(update?.sessionUpdate, frameContext.replayingHistory,
|
|||
|
|
result.completeAssistantStream === true))
|
|||
|
|
this.init.log("event-machine:dispatch", { … });
|
|||
|
|
|
|||
|
|
/** 默认丢掉历史回放帧和正文流式 chunk；verbose 或 turn 收口帧仍落盘。 */
|
|||
|
|
function shouldLogEventMachineDispatch(sessionUpdate, replayingHistory, completeAssistantStream) {
|
|||
|
|
if (shouldLogContent()) return true; // env WB_CONVERSATION_LOG_CONTENT === "1" ⇒ 全开
|
|||
|
|
if (replayingHistory) return false; // 历史回放帧 ⇒ 丢
|
|||
|
|
if (completeAssistantStream) return true; // turn 收口帧 ⇒ 必写
|
|||
|
|
return !STREAM_CHUNK_UPDATES.has(sessionUpdate ?? "");
|
|||
|
|
}
|
|||
|
|
var STREAM_CHUNK_UPDATES = /* @__PURE__ */ new Set(["agent_message_chunk", "agent_thought_chunk"]);
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
🔴 **读法（关键）**：宿主**已经**有一套"高频流式帧不落盘"的机制 —— 它把
|
|||
|
|
`agent_message_chunk` / `agent_thought_chunk` 两类**主动丢掉**（注释原文：「默认丢掉历史回放帧和正文流式 chunk」）。
|
|||
|
|
**但 `tool_call_update` 不在这个集合里** ⇒ 它**逐帧全部落盘**。
|
|||
|
|
|
|||
|
|
⇒ 而按第一节实测，**`tool_call_update` 恰好就是占比 97.8% 的那一类**（与"正文流式 chunk"完全同性质的高频帧）。
|
|||
|
|
|
|||
|
|
**建议（最小改动 · 一行）**：把 `tool_call_update` 加进该集合（或按 `requestId` 做状态变化去重）：
|
|||
|
|
|
|||
|
|
```js
|
|||
|
|
var STREAM_CHUNK_UPDATES = new Set(["agent_message_chunk", "agent_thought_chunk", "tool_call_update"]);
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
**预期收益（按本报告量化基线推算）**：日志量 **↓ ≈98%**（37 KB/次 → 约 0.7 KB/次）
|
|||
|
|
⇒ 撞 10 MiB 的调用数 **280 次 → 约 14,000 次** ⇒ **"会话写爆日志而静默哑掉"这一问题基本消失**。
|
|||
|
|
|
|||
|
|
⚠️ **本地没有可用的开关**：我们完整检查了 `shouldLogEventMachineDispatch` 及其上游 ——
|
|||
|
|
唯一相关的 env 是 `WB_CONVERSATION_LOG_CONTENT=1`，而它是**反方向**的（`shouldLogContent()` 为真 ⇒ **全部**落盘，只会更糟）。
|
|||
|
|
⇒ **没有"静默档"可用**，所以这一项**只能由宿主侧修**（我们不会去改 `app.asar`：那违反我们的红线，且升级即被覆盖）。
|
|||
|
|
|
|||
|
|
**`input` 分布（同会话）**：`tool_call_update` 23,803 ｜ `session_info_update` 434 ｜ `usage_update` 165 ｜
|
|||
|
|
`tool_call` 164 ｜ `config_option_update` 10 ｜ `current_mode_update` 3。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 三、缺陷 ② 🔴 写满上限后**丢行而非轮转**，且**轮转成功与否不可预期**
|
|||
|
|
|
|||
|
|
**同日同目录（`logs/2026-10-01/sdk/conversations/`）横向对比：**
|
|||
|
|
|
|||
|
|
| 会话 | 当前文件 | 轮转件 | 结果 |
|
|||
|
|
|---|---|---|---|
|
|||
|
|
| `cb60cb60-…` | **10,485,737 B** | **0 个** | 精确撞顶后停止 |
|
|||
|
|
| `5f607d3e-…` | **10,485,717 B** | **0 个** | 同上 |
|
|||
|
|
| `f8a792ab-…` | **10,485,715 B** | **0 个** | 同上 |
|
|||
|
|
| `a202550c-…` | 4,355,503 B | **3 个**（`.log.1/.2/.3`，各 ≈10 MB） | ✅ 正常轮转、会话存活 |
|
|||
|
|
|
|||
|
|
**`a202550c` 的轮转时刻**（文件 mtime）：`.log.3` 00:56:07 ｜ `.log.2` 01:14:59 ｜ `.log.1` 01:39:13。
|
|||
|
|
|
|||
|
|
🔴 **读法**：**轮转能力是存在的**（上限 10,485,760 B ＝ 10 MiB，`a202550c` 一天转 3 次、每转一次文件归零）。
|
|||
|
|
但**另外 3 个会话在完全相同的上限上零轮转** ⇒ 轮转**不是必然路径**，**失败时静默降级为丢行**。
|
|||
|
|
|
|||
|
|
**可疑机理（未证实，需宿主侧确认）**：Windows 上重命名要求目标文件**可被其他持有者释放**
|
|||
|
|
（`FILE_SHARE_DELETE`）。若轮转瞬间该文件仍被另一进程/句柄打开 ⇒ 轮转失败。
|
|||
|
|
**⇒ 我们建议的验证**：在轮转失败分支上**打一条明确日志**（如 `ROTATE_UNAVAILABLE`）——
|
|||
|
|
目前**失败是完全静默的**，这正是我们排查了两天的主要原因。
|
|||
|
|
|
|||
|
|
**建议**：
|
|||
|
|
1. 轮转失败 ⇒ **必须留痕**（等级不低于 WARN），并**退避重试**；
|
|||
|
|
2. 轮转失败 ⇒ **不要把"丢行"当作正常路径**：至少应向 UI 暴露"本会话诊断日志已满、已停止记录"；
|
|||
|
|
3. 🔴 无论轮转成败，**"日志已满/已丢行"应当是一个可被外部观测的状态**（见下节）。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 四、缺陷 ③ 🔴 "日志快满 / 已满"没有任何外部信号
|
|||
|
|
|
|||
|
|
宿主对**自家 daemon 日志**有指纹限流（`scope+level+首参` 同指纹 1 秒最多 5 条），
|
|||
|
|
但**单会话诊断日志**是零去重、零节流、零告警；而**写满后的"拒写"同样无声**。
|
|||
|
|
|
|||
|
|
**后果链**：`日志满 → 拒写 → UI 静默哑掉 → 协作程序投递仍记 ok:true（假绿） → 无人知晓`。
|
|||
|
|
|
|||
|
|
**建议（最小可用）**：
|
|||
|
|
1. 达上限时**写入一条显式记录**（哪怕写到另一个文件），或
|
|||
|
|
2. 对外暴露**可查询的会话健康状态**（如"本会话日志已停止写入"），或
|
|||
|
|
3. 直接**恢复写入**（轮转 + 去重），使"写满"不再是终态。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 五、我们这一侧已经做的（供对照，非宿主职责）
|
|||
|
|
|
|||
|
|
我们无法改宿主，所以在**宿主之外**补了一道**事前叫停**：
|
|||
|
|
`07-scripts/session-log-guard.py` —— 挂在 `PostToolUse` ＋ `UserPromptSubmit`，
|
|||
|
|
**只读**日志字节数（`os.path.getsize`，⛔ 不读内容）⇒ 软 5 MiB / 硬 8 MiB 时向该会话注入一条提醒。
|
|||
|
|
🔴 **它只能"叫停"，⛔ 不能"降速"** —— 上面三条缺陷不修，会话寿命仍然只有约 **280 次工具调用**。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 六、量化基线（可直接用于验收宿主侧的修复效果）
|
|||
|
|
|
|||
|
|
| 指标 | 实测值 | 修复后应变为 |
|
|||
|
|
|---|---|---|
|
|||
|
|
| 每次工具调用日志量 | **144 帧 = 37,502 B** | 大幅下降（去掉心跳行后应 ≈1 KB/次） |
|
|||
|
|
| 调用频率（本机较忙会话） | **≈20 次/分** | 不变 |
|
|||
|
|
| 达 5 MiB 所需时间 | **约 8 分钟** | 显著拉长 |
|
|||
|
|
| 撞 10 MiB 的调用次数 | **≈280 次** | 不再是终态（轮转可靠） |
|
|||
|
|
| 日志中零信息行占比 | **97.8%** | ≈0% |
|
|||
|
|
|
|||
|
|
**换算自证**：`10 MiB ÷ 37 KB ≈ 283 次`，与实测撞顶会话的 264~297 次吻合。
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
## 附：复现命令（只读，可在本机直接跑）
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
D="$CODEBUDDY_CONFIG_DIR/logs/$(date +%F)/sdk/conversations"
|
|||
|
|
# ① 零信息行占比
|
|||
|
|
ls -S "$D" | head -1 | xargs -I{} sh -c 'T=$(wc -l < "'"$D"'/{}"); H=$(grep -c "event-machine:dispatch" "'"$D"'/{}"); echo "$H/$T"'
|
|||
|
|
# ② 每次调用的日志量
|
|||
|
|
f="$D/<会话id>.log"; echo $(( $(stat -c%s "$f") / $(grep -c "\"input\":\"tool_call\"" "$f") ))
|
|||
|
|
# ③ 撞顶未轮转的会话（应为空）
|
|||
|
|
ls -l "$D" | awk '$5==10485737 || $5==10485717 || $5==10485715'
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
---
|
|||
|
|
|
|||
|
|
**报告人**：项目侧（会话 `ee3c2d82`）
|
|||
|
|
**关联材料**：`接续包_日志事前叫停_20261001.md`（§1.5 / §6）｜`.workbuddy/memory/2026-10-01.md` §四十
|