Echo Timeout middleware returning multiple responses for a single request on another handler

[afdalwahyu]

We’ve encountered an issue where multiple unexpected responses are returned when using the Timeout middleware on a single handler.

Example code:

package main

import (
	"net/http"
	"time"

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

func main() {
	e := echo.New()

	e.GET("/built-in-mdw", func(c echo.Context) error {
		time.Sleep(time.Second)

		return c.String(http.StatusOK, "built-in-mdw: param counter = "+c.QueryParam("counter"))
	}, middleware.TimeoutWithConfig(middleware.TimeoutConfig{
		Timeout: 500 * time.Millisecond,
	}))

	e.GET("/health", func(c echo.Context) error {
		time.Sleep(100 * time.Millisecond)
		return c.String(http.StatusOK, "healthz: OK")
	})

	e.Logger.Fatal(e.Start(":1323"))
}

How to test:

1. In the first terminal, run:

$> i=1; while :; do echo -n $i; curl "localhost:1323/built-in-mdw?counter=$i"; i=$((i+1)); done

2. In the second terminal, run:

i=1; while :; do echo -n $i; curl localhost:1323/health; i=$((i+1)); echo ''; done

We occasionally receive unexpected responses in the second terminal. For example:

58healthz: OK
59healthz: OK
60healthz: OK
61built-in-mdw: param counter = healthz: OK

We’re seeing multiple responses for what should be a single request. I’m using Echo’s Timeout feature as provided in the documentation. Can anyone help me investigate this issue?

[afdalwahyu]

Using another approach based on the comment here, I’m still encountering the same issue.

another approach:

package main

import (
	"context"
	"net/http"
	"time"

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

func main() {
	e := echo.New()

	handlerTimeout := 500 * time.Millisecond

	g := e.Group("/built-in-mdw")
	g.Use(func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			timeoutCtx, cancel := context.WithTimeout(c.Request().Context(), handlerTimeout)
			c.SetRequest(c.Request().WithContext(timeoutCtx))
			defer cancel()
			return next(c)
		}
	})
	g.GET("", func(c echo.Context) error {
		doneCh := make(chan error)

		go func(ctx context.Context) {
			// long running process here
			time.Sleep(time.Second)

			doneCh <- c.String(http.StatusOK, "built-in-mdw: param counter = "+c.QueryParam("counter"))
		}(c.Request().Context())

		select {
		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: built-in-mdw: param counter = "+c.QueryParam("counter"))
			}
			return c.Request().Context().Err()
		}
	})

	e.GET("/health", func(c echo.Context) error {
		time.Sleep(100 * time.Millisecond)
		return c.String(http.StatusOK, "healthz: OK")
	})

	e.Logger.Fatal(e.Start(":1323"))
}

[aldas]

Please do not use timeout middleware.

and about doneCh <- c.String(http.StatusOK, "built-in-mdw: param counter = "+c.QueryParam("counter")) }(c.Request().Context()) this will write that message to context and therefore "commiting" the response. Afterwards return c.String(http.StatusOK, "OK") will not do anything meaningful as http.StatusOK will not be sent to client anymore

[aldas]

if you are selecting from 2 channels case err := <-doneCh: and case <-c.Request().Context().Done(): you need to make sure that when case <-c.Request().Context().Done(): path is taken nothing else should hold reference to echo.Context instance anymore and especially important is not to c.String to it anymore from other goroutines as this context instance could be already assigned to another request being server (to another client).