go-zero框架HttpCode 503錯(cuò)誤與context canceled高相關(guān)性根因分析
這里是Z哥的個(gè)人公眾號(hào)
當(dāng)前處于不穩(wěn)定更新?tīng)顟B(tài)
何時(shí)恢復(fù)周更,未知……
我的第「232」篇原創(chuàng)敬上
前陣子團(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ò)誤拋出的代碼位置。


- 往 Reponse 寫入數(shù)據(jù)時(shí)發(fā)生了 context canceled 錯(cuò)誤。
- 并且 http code >= 500,則會(huì)記錄error級(jí)別日志。以下是 isOkResponse 函數(shù)內(nèi)的邏輯。
根據(jù)debug中的 執(zhí)行過(guò)程來(lái)看,代碼的執(zhí)行順序就是上面的定義的序號(hào),先1,再2。func isOkResponse(code int) bool {// not server errorreturn code < http.StatusInternalServerError}
雖然拋出日志的代碼在 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)求如何被處理

- 以 sync 方式監(jiān)聽(tīng)網(wǎng)絡(luò)請(qǐng)求,并返回 net.Conn 對(duì)象。
- 服務(wù)端創(chuàng)建一個(gè)鏈接 conn 對(duì)象來(lái)承接這個(gè)客戶端的請(qǐng)求。
- 以 async 方式建立連接。循環(huán)到 l.Accept() 函數(shù)繼續(xù)監(jiān)聽(tīng)網(wǎng)絡(luò)請(qǐng)求。

- 如果啟用了https,那么會(huì)走到這個(gè)函數(shù),這個(gè)函數(shù)中會(huì)進(jìn)行加密連接的“握手”。
- 這里不重要,因?yàn)檫@個(gè)函數(shù)沒(méi)有變更當(dāng)前上下文中的 ctx 變量,不會(huì)引發(fā) context canceled 錯(cuò)誤。
- 定義了一個(gè) cancelCtx,賦值給了c.cancelCtx,同時(shí)覆寫了 ctx 變量。 意味著,出現(xiàn)的 context canceled 的場(chǎng)景出現(xiàn)了,有以下幾個(gè)可能:
- 如果下面的 for 循環(huán)退出了,則會(huì)執(zhí)行這個(gè) cancelCtx,以取消 所有基于ctx 變量的相關(guān)操作。
- 任何可以獲取到 c.cancelCtx 變量的地方,可以執(zhí)行 cancelCtx() 。
- 以 sync 方式從連接中讀取請(qǐng)求。
- 調(diào)用handler鏈處理請(qǐng)求。
- 如果 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() 的代碼。
以上函數(shù)在客戶端的Read返回非nil錯(cuò)誤時(shí)被調(diào)用。 并且引導(dǎo)我們將任何錯(cuò)誤視為連接已中斷,關(guān)閉其上下文 。 因此會(huì)調(diào)用 cancelCtx()。-- server.go 的 739行// 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ù)在執(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è)分支。-- 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 = errw.c.cancelCtx()}return}
02 導(dǎo)致 for 循環(huán)退出的地方 for循環(huán)退出的地方有以下兩處。

- c.readRequest(ctx) 返回任意 err。
- 由于這里觸發(fā)的 err 產(chǎn)生的 context canceled 并不會(huì)觸發(fā)錯(cuò)誤日志 `responses.go:69 write response failed, error: context canceled` ,所以這個(gè)分支排除。
- req.Header.get("Expect") != ""。
- 由于出現(xiàn)503錯(cuò)誤的請(qǐng)求中,并沒(méi)有傳入這個(gè) Header 的 Key,所以這個(gè)分支排除。
03 以上四個(gè)可疑點(diǎn),使用排除法后僅剩下唯一的觸發(fā)場(chǎng)景
我們可以在業(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 (cr *connReader) handleReadError(_ error) {cr.conn.cancelCtx()cr.closeNotify()}
一旦執(zhí)行了 cr.conn.cancelCtx() 后,就會(huì)觸發(fā)這里的第40行 case <-ctx.Done(): 分支,并引發(fā) 503 錯(cuò)誤。func (h *timeoutHandler) ServeHTTP(w ResponseWriter, r *Request) {ctx := h.testContextif ctx == nil {var cancelCtx context.CancelFuncctx, 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}}
雖然通過(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)。
在項(xiàng)目中的實(shí)現(xiàn)代碼(go 版本 v1.17.13)是: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)}}
通過(guò)分析,這個(gè)函數(shù)不會(huì)導(dǎo)致拋出 context canceled 錯(cuò)誤,于是懷疑是 golang 標(biāo)準(zhǔn)庫(kù)的版本問(wèn)題。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)}
向 CI 組了解到目前 C I機(jī)器上固定使用 go 版本 v1.20 進(jìn)行編譯,于是找到這個(gè)版本下的這個(gè)函數(shù)代碼:
4~6行就是拋出 context canceled 錯(cuò)誤的地方。 這段代碼的變更c(diǎn)ommit: https://github.com/golang/go/commit/4c7cafdd03426bc2b9fb1275d13d0abc755dde16func (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)}
變更的原因也是有人提了一個(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)擊「閱讀原文」
評(píng)論
圖片
表情
