fatal error: concurrent map writes

[xtony77]

If set the handler time.Sleep same as the timeout, there is a chance to reproduce this error!

api.GET("/test", timeout.New(
			timeout.WithTimeout(200*time.Microsecond),
			timeout.WithHandler(func(c *gin.Context) {
				time.Sleep(200*time.Microsecond)
				c.JSON(http.StatusOK, gin.H{
					"code": 200,
					"data": "",
				})
			}),
			timeout.WithResponse(func(c *gin.Context) {
				c.JSON(http.StatusRequestTimeout, gin.H{
					"code":    "408",
					"message": "test",
				})
			}),
		))

Here is gin panic code line:
https://github.com/gin-gonic/gin/blob/580e7da6eed01e2926de1240ec31f6473cd1a2af/render/render.go#L38

There is also a chance of combined http results:

{
    "code": 200,
    "data": ""
}{
    "code": "408",
    "message": "test"
}

I can't think of a solution at the moment, does anyone have any good ideas?

[appleboy]

What is your version?

[xtony77]

github.com/gin-contrib/timeout v0.0.3-0.20220106074521-2cfe50edf125
github.com/gin-gonic/gin v1.7.2

[appleboy]

@xtony77 I can't reproduce the issue

[xtony77]

I tried a few more times and still have a chance to reproduce the problem!
As you can see in the screenshot, although the http status code is 408, the http result is merged.

github.com/gin-gonic/gin v1.8.1
github.com/gin-contrib/timeout v0.0.3

[appleboy]

@xtony77 OK. I will take a look.

[KuanYuLai]

I was able to reproduce the bug but the chance is very rare for me. However, when I change the sleep duration of the code: 200 response, the chance to produce the fatal error: concurrent map writes error is higher.

Code:

	r.GET("/timeout", timeout.New(timeout.WithTimeout(200*time.Microsecond),
		timeout.WithHandler(func(c *gin.Context) {
			time.Sleep(199 * time.Microsecond)
			c.JSON(http.StatusOK, gin.H{
				"code": 200,
				"data": "",
			})
		}),
		timeout.WithResponse(func(c *gin.Context) {
			c.JSON(http.StatusRequestTimeout, gin.H{
				"code":    408,
				"message": "test",
			})
		})))

Error:

[marko1777]

if you use apach benchmark you can easily reproduce this issue
ab -n 3000 -c 500 localhost:8080/

func timeoutMiddleware() gin.HandlerFunc {
   return timeout.New(
   	timeout.WithTimeout(2*time.Second),
   	timeout.WithHandler(func(c *gin.Context) {
   		c.Next()
   	}),
   	timeout.WithResponse(testResponse),
   )
}

func main() {
   router := gin.Default()
   router.Use(timeoutMiddleware())
}

[x-lambda]

// Header will get response headers
func (w *Writer) Header() http.Header {
	for i := 0; i < 100000; i++ {
		w.headers["a"] = []string{"b"}
	}

	return w.headers
}

Actually, I use for{} write map When call Header(), it's 100% panic.

This proves that 2 gotoutine are operating with header in parallel

[zhyee]

Try below codes, it can stability reproduce this case:

package main

import (
	"log"
	"net/http"
	"time"

	"github.com/gin-contrib/timeout"
	"github.com/gin-gonic/gin"
)

func main() {
	g := gin.Default()
	g.Use(timeout.New(
		timeout.WithTimeout(time.Second),
		timeout.WithHandler(func(ctx *gin.Context) {
			ctx.Next()
		}),
	))

	g.GET("/", func(ctx *gin.Context) {
		for {
			ctx.Header("foo", "bar")
		}
	})

	serv := &http.Server{
		Addr:    ":1997",
		Handler: g,
	}

	if err := serv.ListenAndServe(); err != nil {
		log.Fatal(err)
	}
}

the crash output:

[GIN-debug] [WARNING] Creating an Engine instance with the Logger and Recovery middleware already attached.

[GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production.
 - using env:   export GIN_MODE=release
 - using code:  gin.SetMode(gin.ReleaseMode)

[GIN-debug] GET    /                         --> main.main.func2 (4 handlers)
fatal error: concurrent map writes

goroutine 3 [running]:
net/textproto.MIMEHeader.Set(...)
        /Users/zy/go/go1.23.0/src/net/textproto/header.go:22
net/http.Header.Set(...)
        /Users/zy/go/go1.23.0/src/net/http/header.go:40
github.com/gin-gonic/gin.(*Context).Header(0x1400048e000?, {0x1049a1777, 0x3}, {0x1049a177a, 0x3})
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/context.go:866 +0xb0
main.main.func2(0x1400048e000)
        /Users/zy/project/timeout-demo/main.go:23 +0x38
github.com/gin-gonic/gin.(*Context).Next(...)
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/context.go:174
main.main.func1(0x1400048e000)
        /Users/zy/project/timeout-demo/main.go:17 +0x44
github.com/gin-contrib/timeout.New.func1.1()
        /Users/zy/go/pkg/mod/github.com/gin-contrib/timeout@v1.0.1/timeout.go:55 +0x60
created by github.com/gin-contrib/timeout.New.func1 in goroutine 35
        /Users/zy/go/pkg/mod/github.com/gin-contrib/timeout@v1.0.1/timeout.go:49 +0x1c0

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x1051a4a48, 0x72)
        /Users/zy/go/go1.23.0/src/runtime/netpoll.go:351 +0xa0
