给 Agent 加可观测性：那次跑对了的任务，44% 的调用是白跑的

Agent SDK 与可观测性第 2 / 2 篇

本文的每个数字都是跑出来的。 环境是 @anthropic-ai/claude-agent-sdk@0.3.260 + claude CLI 2.1.258， 模型 claude-haiku-4-5，验证代码在仓库 experiments/agent-sdk/（obs.mjs）。 ⚠️ 日志与抓包文件不入库（.gitignore 里排掉了）—— 它们是每次跑出来的产物，而且是这一篇最该小心对待的那类文件。原因见第四节。

复核：2026-09-07（SDK 升到 0.3.263，CLI 仍 2.1.258）

✅ 本篇依赖的凭据前提仍然成立：无 key 能跑、无效 key 硬失败 401 不回退， 且认证失败时 result.subtype 仍是 'success'（只有 is_error 分得开）—— 那正是本篇讲「日志要记什么」时反复用到的那个坑。

⚠️ 只重跑了凭据探针，没有重跑 obs.mjs： 正文里的浪费统计、缺陷定位、密钥扫描三段没有重新量过。 那三段要真跑一轮任务并抓包，属于另一个成本量级。 ⇒ 把正文的具体数字当写作时那一轮的记录读，方法本身不随版本变。

上一篇把 SDK 发出去的载荷抓了下来。 这一篇换个方向：运行完了，你怎么知道它干了什么。

先给结论：我跑了一个平凡任务，最终答案完全正确， result.is_error 是 false，过程里一步都没报错。 日志打开一看，9 次工具调用里有 4 次是白跑的。

一、那次“完美”的运行

任务：数四个 .txt 文件各有多少行。只给 Read 和 Glob （不给 Bash —— 给了它一条 wc -l 就结束了，看不到多步过程）。

日志里的九步：

# 工具 入参 结果
1 Glob {"pattern":"*.txt"} ✅ alpha.txt\nbeta.txt\ngamma.txt\ndelta.txt
2 Read /Users/leo/alpha.txt ❌ File does not exist
3 Read /Users/leo/beta.txt ❌ File does not exist
4 Read /Users/leo/gamma.txt ❌ File does not exist
5 Read /Users/leo/delta.txt ❌ File does not exist
6 Read …/fixture/alpha.txt ✅
7 Read …/fixture/beta.txt ✅
8 Read …/fixture/gamma.txt ✅
9 Read …/fixture/delta.txt ✅

看得很清楚：

  • Glob 返回的是裸文件名，不带目录
  • Read 要绝对路径
  • 中间那个缺口，模型用 /Users/leo/（家目录） 补的 —— 不是我传给它的 cwd

四次全失败。救回来的是错误消息自己：

File does not exist. Note: your current working directory is
/Users/leo/…/experiments/agent-sdk/fixture.

拿到这句它就改对了。代价是四次往返、一轮多余的对话、以及那部分 token。

🚨 而这一切从外面完全看不见。 调用方拿到的是：

result.is_error : false
最终答案        : {"alpha.txt":12,"beta.txt":7,"gamma.txt":23,"delta.txt":4}   ← 全对

⭐ 这就是我认为可观测性值得单开一篇的理由： 能靠返回值发现的问题，本来就不需要日志。日志是为这一类准备的 —— 它跑对了，只是比该花的多花了一倍。

这个失败复现了 3/4 次

同样的提示词、同样的选项，跑四次：三次踩了家目录，一次没踩。 没踩的那次它用的是相对路径：

Glob {"pattern":"*.txt"} → Read "./alpha.txt" → …   5 次调用，0 次浪费

⚠️ 所以这不是一个确定的 bug，是一个每次都在掷骰子的接缝： Glob 给相对名、Read 要绝对路径，谁来补这个缺口没有规定。 📌 我不写「25% 的概率」—— n=4 撑不起一个百分比。 能说的是：这个接缝真实存在，而且经常被踩到。

二、「浪费」必须是可判定的，否则那个百分比是我编的

「44%」这个数只有在浪费的定义能由脚本机械判定时才有意义。 所以判据写在代码里（obs.mjs 的 WASTE_KINDS），不写在文章里 —— 写在文章里的判据会和代码分叉，而且分叉时不报错。

