業務方突然找來說調用我們程式大量提示“觸發限流”，但是我們沒有收到任何監控報警。緊急檢視了下 _`ServiceMesh sidecar`_ 代理監控發現流量持續在減少，但是監控中沒有任何觸發限流的 _http code 429_ 占比，如果有觸發限流我們會收到報警。
後來通過排查是程式中有一個曆史限流邏輯觸發了，但是程式中觸發限流傳回的 _http code_ 是 200，這就完全避開了 _sidecar http code 非200_ 異常名額監控報警。把代碼中的限流門檻值調了非常大的一個值，統一走 _sidecar_ 限流為準。
- 事故經過
- 排查
- 總結
【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 的請求日志，觀察請求的日志，等待下次觸發。(由于 qps 較高，預設是不打開 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）