故障档案

「输出超时」——可文件已经装好了

前端超时 watchdog 误杀长工具链,同时掩盖后端真实错误,导致排障困难。

「输出超时,已自动结束」。用户看到这个提示,肯定以为失败了。但检查客户机的文件系统发现:~/.skillhub/config.json~/.local/bin/skillhub.cmd 都已落地,时间戳是 17:51:16 和 17:51:19。文件装好了。错位了。

现象

某客户机(Windows),用户让 deepseek-v4-flash 帮忙手动安装 SkillHub CLI,在无 bash 环境下。AI 开始顺利执行:先 web_fetch 拉取安装文档,提示「先检查是否已安装 SkillHub CLI」,随后进入连续工具循环——exec / read / write 轮流调用,手工解包 tarball、复制 .py 文件、写 skillhub.cmd、修改 PATH。

约 90 秒后,聊天框直接弹出系统消息:「输出超时,已自动结束」。AI 的输出被截断,会话强制结束。

看起来失败了。但检查客户机发现:~/.skillhub/config.json~/.local/bin/skillhub.cmd 都已落地,时间戳分别是 17:51:16 和 17:51:19。文件装好了。

这就是那个典型的"前端保护机制掩盖后端真实状态"的现象——超时提示完全错误,但用户根本看不到真相。

排查过程

第一步:找到超时提示的源头

grep 整个 wakou-full 仓库搜「输出超时,已自动结束」,定位到两个位置:src/locales/zh-CN.json:1655 的多语言文本,以及 src/pages/chat.js:1909 的调用点。

第二步:看计时器的逻辑

打开 chat.js:1907-1917,这是一个 90 秒的安全计时器。每次收到 text delta 事件就调用 clearTimeout() 重置,超时后就执行 appendSystemMessage(t('chat.streamTimeout')) 加上强制 reset 流式状态。

逻辑看起来合理,但 reset 的触发条件很关键:

if (state === 'delta') {
  ...
  if (c?.text && c.text.length > _currentAiText.length) {
    ...
    clearTimeout(_streamSafetyTimer)
    _streamSafetyTimer = setTimeout(() => { ... 90s 后强切 ... }, 90000)
  }
}

只有在 state === 'delta'text 长度增长 时才会 reset。这是关键漏洞。

第三步:找会话记录验证

进客户机的本地数据目录,找到 data/openclaw/agents/main/sessions/ 下的会话日志文件(JSONL 格式),时间范围 17:50:32 → 17:51:22,约 50 秒跨度。逐行解析事件流:

17:50:32 - state: 'delta', text: '先检查是否已安装 SkillHub CLI。'
17:50:35 - state: 'delta', text: '正在检查...' (这是最后一个 text 输出)
17:50:37 - state: 'thinking', reasoning_content: [...]
17:50:43 - state: 'toolCall', tool: 'exec', args: {...}
17:50:45 - state: 'toolResult', result: {...}
17:50:46 - state: 'thinking', reasoning_content: [...]
... (重复的 thinking + toolCall + toolResult 循环)
17:51:15 - state: 'toolResult', result: '文件已写入 ~/.local/bin/skillhub.cmd'

共 10+ 轮 thinking + toolCall 事件。期间没有任何新的 text 块。最后一次 text 输出发生在 17:50:35,然后就是工具循环。

90 秒的计时器从 17:50:35 开始计数(此时最后一次 reset),约 17:52:05 时触发(距离最后的活动已经 90+ 秒)。

第四步:发现被吞掉的真实错误

同时期的后端日志 profile/Temp/openclaw/openclaw-2026-05-02.log,17:51:41 记录了一条 deepseek API 返回 400:

error: The reasoning_content in the thinking mode must be passed back to the API.
code: 400

这是 deepseek 的 thinking 模式协议要求——当模型产出 reasoning_content 时,agent runtime 必须在下一轮请求里回传这段内容,否则 API 会拒绝。wakou 的 agent runtime 在多轮对话中没有正确回传,导致了这个 400 错误。

但这条错误被前端 watchdog 抢先吞掉了。用户只看到「输出超时」,工程师也看不到真实的 API 错误。排障线索完全丢失。

根因

两层问题叠加:

一级问题:超时判据不完整

