周六下午,手机突然连续震了十几下,全部来自同一个群里同一句艾特:Agent 服务又挂了,用户第一句话就报 500。
我打开后台,心跳监控是绿的,进程状态正常,内存和 CPU 也没有异常波动。但试了几个请求,确实第一轮对话就直接打回 500。更麻烦的是,这条 500 不是一个通用的错误页,而是 Agent 编排层转出来的业务错误码,也就是说请求已经走到了 Agent 的入口逻辑,但在某个节点上被直接掐断了。
这种问题最难受,因为它不是“挂了”,而是“半死不活”。我们三个人,从下午四点半开始查,查了三轮,最后发现原因落在入口日志少打了一个参数上。这个过程挺有代表性,写下来给做 Agent 应用、做 LLM 编排、做在线服务排查的朋友们做个参考。
1. 先说清楚 Agent 入口日志到底长什么样
我们这个 Agent 服务,属于典型的“编排型 Agent”架构。外面是 API 网关,进来之后是会话管理模块,然后是工具注册中心、大模型调用层、以及最外层的 Prompt 组装逻辑。用户第一句话进来,会先走一遍完整的链路:鉴权、查会话上下文、判断要不要使用工具、组装 Prompt、调用大模型、解析返回结果,再落库、返回给用户。
整套链路里,入口日志是第一条记录。每进来一次请求,我们都会打一条带有全局 request_id、用户 ID、会话 ID、模型名称、请求摘要的日志。正常情况下,这条日志是排障的第一道门面,一眼就能看出来请求是从哪儿进来的、带了多少上下文、走的哪个模型。
问题就出在这条日志上。500 报错之后,我们做的第一件事,就是把入口日志全部捞出来看了一眼。
那天的日志大概是这样的:
# 入口日志正常应该有的样子 { "request_id": "req_a1b2c3", "user_id": "u_10086", "session_id": "s_20241111_001", "model": "gpt-4o-mini", "prompt_preview": "帮我查一下本月账单", "timestamp": "2025-01-18T16:30:01.123Z" }但报错的那段时间,日志长这样:
# 异常期间的入口日志 { "request_id": "req_d4e5f6", "user_id": "u_10086", "session_id": "", "model": "gpt-4o-mini", "prompt_preview": "帮我查一下本月账单", "timestamp": "2025-01-18T16:30:01.125Z" }session_id 是空的。当时我们没人注意到这个空格,因为请求照样进来了,用户照样能触发后续逻辑,只有等到下游报错时才发现问题。但更关键的是,这个日志缺失的字段,直接导致了后面整个链路追踪断掉。
现在回头看,如果第一轮排查时有人认真对着日志字段清单核对一遍,大概五分钟就能锁定问题。但实话讲,没人会觉得入口日志这种“基础到不能再基础”的东西会出错,所有人都在往模型层、网络层、上游网关去猜。
这个案例本身,就是一次“低层错误被高层复杂度掩盖”的典型教学。
2. 第一轮排查:直觉都在往大模型接口上引
说实话,面对一个 Agent 的 500,大多数工程师的第一反应都是:是不是大模型那边出问题了?我也不例外。
第一轮排查的三个动作,顺序也都是顺着这个思路来的:
2.1 先做模型接口自测
我们用的模型是走统一封装的 LLM Gateway,底层对接了 GPT 系列和国产模型。排查刚开始,我就先用 Python 脚本直接调了一下模型接口:
from openai import OpenAI client = OpenAI(base_url="http://llm-gateway.internal:8080/v1", api_key="sk-test-key") response = client.chat.completions.create( model="gpt-4o-mini", messages=[{"role": "user", "content": "你好,简单介绍一下你自己"}], timeout=15 ) print(response.choices[0].message.content)结果一切正常。模型接口能通,返回速度稳定在 1 到 2 秒,没有超时,也没有限流报错。我又拿同样环境的 session_id 去重放 Agent 请求,前置的模型调用竟然也是通的。这就很奇怪了,接口没挂,参数也传了,为什么线上就是 500?
于是我们把目光转向了网络层。
2.2 查网关和 DNS
Agent 服务和模型网关之间走的是内网 HTTP,跨了一个 Kubernetes 集群。我们查看了入口流量、出口流量、P95 延迟,都没有异常。K8s 里的 DNS 解析也正常,没有出现周期性的解析失败,Pod 日志没有任何规模性的连接重置错误。
这里我其实已经开始动摇,觉得问题可能不在“外部依赖”上,而是在我们自己的代码逻辑里。
但那阵子线上的 Agent 版本刚发过一个更新,涉及会话上下文的组装逻辑,所以大家倾向于相信:肯定是新版本把某个上下文搞坏了,不是入口问题。
2.3 翻会话上下文存储
这是第一轮排查里最后一个动作。我们去看 Redis 和 MySQL 里的 session 数据,确认会话有没有过期、被清理、或者序列化异常。
结果让人意外:全部正常。每个用户的会话数据都完整保存在 Redis 里,时间戳也对得上,上下文长度量级也合理。但诡异的是,无论怎么尝试,线上 Agent 的第一句话就是报 500,而本地和测试环境怎么复现都复现不出来。
这个“线上必现、本地必不现”的特征,恰恰说明问题是被某个环境参数或运行时状态触发的。敏感一点的人,这时候应该想到去看原始日志的完整字段,而不是只看错误码。
但我们没刹住车,直接滑向了第二轮排查。
3. 第二轮排查:怀疑链路追踪数据丢了吗
第一轮结束后,三个人开了一个简短的会。结论是:模型接口没问题,网络没问题,会话数据没问题,那么问题大概率出在 Agent 编排层内部的某个子调用上。我们需要一条完整的链路追踪来确认是哪一步崩了。
3.1 链路追踪为什么断了
我们的链路追踪用的是 OpenTelemetry,从 Agent 入口开始会生成一个 trace,然后每个子调用会生成对应的 span。正常情况下,通过 request_id 就能查到一个完整的链路拓扑,从入口到模型调用,到工具调用,到数据库访问,每一跳都有记录。
但我们查的时候发现,大量的请求 trace 是断裂的。只有入口这一个 span,下游所有调用全部查不到,像是一个 trace 只生成了第一个节点的数据,后面就“静默蒸发”了一样。
这就非常反常识了。因为我们的 Agent 编排逻辑里,只要请求进来了,一定会在子调用前创建 child span。除非……整个链路在还没走到创建下游 span 之前就已经崩溃了。
我们开始怀疑是不是 OpenTelemetry 的 SDK 出了兼容性问题,或者 Agent 框架升级之后 SDK 自动注入失效了。
排查到这里,我们浪费了不少时间在“质疑基础设施”上,但其实问题根源很简单:链路追踪依赖 request_id、session_id 等字段来串联上下文,如果入口日志里这些字段已经有缺失,那链路追踪的字段注入也一定会在上游就丢失。
一句话总结:链路追踪断了,不是因为追踪系统出问题,而是因为我们自己的入口参数没有打全,把追踪的“起点标识”弄丢了。
3.2 顺带查了 Agent 框架的编排日志
我们用的 Agent 编排框架是自研的轻量版本,内部有 step 级别的日志。正常情况下,每个 Agent 的执行步骤都会记录从“意图识别”到“工具选择”到“模型调用”的完整路径。
翻自研框架日志时,很快发现一个问题:所有报 500 的请求,都在第一步执行完之后直接退出了,第二步根本没进。退出时只有一个非常宽泛的异常提示:ERROR - pre-check failed。
当时看到这行日志,三个人面面相觑:“pre-check 是什么?”“谁写的这个异常?”“这个 check 什么时候加的?”然后去翻代码,发现 pre-check 是入口函数里一个非常不起眼的参数校验逻辑,写在调用 Agent 编排引擎之前。
这个 pre-check 校验的是 Agent 会话状态的完整性,最核心的一条就是 session_id 不能为空。如果为空,直接返回 500。
到这里,问题已经浮出水面了一半:我们会话 ID 居然为空。
3.3 为什么 session_id 会为空
这是第二轮排查结束前我们查的最后一个问题。session_id 为什么为空?到底是谁把 session_id 弄丢了?
回到代码逻辑,session_id 是前端在请求头里带过来的,后端从 header 里取出来之后,会放到一个上下文对象里。入口日志也是从同一个上下文对象里取的 session_id。
理论上来讲,如果前端的 session_id 是正常的,我们的入口日志不应该为空。
于是我查了网关的 access log,发现前端的请求头里session_id 是正常带的,没有任何丢失。那问题就出在我们后端把 session_id 塞到上下文对象的过程中。
这里出现了一个非常隐蔽的代码问题。我们有一个公共方法叫build_context(request),它负责从 HTTP 请求中提取所有公共参数,构建上下文。但某次重构时,有人在方法里多写了一个条件分支,导致 session_id 只有在“特殊内部调用”时才会被赋值,而来自外部 API 的请求走的是另一个分支,那个分支漏掉了 session_id。
这个问题的隐蔽程度极高,因为:
- 外部请求依然能进入 Agent 流程,因为 session_id 不是硬性鉴权条件;
- 入口日志里 session_id 为空,但其他字段正常,不容易引起注意;
- 测试环境复现时,因为我们习惯用内部调用方式触发 Agent,所以 session_id 会正常赋值,完全不会复现线上问题。
第二轮排查到这里,我们已经很确定 500 是 pre-check 拦截出来的。但还有最后一个关键问题没解决:为什么入口日志会少打一个参数?这不只是 session_id 为空的问题,而是入口日志本身在打印时丢了一个字段——这就是标题里说的“少打了一个参数”。
4. 第三轮排查:最终是日志参数缺失坑了我们
第二轮结束时,我们已经定位到 500 的直接原因是 pre-check 拦截,而根本原因正在指向会话上下文构建分支缺陷。但真正的“最后一根稻草”,是第三轮排查里对入口日志本身的逐字段核对。
4.1 日志的字段规格与实际输出完全对不上
我们回过头来,把正常请求的入口日志和异常请求的入口日志放在一起做了一次并排比对,注意,不是只看内容,而是逐个字段比对。
对比表长这样:
| 日志字段 | 正常值示例 | 异常期间值 | 备注 |
|---|---|---|---|
| request_id | req_a1b2c3 | req_d4e5f6 | 正常生成 |
| user_id | u_10086 | u_10086 | 正常 |
| session_id | s_20241111_001 | 空 | 缺失 |
| model | gpt-4o-mini | gpt-4o-mini | 正常 |
| prompt_preview | 帮我查账单 | 帮我查账单 | 正常 |
| trace_id | 00-abc-123 | 空 | 缺失 |
是的,不止 session_id 是空的,trace_id 也是空的。
到这里,我们才真正意识到问题不仅仅出在“会话上下文被清空”上,还出在“日志本身没有把调试所需的关键参数完整记录下来”。如果第一轮就做这样一个逐字段的日志完整性检查,大概二十秒就能看到 session_id 和 trace_id 的空值,也就不需要绕这么大一圈。
4.2 入口日志少了哪两个参数
细看代码之后,原因就非常清晰了。入口日志在打印时,从上下文对象里取字段,但上下文对象里有三个字段是延迟加载的,分别是 session_id、trace_id、request_id。request_id 是通过中间件先生成的,所以每次都有值;session_id 和 trace_id 则是在后续逻辑里才被补充进去的。
而入口日志打印语句是长这样写的:
logger.info( "agent entry log", extra={ "request_id": ctx.request_id, "user_id": ctx.user_id, "session_id": ctx.session_id or "", "trace_id": ctx.trace_id or "", "model": ctx.model, "prompt_preview": ctx.prompt_preview, } )看起来没什么问题对吧?但问题是,这个入口日志本身的调用时机,是在会话上下文构建之前。也就是说,日志打印的时候,ctx.session_id 和 ctx.trace_id 还没有被赋值,所以不管上下文构建逻辑是不是正常,入口日志里这两个字段都会输出为空。
换句话说:入口日志自身少打了两个参数,导致我们看到的日志数据“看起来一切正常”,但实际上缺失了最关键的两个调试字段。
这比“报错”更可怕。一个报错的日志会逼着你往下查,而一个字段缺失但不报错的日志,会让你误以为链路正常,从而把排查方向带偏。
4.3 修复方案:把日志打印时机后移 + 增加字段完整性检查
修复这件事,其实不复杂。我们做了两个改动。
第一个改动,是把入口日志的打印时机从“请求进入后立刻打”改成“上下文初始化完成后打”。改动后,打印日志时所有关键字段已经全部落位,不会再出现空值。
第二个改动,是加了一个名为“日志字段完整性校验”的轻量函数。每次打印入口日志时,会检查 session_id、trace_id、request_id 三个关键字段是否为空,如果为空,就额外再打一条 warning 日志,标题就叫entry_log_missing_critical_fields。
def validate_entry_log_fields(ctx): required_fields = ["session_id", "trace_id", "request_id"] missing = [f for f in required_fields if not getattr(ctx, f, None)] if missing: logger.warning( "entry_log_missing_critical_fields", extra={"missing_fields": missing, "request_id": ctx.request_id} )这个函数上线后,效果立竿见影。入参一旦缺失,告警会立刻出来,而不是让请求带着残缺字段一路往下走,直到下游莫名爆炸。
一个实际排查的教训:日志不只是给人看的,更是给机器看的。人在看日志时,会在潜意识里补全缺失的信息,但机器不会,下游框架不会,链路追踪系统不会。少打印一个字段,可能不会让日志“看着不对”,但会让整个排障链路少一条关键线索。
5. 三轮排查复盘:到底哪一步真正耽误了时间
这个 500 问题,从发现到修复上线,整个流程花了大概四个小时。其中真正修复代码的时间不到十分钟,剩下三个多小时全花在排查上。
我复盘了一下,最有价值的部分,是以下三点:
5.1 第一浪费点:凭直觉跳过了“基础字段检查”
做 Agent 开发的人,通常对模型层、编排层、工具层这些“高层逻辑”更敏感,反而容易忽略入口参数、日志格式这些“地基”。
第一轮排查时,我们三个人都默认入口日志是“可信的”,默认它记录全了字段,默认它不会出错。但事实恰恰相反,入口日志这一层,如果出了问题,影响的是全局可观测性,下游所有排查都会失去参照物。
建议是:凡是线上出现异常,第一步先做“入口数据体检”——把请求头、参数、日志字段全部拉出来,对照字段清单逐项检查,宁可慢五分钟,也不要跳过这一步直接往深处猜。
5.2 第二浪费点:链路追踪数据断链后没有第一时间反向追查
链路追踪断链本来是一个极强的信号,说明问题出在“创建 trace 的起点”之前。但我们当时把断链归因到了 SDK 或者基础设施,没有意识到是入口字段缺失导致的 root span 数据不全。
如果把“链路追踪断了”当成第一线索,而不是当成基础设施异常,那排查速度会快很多。链路追踪断链在大多数情况下不是基础设施问题,而是业务代码在创建 span 的时候丢失了上下文。
5.3 第三浪费点:本地无法复现问题,导致反复怀疑环境
本地和测试环境无法复现这个问题,其实是非常正常的事情。因为我们的测试链路全部走的是内部调用,session_id 会被主动注入,而线上外部请求却会被那个条件分支漏掉。
这个经验非常宝贵:当出现“线上必现、本地必不现”时,第一时间要怀疑“环境差异导致的分支行为”,而不是环境本身。正确的做法,是从线上原始日志中找到与本地日志的字段级差异,逐项比对,这往往比在本地尝试构造复现条件高效得多。
6. 排查 Agent 500 的实用方法论与工具配置参考
绕了这么一大圈,我把这次排查沉淀下来的方法论整体整理一下,方便以后遇到类似问题时直接照搬。
6.1 Agent 服务 500 排查动作顺序表
| 排查顺序 | 检查项 | 常见误区 | 验证方式 |
|---|---|---|---|
| 1 | 入口日志字段完整性 | 默认日志一定完整 | 逐字段核对,重点检查 request_id、trace_id、session_id |
| 2 | 网关原始请求 | 直接看业务日志 | 对比 access log 和业务日志中相同请求的字段 |
| 3 | 上下文构建分支 | 只看核心逻辑 | 检查条件分支是否覆盖全部调用来源 |
| 4 | 链路追踪数据完整性 | 怀疑 SDK/网络 | 查看 root span 生成时机和字段赋值顺序 |
| 5 | Agent 编排步骤日志 | 只看最终报错 | 检查“第一步正常、第二步未执行”的断点位置 |
| 6 | 模型接口/工具调用 | 优先怀疑外部依赖 | 通过独立脚本验证外部依赖可用性 |
6.2 日志规范配置参考
经历了这次事故,我重新整理了团队内部的入口日志规范,核心就三条:
第一,所有请求入口必须使用结构化日志,禁止裸打印字符串。结构化日志的好处是,字段缺失可以被程序自动检测,而不是靠人眼去扫。
第二,入口日志的打印时机必须放在所有上下文初始化完成之后,不能放在刚收到请求时。如果担心丢失最早的请求耗时数据,可以另外打一条“raw request received”的日志,但那条日志只能记录原始请求基本信息,不能作为排障主日志。
第三,每个日志字段都需要标注“是否关键字段”。关键字段缺失时,必须立即触发 warning 级别的告警,而不是静默继续。
下面是一个可以参考的 JSON 日志格式:
{ "level": "INFO", "logger": "agent_entry", "message": "entry request handled", "timestamp": "2025-01-18T16:30:01.123Z", "request_id": "req_a1b2c3", "session_id": "s_20241111_001", "trace_id": "00-abc-123", "user_id": "u_10086", "session_active": true, "model": "gpt-4o-mini", "prompt_preview_length": 18 }6.3 一个低成本的自检脚本
修复之后,我写了一个非常简单的小脚本,放在 CI 里跑,每次 Agent 服务发版前自动检查一遍日志代码的字段填充情况,逻辑非常简单:
import ast import sys required_fields = {"request_id", "session_id", "trace_id", "user_id"} for file in sys.argv[1:]: tree = ast.parse(open(file).read()) for node in ast.walk(tree): if isinstance(node, ast.Call): func = node.func if isinstance(func, ast.Attribute) and func.attr == "info": # 简单检查:extra 字典里是否包含关键字段 for kw in node.keywords: if kw.arg == "extra" and isinstance(kw.value, ast.Dict): keys = {k.value for k in kw.value.keys if isinstance(k, ast.Constant)} missing = required_fields - keys if missing: print(f"{file}: missing fields {missing}")这个静态检查工具当然不如运行时检测全面,但胜在成本极低,能在代码评审阶段就拦住大部分“日志字段遗漏”问题。
6.4 对 Agent 开发者的额外提醒
Agent 类应用和普通 Web 服务最大的不同是,它的链路更长,状态更多,上下文更复杂。一个请求从进入到返回,可能要经历意图识别、工具选择、多轮模型调用、外部 API 请求等多个节点,任何一个节点都有可能因为一个字段缺失而产生连锁失败。
在 Agent 项目里,入口日志和链路追踪不是“可选项”,而是“保命项”。如果你正在做一个 Agent 项目,我强烈建议你:
- 把所有关键参数用显式字段记录在结构化日志里,而不是只放在 message 文本里;
- 至少在入口、工具调用前、模型调用前、返回前四个节点各打一条日志;
- 对入口关键字段做运行时校验,缺失就立刻 warning;
- 每次发版都实际看一次线上日志样例,不要只看测试环境的日志。
这些事单独看起来都不难,但如果不做,下次出问题时,大概率又要三个人在周六下午对着一个半死不活的服务查三轮。
我的体会是:Agent 越复杂,越要花功夫把日志这些“地基”打扎实。这次准确找到 500 的根因,靠的不是什么高深技巧,而是在第三轮排查时老老实实坐下来,把每条日志的每个字段和每条链路的每个 span 都核对了一遍。排查线上问题,真正拼的不是聪明,而是谁先愿意回到最基础的地方,把最容易出错的那一层检查完。