Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Data Race in timeout middleware #1761

Closed
scraymondjr opened this issue Jan 22, 2021 · 4 comments · Fixed by #1801
Closed

Data Race in timeout middleware #1761

scraymondjr opened this issue Jan 22, 2021 · 4 comments · Fixed by #1801

Comments

@scraymondjr
Copy link

scraymondjr commented Jan 22, 2021

Issue Description

Timeout middleware added in #1684 fails data race detector when the handler tries to write to the response at same time as the context times out.

Checklist

  • [ x] Dependencies installed
  • [ x] No typos
  • [x ] Searched existing issues and docs

Expected behaviour

There should be no data race when writing the response in the downstream handler.

Actual behaviour

A data race is detected when writing the response at roughly the same time as the middleware times out.

Steps to reproduce

Working code to debug

// TestTimeoutDataRace shows a data race occurs if the handle func executes for same duration as specified timeout.
func TestTimeoutDataRace(t *testing.T) {
	t.Parallel()
	const timeout = 10 * time.Millisecond
	m := TimeoutWithConfig(TimeoutConfig{
		Timeout: timeout,
	})

	req := httptest.NewRequest(http.MethodGet, "/", nil)
	rec := httptest.NewRecorder()

	e := echo.New()
	c := e.NewContext(req, rec)

	const helloWorld = "Hello, World!"
	err := m(func(c echo.Context) error {
		time.Sleep(timeout)
		return c.String(http.StatusOK, helloWorld)
	})(c)

	assert.NoError(t, err)
	assert.Equal(t, http.StatusOK, rec.Code)
	assert.Equal(t, helloWorld, rec.Body.String())
}

execute with

$ go test -race -run TestTimeoutDataRace github.com/labstack/echo/v4/middleware

to see errors from data race detector.

Version/commit

7c8592a

@scraymondjr
Copy link
Author

Snippet of data race error output:

==================
WARNING: DATA RACE
Read at 0x00c000020080 by goroutine 8:
  github.com/labstack/echo/v4/middleware.TestTimeoutWithTimeout0()
      GOPATH/echo/middleware/timeout_test.go:60 +0x602
  testing.tRunner()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:909 +0x199

Previous write at 0x00c000020080 by goroutine 11:
  net/http/httptest.(*ResponseRecorder).WriteHeader()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/net/http/httptest/recorder.go:129 +0x5f
  github.com/labstack/echo/v4.(*Response).WriteHeader()
      GOPATH/echo/response.go:63 +0x137
  github.com/labstack/echo/v4.(*context).Blob()
      GOPATH/echo/context.go:559 +0x85
  github.com/labstack/echo/v4.(*context).String()
      GOPATH/echo/context.go:456 +0x9d
  github.com/labstack/echo/v4/middleware.TestTimeoutWithTimeout0.func1()
      GOPATH/echo/middleware/timeout_test.go:56 +0x70
  github.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1.1()
      GOPATH/echo/middleware/timeout.go:67 +0x47

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:960 +0x651
  testing.runTests.func1()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:1202 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:909 +0x199
  testing.runTests()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:1200 +0x521
  testing.(*M).Run()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:1117 +0x2ff
  main.main()
      _testmain.go:218 +0x223

Goroutine 11 (finished) created at:
  github.com/labstack/echo/v4/middleware.TimeoutWithConfig.func1.1()
      GOPATH/echo/middleware/timeout.go:64 +0x27f
  github.com/labstack/echo/v4/middleware.TestTimeoutWithTimeout0()
      GOPATH/echo/middleware/timeout_test.go:57 +0x5c3
  testing.tRunner()
      /usr/local/Cellar/go@1.13/1.13.10_1/libexec/src/testing/testing.go:909 +0x199
==================

@lammel
Copy link
Contributor

lammel commented Jan 31, 2021

Interesting bug and easily reproducable. Not that easy to fix though.

lammel added a commit to lammel/echo that referenced this issue Feb 7, 2021
Run with `go test -race -count 1 -timeout 10s -run ^TestTimeoutDataRace$ github.com/labstack/echo/v4/middleware`
@lammel lammel added this to the v4.2.1 milestone Feb 15, 2021
@aldas
Copy link
Contributor

