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

[Syuparn]

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

[Syuparn]

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]

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