Compare commits
1 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
 claude_dev
|
da8269f16b |
@@ -0,0 +1,124 @@
|
||||
# 事故调查报告：daemon ticker「停摆 8 小时」指控（2026-09-02/03）
|
||||
|
||||
**调查人**：姜维（jiangwei-infra subagent，只读调查）
|
||||
**结论**：⚠️ **不存在 daemon ticker 停摆。所谓「8 小时零 tick」是 SQLite UTC 时间戳被误读为本地时间（GMT+8）造成的误报，时差恰好 8 小时。** 调查期间 ticker 全程健康运行，每 30 秒一轮 tick，从未中断。
|
||||
|
||||
---
|
||||
|
||||
## ① 时间线（已全部换算为本地时间 Asia/Shanghai；DB 原始时间戳为 UTC）
|
||||
|
||||
| 本地时间 | 事件 | 证据来源 |
|
||||
|---|---|---|
|
||||
| 09-02 05:02:31–05:03:55 | simayi→pangtong 两封邮件正常 dispatch→spawn→completed→marked done，闭环完成 | daemon.err.log L3525-3539 |
|
||||
| 09-02 05:14:35 | `Zombie detected: _mail (stale=20)`（凌晨无邮件活动，连续 20 tick 无非 tick 事件的**常规告警**，09-01 05:21:49 同样出现过） | daemon.err.log L3540 |
|
||||
| 09-02 05:14 → 09-03 05:01 | 应用日志（daemon.err.log）约 24h 无任何输出 —— 因期间无 INFO 级事件（无 dispatch/spawn/error；tick 完成日志为 debug 级不输出）。**期间 ticker 正常运行**：DB 中每 30s 一条 daemon_tick，「疑似停摆窗口」内 `_mail` 有 915 条、`sanguo_moziplus_v2` 有 915 条规律 tick | daemon.err.log；`data/_mail/blackboard.db`、`data/sanguo_moziplus_v2/blackboard.db` events 表 |
|
||||
| 09-03 05:01:51–52 | 调查发起方逐项目扫描 `GET /api/projects/*/tasks?status=failed`（22 个项目） | daemon.out.log |
|
||||
| 09-03 05:03:00 | 调查发起方 `POST /api/mail` 创建 `mail-1788382980110`（标题：「黑板 daemon 疑似停摆 8h（09-02 21:01 起零 tick），请调查根因」） | daemon.out.log；`_mail` DB：created_at=**2026-09-02 21:03:00 UTC** = 本地 09-03 05:03:00 ✅ |
|
||||
| 09-03 05:03:21 | 下一个 30s tick（tick 18292）**正常调度**该邮件：`Phase 2 session check for jiangwei-infra` → `Spawned agent jiangwei-infra (pid=36795)` → `Dispatched mail-1788382980110` → 邮件事件使 _mail 有真实变更 → `Zombie resolved: _mail`。**这是 ticker 主循环的常规调度路径，不是「API 旁路」** | daemon.err.log；`_mail` DB 同 tick（18292）daemon_tick |
|
||||
| 09-03 05:04:25–05:04:56 | 第 18295 轮 tick 遍历 22 个正式项目（31s/轮）——被误读为「最后 tick 21:04:25/21:04:56」 | 各项目 DB daemon_tick（UTC 21:04:25/21:04:56） |
|
||||
| 09-03 05:05–05:13（调查进行中） | ticker 持续 tick：18296→18310，`GET /api/daemon/status` 返回 `{"ticker_running":true,"tick_count":18310}`；调查查询 SQLite 时多次遇到 `database is locked`（daemon 正在写入） | API 实测；`_mail` DB daemon_tick 至 UTC 21:12:03（本地 05:12:03）仍在推进 |
|
||||
| 09-03 05:07:39 | 上述邮件 agent completed 但未回信 → request 类型 verify(no_reply) → 标 failed → 自动创建「[投递失败]」通知邮件（**行为问题，非 daemon 故障**，见 ④-6） | `_mail` DB：agent_completed/status_change/task_created @UTC 21:07:39 |
|
||||
|
||||
## ② 证据清单
|
||||
|
||||
1. **`src/blackboard/db.py:82`**：`created_at TEXT NOT NULL DEFAULT (datetime('now'))` —— SQLite `datetime('now')` 返回 **UTC**。所有黑板 DB 时间戳均为 UTC。
|
||||
2. **`src/main.py` logging 配置**（`_setup_logging`，`datefmt="%Y-%m-%d %H:%M:%S"`）—— Python logging 使用**本地时间**（Asia/Shanghai）。两套时间系统相差 8 小时。
|
||||
3. **tick 连续性**（决定性反证）：`sqlite3 data/_mail/blackboard.db`：UTC 13:00–21:00（=本地 09-02 21:00–09-03 05:00，即所谓停摆窗口）daemon_tick **915 条**，min=13:00:03、max=20:59:56，间隔 30s 规律分布；`sanguo_moziplus_v2` 项目同窗口同样 **915 条**。UTC 12:30–14:00 抽样逐条核验，无任何空洞。
|
||||
4. **ticker 当前状态**：`GET /api/daemon/status` → `ticker_running=true, tick_count=18310`（调查时刻），与 DB 最新 daemon_tick（tick 18308 @UTC 21:12:03）吻合。
|
||||
5. **05:03:21 调度日志与 DB 同 tick 对齐**：`_mail` DB tick 18292 的 daemon_tick 落在 UTC 21:03:21，与 `Dispatched mail-1788382980110`、`Zombie resolved: _mail` 同秒——三者都出自 `_tick_project("_mail")` 单次执行（dispatch→写 tick→health check），证明是主循环常规路径。
|
||||
6. **mail-1788382980110 创建时间**：`_mail` DB `task_created @UTC 2026-09-02 21:03:00` = 本地 09-03 05:03:00，与 daemon.out.log `POST /api/mail` 访问日志完全一致。
|
||||
7. **macOS sample（/tmp/sanguo_daemon_sample.txt）**：
|
||||
- 主线程：uvloop `uv_run/uv__io_poll(kevent)` + `uv__run_idle` 正常轮转；
|
||||
- 主线程 2 秒采样中 91/1571 samples（≈6%）在执行一个 Python 回调，其中 77 samples 深入 `sqlite3_step → sqlite3VdbeExec → sqlite3BtreeCount → pread`（对大表做 `COUNT(*)` 全表扫描，见 ④-5）；
|
||||
- Thread_4920533：卡在 `PyThread_acquire_lock_timed → _pthread_cond_wait`。**源码 grep 全仓无任何 `threading.Thread`/`run_in_executor`/`queue.Queue` 用法**，应用层不创建工作线程；结合 FastAPI/Starlette 架构，这是 **anyio 的空闲 worker 线程在等待新任务**（sync 端点线程池），属正常空闲态，与停摆无关。
|
||||
8. **代码一致性**：`diff -rq` 开发目录与安装目录 `src/` **零差异**（运行版本 = 开发版本）。
|
||||
9. **任务状态**：全部 25 个 DB 中无任何 pending/claimed/working/blocked 卡住任务。
|
||||
10. **git log**：daemon 相关最近提交（35959e1 §22 P1+P2、dc1d444 §22 P0 等）均早于事发且无异常回滚。
|
||||
|
||||
## ③ 根因分析
|
||||
|
||||
### 直接根因：时区误读（UTC vs 本地 GMT+8，差值恰为 8 小时）
|
||||
|
||||
误判链条还原：
|
||||
|
||||
1. 调查发起方查询各项目 DB `SELECT MAX(created_at) FROM events WHERE event_type='daemon_tick'`，得到 `2026-09-02 21:04:56`（**UTC**，即本地 09-03 05:04:56 —— 查询前 2~3 分钟，ticker 刚写的）。
|
||||
2. 该值被当作**本地时间**解读 →「21:04 起零 tick」→ 与当下 05:07 相差约 8 小时 →「停摆 8 小时」。
|
||||
3. 「遍历第一个项目 sanguo_moziplus_v2 = 21:04:25、最后一个 = 21:04:56」实为**同一轮正常 tick**（22 项目 31s，与 30s tick_interval + 1s 工作量完全一致）。
|
||||
4. 「此后仍无新 daemon_tick 写入」不成立：tick 18296–18310 在 UTC 21:05:27–21:12:03 持续写入（发起方可能再次被 UTC 混淆，或在少数项目上抽查时机不巧遇到 `database is locked`）。
|
||||
5. 交叉印证全部自洽：
|
||||
- 「进程未崩溃、API 正常、主线程 uvloop 正常」—— 因为服务本就健康；
|
||||
- 「连 `Tick error` 都没触发」—— 因为根本没有错误发生；
|
||||
- 「05:03:21 恢复活动」—— 不是恢复，是 30s tick 命中了刚创建的邮件任务；
|
||||
- 「Zombie _mail 每天凌晨告警、次日 dispatch 时 resolved」—— health.py 逻辑（连续 20 tick=10 分钟无非 tick 事件即告警），凌晨无邮件 → 常规告警；09-02 05:14 告警后因 _mail 长时间无真实事件，直到 09-03 05:03 新邮件才触发 resolved。与停摆无因果。
|
||||
|
||||
### 证据文件:行号
|
||||
|
||||
| 事实 | 位置 |
|
||||
|---|---|
|
||||
| DB 时间戳 = UTC | `src/blackboard/db.py:82`（`DEFAULT (datetime('now'))`） |
|
||||
| 日志时间戳 = 本地 | `src/main.py` `_setup_logging()` Formatter |
|
||||
| tick 主循环 30s | `src/daemon/ticker.py` `Ticker.__init__/tick_interval`、`_loop()` |
|
||||
| dispatch 日志（"Dispatched %s to %s"） | `src/daemon/ticker.py:1058/1075`（`_dispatch_pending`） |
|
||||
| Zombie 告警/解除 | `src/daemon/health.py` `_write_alert/_write_resolution`（stale 单位 = tick 数，阈值 20） |
|
||||
| 邮件创建仅 create_task、由 ticker 调度 | `src/api/mail_routes.py` `send_mail()`（无 dispatch 逻辑，旁路指控不成立） |
|
||||
| 调度-写tick-健康检查同轮次序 | `src/daemon/ticker.py` `_tick_project()` 步骤 4/9/8' |
|
||||
|
||||
### 已排除项
|
||||
|
||||
- ❌ counter/Semaphore 死锁（`counter.acquire` 内 `can_acquire` 先检后取，无无限等待路径）
|
||||
- ❌ spawner/monitor 卡死（monitor 全程 `asyncio.wait_for` 超时保护）
|
||||
- ❌ 事件循环阻塞（uvloop 主线程 kevent 正常）
|
||||
- ❌ Thread_4920533 异常（anyio 空闲 worker 正常态）
|
||||
- ❌ 代码版本漂移（开发/安装目录零 diff）
|
||||
- ❌ SQLite 锁死（`database is locked` 是调查方与 daemon 写入的瞬时竞争，且均为调查进程侧报错）
|
||||
|
||||
### 区分方法（若未来再现类似指控）
|
||||
|
||||
```bash
|
||||
# 1) 看绝对最新 tick（注意 DB 是 UTC，本地=UTC+8）
|
||||
sqlite3 data/_mail/blackboard.db \
|
||||
"SELECT datetime(created_at,'+8 hours'), detail FROM events WHERE event_type='daemon_tick' ORDER BY created_at DESC LIMIT 3"
|
||||
# 2) 看 ticker 内存状态（无需任何推理）
|
||||
curl -s localhost:8083/api/daemon/status
|
||||
```
|
||||
若 status 显示 `ticker_running=true` 且 tick_count 在两次查询间递增，即可直接否定「停摆」。
|
||||
|
||||
## ④ 次要发现（真实存在、值得处理的问题）
|
||||
|
||||
1. **可观测性缺陷（本次误报的温床）**：黑板 DB 存 UTC、日志存本地时间、无任何文档标注；且 ticker 正常轮转时**完全静默**（`Tick %d complete` 是 debug 级，`main.py:49` 设 INFO 不输出），导致「无日志 = 疑似挂死」的错误直觉。
|
||||
2. **events 表无限膨胀 + 每轮 tick 全表 COUNT**：每项目 events 已 22–27 万行（6 天累积，其中 daemon_tick 占绝对多数）。`src/daemon/health.py:check()` 每轮 tick 对每项目执行 `SELECT COUNT(*) FROM events` 及带 WHERE 的 COUNT —— sample 显示该扫描已占主线程约 6% 采样时间（`sqlite3BtreeCount→pread`）。按当前增速会持续恶化，最终可能显著拖慢 tick 甚至长时间阻塞事件循环。
|
||||
3. **`_check_session_state` 每次读 gateway 日志尾部 2MB + session jsonl 尾部 1MB**：每次 spawn 前同步文件 IO，随日志增大变慢（目前未致命）。
|
||||
4. **邮件 request 类型验证过严**：本例 agent 回复了文本 payload 但未通过 `POST /api/mail` 回信，被 verify 判 `no_reply` → failed → 自动发「投递失败」邮件（05:07:39），对发起方造成二次困扰，也污染了本次判断。
|
||||
5. **Zombie 告警语义误导**：`stale=20` 的单位是 tick 数（约 10 分钟），凌晨空闲期每天必然告警一次，属告警噪声。
|
||||
6. **调查方 SQLite 直查与 daemon 写入竞争**会得到 `database is locked`，容易误判为「锁死」。建议只读调查加 `-readonly` 打开（`sqlite3 "file:xxx.db?mode=ro"`）。
|
||||
|
||||
## ⑤ 恢复方案建议（只建议，未执行）
|
||||
|
||||
- **无需恢复**：服务健康，PM2 restarts=0，tick 持续。不要重启。
|
||||
- 可选：将 `mail-1788382980110` 及其「[投递失败]」通知邮件标记已读/取消（`PATCH /api/mail/{id}`），避免后续再次触发 spawn。
|
||||
- 可选：对 mail 模板加一句「如需回复请务必走 POST /api/mail」的强调（`src/daemon/mail_handler.py` MailContextSection），缓解 ④-4。
|
||||
|
||||
## ⑥ 预防建议
|
||||
|
||||
1. **统一时间语义**（治本）：
|
||||
- 短期：所有 DB 查询工具/文档标注「created_at 为 UTC」；给运维巡检提供 `datetime(created_at,'+8 hours')` 的惯用查询；
|
||||
- 中期：`get_connection` 写入统一 `datetime('now','localtime')` 或迁移 ISO8601 带 `+08:00` 后缀（需一次性数据迁移，建议排期设计）。
|
||||
2. **ticker 心跳可观测**：将 `Tick %d complete` 从 debug 提到 INFO（或每 N=10 轮打一条 INFO 心跳），并在 `/api/daemon/status` 增加 `last_tick_at`（本地时间）字段 —— 任何人一条 curl 即可自证清白，本次误报可在 30 秒内排除。
|
||||
3. **daemon_tick 事件瘦身/归档**：daemon_tick 写入 events 是主要膨胀源。建议（任选）：a) 每 N 轮写一条汇总 tick；b) 建立每日 cron 归档/删除 7 天前的 daemon_tick 行；c) health.py 的 COUNT 改为维护计数表或 `SELECT MAX(rowid)` 估算，消除每轮全表扫描。
|
||||
4. **watchdog（若仍担心静默挂死）**：外部（PM2/cron）每 5 分钟 curl `/api/daemon/status`，断言 `tick_count` 递增；连续 2 次不递增才告警 —— 基于计数而非时间戳，天然免疫时区问题。
|
||||
5. **health.py zombie 告警降噪**：凌晨时段（00:00–07:00）提高阈值或静默，或告警文案注明「空闲属正常」。
|
||||
|
||||
---
|
||||
|
||||
### 附：原始证据核对表（发起方证据 → 实际含义）
|
||||
|
||||
| 发起方证据（原文） | 实际含义（时区纠正后） | 是否成立 |
|
||||
|---|---|---|
|
||||
| 22 项目最后 daemon_tick = 21:04:56（DB） | 本地 09-03 05:04:56，查询前 2~3 分钟的正常最新 tick | ❌ 误读 |
|
||||
| 第一个项目 tick = 21:04:25 | 同一轮 tick 的起点（22 项目 31s），非「遍历开始」异常 | ❌ 误读 |
|
||||
| 09-02 21:01 起零 tick | UTC 12:30–14:00（本地 20:30–22:00）实测每 30s 有 tick，无空洞 | ❌ 不成立 |
|
||||
| 05:03:21 恢复活动（API 旁路） | 30s tick 常规调度新邮件，dispatch/daemon_tick/zombie-resolved 同 tick 出现 | ❌ 并非旁路 |
|
||||
| 此后仍无新 daemon_tick | tick 18296–18310 持续写入（UTC 21:05–21:12） | ❌ 不成立 |
|
||||
| 8h 无报错日志（连 Tick error 都没有） | 24h 无 INFO 级事件属正常静默；无错误因为无错误发生 | ❌ 误读 |
|
||||
| Zombie _mail stale=20 每天 05:1x 告警 | health.py 凌晨空闲常规告警（stale 单位=tick 数） | ✅ 现象真实，但与停摆无关 |
|
||||
| sample Thread_4920533 卡锁 | anyio 空闲 worker 线程等待任务，正常态 | ❌ 干扰项 |
|
||||
Reference in New Issue
Block a user