<kbd id="5sdj3"></kbd>
<th id="5sdj3"></th>

  • <dd id="5sdj3"><form id="5sdj3"></form></dd>
    <td id="5sdj3"><form id="5sdj3"><big id="5sdj3"></big></form></td><del id="5sdj3"></del>

  • <dd id="5sdj3"></dd>
    <dfn id="5sdj3"></dfn>
  • <th id="5sdj3"></th>
    <tfoot id="5sdj3"><menuitem id="5sdj3"></menuitem></tfoot>

  • <td id="5sdj3"><form id="5sdj3"><menu id="5sdj3"></menu></form></td>
  • <kbd id="5sdj3"><form id="5sdj3"></form></kbd>

    go-zero框架HttpCode 503錯(cuò)誤與context canceled高相關(guān)性根因分析

    共 10388字,需瀏覽 21分鐘

     ·

    2024-03-25 20:30

    這里是Z哥的個(gè)人公眾號(hào)

    當(dāng)前處于不穩(wěn)定更新?tīng)顟B(tài)

    何時(shí)恢復(fù)周更,未知……

    我的第「232」篇原創(chuàng)敬上


    大家好,我是Z哥。 好久不見(jiàn),我今天強(qiáng)行逼自己上崗,來(lái)更新一篇。 9fd66951751cca4ed1c129d59edb82d0.webp前陣子團(tuán)隊(duì)內(nèi)備戰(zhàn)雙11的時(shí)候出現(xiàn)了一個(gè)問(wèn)題: 當(dāng)流量瞬時(shí)激增時(shí),API會(huì)出現(xiàn)大量 HttpCode 為 503 的錯(cuò)誤。與此同時(shí),發(fā)現(xiàn)另一個(gè)錯(cuò)誤 `responses.go:69 write response failed, error: context canceled` 與該錯(cuò)誤具有很強(qiáng)的相關(guān)性。這 2 個(gè)錯(cuò)誤都由我們使用的 go-zero 框架內(nèi)部拋出。 后來(lái)我花費(fèi)了16個(gè)小時(shí)來(lái)搞清楚這個(gè)事情,在這里分享給大家。

    /01 結(jié)論先行/ 我先講結(jié)論: 以上 503 錯(cuò)誤是由于客戶端取消請(qǐng)求引發(fā)的,并非真正是 5xx 所定義的「服務(wù)端異?!瓜嚓P(guān)的錯(cuò)誤。前面提到的第 2 個(gè)錯(cuò)誤就是表示「請(qǐng)求被取消」的意思。 go-zero 在 Dec 20, 2021 之后的版本(>= v1.2.5)中,增加了錯(cuò)誤碼 499(參考nginx 的狀態(tài)碼定義) 來(lái)專門表示這類錯(cuò)誤,代替了原先的 503 錯(cuò)誤碼。 相關(guān)commit:https://github.com/zeromicro/go-zero/commit/4ba2ff7cdd34b73312f5ce17191068146bc676a0 由于我們項(xiàng)目中使用的版本為 v1.2.2 因此以錯(cuò)誤碼 503 輸出。 解決方式也很簡(jiǎn)單,升級(jí) go-zero 的版本。

    下面是整個(gè)長(zhǎng)達(dá)16小時(shí)的分析的過(guò)程。除了你可以了解具體的根因外,也歡迎你和我分享當(dāng)你遇到類似情況時(shí)好用、高效的排查思路。
    /02 why?/ 01   拋出日志的代碼位置
    首先,找到源碼中兩個(gè)錯(cuò)誤拋出的代碼位置。

    1cdfa11bd5e4e2c1a8271bf1eb3f0f14.webp

    8ee5f2eebbf4be62dcb94b81afa7d824.webp

    以上輸出錯(cuò)誤日志的代碼位置可以分析出場(chǎng)景為:
    1. 往 Reponse 寫入數(shù)據(jù)時(shí)發(fā)生了 context canceled 錯(cuò)誤。
    2. 并且 http code >= 500,則會(huì)記錄error級(jí)別日志。以下是 isOkResponse 函數(shù)內(nèi)的邏輯。
          
            func isOkResponse(code int) bool {
          
          
               // not server error
          
          
               return code < http.StatusInternalServerError
          
          
            }
          
        
    根據(jù)debug中的 執(zhí)行過(guò)程來(lái)看,代碼的執(zhí)行順序就是上面的定義的序號(hào),先1,再2。

    雖然拋出日志的代碼在 go-zero 框架內(nèi)。但是,導(dǎo)致根因的關(guān)鍵代碼都在 golang 標(biāo)準(zhǔn)庫(kù) net/http/server.go 中。 我們從作為一個(gè) http server 是如何處理每一個(gè)請(qǐng)求的源頭開始逐步梳理,以幫助我們搞清楚這件事。
    02   梳理請(qǐng)求如何被處理

    e6338ca7f680a0224c30a8b82c579adc.webp

    關(guān)鍵代碼是上面紅框的部分,從上往下分別是:
    1. 以 sync 方式監(jiān)聽(tīng)網(wǎng)絡(luò)請(qǐng)求,并返回 net.Conn 對(duì)象。
    2. 服務(wù)端創(chuàng)建一個(gè)鏈接 conn 對(duì)象來(lái)承接這個(gè)客戶端的請(qǐng)求。
    3. 以 async 方式建立連接。循環(huán)到 l.Accept() 函數(shù)繼續(xù)監(jiān)聽(tīng)網(wǎng)絡(luò)請(qǐng)求。

    1de5cd8f45778e13467323a1b1686ff4.webp

    關(guān)鍵代碼是上面紅框的部分,從上往下分別是:
    1. 如果啟用了https,那么會(huì)走到這個(gè)函數(shù),這個(gè)函數(shù)中會(huì)進(jìn)行加密連接的“握手”。
      1. 這里不重要,因?yàn)檫@個(gè)函數(shù)沒(méi)有變更當(dāng)前上下文中的 ctx 變量,不會(huì)引發(fā) context canceled 錯(cuò)誤。
    2. 定義了一個(gè) cancelCtx,賦值給了c.cancelCtx,同時(shí)覆寫了 ctx 變量。 意味著,出現(xiàn)的 context canceled 的場(chǎng)景出現(xiàn)了,有以下幾個(gè)可能:
      1. 如果下面的 for 循環(huán)退出了,則會(huì)執(zhí)行這個(gè) cancelCtx,以取消 所有基于ctx 變量的相關(guān)操作。
      2. 任何可以獲取到 c.cancelCtx 變量的地方,可以執(zhí)行 cancelCtx() 。
    3. 以 sync 方式從連接中讀取請(qǐng)求。
    4. 調(diào)用handler鏈處理請(qǐng)求。
      1. 如果 ServeHTTP 函數(shù)被執(zhí)行完成,那么意味著請(qǐng)求被全部handler處理完成了,包括寫業(yè)務(wù)代碼的自定義 handler。

    根據(jù)以上的邏輯分析,導(dǎo)致 context canceled 錯(cuò)誤的范圍從:
    • 開始: c.r = &connReader。
    • 結(jié)束: serverHandler{ c.server }.ServeHTTP(w, w.req) 之前。

    /03 排除法縮小范圍/ 01   執(zhí)行 c.cancelCtx() 的地方 反向查找函數(shù)被使用的地方,可以找到兩處調(diào)用  c.cancelCtx() 的代碼。
          
            -- server.go739
          
          
            
              // 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()
          
          
            }
          
        
    以上函數(shù)在客戶端的Read返回非nil錯(cuò)誤時(shí)被調(diào)用。 并且引導(dǎo)我們將任何錯(cuò)誤視為連接已中斷,關(guān)閉其上下文 。 因此會(huì)調(diào)用 cancelCtx()。
          
            -- server.go 的 3525
          
          
            
              

    // 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 }
    以上函數(shù)在執(zhí)行 w.c.rwc.Write(p) 時(shí)出現(xiàn)錯(cuò)誤會(huì)記錄到 w.c.werr 變量上,并調(diào)用 cancelCtx() 。 通過(guò)debug驗(yàn)證,當(dāng)執(zhí)行到該函數(shù)時(shí),控制臺(tái)已經(jīng)輸出了 response 的狀態(tài)碼,因此排除這個(gè)分支。
    02   導(dǎo)致 for 循環(huán)退出的地方 for循環(huán)退出的地方有以下兩處。

    38900f04c08d834a7aacc3a4b21d4bd7.webp

    1. c.readRequest(ctx) 返回任意 err。
      1. 由于這里觸發(fā)的 err 產(chǎn)生的 context canceled 并不會(huì)觸發(fā)錯(cuò)誤日志 `responses.go:69 write response failed, error: context canceled` ,所以這個(gè)分支排除。
    2. req.Header.get("Expect") != ""。
      1. 由于出現(xiàn)503錯(cuò)誤的請(qǐng)求中,并沒(méi)有傳入這個(gè) Header 的 Key,所以這個(gè)分支排除。

    03   以上四個(gè)可疑點(diǎn),使用排除法后僅剩下唯一的觸發(fā)場(chǎng)景
          
            func (cr *connReader) handleReadError(_ error) {
          
          
               cr.conn.cancelCtx()
          
          
               cr.closeNotify()
          
          
            }
          
        
    我們可以在業(yè)務(wù)處理API里手動(dòng)增加 sleep X秒 ,然后客戶端在接收到 response 之前主動(dòng)取消,可以 100% 走到這個(gè)函數(shù)里。 而之所以出現(xiàn)503錯(cuò)誤,是因?yàn)?go-zero v1.2.2 版本中的 timeoutHandler 使用的是 net/http 標(biāo)準(zhǔn)庫(kù)中的函數(shù):
          
            func (h *timeoutHandler) ServeHTTP(w ResponseWriter, r *Request) {
          
          
               ctx := h.testContext
          
          
               if ctx == nil {
          
          
                  var cancelCtx context.CancelFunc
          
          
                  ctx, cancelCtx = context.WithTimeout(r.Context(), h.dt)
          
          
                  defer cancelCtx()
          
          
               }
          
          
               r = r.WithContext(ctx)
          
          
               done := make(chan struct{})
          
          
               tw := &timeoutWriter{
          
          
                  w:   w,
          
          
                  h:   make(Header),
          
          
                  req: r,
          
          
               }
          
          
               panicChan := make(chan interface{}, 1)
          
          
               go func() {
          
          
                  defer func() {
          
          
                     if p := recover(); p != nil {
          
          
                        panicChan <- p
          
          
                     }
          
          
                  }()
          
          
                  h.handler.ServeHTTP(tw, r)
          
          
                  close(done)
          
          
               }()
          
          
               select {
          
          
               case p := <-panicChan:
          
          
                  panic(p)
          
          
               case <-done:
          
          
                  tw.mu.Lock()
          
          
                  defer tw.mu.Unlock()
          
          
                  dst := w.Header()
          
          
                  for k, vv := range tw.h {
          
          
                     dst[k] = vv
          
          
                  }
          
          
                  if !tw.wroteHeader {
          
          
                     tw.code = StatusOK
          
          
                  }
          
          
                  w.WriteHeader(tw.code)
          
          
                  w.Write(tw.wbuf.Bytes())
          
          
               case <-ctx.Done():
          
          
                  tw.mu.Lock()
          
          
                  defer tw.mu.Unlock()
          
          
                  w.WriteHeader(StatusServiceUnavailable)
          
          
                  io.WriteString(w, h.errorBody())
          
          
                  tw.timedOut = true
          
          
               }
          
          
            }
          
        
    一旦執(zhí)行了 cr.conn.cancelCtx() 后,就會(huì)觸發(fā)這里的第40行 case <-ctx.Done(): 分支,并引發(fā) 503 錯(cuò)誤。

    雖然通過(guò)排除法定位到了問(wèn)題所在,但是還有 1 個(gè)疑惑遲遲未解,就是沒(méi)有在出現(xiàn)503的同時(shí)看到錯(cuò)誤:`responses.go:69 write response failed, error: context canceled`。無(wú)法 100% 還原遇到的情況。 于是,我找到了 responses.go:65 行 w.Write(bs) 的底層實(shí)現(xiàn)。
          
            func WriteJson(w http.ResponseWriter, code int, v interface{}) {
          
          
               w.Header().Set(ContentType, ApplicationJson)
          
          
               w.WriteHeader(code)
          
          
            
              

    if bs, err := json.Marshal(v); err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) } else if n, err := w.Write(bs); err != nil { // http.ErrHandlerTimeout has been handled by http.TimeoutHandler, // so it's ignored here. if err != http.ErrHandlerTimeout { logx.Errorf("write response failed, error: %s", err) } } else if n < len(bs) { logx.Errorf("actual bytes: %d, written bytes: %d", len(bs), n) } }
    在項(xiàng)目中的實(shí)現(xiàn)代碼(go 版本 v1.17.13)是:
          
            func (tw *timeoutWriter) Write(p []byte) (int, error) {
          
          
               tw.mu.Lock()
          
          
               defer tw.mu.Unlock()
          
          
               if tw.timedOut {
          
          
                  return 0, ErrHandlerTimeout
          
          
               }
          
          
               if !tw.wroteHeader {
          
          
                  tw.writeHeaderLocked(StatusOK)
          
          
               }
          
          
               return tw.wbuf.Write(p)
          
          
            }
          
        
    通過(guò)分析,這個(gè)函數(shù)不會(huì)導(dǎo)致拋出 context canceled 錯(cuò)誤,于是懷疑是 golang 標(biāo)準(zhǔn)庫(kù)的版本問(wèn)題。
    向 CI 組了解到目前 C I機(jī)器上固定使用 go 版本 v1.20 進(jìn)行編譯,于是找到這個(gè)版本下的這個(gè)函數(shù)代碼:
          
            func (tw *timeoutWriter) Write(p []byte) (int, error) {
          
          
                    tw.mu.Lock()
          
          
                    defer tw.mu.Unlock()
          
          
                    if tw.err != nil {
          
          
                            return 0, tw.err
          
          
                    }
          
          
                    if !tw.wroteHeader {
          
          
                            tw.writeHeaderLocked(StatusOK)
          
          
                    }
          
          
                    return tw.wbuf.Write(p)
          
          
            }
          
        
    4~6行就是拋出 context canceled 錯(cuò)誤的地方。 這段代碼的變更c(diǎn)ommit: https://github.com/golang/go/commit/4c7cafdd03426bc2b9fb1275d13d0abc755dde16
    變更的原因也是有人提了一個(gè)issue(https://github.com/golang/go/issues/48948),建議區(qū)分服務(wù)端超時(shí)與客戶端關(guān)閉,而不是統(tǒng)一作為服務(wù)端超時(shí)處理。
    然后使用 v1.20 進(jìn)行驗(yàn)證,完全復(fù)現(xiàn)了文章開頭提到的情況。

    好了,今天呢Z哥和你分享了我們近期遇到的一個(gè)問(wèn)題,也算是疑難雜癥吧。 最終的結(jié)論倒是次要的,關(guān)鍵是分析過(guò)程的思路。 希望對(duì)你有所啟發(fā)。
    如果你有哪些好的排查此類問(wèn)題的思路,歡迎找我交流哈。

    推薦閱讀:


    原創(chuàng)不易,如果你覺(jué)得這篇文章還不錯(cuò),就「 點(diǎn)贊 」或者「在看」一下吧,鼓勵(lì)我的創(chuàng)作 :)


    也可以分享我的公眾號(hào)名片給有需要的朋友們。

    如果你有關(guān)于軟件架構(gòu)、分布式系統(tǒng)、產(chǎn)品、運(yùn)營(yíng)的困惑

    可以試試點(diǎn)擊「閱讀原文

    瀏覽 154
    點(diǎn)贊
    評(píng)論
    收藏
    分享

    手機(jī)掃一掃分享

    分享
    舉報(bào)
    評(píng)論
    圖片
    表情
    推薦
    點(diǎn)贊
    評(píng)論
    收藏
    分享

    手機(jī)掃一掃分享

    分享
    舉報(bào)

    <kbd id="5sdj3"></kbd>
    <th id="5sdj3"></th>

  • <dd id="5sdj3"><form id="5sdj3"></form></dd>
    <td id="5sdj3"><form id="5sdj3"><big id="5sdj3"></big></form></td><del id="5sdj3"></del>

  • <dd id="5sdj3"></dd>
    <dfn id="5sdj3"></dfn>
  • <th id="5sdj3"></th>
    <tfoot id="5sdj3"><menuitem id="5sdj3"></menuitem></tfoot>

  • <td id="5sdj3"><form id="5sdj3"><menu id="5sdj3"></menu></form></td>
  • <kbd id="5sdj3"><form id="5sdj3"></form></kbd>
    天堂va欧美ⅴa亚洲va一夜 | 超碰在线图片 | 黄页网站免费在线观看 | 欧美AAAAA | 超碰99精品 |