golang 服務詭異49九、504網絡故障排查

• 事故通過
• 排查
• 總結

事故通過

11-01 12:00 中午午餐期間，手機忽然收到業務網關非200異常報警，平時也會有一些少許499或者網絡抖動問題觸發報警，可是很快就會恢復（目前配置的報警閾值是5%，閾值跟當時的採樣窗口qps有直接關係）。

報警當時非200佔比已通過10%而且在持續升高，根據歷史規律應該很快就會恢復，咱們稍微觀察了幾分鐘（一邊吃着很香的餃子一邊看着手機），可是過了幾分鐘故障沒有恢復並且佔比升高了突破50%，故障逐漸升級（故障若是不在固定時間內解決會逐漸升級，故障羣每次升級都會逐層拉更高level的boss進來）手機持續報警震動已經發燙了，故障佔比已經快100%，影響面忽然變大。

此時提現系統也開始報警，大量打款訂單擠壓（打款訂單擠壓突破必定閾值纔會報警，因此不是實時），工位同事也反應支付系統也有少許鏈接錯誤，忽然感受狀況複雜了，迅速中止吃飯，趕忙回公司排查。

回到工位時間差很少12:40左右，快速查看監控大盤，基本都是49九、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關閉下游鏈接

事故當時49九、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 關閉鏈接的一、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）