echo
echo copied to clipboard
labstack
fatal error: concurrent map read and map write
Issue Description
Server fails if request context timeout happens and work duration has the same duration.
Checklist
- [+] Dependencies installed
- [+] No typos
- [+] Searched existing issues and docs
Expected behaviour
Expected http error at application logic level.
Actual behaviour
Panic inside timeout middleware handler.
Steps to reproduce
repeat several times this request:
curl -v 'http://localhost:7000/sleep/2?timeout=2s'
Working code to debug
package main
import (
"context"
"github.com/labstack/echo/v4"
"github.com/labstack/echo/v4/middleware"
"github.com/labstack/gommon/log"
"net/http"
"strconv"
"time"
)
func timeoutMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
return func(c echo.Context) error {
// Just to play easily with the middleware using a query parameter
timeout := 2 * time.Second
if t, err := time.ParseDuration(c.QueryParam("timeout")); err == nil {
timeout = t
}
c.Logger().Infof("timeout = %s", timeout.String())
// This is the context that controls the timeout. Its parent is the original
// http.Request context
ctx, cancel := context.WithTimeout(c.Request().Context(), timeout)
defer cancel() // releases resources if next(c) completes before timeout elapses
// A channel and a goroutine to run next(c) and know if its ends
done := make(chan error, 1)
go func() {
// This goroutine will not stop even this middleware timeouts,
// unless someone in the next(c) call chain handle ctx.Done() properly
c.SetRequest(c.Request().Clone(ctx))
done <- next(c)
}()
// The real timeout logic
select {
case <-ctx.Done():
return c.JSON(http.StatusGatewayTimeout, ctx.Err())
case err := <-done:
return err
}
}
}
func main() {
e := echo.New()
e.Logger.SetLevel(log.DEBUG)
e.Use(middleware.Logger())
e.GET("/notimeout", func(c echo.Context) error {
return c.String(200, "Good")
})
e.GET("/sleep/:duration", func(c echo.Context) error {
// This select make the trick of finish this request when the middleware timeouts
duration, err := strconv.Atoi(c.Param("duration"))
if err != nil {
return err
}
select {
case <-time.After(time.Duration(duration) * time.Second):
c.Logger().Info("Done")
return c.JSON(http.StatusOK, "Done")
case <-c.Request().Context().Done():
c.Logger().Info("Timeout")
return nil
}
}, timeoutMiddleware)
e.Logger.Fatal(e.Start("0:7000"))
}
Version/commit
github.com/labstack/echo/v4 v4.7.2
I can not recreate panic but I can see that when duration is same this code has race condition - both goroutines will write to response and therefore output contains response from timeout middleware and from handler. You need to make sure that when one of those goroutines end that writer is not writable anymore and later response is discarded.
Echos own timeout middleware addresses that. See https://github.com/labstack/echo/blob/master/middleware/timeout.go
➜ samples git:(dev) ✗ go run samples/timeout_echo.go
____ __
/ __/___/ / ___
/ _// __/ _ \/ _ \
/___/\__/_//_/\___/ v4.7.2
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
O\
⇨ http server started on [::]:7000
fatal error: concurrent map writes
goroutine 42 [running]:
runtime.throw({0x6adcba?, 0x10?})
/usr/local/go/src/runtime/panic.go:992 +0x71 fp=0xc000236db0 sp=0xc000236d80 pc=0x434dd1
runtime.mapassign_faststr(0x6aaba8?, 0x6aaba8?, {0x6aaba8, 0xc})
/usr/local/go/src/runtime/map_faststr.go:212 +0x39c fp=0xc000236e18 sp=0xc000236db0 pc=0x41433c
net/textproto.MIMEHeader.Set(...)
/usr/local/go/src/net/textproto/header.go:22
net/http.Header.Set(...)
/usr/local/go/src/net/http/header.go:40
github.com/labstack/echo/v4.(*context).writeContentType(0x10?, {0x6b1d3b, 0x1f})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/context.go:227 +0xc7 fp=0xc000236e68 sp=0xc000236e18 pc=0x6355c7
github.com/labstack/echo/v4.(*context).json(0xc000129040, 0xc8, {0x659700, 0x71ee70}, {0x0, 0x0})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/context.go:483 +0x47 fp=0xc000236eb0 sp=0xc000236e68 pc=0x635d67
github.com/labstack/echo/v4.(*context).JSON(0xc000129040, 0xc000013540?, {0x659700, 0x71ee70})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/context.go:493 +0xc8 fp=0xc000236ef8 sp=0xc000236eb0 pc=0x635ec8
main.main.func2({0x722d10, 0xc000129040})
/samples/timeout_echo.go:57 +0x186 fp=0xc000236f78 sp=0xc000236ef8 pc=0x63c9c6
main.timeoutMiddleware.func1.1()
/samples/timeout_echo.go:30 +0x91 fp=0xc000236fe0 sp=0xc000236f78 pc=0x63c791
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1571 +0x1 fp=0xc000236fe8 sp=0xc000236fe0 pc=0x4633a1
created by main.timeoutMiddleware.func1
/samples/timeout_echo.go:26 +0x1ca
goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x7f8c4ceb0818, 0x72)
/usr/local/go/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc000170400?, 0xc0000021a0?, 0x0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Accept(0xc000170400)
/usr/local/go/src/internal/poll/fd_unix.go:614 +0x22c
net.(*netFD).accept(0xc000170400)
/usr/local/go/src/net/fd_unix.go:172 +0x35
net.(*TCPListener).accept(0xc00000e4b0)
/usr/local/go/src/net/tcpsock_posix.go:139 +0x28
net.(*TCPListener).AcceptTCP(0xc00000e4b0)
/usr/local/go/src/net/tcpsock.go:275 +0x3d
github.com/labstack/echo/v4.tcpKeepAliveListener.Accept({0x43fa40?})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/echo.go:941 +0x1d
net/http.(*Server).Serve(0xc000178000, {0x7218b0, 0xc000010078})
/usr/local/go/src/net/http/server.go:3039 +0x385
github.com/labstack/echo/v4.(*Echo).Start(0xc000146240, {0x6a8f38, 0x6})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/echo.go:647 +0xce
main.main()
/samples/timeout_echo.go:64 +0xcb
goroutine 40 [runnable]:
encoding/json.(*encodeState).marshal(0xc000170580?, {0x677860?, 0x8db5c0?}, {0x0?, 0x1?})
/usr/local/go/src/encoding/json/encode.go:322 +0x15b
encoding/json.(*Encoder).Encode(0xc000208810, {0x677860, 0x8db5c0})
/usr/local/go/src/encoding/json/stream.go:206 +0x7e
github.com/labstack/echo/v4.DefaultJSONSerializer.Serialize({}, {0x722d10?, 0xc000129040?}, {0x677860, 0x8db5c0}, {0x0, 0x0})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/json.go:19 +0xc5
github.com/labstack/echo/v4.(*context).json(0xc000129040, 0x1f8, {0x677860, 0x8db5c0}, {0x0, 0x0})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/context.go:485 +0x8c
github.com/labstack/echo/v4.(*context).JSON(0xc000129040, 0xc000208988?, {0x677860, 0x8db5c0})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/context.go:493 +0xc8
main.timeoutMiddleware.func1({0x722d10, 0xc000129040})
/samples/timeout_echo.go:36 +0x28d
github.com/labstack/echo/v4.(*Echo).add.func1({0x722d10, 0xc000129040})
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/echo.go:520 +0x51
github.com/labstack/echo/v4.(*Echo).ServeHTTP(0xc000146240, {0x721ac0?, 0xc00022c1c0}, 0xc00021c600)
/home/andrew/go/pkg/mod/github.com/labstack/echo/[email protected]/echo.go:630 +0x3bc
net/http.serverHandler.ServeHTTP({0xc00020c630?}, {0x721ac0, 0xc00022c1c0}, 0xc00021c600)
/usr/local/go/src/net/http/server.go:2916 +0x43b
net/http.(*conn).serve(0xc00021e140, {0x721cb8, 0xc000109b30})
/usr/local/go/src/net/http/server.go:1966 +0x5d7
created by net/http.(*Server).Serve
/usr/local/go/src/net/http/server.go:3071 +0x4db
goroutine 41 [IO wait]:
internal/poll.runtime_pollWait(0x7f8c4ceb0728, 0x72)
/usr/local/go/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc00020e280?, 0xc00020c641?, 0x0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0xc00020e280, {0xc00020c641, 0x1, 0x1})
/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc00020e280, {0xc00020c641?, 0x0?, 0x0?})
/usr/local/go/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000212028, {0xc00020c641?, 0x0?, 0x0?})
/usr/local/go/src/net/net.go:183 +0x45
net/http.(*connReader).backgroundRead(0xc00020c630)
/usr/local/go/src/net/http/server.go:672 +0x3f
created by net/http.(*connReader).startBackgroundRead
/usr/local/go/src/net/http/server.go:668 +0xca
exit status 2
I've copied stacktrace. As I've understood - my code is incorrect at logic level - there are no bug in your library ?
In my opinion this problem is caused by sharing echo.Context instance between two goroutines and not making sure that writer used to respond header and body to client is only not usable after response has been sent.
Please see this writer https://github.com/labstack/echo/blob/61422dd7de9b0359708ff56b67099b91b5954c31/middleware/timeout.go#L187-L191
In current situation I think it is even possible that timeout middleware returns and Echo adds that echo.Context instance back to the pool and it is given out to some new request and then handler starts to write its response.
Timeout as middleware is quite complex thing to solve and if you happen to have some upstream server doing proxing (Apache/Nginx/some K8 ingress) it is easier to have them handle timeouting (503) long requests to the client.
closing, I think this is caused by writing to same writer from multiple goroutines