timeout
timeout copied to clipboard
gin-contrib
fatal error: concurrent map writes
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?
github.com/gin-contrib/timeout v0.0.3-0.20220106074521-2cfe50edf125
github.com/gin-gonic/gin v1.7.2
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
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:
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())
}
// 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
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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/logger.go:144 +0x2d0
github.com/gin-gonic/gin.LoggerWithConfig.func1(0x1400048e000)
/Users/zy/go/pkg/mod/github.com/gin-gonic/[email protected]/logger.go:267 +0x2a0
github.com/gin-gonic/gin.(*Context).Next(...)
/Users/zy/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0x14000119a00, 0x1400048e000)
/Users/zy/go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:620 +0x518
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0x14000119a00, {0x104b01998, 0x1400048a000}, 0x1400007e000)
/Users/zy/go/pkg/mod/github.com/gin-gonic/[email protected]/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
