go-zero框架HttpCode 503错误与context canceled高相关性根因分析

共 10388字,需浏览 21分钟

 ·

2024-03-25 20:30

这里是Z哥的个人公众号

当前处于不稳定更新状态

何时恢复周更,未知……

我的第「232」篇原创敬上


大家好,我是Z哥。 好久不见,我今天强行逼自己上岗,来更新一篇。 9fd66951751cca4ed1c129d59edb82d0.webp前阵子团队内备战双11的时候出现了一个问题: 当流量瞬时激增时,API会出现大量 HttpCode 为 503 的错误。与此同时,发现另一个错误 `responses.go:69 write response failed, error: context canceled` 与该错误具有很强的相关性。这 2 个错误都由我们使用的 go-zero 框架内部抛出。 后来我花费了16个小时来搞清楚这个事情,在这里分享给大家。

/01 结论先行/ 我先讲结论: 以上 503 错误是由于客户端取消请求引发的,并非真正是 5xx 所定义的「服务端异常」相关的错误。前面提到的第 2 个错误就是表示「请求被取消」的意思。 go-zero 在 Dec 20, 2021 之后的版本(>= v1.2.5)中,增加了错误码 499(参考nginx 的状态码定义) 来专门表示这类错误,代替了原先的 503 错误码。 相关commit:https://github.com/zeromicro/go-zero/commit/4ba2ff7cdd34b73312f5ce17191068146bc676a0 由于我们项目中使用的版本为 v1.2.2 因此以错误码 503 输出。 解决方式也很简单,升级 go-zero 的版本。

下面是整个长达16小时的分析的过程。除了你可以了解具体的根因外,也欢迎你和我分享当你遇到类似情况时好用、高效的排查思路。
/02 why?/ 01   抛出日志的代码位置
首先,找到源码中两个错误抛出的代码位置。

1cdfa11bd5e4e2c1a8271bf1eb3f0f14.webp

8ee5f2eebbf4be62dcb94b81afa7d824.webp

以上输出错误日志的代码位置可以分析出场景为:
  1. 往 Reponse 写入数据时发生了 context canceled 错误。
  2. 并且 http code >= 500,则会记录error级别日志。以下是 isOkResponse 函数内的逻辑。
      
        func isOkResponse(code int) bool {
      
      
           // not server error
      
      
           return code < http.StatusInternalServerError
      
      
        }
      
    
根据debug中的 执行过程来看,代码的执行顺序就是上面的定义的序号,先1,再2。

虽然抛出日志的代码在 go-zero 框架内。但是,导致根因的关键代码都在 golang 标准库 net/http/server.go 中。 我们从作为一个 http server 是如何处理每一个请求的源头开始逐步梳理,以帮助我们搞清楚这件事。
02   梳理请求如何被处理

e6338ca7f680a0224c30a8b82c579adc.webp

关键代码是上面红框的部分,从上往下分别是:
  1. 以 sync 方式监听网络请求,并返回 net.Conn 对象。
  2. 服务端创建一个链接 conn 对象来承接这个客户端的请求。
  3. 以 async 方式建立连接。循环到 l.Accept() 函数继续监听网络请求。

1de5cd8f45778e13467323a1b1686ff4.webp

关键代码是上面红框的部分,从上往下分别是:
  1. 如果启用了https,那么会走到这个函数,这个函数中会进行加密连接的“握手”。
    1. 这里不重要,因为这个函数没有变更当前上下文中的 ctx 变量,不会引发 context canceled 错误。
  2. 定义了一个 cancelCtx,赋值给了c.cancelCtx,同时覆写了 ctx 变量。 意味着,出现的 context canceled 的场景出现了,有以下几个可能:
    1. 如果下面的 for 循环退出了,则会执行这个 cancelCtx,以取消 所有基于ctx 变量的相关操作。
    2. 任何可以获取到 c.cancelCtx 变量的地方,可以执行 cancelCtx() 。
  3. 以 sync 方式从连接中读取请求。
  4. 调用handler链处理请求。
    1. 如果 ServeHTTP 函数被执行完成,那么意味着请求被全部handler处理完成了,包括写业务代码的自定义 handler。

