golang 服務(wù)詭異499、504網(wǎng)絡(luò)故障排查

• 事故經(jīng)過
• 排查
• 總結(jié)

事故經(jīng)過

11-01 12:00 中午午飯期間，手機突然收到業(yè)務(wù)網(wǎng)關(guān)非200異常報警，平時也會有一些少量499或者網(wǎng)絡(luò)抖動問題觸發(fā)報警，但是很快就會恢復(fù)（目前配置的報警閾值是5%，閾值跟當(dāng)時的采樣窗口qps有直接關(guān)系）。

報警當(dāng)時非200占比已經(jīng)過10%并且在持續(xù)升高，根據(jù)歷史規(guī)律應(yīng)該很快就會恢復(fù)，我們稍微觀察了幾分鐘（一邊吃著很香的餃子一邊看著手機），但是過了幾分鐘故障沒有恢復(fù)而且占比升高了突破50%，故障逐漸升級（故障如果不在固定時間內(nèi)解決會逐漸升級，故障群每次升級都會逐層拉更高level的boss進來）手機持續(xù)報警震動已經(jīng)發(fā)燙了，故障占比已經(jīng)快100%，影響面突然變大。

此時提現(xiàn)系統(tǒng)也開始報警，大量打款訂單擠壓（打款訂單擠壓突破一定閾值才會報警，所以不是實時），工位同事也反應(yīng)支付系統(tǒng)也有少量連接錯誤，突然感覺情況復(fù)雜了，迅速停止吃飯，趕緊回公司排查。

回到工位時間差不多12:40左右，快速查看監(jiān)控大盤，基本都是499、504錯誤，此類錯誤都是因為網(wǎng)絡(luò)超時導(dǎo)致。集群中的兩臺機器均有錯，而且qps也比較平均，可以排除某臺機器問題。

RT99線基本5s，而且連續(xù)橫盤，這5s是觸發(fā)了上游sidecar proxy調(diào)用超時主動斷開了，真正的RT時間可能更長。

故障還未見恢復(fù)，業(yè)務(wù)運維協(xié)助一起排查，此時故障群已經(jīng)升級到技術(shù)中心老大，壓力瞬間大的一筆。

查看網(wǎng)關(guān)系統(tǒng)日志，大量調(diào)用我們內(nèi)部的兩個系統(tǒng)報出“下游服務(wù)器超時”錯誤，根據(jù)日志信息可以判斷網(wǎng)絡(luò)問題導(dǎo)致超時，但是我們調(diào)用的是內(nèi)網(wǎng)服務(wù)，如果是網(wǎng)絡(luò)問題為什么只有我們的系統(tǒng)受到影響。

在12:51到13:02之間錯誤占比情況有所好轉(zhuǎn)，但是之后錯誤占比繼續(xù)升高。

此時業(yè)務(wù)運維同步其他部門有大量302報警，時間線有點吻合，此時時間差不多13:30。但是別的部門的系統(tǒng)和我們的系統(tǒng)沒有任何關(guān)系，太多的疑問大家開始集中坐到一起排查問題。

他們嘗試做了版本回滾未見好轉(zhuǎn)，然后嘗試將訪問返回302域名切到內(nèi)網(wǎng)故障立馬恢復(fù)，此時正好14:00。根據(jù)他們的反饋在做實驗放量，導(dǎo)致在12:00的時候有一波流量高峰，但是這一波流量高峰對我的系統(tǒng)鏈路沖擊在哪里，一臉懵逼，疑點重重。

本次故障持續(xù)時間太長，報警整整報了兩個小時，故障群每三種報警一次并且電話通知，報警電話幾十個，微信報警群“災(zāi)難”級別的信息更多，嚴重程度可想而知。

排查

