timeout
timeout copied to clipboard
gin-contrib
Middleware crashes when handler completed and timed out at the same time
When a handler passed to timeout.WithHandler completed and the middleware timed out at the same time, the context writes both response bodies or panics due to concurrent writes.
Reproduction
package main
import (
"log"
"net/http"
"time"
"github.com/gin-contrib/timeout"
"github.com/gin-gonic/gin"
)
func testResponse(c *gin.Context) {
c.String(http.StatusRequestTimeout, `{"error": "timeout error"}`)
}
func timeoutMiddleware() gin.HandlerFunc {
return timeout.New(
timeout.WithTimeout(1*time.Second),
timeout.WithHandler(func(c *gin.Context) {
c.Next()
}),
timeout.WithResponse(testResponse),
)
}
func main() {
r := gin.New()
r.Use(timeoutMiddleware())
r.GET("/slow", func(c *gin.Context) {
time.Sleep(999*time.Millisecond + 500*time.Microsecond) // wait almost same as timeout
c.String(http.StatusRequestTimeout, `{"error": "handler error"}`)
})
if err := r.Run(":8080"); err != nil {
log.Fatal(err)
}
}
$ go run main.go
Result
response bodies
Approximately 15% responses has duplicated response body.
# statistics of 100 responses of the server above
$ for i in {1..100}; do curl -s localhost:8080/slow --output - >> result.txt; echo >> result.txt; done
$ cat result.txt | sort | uniq -c
6 {"error": "handler error"}
8 {"error": "handler error"}{"error": "timeout error"}
80 {"error": "timeout error"}
6 {"error": "timeout error"}{"error": "handler error"}
panic
Also, server sometimes crashes due to concurrent map writes.
Panic stacktraces (click to open)
fatal error: concurrent map writes
goroutine 9 [running]:
github.com/gin-gonic/gin/render.writeContentType({0x7f05a033b818?, 0xc000478100?}, {0xac9820, 0x1, 0x1})
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/render/render.go:39 +0x7f
github.com/gin-gonic/gin/render.WriteString({0x7f05a033b818?, 0xc000478100}, {0x7f4f0d, 0x1a}, {0x0, 0x0, 0x0})
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/render/text.go:34 +0x6f
github.com/gin-gonic/gin/render.String.Render(...)
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/render/text.go:24
github.com/gin-gonic/gin.(*Context).Render(0xc000478100, 0x198, {0x895858, 0xc0003ed950})
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:910 +0xf8
github.com/gin-gonic/gin.(*Context).String(...)
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:991
main.main.func1(0x0?)
/home/syuparn/middle/main.go:31 +0x77
github.com/gin-gonic/gin.(*Context).Next(...)
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:173
main.timeoutMiddleware.func1(0xc000478100)
/home/syuparn/middle/main.go:20 +0x2d
github.com/gin-contrib/timeout.New.func1.1()
/home/syuparn/go/pkg/mod/github.com/gin-contrib/[email protected]/timeout.go:55 +0x6d
created by github.com/gin-contrib/timeout.New.func1
/home/syuparn/go/pkg/mod/github.com/gin-contrib/[email protected]/timeout.go:49 +0x245
goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x7f05a02f6f08, 0x72)
/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc000412180?, 0x6?, 0x0)
/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000412180)
/usr/lib/go-1.19/src/internal/poll/fd_unix.go:614 +0x234
net.(*netFD).accept(0xc000412180)
/usr/lib/go-1.19/src/net/fd_unix.go:172 +0x35
net.(*TCPListener).accept(0xc000414150)
/usr/lib/go-1.19/src/net/tcpsock_posix.go:142 +0x28
net.(*TCPListener).Accept(0xc000414150)
/usr/lib/go-1.19/src/net/tcpsock.go:288 +0x3d
net/http.(*Server).Serve(0xc000470000, {0x895eb8, 0xc000414150})
/usr/lib/go-1.19/src/net/http/server.go:3070 +0x385
net/http.(*Server).ListenAndServe(0xc000470000)
/usr/lib/go-1.19/src/net/http/server.go:2999 +0x7d
net/http.ListenAndServe(...)
/usr/lib/go-1.19/src/net/http/server.go:3255
github.com/gin-gonic/gin.(*Engine).Run(0xc00044a680, {0xc00029ff50, 0x1, 0x1})
/home/syuparn/go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:382 +0x20e
main.main()
/home/syuparn/middle/main.go:33 +0xc9
goroutine 7 [runnable]:
context.removeChild({0x896778?, 0xc0003d7e40?}, {0x8949f8, 0xc0003d7f00})
/usr/lib/go-1.19/src/context/context.go:321 +0x9f
context.(*cancelCtx).cancel(0xc0003d7f00, 0x1, {0x8937e0, 0xc000016250})
/usr/lib/go-1.19/src/context/context.go:421 +0x265
context.WithCancel.func1()
/usr/lib/go-1.19/src/context/context.go:238 +0x30
net/http.(*conn).serve(0xc0003eb860, {0x896820, 0xc000404de0})
/usr/lib/go-1.19/src/net/http/server.go:1993 +0x628
created by net/http.(*Server).Serve
/usr/lib/go-1.19/src/net/http/server.go:3102 +0x4db
goroutine 8 [IO wait]:
internal/poll.runtime_pollWait(0x7f05a02f6e18, 0x72)
/usr/lib/go-1.19/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc0003da380?, 0xc0003ed811?, 0x0)
/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
/usr/lib/go-1.19/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0003da380, {0xc0003ed811, 0x1, 0x1})
/usr/lib/go-1.19/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0003da380, {0xc0003ed811?, 0xc00040e2d8?, 0xc000066768?})
/usr/lib/go-1.19/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000014b90, {0xc0003ed811?, 0xc0003ee3c0?, 0x0?})
/usr/lib/go-1.19/src/net/net.go:183 +0x45
net/http.(*connReader).backgroundRead(0xc0003ed800)
/usr/lib/go-1.19/src/net/http/server.go:678 +0x3f
created by net/http.(*connReader).startBackgroundRead
/usr/lib/go-1.19/src/net/http/server.go:674 +0xca
exit status 2
version
- github.com/gin-contrib/timeout v0.0.3
- github.com/gin-gonic/gin v1.8.1
- Go go1.19.1 linux/amd64
- running on WSL2/Windows11
concurrent writes occur when t.handler writes response just after c.Writer is changed for t.response().
https://github.com/gin-contrib/timeout/blob/master/timeout.go#L88
Since writer is changed to the original one, lock does not work on this line.
How about copying context before replacing Writer? In this case, t.handler cannot write to copied context's writer.
+ cc := c.Copy()
+ cc.Writer = w
+ t.response(cc)
- c.Writer = w
- t.response(c)
- c.Writer = tw