Agent 500故障复盘：入口日志少打一个参数拖垮整条链路

那天晚上九点我们这套 Agent 平台第一次跑通真实会话链路。前端同学在预览页面敲了一行“你好”回车几秒钟后页面弹出“服务内部错误”控制台里 HTTP 状态码 500 格外刺眼。更扎心的是这是平台接到的第一句用户消息第一句就 500连个缓冲的机会都没给。我在现场盯着监控面板错误曲线直接从零拉成一条红线。团队花了三个晚上排查了整整三轮最后定位出来的根因居然是一行日志代码的问题入口日志少打了一个参数。而那个被漏掉的参数恰好决定了 Agent 的模型路由走向——因为日志里看不到它我们一度以为是鉴权、超时、甚至模型网关的问题绕了一大圈才回到起点。这篇内容会把这次故障的完整过程、排查思路、修复方案以及后续日志规范改造一起整理出来。无论你是在做 Agent 接入、API 网关、还是日常服务端排障这个案例都值得花几分钟过一遍尤其是那些只打“failed”不打参数的日志真的太坑了。1. 故障现场先复盘一下1.1 一个“你好”把 Agent 干成 500先说下这套 Agent 平台的定位。它解决的是企业内部多轮问答场景用户进来之后先做会话初始化系统为这个用户创建上下文并根据配置决定当前会话默认调用哪条模型路由。首句“你好”看着简单但它恰好必经最完整的链路HTTP 入口、鉴权、会话初始化、模型路由、模型网关任何一个环节不支持第一句话就会挂。我们当时是从监控面板看到一条扩大的错误曲线点进 top 错误入口服务返回 500。团队第一反应是怀疑模型网关或者鉴权模块毕竟新老系统对接时最容易出问题的就是鉴权参数没对齐比如某个 header 字段名大小写不一致、token 过期之类的。但我们顺着这个方向查了很久毫无进展方向完全猜反了。现在回头看首句 500 本质上有两类原因一类是链路本身对新会话不兼容比如初始化依赖的配置缺失、路由映射没建好另一类是入口层的通用问题比如参数解析、鉴权、超时等。第一类往往更隐蔽因为它不会在网关层立刻暴露要深入下游才能看到。这次就是典型的“链路深层配置缺失”问题。1.2 排障本质500 排查就是把“出错现场”找回来排 500 其实就三件事先找到第一个抛异常的服务再拿到异常堆栈和出错的入参最后修复并回归。不管中间用了多少监控工具最终依赖的核心物料只有一个——日志。日志里有没有参数决定你是按图索骥还是大海捞针。这次故障里入口日志少打的那个参数恰恰是关键入参。它一缺失我们第一轮就陷入被动。用生活里的场景类比日志就像行车记录仪没拍下车牌号你再怎么回放视频也查不到肇事车。入口日志缺了 modelRoute 这个参数等于记录仪没拍到最关键的一帧画面。另外要补充一个经验Agent 类服务通常至少分三层接入层负责对外协议转换编排层负责会话状态和任务调度执行层负责调模型或工具。每层之间通过内部 RPC 传递参数链路跨度长参数名在不同服务里还可能不一样。这种架构下日志字段的完整度直接决定排障效率因为它就是你回溯整条链路时唯一的“共同语言”。2. 三轮排查实录2.1 第一轮翻入口日志看到的是“阉割版”信息第一轮排查从入口服务开始。为什么先看入口因为 500 是入口层抛给用户的入口日志理论上会记录完整调用结果。我们打开日志平台按关键字一搜出来的内容大致长这样2025-06-17 14:03:11.231 ERROR 12888 [http-nio-8080-exec-3] c.a.gateway.AgentGateway : call session init failed, internal error就一行。没有请求路径没有用户 ID没有会话 ID没有 traceId更没有异常堆栈。看到这个日志的第一感觉是这日志跟没打差不多。我马上翻了入口服务里对应的 catch 代码发现它用的是手拼字符串的方式大概长这样// 某入口服务的 catch 片段示意 log.error(call session init failed, internal error);既没传异常对象也没带任何 request 字段。当时我第一反应是怀疑框架层是不是有个全局异常拦截器把堆栈吞了结果查完发现不是拦截器的问题是业务代码的 catch 块本身就把信息截断了。这种情况在实际代码里相当常见尤其是复制粘贴老代码后稍作修改的时候日志字段常常被顺手精简掉。这一轮能得出的结论只有一个500 确实发生在“会话初始化”这段调用之后。但具体是初始化服务的参数问题、超时问题还是下游模型路由的问题完全看不出来只能进入第二轮。2.2 第二轮靠链路追踪锁定“下游某一段”但参数对不上第一轮没有收获我们上了第二招全链路追踪。链路追踪平台理论上能记录一次请求经过了哪些节点每个节点耗时多少哪个节点失败。我们按时间窗筛出了一批失败请求链路数据的走向很清晰入口服务 → 会话初始化服务 → 模型路由服务 → 模型网关然后断在模型网关。到这里边界已经锁死了问题出在模型路由服务或模型网关。但当我们想进一步看具体入参时问题又来了。链路追踪平台只展示了“调用了哪个方法、有没有异常”它并不保存每次调用的完整业务参数。想要确认是不是某个参数不对必须回业务日志里翻。而这一翻又翻到坑里了。模型路由服务的日志里确实打印了接收参数但只打出了 modelRoute 这种显示没有 uid、没有会话 ID入口服务的日志里又没有 modelRoute。两边日志用同一个时间窗去比对还不能用 ID 精确关联只能靠“这个时间点大概就是这个请求”这种模糊推断。这个阶段特别耗时间相当于每一条候选请求都要肉眼去匹配。说实话走到这里我们已经大概率猜出是参数传递出了问题但传丢了哪个参数、在哪一环丢的还没有确凿证据。这也暴露了链路追踪的一个局限它擅长回答“哪一段调用失败”但不擅长回答“失败时的入参是什么”。后者只能靠业务日志补全如果业务日志本身缺参数追踪系统也帮不上忙。2.3 第三轮补日志复现发现模板有三个占位符却只传了俩变量第三轮我们决定不猜了直接在代码里加日志带完整参数现场重新发一次“你好”。加完日志重新部署再请求一次这次路子清晰多了。模型路由服务打出了异常unknown model route。模型网关返回 500原因是它根据路由标识查不到对应的模型配置。但模型路由服务里打印的路由标识是一个空字符串所以问题不在模型网关本身而是上游传过来的 modelRoute 是空值。再往上游看会话初始化服务的问题终于浮现它调用下游构造 request 的时候把从配置中心读到的 modelRoute 传给了下游。而配置中心那个 key 本身没有配置读出来就是一个空字符串。到这里根因基本清楚了但还有一个细节让所有人都愣住了会话初始化服务在 catch 块里记录日志时模板和变量对不上。// 修复前模板里有 3 个占位符实际只传了 2 个变量modelRoute 直接丢失 log.error(session init failed, uid{}, conversationId{}, modelRoute{}, uid, conversationId); // 修复后补上 modelRoute log.error(session init failed, uid{}, conversationId{}, modelRoute{}, uid, conversationId, modelRoute);模板里写了 modelRoute 这个占位符但变量列表里根本没传它。在一些日志框架的默认配置下模板和变量对不上不会报错输出结果会把 modelRoute 的位置原样打成模板字面量或者直接丢掉。所以日常日志里我们根本看不到 modelRoute 的真实值也就无从未判断这个参数是不是罪魁祸首。这就是标题里那句“入口日志少打了一个参数”的完整含义。严格说入口和会话初始化两个服务都打了缩水日志而会话初始化服务少打的恰恰是最核心的 modelRoute。因为少了它第一轮和第二轮我们看到的都是一个被隐藏了空值的空壳日志直到把它补出来才发现它是个空字符串这才一路查到配置中心。3. 为什么一个空值能把整条链路弄挂3.1 参数在链路里的真实流向从用户输入“你好”到拿到 500 响应参数是这样一步步流转的客户端请求进入 API 网关带 uid 和 token入口服务从 HTTP header 中解析 uid从 body 中取 message调用会话初始化服务会话初始化服务按 uid 去配置中心取“默认模型路由”配置这个键没有配置返回空字符串会话初始化服务把空字符串作为 modelRoute 通过 RPC 传给模型路由服务模型路由服务拿空字符串去查模型 provider 映射表查不到抛出 unknown model route模型网关把这个未知路由包装成 500 错误码返回入口层原样透传用户最终看到 500。可以看到断点出现在第三步和第五步之间。但从日志角度断点前面的第三步日志没有 modelRoute 字段断点后面的第五步日志又没有 uid两段日志就像两张拍不到对方特征的拼图硬是拼不起来。如果第三方的日志当时打了 modelRoute哪怕只是打出一个空字符串我们第一轮就能顺着它直接查配置中心根本不用折腾三轮。3.2 空字符串和 null 在 RPC 里的隐蔽性这里还有个特别坑的细节配置中心读不到键时很多 SDK 默认返回 null但经过一次 RPC 序列化后null 会被转成空字符串。而空字符串在日志里看起来就像“有值但内容为空”很容易被一眼带过。如果日志没有打印这个字段那连被带过的机会都没有完全隐身。这也是为什么这类问题很难快速定位它的表象是 500但根因是配置缺失加日志参数缺打两个问题叠加成了一个刁钻故障。单看任何一个环节都不至于花三个晚上但两个问题前后脚出现就把排查路径拉长了好几倍。另外还要提醒一点有些代码里对配置值的处理过于乐观拿过来就用不做空值兜底。配置中心不是每个 key 都有人保证提前配好越是这种动态下发的配置越要在代码里加默认值。否则一个 key 的遗漏就能把整条 Agent 链路打挂而且报错位置离配置读取点隔了三个服务定位成本极其高。3.3 “日志精简”的坑为什么防不胜防复盘下来这次故障暴露了四个容易被忽略的隐患日志模板占位符和实际传参数量不匹配编译器不报错运行期也不会立刻暴露只有靠人眼逐条核对才能发现全局异常拦截器会把所有未知异常统一包装成 500堆栈被隔离在拦截器内部业务日志里只剩下一个状态码链路追踪平台只定位调用边界不保存业务入参边界定位之后仍然要回到业务日志里找参数多个服务之间对同一个参数用了不同名称route、modelRoute、model_route、modelRouter 混在一起日志检索时很难用同一个关键字拉出完整链路。这几类问题单看都不难但叠加在一起确实能拖垮一个晚上的排障进度。我们真实花在定位上的时间大概四个小时其中一半都用在了比对缺失的参数上。如果入口日志一开始就把 modelRoute 打出来从发现 500 到定位配置缺失可能只需要十分钟。4. 修复方案和日志规范改造4.1 第一时间补上代码和配置定位到根因之后修复分三步进行。第一步补全会话初始化服务的日志参数把模板和变量一一对应。这一步很简单但效果立竿见影之后任何 modelRoute 异常都能在日志里直接看到值。// 修复后完整打印 uid、会话 ID、模型路由和链路 ID log.error(session init failed, uid{}, conversationId{}, modelRoute{}, traceId{}, uid, conversationId, modelRoute, traceId);第二步给配置读取加默认值兜底不能允许空字符串进入路由。我们配置中心的键补上了默认模型路由同时在代码里加了 fallbackString defaultModelRoute configCenter.get(agent.default.model.route, default_llm); if (StringUtils.isBlank(defaultModelRoute)) { defaultModelRoute default_llm; }第三步在模型路由服务入口加参数校验modelRoute 为空时直接抛业务异常返回明确的错误码而不是等它穿透到模型网关再被转成 500。if (StringUtils.isBlank(request.getModelRoute())) { throw new BizException(StatusCode.MODEL_ROUTE_NOT_FOUND, model route is blank); }这样改造之后同类故障再发生时日志里可以立刻看到 modelRoute 的真实值如果它是空也会在路由服务这一层直接以明确的业务错误码暴露而不是伪装成服务内部错误。这一点很重要500 是“服务内部错误”的笼统表达它掩盖了真正的问题类型而业务错误码能让排查者第一时间知道是参数、配置还是依赖问题。4.2 核心入口日志必须带哪些字段吃过这次亏我把团队日志规范里的“最小字段集”重新列了一遍凡是 Agent 类服务的核心入口日志至少包含下面这些字段。字段含义是否必须uid用户标识必须conversationId会话标识必须modelRoute模型路由标识必须traceId链路 ID必须requestPath请求路径建议costMs接口耗时建议requestBodySummary请求体摘要脱敏建议关键的一条铁律是错误日志必须打印异常堆栈。所有 catch 到异常的地方第一个参数传日志消息最后一个参数传异常对象中间按顺序补业务字段。宁可多打几 KB 日志也不能在出错时只留下一句“failed”。因为堆栈里有异常发生的确切代码行号有调用链信息往往看到堆栈的瞬间就定位了一半问题。这里顺便说一句脱敏请求体摘要里不要出现完整的 token、密钥、明文密码这类信息但像会话 ID、用户 ID 这类用于关联请求的标识必须原样保留。脱敏的范围和保留的范围要提前定义清楚不能用“日志就打个信息都没了”来应付。4.3 日志模板与变量数的自动化校验光靠人工记性是不够的。这次故障之后我们给代码评审和发布流程里加了两道自动化的检查。第一道用静态扫描脚本检查项目里的日志语句提取模板里的占位符数量和实际变量数量不一致的当场标红禁止合并。技术实现上很简单正则匹配加 AST 解析都可以关键是把它接进流水线里成为硬性门禁。这一步成本极低但对这类 bug 的拦截率几乎是百分之百。第二道在入口和关键中转服务上强制使用自定义日志切面把请求入参摘要、响应状态、耗时、traceId 统一打印业务代码里不再允许手拼日志消息。切面打印的字段由平台侧统一维护只要新服务接了规范日志字段就不会缺。这样也从源头避免了“忘了传参”这类问题因为参数收集是框架统一做的不是靠每个开发者手动写。5. 排障笔记和个人体会5.1 Agent 类服务 500 排查的黄金步骤给所有做服务端开发和运维的同学一个可复用的排查顺序先看监控趋势图和 top 错误确认 500 集中在哪个时间窗、哪个服务打开入口服务日志搜状态码附近的错误日志先看有没有异常堆栈没堆栈就找全局异常拦截器看是不是它把异常吞了有堆栈就直接定位到具体异常类名在代码里找到抛出位置用链路追踪平台确认一次请求完整经过的服务节点锁定第一个出错的服务对比出入口日志和下游日志中的关键参数确认参数是否在传递过程中丢失或变形如果日志字段缺失立刻现场补打印并复现不要依赖猜。这套顺序的核心思想是先用监控和链路追踪缩小范围再用日志参数做精确定位。缩小范围和精确定位是两个步骤不能混在一起。很多人习惯一上来就翻代码找异常类但如果不知道请求具体走到哪个服务翻代码就像在图书馆里不查索引直接找一本书。5.2 日志打点自查清单我按照踩过的所有坑整理了一份清单每次上线上新 Agent 服务前过一遍所有 catch 块是否都打印了异常对象保留堆栈日志模板占位符数量是否与实际变量一致入口服务是否打印请求路径、用户标识、会话标识和路由标识错误日志是否包含 traceId 并能被日志平台检索配置中心读出来的 key 是否有默认值兜底是否对请求参数做了脱敏处理模型路由等核心参数是否加了非空校验。这份清单看起来简单但每一条背后都是一次线上事故的教训。我个人的经验是日志多打一个字段可能只需要半分钟但缺这个字段故障恢复时间轻则增加一到两小时重则整个晚上通宵。尤其像 Agent 这种多跳转的链路每一跳日志都是破案线索少一条线索后续所有排查都会绕远路。5.3 最后想多说一句这次故障过后我对检查日志的态度完全变了。以前写代码时日志往往是最容易被忽略的部分功能跑通就算完事。现在我会把日志字段当成接口契约的一部分来看待日志不只是给开发看的过程记录更是未来线上出问题时的第一手证据。把证据链建完整排障就是按图索骥证据链断了再强的监控工具也救不了你。如果你也正在维护 Agent 类服务不妨现在就翻一眼入口日志看看里面有没有把 modelRoute、uid、conversationId 这些关键字段打全。没打全的趁现在补上别等下一次 500 找上门。