计时器只把 text delta 当作"模型仍在工作"的信号。但当下 agent 的常态是长工具链和长思考链

  • thinking 事件只是模型的 reasoning_content,不增加 c.text 长度,不会 reset 计时器;
  • toolCall / toolResult 事件走的是另一条消息路径(payload.message.tools),同样不触发 state === 'delta' 的分支;
  • 实际的工具执行(比如 web_fetch、exec 在 Windows 上跑 Invoke-WebRequest 拉 tarball)可能耗时 30s+。

只要"两次连续 text 输出之间的间隔 > 90s",watchdog 就会误杀。而这种间隔在「先报告思路 → 进入长工具循环 → 工具执行完成后汇报结果」的对话模式里是完全正常的,不是异常。

二级问题:错误被覆盖

watchdog 误杀后,前端把 state:'error' 的事件处理路径也覆盖掉了。后端返回的真实错误(比如这次的 deepseek 400)无法被用户和工程师看到。排障难度上升,因为现象看起来就是"超时",导致团队去排查网络、延迟、模型响应,而不是去看 API 协议是否实现正确。

修复

根治方案:让超时判据覆盖所有"活着"的信号

需要前后端配合。前端不能只看 text delta,而是只要后端还在工作就持续 reset;超时只在"真的什么都没发生"时才触发。

后端侧修改(gateway / agent runtime)

在 SSE/事件发送处,在工具调用、reasoning、思考阶段持续推送 keepalive 事件。两个等价做法:

推荐方案:新增独立事件

每隔约 10 秒推一个 state:'progress' 事件,payload 带当前阶段标签和进度信息。这样前端在收到任意非 final|error 事件时都能 reset 计时器。事件语义清晰,后续 UI 也能基于 progress 显示"正在执行 xxx 工具"。

备选方案:复用 delta 承载

在 thinking / tool 阶段把当前阶段名、工具名、进度作为非空 payload 的 delta 推出来(不一定要写到 text 字段),前端在收到任何 delta(含 thinking、tools 字段更新)时统一 reset。这个方案改动小但语义不如第一种清晰。

前端侧修改(src/pages/chat.js

把 reset 触发条件从"只看 text 长度增长"放宽到"收到任何 state ≠ final|error 的事件":

if (state === 'delta' || state === 'progress' || state === 'tool_running' || state === 'thinking') {
  clearTimeout(_streamSafetyTimer)
  _streamSafetyTimer = setTimeout(() => { ... }, STREAM_TIMEOUT_MS)
}

同时把 STREAM_TIMEOUT_MS 从 90 秒调整到 180 秒作为兜底。即便 keepalive 事件因为网络或其他原因没按时来,也给后端、网络、模型多留一点容错空间。建议把 STREAM_TIMEOUT_MS 常量提到文件顶部,方便后续按不同客户场景调整。

顺手修的二级问题

watchdog 触发后不要清空 runId 状态,给后端一个继续把 final / error 事件推上来的窗口。这样真实错误(包括 deepseek 的 API 400、超时、业务逻辑错误)仍能展示给用户和工程师,便于排障。

修改建议:

if (timeout triggered) {
  appendSystemMessage(t('chat.streamTimeout'))
  // 不调用 resetStreamState(),保留 runId
  // 让后端继续推送 final / error 事件
}

deepseek thinking 模式 reasoning_content 必须回传是另一个独立 bug(已单独跟进),不在本次范围内。

防回归

任何"前端拿超时 watchdog 守后端流"的场景都要明确"在工作"的最小信号集。只盯 text delta 是天然脆弱的,因为 LLM 工具循环里 text 本来就会出现长间隔。需要在 SSE/WS 事件规范中明确约定:后端在长任务(tool / 网络拉取 / reasoning)阶段必须有 ≤ 30 秒心跳。

测试层应构造一个"AI 执行 10+ 轮工具调用但中间没有 text 输出"的测试用例,验证 watchdog 不会误杀。监控层则需要关联前端 watchdog 触发频率与后端 error 日志,如果超时提示频繁出现但没有对应的真实错误,说明 watchdog 在误杀。

星野的头像

星野 XINGYE

一个人维护 AI 平台的工程师。这里记录 63 篇复盘:18 份故障档案、OTA、架构演进与工作流。