- 事故經過
- 排查
- 總結
11-01 12:00 中午午飯期間，手機突然收到業務網關非200異常報警，平時也會有一些少量499或者網絡抖動問題觸發報警，但是很快就會恢複（目前配置的報警門檻值是5%，門檻值跟當時的采樣視窗qps有直接關系）。
報警當時非200占比已經過10%并且在持續升高，根據曆史規律應該很快就會恢複，我們稍微觀察了幾分鐘（一邊吃着很香的餃子一邊看着手機），但是過了幾分鐘故障沒有恢複而且占比升高了突破50%，故障逐漸更新（故障如果不在固定時間内解決會逐漸更新，故障群每次更新都會逐層拉更高level的boss進來）手機持續報警震動已經發燙了，故障占比已經快100%，影響面突然變大。
此時提現系統也開始報警，大量打款訂單擠壓（打款訂單擠壓突破一定門檻值才會報警，是以不是實時），工位同僚也反應支付系統也有少量連接配接錯誤，突然感覺情況複雜了，迅速停止吃飯，趕緊回公司排查。
回到工位時間差不多12:40左右，快速檢視監控大盤，基本都是499、504錯誤，此類錯誤都是因為網絡逾時導緻。叢集中的兩台機器均有錯，而且qps也比較平均，可以排除某台機器問題。
RT99線基本5s，而且連續橫盤，這5s是觸發了上遊sidecar proxy調用逾時主動斷開了，真正的RT時間可能更長。
故障還未見恢複，業務運維協助一起排查，此時故障群已經更新到技術中心老大，壓力瞬間大的一筆。
檢視網關系統日志，大量調用我們内部的兩個系統報出“下遊伺服器逾時”錯誤，根據日志資訊可以判斷網絡問題導緻逾時，但是我們調用的是内網服務，如果是網絡問題為什麼隻有我們的系統受到影響。
在12:51到13:02之間錯誤占比情況有所好轉，但是之後錯誤占比繼續升高。
此時業務運維同步其他部門有大量302報警，時間線有點吻合，此時時間差不多13:30。但是别的部門的系統和我們的系統沒有任何關系，太多的疑問大家開始集中坐到一起排查問題。
他們嘗試做了版本復原未見好轉，然後嘗試将通路傳回302域名切到内網故障立馬恢複，此時正好14:00。根據他們的回報在做實驗放量，導緻在12:00的時候有一波流量高峰，但是這一波流量高峰對我的系統鍊路沖擊在哪裡，一臉懵逼，疑點重重。
本次故障持續時間太長，報警整整報了兩個小時，故障群每三種報警一次并且電話通知，報警電話幾十個，微信報警群“災難”級别的資訊更多，嚴重程度可想而知。
雖然故障是因為别的部門放量導緻，但是還是有太多疑問沒有答案，下次還會再出現。作為技術人員，線上環境是非常神聖的地方是禁區，一定要找到每次故障的 root cause，否則沒辦法給自己一個交代，我們開始逐層剝洋蔥。
我們來梳理下疑問點：
1.302是什麼原因，為什麼做了域名切換就整體恢複了？
2.兩邊的系統在鍊路上有什麼交集？如果應用鍊路沒有交集，那麼在網絡鍊路上是否有交集？
3.我們業務網關中的“下遊伺服器逾時”為什麼其他系統沒有影響？對日志的解讀或者描述是否有歧義？
4.504是觸發sidecar proxy 逾時斷開連接配接，網關服務設定的逾時為什麼沒起作用？
經過我們的運維和阿裡雲專家的排查，出現大量302是因為通路的域名觸發DDos/CC高防政策。由于通路的域名配置了DDos/CC高防政策，大量請求觸發了其中一條規則導緻拒絕請求（具體觸發了什麼規則就不友善透露），是以會傳回302，通過添加白名單可以解決被誤殺的情況。
（從合理性角度講内部調用不應該走到外網，有一部分是曆史遺留問題。）
所有人焦點都集中在高防上，認為網關故障就是因為也走到了被高防的位址上，但是我們的網關配置裡根本沒有這個高防位址，而且我們内部系統是不會有外網位址的。
排查提現系統問題，提現系統的配置裡确實有用到被高防的外網位址，認為提現打款擠壓也是因為走到了高防位址，但是這個高防位址隻是一個旁路作用，不會影響打款流程。但是配置裡确實有配置到，是以有理由判斷肯定使用到了才會影響，這在當時确實是個很重要的線索，是個突破口。
根據這個線索認為網關系統雖然本身沒有調用到高防位址，但是調用的下遊也有可能會走到才會導緻整個鍊路出現雪崩的問題。
通過大量排查下遊服務，翻代碼、看日志，基本上在應用層調用鍊路沒有找到任何線索。開始在網絡層面尋找線索，由于是内網調用是以路線是比較簡單的，client->slb->gateway->slb->sidecar proxy->ecs，幾個下遊被調用系統請求一切正常，slb、sidecar proxy監控也一切正常，應用層、網絡層都沒有找到答案。
sidecar proxy 因為沒有打開日志是以看不到請求（其實有一部分調用沒有直連還是通過slb、vtm中轉），從監控上看下遊的 sidecar proxy 也一切正常，如果網路問題肯定是連鎖反應。
百般無解之後，開始仔細檢查當天出現故障的所有系統日志（由于現在流行Microservice是以服務比較多，錯誤日志量也比較大），在排查到支付系統的管道服務時發現有一些線索，在事故發生期間有一些少量的 __connection reset by peer__，這個錯誤基本上多數出現在連接配接池化技術中使用了無效連接配接，或者下遊伺服器發生重新開機導緻。但是在事故當時并沒有釋出。
通過對比前一周日志沒有發生此類錯誤，那很有可能是很重要的線索，聯系阿裡雲開始幫忙排查當時ecs執行個體在鍊路上是否有問題，驚喜的是阿裡雲回報在事故當時出現 nat網關 限流丢包，一下子疑問全部解開了。
限流丢包才是引起我們系統大量錯誤的主要原因，是以整個故障原因是這樣的，由于做活動放量導緻高防302和出網限流丢包，而我們系統受到影響都是因為需要走外網，提現打款需要用到支付寶、微信等支付管道，而支付系統也是需要出外網用到支付寶、微信、銀聯等支付管道。
（由于當時我們并沒有nat網關的報警導緻我們都一緻認為是高防攔截了流量。）
問題又來了，為什麼網關調用内部系統會出現問題，但是答案已經很明顯。簡單的檢查了下其中一個調用會走到外網，網關的接口會調用下遊三個服務，其中第一個服務調用就是會出外網。
這個問題是找到了，但是為什麼下遊設定的逾時錯誤一個沒看見，而且“下遊伺服器逾時”的錯誤日志stack trace 堆棧資訊是内網調用，這個還是沒搞明白。
3.我們業務網關中的“下遊伺服器逾時”為什麼其他系統沒有影響？對日志的解讀或者描述是否有歧義？
通過分析代碼，這個日志的輸出并不是直接調用某個服務發生逾時timeout，而是 go Context.Done() channel 的通知，我們來看下代碼：
func Send(ctx context.Context, serverName, method, path string, in, out interface{}) (err error) {
e := make(chan error)
go func() {
opts := []utils.ClientOption{
utils.WithTimeout(time.Second * 1),
}
if err = utils.HttpSend(method, path, in, out, ops, opts...); err != nil {
e <- err
return
}
e <- nil
}()
select {
case err = <-e:
return
case <-ctx.Done():
err = errors.ErrClientTimeOut
return
}
} Send 的方法通過 goroutine 啟動一個調用，然後通過 select channel 感覺http調用的結果，同時通過 ctx.Done() 感覺本次上遊http連接配接的 __canceled__。
err = errors.ErrClientTimeOut
ErrClientTimeOut = ErrType{64012, "下遊伺服器逾時"} 這裡的 errors.ErrClientTimeOut 就是日志“下遊伺服器逾時”的錯誤對象。
很奇怪，為什麼調用下遊伺服器沒有逾時錯誤，明明設定了timeout時間為1s。
opts := []utils.ClientOption{
utils.WithTimeout(time.Second * 1),
}
if err = utils.HttpSend(method, path, in, out, ops, opts...); err != nil {
e <- err
return
} 這個 utils.HttpSend 是有設定調用逾時的，為什麼一條調用逾時錯誤日志沒有，跟蹤代碼發現雖然opts對象傳給了utils.HttpSend方法，但是裡面卻沒有設定到 __http.Client__對象上。
client := &http.Client{}
// handle option
{
options := defaultClientOptions
for _, o := range opts {
o(&options)
}
for _, o := range ops {
o(req)
}
//set timeout
client.Timeout = options.timeout
}
// do request
{
if resp, err = client.Do(req); err != nil {
err = err502(err)
return
}
defer resp.Body.Close()
} 就是缺少一行 client.Timeout = options.timeout 導緻http調用未設定逾時時間。加上之後調用一旦逾時會抛出 “net/http: request canceled (Client.Timeout exceeded while awaiting headers)” timeout 錯誤。
問題我們大概知道了，就是因為我們沒有設定下遊服務調用逾時時間，導緻上遊連接配接逾時關閉了，繼而觸發context.canceled事件。
上層調用會逐個同步進行。
couponResp, err := client.Coupon.GetMyCouponList(ctx, r)
// 不傳回錯誤 降級為沒有優惠券
if err != nil {
logutil.Logger.Error("get account coupon faield",zap.Any("err", err))
}
coins, err := client.Coin.GetAccountCoin(ctx, cReq.UserID)
// 不傳回錯誤 降級為沒有金币
if err != nil {
logutil.Logger.Error("get account coin faield",zap.Any("err", err))
}
subCoins, err := client.Coin.GetSubAccountCoin(ctx, cReq.UserID)
// 不傳回錯誤 降級為沒有金币
if err != nil {
logutil.Logger.Error("get sub account coin faield",zap.Any("err", err))
} client.Coupon.GetMyCouponList 擷取優惠券
client.Coin.GetAccountCoin 擷取金币賬戶
client.Coin.GetSubAccountCoin 擷取金币子賬戶
這三個方法内部都會調用Send方法，這個接口邏輯就是擷取使用者名下所有的現金抵扣權益，并且在逾時時間内做好業務降級。但是這裡處理有一個問題，就是沒有識别Send方法傳回的錯誤類型，其實連接配接斷了之後程式再往下走已經沒有意義也就失去了Context.canceld的意義。
（go和其他主流程式設計語言線上程（Thread）概念上有一個很大的差別，go是沒有線程概念的（底層還是通過線程在排程），都是goroutine。go也是完全隐藏routine的，你無法通過類似Thread Id 或者 Thread local線程本地存儲等技術，所有的routine都是通過context.Context對象來協作，比如在java 裡要想取消一個線程必須依賴Thread.Interrupt中斷，同時要捕獲和傳遞中斷信号，在go裡需要通過捕獲和傳遞Context信号。）
4.504是觸發sidecar proxy 逾時斷開連接配接，網關伺服器設定的逾時為什麼沒起作用？
sidecar proxy 斷開連接配接有三個場景：
1.499同時會關閉下遊連接配接
2.504逾時直接關閉下遊連接配接
3.空閑超過60s關閉下遊連接配接
事故當時499、504 sidecar proxy 主動關閉連接配接，網關服務Context.Done()方法感覺到連接配接取消抛出異常，上層方法輸出日志“下遊伺服器逾時”。那為什麼我們網關伺服器本身的逾時沒起作用。
http/server.Server對象有四個逾時參數我們并沒有設定，而且這一類參數通常會被忽視，作為一個伺服器本身對所有進來的請求是有最長服務要求，我們一般關注比較多的是下遊逾時會忽視服務本身的逾時設定。
type Server struct {
// ReadTimeout is the maximum duration for reading the entire
// request, including the body.
//
// Because ReadTimeout does not let Handlers make per-request
// decisions on each request body's acceptable deadline or
// upload rate, most users will prefer to use
// ReadHeaderTimeout. It is valid to use them both.
ReadTimeout time.Duration
// ReadHeaderTimeout is the amount of time allowed to read
// request headers. The connection's read deadline is reset
// after reading the headers and the Handler can decide what
// is considered too slow for the body.
ReadHeaderTimeout time.Duration
// WriteTimeout is the maximum duration before timing out
// writes of the response. It is reset whenever a new
// request's header is read. Like ReadTimeout, it does not
// let Handlers make decisions on a per-request basis.
WriteTimeout time.Duration
// IdleTimeout is the maximum amount of time to wait for the
// next request when keep-alives are enabled. If IdleTimeout
// is zero, the value of ReadTimeout is used. If both are
// zero, ReadHeaderTimeout is used.
IdleTimeout time.Duration
} 這些逾時時間都會通過setDeadline計算成絕對時間點設定到netFD對象（Network file descriptor.）上。
由于沒有設定逾時時間是以相當于所有的連接配接關閉都是通過sidecar proxy觸發傳遞下來的。
我們已經知道 sidecar proxy 關閉連接配接的1、2兩種原因，第3種情況出現在http長連接配接上，但是這類連接配接關閉是無感覺的。
預設的tcpKeepAliveListener對象的keepAlive是3分鐘。
func (ln tcpKeepAliveListener) Accept() (net.Conn, error) {
tc, err := ln.AcceptTCP()
if err != nil {
return nil, err
}
tc.SetKeepAlive(true)
tc.SetKeepAlivePeriod(3 * time.Minute)
return tc, nil
} 我們服務host是使用endless架構，預設也是3分鐘，這其實是個約定90s，過小會影響上遊代理。
func (el *endlessListener) Accept() (c net.Conn, err error) {
tc, err := el.Listener.(*net.TCPListener).AcceptTCP()
if err != nil {
return
}
tc.SetKeepAlive(true) // see http.tcpKeepAliveListener
tc.SetKeepAlivePeriod(3 * time.Minute) // see http.tcpKeepAliveListener
c = endlessConn{
Conn: tc,
server: el.server,
}
el.server.wg.Add(1)
return
} sidecar proxy 的逾時是60s，就算我們要設定keepAlive的逾時時間也要大于60s，避免sidecar proxy使用了我們關閉的連接配接。
（但是這在網絡不穩定的情況下會有問題，如果發生HA Failover 然後在一定小機率的心跳視窗内，服務狀态并沒有傳遞到注冊中心，導緻sidecar proxy重用了之前的http長連接配接。這其實也是個權衡，如果每次都檢查連接配接狀态一定會影響性能。）
這裡有個好奇問題，http是如何感覺到四層tcp的狀态，如何将Context.cancel的事件傳遞上來的，我們來順便研究下。
type conn struct {
// server is the server on which the connection arrived.
// Immutable; never nil.
server *Server
// cancelCtx cancels the connection-level context.
cancelCtx context.CancelFunc
} func (c *conn) serve(ctx context.Context) {
// HTTP/1.x from here on.
ctx, cancelCtx := context.WithCancel(ctx)
c.cancelCtx = cancelCtx
defer cancelCtx()
c.r = &connReader{conn: c}
c.bufr = newBufioReader(c.r)
c.bufw = newBufioWriterSize(checkConnErrorWriter{c}, 4<<10)
for {
w, err := c.readRequest(ctx)
if !w.conn.server.doKeepAlives() {
// We're in shutdown mode. We might've replied
// to the user without "Connection: close" and
// they might think they can send another
// request, but such is life with HTTP/1.1.
return
}
if d := c.server.idleTimeout(); d != 0 {
c.rwc.SetReadDeadline(time.Now().Add(d))
if _, err := c.bufr.Peek(4); err != nil {
return
}
}
c.rwc.SetReadDeadline(time.Time{})
}
} // handleReadError is called whenever a Read from the client returns a
// non-nil error.
//
// The provided non-nil err is almost always io.EOF or a "use of
// closed network connection". In any case, the error is not
// particularly interesting, except perhaps for debugging during
// development. Any error means the connection is dead and we should
// down its context.
//
// It may be called from multiple goroutines.
func (cr *connReader) handleReadError(_ error) {
cr.conn.cancelCtx()
cr.closeNotify()
}
// checkConnErrorWriter writes to c.rwc and records any write errors to c.werr.
// It only contains one field (and a pointer field at that), so it
// fits in an interface value without an extra allocation.
type checkConnErrorWriter struct {
c *conn
}
func (w checkConnErrorWriter) Write(p []byte) (n int, err error) {
n, err = w.c.rwc.Write(p)
if err != nil && w.c.werr == nil {
w.c.werr = err
w.c.cancelCtx()
}
return
} 其實tcp的狀态不是通過主動事件觸發告訴上層http的，而是每當http主動去發現。
read時使用connReader來感覺tcp狀态，writer時使用checkConnErrorWriter對象來感覺tcp狀态，然後通過server.conn對象中的cancelCtx來遞歸傳遞。
type conn struct {
// server is the server on which the connection arrived.
// Immutable; never nil.
server *Server
// cancelCtx cancels the connection-level context.
cancelCtx context.CancelFunc
} 此次故障排查了整整兩天半，很多點是需要去反思和優化的。
1.所有的網絡調用沒有抛出最原始error資訊。（經過加工之後的日志會嚴重誤導人。）
2.逾時時間的設定未能起到作用，未經過完整的壓測和故障演練，是以逾時時間很容易無效。
3.内外網域名沒有隔離，需要區分内外網調用，做好環境隔離。
4.http伺服器本身的逾時沒有設定，如果程式内部出現問題導緻處理逾時，并發會把伺服器拖垮。
5.對雲上的調用鍊路和網絡架構需要非常熟悉，這樣才能快速定位問題。
其實系統一旦上雲之後整個網絡架構變得複雜，幹擾因素太多，排查也會面臨比較大的依賴，監控告警覆寫面和基數也比較大很難察覺到個别業務線。（其實有些問題根本找不到答案。）
所有無法複現的故障是最難排查的，因為隻能事後靠證據一環環解釋，涉及到網絡問題情況就更加複雜。
作者：王清培（趣頭條 Tech Leader）