雖然故障是因為別的部門放量導(dǎo)致，但是還是有太多疑問沒有答案，下次還會再出現(xiàn)。作為技術(shù)人員，線上環(huán)境是非常神圣的地方是禁區(qū)，一定要找到每次故障的 root cause，否則沒辦法給自己一個交代，我們開始逐層剝洋蔥。

我們來梳理下疑問點：

1.302是什么原因，為什么做了域名切換就整體恢復(fù)了？
2.兩邊的系統(tǒng)在鏈路上有什么交集？如果應(yīng)用鏈路沒有交集，那么在網(wǎng)絡(luò)鏈路上是否有交集？
3.我們業(yè)務(wù)網(wǎng)關(guān)中的“下游服務(wù)器超時”為什么其他系統(tǒng)沒有影響？對日志的解讀或者描述是否有歧義？
4.504是觸發(fā)sidecar proxy 超時斷開連接，網(wǎng)關(guān)服務(wù)設(shè)置的超時為什么沒起作用？

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

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

2.兩邊的系統(tǒng)在鏈路上有什么交集？如果應(yīng)用鏈路沒有交集，那么在網(wǎng)絡(luò)鏈路上是否有交集？

所有人焦點都集中在高防上，認為網(wǎng)關(guān)故障就是因為也走到了被高防的地址上，但是我們的網(wǎng)關(guān)配置里根本沒有這個高防地址，而且我們內(nèi)部系統(tǒng)是不會有外網(wǎng)地址的。

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

根據(jù)這個線索認為網(wǎng)關(guān)系統(tǒng)雖然本身沒有調(diào)用到高防地址，但是調(diào)用的下游也有可能會走到才會導(dǎo)致整個鏈路出現(xiàn)雪崩的問題。

通過大量排查下游服務(wù)，翻代碼、看日志，基本上在應(yīng)用層調(diào)用鏈路沒有找到任何線索。開始在網(wǎng)絡(luò)層面尋找線索，由于是內(nèi)網(wǎng)調(diào)用所以路線是比較簡單的，client->slb->gateway->slb->sidecar proxy->ecs，幾個下游被調(diào)用系統(tǒng)請求一切正常，slb、sidecar proxy監(jiān)控也一切正常，應(yīng)用層、網(wǎng)絡(luò)層都沒有找到答案。

sidecar proxy 因為沒有打開日志所以看不到請求（其實有一部分調(diào)用沒有直連還是通過slb、vtm中轉(zhuǎn)），從監(jiān)控上看下游的 sidecar proxy 也一切正常，如果網(wǎng)路問題肯定是連鎖反應(yīng)。

百般無解之后，開始仔細檢查當(dāng)天出現(xiàn)故障的所有系統(tǒng)日志（由于現(xiàn)在流行Microservice所以服務(wù)比較多，錯誤日志量也比較大），在排查到支付系統(tǒng)的渠道服務(wù)時發(fā)現(xiàn)有一些線索，在事故發(fā)生期間有一些少量的 connection reset by peer，這個錯誤基本上多數(shù)出現(xiàn)在連接池化技術(shù)中使用了無效連接，或者下游服務(wù)器發(fā)生重啟導(dǎo)致。但是在事故當(dāng)時并沒有發(fā)布。

通過對比前一周日志沒有發(fā)生此類錯誤，那很有可能是很重要的線索，聯(lián)系阿里云開始幫忙排查當(dāng)時ecs實例在鏈路上是否有問題，驚喜的是阿里云反饋在事故當(dāng)時出現(xiàn) nat網(wǎng)關(guān) 限流丟包，一下子疑問全部解開了。

限流丟包才是引起我們系統(tǒng)大量錯誤的主要原因，所以整個故障原因是這樣的，由于做活動放量導(dǎo)致高防302和出網(wǎng)限流丟包，而我們系統(tǒng)受到影響都是因為需要走外網(wǎng)，提現(xiàn)打款需要用到支付寶、微信等支付渠道，而支付系統(tǒng)也是需要出外網(wǎng)用到支付寶、微信、銀聯(lián)等支付渠道。
（由于當(dāng)時我們并沒有nat網(wǎng)關(guān)的報警導(dǎo)致我們都一致認為是高防攔截了流量。）

