Middleware crashes when handler completed and timed out at the same time

Syuparn commented 1 year ago

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/gin@v1.8.1/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/gin@v1.8.1/render/text.go:34 +0x6f github.com/gin-gonic/gin/render.String.Render(...) /home/syuparn/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/render/text.go:24 github.com/gin-gonic/gin.(*Context).Render(0xc000478100, 0x198, {0x895858, 0xc0003ed950}) /home/syuparn/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/context.go:910 +0xf8 github.com/gin-gonic/gin.(*Context).String(...) /home/syuparn/go/pkg/mod/github.com/gin-gonic/gin@v1.8.1/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/gin@v1.8.1/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/timeout@v0.0.3/timeout.go:55 +0x6d created by github.com/gin-contrib/timeout.New.func1 /home/syuparn/go/pkg/mod/github.com/gin-contrib/timeout@v0.0.3/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/gin@v1.8.1/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

Syuparn commented 1 year ago

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.

Syuparn commented 1 year ago

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

gin-contrib / timeout