From 626a4f1f27c7280d062b1afa37ec03e49dc532e4 Mon Sep 17 00:00:00 2001 From: lipengwei Date: Mon, 2 Aug 2021 15:04:50 +0800 Subject: [PATCH 1/4] fix 1905 and add some notes (cherry picked from commit 9d96199e2dbb6d4374b5a8b6e16fdc0b0d7cb3a7) --- middleware/timeout.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/middleware/timeout.go b/middleware/timeout.go index 731136541..507557a24 100644 --- a/middleware/timeout.go +++ b/middleware/timeout.go @@ -116,13 +116,19 @@ func (t echoHandlerFuncWrapper) ServeHTTP(rw http.ResponseWriter, r *http.Reques // we restore original writer only for cases we did not timeout. On timeout we have already sent response to client // and should not anymore send additional headers/data // so on timeout writer stays what http.TimeoutHandler uses and prevents writing headers/body - t.ctx.Response().Writer = originalWriter + // https://github.com/labstack/echo/issues/1905 + // error handling is a part of processes in Echo handler, if a handler returns an error + // and if it did not timeout, the global error handler shall act on rw (`http.timeoutWriter` in our case) + // to avoid superfluous response.WriteHeader call if err != nil { // call global error handler to write error to the client. This is needed or `http.TimeoutHandler` will send status code by itself // and after that our tries to write status code will not work anymore t.ctx.Error(err) // we pass error from handler to middlewares up in handler chain to act on it if needed. But this means that // global error handler is probably be called twice as `t.ctx.Error` already does that. + // NB: later call of thr global error handler will not take any effect, as echo.Response will be marked as `committed` + // when the first call take place. + t.ctx.Response().Writer = originalWriter t.errChan <- err } } From bd81593e706749c489c86e0eb29832c02d96e7bc Mon Sep 17 00:00:00 2001 From: lipengwei Date: Mon, 2 Aug 2021 15:35:03 +0800 Subject: [PATCH 2/4] fix typo (cherry picked from commit e8ea1bcabb6cdb50b06e1ec0e7c3cce44287d8b7) --- middleware/timeout.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/middleware/timeout.go b/middleware/timeout.go index 507557a24..94049a0f0 100644 --- a/middleware/timeout.go +++ b/middleware/timeout.go @@ -126,7 +126,7 @@ func (t echoHandlerFuncWrapper) ServeHTTP(rw http.ResponseWriter, r *http.Reques t.ctx.Error(err) // we pass error from handler to middlewares up in handler chain to act on it if needed. But this means that // global error handler is probably be called twice as `t.ctx.Error` already does that. - // NB: later call of thr global error handler will not take any effect, as echo.Response will be marked as `committed` + // NB: later call of the global error handler will not take any effect, as echo.Response will be marked as `committed` // when the first call take place. t.ctx.Response().Writer = originalWriter t.errChan <- err From 395acafa08e4d4b5c6e016e3331d2c90793f70e7 Mon Sep 17 00:00:00 2001 From: toimtoimtoim Date: Sun, 22 Aug 2021 19:44:29 +0300 Subject: [PATCH 3/4] Add tests for timeout middleware with full http.Server stack running. Add warning about middleware --- middleware/timeout.go | 66 ++++++++++++++++--- middleware/timeout_test.go | 128 +++++++++++++++++++++++++++++++++++++ 2 files changed, 185 insertions(+), 9 deletions(-) diff --git a/middleware/timeout.go b/middleware/timeout.go index 94049a0f0..e33085757 100644 --- a/middleware/timeout.go +++ b/middleware/timeout.go @@ -8,6 +8,53 @@ import ( "github.com/labstack/echo/v4" ) +// --------------------------------------------------------------------------------------------------------------- +// WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING +// WARNING: Timeout middleware causes more problems than it solves. +// WARNING: This middleware should be first middleware as it messes with request Writer and could cause data race if +// it is in other position +// +// Depending on out requirements you could be better of setting timeout to context and +// check its deadline from handler. +// +// For example: create middleware to set timeout to context +// func RequestTimeout(timeout time.Duration) echo.MiddlewareFunc { +// return func(next echo.HandlerFunc) echo.HandlerFunc { +// return func(c echo.Context) error { +// timeoutCtx, cancel := context.WithTimeout(c.Request().Context(), timeout) +// c.Request().WithContext(timeoutCtx) +// defer cancel() +// return next(c) +// } +// } +//} +// +// Create handler that checks for context deadline and runs actual task in separate coroutine +// Note: separate coroutine may not be even if you do not want to process continue executing and +// just want to stop long-running handler to stop and you are using "context aware" methods (ala db queries with ctx) +// e.GET("/", func(c echo.Context) error { +// +// doneCh := make(chan error) +// go func(ctx context.Context) { +// doneCh <- myPossiblyLongRunningBackgroundTaskWithCtx(ctx) +// }(c.Request().Context()) +// +// select { // wait for task to finish or context to timeout/cancelled +// case err := <-doneCh: +// if err != nil { +// return err +// } +// return c.String(http.StatusOK, "OK") +// case <-c.Request().Context().Done(): +// if c.Request().Context().Err() == context.DeadlineExceeded { +// return c.String(http.StatusServiceUnavailable, "timeout") +// } +// return c.Request().Context().Err() +// } +// +// }) +// + type ( // TimeoutConfig defines the config for Timeout middleware. TimeoutConfig struct { @@ -116,19 +163,20 @@ func (t echoHandlerFuncWrapper) ServeHTTP(rw http.ResponseWriter, r *http.Reques // we restore original writer only for cases we did not timeout. On timeout we have already sent response to client // and should not anymore send additional headers/data // so on timeout writer stays what http.TimeoutHandler uses and prevents writing headers/body - // https://github.com/labstack/echo/issues/1905 - // error handling is a part of processes in Echo handler, if a handler returns an error - // and if it did not timeout, the global error handler shall act on rw (`http.timeoutWriter` in our case) - // to avoid superfluous response.WriteHeader call if err != nil { - // call global error handler to write error to the client. This is needed or `http.TimeoutHandler` will send status code by itself - // and after that our tries to write status code will not work anymore + // Error must be written into Writer created in `http.TimeoutHandler` so to get Response into `commited` state. + // So call global error handler to write error to the client. This is needed or `http.TimeoutHandler` will send + // status code by itself and after that our tries to write status code will not work anymore and/or create errors in + // log about `superfluous response.WriteHeader call from` t.ctx.Error(err) // we pass error from handler to middlewares up in handler chain to act on it if needed. But this means that // global error handler is probably be called twice as `t.ctx.Error` already does that. - // NB: later call of the global error handler will not take any effect, as echo.Response will be marked as `committed` - // when the first call take place. - t.ctx.Response().Writer = originalWriter + + // NB: later call of the global error handler or middlewares will not take any effect, as echo.Response will be + // already marked as `committed` because we called global error handler above. + t.ctx.Response().Writer = originalWriter // make sure we restore before we signal original coroutine about the error t.errChan <- err + return } + t.ctx.Response().Writer = originalWriter } diff --git a/middleware/timeout_test.go b/middleware/timeout_test.go index 80891e829..aa6402b8d 100644 --- a/middleware/timeout_test.go +++ b/middleware/timeout_test.go @@ -1,7 +1,12 @@ package middleware import ( + "bytes" "errors" + "fmt" + "io/ioutil" + "log" + "net" "net/http" "net/http/httptest" "net/url" @@ -313,3 +318,126 @@ func TestTimeoutCanHandleContextDeadlineOnNextHandler(t *testing.T) { assert.Equal(t, "Timeout! change me", rec.Body.String()) assert.False(t, <-handlerFinishedExecution) } + +func TestTimeoutWithFullEchoStack(t *testing.T) { + // test timeout with full http server stack running, do see what http.Server.ErrorLog contains + var testCases = []struct { + name string + whenPath string + expectStatusCode int + expectResponse string + expectLogContains []string + expectLogNotContains []string + }{ + { + name: "404 - write response in global error handler", + whenPath: "/404", + expectResponse: "{\"message\":\"Not Found\"}\n", + expectStatusCode: http.StatusNotFound, + expectLogNotContains: []string{"echo:http: superfluous response.WriteHeader call from"}, + expectLogContains: []string{`"status":404,"error":"code=404, message=Not Found"`}, + }, + { + name: "418 - write response in handler", + whenPath: "/", + expectResponse: "{\"message\":\"OK\"}\n", + expectStatusCode: http.StatusTeapot, + expectLogNotContains: []string{"echo:http: superfluous response.WriteHeader call from"}, + expectLogContains: []string{`"status":418,"error":"",`}, + }, + { + name: "503 - handler timeouts, write response in timeout middleware", + whenPath: "/?delay=50ms", + expectResponse: "Timeout

Timeout

", + expectStatusCode: http.StatusServiceUnavailable, + expectLogNotContains: []string{ + "echo:http: superfluous response.WriteHeader call from", + "{", // means that logger was not called. + }, + }, + } + + e := echo.New() + + buf := new(bytes.Buffer) + e.Logger.SetOutput(buf) + + // NOTE: timeout middleware is first as it changes Response.Writer and causes data race for logger middleware if it is not first + // FIXME: I have no idea how to fix this without adding mutexes. + e.Use(TimeoutWithConfig(TimeoutConfig{ + Timeout: 15 * time.Millisecond, + })) + e.Use(Logger()) + e.Use(Recover()) + + e.GET("/", func(c echo.Context) error { + var delay time.Duration + if err := echo.QueryParamsBinder(c).Duration("delay", &delay).BindError(); err != nil { + return err + } + if delay > 0 { + time.Sleep(delay) + } + return c.JSON(http.StatusTeapot, map[string]string{"message": "OK"}) + }) + + server, addr, err := startServer(e) + if err != nil { + assert.NoError(t, err) + return + } + defer server.Close() + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + buf.Reset() // this is design this can not be run in parallel + + res, err := http.Get(fmt.Sprintf("http://%v%v", addr, tc.whenPath)) + if err != nil { + assert.NoError(t, err) + return + } + + assert.Equal(t, tc.expectStatusCode, res.StatusCode) + if body, err := ioutil.ReadAll(res.Body); err == nil { + assert.Equal(t, tc.expectResponse, string(body)) + } else { + assert.Fail(t, err.Error()) + } + + logged := buf.String() + for _, subStr := range tc.expectLogContains { + assert.True(t, strings.Contains(logged, subStr)) + } + for _, subStr := range tc.expectLogNotContains { + assert.False(t, strings.Contains(logged, subStr)) + } + }) + } +} + +func startServer(e *echo.Echo) (*http.Server, string, error) { + l, err := net.Listen("tcp", ":0") + if err != nil { + return nil, "", err + } + + s := http.Server{ + Handler: e, + ErrorLog: log.New(e.Logger.Output(), "echo:", 0), + } + + errCh := make(chan error) + go func() { + if err := s.Serve(l); err != http.ErrServerClosed { + errCh <- err + } + }() + + select { + case <-time.After(10 * time.Millisecond): + return &s, l.Addr().String(), nil + case err := <-errCh: + return nil, "", err + } +} From c30229036e8332ab195795927374673b40bac5b3 Mon Sep 17 00:00:00 2001 From: toimtoimtoim Date: Sun, 22 Aug 2021 19:47:59 +0300 Subject: [PATCH 4/4] Fix example --- middleware/timeout.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/middleware/timeout.go b/middleware/timeout.go index e33085757..768ef8d70 100644 --- a/middleware/timeout.go +++ b/middleware/timeout.go @@ -22,7 +22,7 @@ import ( // return func(next echo.HandlerFunc) echo.HandlerFunc { // return func(c echo.Context) error { // timeoutCtx, cancel := context.WithTimeout(c.Request().Context(), timeout) -// c.Request().WithContext(timeoutCtx) +// c.SetRequest(c.Request().WithContext(timeoutCtx)) // defer cancel() // return next(c) // }