問題又來了，為什么網(wǎng)關(guān)調(diào)用內(nèi)部系統(tǒng)會出現(xiàn)問題，但是答案已經(jīng)很明顯。簡單的檢查了下其中一個調(diào)用會走到外網(wǎng)，網(wǎng)關(guān)的接口會調(diào)用下游三個服務(wù)，其中第一個服務(wù)調(diào)用就是會出外網(wǎng)。

這個問題是找到了，但是為什么下游設(shè)置的超時錯誤一個沒看見，而且“下游服務(wù)器超時”的錯誤日志stack trace 堆棧信息是內(nèi)網(wǎng)調(diào)用，這個還是沒搞明白。

3.我們業(yè)務(wù)網(wǎng)關(guān)中的“下游服務(wù)器超時”為什么其他系統(tǒng)沒有影響？對日志的解讀或者描述是否有歧義？

通過分析代碼，這個日志的輸出并不是直接調(diào)用某個服務(wù)發(fā)生超時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 啟動一個調(diào)用，然后通過 select channel 感知http調(diào)用的結(jié)果，同時通過 ctx.Done() 感知本次上游http連接的 canceled。

err = errors.ErrClientTimeOut
ErrClientTimeOut         = ErrType{64012, "下游服務(wù)器超時"}

這里的 errors.ErrClientTimeOut 就是日志“下游服務(wù)器超時”的錯誤對象。

很奇怪，為什么調(diào)用下游服務(wù)器沒有超時錯誤，明明設(shè)置了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 是有設(shè)置調(diào)用超時的，為什么一條調(diào)用超時錯誤日志沒有，跟蹤代碼發(fā)現(xiàn)雖然opts對象傳給了utils.HttpSend方法，但是里面卻沒有設(shè)置到 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 導(dǎo)致http調(diào)用未設(shè)置超時時間。加上之后調(diào)用一旦超時會拋出 “net/http:?request?canceled?(Client.Timeout?exceeded?while?awaiting?headers)” timeout 錯誤。

問題我們大概知道了，就是因為我們沒有設(shè)置下游服務(wù)調(diào)用超時時間，導(dǎo)致上游連接超時關(guān)閉了，繼而觸發(fā)context.canceled事件。

上層調(diào)用會逐個同步進行。

    couponResp, err := client.Coupon.GetMyCouponList(ctx, r)
    // 不返回錯誤 降級為沒有優(yōu)惠券
    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 獲取優(yōu)惠券
client.Coin.GetAccountCoin 獲取金幣賬戶
client.Coin.GetSubAccountCoin 獲取金幣子賬戶

這三個方法內(nèi)部都會調(diào)用Send方法，這個接口邏輯就是獲取用戶名下所有的現(xiàn)金抵扣權(quán)益，并且在超時時間內(nèi)做好業(yè)務(wù)降級。但是這里處理有一個問題，就是沒有識別Send方法返回的錯誤類型，其實連接斷了之后程序再往下走已經(jīng)沒有意義也就失去了Context.canceld的意義。
（go和其他主流編程語言在線程（Thread）概念上有一個很大的區(qū)別，go是沒有線程概念的（底層還是通過線程在調(diào)度），都是goroutine。go也是完全隱藏routine的，你無法通過類似Thread Id 或者 Thread local線程本地存儲等技術(shù)，所有的routine都是通過context.Context對象來協(xié)作，比如在java 里要想取消一個線程必須依賴Thread.Interrupt中斷，同時要捕獲和傳遞中斷信號，在go里需要通過捕獲和傳遞Context信號。）

4.504是觸發(fā)sidecar proxy 超時斷開連接，網(wǎng)關(guān)服務(wù)器設(shè)置的超時為什么沒起作用？

sidecar proxy 斷開連接有三個場景：

1.499同時會關(guān)閉下游連接
2.504超時直接關(guān)閉下游連接
3.空閑超過60s關(guān)閉下游連接

事故當(dāng)時499、504 sidecar proxy 主動關(guān)閉連接，網(wǎng)關(guān)服務(wù)Context.Done()方法感知到連接取消拋出異常，上層方法輸出日志“下游服務(wù)器超時”。那為什么我們網(wǎng)關(guān)服務(wù)器本身的超時沒起作用。

http/server.Server對象有四個超時參數(shù)我們并沒有設(shè)置，而且這一類參數(shù)通常會被忽視，作為一個服務(wù)器本身對所有進來的請求是有最長服務(wù)要求，我們一般關(guān)注比較多的是下游超時會忽視服務(wù)本身的超時設(shè)置。

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計算成絕對時間點設(shè)置到netFD對象（Network file descriptor.）上。
由于沒有設(shè)置超時時間所以相當(dāng)于所有的連接關(guān)閉都是通過sidecar proxy觸發(fā)傳遞下來的。

我們已經(jīng)知道 sidecar proxy 關(guān)閉連接的1、2兩種原因，第3種情況出現(xiàn)在http長連接上，但是這類連接關(guān)閉是無感知的。

默認的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
}

我們服務(wù)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，就算我們要設(shè)置keepAlive的超時時間也要大于60s，避免sidecar proxy使用了我們關(guān)閉的連接。
（但是這在網(wǎng)絡(luò)不穩(wěn)定的情況下會有問題，如果發(fā)生HA Failover 然后在一定小概率的心跳窗口內(nèi)，服務(wù)狀態(tài)并沒有傳遞到注冊中心，導(dǎo)致sidecar proxy重用了之前的http長連接。這其實也是個權(quán)衡，如果每次都檢查連接狀態(tài)一定會影響性能。）

這里有個好奇問題，http是如何感知到四層tcp的狀態(tài)，如何將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的狀態(tài)不是通過主動事件觸發(fā)告訴上層http的，而是每當(dāng)http主動去發(fā)現(xiàn)。

read時使用connReader來感知tcp狀態(tài)，writer時使用checkConnErrorWriter對象來感知tcp狀態(tài)，然后通過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
}

總結(jié)

此次故障排查了整整兩天半，很多點是需要去反思和優(yōu)化的。

1.所有的網(wǎng)絡(luò)調(diào)用沒有拋出最原始error信息。（經(jīng)過加工之后的日志會嚴重誤導(dǎo)人。）
2.超時時間的設(shè)置未能起到作用，未經(jīng)過完整的壓測和故障演練，所以超時時間很容易無效。
3.內(nèi)外網(wǎng)域名沒有隔離，需要區(qū)分內(nèi)外網(wǎng)調(diào)用，做好環(huán)境隔離。
4.http服務(wù)器本身的超時沒有設(shè)置，如果程序內(nèi)部出現(xiàn)問題導(dǎo)致處理超時，并發(fā)會把服務(wù)器拖垮。
5.對云上的調(diào)用鏈路和網(wǎng)絡(luò)架構(gòu)需要非常熟悉，這樣才能快速定位問題。

其實系統(tǒng)一旦上云之后整個網(wǎng)絡(luò)架構(gòu)變得復(fù)雜，干擾因素太多，排查也會面臨比較大的依賴，監(jiān)控告警覆蓋面和基數(shù)也比較大很難察覺到個別業(yè)務(wù)線。（其實有些問題根本找不到答案。）
所有無法復(fù)現(xiàn)的故障是最難排查的，因為只能事后靠證據(jù)一環(huán)環(huán)解釋，涉及到網(wǎng)絡(luò)問題情況就更加復(fù)雜。

作者：王清培（趣頭條 Tech Leader）