aldas commented Mar 4, 2021

If we want to keep behavior ... that is:

when deadline is exceeded then requester will get error response but handler stays executing in their own coroutine

Problem is that we have 2 coroutines (original coroutine created by e.ServeHTTP listener loop and second one created in timeout middleware) and share same response writer in between those two. we would need to use io.MultiWriter maybe? justforfunc had video about similar stuff https://youtu.be/LHZ2CAZE6Gs Just spewing out ideas - not sure if it would work.

Actually. lets go back a little and think what we want to achieve. One of the original issues has this requirement

There are occasions when you want to add a timeout to your handlers, so they get finished within a specified period of time.

In my understanding this wording does no imply that original issue creator wanted to return early to requestor and let handler execute.
Maybe all we need is to cancel context in timeout middleware and send error to client - without executing next(c) in separate coroutine. Something like #1684 (comment) This would mean that developer has to actively handle context in their handlers and check ctx.Done() regularly or there will not be early timeout error for client. But if developer can do that - we would not need timeout middleware as all of this context with timeout could be created in handler also.

Also there is TimeoutHandler in net/http std package. Maybe this is what we are looking for as it does locking internally https://github.com/golang/go/blob/c015f76acb73990d4cb7fb056165b64d79b1b037/src/net/http/server.go#L3266

// TimeoutHandler returns a Handler that runs h with the given time limit.
//
// The new Handler calls h.ServeHTTP to handle each request, but if a
// call runs for longer than its time limit, the handler responds with
// a 503 Service Unavailable error and the given message in its body.
// (If msg is empty, a suitable default message will be sent.)
// After such a timeout, writes by h to its ResponseWriter will return
// ErrHandlerTimeout.
//
// TimeoutHandler supports the Pusher interface but does not support
// the Hijacker or Flusher interfaces.
func TimeoutHandler(h Handler, dt time.Duration, msg string) Handler {

@aldas
Copy link
Contributor

aldas commented Mar 4, 2021

Something like that

func TimeoutWithConfig(config TimeoutConfig) echo.MiddlewareFunc {
	// Defaults
	if config.Skipper == nil {
		config.Skipper = DefaultTimeoutConfig.Skipper
	}

	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			if config.Skipper(c) || config.Timeout == 0 {
				return next(c)
			}

			handlerWrapper := echoHandlerFuncWrapper{
				ctx:     c,
				handler: next,
				errChan: make(chan error, 1),
			}
			handler := http.TimeoutHandler(handlerWrapper, config.Timeout, config.ErrorMessage)
			handler.ServeHTTP(c.Response().Writer, c.Request())

			select {
			case err := <-handlerWrapper.errChan:
				return err
			default:
				return nil
			}
		}
	}
}

type echoHandlerFuncWrapper struct {
	ctx     echo.Context
	handler echo.HandlerFunc
	errChan chan error
}

func (t echoHandlerFuncWrapper) ServeHTTP(rw http.ResponseWriter, r *http.Request) {
	// replace writer with TimeoutHandler custom one. This will guarantee that
	// `writes by h to its ResponseWriter will return ErrHandlerTimeout.`
	originalWriter := t.ctx.Response().Writer
	t.ctx.Response().Writer = rw

	err := t.handler(t.ctx)
	t.ctx.Response().Writer = originalWriter
	if ctxErr := r.Context().Err(); ctxErr == context.DeadlineExceeded {
		return // on timeout we can not send handler error to client because `http.TimeoutHandler` has already sent headers
	}
	if err != nil {
		t.errChan <- err
	}
}
func main() {
	e := echo.New()

	e.Use(middleware.Logger())
	e.Use(middleware.TimeoutWithConfig(middleware.TimeoutConfig{
		Timeout: 1 * time.Second,
	}))

	e.GET("/", func(c echo.Context) error {
		time.Sleep(2 * time.Second)
		return c.String(http.StatusOK, "OK")
		//return echo.NewHTTPError(http.StatusForbidden, "nope")
	})

	e.Start(":8080")
}
x@x:~/code/echo$ time curl http://localhost:8080
Timeout! change me
real    0m1.012s
user    0m0.008s
sys     0m0.005s

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants