这是一次真实的生产事故排查记录。我们的[多模态识图](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E5%A4%9A%E6%A8%A1%E6%80%81%E8%AF%86%E5%9B%BE&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLlpJrmqKHmgIHor4blm74iLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.WvBJgeYQR8DKRABys3EXlx7BsfxCnpd0M69s2sd7cyo&zhida_source=entity)服务跑在海光 DCU 八卡集群上（8 个 vLLM 实例 + 自研反向代理统一入口），业务方接入了生产流量。某天业务方反馈「结果尾部全是截断的」，我们自测一切正常——但深挖之后发现的真相比截断严重得多：**业务方的请求 100% 返回 400，一张图都没处理成功，而这个状态已经持续了一整天**。 100% 失败的服务，为什么我们自测全绿？为什么业务方只抱怨了「截断」这种小问题？为什么最初的统计还得出过「69% 成功率」的错误结论？这篇完整还原排查链路——每一层的判断依据都是真实日志，方法可以直接迁移到任何「服务方说好的、调用方说坏了」的争议现场。 ## 背景：服务形态与可观测性 先交代事故现场的架构，因为后面每一步排查都依赖它： ```text 业务方(.130) ──→ 反向代理(:8000, 最少连接) ──→ vLLM × 8 (:8002–8009, 各占一张 DCU) ``` 代理层有一条结果日志，每个请求记一行： ```text 08-24 06:41:02 orid=anonymous 127.0.0.1:8004 status=400 req_keys=['chat_template_kwargs', 'max_tokens','messages','model','stream','temperature','user'] mt=1024 thinking=False ERR_BODY | {"error":{"message":"cannot identify image file ...","type":"BadRequestError","code":400}} ``` 关键字段：`orid`（业务请求追踪 ID，从请求体的 `user` 字段提取）、`status`、`req_keys`（请求带了哪些顶层字段）、`ERR_BODY`（**后端返回的错误正文原文**）。这些字段不是一开始就有的——其中 `ERR_BODY` 正是这次事故逼出来的，后面会讲。 ## 第一层误判：69% 成功率，一个错误的分母 排查的起点是业务方的一句反馈：「返回结果尾部全是 `finish_reason=length`（截断）」。 我们拉出代理日志做统计：全天请求里，约 69% 返回 200，31% 返回 400。第一反应是「大部分成功，小部分失败，失败率和截断率对得上」——**这个结论错了**。 错在分母。那 69% 的 200 里，绝大部分是我们自己的冒烟自测（`orid=ORD-1001` 这类测试 ID，全天只有 3 个 distinct），业务方的真实请求（`orid` 是一串数字 ID）几乎全在 400 那一边。把自测流量和业务流量混在一个池子里算比率，得出的「服务基本正常」是个统计幻觉。 **教训一：做成功率统计前，先把「谁的请求」分开。** 自测请求证明的是「服务还活着」，业务请求的成功率才是服务真正的成绩单——两者混算，等于用自己抄的卷子给学生的考试打分。 ## 第二层：orid [交集分析](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E4%BA%A4%E9%9B%86%E5%88%86%E6%9E%90&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLkuqTpm4bliIbmnpAiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.g10fOArL6lD51AmsXsZRfEJGbkmpXiuwr2teELpRZqc&zhida_source=entity)，钉死「100% 失败」 把日志按来源拆开后，事实浮出水面： | | 200 的请求 | 400 的请求 | | ------------- | ------------------ | --------------------------- | | orid 特征 | ORD-1001 等自测 ID | 数字 ID（业务方每张图一个） | | distinct 数量 | 3 | 905（905 张不同的图） | | 来源 | 本机自测脚本 | 业务方 .130 | 两个集合的 orid **交集为零**——905 张图，没有一张成功。业务方实际是 100% 失败。 这里有个值得玩味的细节：为什么业务方只抱怨「截断」，没抱怨「全挂」？因为他们的代码把 400 当成了「处理失败但流程继续」，批量跑完后只看得到少量带 `length` 截断的正常结果（那些其实是早期接入[联调](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E8%81%94%E8%B0%83&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLogZTosIMiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.HaD2bEs2t91VkyEMeF0-KvytRywAS2vAizqz-CNSjdE&zhida_source=entity)时成功过的存量），错误被吞在他们的日志里。**调用方不报错，不代表没有错**——这在集成场景里太常见了。 ## 第三层：ERR\_BODY——错误正文必须由代理抓 定位到「业务方 100% 400」后，下一个问题是：**vLLM 为什么拒绝这些请求？** 第一反应去翻 vLLM（uvicorn）的 access 日志——只有一行 `400 Bad Request`，没有正文。vLLM 的访问日志只记状态码不记 body，而 400 的具体原因恰恰在 body 里。这一步卡住时，我们的怀疑清单有三个： 1. `model` 字段的模型名和服务端不一致？ 2. 业务方把 `enable_thinking` 放在了顶层，服务端不认？ 3. 图片不是合法 base64（或 URL 拉取失败）？ 与其逐个猜，不如让证据自己说话：**在[代理层](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=2&q=%E4%BB%A3%E7%90%86%E5%B1%82&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLku6PnkIblsYIiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MiwiemRfdG9rZW4iOm51bGx9.w-9pMdK7CBApjnL_TuxlUxFoXt3En9SL2QKMuByRcwY&zhida_source=entity)加****`ERR_BODY`捕获**——转发时把后端响应的前若干 KB 缓下来，非 200 就把错误正文完整记进结果日志。重新放量后，第一条 400 的错误正文就把真相拍在了桌上： ```text {"error": {"message": "... loc = ('body', 'user')", "msg": "Input should be a valid string", "input": 905112, "type": "Input should be a valid string"}} ``` **教训二：链路上每一跳的日志都要能回答「这个请求具体怎么了」。** 状态码只告诉你死没死，body 才告诉你怎么死的。后端不给，就在代理层抓——这是代理存在的意义之一。 ## 真因：一个整型 `user` 字段 根因极其朴素：业务方把每张图的业务 ID（一串数字）**当作整数**塞进了请求体的 `user` 字段： ```text # 业务方的写法 payload["user"] = 905112 # ❌ 整数 # 正确的写法 payload["user"] = str(905112) # ✅ 字符串 ``` OpenAI 兼容 API 的规范里 `user` 是 string 类型，vLLM 用 [Pydantic](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=Pydantic&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiJQeWRhbnRpYyIsInpoaWRhX3NvdXJjZSI6ImVudGl0eSIsImNvbnRlbnRfaWQiOjI4MjE2MzcyOCwiY29udGVudF90eXBlIjoiQXJ0aWNsZSIsIm1hdGNoX29yZGVyIjoxLCJ6ZF90b2tlbiI6bnVsbH0.Izr4zirwyJ_aTdjyoG1GCPJKzC-1dL9w1V1DWOo1K0U&zhida_source=entity) 做请求校验，类型不符直接拒绝、返回 400。一个类型错误 × 905 张图 = 905 个 400，零个成功。 这个坑阴险在三点：一是 `user` 是个「可传可不传」的冷门字段，大家平时根本不注意它的类型；二是业务方在 Python 里 `payload["user"] = orid` 时，`orid` 从数据库读出来天然就是 int，本地联调时如果恰好传过字符串就通了，换成批量数字流就全挂；三是错误被调用方吞掉，双方各自看到「我这边正常」的假象。 ## 修复：改一行代码，再堵住一类问题 **立即修复**：业务方把 `user` 改为 `str(orid)`，一行代码，恢复 100% 成功。 但只修这一行，下次还会以别的姿势摔进来（后来果然又有新的 400，见下节）。所以同时做了机制层面的固化：**写标准客户端库，所有调用方统一复用，禁止各自拼请求**： ```text # 标准客户端内部 "user": str(orid) if orid is not None else "anonymous" ``` 这个客户端同时封装了：`user` 强制字符串、图片 MIME 类型推断、think 推理链剥离、极端长宽比图的 padding、错误结构化解析。每一项都对应一个真实踩过的坑——**[接口契约](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E6%8E%A5%E5%8F%A3%E5%A5%91%E7%BA%A6&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLmjqXlj6PlpZHnuqYiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.N1NFiayZ1qG1pzVxrz18MSSyfV5j8p5BAJp8ICMCj9M&zhida_source=entity)不应该写在文档里等人对齐，应该直接编译进唯一的标准实现里**。文档会没人读，代码不会。 ## 同一个机制的二次回报 `ERR_BODY` 上线后不到两周就抓到了第二类 400，这次真的是图片问题： ```text status=400 ERR_BODY | {"message": "cannot identify image file <_io.BytesIO object at ...>"} ``` [PIL](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=PIL&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiJQSUwiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.6ZCBYjNNWy41GqBF_ld2VOWvwT_iHkCNz40oOCy-t44&zhida_source=entity) 无法识别的图片字节（损坏的文件头、不支持的格式）进到视觉编码前就死了。同样是 400，[根因](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=2&q=%E6%A0%B9%E5%9B%A0&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLmoLnlm6AiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MiwiemRfdG9rZW4iOm51bGx9.QOxLbmx4snsubdoyu5Z6c-ogwpkoGpzDNoTm88LH1tY&zhida_source=entity)完全不同——但排查动作一模一样：`grep ERR_BODY req_results.log`，一秒定位。一次基建投入，两次事故受益。 ## 复盘：四条沉淀 1. **统计先审口径**。「69% 成功」是分母混入自测的幻觉。任何成功率数字，先问一句：分子分母各自是谁的请求？ 2. **日志按请求[归因](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E5%BD%92%E5%9B%A0&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLlvZLlm6AiLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.b1yU7GKK1gsgOxdCQEome7Vw4h7ruO-0yf4qI8-ApCM&zhida_source=entity)设计**。orid 贯穿、req\_keys 记字段、ERR\_BODY 抓正文——这三个字段让「业务方说挂了」从吵不清的罗生门变成一次 grep。 3. **调用方吞错 = 双盲**。业务方代码吞掉 400，导致 100% 失败持续了一整天才被「截断」这个不相干的反馈顺带暴露。集成时的错误处理约定（至少计数、告警）和服务本身一样重要。 4. **契约进代码，不进文档**。`user` 必须字符串这类约定，写进标准客户端后，新调用方从第一天就是对的。 ## 小结 这次事故最有意思的地方是它的「罗生门结构」：服务方自测全绿（真话）、业务方只报截断（真话）、统计显示 69% 成功（假象）——三方信息拼起来，险些掩盖了一个 100% 失败的服务。破局的不是什么高深技术，而是一条按请求归因的结果日志：orid 分集合、交集归零、ERR\_BODY 见真因，三步收网。在[海光 DCU](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=2&q=%E6%B5%B7%E5%85%89+DCU&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLmtbflhYkgRENVIiwiemhpZGFfc291cmNlIjoiZW50aXR5IiwiY29udGVudF9pZCI6MjgyMTYzNzI4LCJjb250ZW50X3R5cGUiOiJBcnRpY2xlIiwibWF0Y2hfb3JkZXIiOjIsInpkX3Rva2VuIjpudWxsfQ.MM7p-6MFgWktinsOgR1rM8mXY8av6GSdr5BsnxG0KvQ&zhida_source=entity) 上搭起一套多模态服务不难，难的是让它在「有人报错」的那一刻，能在十分钟内自证清白或认罪伏法——这取决于你平时在日志里存了多少「暂时没用」的信息。 --- *环境信息：海光 K100\_AI × 8 / vLLM 多实例集群（DCU 定制版）+ aiohttp 反向代理 / 事故发生于多模态识图服务生产[运行期](https://zhida.zhihu.com/search?content_id=282163728&content_type=Article&match_order=1&q=%E8%BF%90%E8%A1%8C%E6%9C%9F&zd_token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJ6aGlkYV9zZXJ2ZXIiLCJleHAiOjE3OTA4NDE2MjYsInEiOiLov5DooYzmnJ8iLCJ6aGlkYV9zb3VyY2UiOiJlbnRpdHkiLCJjb250ZW50X2lkIjoyODIxNjM3MjgsImNvbnRlbnRfdHlwZSI6IkFydGljbGUiLCJtYXRjaF9vcmRlciI6MSwiemRfdG9rZW4iOm51bGx9.JwOrjh9XVcHKGYIfDJr8VFH3-hJiAOQJ2FLlPEvFXXw&zhida_source=entity) / 文中日志行已脱敏。*