try to fix #1905 and add some notes (#1947)

* fix 1905 and add some notes

(cherry picked from commit 9d96199)

* fix typo

(cherry picked from commit e8ea1bc)

* Add tests for timeout middleware with full http.Server stack running.
Add warning about middleware

* Fix example

Co-authored-by: lipengwei <[email protected]>
Co-authored-by: toimtoimtoim <[email protected]>

Author: 3 people

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
 }

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:   "<html><head><title>Timeout</title></head><body><h1>Timeout</h1></body></html>",
+			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
+	}
+}