• 事故經過
• 排查
• 總結

事故經過

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 超時斷開連接，網關服務設定的超時為什么沒起作用？

1.302是什么原因，為什么做了域名切換就整體恢復了？

經過我們的運維和阿里云專家的排查，出現大量302是因為訪問的域名觸發DDos/CC高防策略，由于訪問的域名配置了DDos/CC高防策略，大量請求觸發了其中一條規則導致拒絕請求（具體觸發了什么規則就不方便透露），所以會回傳302，通過添加白名單可以解決被誤殺的情況，
（從合理性角度講內部呼叫不應該走到外網，有一部分是歷史遺留問題，）

2.兩邊的系統在鏈路上有什么交集？如果應用鏈路沒有交集，那么在網路鏈路上是否有交集？

所有人焦點都集中在高防上，認為網關故障就是因為也走到了被高防的地址上，但是我們的網關配置里根本沒有這個高防地址，而且我們內部系統是不會有外網地址的，

排查提現系統問題，提現系統的配置里確實有用到被高防的外網地址，認為提現打款擠壓也是因為走到了高防地址，但是這個高防地址只是一個旁路作用，不會影響打款流程，但是配置里確實有配置到，所以有理由判斷肯定使用到了才會影響，這在當時確實是個很重要的線索，是個突破口，

根據這個線索認為網關系統雖然本身沒有呼叫到高防地址，但是呼叫的下游也有可能會走到才會導致整個鏈路出現雪崩的問題，

通過大量排查下游服務，翻代碼、看日志，基本上在應用層呼叫鏈路沒有找到任何線索，開始在網路層面尋找線索，由于是內網呼叫所以路線是比較簡單的，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）

標籤：Go

上一篇：【go學習筆記】二、變數、常量【連載】

下一篇：go-面向物件編程（下）