日志少打一个参数，为何引发Agent服务大面积500？

上周二下午，我们负责的 Agent 服务发了一个新版本。发布流程走到一半，监控面板就红了：新版本收到第一个请求后，第一句话就返回 500。不是偶发，不是单链路，是绝大多数会话都建立不起来。我们三个人轮着查了三个多小时，做了三轮排查，最后发现根因小得有点搞笑——入口日志里少打了一个参数。

这不是什么架构级事故，也不是什么性能瓶颈，但恰恰是这种“原因极小、影响面大”的故障，最能暴露系统在可观测性上的短板。如果你在做 Agent、智能体网关、会话服务这类业务，或者只是平时写接口喜欢随手打一行日志，这篇复盘值得你看完。我会把三轮排查的完整思路、对比过的日志、代码变更里的盲区以及修复方案都摆出来，尽量还原当时的真实过程。

1. 事故现场：Agent 第一句就 500

1.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] [traceId=3f8a9c] Agent request entry: traceId=3f8a9c, userId=10001, sessionId=session-001, agentId={}

这里划重点：agentId={}。它不是空值，也不是“null”，而是日志模板里的占位符没有被替换成功。

这是 logback 这类日志框架的默认行为：模板里声明了 N 个占位符，但实际传入的参数少于 N 个，多出来的占位符就会原样打印出来。看到{}，基本可以确定日志语句的参数个数和模板对不上。也就是说，写日志的那行代码里，模板写了 4 个字段，但只传了 3 个参数。

2.2 从日志能判断参数有没有进来吗

严格来说，不能。日志没打印 agentId，只能说明打印语句这个环节出了问题，并不能断定请求里没有 agentId。

但第一轮排查的时候，我们的直觉判断是“网关把参数丢了”。理由是 Agent 服务这边业务日志太干净，只有一行入口记录，后面没有任何会话初始化的日志，看起来就像参数不全导致流程直接中断。加上 agentId 在入口日志里就是缺失的，这种顺着日志往下推的思路，很容易把责任推给上游。

这个判断后来被证明是错的。教训是：日志是记录的载体，不是通路的证据。不能在入口日志缺一个字段的时候，就默认上游请求也缺这个字段。日志格式异常和业务参数缺失，完全是两个维度的故障。

2.3 第一轮的临时缓解尝试

在确认根因之前，我们做过一个临时尝试：在 Agent 服务新增一个极简的探活接口，用控制变量法确认服务本身是活的。

结果服务健康检查正常，响应体返回的内容符合预期。这说明不是进程假死、不是资源耗尽、不是端口冲突，而是业务逻辑在执行过程中主动中断了。这个探活动作虽然没有直接解决问题，但帮我们排除了一个常见大类，后面再排查时不用反复怀疑基础设施层。

另外我们也确认了一下新版本的配置项：数据库连接、缓存连接、模型网关地址都没有变化。排除了环境配置差异后，我们把重点完全放在业务代码和日志切面这一层。

3. 第二轮排查：参数明明传进来了

3.1 网关日志：agentId 一直都在

第二轮，我去查流量网关的访问日志。结果很打脸：原始请求里，header 中带了一个完整的 agentId，body 里也有同名字段。网关日志把请求头打印得很清楚，那个参数从头到尾都在。

具体来说，请求长这样：

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 没有被提取，也没有写入上下文 Map<String, 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(); Map<String, 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. 复盘：为什么“日志少打一个参数”能引发 500

5.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 常见问题速查表

6.2 排障方法：三层递进

这次事故之后，我总结了一个三层递进的排障方法，用来处理“看起来哪都正常但就是报错”的问题。

第一层，先看日志本身有没有字段、参数全不全。这一步最容易被忽略，因为大家默认日志是可信的。但日志本身可能出错，占位符错漏、字段被吞掉、上下文没写入，都会让日志失真。

第二层，再确认参数到底有没有传进来。靠网关日志和链路追踪，把请求的原文捞出来，和服务端接收到的信息做对账。这一层的核心是区分“没打印”和“没传进来”，两种情况的排查方向完全不同。

第三层，最后对比代码变更，用 git diff 检查最近改了什么。很多时候问题就藏在一次看似无关紧要的重构里。我们这次就是靠 review 最近一次切面改动才找到了漏掉的 agentId。三层走完，90% 的“诡异故障”都能落地。

6.3 一点实操心得

我印象很深的是，这次排查里真正起决定作用的不是某个高深工具，而是“把日志模板占位符和参数个数对一遍”这个近乎笨拙的动作。

很多线上问题不是高并发、不是复杂算法，就是一个小参数没接上。在 Agent 这类新业务里，链路长、模块多，入口参数很容易在某一环被漏掉。尤其是重构入口逻辑的时候，字段的增删往往不会立刻暴露问题，要等到下游真正消费它才会引爆。

我的建议是：每次改动涉及参数提取时，都拿真实报文在本地走一遍，日志里每个字段都检查一遍有没有占位符错漏。这个过程虽然不刺激，但非常有效。如果你也遇到过类似的“哪都看了就是找不到原因”的问题，不妨先回头看看自己打的那行日志：占位符对上了吗？字段真的提取到了吗？有时候，最笨的检查反而是最快的出路。