Skip to content

Custom timeout middleware changes behavior of code #2763

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
thestephenstanton opened this issue Apr 3, 2025 · 22 comments
Closed

Custom timeout middleware changes behavior of code #2763

thestephenstanton opened this issue Apr 3, 2025 · 22 comments

Comments

@thestephenstanton
Copy link

thestephenstanton commented Apr 3, 2025

I could totally be thinking about this thing wrong and have the wrong mental model but in this simplified configuration, I'm getting weird behavior:

package main

import (
	"errors"
	"log"
	"net/http"
	"time"

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

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

	timeoutMW1 := middleware.Timeout()

	// from docs: https://echo.labstack.com/docs/middleware/timeout
	timeoutMW2 := middleware.TimeoutWithConfig(middleware.TimeoutConfig{
		Skipper:      middleware.DefaultSkipper,
		ErrorMessage: "custom timeout error message returns to client",
		OnTimeoutRouteErrorHandler: func(err error, c echo.Context) {
			log.Println(c.Path())
		},
		Timeout: 30 * time.Second,
	})

	e.GET("/do1", hello, timeoutMW1, authenticate)
	e.GET("/do2", hello, timeoutMW2, authenticate)

	e.Start(":8080")
}

type customError struct {
	Message string `json:"message"`
}

func authenticate(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		authHeader := c.Request().Header.Get("Authorization")
		if authHeader != "secret" {
			c.JSON(http.StatusUnauthorized, customError{Message: "unauthorized"})

			return errors.New("unauthorized")
		}

		return next(c)
	}
}

func hello(c echo.Context) error {
	return c.JSON(http.StatusOK, "hello")
}

/do1 will return as expected but /do2 will respond with a 200 and have no body

Maybe where I'm wrong in my thoughts is responding in the authenticate middleware. Essentially I want to have that middleware respond but I also want to return up the error so that other middlewares above can get that error (e.g. logging middleware). Is this not the right way to go about this?

To me it seems more like a problem with that custom timeout middleware. I don't understand why having the custom one would act any different than the middleware.Timeout() one.

@thestephenstanton
Copy link
Author

Well I see why it works for the first one, it essentially is just skipping the timeout middleware.

Still curious why it is sending a 200 for /do2

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

You are probably better off with context timeout middleware. Timeout middleware runs handler actually in separate goroutine and if that ends up in endless loop there is nothing that will stop it.

@thestephenstanton
Copy link
Author

So I tried that one and it does cancel the context but it doesn't automatically respond with a timeout like the regular timeout middleware does. It also doesn't seem to run that error function that it has in its config.

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

For

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

	ctmw := middleware.ContextTimeoutWithConfig(middleware.ContextTimeoutConfig{
		Skipper: nil,
		ErrorHandler: func(err error, c echo.Context) error {
			return err
		},
		Timeout: 10 * time.Second,
	})
	e.GET("/do2", hello, ctmw, authenticate)

	e.Start(":8080")
}

return func(next echo.HandlerFunc) echo.HandlerFunc {
return func(c echo.Context) error {
if config.Skipper(c) {
return next(c)
}
timeoutContext, cancel := context.WithTimeout(c.Request().Context(), config.Timeout)
defer cancel()
c.SetRequest(c.Request().WithContext(timeoutContext))
if err := next(c); err != nil {
return config.ErrorHandler(err, c)
}
return nil
}
}, nil

line 70 is not executed when handler retuns an error?

@thestephenstanton
Copy link
Author

Sorry, my mistake. I got two things switched around in my code I was testing with.

So the error is handling correctly, however the timeout is only cancelling the context and not responding with the 503 as I expected and does in the other middleware. Which I know isn't programmed in. Is this just not a feature that is supported?

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

this current example does not run long enough to context to be deadlined. Without auth headers you will be served with 401 as this is the error that is returned.

			c.JSON(http.StatusUnauthorized, customError{Message: "unauthorized"})

			return errors.New("unauthorized")

also this code is problematic - c.JSON will send the response and error that is returned is ignored by global error handler because the response was already sent with c.Json

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

your handler has to be

func authenticate(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		authHeader := c.Request().Header.Get("Authorization")
		if authHeader != "secret" {
			return echo.ErrUnauthorized
		}

		return next(c)
	}
}

with this - timeout middleware will be also ok

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

but I still recommend context timeout.

@thestephenstanton
Copy link
Author

If I change my hello handler to be:

func hello(c echo.Context) error {
	go func() {
		fmt.Println("deadline started")
		<-c.Request().Context().Done()
		fmt.Println("deadline done")
	}()
	time.Sleep(10 * time.Second)
	return c.JSON(http.StatusOK, "hello")
}

The deadline will stop after the 3 seconds (good), but it will wait the full 10 seconds then respond to my client with a 200.

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

this is because time.Sleep(10 * time.Second) is not "context aware"

context aware is something like that

	select {
	case <-time.After(10 * time.Second):
	case <-c.Request().Context().Done():
	}

@thestephenstanton
Copy link
Author

thestephenstanton commented Apr 3, 2025 via email

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

you really should not choose this kind of middleware just base of response code.

Context timeout will do that same, assuming you are using context aware methods

