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