我是一个着迷于产品和运营的技术人，乐于跨界的终身学习者。欢迎关注我哟～
当前处于不稳定更新状态
何时恢复「周更」未知……
我的第「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 抛出日志的代码位置

首先，找到源码中两个错误抛出的代码位置。

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

往 Reponse 写入数据时发生了 context canceled 错误。
并且 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 梳理请求如何被处理

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

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

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

如果启用了https，那么会走到这个函数，这个函数中会进行加密连接的“握手”。

这里不重要，因为这个函数没有变更当前上下文中的 ctx 变量，不会引发 context canceled 错误。

定义了一个 cancelCtx，赋值给了c.cancelCtx，同时覆写了 ctx 变量。意味着，出现的 context canceled 的场景出现了，有以下几个可能：

如果下面的 for 循环退出了，则会执行这个 cancelCtx，以取消所有基于ctx 变量的相关操作。
任何可以获取到 c.cancelCtx 变量的地方，可以执行 cancelCtx() 。

以 sync 方式从连接中读取请求。
调用handler链处理请求。

如果 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循环退出的地方有以下两处。

c.readRequest(ctx) 返回任意 err。

由于这里触发的 err 产生的 context canceled 并不会触发错误日志 `responses.go:69 write response failed, error: context canceled` ，所以这个分支排除。

req.Header.get("Expect") != ""。

由于出现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哥和你分享了我们近期遇到的一个问题，也算是疑难杂症吧。

最终的结论倒是次要的，关键是分析过程的思路。希望对你有所启发。

如果你有哪些好的排查此类问题的思路，欢迎找我交流哈。

也可以「关注」我，带你以技术思维看世界～

想更进一步和我一起玩耍，欢迎「搜索微信公号：跨界架构师」。

内容包括：架构设计丨分布式系统丨产品丨运营丨个人深度思考。

网站首页 > 技术文章正文

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

也可以「关注」我，带你以技术思维看世界～

想更进一步和我一起玩耍，欢迎「搜索微信公号：跨界架构师」。

猜你喜欢

网站首页 > 技术文章 正文

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

也可以「关注」我，带你以技术思维看世界～

想更进一步和我一起玩耍，欢迎「搜索微信公号：跨界架构师」。

猜你喜欢

网站首页 > 技术文章正文