if config.ErrorHandler == nil {
config.ErrorHandler = func(err error, c echo.Context) error {
if err != nil && errors.Is(err, context.DeadlineExceeded) {
return echo.ErrServiceUnavailable.WithInternal(err)
}
return err
}
}

@aldas
Copy link
Contributor

aldas commented Apr 3, 2025

Please read #2745 (comment) and there are older posts that discuss differencens in these middlewares if you search in issues history

@thestephenstanton
Copy link
Author

you really should not choose this kind of middleware just base of response code.

It's more of just convenience. It is nice because we have some endpoints that do things that aren't necessarily context away and even though we may have a rogue go routine, it ends up being a better DX (in our situation) to have this cancel and respond with a simple middleware.

We also are moving from the base http library to Echo, and are using this from the standard library. Having the same functionality would be nice but if it isn't achievable with Echo then it ain't the end of the world.

And thanks for the link, in there you say "Timeout MW will just send response to client that request timeoutted" which is exactly what I want, its more of the weird behavior around another middleware sending a response but then the client receiving a 200.

You did mention earlier that "c.JSON will send the response and error that is returned is ignored by global error handler because the response was already sent with c.Json", which seems like it relates to what problem I'm seeing? But I would expect a call to c.JSON to start writing immediately then if the global error handler tried to write again, it would really just be a superfluous write cause the middleware already sent the response.

@aldas
Copy link
Contributor

aldas commented Apr 4, 2025

generally with Echo - do not write/send errors to client with c.JSON/.String. Errors have to be returned from handlers as error type objects. By using c.JSON response (status code) will be "commited" i.e. sent to the client and no middleware in future will be able to send another status code to the client during the same request.

@thestephenstanton
Copy link
Author

Ok that makes sense. So this is really me not using things right. I should send an "unauthorized" error back up from my middleware and have a global error handler right? Like should I be using the echo.HTTPErrorHandler for that?

@aldas
Copy link
Contributor

aldas commented Apr 4, 2025

yes, e.HTTPErrorHandler is that place.

nb: check the comment on default error handler about errors and if you implement your version then do not forget to add that if c.Response().Committed part.

echo/echo.go

Lines 411 to 422 in de44c53

// DefaultHTTPErrorHandler is the default HTTP error handler. It sends a JSON response
// with status code.
//
// NOTE: In case errors happens in middleware call-chain that is returning from handler (which did not return an error).
// When handler has already sent response (ala c.JSON()) and there is error in middleware that is returning from
// handler. Then the error that global error handler received will be ignored because we have already "committed" the
// response and status code header has been sent to the client.
func (e *Echo) DefaultHTTPErrorHandler(err error, c Context) {
if c.Response().Committed {
return
}

@thestephenstanton
Copy link
Author

I guess that is what is confusing me. If c.Response().Committed will be true only when the header has been written, and c.JSON should be the thing writing to the client, then why wouldn't it be the status code I write?

This is a little out of my realm of expertise, but if that is saying that it Committed is true (which I verified that it does in my example), and assuming that Committed is set because of the c.JSON call and that Committed means that it write the header (may be wrong here), then I don't understand why (and I just found this out) this piece of code is causing the status to be 200.

Also, I know you've basically solved my issue and I appreciate you taking time to help me understand the why here. So if this is getting to be too much then just let me know. I just am trying to understand why this is happening.

@obataku
Copy link

obataku commented Apr 10, 2025

@thestephenstanton did you figure out the source of the cryptic 200?

@aldas
Copy link
Contributor

aldas commented Apr 11, 2025

@obataku this is because authentication middleware in example is sending the response for error itself and not letting timeout middleware to handle it.

So this

func authenticate(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		authHeader := c.Request().Header.Get("Authorization")
		if authHeader != "secret" {
			c.JSON(http.StatusUnauthorized, customError{Message: "unauthorized"})

			return echo.ErrUnauthorized
		}

		return next(c)
	}
}

should be this

func authenticate(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) error {
		authHeader := c.Request().Header.Get("Authorization")
		if authHeader != "secret" {
			return echo.ErrUnauthorized
		}

		return next(c)
	}
}

@obataku
Copy link

obataku commented Apr 11, 2025

@aldas I follow but it's not obvious to me why 200 is sent rather than 401 there, and it seems like @thestephenstanton isn't sure either

@aldas
Copy link
Contributor

aldas commented Apr 11, 2025

c.JSON(http.StatusUnauthorized, customError{Message: "unauthorized"}) starts to write response to the client. First the response objects fill store status code and sometime later write is flushed to the client. Now return echo.ErrUnauthorized will make it so that timeout middleware spawned goroutine receives that error and sends that back to the original request goroutine - swaps pack response objects + other things. all that time response object knows that has been written and ignores error that was received but to send response to the client status has to be written and default one is 200.

Probably if you try this enough time you will see sometimes that c.JSON will actually manage to send response to the client and client sees 401 but most of the time - Go scheduler works in a way that flushing will not be done and original goroutine logic will execute.

as you see - this is not trivial. far from it. If you want to run your business logic asynchnously then create/run goroutine in your business layer and DO NOT try to delegate this to webframe work. Timeout middleware is actually about running response asynchnously and Context timeout middleware is about ending handlers after certain time or client disconnects.

timeout middleware is black magic around multiple goroutines and how/when Go standard library decides to write data back to client.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants