AI 应用日志别再 print 了：结构化日志 + request_id 贯穿（O01）

前端阿凡
14 阅读5分钟

AI 应用日志别再 print 了：结构化日志 + request_id 贯穿（O01）

系列《AI 应用生产化手册》第 6 篇（共 30 篇）｜配套开源项目：github.com/ChenYingbo/… 模块一（评测工程）5 篇已完结，从本篇进入模块二：可观测性

一、先看三个"盲人摸象"时刻

  1. 用户说"回答好慢"——多慢？哪个环节慢？是模型慢还是网关慢？你答不上来。
  2. 线上回答质量突然变差——是换模型了？提示词被改了？还是某类问题本来就差？没有历史日志，无从对比。
  3. 请求失败了，日志里只有一行 ERROR: xxx——没有 request_id、没有上下文、没有当时模型看到了什么，根本没法排查。

根因只有一个：你的 AI 应用"不可观测"——出了事你只能靠用户描述和猜。

核心认知：AI 应用观测的第一层不是炫酷的追踪平台，而是"结构化日志"。追踪平台是锦上添花，结构化日志是地基。

二、原理：为什么传统观测对 AI 应用失效

传统观测三支柱（Metrics / Logs / Traces）在 AI 应用上有三个失效点：

传统假设AI 应用的现实后果
输出是确定的，日志能比对"预期"输出是概率性的，没有"预期值"日志只能记录，不能断言对错
一次请求一次调用一次问答 = 多步（检索→LLM→工具→再生成）单条日志看不出完整链路
上下文无关答案质量强依赖上下文不知道"模型当时看到了什么"，无法定位答错原因

结论：AI 应用观测的关键不在"多打日志"，而在"打对什么"——尤其是把输入、上下文、中间步骤记录下来。

AI 应用该观测的六类信息

类别记录什么回答什么问题
① 输入输出问题（脱敏后）、答案长度"用户问的什么、模型答的什么"
② 思考过程推理步骤、中间结果（Agent）"模型怎么得出这个答案的"
③ 工具调用工具名、参数、返回值、耗时"工具用对没有、卡在哪"
④ 上下文系统提示词版本、检索到的文档"模型看到了什么"（定位幻觉的关键）
⑤ 成本in/out tokens、模型"这次回答花了多少钱"
⑥ 延迟总耗时、各环节耗时"慢在哪一环"

结构化日志 vs 自由文本日志

自由文本（print）结构化（key=value）
示例模型返回了，用了 3 秒event=llm_call model=chat-cheap in_tokens=69 out_tokens=85 latency_ms=1766
检索grep 只能按人话猜按字段精确过滤
对比无法程序化分析可解析、可聚合、可入看板
串联没有 request_id全链路同一 request_id

结构化 = 机器可读。机器可读 = 可以聚合、告警、画图——这就是监控看板的地基。

request_id：把碎片串成链路

grep request_id=a1b2c3d4e5f6 app.log
→ 完整还原一次请求的生命周期（耗时、token、哪一步失败）

三、动手：装上结构化日志

git clone https://github.com/ChenYingbo/ai-prod-demo.git && cd ai-prod-demo
cp .env.example .env   # 填 DEEPSEEK_API_KEY
docker compose up -d litellm
source .venv/bin/activate && pip install -r requirements.txt
uvicorn app.main:app --port 8000

制造一次真实请求，观察日志：

curl -s -X POST http://localhost:8000/api/chat \
  -H "Content-Type: application/json" -d '{"question":"什么是 RAG？"}' | head -c 120

你会看到同一 request_id 串起的完整链路（这是配套项目的真实日志）：

event=chat_request  request_id=05e83d83c150 question_len=13
event=llm_call      request_id=05e83d83c150 model=chat-cheap in_tokens=69 out_tokens=85 latency_ms=1766
event=chat_response request_id=05e83d83c150 answer_len=207 latency_ms=1889

三条验证断言

  1. 同一 request_id：三个事件 request_id 一致 → 链路可串联
  2. 字段可检索：grep -c "event=llm_call" app.log 能数出调用次数
  3. 错误可见：grep "event=chat_error" 能看到 502 的延迟和错误摘要

这些日志能回答什么

  • "慢在哪一环？" → chat_response.latency_ms vs llm_call.latency_ms 对比
  • "平均每次请求花多少 token？" → llm_call.in_tokens 求和
  • "今天失败了多少次？" → chat_error 计数

四、真实踩坑

  1. 日志打全量输入：问题全文进日志 = 隐私风险 + 体积爆炸——只打 question_len
  2. 没有 request_id：一堆日志散落无法串联——中间件必须为每个请求生成并贯穿
  3. LLM 日志和业务日志混在默认 logger：uvicorn.access 默认日志是双份噪音——关掉，统一走结构化
  4. （实测）第三方库噪音：openai SDK 底层 httpx 会把每次 HTTP 请求打成 INFO，直接淹没业务日志——httpx/httpx2/openai/httpcore/urllib3 全部压到 WARNING。特别提醒：新版 openai 的内部 logger 叫 httpx2（不是 httpx），只压 httpx 是不够的
  5. 只在错误时打日志：成功路径也要打——没有成功基线就没法对比退化
  6. 时间戳没有时区：跨机器对比全是坑——统一 UTC ISO8601
  7. 打印配置的模型名而不是实际模型：配置写 chat-strong，实际调 deepseek-chat——要打 resp.model（实际值）

五、小结

  • 传统观测三失效：输出不确定 / 多步调用 / 上下文依赖
  • 六类信息：输入输出、思考过程、工具调用、上下文、成本、延迟
  • request_id 是地基——追踪平台本质就是"自动化的 request_id 串联"
avatar
文章
阅读
粉丝