Context的错误使用引发Panic的问题复盘

发表于 更新于 分类于 阅读次数：

我们有这么一段业务代码，在 Gin 的 API Handler 中，开了一个子 goroutine 写 DB，代码大概是这样：

package main

import (
    "github.com/gin-gonic/gin"
    "gorm.io/gorm"
)

var db *gorm.DB

func ServerHandler(c *gin.Context) {
    // 一些旁路逻辑，为了不影响接口耗时，在子goroutine中执行
    go func() {
       db.WithContext(c).Exec("update xxx")
    }()
    // 一些后置逻辑
}

代码在测试阶段一直没啥问题，但是一上线立马出现了大面积的 panic。panic 的栈也非常奇怪，挂在了 mysql driver 里面：

panic: sync/atomic: store of nil value into Value
goroutine 357413 [running]:
sync/atomic.(*Value).Store(0xc004097ef0, {0x0,0x0})

/usr/local/go/src/sync/atomic/value.go:47 +0xeb
github.com/go-sql-driver/mysql.(*atomicError).Set(..)
/root/go/pkg/mod/github.com/go-sql-driver/mysql@v1.6.0/utils.go:831
github.com/go-sql-driver/mysql.(*mysqlConn).cancel(0xc004e6fc20, {0x0, 0x0})
/root/go/pkg/mod/github.com/go-sql-driver/mysql@v1.6.0/connection.go:435 +0x3d
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1()
/root/go/pkg/mod/github.com/go-sql-driver/mysql@v1.6.0/connection.go:622 +0x192
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
/root/go/pkg/mod/github.com/go-sql-driver/mysql@v1.6.0/connection.go:611 +0x105

把 mysql driver 相关栈的源码扒出来，大概是这样：

func (mc *mysqlConn) startWatcher() {
    watcher := make(chan context.Context, 1)
    mc.watcher = watcher
    finished := make(chan struct{})
    mc.finished = finished
    go func() {
       for {
          var ctx context.Context
          select {
          case ctx = <-watcher:
          case <-mc.closech:
             return
          }

          select {
          case <-ctx.Done():
             // 监听ctx.Done()
             mc.cancel(ctx.Err())
          case <-finished:
          case <-mc.closech:
             return
          }
       }
    }()
}

// finish is called when the query has canceled.
func (mc *mysqlConn) cancel(err error) {
	// 这里设置了原子变量
    mc.canceled.Set(err)
    mc.cleanup()
}

具体的故障现象大概明确了：

  1. mysql driver 里面监听了context.Done(), 当 channel 返回时，将ctx.Err()设置到原子变量里面。
  2. 问题就在于：context.Done()虽然返回了，ctx.Err()却是 nil。这就导致了在 set 原子变量时直接 panic 了。

这个问题非常难以理解，因为根据 context 的源码来看，只要context.Done()返回了，ctx.Err()就不可能是 nil。而且这个问题在测试环境无法复现，问题排查暂时陷入了僵局。

错误的 Context 使用

虽然 panic 的原因暂未查明，但是仔细看下这段业务逻辑，就可以看出来一些问题。

首先，我们需要知道这个 context 在什么时候会触发 Done，也就是什么时候 cancel 的。翻下 Golang HTTP Server 的源码，事情一目了然：

func (c *conn) serve(ctx context.Context) {
	...

	ctx, cancelCtx := context.WithCancel(ctx)
	c.cancelCtx = cancelCtx
	defer cancelCtx()

    // handle request
    ....
}

在开始处理请求之前，HTTP Server 会创建一个 context 对象，在请求处理结束之后，会自动 cancel 这个 context。

也就是说：当 API Handler 的处理逻辑完成返回的时候，context 会主动 cancel。此时即使子 goroutine 的处理逻辑还没结束，db 请求也会取消。按照 mysql driver 的逻辑，应该会抛出来一个context canceled的 Err。

翻了下测试环境的日志，的确有偶发的context canceled。 之所以不是必现，是因为子 goroutine 之后还有后置的处理逻辑。如果子 goroutine 的处理逻辑快于接口的后续处理逻辑，那这个 Err 就不会触发。

实际上，这里业务代码对 Context 使用上出现了错误：在这个场景下，子 goroutine 的逻辑处理的生命周期实际上是和父层的逻辑完全没有关系，我们不需要用同一个 context 强行把两个逻辑的生命周期保持一致。

在这种情况下，子 goroutine 中可以用context.Background()创建一个新的 context 对象 ，和外部接口主逻辑的 context 分离开，以免受到影响。

按照这个逻辑更改完成之后，测试环境没有了context canceled错误，线上服务也正常恢复了。

问题虽然得到了解决，但是 panic 的原因还没有完全查明，问题的阴影仍然持续笼罩着：

  1. 按照我们的推断，应该只会返回 error，不会出现 panic。
  2. 这个问题对于线上和测试环境应该没有什么区别，为什么错误的表现却不一样？

Gin 对 Context 的缓存

继续深扒下源码，这次找到了 Gin 对请求的处理过程：在每个处理过程中，都有对sync.Pool的使用。
对缓存的复用和清理一般是问题频发的根源，我们对这块着重进行了梳理，还真的找到了原因：

  1. gin.Context本质上是对c.Request.Context()的封装。所有对 Context 的 Done、Err 方法调用，都会转发给c.Request.Context()。
  2. gin 会利用sync.Pool对gin.Context进行对象复用。每次从sync.Pool拿到一个 gin.Context 对象的时候，都会重置其 Request 属性。
