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

这里是Z哥的个人公众号

当前处于不稳定更新状态

何时恢复周更，未知……

我的第「232」篇原创敬上

大家好，我是Z哥。 好久不见，我今天强行逼自己上岗，来更新一篇。 前阵子团队内备战双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   抛出日志的代码位置
首先，找到源码中两个错误抛出的代码位置。

以上输出错误日志的代码位置可以分析出场景为：

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   梳理请求如何被处理

关键代码是上面红框的部分，从上往下分别是：

1. 以 sync 方式监听网络请求，并返回 net.Conn 对象。
2. 服务端创建一个链接 conn 对象来承接这个客户端的请求。
3. 以 async 方式建立连接。循环到 l.Accept() 函数继续监听网络请求。

关键代码是上面红框的部分，从上往下分别是：

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.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()
      
      
        }
      
    

以上函数在客户端的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循环退出的地方有以下两处。

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

推荐阅读：

• 保姆级教程，golang熔断实践
  

• 「任务拆分」，被低估的要事
  

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

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

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

可以试试点击「阅读原文」