1. 程式人生 > >golang 服務詭異499、504網路故障排查

golang 服務詭異499、504網路故障排查

  • 事故經過
  • 排查
  • 總結

事故經過

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