三类，每一类都不需要我做判断：

类别 判据
重复调用 同名 + 同入参出现 ≥2 次，第 2 次起计
读了无关对象 入参里出现了不在标准答案集合中的文件名
失败的调用 tool_result 的 is_error 为 true

⚠️ 判不了的就不进统计。 比如「这一步思路绕了」—— 我看着觉得绕，但没有任何脚本能复核它。 宁可少算（把 44% 算成偏低的数），也不掺进主观项。 上面那次 44% 全部来自第三类，一次重复调用都没有。

📌 顺带一条：分子和分母必须来自同一份记录。 全量日志之所以要全量，不是为了详尽，是为了让「9」这个分母 不是我挑出来的。只记「我认为重要的调用」，比例就没有意义了。

三、最难查的那类：全程零报错，答案却是错的

上面那种失败至少还留下了四条 is_error: true。真正难查的是不报错的。

我造了一个描述与实现不一致的工具 —— 这是很常见的一类真实缺陷：

tool('list_txt_files',
     '列出当前目录下所有 .txt 文件的文件名。返回的文件名保证都以 .txt 结尾。',
     {},
     async () => {
       const all = fs.readdirSync(FIXTURE_DIR)   // 🐛 描述承诺只返回 .txt，实现返回了全部
       return { content: [{ type: 'text', text: JSON.stringify(all) }] }
     })

跑出来：

最终答案: {"alpha.txt":12, "beta.txt":7, "delta.txt":4, "gamma.txt":23, "notes.md":2}
                                                                        ^^^^^^^^^^^^
全程报错的步数: 0

notes.md 混进来了，而没有任何一步失败。模型完全按描述行事 —— 它被告知「返回的都是 .txt」，就没有再筛一遍。

⇒ 光看最终答案，你只知道“错了”。判据要求的是日志能指出是哪一步、为什么。 从日志里机械地找（不用我已知的答案）：

⇒ 第 1 步 mcp__files__list_txt_files
   描述承诺：「返回的文件名保证都以 .txt 结尾」
   实际出参：["alpha.txt","beta.txt","delta.txt","gamma.txt","notes.md"]
   违约项  ：notes.md
⇒ 缺陷在工具实现，不在模型 —— 模型是照描述行事的

⭐ 定位的判据是可写死的：某个工具的描述里承诺了什么，它的出参就要满足什么。 这不需要理解语义，只需要把承诺写成一条能检查的规则。 （所以工具描述里那句“保证……“不只是给模型看的， 它同时是一条你可以拿去校验自己实现的断言。）

🚨 我的定位器第一版没找到它，而日志里明明有

第一次跑 U 段，输出是「日志里没定位到（这次它可能没触发）」—— 但缺陷明明触发了。问题在日志的存法：

"head": "[{\"type\":\"text\",\"text\":\"[\\\"alpha.txt\\\",\\\"notes.md\\\"]\"}]"

我用 JSON.stringify(b.content) 存了 MCP 工具返回的块数组， 于是内层引号被**转义了两层**，那条找文件名的正则一条也匹配不到。 数据一个字节都没少，但查不动了。

⭐ 这条比它修起来的样子重要得多： 「记下来了」不等于「查得动」。 全量日志如果存的是结构化对象的字符串化， 后面所有基于文本的分析都会静默地扫不到东西 —— 不是报错，是返回空。 而「扫不到」和「没有问题」长得一模一样。

修法是在写日志时就把 tool_result 正规化成纯文本（obs.mjs 的 textOf）， 而不是在分析时一层层反解析。

四、脱敏：这一篇的判据是「扫得出密钥就是错的」

上一篇那个抓包代理会看到什么？看它自己记下来的：

authorization : <redacted len=115 sha256=3234d67c>
x-api-key     : (没有这个头)

len=115。 那个位置原本躺着一个 115 字符的真凭据。 一个朴素的、把 req.headers 直接写进日志的代理， 会把它原样写进一个准备入库、准备在文章里引用的文件。

（顺带印证了上一篇的结论：走的是 authorization，没有 x-api-key —— 和“借用已登录 CLI 的 OAuth 凭据”对得上。）