根据以上的逻辑分析,导致 context canceled 错误的范围从:
  • 开始: c.r = &connReader。
  • 结束: serverHandler{ c.server }.ServeHTTP(w, w.req) 之前。

/03 排除法缩小范围/ 01   执行 c.cancelCtx() 的地方 反向查找函数被使用的地方,可以找到两处调用  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()
      
      
        }
      
    
以上函数在客户端的Read返回非nil错误时被调用。 并且引导我们将任何错误视为连接已中断,关闭其上下文 因此会调用 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 }
以上函数在执行 w.c.rwc.Write(p) 时出现错误会记录到 w.c.werr 变量上,并调用 cancelCtx() 。 通过debug验证,当执行到该函数时,控制台已经输出了 response 的状态码,因此排除这个分支。
02   导致 for 循环退出的地方 for循环退出的地方有以下两处。

38900f04c08d834a7aacc3a4b21d4bd7.webp

  1. c.readRequest(ctx) 返回任意 err。
    1. 由于这里触发的 err 产生的 context canceled 并不会触发错误日志 `responses.go:69 write response failed, error: context canceled` ,所以这个分支排除。
  2. req.Header.get("Expect") != ""。
    1. 由于出现503错误的请求中,并没有传入这个 Header 的 Key,所以这个分支排除。

03   以上四个可疑点,使用排除法后仅剩下唯一的触发场景
      
        func (cr *connReader) handleReadError(_ error) {
      
      
           cr.conn.cancelCtx()
      
      
           cr.closeNotify()
      
      
        }
      
    
我们可以在业务处理API里手动增加 sleep X秒 ,然后客户端在接收到 response 之前主动取消,可以 100% 走到这个函数里。 而之所以出现503错误,是因为 go-zero v1.2.2 版本中的 timeoutHandler 使用的是 net/http 标准库中的函数:
      
        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
      
      
           }
      
      
        }
      
    
一旦执行了 cr.conn.cancelCtx() 后,就会触发这里的第40行 case <-ctx.Done(): 分支,并引发 503 错误。

虽然通过排除法定位到了问题所在,但是还有 1 个疑惑迟迟未解,就是没有在出现503的同时看到错误:`responses.go:69 write response failed, error: context canceled`。无法 100% 还原遇到的情况。 于是,我找到了 responses.go:65 行 w.Write(bs) 的底层实现。
      
        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) } }
在项目中的实现代码(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)
      
      
        }
      
    
通过分析,这个函数不会导致抛出 context canceled 错误,于是怀疑是 golang 标准库的版本问题。
向 CI 组了解到目前 C I机器上固定使用 go 版本 v1.20 进行编译,于是找到这个版本下的这个函数代码:
      
        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 错误的地方。 这段代码的变更commit: https://github.com/golang/go/commit/4c7cafdd03426bc2b9fb1275d13d0abc755dde16
变更的原因也是有人提了一个issue(https://github.com/golang/go/issues/48948),建议区分服务端超时与客户端关闭,而不是统一作为服务端超时处理。
然后使用 v1.20 进行验证,完全复现了文章开头提到的情况。

好了,今天呢Z哥和你分享了我们近期遇到的一个问题,也算是疑难杂症吧。 最终的结论倒是次要的,关键是分析过程的思路。 希望对你有所启发。
如果你有哪些好的排查此类问题的思路,欢迎找我交流哈。

推荐阅读:


原创不易,如果你觉得这篇文章还不错,就「 点赞 」或者「在看」一下吧,鼓励我的创作 :)


也可以分享我的公众号名片给有需要的朋友们。

如果你有关于软件架构、分布式系统、产品、运营的困惑

可以试试点击「阅读原文

浏览 76
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报
评论
图片
表情
推荐
点赞
评论
收藏
分享

手机扫一扫分享

分享
举报