gin detects `DATA RACE` with Go1.21, Go1.22

[georgehao]

Description

==================
WARNING: DATA RACE
Write at 0x00c0001ea020 by goroutine 50:
  github.com/gin-gonic/gin.(*Engine).ServeHTTP()
      /Users/xx/goproject/test/test/gin/gin.go:573 +0x174
  net/http.serverHandler.ServeHTTP()
      /Users/xx/sdk/go1.22.2/src/net/http/server.go:3137 +0x2a8
  net/http.(*conn).serve()
      /Users/xx/sdk/go1.22.2/src/net/http/server.go:2039 +0xf28
  net/http.(*Server).Serve.gowrap3()
      /Users/xx/sdk/go1.22.2/src/net/http/server.go:3285 +0x4c

Previous read at 0x00c0001ea020 by goroutine 45:
  github.com/gin-gonic/gin.(*Context).hasRequestContext()
      /Users/xx/goproject/test/test/gin/context.go:1186 +0x8c
  github.com/gin-gonic/gin.(*Context).Done()
      /Users/xx/goproject/test/test/gin/context.go:1200 +0x108
  database/sql.(*Rows).awaitDone()
      /Users/xx/sdk/go1.22.2/src/database/sql/sql.go:2991 +0x70
  database/sql.(*Rows).initContextClose.gowrap1()
      /Users/xx/sdk/go1.22.2/src/database/sql/sql.go:2977 +0x7c

How to reproduce

package main

import (
    "github.com/gin-gonic/gin"
    "github.com/go-resty/resty/v2"
    "gorm.io/driver/postgres"
    "gorm.io/gorm"
    "gorm.io/gorm/logger"
    "log"
    "net/http"
    "time"
)

type Test struct {
    db *gorm.DB `gorm:"column:-"`

    ID int   `gorm:"column:id"`
    T  int64 `gorm:"column:t"`
}

func (r *Test) TableName() string {
    return "test"
}

func main() {
    go func() {
        for {
            _, err := resty.New().R().Get("http://127.0.0.1:8080/ping")
            if err != nil {
                log.Println("get err", err.Error())
            }
            time.Sleep(time.Second)
        }
    }()

    dsn := "sql dsn"
    db, err := gorm.Open(postgres.Open(dsn), &gorm.Config{
        Logger: logger.Default.LogMode(logger.Info),
    })
    if err != nil {
        panic(err)
    }

    r := gin.Default()
    r.GET("/ping", func(c *gin.Context) {
        aa := Test{
            T: 10,
        }
        if err = db.WithContext(c).Create(&aa).Error; err != nil {
            log.Println("error", err)
            c.JSON(http.StatusBadRequest, err)
            return
        }

        c.JSON(http.StatusOK, gin.H{
            "message": "pong",
        })
    })
    r.Run() // listen and serve on 0.0.0.0:8080 (for windows "localhost:8080")
}

go run -race main.go

you will see the DATA RACE

The reason

1. When gin server starting, will call ServeHTTP. This a goroutine, allocates from go lib http https://github.com/gin-gonic/gin/blob/master/gin.go#L583C1-L592C2

   func (engine *Engine) ServeHTTP(w http.ResponseWriter, req *http.Request) {
   c := engine.pool.Get().(*Context)
   c.writermem.reset(w)
   c.Request = req
   c.reset()
   
   engine.handleHTTPRequest(c)
   
   engine.pool.Put(c)
   }

   can see that gin.Context allocate from sync.Pool

2. When call db

db.WithContext(c).Create(&aa)

gorm will call initContextClose finally. https://github.com/golang/go/blob/go1.20.14/src/database/sql/sql.go#L2916-L2941

go rs.awaitDone(ctx, txctx)

can see here initContextClose will start a goroutine to deal ctx, this ctx is gin.Context.

think one case: if go rs.awaitDone(ctx, txctx) run over after ServeHTTP goroutine. The gin.Context allocated from sync.Pool will be recovered and allocates for next request.

This really a data race

3. Why DATA RACE happens when go version large than go1.20?

I think go upgrade the race detector, the new race detector detects this.

Environment

• go version: 1.21.x, 1.22.x
• gin version (or commit ref):1.9.1
• operating system: all

[georgehao]

actually, this data race can avoid by pass ctx.Copy(). and this case is very hard to trigger, but for thread safe, it's better to consider it.

[kingcanfish]

Just a question, in what scenarios is it necessary to pass the Gin context into Gorm's? After all, Gorm is primarily used for controlling database-related operations, such as querying with timeouts. The context in Gin seems fundamentally different from the context in Gorm

[georgehao]

but the profiles I know are more SRE oriented, not really on protocol side.

yes, but sometimes developer will directly passes the gin.Context to db interface, it will becomes a issue. (I always pass like this)

[kbiits]

Wow, Good findings @georgehao

If I understand correctly, the race is happen between go rs.awaitDone(ctx, txctx) from sql package and the gin ServeHTTP that trying to serve new request comes in.

So, there are 2 goroutines run parallel.

The first one is from go rs.awaitDone(ctx, txctx) which trying to read *http.Request to get the context.Context from std http lib.

The second goroutine is from a new request comes in and got a same reference of gin.Context (previous request already marked as finished by gin and gin put the gin.Context back to the pool) trying to write the new http.Request to the gin.Context

[georgehao]

The second goroutine is from a new request comes in and got a same reference of gin.Context (previous request already marked as finished by gin and gin put the gin.Context back to the pool) trying to write the new http.Request to the gin.Context

Almost correct, only tweak a little. owing to rs.close(ctx.Err()) => ctx.Err() cause the data race.

[kbiits]

Almost correct, only tweak a little. owing to rs.close(ctx.Err()) => ctx.Err() cause the data race.

If I read your data race stack trace, the race comes from <-ctx.Done() which trying to call gin HasRequestContext reading the http.Request, but at the same time the new request trying to store new http.Request in same *gin.Context

[kbiits]

Oh my bad I didn't notice that the stacktrace shows the race comes from ctx.Err() that trying to read *gin.Context.Request

[tephrocactus]

Just pass c.Request.Context() instead of c (*gin.Context) itself.

db.WithContext(c.Request.Context())

Also consider not passing request's context to a DBMS transaction when performing INSERT/UPDATE/DELETE. Otherwise your transaction may rollback if request is canceled by client (by accidental page refresh, for example, if client is a web application). Create separate context with timeout instead.