前两天排查一个 AI 客服应用的问题用户反馈某条回答答非所问我去翻日志看到的是一堆 print 出来的字符串中间还夹杂着别的用户的输出片段根本没法定位是谁的请求、什么时间、调了哪次模型。那一刻我意识到print 在 AI 应用里已经不是够不够用的问题是在埋雷。这篇文章想聊的就是一件事AI 应用日志别再 print 了换成结构化日志并且用 request_id 把一次请求从头到尾贯穿起来。它适合那些正在做 AI 应用、AI Agent、RAG 服务的开发者也适合后端工程师想给自己的服务补上可观测性短板。内容不涉及特别高深的理论全是能直接抄的配置、代码和经验我把踩过的坑也一并写出来。1. print 在 AI 应用里到底埋了多少雷先说个扎心的事实print 不是日志它只是把字打到屏幕上。很多 AI 应用跑通了 Demo 就直接上了生产日志全是 print等真正出问题的时候才发现自己手里只有一堆谁也看不懂的字符串。1.1 AI 应用的调用链比传统接口长太多传统 Web 接口的逻辑通常是接收参数、查库、算一下、返回链路短出问题顶多两三个环节。但 AI 应用不一样一次用户请求可能要经历网关鉴权、限流查询用户上下文 / 历史会话如果需要 RAG还要做检索、重排构造 Prompt调用大模型 API处理流式输出可能触发回调、写入向量库、记录用量如果是个 Agent 应用还可能循环调工具、多模型协作这么多环节任何一个地方出问题最终表象都是用户觉得回答不对。如果你的日志只有一串 print你连是检索阶段出了问题还是模型本身抽风了都分不出来。1.2 并发场景下 print 的输出顺序全是乱的只要你的服务同时服务多个用户print 就彻底失控了。Python 的 print 默认输出到标准输出多个协程、线程同时打印的时候输出片段会交错在一起。上一行还在打 A 用户的 prompt下一行突然跳成 B 用户的模型返回值再下一行又变成 C 用户的异常堆栈。你盯着控制台看了半天根本分不清哪段日志属于哪个请求。更别提 print 默认没有时间戳即使你手动加上时间也只精确到秒级在同一次请求里多个步骤之间的先后关系根本还原不出来。1.3 print 对性能的影响比想象中大很多人忽略了 print 是有成本的。print 是同步写 IO每调一次都会触发系统调用。AI 应用往往是高并发、长连接、流式响应的场景如果你在流式输出的循环里 print 每个 chunk输出量会非常惊人而且会阻塞事件循环直接影响响应速度。我之前接手过一个服务流式输出的时候每收到一个 token 就打一行 print压测时吞吐量直接掉了差不多 30%。把 print 全删掉、换成异步日志采集之后性能才恢复正常。1.4 云环境里 print 日志等于没有日志现在的服务基本都部署在容器或云平台上标准输出会被采集系统统一收走。print 输出的纯文本采集器收走之后就是一坨一坨的字符串没法按级别过滤、没法按字段检索、没法设置告警。你想查某个用户在某天的所有请求print 根本做不到你只能 grep 关键字然后在几百条混杂着别人请求的日志里人肉找。说白了print 是本地开发时看一眼用的不是生产环境查问题用的。这两件事的差别就是玩具和工具之间的差别。2. 结构化日志别把换掉 print理解成换个 Logger很多人意识到 print 不行之后第一反应是那我换用 logging 模块不就行了。换是应该换但如果只是把 print 换成 logger.info那等于换汤不换药你得到的仍然是一堆字符串。结构化日志的核心不是用哪个库输出而是输出什么形态的数据。真正的结构化日志每一条日志都应该是一个自带字段的 JSON 对象而不是一行拼好的字符串。2.1 一个最小的结构化日志长什么样这是我目前在 Python 服务里用的基础格式先贴出来给你看{ timestamp: 2025-06-18T14:32:07.123Z, level: INFO, logger: app.service.chat, message: llm_call_start, request_id: 9f2c1a7e-8b3d-4f5a-9c6e-1d2b3a4c5d6e, user_id: u_10086, session_id: s_20250618_001, model: gpt-4o-mini, latency_ms: 1234, token_usage: {prompt: 320, completion: 180, total: 500}, temperature: 0.7, retry_attempt: 1 }注意看这里的 message 字段不再是某某用户请求了什么模型、用了多少 token这种拼好的句子而是一个简短的事件名比如llm_call_start、llm_call_end、retrieval_hit、tool_execute。真正想看的上下文信息全部放在独立的字段里。这样做的价值是日志平台可以直接解析每个字段你想要按 request_id 查、按 model 统计、按 latency_ms 找慢请求都是写一条查询语句的事不需要正则去抠文本。2.2 Python 里怎么快速落地结构化日志Python 自带的 logging 模块配合 json 序列化就能实现不需要引入重依赖。核心思路是自定义一个 JSON Formatterimport json import logging from datetime import datetime, timezone class JsonFormatter(logging.Formatter): def format(self, record): log_obj { timestamp: datetime.now(timezone.utc).isoformat(), level: record.levelname, logger: record.name, message: record.getMessage(), } # 把 extra 参数里的字段合并进来 if hasattr(record, extra_fields): log_obj.update(record.extra_fields) return json.dumps(log_obj, ensure_asciiFalse) def setup_logging(): handler logging.StreamHandler() handler.setFormatter(JsonFormatter()) root logging.getLogger() root.handlers [handler] root.setLevel(logging.INFO)然后在业务代码里这样打日志logger logging.getLogger(app.service.chat) logger.info(llm_call_start, extra{extra_fields: { request_id: request_id, model: gpt-4o-mini, prompt_tokens: 320, }})这样每行日志就是一个 JSON采集系统收走后直接能解析。2.3 两个很常见的误区我一开始也踩过第一个误区只把 message 拼成 JSON 字符串其他字段不处理。比如logger.info({user_id: u_1, action: login})这在日志平台看来仍然是一整个字符串字段你想单独筛user_id是筛不出来的所有字段还是挤在 message 里。第二个误区重复配置 handler导致同一条日志打了两遍而且两遍的格式还不一样。这个问题主要出现在你用logging.basicConfig配了一次又手动往 logger 上挂 handler。我现在的习惯是只在根 logger 上配 handler子 logger 只设置 propagateTrue不另挂 handler从源头上避免重复。3. request_id 贯穿全链路的落地做法结构化日志只是把一行日志变成了一个对象但要真正把一次请求的所有日志串起来还得靠 request_id。这个字段就是一次请求的案号从请求进门开始生成一直带到整个流程结束所有环节的日志都带着它。3.1 为什么 AI 应用尤其需要 request_idAI 应用一个请求可能持续几十秒甚至几分钟期间有多次模型调用、多次工具调用日志量是普通接口的几倍甚至几十倍。没有 request_id你面对的就是几百条同等时间戳的日志根本不知道谁跟谁是一伙的。有了 request_id一条查询就能拉出这次请求在每一个环节发生了什么。这个感受在做 Agent 应用的时候尤其明显。一个 Agent 循环里可能调了五次模型、三次工具如果日志里没有 request_id你根本分不清哪次工具调用属于哪个 Agent 轮次排查效率是断崖式下跌。3.2 用 contextvars 而不是 threading.local在 Python 的异步场景下用threading.local存 request_id 是不行的。同一个线程里可能交替跑多个协程threading.local 会把不同请求的 id 串掉。正确做法是使用contextvars它可以跟随异步上下文自动传递import contextvars request_id_var: contextvars.ContextVar[str] contextvars.ContextVar(request_id, default-) def get_request_id() - str: return request_id_var.get() def set_request_id(rid: str) - None: request_id_var.set(rid)3.3 入口处注册 request_idFilter 自动注入request_id 在哪里生成最佳位置是服务的最外层入口也就是中间件。以 FastAPI 为例import uuid from starlette.middleware.base import BaseHTTPMiddleware class RequestIDMiddleware(BaseHTTPMiddleware): async def dispatch(self, request, call_next): # 优先沿用上游传过来的 id方便跨服务串链路 rid request.headers.get(X-Request-ID, str(uuid.uuid4())) set_request_id(rid) response await call_next(request) response.headers[X-Request-ID] rid return response注意这里建议优先沿用上游的X-Request-ID没有才自己生成。如果你有网关层网关已经生成了一个 id下游服务都沿用同一个跨服务排查的时候就都能串起来。这是分布式链路追踪最朴素的形态不用上 Jaeger/Zipkin 也能先解决同一请求跨服务的问题。有了 contextvars 里的 request_id还需要让它自动进到每条日志里。写一个 Filter 挂到根 logger 上class RequestIDFilter(logging.Filter): def filter(self, record): record.extra_fields getattr(record, extra_fields, {}) record.extra_fields[request_id] get_request_id() return True这样你在任何地方打日志都不用手动传 request_id 这个参数它自动出现在每条日志的字段里。注意我这里的 JsonFormatter 里已经有对 extra_fields 的合并逻辑Filter 只需要往这个属性里塞值就行。这个设计解决了我最大的痛点如果 request_id 要手动传总有漏传的时候而 Filter 自动注入可以保证每条日志都有漏不掉。3.4 下游调用时透传 request_id一次请求如果涉及多个服务比如你有一个独立的 RAG 检索服务你需要在调用它的时候通过 HTTP Header 把 request_id 传过去import httpx async def call_retrieval_service(query: str): async with httpx.AsyncClient() as client: resp await client.post( http://retrieval-service/search, json{query: query}, headers{X-Request-ID: get_request_id()}, ) return resp.json()下游服务也按上面的方式在入口中间件里读取X-Request-ID并写入自己的 contextvars它产生的所有日志就都带上了同一个 id。这样从用户请求到检索服务、再到模型调用整条链路的日志都能通过一个 request_id 拉出来。3.5 异步任务和消息队列场景怎么透传如果请求内部还要起 asyncio 任务需要注意 contextvars 在任务创建时会被复制一份。也就是说你在任务外 set 的 request_id任务内部能读到但任务里修改的话不会影响外面。如果任务要用外部的 request_id一般不用额外处理直接读就行。如果是真正跨进程的异步任务比如通过消息队列把任务发给 worker那么 producer 在发消息时要把 request_id 放进消息体consumer 收到后先set_request_id(msg[request_id])再执行业务逻辑这样 worker 里的日志也带上了源头请求的 id。我见过不少团队在这一点上栽过跟头HTTP 阶段日志很规范一到异步 worker 就全断了等于是前半段有案号后半段没案号。4. AI 应用专属的日志难啃点流式输出、回调与异步任务前面说的都是通用做法但 AI 应用有几类日志场景和传统接口很不一样需要单独设计否则 request_id 贯穿了也没用关键信息照样抓不到。4.1 流式输出别只打开始和结束现在大模型接口基本都走流式输出。很多人在流式场景下只记录llm_stream_start和llm_stream_end结束的时候打个总耗时、总 token 数就完事了。这种做法的问题在于如果你想知道用户看到第一个字之前等了多久也就是首 token 延迟你根本查不到。我在做流式日志时会分三个节点记录请求发起时记录llm_stream_start带上模型名、请求参数收到第一个 chunk 时记录first_token_received带上首 token 延迟time_to_first_token_ms流结束/中断时记录llm_stream_end带上总延迟、总 token、是否正常结束首 token 延迟是 AI 应用的核心体验指标。用户觉得卡了没反应很多时候不是总耗时高而是首 token 遥遥无期。你不在日志里记录这个值就永远只能靠用户反馈猜。另外流式响应中途可能因为客户端断开、服务端超时而中断。llm_stream_end这条日志一定要记清楚finish_reason或truncated字段否则你怎么也统计不出有多少请求是没看完就被用户关掉的。我在客户端断开连接的处理上踩过一次坑客户端取消请求后服务端 stream 循环里捕获到异常但只 print 了一下就过去了导致日志里完全看不出这次请求是被用户中断的。后来改成统一记录stream_interrupted事件日志带上 request_id 和已收到的 chunk 数这个问题才变得可观测。4.2 模型调用的重试与多轮需要 attempt 维度AI 应用里一次用户请求可能对应多次模型调用。两种常见情况大模型接口超时或返回 5xx你设置了重试重试两三次后成功RAG 场景里多次调用不同模型或者 Agent 要调好几轮模型如果日志只记录 request_id你能看到有三次 llm_call但看不出哪次是第几次尝试。我建议给每次模型调用都带上attempt编号0 是第一次1 是第一次重试以此类推。同时记录input_message或prompt_preview。用了字段之后排查为什么这次重试后回答质量变差就简单多了你能确切地看到第 0 次尝试用了什么 prompt、第 1 次重试又用了什么 prompt。我在一个 RAG 项目里就出现过一次重试时不小心把检索上下文搞丢的问题靠 attempt 字段一查就定位了。4.3 Agent 循环每个决策都要可追溯如果你在做 Agent 应用日志设计得更需要前置。Agent 循环里模型每做一次决策就调用一次工具然后再把工具结果交给模型。这个循环可能持续十几分钟如果日志只在最后打个 summary中间出了问题根本无处下手。我设计 Agent 日志时会区分几个事件类型agent_step_start记录这一步的模型输入、当前意图tool_call记录工具名、参数、耗时tool_result记录工具返回值的摘要或截断内容agent_final_answer记录最终答案每一步都带 request_id同时再加一个step_index字段标明是第几步。这样你能把一次 Agent 运行的完整轨迹拼出来就像看一集电视剧的分集剧情。甚至可以把每个 step 的关键信息抽出来做成对话式时间线比看原始日志高效得多。我还习惯在每个 step 日志里带上agent_scratchpad_size也就是当前已累积的思考内容大小。Agent 跑久了上下文会越来越长最终可能爆掉上下文窗口。有了这个字段你就可以提前发现这个 Agent 快超了而不是等它报错。4.4 回调场景别让回调日志变成孤儿很多 AI 应用会接入异步回调比如模型 API 流式输出完成后回调通知你的服务做后续处理记账、入库、发通知。这里有个隐蔽的问题回调过来的请求本身是一个新的 HTTP 请求如果你不在回调请求里带上原 request_id回调产生的日志就没有案号和前面的链路断了。我的做法是在发起模型调用的请求参数里就带上一个回调地址回调地址里包含原 request_id 作为查询参数或 Header。回调服务入口中间件同样读取X-Request-ID这样回调日志和原始请求日志就自动串在一起了。这个设计看起来很简单但实际项目里很多团队没做导致模型结果正常但后续处理失败时你只能查到两个孤立的日志片段怎么都对不上。5. 一个真实线上问题的排查链路request_id 怎么帮我省下两小时这一节想用一个真实的排查案例让你直观感受一下结构化日志加 request_id 的价值。这不是理论推演是我在某次值班时真的遇到的场景。5.1 现象用户说回答完全不对某 AI 客服产品用户提问后得到的回答是根据您提供的信息我们无法确认……这样一段空话。用户很生气反馈说问题根本没回答。排班同事看了半天代码觉得逻辑没问题于是随手在日志里翻了翻只看到一堆 print 的输出什么都没查出来。当天我把这个 bug 接过来排查。这时候服务已经完成了一轮日志改造所有关键路径都上了结构化日志并且带 request_id。我问用户要了大概的反馈时间从网关日志里找到了这次请求的 request_id然后在日志平台里执行了一次查询request_id xxxx。5.2 日志拉出来之后5 分钟定位根因这次请求的日志一共 23 条按时间顺序排开我很快就看到了问题所在retrieval_start正常开始检索retrieval_done检索到 0 条结果耗时 180msprompt_build构造 prompt当时检索结果为空的 flag 没有传给 prompt 构造逻辑llm_call_start拿着一个没有检索上下文的 prompt 去调模型llm_call_end模型正常返回回答了那段空话根因很清楚检索阶段返回空结果代码没有做分支处理仍然拿空上下文构造了 prompt 去问模型模型只能自由发挥。如果是以前那堆 print我要么没法定位具体是哪次请求要么得靠猜。现在每一条日志都指向同一个 request_id逻辑链完整前后因果关系一目了然。整个排查过程不到 20 分钟其中大部分时间还是花在等日志平台查询上。5.3 同类排查案例Token 用量怎么莫名其妙翻倍另一个案例也很有代表性。某应用上线后发现账单里的大模型 token 消耗比预估高了一倍但没人能解释多出来的消耗去哪了。用结构化日志之前谁也说不清。用上 request_id 之后我在日志里按token_usage字段做了一次聚合发现某个服务在特定场景下会调用模型两次一次是生成一个中间摘要另一次是拿摘要去生成最终回答。而第一次调用的结果压根没被使用等于白白烧了一倍 token。这种问题如果只看代码很难发现因为代码逻辑看起来是合理的但实际运行时的调用路径和你想的不一样。有了带 token 用量的结构化日志一查一个准。5.4 结构化日志排查问题的核心思路结合上面的案例我想强调一个排查思路不要先翻代码先翻日志。代码只能告诉你逻辑上应该怎么走日志才能告诉你实际上是怎么走的。尤其在 AI 应用这种多环节、多依赖、多不确定性的场景下日志的实证价值远大于代码阅读。正确的排查姿势是拿到 request_id拉出整条链路的日志按时间顺序检查每个环节的关键字段找出第一个不符合预期的节点。这个节点后面的所有异常基本都是它的下游影响。6. 上线前要做的几件事脱敏、采样与成本控制日志改造到这一步已经能解决大部分排查问题了。但作为有经验的人我必须提醒你在把全部日志接入采集平台之前还有几件脏活必须先做否则后面会很被动。6.1 脱敏prompt 和 response 里全是敏感信息AI 应用的日志里天然包含大量用户输入和模型输出。用户可能在 chat 里输入电话号码、身份证号、地址、甚至 API key。如果你把这些内容原样打日志就等于把用户隐私裸奔在日志平台上。我的建议是日志里不要记录完整的 prompt 和 response只记录截断后的摘要比如前 500 字符。必要的时候再做一层脱敏处理匹配手机号、邮箱、身份证等模式并替换成***。有一个折中方案把完整的 prompt 单独存进一个受权限控制的对象存储里日志里只记录它的引用地址比如prompt_s3_key。这样既能保证排查时有完整的原始数据可用又不会让敏感信息散落在日志系统里。6.2 采样不是每条日志都需要全量保存AI 应用的日志量非常大。一次流式调用如果打 3 条 JSON 日志每条 1KB一个每秒 100 请求的服务一天的日志量就是十几 GB 甚至几十 GB。日志存储是持续的花费不能无脑全存。我的做法是分级采样核心路径检索、模型调用、工具执行的元数据字段全量保存业务详情prompt 内容、工具返回值按比例采样比如只保存 10%全量原始信息只针对错误请求或显式标记的调试请求保存这样做的逻辑是元数据字段request_id、耗时、模型、token 数、错误码已经能覆盖绝大多数定位问题在哪个环节的需求。只有当你需要深挖具体 prompt 内容时才需要那 10% 的采样样本。而对错误请求的全量保存是为了保证排错时有充足的上下文。6.3 字段别乱加JSON 日志的每多一个字段都是成本日志字段加多了每条日志的体积就会变大存储成本、采集带宽、查询性能都会受影响。我见过有些团队的日志字段几十个一半是用不上的冗余字段。我现在的原则是必须有timestamp、level、request_id、event按场景加模型名、延迟、token 用量、错误类型不加依赖图、环境变量快照、内部对象序列化核心是每个字段都有明确的查询或告警用途否则就不加。宁可维护两套 logger一套精简线上用、一套详细调试用也不要让线上日志变成信息垃圾场否则等到日志量大到查询超时的时候再优化就晚了。我在接手一个老项目时就碰到过这种问题日志每条 5KB绝大多数是序列化的内部对象看着很全实际上查询一次要几十秒。后来一刀切改了精简字段查询速度上去了排查效率反而提升了一大截。日志不是越全越好是越可检索越好。6.4 用结构化字段直接做告警结构化日志还带来一个隐藏收益可以直接基于字段做告警而不是整天对着关键字正则匹配。比如我可以设置这样的告警规则当event llm_call_end且latency_ms 10000的日志数量在 5 分钟内超过 20 条就触发告警。或者level ERROR且retry_attempt 2时立刻告警。这些规则在非结构化日志里很难实现因为你得先解析文本。结构化之后日志平台和监控系统是天然打通的。这也是我觉得结构化日志不是锦上添花而是上生产的前提的原因。最后说点我的实际操作感受这篇文章是基于我自己做 AI 应用日志改造的真实过程总结的。印象最深的是第一次把整条链路用 request_id 串起来、在日志平台里一次性拉出某个用户完整请求轨迹的那几分钟那种终于看清全局的感觉。之前那种面对一堆 print 无从下手的憋屈感确实一去不复返了。如果你正准备给 AI 应用上日志我个人的建议是先别追求上什么分布式追踪平台把两件事做好就够了一是所有日志换成带结构化字段的 JSON二是让 request_id 自动注入并贯穿每一个环节。这两件事做扎实绝大多数线上问题都能快速定位。日志改造要趁早等日志量大了、链路复杂了再回头改成本会成倍增加。这篇文章属于一个AI 应用工程实践的系列编号 O01专注可观测性这一块。后面我打算接着写一写 AI 应用里的链路追踪、Metrics 埋点和告警设计都是实际项目里跑出来的经验到时见了。
