108 lines
14 KiB
Markdown
108 lines
14 KiB
Markdown
# ccweb 频繁掉线诊断发现
|
||
|
||
## 当前状态（2026-07-11 22:29 +08:00）
|
||
|
||
- `ccweb` 当前为 `online`，PID 1606383，单实例 fork 模式。
|
||
- PM2 累计重启次数为 60，说明不是一次性偶发。
|
||
- 当前进程 `pm_uptime=1783779949754`，约在 22:25:49 启动，距检查仅约 3 分半钟，符合用户所述“刚才掉线”。
|
||
- 当前进程内存约 76 MiB、CPU 3.1%；主机可用内存约 4.8 GiB、磁盘使用率 32%，检查时不存在资源耗尽。
|
||
- 主机已持续运行 119 天，说明刚才并非整机重启。
|
||
|
||
## 日志时间线
|
||
|
||
- 2026-07-11 22:25:49，PM2 明确记录 `Stopping app:ccweb`，随后进程以 `code [0] via signal [SIGINT]` 正常退出，并在同一秒重新启动、恢复 online。
|
||
- 同日 11:21:10、12:25:37 也出现完全相同的“主动停止 → SIGINT/0 → 立即启动”序列。
|
||
- 近期大量记录都是该形态；这更像 `pm2 restart/reload/stop` 一类外部管理动作，不像应用崩溃或被系统 OOM Kill。
|
||
- `ccweb-out.log` 只看到重复的 `CC-Web server listening on 0.0.0.0:8002`，对应多次启动，没有本次异常堆栈。
|
||
- `ccweb-error.log` 最后修改时间是 2026-06-15；其中确有一次 V8 堆达到约 2 GiB 后 OOM，但它不是 7 月 11 日这次掉线的直接原因。
|
||
|
||
## 自动策略与系统反证
|
||
|
||
- PM2 配置：`watch=false`、`cron_restart=null`、`max_memory_restart=null`；因此本次不是文件监听、定时器或 PM2 内存阈值触发。
|
||
- 同一时间窗口的内核日志没有 OOM、Killed process 或段错误记录。
|
||
- 当前 8002 端口由 ccweb 进程正常监听，本地 HTTP 检查返回 200，耗时约 2.6 ms。
|
||
- 项目源码、用户 crontab、系统 cron/timer 未发现自动执行 `pm2 restart/reload ccweb` 的配置；交互式 shell 历史也没有可归因的匹配记录。
|
||
- PM2 日志只记录了动作结果，不记录发起 restart 的客户端 PID/会话，因此现有日志能确认“外部管理动作”，但无法可靠归因到具体用户或具体对话。
|
||
- 检查时除当前对话外还有一个 English 项目的 codexapp 对话处于 running；本轮没有执行服务重启。
|
||
|
||
## 频率与可归因证据
|
||
|
||
- 2026-07-01 至 2026-07-11 共发生 19 次 `Stopping app:ccweb`；逐次退出全部为 `code=0, signal=SIGINT`，没有一次属于异常退出。
|
||
- 分布：7 月 1 日 3 次、2 日 6 次、3 日 1 次、5 日 4 次、7 日 2 次、11 日 3 次。
|
||
- Codex 本地会话记录能确认至少 7 月 7 日的两次重启确实由会话内显式执行 `pm2 restart ccweb --update-env` 触发，说明“开发/代理完成改动后手动重启”是真实存在的来源。
|
||
- 截至当前证据，尚未定位 7 月 11 日 22:25:49 这一次的具体发起会话。
|
||
|
||
## 初步结论（已被用户澄清推翻）
|
||
|
||
以下判断仅保留为调查过程记录，不是最终结论：
|
||
|
||
- 本次连接失败的直接原因是 ccweb 在 22:25:49 被外部 PM2 管理动作主动重启，单实例在停止/启动窗口内中断现有连接。
|
||
- “最近频繁掉线”的主因也是频繁主动重启，而不是当前应用持续崩溃；7 月以来已发生 19 次同类主动重启。
|
||
- 现有 PM2 日志缺少调用者审计，因此无法仅靠当前日志追溯 22:25 这一次是谁发起。
|
||
- 独立风险：6 月 15 日曾发生 V8 堆 OOM，且 PM2 主日志已约 157 MiB；两者值得后续单独治理，但与本次中断无直接因果关系。
|
||
|
||
## 用户澄清后的因果修正
|
||
|
||
- 用户确认：网页先打不开，随后由用户人工执行 PM2 重启恢复。
|
||
- 因此 22:25:49 的 `Stopping app` / `SIGINT` 只能证明恢复动作，不能解释故障起因。
|
||
- 现阶段真正待查的是：旧 PID 1163252 在退出前为何无法响应 HTTP；由于重启前没有请求延迟、事件循环延迟、堆内存和活跃句柄快照，历史日志证据存在明显缺口。
|
||
- `home-cc-web` 代码索引状态为 ready（3072 节点、7430 条边），可继续按函数和调用链定位阻塞候选。
|
||
|
||
## 初步代码风险面
|
||
|
||
- 主服务是单 Node.js 事件循环；`server.js` 在请求和 WebSocket 热路径中存在大量同步文件系统调用。
|
||
- `plog` 每次记录都同步执行 `statSync`、可能的 rotate/unlink/rename，再 `appendFileSync`；若日志路径所在文件系统短时阻塞，会拖住整个 HTTP 服务。
|
||
- `sendSessionList` 同步扫描会话目录并读取/解析会话元数据；会话数量或单文件体积增大时，可能形成明显事件循环停顿。
|
||
- `handleMessage` 同步读取并 base64 编码附件、同步创建输入/输出文件；大附件会放大停顿和堆占用。
|
||
- `wsSend` 直接在主线程 `JSON.stringify(data)`；历史 6 月 15 日 OOM 栈也落在 V8 `JsonStringify`，说明超大对象序列化是已发生过的真实风险，而非纯理论。
|
||
- 这些是“具备卡死能力”的候选路径；尚不能仅凭静态代码断定 22:25 具体命中了哪一条。
|
||
- `plog` 有 38 个调用方，属于广泛热路径；每次调用都同步触盘。
|
||
- `wsSend` 有 48 个调用方且统一同步序列化；只要某次 payload 意外携带超大对象，整个服务会在 `JSON.stringify` 期间停止处理新 HTTP 请求。
|
||
- `sendSessionList` 有 15 个调用方；每次都同步遍历所有会话文件，并逐文件 `statSync`，小于阈值时还会整文件 `readFileSync + JSON.parse + normalizeSession`。
|
||
- 因此“网页整体打不开”更符合主事件循环被长任务/同步 I/O 占住，而不是单个 WebSocket 会话故障；但仍需用运行态日志与文件规模交叉验证。
|
||
- 当前代码已有单会话/消息截断上限：会话持久化默认 10 MiB、加载上限 32 MiB、列表元数据整文件解析阈值 512 KiB，tool result 持久化默认截到 32 KiB。它们能降低风险，但无法消除“很多会话逐个同步读取”或某个发送前对象尚未裁剪的阻塞。
|
||
- 在常见目录范围内暂未找到 `logs/process.log`；需要继续确认 `APP_DIR` 实际值。若结构化日志实际未落盘，正好解释了为什么本次只剩 PM2 生命周期日志而没有故障前业务事件。
|
||
- 已确认源码运行目录就是 `/home/cc-web`，结构化日志实际位于 `logs/process.log`；此前检索未命中属于检索结果异常，现已纠正。
|
||
- 当前 `sessions/` 有 112 个 JSON 会话文件，总体积约 64 MiB；最大单文件约 4.09 MiB，多份文件超过 1 MiB。
|
||
- 用与 `sendSessionList` 等价的同步读取策略做只读基准，一次扫描实测约 5.99 秒（user 2.07 秒、sys 1.35 秒）。在这段时间内单线程 Node 无法响应 8002 上的任何 HTTP 请求。
|
||
- `sendSessionList` 又会被 turn complete、消息处理、终止、导入等至少 15 类路径触发；若短时间连续触发广播，会形成数秒级阻塞叠加，足以解释“网页完全打不开但 PM2 进程仍在线”。这是目前证据最强的根因候选。
|
||
- `process.old.log` 在 22:24:01 完成约 2 MiB 轮转，距离 22:25:49 人工重启约 1 分 48 秒；需要检查轮转前后事件是否出现会话列表广播/完成风暴。
|
||
- 22:15–22:26 的结构化日志共有 1089 条 `codex_app_notification_unrouted`；其中 991 条是 `item/agentMessage/delta`，另有 32 条 item completed、30 条 item started。
|
||
- 这些通知集中指向同一个找不到路由的 app-server thread/turn；频率约 1–2 条/秒，部分时刻同一毫秒多条。
|
||
- `handleCodexAppNotification` 对每一条未路由通知都会同步调用 `plog` 后返回；因此这 1089 条通知直接转化为 1089 次主线程 `statSync + appendFileSync`，并导致故障前日志轮转。
|
||
- 当前最可能的故障模型：孤儿/失路由 app-server 流式通知持续灌入，同步日志 I/O 占用事件循环；同时任何 session list 广播还会触发一次全量同步扫描。两者叠加时，HTTP 请求长时间排队，网页表现为不可达。
|
||
- 仍需确认该 orphan thread 来自哪个会话，并复测扫描耗时以排除首次冷缓存/Node 启动成本夸大。
|
||
- 已确认 thread `019f5186…` 对应当时正在运行的 English 会话 `a21170ff…`，并有对应 22:13 启动的 Codex rollout；它不是无主外部进程，而是 ccweb 对一个真实活跃会话丢失了 runtime 路由。
|
||
- 热缓存下连续 5 次等价会话扫描为 188–243 ms，每次读取约 22 MiB；因此先前约 5.99 秒结果包含 Node 冷启动/系统抖动，不能把单次会话扫描独立定为根因。
|
||
- 200 ms 级同步扫描仍会造成可感知卡顿，连续触发仍可叠加，但本次更直接的异常是“活跃 thread 持续产出通知，ccweb 却无法路由”。
|
||
- 修正后的高概率链路：活跃会话 runtime 路由丢失 → 大量流式通知被判为 unrouted → 每条同步写日志并轮转；同时 UI 收不到该会话事件。是否足以让静态 HTTP 也超时，仍需结合路由查找复杂度和当时其它事件判断。
|
||
- 对应 thread 的未路由状态不是运行中途才丢失：首次出现在 22:13:44（thread 启动/MCP startup 阶段），一直持续到 22:25:49 人工重启，共 1054 条，集中在同一个 turn。
|
||
- `findCodexAppRouteByRuntime` 本身只做 route 查找、一次未路由 turn 认领尝试和 child map 查询，不是高复杂度扫描；真正异常是 thread 从创建开始就没有被成功注册/认领到 `activeCodexAppTurns`。
|
||
- 因而更准确的描述是“新活跃 thread 路由建立失败”，而不是“已建立路由后来丢失”。重启后的 recovery 能重新挂接该会话，解释了为什么重启会恢复。
|
||
- 未路由认领逻辑要求同时满足：方法在 adoptable 白名单、通知含 threadId+turnId、持久化会话文件已经能按 threadId 命中；任一条件不满足都会继续丢弃并写日志。
|
||
- 一旦认领成功，代码会写入 `activeCodexAppTurns`、持久化状态并记录 `codex_app_unrouted_turn_adopted`；故障窗口完全没有该事件，说明认领条件始终未满足。
|
||
- 当前会话文件只在父级 `collabAgentToolCall` 输入中引用该 child thread，并不能通过 `getRuntimeSessionId` 匹配；后续确认这是原生子代理映射注册缺口，不是父会话 threadId 持久化竞态。
|
||
- 常规 route 查找会线性遍历 `activeCodexAppTurns` 两次（threadId、turnId），但活跃会话数量很小，不足以解释整体失联。
|
||
- 已定位决定性放大器：`isCodexAppAdoptableRuntimeMethod` 明确把 `item/agentMessage/delta`、item started/completed 等高频通知列为可认领方法。
|
||
- 每条可认领但未路由通知都会进入 `findCodexAppSessionByThreadId`；该函数同步 `readdirSync` 全部会话文件，并逐个调用 `loadSession(sessionId)`，直到找到 thread 或扫描到底。
|
||
- 故障 thread 当时无法命中，因此 991 条 delta 基本都会扫描全部 112 个会话、约 64 MiB 数据。数量级约为 991 × 64 MiB ≈ 63 GiB 的同步读取/解析压力，集中在约 11 分钟内并占用 HTTP 主线程。
|
||
- 这条链路可以同时解释三个现象：PM2 仍显示 online、结构化日志仍断续增长、网页却无法打开——进程没死，只是事件循环被同步扫描持续压满。
|
||
- 目前只差核对 `loadSession` 的精确读取策略并做一次“thread miss”只读基准，即可给出高置信结论。
|
||
- `loadSession` 确认通过 `safeReadSessionJson` 执行 `statSync + readFileSync + JSON.parse`，默认允许读取到 32 MiB；当前所有 112 个会话文件都低于该上限，因此 miss 时会整批完整读取和解析。
|
||
- “thread miss”全量读取/JSON 解析的 5 次热缓存基准为 604–840 ms，每次实际读取 60.8 MiB；这仍未包含生产代码的 `normalizeSession` 成本，因此是保守下界。
|
||
- 故障 thread 的 1054 条未路由通知覆盖约 725 秒，平均间隔约 0.69 秒，几乎等于一次全量扫描耗时。于是主线程形成连续循环：通知 → 60.8 MiB 同步扫描 → miss → 同步日志 → 下一通知。
|
||
- 按 1054 次估算，累计同步读取量约 62.6 GiB；按实测下界累计阻塞时间约 637–885 秒，与 725 秒故障窗口同量级。这足以高置信解释整个 HTTP 服务无响应。
|
||
- 根因已从“候选”提升为高置信：未路由高频通知触发无缓存、无退避的全量同步会话查找，压满 Node 事件循环。
|
||
- 故障 thread 的 rollout 元数据确认它是父 thread `019f514d…` 在 English 会话中通过 `spawn_agent` 启动的 depth=1 原生子代理，任务名为 `inspect_drill_tests`。
|
||
- 子 thread ID 在父 ccweb 会话 JSON 中只出现在 `collabAgentToolCall` 的 `agentThreadId` 输入路径，不是父会话的 runtime session ID；因此 `findCodexAppSessionByThreadId` 扫遍所有父会话也必然 miss。
|
||
- 子代理通知本应通过 `ccwebMcpChildThreads` 路由。该映射依赖父级 `collabAgentToolCall` 通知中的 `receiverThreadIds`；同步函数在数组为空时直接返回。spawn 初期若还没有 receiverThreadIds，而后续状态未及时补发/处理，子 thread 会永久没有映射。
|
||
- 最终根因链路：原生子代理 spawn 后 child thread 映射未及时建立 → child 高频 delta 无路由 → 每条 delta 错误进入父会话全量同步查找 → 60.8 MiB/次、约 0.6–0.84 秒/次 → Node 主事件循环被持续占满 → 网页打不开；人工重启通过 recovery 重建状态后恢复。
|
||
|
||
## 最终结论
|
||
|
||
- 本次并非进程崩溃或系统 OOM，而是 Node 主事件循环被同步工作持续占满；用户的 PM2 重启是恢复动作。
|
||
- 触发源是 English 会话通过 `spawn_agent` 创建的子代理 `inspect_drill_tests`。child thread 映射未建立，1054 条子代理通知从 22:13:44 起持续走未路由回退。
|
||
- 回退逻辑对每条高频 delta 同步扫描 112 个会话文件并完整读取/解析 60.8 MiB；单次保守基准 604–840 ms，累计约 62.6 GiB、637–885 秒阻塞，和 725 秒故障窗口吻合。
|
||
- 重启后 adoptable 未路由通知已归零；剩余 98 条仅为 rate-limit/status 类非认领通知，不再触发全量会话扫描。22:45 检查服务 online，HTTP 200，响应约 2.5 ms。
|
||
- 修复应同时覆盖三层：spawn 时可靠登记 child thread 路由；未路由查找改为内存索引/负缓存并禁止每 delta 全盘同步扫描；未路由日志做聚合限频和异步写入。
|