上周二下午我们负责的 Agent 服务发了一个新版本。发布流程走到一半监控面板就红了新版本收到第一个请求后第一句话就返回 500。不是偶发不是单链路是绝大多数会话都建立不起来。我们三个人轮着查了三个多小时做了三轮排查最后发现根因小得有点搞笑——入口日志里少打了一个参数。这不是什么架构级事故也不是什么性能瓶颈但恰恰是这种“原因极小、影响面大”的故障最能暴露系统在可观测性上的短板。如果你在做 Agent、智能体网关、会话服务这类业务或者只是平时写接口喜欢随手打一行日志这篇复盘值得你看完。我会把三轮排查的完整思路、对比过的日志、代码变更里的盲区以及修复方案都摆出来尽量还原当时的真实过程。1. 事故现场Agent 第一句就 5001.1 “第一句就 500”意味着什么在 Agent 服务里“第一句就 500”是个很关键的信号。一条会话来了客户端发第一句话服务端需要做的事情包括解析请求、初始化会话上下文、拼接系统提示词、把消息组装成模型调用。如果这一步就失败说明会话初始化链路有硬伤。我当时的第一反应不是去看模型端而是直接在入口处找问题。因为如果是模型超时、内容审核拒绝那至少业务日志会往前多走几步不至于一路红到入口。一个请求在最前面就断掉大概率是服务端自身出了状况比如参数校验失败、依赖组件初始化异常、或者某个上下文为空。带着这个判断我们开始分配排查方向一个同事盯监控指标一个同事翻日志我去看最近的发布变更。1.2 应急动作摘流、保留现场、回滚面对这种问题我的建议是不要急着在线上死磕。先把新版本从流量入口摘下来留一台实例继续承接测试流量其余实例回滚到上一个正常版本。这一步操作看起来保守其实非常关键。摘流让线上不再持续产生错误请求回滚让大部分用户先恢复可用留一台异常实例则是给排查保留现场。故障发生后的黄金时间很宝贵但黄金时间的用途不是“边试边修”而是“有控制地观察、有依据地定位”。我们在一个可控的流量环境下反复触发问题才有机会拿到完整的日志和堆栈。很多人遇到线上问题第一反应是“赶紧改代码重新发布”但如果你连根因都没确认重新发布大概率只是再踩一次坑。回滚不是甩锅回滚是给自己留出从容排查的空间。1.3 三层链路先理清排查边界我们的 Agent 服务链路是客户端 → 流量网关 → Agent 服务 → 模型网关。三层日志各有侧重网关层记 HTTP 访问日志Agent 服务入口有自定义日志切面模型网关则记录模型调用明细。排查的时候我习惯先画一条链路标出每一层能看到什么、不能看到什么。比如流量网关能看到请求头、请求体、路径参数但看不到服务内部的业务状态Agent 服务日志能看到业务执行轨迹和异常堆栈但不一定记录原始报文模型网关能看到模型调用耗时和返回内容但和客户端原始请求之间的关联只靠 traceId。这个边界看着基础但这次事故第一次排查就跑偏正是因为忽略了它。我们盯着 Agent 服务日志看发现入口字段缺失后第一反应是“上游丢参数”差点就往网关方向查下去了。如果把链路边界先立好就能更快意识到入口日志缺字段只代表日志语句或上下文提取有问题不代表请求真的没有这个参数。2. 第一轮排查入口日志打了个“哑巴”2.1 打开日志先看到的不是堆栈我先打开新版本机器的 Agent 服务日志tail 了最近 5 分钟发现只有一行入口记录[2025-01-14 14:02:11.123] [INFO] [traceId3f8a9c] Agent request entry: traceId3f8a9c, userId10001, sessionIdsession-001, agentId{}这里划重点agentId{}。它不是空值也不是“null”而是日志模板里的占位符没有被替换成功。这是 logback 这类日志框架的默认行为模板里声明了 N 个占位符但实际传入的参数少于 N 个多出来的占位符就会原样打印出来。看到{}基本可以确定日志语句的参数个数和模板对不上。也就是说写日志的那行代码里模板写了 4 个字段但只传了 3 个参数。2.2 从日志能判断参数有没有进来吗严格来说不能。日志没打印 agentId只能说明打印语句这个环节出了问题并不能断定请求里没有 agentId。但第一轮排查的时候我们的直觉判断是“网关把参数丢了”。理由是 Agent 服务这边业务日志太干净只有一行入口记录后面没有任何会话初始化的日志看起来就像参数不全导致流程直接中断。加上 agentId 在入口日志里就是缺失的这种顺着日志往下推的思路很容易把责任推给上游。这个判断后来被证明是错的。教训是日志是记录的载体不是通路的证据。不能在入口日志缺一个字段的时候就默认上游请求也缺这个字段。日志格式异常和业务参数缺失完全是两个维度的故障。2.3 第一轮的临时缓解尝试在确认根因之前我们做过一个临时尝试在 Agent 服务新增一个极简的探活接口用控制变量法确认服务本身是活的。结果服务健康检查正常响应体返回的内容符合预期。这说明不是进程假死、不是资源耗尽、不是端口冲突而是业务逻辑在执行过程中主动中断了。这个探活动作虽然没有直接解决问题但帮我们排除了一个常见大类后面再排查时不用反复怀疑基础设施层。另外我们也确认了一下新版本的配置项数据库连接、缓存连接、模型网关地址都没有变化。排除了环境配置差异后我们把重点完全放在业务代码和日志切面这一层。3. 第二轮排查参数明明传进来了3.1 网关日志agentId 一直都在第二轮我去查流量网关的访问日志。结果很打脸原始请求里header 中带了一个完整的 agentIdbody 里也有同名字段。网关日志把请求头打印得很清楚那个参数从头到尾都在。具体来说请求长这样POST /v1/agent/chat Header: X-Agent-ID: agent-demo-001 Body: {sessionId:session-001,message:你好,userId:10001}agentId 清晰可见网关没有任何丢弃或改写的逻辑。于是问题从“网关丢参数”变成了“Agent 服务端为什么拿不到或者不打印”。这一步排查告诉我们要对账不要想当然。网关日志说传了服务端日志说没打到这两条信息必须放在一起对比而不是互相推断。我们当时把两个日志的时间戳对齐确认是同一个 traceId、同一个请求才敢下结论说参数确实到达了服务端所在的机器。3.2 链路追踪里的 span 对比我们在链路追踪平台上对比了网关到 Agent 服务的调用 span。请求的 header、query 参数、请求体快照都在agentId 依然清晰可见。这进一步确认参数在 HTTP 层面已经传到了 Agent 服务端。但有个细节很有意思。链路追踪展示的 span 标签里只有网关视角的 outbound 参数Agent 服务作为接收方它的 span 标签里却没有 agentId 这个字段。这说明 Agent 服务在接收请求后没有把 agentId 放进自己的链路追踪上下文。那它是怎么处理这个字段的只有一种可能入口代码在提取参数时压根没把 agentId 从请求对象里拿出来。否则哪怕不打印只要写进上下文链路追踪的 tag 列表里都应该能看到。3.3 在不起眼的日志尾部找到突破口第二轮排查接近尾声时我在 Agent 服务的完整日志文件末尾找到了真正的异常堆栈java.lang.IllegalStateException: agentId is required for session initialization at com.example.agent.session.SessionInitializer.initialize(SessionInitializer.java:58) at com.example.agent.session.SessionService.createSession(SessionService.java:34) at com.example.agent.controller.ChatController.chat(ChatController.java:71)虽然中间一堆业务日志没有打出来但异常堆栈暴露了关键信息有一个叫SessionInitializer的类在初始化会话时拿 agentId拿到的是 null。这个发现直接把问题范围缩小到了“参数提取与传递”这一个环节。agentId 在请求里有网关没有丢HTTP 层面也传到了服务端但服务端内部某个环节把它丢了。最有可能的就是入口处的日志切面或者参数解析器。4. 第三轮排查真凶是入口日志切面4.1 找到那段入口日志的代码顺着异常堆栈往上找我打开了 Agent 服务的入口日志切面AgentRequestLogAspect。代码简化后大概是这样的Component Aspect public class AgentRequestLogAspect { Around(annotation(agentLog)) public Object around(ProceedingJoinPoint joinPoint, AgentLog agentLog) { String traceId TraceContext.getTraceId(); String userId resolveUserId(); String sessionId resolveSessionId(); // 注意这里agentId 没有被提取也没有写入上下文 MapString, String context new HashMap(); context.put(traceId, traceId); context.put(userId, userId); context.put(sessionId, sessionId); LogContext.init(context); log.info(Agent request entry: traceId{}, userId{}, sessionId{}, agentId{}, traceId, userId, sessionId); // 模板有 4 个占位符参数只传了 3 个最后一个占位符原样打成了 {} return joinPoint.proceed(); } }这里有两个坑是同时埋下的第一个坑LogContext里没有放 agentId业务代码后面去取取出来是 null第二个坑日志模板里写了 4 个占位符实际只传了 3 个参数日志框架不报错只是把最后的{}原样打出来。从日志上看是“agentId 没有被打印”从业务上看是“agentId 为 null”两条线索指向同一个根因。我们当时看到这段代码第一反应是不可思议日志少打一个参数居然能让整个会话初始化挂掉。但后面追踪LogContext.getAgentId()的调用方答案就清楚了。4.2 为什么业务代码会去日志上下文里取参数这是整个事故里最值得反思的设计问题。之前某次改版中为了让入口日志和业务参数保持同一份来源我们把参数统一放进了LogContext。一些业务模块就不再自己从 request 里取参而是直接从LogContext里 get。举个例子SessionInitializer的初始化逻辑是这样的public void initialize() { String agentId LogContext.getAgentId(); if (agentId null) { throw new IllegalStateException(agentId is required for session initialization); } // 用 agentId 初始化会话 }这个改动本身不算坏问题在于它让“日志上下文”变成了“业务上下文”的硬依赖。日志切面少放一个字段业务模块就拿不到。日志打印和业务参数校验被绑定在同一个数据源上日志的一个小疏忽就会变成业务层的一次大故障。这种设计在平时不会出问题因为它要求所有开发者都记住“日志上下文里有哪些字段、业务模块要从哪里取参”。但人的记忆力是有限的尤其是重构切面、调整参数提取逻辑的时候很容易漏一个字段。漏了之后还不会立刻暴露直到线上某个业务流程真正用到这个参数才会炸出来。4.3 一行代码的修复方案修复很简单补上 agentId 的提取和写入String agentId resolveAgentId(); MapString, String context new HashMap(); context.put(traceId, traceId); context.put(userId, userId); context.put(sessionId, sessionId); context.put(agentId, agentId); // 补上的关键一行 LogContext.init(context); log.info(Agent request entry: traceId{}, userId{}, sessionId{}, agentId{}, traceId, userId, sessionId, agentId); // 参数个数与模板对齐改完之后先在本地用真实请求报文跑了一遍agentId 正常显示。再重新发布500 消失新会话的初始化也变得顺畅。当时我盯着这行代码心里挺五味杂陈的。查了三个多小时最后就是一行context.put(agentId, agentId)的事。但如果没有前面三轮的排查我们根本不知道要加这一行。这让我更相信一件事排障的价值不在最后改的那一行而在确认这一行就是根因的过程。4.4 防止同类问题日志模板的参数校验事故之后我们做了一个比较硬性的约束在单元测试里加一条规则把日志模板字符串里的占位符个数和实际参数个数做静态校验不合格直接挂掉。实现思路分两步。第一步自定义一个日志拦截工具扫描代码里所有log.info、log.warn、log.error的调用解析出模板字符串中的{}数量。第二步对比调用时的参数个数。如果模板占位符数量大于参数个数说明肯定有参数漏传测试直接失败。这个规则本身很简单但能把“少打一个参数”这类问题在 CI 阶段就拦住不用等线上暴雷。我们后来也扫描了历史代码还真又揪出来三四处占位符和参数对不上的日志语句都是之前没触发故障但一直潜伏着的隐患。5. 复盘为什么“日志少打一个参数”能引发 5005.1 日志上下文不能充当业务参数源我现在的建议是日志上下文和业务上下文一定要分开。日志切面负责记录业务层负责从请求对象或专门的参数对象里取参。两者如果共用一个 Context日志字段就变成了业务字段日志有一点小疏忽业务就可能挂。我们后来的做法是LogContext只做日志和链路追踪的字段承载专门打印用的业务参数全部在入口处统一解析成RequestContext业务模块从RequestContext里取参。两个 Context 各司其职互不依赖。这样即使日志打印漏了一个字段最多是日志少了信息不会影响业务逻辑。但从另外一个角度说如果日志上下文都乱了排障信息也会跟着失真。所以两个 Context 分离不是说日志可以随便写该有的参数对齐校验还是要做。5.2 参数缺失的连锁反应模型这次故障的完整反应链是这样的一个请求带着 agentId 进来 → 入口切面提取参数时漏了 agentId →LogContext里没有 agentId →SessionInitializer从LogContext取 agentId 得到 null → 抛出IllegalStateException→ 框架统一转成 500 响应。这条链路上的每一个环节单看都不致命但串联起来就是一次大面积故障。这也解释了为什么排查耗时那么长每一层看到的都是“别人的错”。看入口日志像是网关丢参数看网关日志像是服务端没接收看服务端异常堆栈才知道是上下文里取到 null再追上下文写入逻辑最终才定位到日志切面少放了一个字段。如果一开始就沿着“参数最终从哪里被消费”这个方向去追可能会快一些但当时现场的紧张感确实影响了判断节奏。5.3 故障复盘后确定的日志规范复盘之后我们实际落地了几条日志规范日志模板占位符必须与参数个数一致用单测保证不允许跳过。关键业务字段不要只写在日志里业务模块必须通过显式接口获取来源避免从日志上下文隐式读取。线上日志缺失字段时优先检查日志语句本身再排查上游链路顺序不能反。异常日志不仅要打堆栈最好把当前请求的关键 requestId、sessionId、agentId 一并打印方便排障时直接关联。入口日志的字段清单要固定每次改动都需要评审不能随意增删。这些规范没有一条是新发明但每条都是用这次故障换来的。6. 常见问题速查与排查技巧6.1 常见问题速查表现象可能原因排查建议入口日志出现{}占位符原样输出日志模板参数缺失占位符和参数个数对不上检查日志语句的参数个数与模板占位符逐一比对日志字段缺失但上游请求有该字段服务端参数提取或上下文写入遗漏检查入口切面、Filter、拦截器确认字段是否写入上下文业务日志没有输出直接出现异常堆栈入口日志到业务日志之间存在断点可能是上下文初始化失败从异常堆栈倒推找到最早抛错的位置链路追踪显示参数存在业务日志取不到参数没有写入业务可见的上下文或者写入后被清空检查参数写入逻辑、上下文生命周期、异步线程传递逻辑部分请求成功部分请求 500参数来源不统一某些渠道带了参数某些没带对比不同渠道的请求报文检查参数解析的兼容性6.2 排障方法三层递进这次事故之后我总结了一个三层递进的排障方法用来处理“看起来哪都正常但就是报错”的问题。第一层先看日志本身有没有字段、参数全不全。这一步最容易被忽略因为大家默认日志是可信的。但日志本身可能出错占位符错漏、字段被吞掉、上下文没写入都会让日志失真。第二层再确认参数到底有没有传进来。靠网关日志和链路追踪把请求的原文捞出来和服务端接收到的信息做对账。这一层的核心是区分“没打印”和“没传进来”两种情况的排查方向完全不同。第三层最后对比代码变更用 git diff 检查最近改了什么。很多时候问题就藏在一次看似无关紧要的重构里。我们这次就是靠 review 最近一次切面改动才找到了漏掉的 agentId。三层走完90% 的“诡异故障”都能落地。6.3 一点实操心得我印象很深的是这次排查里真正起决定作用的不是某个高深工具而是“把日志模板占位符和参数个数对一遍”这个近乎笨拙的动作。很多线上问题不是高并发、不是复杂算法就是一个小参数没接上。在 Agent 这类新业务里链路长、模块多入口参数很容易在某一环被漏掉。尤其是重构入口逻辑的时候字段的增删往往不会立刻暴露问题要等到下游真正消费它才会引爆。我的建议是每次改动涉及参数提取时都拿真实报文在本地走一遍日志里每个字段都检查一遍有没有占位符错漏。这个过程虽然不刺激但非常有效。如果你也遇到过类似的“哪都看了就是找不到原因”的问题不妨先回头看看自己打的那行日志占位符对上了吗字段真的提取到了吗有时候最笨的检查反而是最快的出路。
