- 事故經過
- 排查
- 總結
【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）