• 事故經過
• 排查
• 總結

事故經過

【2019-12-27 18:00 週五】
業務方突然找來說呼叫我們程式大量提示“觸發限流”，但是我們沒有收到任何監控報警。緊急查看了下 ServiceMesh sidecar 代理監控發現流量持續在減少，但是監控中沒有任何觸發限流的 http code 429 佔比，如果有觸發限流我們會收到報警。

後來通過排查是程式中有一個歷史限流邏輯觸發了，但是程式中觸發限流返回的 http code 是 200，這就完全避開了 sidecar http code 非200 異常指標監控報警。把程式碼中的限流閾值調了非常大的一個值，統一走 sidecar 限流為準。

猜測本次觸發限流可能跟網路抖動有關係，網路抖動導致連線持續被佔用，最終 qps

【2019-12-28 15:30 週六】
相同的問題第二天悄無聲息的又出現了，還是業務請求量持續下掉，上游業務方還是提示“觸發限流”，同時業務監控環比也在逐步下掉。

以恢復線上問題為第一原則快速重啟了程式，線上恢復。

修改了程式碼，去掉了限流邏輯，就算觸發限流也應該第一時間告警出來，這段程式碼返回 http 200 就很坑了，我們完全無感知。雖然我們知道觸發限流是“果”，“因”我們並不知道，但是故障要在第一時間暴露出來才是最重要的。

我們知道這個問題肯定還會出現，要讓隱藏的問題儘可能的全部暴露出來，用最快最小的代價發現和解決掉才是正確的方式。

恢復線上問題之後，開始排查相關係統指標，首先排查程式依賴的 DB、redis 等中介軟體，各項指標都很正常，DB 連線池也很正常，活動連線數個位數，redis 也是。故障期間相關中介軟體、網路流量均出現 _qps_下降的情況。

當時開始排查網路抖動情況，但是仔細排查之後也沒有出現丟包等情況。（仔細思考下，其實網路問題有點不合邏輯，因為相鄰兩天不可能同時觸發同一條鏈路上的網路故障，而且其他系統都很正常。）

【2019-12-28 22:48 週六】
這次觸發了 sidecar http code 非200佔比 告警，我們第一時間恢復了，整個告警到恢復只用了幾分鐘不到，將業務方的影響減少到最低。

但是由於缺少請求鏈路中間環節日誌，很難定位到底是哪裡出現問題。這次我們打開了 sidecar

同時請運維、基礎架構、DBA、雲專家等開始仔細排查整個鏈路。檢視機器監控，發現故障期間 socket fd 升高到了3w多，隨著fd升高記憶體也在持續佔用，但是遠沒有到系統瓶頸，DB、redis 還是出現故障視窗期間 qps 同步下掉的情況。

這個程式是兩臺機器，出故障只有一臺機器，週五和週六分別是兩臺機器交替出現 hang 住的情況。但是由於沒有保留現場，無法仔細分析。（之所以不能直接下掉一臺機器保留現場，是因為有些業務呼叫並不完全走 sidecar，有些還是走的域名進行呼叫。所以無法乾淨的下掉一臺機器排查。）

socket fd 升高暫不確定是什麼原因造成的。這次已經做好準備，下次故障立即 dump 網路連線，步步逼近問題。

【2019-12-29 18:34 週日】
就在我們排查的此時兩臺機器前後炸了一遍，迅速 netstat 下連線資訊，然後重啟程式，現在終於有了一些線索。

回顧整個故障過程，由於我們無法短時間內定位到，但是我們必須轉被動為主動。從原來被動接受通知，到主動發現，讓問題第一時間暴露出來，快速無感知恢復線上，然後逐步通過各種方式方法慢慢定位。

很多時候，我們排查問題會陷入細節，忽視了線上故障時間，應該以先恢復為第一原則。（故障等級和時間是正比的）

排查

【netstat 檔案分析】
到目前為止發現問題沒有那麼簡單，我們開始有備而來，主動揪出這個問題的時候了。做好相應的策略抓取更多的現場資訊分析。分析了 netstat 匯出來的連線資訊。

tcp6       0      0 localhost:synapse-nhttp localhost:56696         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60666         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:39570         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:55682         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36812         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:58454         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:43694         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:32928         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:60710         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:33418         CLOSE_WAIT
tcp6       0      0 localhost:synapse-nhttp localhost:36980         CLOSE_WAIT

一時矇蔽，synapse-nhttp 這個是什麼程式，當時不確定全是 tcp 網路連線的 fd，情急之下只顧著匯出最全的網路資訊執行了 netstat -a ，沒有帶上 -n -p 轉換埠為數字同時輸出執行程式。~_~

這個 synapse-nhttp 非常可疑，同時查看了其他 go 程式機器都沒有這個連線，為了排查是否程式本身問題，查看了 pre、qa 機器的連線，均都是 synapse-nhttp 這個埠名字。

