From 7f502b1ff10913aeab28abab64f2bf45952c768d Mon Sep 17 00:00:00 2001 From: pwli Date: Mon, 23 Aug 2021 01:25:09 +0800 Subject: [PATCH] try to fix #1905 and add some notes (#1947) * fix 1905 and add some notes (cherry picked from commit 9d96199e2dbb6d4374b5a8b6e16fdc0b0d7cb3a7) * fix typo (cherry picked from commit e8ea1bcabb6cdb50b06e1ec0e7c3cce44287d8b7) * Add tests for timeout middleware with full http.Server stack running. Add warning about middleware * Fix example Co-authored-by: lipengwei Co-authored-by: toimtoimtoim --- middleware/timeout.go | 60 ++++++++++++++++- middleware/timeout_test.go | 128 +++++++++++++++++++++++++++++++++++++ 2 files changed, 185 insertions(+), 3 deletions(-) diff --git a/middleware/timeout.go b/middleware/timeout.go index 731136541..768ef8d70 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.SetRequest(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,13 +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 - t.ctx.Response().Writer = originalWriter 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 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 + } +}