問題
為了驗證「錯誤的 stack trace 會完整進到日誌平台」,我故意停掉服務的資料庫再送請求。結果日誌裡沒有任何一筆錯誤帶 stack,只有一筆「請求逾時」的警告,回應是 504。
看起來像日誌平台把 stack 弄丟了,其實是應用程式根本沒產生那筆錯誤。
解法
根因:資料庫連線池的等待上限(30000ms)跟請求逾時(30 秒)一樣長。
- 資料庫掛掉時,連線池等著拿連線,請求逾時也在倒數。
- 兩個計時器同時到,請求逾時先觸發。請求被切斷,記成 WARN「request timeout」。
- 連線池那邊「拿不到連線」的例外,就是本來會被記成 ERROR、帶完整 stack 的那筆,永遠來不及發生。
30 秒這個數字很容易撞在一起。以常見的 JVM 連線池 HikariCP 為例,connectionTimeout 的預設值就是 30000ms,逾時後丟出 SQLException(HikariCP README)。連線池沿用預設、請求上限又剛好設 30 秒,兩個逾時就會同時到期。
把下游逾時縮短到明顯小於請求上限(這裡 30 秒 → 3 秒)之後,同一個情境:
- 回 500
- 記一筆 ERROR,帶完整 stack;access log 那一行用 stack trace 的 ID 指向它
為什麼這樣解
逾時的層級要由外往內遞減:ingress 逾時 > app 請求上限 > 下游逾時 ×(重試次數+1)。順序反過來或相等時,外層的逾時會先觸發,內層真正出事的原因就被蓋掉。
- 對使用者:看到 504(像是服務慢),而不是一個指向「依賴失敗」的錯誤,處理方向會錯。修好之後量到的是 500。程式碼原本的設計是把「連線失敗」分類成 503,實際卻走了 500(未查證:推測是連線池丟出的例外類別不在程式碼判斷「連線失敗」的那幾個類別裡)。
- 對維運:日誌只看得到「逾時」,看不到是哪個依賴、什麼錯誤,要到事故當下才發現證據不見了。
- 對資源:每個請求都白等 30 秒,連線和 worker 被佔滿,很容易從「DB 掛了」擴大成「整個服務掛了」。
這跟 fail-open/fail-closed 的判準與量測陷阱裡講的 driver 逾時是同一個問題的兩面:那篇是「沒設逾時、每層各吃一次預設值」讓請求變慢;這篇是「設了,但內外一樣長」讓錯誤消失。
怎麼預防再次發生
- 設定逾時時三個數字一起看,下游一定要明顯短於請求上限,不能相等。
- 驗證日誌與告警時,要實際讓依賴掛掉看看:
- 「有錯誤 log」不等於「依賴掛掉時會有錯誤 log」
- 不實際停掉依賴,這種賽跑不會現形
- 看到 504 或「request timeout」而預期的是依賴錯誤時,先懷疑逾時層級,不是先懷疑日誌管線。
相關
- 驗收假綠形態目錄:「沒產生錯誤」看起來像「沒有錯誤」,是假綠的一種。
- 同一個依賴、相反的故障方向:停掉依賴做驗證時,量到的是哪一層的行為。
- 這是在驗收 ELK 日誌管線時發現的:日誌平台的驗收,要包含「依賴掛掉時錯誤真的會被產生出來」這一步。