// ServeHTTP conforms to the http.Handler interface.
func (engine *Engine) ServeHTTP(w http.ResponseWriter, req *http.Request) {
    // engine.pool是sync.Pool
    c := engine.pool.Get().(*Context)
    c.writermem.reset(w)
    // 重置Request属性
    c.Request = req
    c.reset()

    engine.handleHTTPRequest(c)

    engine.pool.Put(c)
}
// Done returns nil (chan which will wait forever) when c.Request has no Context.
func (c *Context) Done() <-chan struct{} {
    return c.Request.Context().Done()
}

// Err returns nil when c.Request has no Context.
func (c *Context) Err() error {
    return c.Request.Context().Err()
}

梳理下来，所有的情况都可以得到解释。简单来说：请求 1 中开的子 goroutine 持有的 context 对象，会被请求 2 复用，造成并发问题。

存在这样一种 case：请求1的子goroutine，在ctx.Done返回，并且要准备取ctx.Err之前。context刚好被复用，并且新的请求还没有结束。

  • 请求 1 中开启了子 goroutine ，正在监听 ctx.Done。整个外部处理逻辑结束，触发 HTTP Server 内部的 context cancel。此时，子 goroutine 中的ctx.Done channel 返回，准备去取context.Err()。同时请求 2 到来，复用了 context 对象。
  • 因为线上环境请求非常频繁，context 对象会被立即复用。此时 context 对象的 Request 属性被替换成新的了，因为新的请求还在处理中， c.Request.Context().Err()当然会返回 nil

为什么测试环境很难复现： 测试环境请求非常稀疏：子 goroutine 在取ctx.Err()之前，如果没有其他请求到来并复用这个 context，是不会出现问题的。

怎么复现这个问题?

为了方便构造这种 case，我们需要复现两个充分必要条件：

  • 条件 1：两个请求复用同一个 context 对象。
  • 条件 2：请求 1 在处理 ctx.Err()之前的间隙，请求 2 复用其 context 对象，并重置 Request 对象。

对于条件 1，我们需要简单了解下 sync.Pool 的原理，具体可以看我的另外一篇博客 《深度分析 Golang sync.Pool 底层原理》：

  1. 禁用 GC: debug.SetGCPercent(0) 。因为每轮 GC 之后，sync.Pool 都会被强制清空。
  2. 设置 P 的个数为 1。因为sync.Pool会在每个 P 内部有一个私有对象和 localPool，只有设置为 1，才会保证一定可以复用上次请求的 context。

对于条件 2，其实只要请求 QPS 足够大，基本是可以必现的。我们使用 sleep 协调下两个请求，以模拟这种 case。代码如下：

package main

import (
    "context"
    "fmt"
    "net/http"
    "net/http/httptest"
    "runtime"
    "runtime/debug"
    "time"
    "github.com/gin-gonic/gin"
)

func createTestGinServer() *gin.Engine {
    router := gin.Default()
    router.ContextWithFallback = true

    router.GET("/test1", func(c *gin.Context) {
       // 打印地址，以确认两次拿到了context是不是同一个
       fmt.Printf("context Pointer address: %p\n", c)

       c.JSON(200, gin.H{
          "message": "Hello, World!",
       })

       go func() {
          select {
          case <-c.Done():
             // 等待2秒，保证新的请求到来，覆盖c.Request
             time.Sleep(2 * time.Second)
             if c.Err() == nil {
                panic("context is done, but c.Err() is nil")
             } else {
                fmt.Printf("context done , and err is %s\n", c.Err())
             }
          }
       }()
    })

    router.GET("/test2", func(c *gin.Context) {
       time.Sleep(3 * time.Second)

       c.JSON(200, gin.H{
          "message": "Hello, World!",
       })
    })

    return router
}

func callApi(router *gin.Engine, api string) {
    w := httptest.NewRecorder()
    req, _ := http.NewRequest("GET", api, nil)

    // 模拟http server的cancel逻辑
    ctx, cancelCtx := context.WithCancel(context.Background())
    defer cancelCtx()

    req = req.WithContext(ctx)
    router.ServeHTTP(w, req)
}

func main() {
    // 禁用GC，防止sync.Pool被清空
    debug.SetGCPercent(0)

    // 设置只有一个P，保证两次请求一定能复用同一个context对象
    runtime.GOMAXPROCS(1)

    router := createTestGinServer()

    callApi(router, "/test1")

    // sleep 1s，保证子goroutine一定启动了
    time.Sleep(1 * time.Second)

    // 重新一个耗时请求，模拟请求未结束的情况
    callApi(router, "/test2")

    time.Sleep(5 * time.Second)
}

总结

为了方便描述问题，这里还有个额外的情况没有说明：我们在使用 Gin 时开启了 ContextWithFallback，这是在是在Gin的v1.8.1版本引入的。

如果你的Gin版本在 v1.8.1 之前或者 v1.8.1 之后并开启了 ContextWithFallback，才会保证所有对gin.Context的Done()、Err() 函数的访问，全部转发给c.Request.Context() 。如果没有开启 ContextWithFallback, 实际上ctx.Done() channel 会永远阻塞, 并不会出现本文中的问题。

总结来说该问题的根源在于：不应该在子 goroutine 中继续使用gin.Context，即使不会 panic，也会导致高概率的context.Canceled错误。

我们之后应该如何避免：
方法一：其实可以将 gin 的 ContextWithFallback 设置为 false，这样这类问题都不会出现。
方法二：这种子 goroutine 的逻辑生命周期不需要和外部逻辑强行保持一致的 case， 直接利用context.Background创建一个新的 context 对象即可。
方法三：如果确实有场景需要在子 goroutine 中用 gin 的 Context，可以使用gin.Context.Copy函数复制出来一个新的 context 对象。