企业官网建设流程全解析

前两天排查一个 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 Formatter：

import 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_ascii=False) 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 只设置 propagate=True，不另挂 handler，从源头上避免重复。

3. request_id 贯穿全链路的落地做法

结构化日志只是把"一行日志"变成了"一个对象"，但要真正把一次请求的所有日志串起来，还得靠 request_id。这个字段就是一次请求的"案号"，从请求进门开始生成，一直带到整个流程结束，所有环节的日志都带着它。

3.1 为什么 AI 应用尤其需要 request_id

AI 应用一个请求可能持续几十秒甚至几分钟，期间有多次模型调用、多次工具调用，日志量是普通接口的几倍甚至几十倍。没有 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_id，Filter 自动注入

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 条结果，耗时 180ms
• prompt_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 埋点和告警设计，都是实际项目里跑出来的经验，到时见了。