話第二輪必現(xiàn)500:三個(gè)工程根因與排查復(fù)盤)
上周晚上 11 點(diǎn)同事在群里甩了一張截圖多輪對(duì)話第二輪請求直接 500而且必現(xiàn)。第一輪好好的第二輪一點(diǎn)就炸用戶已經(jīng)在小規(guī)模試用群里討論越來越激動(dòng)。第一反應(yīng)幾乎所有人都一樣——模型出問題了服務(wù)不穩(wěn)定趕緊去查模型服務(wù)商的監(jiān)控面板結(jié)果流量曲線平靜得像什么都沒發(fā)生過錯(cuò)誤率為零。再去翻推理網(wǎng)關(guān)日志也沒有明顯的 5xx。但業(yè)務(wù) API 網(wǎng)關(guān)的告警明明在響紅得刺眼。我按捺住性子把完整鏈路拆開看最后發(fā)現(xiàn)這口鍋從頭到尾就沒落到模型頭上。準(zhǔn)確說是三個(gè)工程問題疊在一起恰好把故障偽裝成了“第二輪必現(xiàn) 500”。這篇文章就把當(dāng)時(shí)的排查過程、三個(gè)根因和修復(fù)方案完整記錄下來給所有做對(duì)話類應(yīng)用、尤其是接了模型 API 做二次開發(fā)的同學(xué)一個(gè)參考以后再遇到“第二輪就掛”先別急著懷疑模型。1. 現(xiàn)象復(fù)盤為什么偏偏是第二輪先說架構(gòu)。整個(gè)鏈路分三層業(yè)務(wù) API 網(wǎng)關(guān)負(fù)責(zé)會(huì)話管理、上下文組裝、推理網(wǎng)關(guān)負(fù)責(zé)統(tǒng)一轉(zhuǎn)發(fā)模型請求、鑒權(quán)、超時(shí)控制、模型服務(wù)。第一輪請求用戶只發(fā)一句話沒有歷史消息業(yè)務(wù)網(wǎng)關(guān)把系統(tǒng)提示詞拼上就直接發(fā)給推理網(wǎng)關(guān)模型正常返回。第二輪業(yè)務(wù)網(wǎng)關(guān)要從會(huì)話存儲(chǔ)里取出第一輪的用戶消息和模型回復(fù)拼進(jìn)上下文再發(fā)給推理網(wǎng)關(guān)結(jié)果這一發(fā)就 500。表面上看問題指向很明確第一輪正常、第二輪異常差別只在于“多了歷史消息”那不就是歷史消息把模型惹毛了很多人到這里就會(huì)下結(jié)論模型對(duì)多輪支持不好或者上下文格式傳錯(cuò)了。但格式傳錯(cuò)是工程問題不是模型問題——傳錯(cuò)了是調(diào)用方?jīng)]按協(xié)議來。我做的第一個(gè)測試很暴力手動(dòng)把第二輪請求應(yīng)該攜帶的完整消息列表截出來用腳本直接調(diào)模型服務(wù)完全正常返回結(jié)果 200內(nèi)容質(zhì)量也沒問題。測試路徑請求內(nèi)容結(jié)果業(yè)務(wù) API 完整鏈路自動(dòng)組裝的第二輪上下文500腳本直連模型服務(wù)手工構(gòu)造的第二輪上下文200業(yè)務(wù) API 只發(fā)第一輪無歷史消息200推理網(wǎng)關(guān)轉(zhuǎn)發(fā)手工上下文繞過業(yè)務(wù)網(wǎng)關(guān)直連推理網(wǎng)關(guān)200四組對(duì)照測完結(jié)論已經(jīng)清楚了模型沒毛病推理網(wǎng)關(guān)沒毛病問題出在業(yè)務(wù) API 網(wǎng)關(guān)——要么它組裝的上下文內(nèi)容有問題要么它在轉(zhuǎn)發(fā)過程中沒有正確對(duì)待上游的異常。順著這個(gè)思路繼續(xù)拆最終挖出了三個(gè)獨(dú)立存在、疊加后才致命的工程問題。這里要先立一個(gè)判斷原則凡是能通過直連模型復(fù)現(xiàn)的問題才可能和模型有關(guān)凡是直連模型一切正常、走完整鏈路才出的問題第一嫌疑永遠(yuǎn)是工程層不用懷疑模型至少不該第一個(gè)懷疑。2. 工程問題一上下文組裝層把臟字段塞進(jìn)了歷史消息排查第一步是抓實(shí)際發(fā)出的請求。我在業(yè)務(wù)網(wǎng)關(guān)加了一個(gè)臨時(shí)日志把第二輪組裝出來的 messages 數(shù)組完整打出來問題立刻暴露歷史消息里塞進(jìn)了大量不該出現(xiàn)的東西。具體來說團(tuán)隊(duì)為了實(shí)現(xiàn)“流式打字機(jī)效果”第一輪請求走的是流式接口。開發(fā)同學(xué)為了省事把流式返回的原始增量對(duì)象直接累積成一個(gè) message 對(duì)象存進(jìn)了會(huì)話緩存。這個(gè)原始對(duì)象里除了 content 之外還帶著finish_reason、接口返回的元數(shù)據(jù)字段甚至在部分模型接口里還帶了一個(gè)reasoning_content字段——這是模型內(nèi)部思考過程的文本正常使用中根本不該回傳給模型。第二輪組歷史時(shí)系統(tǒng)直接把緩存里的原始 message 對(duì)象塞進(jìn) messages 數(shù)組原封不動(dòng)發(fā)給推理網(wǎng)關(guān)。推理網(wǎng)關(guān)再轉(zhuǎn)發(fā)給模型服務(wù)時(shí)模型服務(wù)方的 schema 校驗(yàn)當(dāng)場拒絕assistant 消息里帶了未被允許的字段返回 400。但注意業(yè)務(wù)網(wǎng)關(guān)拿到這個(gè) 400 之后做了統(tǒng)一異常處理把 400 吞掉換成了一個(gè)通用 500 返回給前端。這一層錯(cuò)誤吞沒是第三個(gè)問題先按下不表但要記住它。2.1 為什么臟字段只在第二輪爆發(fā)第一輪沒有歷史消息所以不存在回放問題。第二輪要把第一輪的消息從緩存里讀出來臟字段在這個(gè)環(huán)節(jié)進(jìn)入請求。更坑的是本地自測很難發(fā)現(xiàn)開發(fā)自測時(shí)通常用簡單文本模擬或者干脆不走流式接口緩存里存的是干凈消息。只有線上聯(lián)調(diào)、真實(shí)用戶通過前端流式交互時(shí)原始對(duì)象才會(huì)帶著完整字段落庫。這種情況在對(duì)話類應(yīng)用里太常見了。模型接口的 message 對(duì)象遠(yuǎn)比我們以為的復(fù)雜常見的字段還包括 tool_calls、function_call、refusal 等這些字段在“當(dāng)前輪”作為模型輸出是合法的但作為“歷史 assistant 消息”回放時(shí)不同模型服務(wù)商的處理策略不一樣嚴(yán)格的服務(wù)商直接 400寬松的會(huì)忽略但請求體體積已經(jīng)被撐大了。2.2 上下文組裝的正確姿勢字段白名單清洗修復(fù)方案不復(fù)雜核心是緩存時(shí)只存需要回放的數(shù)據(jù)回放時(shí)只放協(xié)議允許的字段。提供一個(gè)清洗函數(shù)在組裝歷史消息時(shí)強(qiáng)制過濾# 只保留協(xié)議允許回放的字段 def clean_history_message(raw_message: dict) - dict: allowed_fields {role, content} cleaned { role: raw_message.get(role), content: raw_message.get(content, ), } # 如果歷史里有工具調(diào)用記錄要按模型要求的格式單獨(dú)轉(zhuǎn)寫 if raw_message.get(tool_calls): cleaned[tool_calls] raw_message[tool_calls] return cleaned這里的核心思路是白名單思維不是黑名單。黑名單永遠(yuǎn)防不住模型服務(wù)商將來新增字段白名單只放確定合法的字段一勞永逸。同時(shí)在寫入緩存那一步就做清洗不要讓臟數(shù)據(jù)落地。我在項(xiàng)目里加了兩個(gè)措施第一會(huì)話緩存落庫時(shí)只保留 role、content 和按協(xié)議轉(zhuǎn)寫過的 tool_calls 字段其他一概丟棄。第二組裝請求前再加一道白名單校驗(yàn)兩次夾擊徹底杜絕臟字段上位。2.3 快速自查怎么判斷是不是這個(gè)原因一板一眼的排查方法很簡單把第二輪的 messages 數(shù)組原樣打印出來逐條看歷史 assistant 消息的字段。如果發(fā)現(xiàn) content 之外還有 reasoning_content、finish_reason、delta、parts 之類的字段基本就是它了。立即把緩存里的原始對(duì)象換成清洗后的字段故障大概率立刻消失。如果想做成自動(dòng)化防線可以在請求日志里記錄每次請求的字段結(jié)構(gòu)一旦出現(xiàn)協(xié)議外的字段就報(bào)警。3. 工程問題二推理網(wǎng)關(guān)的超時(shí)與上下文壓力雙重夾擊臟字段問題修掉之后第二輪 500 竟然還在只是概率從 100% 降到了 30% 左右。這說明還有另一個(gè)問題而且它不是必現(xiàn)的更像偶發(fā)。這次輪到看推理網(wǎng)關(guān)日志。翻到故障時(shí)間點(diǎn)發(fā)現(xiàn)一批請求在推理網(wǎng)關(guān)側(cè)報(bào)了read timeout超時(shí)閾值居然是 10 秒。再往深挖看到兩個(gè)細(xì)節(jié)連接池最大 10 個(gè)連接高峰期排隊(duì)嚴(yán)重而且請求體里攜帶的消息量比預(yù)期大得多。3.1 上下文體積膨脹推理耗時(shí)被拉長別看第二輪只是多了一輪歷史實(shí)際上上下文體積漲得驚人。我做了個(gè)粗略估算系統(tǒng)提示詞約 500 字折合約 750 token第一輪用戶輸入約 10 個(gè)漢字模型回復(fù)約 1200 字折合約 1800 token。第二輪用戶再輸入 10 個(gè)字整個(gè)請求的輸入 token 數(shù)大概是 2600 左右是原來的三倍還多。輸入 token 暴漲直接影響模型服務(wù)的處理時(shí)間。Transformer 解碼的時(shí)候每生成一個(gè) token 都要對(duì)所有輸入 token 做注意力計(jì)算輸入翻三倍前處理階段和每一步解碼的計(jì)算量都同步上漲。實(shí)測下來第一輪請求 1.5 秒返回首 token第二輪漲到 3.5 秒總生成時(shí)間從 5 秒拉到了 9 秒。如果只是 9 秒10 秒超時(shí)還能勉強(qiáng)扛住但高峰期連接池排隊(duì) 3 到 4 秒總耗時(shí)一下就突破 12 秒推理網(wǎng)關(guān)直接判定超時(shí)向上游返回 504。指標(biāo)第一輪第二輪輸入 token 估算約 800約 2600首 token 耗時(shí)約 1.5s約 3.5s總生成耗時(shí)約 5s約 9s高峰期排隊(duì)時(shí)間0s約 3s網(wǎng)關(guān)讀超時(shí)閾值10s10s是否觸發(fā)超時(shí)否是3.2 臟字段對(duì)上下文體積的二次放大這里還有一個(gè)隱藏的放大器第一個(gè)工程問題留下的臟字段。reasoning_content這種思考過程字段往往特別長模型內(nèi)部推理一遍這段內(nèi)容可能有幾百上千字。它被存進(jìn)了緩存第二輪又被組裝進(jìn)請求等于白白給上下文加了上千 token。臟字段不只是格式問題還直接把延遲推過了超時(shí)臨界點(diǎn)。兩個(gè)問題疊加讓偶發(fā)超時(shí)變成了大概率超時(shí)。解決超時(shí)問題不能只調(diào)大超時(shí)閾值那是在掩蓋問題。我把超時(shí)改成了動(dòng)態(tài)估算請求輸入 token 量小就給短超時(shí)輸入量大給長超時(shí)。估算方式可以很粗糙模型輸入大概每秒能處理多少 token心里要有個(gè)底再乘一個(gè) 1.5 到 2 的余量系數(shù)def estimate_timeout(messages: list[dict], output_tokens: int 512) - int: # 粗略估算輸入 token 數(shù)中文約 1.5 token/字英文約 0.8 token/詞 total_chars sum(len(msg.get(content, )) for msg in messages) input_tokens int(total_chars * 1.5) # 假設(shè)解碼速度約 30 token/s生成 output_tokens 需要的時(shí)間 decode_seconds output_tokens / 30 # 前處理時(shí)間輸入越大越慢粗略按每千 token 增加 0.5s 估算 prefill_seconds 1.0 input_tokens / 1000 * 0.5 # 預(yù)留排隊(duì)、網(wǎng)絡(luò)、重試的余量 return int(prefill_seconds decode_seconds 5)同時(shí)把連接池從 10 個(gè)擴(kuò)到 30 個(gè)加了對(duì)推理網(wǎng)關(guān)排隊(duì)時(shí)長的監(jiān)控隊(duì)列深度超過閾值就提前告警。超時(shí)之后的重試邏輯也從“立刻重試一次”改成“隨機(jī)抖動(dòng) 1 到 3 秒后再重試”避免重試請求扎堆把已經(jīng)過載的推理鏈路徹底打崩。4. 工程問題三錯(cuò)誤處理層“一鍋端”把上游真實(shí)信息全吞了前面兩次修復(fù)之后按理說 500 應(yīng)該徹底消失了。但我在做回歸驗(yàn)證時(shí)故意構(gòu)造了一個(gè)非法請求去測試發(fā)現(xiàn)業(yè)務(wù) API 網(wǎng)關(guān)依然返回一個(gè)干干凈凈的 500{code: 500, message: internal error}。這個(gè)響應(yīng)本身就是第三個(gè)工程問題——錯(cuò)誤處理層的異常吞沒。打開全局異常處理器看一眼代碼大概是這樣的app.exception_handler(Exception) async def global_exception_handler(request, exc): logger.error(global exception: %s, exc, exc_infoTrue) return JSONResponse(status_code500, content{code: 500, message: internal error})所有異常不管來自哪里全部被這個(gè)全局處理器兜住一律返回 500。上游模型服務(wù)返回的 400 被吞、推理網(wǎng)關(guān)返回的 504 被吞、參數(shù)校驗(yàn)錯(cuò)誤被吞、甚至數(shù)據(jù)庫連接超時(shí)也被吞。前端拿到的永遠(yuǎn)是標(biāo)準(zhǔn) 500排障人員看到 500 就默認(rèn)是服務(wù)端出 bug然后一層一層查查半天發(fā)現(xiàn)真正的原因早被這層包裝藏起來了。4.1 錯(cuò)誤碼透傳的規(guī)范設(shè)計(jì)正確做法是分層設(shè)計(jì)錯(cuò)誤信息對(duì)外只暴露安全、無歧義的錯(cuò)誤描述對(duì)內(nèi)完整保留上游狀態(tài)碼、內(nèi)部錯(cuò)誤碼、trace_id方便排障。內(nèi)部錯(cuò)誤碼建議分段設(shè)計(jì)一段標(biāo)識(shí)錯(cuò)誤來源一段標(biāo)識(shí)具體場景。以我們項(xiàng)目為例設(shè)計(jì)成這樣一張表錯(cuò)誤碼段來源示例100xx參數(shù)校驗(yàn)類10001 消息格式非法200xx會(huì)話存儲(chǔ)類20003 會(huì)話上下文讀取失敗300xx推理網(wǎng)關(guān)類30001 上游請求超時(shí)400xx模型服務(wù)類40010 模型觸發(fā)輸入內(nèi)容限制映射規(guī)則是上游返回 4xx內(nèi)部記錄完整上游響應(yīng)對(duì)外返回 502 并帶內(nèi)部錯(cuò)誤碼上游返回 5xx內(nèi)部標(biāo)記為服務(wù)不可用對(duì)外返回 503推理網(wǎng)關(guān)超時(shí)統(tǒng)一識(shí)別為 30001。全局異常處理器只兜底真正的未知異常不再貪吃蛇一樣吞掉所有錯(cuò)誤。修復(fù)后的異常處理器長這樣# 自定義業(yè)務(wù)異常攜帶內(nèi)部錯(cuò)誤碼和上游狀態(tài)碼 class ApiException(Exception): def __init__(self, status_code: int, internal_code: int, message: str, upstream_status: int | None None): self.status_code status_code self.internal_code internal_code self.message message self.upstream_status upstream_status app.exception_handler(ApiException) async def handle_api_exception(request, exc: ApiException): return JSONResponse( status_codeexc.status_code, content{ code: exc.internal_code, message: exc.message, request_id: request.state.request_id, upstream_status: exc.upstream_status, }, )配合一個(gè)從請求開始就生成的 request_id也叫 trace_id前端報(bào)錯(cuò)時(shí)只要把 request_id 發(fā)過來后端一條命令就能把整條鏈路拉全。4.2 日志串聯(lián)用 request_id 貫穿三層多輪對(duì)話這種多服務(wù)鏈路最怕各層日志自成體系。業(yè)務(wù)網(wǎng)關(guān)有業(yè)務(wù)網(wǎng)關(guān)的日志推理網(wǎng)關(guān)有推理網(wǎng)關(guān)的日志模型服務(wù)商有它的日志彼此之間沒有關(guān)聯(lián)字段排查時(shí)只能靠時(shí)間窗口盲猜。必須從入口生成 request_id通過 HTTP Header 傳給每一個(gè)下游。業(yè)務(wù)網(wǎng)關(guān)和推理網(wǎng)關(guān)都是自研的傳 header 很容易。模型服務(wù)商那邊如果支持透傳自定義 header就傳過去不支持的話至少推理網(wǎng)關(guān)要記錄 request_id 到模型服務(wù)請求的時(shí)間戳靠時(shí)間對(duì)齊。排查時(shí)的實(shí)際操作就是 grep# 按 request_id 拉全業(yè)務(wù)網(wǎng)關(guān)日志 grep request_id8f3a2b1c app_gateway.log # 按同一個(gè) request_id 拉全推理網(wǎng)關(guān)日志 grep request_id8f3a2b1c inference_gateway.log # 如果模型服務(wù)商側(cè)沒有該字段用時(shí)間段入?yún)⒄獙?duì)齊 grep 8f3a2b1c model_side.log這一步在復(fù)盤時(shí)幫了大忙。修復(fù)錯(cuò)誤透傳之后再構(gòu)造一個(gè)錯(cuò)誤請求日志里直接顯示上游返回了 400、具體是哪一段消息字段非法、模型服務(wù)商給出的校驗(yàn)提示是什么一眼定位不再需要翻聊天記錄猜來猜去。5. 三層問題疊加后的排查路徑與工程復(fù)盤回頭看整個(gè)故障與其說是一個(gè) 500不如說是三層問題剛好踩在同一個(gè)點(diǎn)上互相放大的結(jié)果。單獨(dú)看任何一個(gè)都不至于讓故障表現(xiàn)成“第二輪必現(xiàn) 500”。第一層上下文組裝臟字段負(fù)責(zé)讓模型服務(wù)商拒絕請求但它返回的是 400如果沒有第三層錯(cuò)誤吞沒前端會(huì)看到一個(gè) 400至少不會(huì)完全摸不著頭腦。第二層推理網(wǎng)關(guān)超時(shí)是偶發(fā)的高峰期才會(huì)觸發(fā)原本只會(huì)造成零星超時(shí)。第三層錯(cuò)誤吞沒把所有上游 4xx 和 5xx 全部統(tǒng)一成 500于是 400 的必現(xiàn)問題、504 的偶發(fā)問題在業(yè)務(wù) API 層全部變成“第二輪必現(xiàn) 500”的單一現(xiàn)象。排查路徑是倒著走的先看見 500確認(rèn)在業(yè)務(wù)網(wǎng)關(guān)順著業(yè)務(wù)網(wǎng)關(guān)抓實(shí)際發(fā)出請求發(fā)現(xiàn)臟字段修掉臟字段后必現(xiàn)問題變成偶發(fā)再看推理網(wǎng)關(guān)才發(fā)現(xiàn)超時(shí)最后為了徹底看清楚錯(cuò)誤全貌修掉了錯(cuò)誤吞沒。如果一開始就打通了錯(cuò)誤透傳第一步就能從響應(yīng)體里的upstream_status: 400直接鎖定臟字段問題后面超時(shí)的排查也會(huì)更快。5.1 復(fù)盤后的關(guān)鍵結(jié)論別讓模型背鍋也別指望模型兜底這里要給團(tuán)隊(duì)立一個(gè)規(guī)矩任何對(duì)話類應(yīng)用只要直連模型服務(wù)正常走業(yè)務(wù)鏈路異常必須先查工程鏈路這是排查順序問題不是甩鍋問題。反過來也成立如果工程鏈路不治理模型服務(wù)商確實(shí)會(huì)被誤傷。用戶看到的是整個(gè)產(chǎn)品他不會(huì)區(qū)分模型問題和網(wǎng)關(guān)問題只知道第二輪就 500 了。等到模型服務(wù)商把日志甩回來說請求根本沒到或者格式非法那個(gè)場面才叫尷尬。我們的教訓(xùn)是多輪對(duì)話不是“把歷史消息拼回去再發(fā)一次”那么簡單。歷史消息的存儲(chǔ)格式、字段回放規(guī)則、組裝后的體積控制、超時(shí)時(shí)間、錯(cuò)誤碼透傳每一層都有工程邊界需要守住。這些邊界不是模型幫你守的模型只負(fù)責(zé)接收合法請求、返回結(jié)果或合法錯(cuò)誤。5.2 上線前預(yù)防方案一覽這次踩坑之后我把多輪對(duì)話類功能的檢查項(xiàng)固定成了一張清單每次上線前過一遍檢查項(xiàng)檢查方法對(duì)應(yīng)問題歷史消息緩存字段白名單檢查緩存結(jié)構(gòu)確認(rèn)只存 role/content/tool_calls防止臟字段回放消息 schema 實(shí)時(shí)校驗(yàn)組裝請求前跑一道 JSON Schema 校驗(yàn)防止意外字段導(dǎo)致 400請求體體積監(jiān)控記錄每次請求的 token 估算值和實(shí)際字節(jié)數(shù)提前發(fā)現(xiàn)上下文膨脹推理網(wǎng)關(guān)超時(shí)動(dòng)態(tài)化根據(jù)輸入規(guī)模計(jì)算超時(shí)不設(shè)固定值防止高峰期 504錯(cuò)誤碼透傳和 request_id檢查響應(yīng)體含 internal_code/upstream_status避免錯(cuò)誤被吞沒多輪回歸壓測至少跑 5 輪以上對(duì)話并發(fā)請求壓推理網(wǎng)關(guān)覆蓋必現(xiàn)和偶發(fā)問題最后再補(bǔ)一個(gè)建議會(huì)話緩存和上下文組裝這兩個(gè)環(huán)節(jié)一定要寫單元測試和集成測試。測試用例里顯式構(gòu)造帶臟字段的歷史消息驗(yàn)證清洗邏輯生效同時(shí)驗(yàn)證超時(shí)重試邏輯不會(huì)導(dǎo)致消息重復(fù)發(fā)送。這些小投入比線上故障后再去補(bǔ)救便宜太多。我個(gè)人在實(shí)際排查里最深的一個(gè)體會(huì)是多輪對(duì)話 500 的故障絕大多數(shù)時(shí)候模型是無辜的。把排查順序固定成“從外到內(nèi)、從工程到模型”先看錯(cuò)誤響應(yīng)是否透傳、再看請求內(nèi)容是否合法最后才輪得到懷疑模型本身。大多數(shù)問題在第三步之前就已經(jīng)水落石出了。