15.2 结构化日志与关联 ID
15.1 的 span 树回答了「这次运行由哪些部分组成」，但树是运行结束才成型的——你没法在运行途中看它一眼，也没法把一次运行和前后几十次运行的记录放在一起检索。真实服务里更常见的场景是：线上突然冒出一批失败，你想知道「刚才那 5 分钟里，哪些 run 卡在了同一个工具上」。这时候需要的不是一棵事后的树，而是一串能按字段筛、能按标识聚的日志。
本节把 minagent 推进到
minagent/logging.py：用标准库logging加一个 JSON formatter，把每个事件输出成一行结构化日志，字段固定为ts/level/event/run_id/session_id/span_id/tool/duration_ms；run_id作为关联 ID 贯穿一次运行的所有日志，把散落的行串成一条线。
15.2.1 print 的问题：给人看，不给机器看
先看一个典型的 print 日志长什么样：
[run] 开始处理：算 2+3
调用模型 第0轮，用了 1.2ms
工具 add 执行完毕
调用模型 第1轮，用了 1.0ms
run 结束
人能读懂，机器读不懂。五个问题逐条说：
| 问题 | 后果 |
|---|---|
| 字段没结构 | 想按「工具名」筛选，只能写正则去抠字符串 |
| 没有唯一标识 | 两次 run 的日志交错在一起，分不清哪行属于哪次 |
| 级别混在文本里 | 想只看错误，没有可依赖的 level 字段 |
| 时间不统一 | 有的行有时间有的没有，跨机对齐无从下手 |
| 无法聚合 | 「这个工具平均耗时多少」这类统计做不了 |
根子在：print 的消费者是人，日志的消费者是机器。日志系统（Elasticsearch、Loki、CloudWatch）都按结构化字段建索引，喂给它一坨自由文本，它只能全文检索——那等于放弃索引。修法只有一个：每个事件输出成一行 JSON，字段名固定。
15.2.2 JSON formatter：一行一条结构化事件
标准库 logging 天生支持自定义 Formatter，让它把 LogRecord 拼成 JSON 即可：
# minagent/logging.py
import json
import logging
import sys
from typing import Any
class JsonFormatter(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
base = {
"ts": self.formatTime(record, "%H:%M:%S"),
"level": record.levelname,
"event": record.getMessage(),
}
base.update(getattr(record, "fields", {}))
return json.dumps(base, ensure_ascii=False)
def get_logger() -> logging.Logger:
logger = logging.getLogger("minagent")
if not logger.handlers:
h = logging.StreamHandler(sys.stdout)
h.setFormatter(JsonFormatter())
logger.addHandler(h)
logger.setLevel(logging.INFO)
logger.propagate = False
return logger
def emit(logger: logging.Logger, event: str, level: int = logging.INFO, **fields: Any) -> None:
logger.log(level, event, extra={"fields": fields})
三个设计点值得停一下：
base.update(getattr(record, "fields", {}))：base是每条日志都有的三个固定字段（ts/level/event），业务字段通过record.fields合并进来。用getattr(..., {})兜底，是为了让没带fields的日志也能正常输出。extra={"fields": fields}：logging的extra会把键值挂到record上。这里把整包业务字段塞进一个fields键，而不是直接散进extra——因为extra的键名不能和LogRecord自带属性（message、levelno等）撞名，包一层最省心。ensure_ascii=False：中文直接输出，不转成\uXXXX。日志要给人看时，这一步让可读性差出好几倍。
emit 是一个薄封装，把「事件名 + 若干字段」变成一条 logger.log 调用。调用处写成 emit(logger, "tool.call", run_id=rid, tool="search", duration_ms=12.4)，读起来就是一句自然的陈述。
本节约定八个固定字段，一次运行里的每条日志都尽量带上能带的：
| 字段 | 含义 | 示例 |
|---|---|---|
ts | 事件时刻 | 01:42:55 |
level | 级别 | INFO / ERROR |
event | 事件名（稳定枚举） | tool.call |
run_id | 本次运行的关联 ID | 510775b8 |
session_id | 所属会话 | sess-A |
span_id | 对应 15.1 的 span | e32aea |
tool | 工具名（仅工具事件） | add |
duration_ms | 该动作耗时 | 1.2 |
字段名是契约：一旦定了就不要改，因为下游的查询、面板、告警都按这些名字写死。event 尤其要收敛成有限枚举（run.start / model.call / tool.call / run.end），别写成自由文本——枚举才能被稳定筛选。
15.2.3 run_id：把散落的日志串成一条线
字段里最关键的一个是 run_id——关联 ID（correlation ID）。它解决的问题是：并发环境下，日志是交错的。进程同时服务几十个 run 时，stdout 里的行会你一段我一段地混在一起，光看内容根本分不清哪些行属于同一次运行。
run_id 的用法很朴素：一次运行开始时生成一个，之后这条运行产生的每一条日志都带上它。有了它，「把所有 run_id=abc 的行捞出来」就等于「还原这次运行的完整时间线」。这和第 7.2 的 session_id 是两种粒度的标识：
| 标识 | 粒度 | 生命周期 | 用途 |
|---|---|---|---|
session_id | 会话 | 跨多轮、跨进程 | 串起一个用户的整段对话 |
run_id | 单次运行 | 一次 run 内 | 串起这次 run 的所有日志与 span |
span_id | 单个 span | 单个调用 | 与 15.1 的树节点对齐 |
三者是嵌套关系：一个 session_id 下有多条 run_id，一个 run_id 下有多个 span_id。把它们都写进每条日志，等于给每行都贴上了「属于哪次会话、哪次运行、哪个调用」的三级坐标——任何一个都能当检索入口。
run_id 生成后必须一路传下去。它通常不是在被调用方临时造的，而是由入口层（HTTP 网关、CLI）生成并随请求带上，因为同一次运行的日志可能跨越多个函数、多个模块甚至多个服务，只有入口处生成的这一个才能统辖全局。本节为了自洽，在 run_with_logs 入口生成；真实系统里它多半是参数传进来的。
15.2.4 真跑：两次 run 的 JSON 日志
把 emit 接进 run 循环，每个关键动作各发一条事件：
def run_with_logs(model, tools, user_input, session_id, logger, max_steps=8):
run_id = uuid.uuid4().hex[:8]
start = time.perf_counter()
emit(logger, "run.start", run_id=run_id, session_id=session_id, input=user_input)
messages = [Message(role="user", content=user_input)]
for i in range(max_steps):
t0 = time.perf_counter()
resp = model.complete(messages, tools)
span_id = uuid.uuid4().hex[:6]
emit(logger, "model.call", run_id=run_id, span_id=span_id, step=i,
duration_ms=round((time.perf_counter() - t0) * 1000, 2),
stop_reason=resp.stop_reason, input_tokens=resp.usage.get("input_tokens"))
messages.append(resp.message)
if not resp.message.tool_calls:
emit(logger, "run.end", run_id=run_id, session_id=session_id,
duration_ms=round((time.perf_counter() - start) * 1000, 2))
return resp.message.content
for tc in resp.message.tool_calls:
t0 = time.perf_counter()
result = tools(tc)
emit(logger, "tool.call", run_id=run_id, span_id=span_id, tool=tc.name,
duration_ms=round((time.perf_counter() - t0) * 1000, 2),
ok="error" not in result)
messages.append(Message(role="tool", content=result, tool_call_id=tc.id))
return ""
四个事件覆盖一次运行的骨架：run.start（开始）、model.call（每轮模型调用）、tool.call（每次工具调用）、run.end（结束）。每次 model.call 与它那轮触发的 tool.call 共用同一个 span_id——这正好和 15.1 的树对齐：同一轮里的模型调用与工具调用，在树上是同一个父 span 下的兄弟。
跑两次 run，两次都调工具，但第二次故意让模型幻觉出一个不存在的工具名 divide（真跑，Python 3.14.6）：
{"ts": "01:42:55", "level": "INFO", "event": "run.start", "run_id": "510775b8", "session_id": "sess-A", "input": "算 2+3"}
{"ts": "01:42:55", "level": "INFO", "event": "model.call", "run_id": "510775b8", "span_id": "e32aea", "step": 0, "duration_ms": 1.2, "stop_reason": "tool_use", "input_tokens": 26}
{"ts": "01:42:55", "level": "INFO", "event": "tool.call", "run_id": "510775b8", "span_id": "e32aea", "tool": "add", "duration_ms": 0.01, "ok": true}
{"ts": "01:42:55", "level": "INFO", "event": "model.call", "run_id": "510775b8", "span_id": "3b9707", "step": 1, "duration_ms": 1.04, "stop_reason": "end_turn", "input_tokens": 18}
{"ts": "01:42:55", "level": "INFO", "event": "run.end", "run_id": "510775b8", "session_id": "sess-A", "duration_ms": 2.81, "input_tokens": 44, "output_tokens": 16}
{"ts": "01:42:55", "level": "INFO", "event": "run.start", "run_id": "03683f02", "session_id": "sess-B", "input": "算 2*3"}
{"ts": "01:42:55", "level": "INFO", "event": "model.call", "run_id": "03683f02", "span_id": "b7cf23", "step": 0, "duration_ms": 1.13, "stop_reason": "tool_use", "input_tokens": 26}
{"ts": "01:42:55", "level": "INFO", "event": "tool.call", "run_id": "03683f02", "span_id": "b7cf23", "tool": "divide", "duration_ms": 0.01, "ok": false}
{"ts": "01:42:55", "level": "INFO", "event": "model.call", "run_id": "03683f02", "span_id": "bae71c", "step": 1, "duration_ms": 1.29, "stop_reason": "end_turn", "input_tokens": 18}
{"ts": "01:42:55", "level": "INFO", "event": "run.end", "run_id": "03683f02", "session_id": "sess-B", "duration_ms": 2.89, "input_tokens": 44, "output_tokens": 16}
十行日志、两次运行，它们交错在一个 stdout 流里。注意第八行那个 "tool": "divide" 配 "ok": false——这就是「模型幻觉出一个不存在的工具」在日志里留下的指纹。如果没有结构化字段，你得读遍十行才能发现它；有了字段，一行 jq 就能筛出来。
15.2.5 用 run_id 过滤：还原单次运行
结构化日志真正的威力在检索。两次运行的日志混在一起，但每行都带着 run_id，按它一分就还原成两条独立的时间线：
def pick(run_id: str) -> list[str]:
return [l for l in sink.lines if json.loads(l).get("run_id") == run_id]
ids = [json.loads(l)["run_id"] for l in sink.lines
if json.loads(l)["event"] == "run.start"]
for rid in ids:
rows = pick(rid)
print(f"run_id={rid} 共 {len(rows)} 行")
run_id=510775b8 共 5 行 run 总耗时 2.81 ms
run_id=03683f02 共 5 行 run 总耗时 2.89 ms
两次运行各 5 行，一条不多一条不少。pick 用的是 json.loads(l).get("run_id")——先解析再比较，而不是字符串 in。这个区别很重要：字符串匹配会把「某行内容里恰好包含这个 id」也算进来，而按字段解析只在字段真的等于这个 id 时才命中。结构化日志之所以能这么可靠，正是因为字段边界由 JSON 保证，不用猜。
同样的字段还能换别的维度聚合。三条典型查询：
| 想回答的问题 | 过滤条件 |
|---|---|
| 这次 run 经历了什么 | run_id == "510775b8" |
| 这个会话下所有运行 | session_id == "sess-A" |
| 所有失败的工具调用 | event == "tool.call" and ok == false |
第三条尤其有用：event == "tool.call" and ok == false 会捞出全站所有失败的工具调用，不用管它们属于哪次运行。这就是**「关联 ID 串起来、固定字段筛出来」**的双重价值——run_id 负责纵向串联，其余字段负责横向筛选。
同样的过滤用命令行工具 jq 就能做，不必写 Python：
jq -c 'select(.event=="tool.call" and .ok==false)' minagent.log
一行 jq 就捞出所有失败的工具调用——这就是结构化日志「可检索」的直接兑现：字段是机器可读的，检索工具就能即插即用。
15.2.6 日志、追踪、指标：三者的分工
现在 minagent 手里有三样观测手段了，它们不是竞争关系，而是各管一段：
| 手段 | 数据形态 | 回答的问题 | 本节/前节 |
|---|---|---|---|
| 日志 | 离散事件（一行一条） | 某时刻发生了什么 | 15.2 |
| 追踪 | 结构化调用树（span） | 这次运行的结构与耗时分布 | 15.1 |
| 指标 | 数值时间序列（计数器/直方图） | 整体趋势与告警 | 15.3 铺路 |
一句话区分：日志是点，追踪是结构，指标是趋势。日志回答「发生了什么」，量在精、在能检索；追踪回答「为什么是它、卡在哪」，重在嵌套与耗时；指标回答「最近变好了还是变差了」，重在可聚合、可画图、可设阈值。
三者用同一套 run_id / session_id / span_id 打通时，排查体验是这样的：指标先报警（「p99 延迟翻倍」），顺着时间找到可疑的 run_id，用追踪看那次运行卡在哪个 span，再用日志读那个 span 的原始事件——从趋势到结构到事件，一路下钻。这就是「关联 ID」最实用的地方：它让三种数据能互相跳转，而不是三个孤岛。
15.2.7 埋点位置的取舍
日志不是越多越好。埋太密，一次 run 几百行，真出事时反而找不到重点；埋太疏，关键转折没记录，事后无从复盘。一条经验是：在「状态发生跃迁」的地方埋点。一次 run 里状态跃迁就那么几处——运行开始、每轮模型返回、每次工具调用返回、运行结束，它们恰好对应四个事件，不多不少。
反过来，不要埋的点也要说清：
| 不该埋的点 | 原因 |
|---|---|
| 每次消息追加 | 纯内部动作，出错时看上下文快照即可 |
| 循环的每一行 | 噪声，淹没真正的信号 |
| 完整 prompt / 完整响应全文 | 体积大、可能含敏感信息，只记长度与摘要 |
第三点尤其要克制。真实系统里把整段 prompt 写进日志是事故高发区：既撑爆日志存储，又可能把用户隐私或密钥泄漏到日志平台。本节的 model.call 只记 input_tokens 与 stop_reason 两个标量，就是这个原则的体现——记元数据，不记全文；真要留全文，走单独的、带访问控制的存储。
真实模型下会怎样：本节的日志只有十几个字段、每次运行区区 5 行；真实系统里，一次 run 的日志可能有几十上百行（每次流式增量、每次重试、每个子 Agent 的进出都各算一条），字段也多得多（model、request_id、trace_id、cost_usd）。量级一上来，两个问题立刻浮现。其一是成本：把每条日志都 json.dumps 再写 stdout，I/O 会成为瓶颈，真实系统会用异步日志或批量 flush。其二是采样：高流量下不可能全量保留，常见做法是错误日志全留、成功日志按比例采样——但采样时必须保证同一个 run_id 要么整体留下要么整体丢弃，否则时间线会残缺。此外，真实的 run_id 往往就是分布式追踪里的 trace_id，日志系统与追踪后端共用它，才能在两个系统之间一键跳转；本节为了讲清概念把它们拆开了，落地时应统一。
阅读导航：上一节：15.1 运行追踪 · 下一节：15.3 成本与用量核算 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。