判斷下來 synapse-nhttp 確實是我們自己的程式，但是為什麼埠名字會是 synapse-nhttp，後來查詢下來發現我們程式使用的 8280 埠就是 synapse-nhttp 預設埠，所以被 netstat 自動人性化解析了。~_~

由於請求鏈路經過 sidecar 進來，大量的 CLOSE_WAIT 被動關閉狀態，開始懷疑 sidecar 問題，保險起見我們採用排除法先將一個機器的量切到走域名做灰度測試，看是 sidecar 問題還是程式本身問題。

我們發現一個有意思的現象，CLOSE_WAIT 是被動關閉連線的狀態，主動關閉連線的狀態應該是 FIN_WAIT1。比較了兩種狀態連線數不是一個數量級，CLOSE_WAIT 將近1w個，而 FIN_WAIT1 只有幾個，同時 FIN_WAIT2 只有幾十個，TIME_WAIT一個沒有。

合理情況下，sidecar 連線的 FIN_WAIT1 狀態和本機程式連線的 CLOSE_WAIT 狀態應該是一個數量級才對。但是現在明顯被動關閉並沒有成功完成，要麼是上游 sidecar 主動斷開了連線，本機程式遲遲未能傳送 fin ack，sidecar 端的連線被 tcp keepalive 保活關閉釋放了。或者本機程式已經發出 fin ack 但是 sidecar 沒有收到，還有一種可能就是，sidecar 端連線在收到 fin ack 前被回收了。

當然，這些只是猜測，為了搞清楚具體什麼原因導致只能抓包看 tcp 互動才能得出最終結論。

【tcpdump 包分析】
我們準備好 tcpdump 指令碼，定期抓取 tcp 包，現在就在等故障出現了，因為故障一定還會出現。果然在30號下午又出現了，我們一陣激動準備分析dump檔案，但是埠抓錯了，sidecar 和程式都是本機呼叫走的是本地環回 lo 虛擬網絡卡介面，調整指令碼在耐心的等待。~_~

問題又如期而至，我們開始分析包。

可以很清楚看到 HTTP 請求有進來沒有返回的。第一個紅框是請求超時，上游主動關閉連線，超時時間大概是1s，伺服器正常返回了 fin ack。第二個紅框大概是間隔了一分半鐘，主動關閉連線，但是直接返回 RST 重置標誌，原先的連線其實已經不存在了。

為了驗證這個請求為什麼沒有返回，我們提取 tcpdump 中的 HTTP 請求到後端日誌檢視發現到了伺服器，我們再從 Mysql 伺服器請求 sql 中檢視發現沒有這個請求沒有進來，同時我們發現一個規律，故障期間 DB 非活動連線數都有持續跑高現象，非常規律。

基本上斷定是 DB 連線池洩漏，開始排查程式碼。

發現程式碼中有一個方法有問題，這個方法之前一直沒有業務規則命中，故障前一天26號有一個業務方開始走到這個方法。這個方法有一個隱藏bug，會導致 go 連線無法關閉。

這個bug其實也有go.sql原生庫的一半責任。

var r *sql.Rows
    if r, err = core.GetDB().NewSession(nil).SelectBySql(query).Rows(); err != nil {
        return
    }

    for r.Next() {
        if err = r.Scan(&sum); err != nil {
            applog.Logger.Error(fmt.Sprint("xxx", err))
            r.Close() // 由於沒有主動close連線導致洩漏
            return
        }
    }

sql.Rows 的Scan方法內部由於沒有判斷查詢DB返回的空，就直接轉換導致 converting panic 。在加上我們這個方法沒有處理 panic 情況，所以命中隱藏bug就會洩漏。

這個方法為什麼不主動關閉連線是因為 sql.Rows 掃描到最後會做關閉動作，所以一直以來都很好。

所以真正的問題是由於 連線池洩漏，導致所有的請求 goroutine block 在獲取連線地方的地方，這一類問題排查起來非常困難。

總結

1.回顧這整個排查過程，我覺得讓系統執行的健康狀態透明化才是發現問題的最有效手段，程式碼不出問題不現實。

2._go.sql_ 庫還談不上企業級應用，整個連線消耗、空閒和工作時長都是沒有監控的，這也是導致這個case無法快速定位的原因。包括go的其他方面都存在很多不完善的地方，尤其是企業級應用套件都很弱，包括_go_原生 dump 記憶體之後分析的套件。

3.整個排查還是受到了一些噪音干擾，沒能堅定核心邏輯和理論。DB 連線跑高為什麼沒注意到，這一點其實是因為我們一般只看當時故障前後半小時後指標，沒有拉長看最近一段時間規律是否有異樣，包括 sidecar 流量持續下掉是因為都是存量請求，請求逐漸被 _hang_住，導致量持續下掉，所以看上去感覺請求變少了，因為並沒有多出流量。

4.其實線上故障一旦被定位之後，問題本身都很簡單，一行不起眼的程式碼而已。所以我們必須敬畏每一行程式碼。

作者：王清培（趣頭條 Tech Leader）