Timeout middleware should propagate context.Context on echo.Context http Request

[pafuent]

Issue Description

When the Timeout middleware is used and the timeout is reached, the http.Request Context propagated isn't properly cancelled.

Expected behavior

With the server example below this logs should be seen

{"time":"2021-07-06T00:05:08.341357-03:00","level":"INFO","prefix":"echo","file":"main.go","line":"23","message":"Start Log Job..."}
{"time":"2021-07-06T00:05:10.342116-03:00","level":"WARN","prefix":"echo","file":"main.go","line":"28","message":"Long Job Cancelled!!!"}
{"time":"2021-07-06T00:05:16.342187-03:00","level":"INFO","prefix":"echo","file":"main.go","line":"40","message":"Previous Long Middleware Finished!!!"}

Actual behavior

With the server example below this logs are seen

{"time":"2021-07-06T00:07:50.818216-03:00","level":"INFO","prefix":"echo","file":"main.go","line":"22","message":"Start Log Job..."}
{"time":"2021-07-06T00:07:54.819956-03:00","level":"INFO","prefix":"echo","file":"main.go","line":"25","message":"Long Job Finished!!!"}
{"time":"2021-07-06T00:07:58.819891-03:00","level":"INFO","prefix":"echo","file":"main.go","line":"39","message":"Previous Long Middleware Finished!!!"}

Steps to reproduce

Perform this request to the server example below

curl --request GET --url http://127.0.0.1:8080/ --header 'content-type: application/json'
Timeout!!!

Working code to debug

package main

import (
	"net/http"
	"time"

	"github.com/labstack/echo/v4"
	"github.com/labstack/echo/v4/middleware"
)

const longJobFinished string = "Long Job Finished!!!"

func main() {
	// Echo instance
	e := echo.New()
	e.Debug = true

	// Middleware
	e.Use(middleware.Recover())

	handlerFunc := func(c echo.Context) error {
		e.Logger.Info("Start Log Job...")
		select {
		case <-time.After(4 * time.Second):
			e.Logger.Info(longJobFinished)
		case <-c.Request().Context().Done():
			e.Logger.Warn("Long Job Cancelled!!!")
			return nil
		}
		return c.String(http.StatusOK, longJobFinished)
	}

	// This middleware that sleeps is needed because to avoid the original Request Context gets cancelled by Go stdlib
	// See https://golang.org/pkg/net/http/#Request.Context
	previousLongMiddleware := func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			next(c)
			time.Sleep(6 * time.Second)
			e.Logger.Info("Previous Long Middleware Finished!!!")
			return nil
		}
	}

	// Timeout handler middleware
	middlewareFunc := middleware.TimeoutWithConfig(middleware.TimeoutConfig{
		Timeout:      2 * time.Second,
		ErrorMessage: "Timeout!!!",
	})
	// Handler with timeout middleware
	e.GET("/", handlerFunc, previousLongMiddleware, middlewareFunc)

	// Start server
	e.Logger.Fatal(e.Start(":8080"))
}

Version/commit

4.3.0

[aldas]

I really think adding timeout middleware was a mistake and people are adding it without thinking to their apps. @pafuent could you review?

[aldas]

I have been thinking but have not investigated it but I suspect timeout could have data race. when timeout occurs coroutine that http.server created for Echo to call ServeHTTP will end and that coroutine Context will be released to pool. Now coroutine that timeout created still has pointer to that Context and could use that even after that same Context is taken out of pool for next requests. Even though context will get reset every request it would be problematic if you call methods on that instance that now write to new io.writer and output stuff to client.

[pafuent]

I think you are right. Maybe we can try to clone the Context before passing it to the goroutine, and because that gouroutine is not intended to pass information back into the context to "upper" middlewares in the chain it would be OK if it is a copy and not the original.