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