所以敏感头一律换成占位符，而保留两样东西：

  • len —— 还能回答「那里原本有没有东西、多长」
  • sha256 前 8 位 —— 还能回答「两次请求用的是不是同一个凭据」

这两样都还原不出原值，但把可观测性里最常需要的两个问题保住了。 📌 脱敏不是把字段删掉。 删掉之后你连“这里本来有个凭据”都不知道了， 而那恰恰是排查认证问题时最想知道的一件事。

🚨 先证明扫描器有牙，再让它去扫

判据是「扫得出密钥就是错的」。那么一个**永远返回“干净”**的扫描器 可以完美通过这个判据 —— 而那是最坏的情况：判据看着过了，实际什么都没查。

所以扫描分两步。第一步喂它六个合成的假密钥：

诱饵 结果
sk-ant-api03-CCCC… ✅ Anthropic API key
Authorization: Bearer DDDD… ✅ Bearer token
eyJhbGciOiJIUzI1NiJ9.… ✅ JWT
ghp_EEEE… ✅ GitHub token
AKIAFFFF… ✅ AWS access key id
"authorization": "GGGG…" ✅ 未脱敏的敏感头

牙口 6/6。

⚠️ 用的是合成值。不能为了测扫描器而把真凭据写到磁盘上 —— 那正好制造了这一篇要防的那件事。

第二步才是扫真实日志：

capture-P.jsonl   326KB  ✅ 干净
capture-R.jsonl   400KB  ✅ 干净
capture-S.jsonl   115KB  ✅ 干净
capture.jsonl     791KB  ✅ 干净
log-T.jsonl         7KB  ✅ 干净
log-U.jsonl         4KB  ✅ 干净
…
脱敏占位符出现 34 处 —— 字段还在，值没了

⇒ ✅ 扫描器有牙（6/6 抓到诱饵），且真实日志 0 命中。判据通过。

📌 最后一道保险：这些文件根本不入库。 判据通过是一回事，把 1.6MB 的原始抓包放进 git 是另一回事 —— 今天扫干净了，不代表下次加了个新字段还干净， 而一旦提交就再也删不掉。可复现性由脚本保证，不由产物保证。

五、那么该记什么

按这三段实际用上的东西倒推，最小集合是：

记什么 少了它会怎样
每次 tool_use 的名字与完整入参 定位不到“是哪一步”，44% 那张表整个不存在
每次 tool_result 的 is_error 与出参正文 U 段无法比对“描述承诺 vs 实际返回”
出参要正规化成文本再存 见第三节：存下来了但扫不动
相对时间戳 用来看哪一步慢；本文没展开
result 的 usage 与 num_turns 成本归因；注意 is_error 不能当成功判据
敏感头的占位符（不是删掉） 排查认证问题时连“这里有没有凭据”都不知道

不记的：请求体里那七万多字符的工具定义（上一篇量过，每轮都一样， 记 N 遍只是把日志撑大）。记它的大小和哈希就够了。

六、能带走的四条

  1. result.is_error === false 不代表这次运行没问题。 它只说明流程没崩。答案对不对、绕了多少路，都要另外看。
  2. 「浪费」要有可判定的定义，否则那个百分比是编的。 判据写在代码里；判不了的宁可不算。
  3. 日志的存法决定它能不能被查。 结构化对象直接 JSON.stringify 存进去， 后面的文本分析会静默失效 —— 扫不到和没问题长得一样。
  4. 脱敏保留 len 和哈希前缀，别整个删掉； 而扫描器必须先被诱饵证明有牙，再去扫真实日志。 一个永远说“干净”的扫描器能通过任何“不许泄露”的判据。

七、没有回答的问题

  • Glob 给相对名、Read 要绝对路径这个接缝，有没有官方的弥合办法？ 我没找到（在提示词里写死绝对路径当然可以，但那是绕过去，不是修好）。
  • 那个 3/4 的踩坑率，换个模型是多少？ 只测了 claude-haiku-4-5。
  • 本文的“浪费”只覆盖了三类可判定的。 无效重试、上下文膨胀这两类 （stub 里点名的）我没能写出机械判据，所以没算 —— 它们大概率真实存在， 只是这套量具看不见。
  • usage.cache_read_input_tokens 能不能用来定位“上下文膨胀”？ 值得试，本文没做。

← 返回 Agent 开发