internal/poll.(*pollDesc).wait(0x14000428200?, 0x10?, 0x0)
        /Users/zy/go/go1.23.0/src/internal/poll/fd_poll_runtime.go:84 +0x28
internal/poll.(*pollDesc).waitRead(...)
        /Users/zy/go/go1.23.0/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0x14000428200)
        /Users/zy/go/go1.23.0/src/internal/poll/fd_unix.go:620 +0x24c
net.(*netFD).accept(0x14000428200)
        /Users/zy/go/go1.23.0/src/net/fd_unix.go:172 +0x28
net.(*TCPListener).accept(0x1400041c740)
        /Users/zy/go/go1.23.0/src/net/tcpsock_posix.go:159 +0x28
net.(*TCPListener).Accept(0x1400041c740)
        /Users/zy/go/go1.23.0/src/net/tcpsock.go:372 +0x2c
net/http.(*Server).Serve(0x14000324ff0, {0x104b01a58, 0x1400041c740})
        /Users/zy/go/go1.23.0/src/net/http/server.go:3330 +0x294
net/http.(*Server).ListenAndServe(0x14000324ff0)
        /Users/zy/go/go1.23.0/src/net/http/server.go:3259 +0x84
main.main()
        /Users/zy/project/timeout-demo/main.go:32 +0x134

goroutine 35 [runnable]:
time.(*Location).get(0x10000000000)
        /Users/zy/go/go1.23.0/src/time/zoneinfo.go:91
time.Time.locabs({0xc1ac1d35b3b5ee28, 0x115c855d1, 0x104d4be40})
        /Users/zy/go/go1.23.0/src/time/time.go:494 +0x48
time.Time.appendFormat({0x1400048e000?, 0x104d4d5e0?, 0x104d4be40?}, {0x140001476b8, 0x0, 0x40}, {0x1049a9007, 0x15})
        /Users/zy/go/go1.23.0/src/time/format.go:668 +0x40
time.Time.AppendFormat({0x0?, 0x140001476f9?, 0x104d4be40?}, {0x140001476b8, 0x0, 0x40}, {0x1049a9007, 0x15})
        /Users/zy/go/go1.23.0/src/time/format.go:662 +0xf0
time.Time.Format({0x14000126840?, 0x0?, 0x104d4be40?}, {0x1049a9007?, 0x0?})
        /Users/zy/go/go1.23.0/src/time/format.go:648 +0xac
github.com/gin-gonic/gin.init.func1({0x1400007e000, {0xc1ac1d35b3b5ee28, 0x115c855d1, 0x104d4be40}, 0x198, 0x3babec64, {0x140005e6010, 0x9}, {0x1400000e0b0, 0x3}, ...})
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/logger.go:144 +0x2d0
github.com/gin-gonic/gin.LoggerWithConfig.func1(0x1400048e000)
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/logger.go:267 +0x2a0
github.com/gin-gonic/gin.(*Context).Next(...)
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/context.go:174
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0x14000119a00, 0x1400048e000)
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/gin.go:620 +0x518
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0x14000119a00, {0x104b01998, 0x1400048a000}, 0x1400007e000)
        /Users/zy/go/pkg/mod/github.com/gin-gonic/gin@v1.9.1/gin.go:576 +0x174
net/http.serverHandler.ServeHTTP({0x14000074030?}, {0x104b01998?, 0x1400048a000?}, 0x6?)
        /Users/zy/go/go1.23.0/src/net/http/server.go:3210 +0xbc
net/http.(*conn).serve(0x1400016a990, {0x104b021f0, 0x140004253b0})
        /Users/zy/go/go1.23.0/src/net/http/server.go:2092 +0x4fc
created by net/http.(*Server).Serve in goroutine 1
        /Users/zy/go/go1.23.0/src/net/http/server.go:3360 +0x3dc

goroutine 2 [IO wait]:
internal/poll.runtime_pollWait(0x1051a4940, 0x72)
        /Users/zy/go/go1.23.0/src/runtime/netpoll.go:351 +0xa0
internal/poll.(*pollDesc).wait(0x14000428280?, 0x14000074041?, 0x0)
        /Users/zy/go/go1.23.0/src/internal/poll/fd_poll_runtime.go:84 +0x28
internal/poll.(*pollDesc).waitRead(...)
        /Users/zy/go/go1.23.0/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0x14000428280, {0x14000074041, 0x1, 0x1})
        /Users/zy/go/go1.23.0/src/internal/poll/fd_unix.go:165 +0x1fc
net.(*netFD).Read(0x14000428280, {0x14000074041?, 0x0?, 0x0?})
        /Users/zy/go/go1.23.0/src/net/fd_posix.go:55 +0x28
net.(*conn).Read(0x14000102c48, {0x14000074041?, 0x0?, 0x0?})
        /Users/zy/go/go1.23.0/src/net/net.go:189 +0x34
net/http.(*connReader).backgroundRead(0x14000074030)
        /Users/zy/go/go1.23.0/src/net/http/server.go:690 +0x40
created by net/http.(*connReader).startBackgroundRead in goroutine 35
        /Users/zy/go/go1.23.0/src/net/http/server.go:686 +0xc4

Process finished with the exit code 2