logger middleware shows wrong status code when used with timeout middleware

[gmattcrowley]

Issue Description

When using both the "Logging" and "Timeout" middleware together, the client is getting the appropriate 503 response, but the logs show that the response was 200.

Checklist

• Dependencies installed
• No typos
• Searched existing issues and docs

Expected behaviour

The server logs would show accurate response details, eg. "status": 503 in the case of the request timeout

Actual behaviour

The server logs show "status": 200

Example:
{"time":"2021-08-10T11:12:02.5457958-04:00","id":"","remote_ip":"::1","host":"localhost:8080","method":"POST","uri":"/sleep","user_agent":"PostmanRuntime/7.28.2","status":200,"error":"","latency":11997200,"latency_human":"11.9972ms","bytes_in":0,"bytes_out":0}

Steps to reproduce

1. Create a simple echo server with a single endpoint that sleeps for a few seconds
2. Add the use the logging and timeout middleware, set timeout to less than the above sleep
3. Startup the server and invoke the endpoint

Working code to debug

package main

import (
	"time"

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

func main() {
	e := echo.New()
	e.Use(middleware.Logger())
	e.Use(middleware.TimeoutWithConfig(middleware.TimeoutConfig{
		Timeout: time.Duration(1) * time.Millisecond,
	}))
	e.Logger.SetLevel(log.INFO)

	e.POST("/sleep", func(c echo.Context) error {
		c.Logger().Info("Before sleeping in /sleep")
		time.Sleep(12 * time.Second)
		c.Logger().Info("After sleeping in /sleep")
		return nil
	})

	e.Logger.Panic(e.Start(":8080"))
}

Version/commit

go 1.16

require (
github.com/labstack/echo/v4 v4.5.0
github.com/labstack/gommon v0.3.0
)

Additional Comments:

This example also seems to throw a Data Race warning if you run it a couple times... I think the stack traces suggests it's related to the timeout handler as well.

I think in another issue the timeout middleware was described as a having many landmines, is there another way other echo users are dealing with request timeouts? My particular use case is internal only so I really only need to ensure that connections don't hang indefinately. Would server timeouts be good enough for that?

Example:

package main

import (
	"net/http"
	"time"

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

func main() {
	e := echo.New()
	e.Use(middleware.Logger())
	e.Logger.SetLevel(log.INFO)

	e.POST("/sleep", func(c echo.Context) error {
		time.Sleep(12 * time.Second)
		return nil
	})

	srv := &http.Server{
		Addr:         ":8080",
		Handler:      e,
		ReadTimeout:  1 * time.Second,
		WriteTimeout: 1 * time.Second,
	}

	if err := srv.ListenAndServe(); err != http.ErrServerClosed {
		e.Logger.Fatal(err)
	}
}

In that case my client would get a server hangup (oh and the Logger still logs it as a 200, which is still a problem...)

[aldas]

What do you mean by connection hangs indefinitely? Are you concerned about misbehaving clients or misbehaving handlers at server side (endless loop etc)?

TCP connection will be ended by OS to my knowledge if there is no traffic. In Echo it is set to 3 minutes.

http.Server.ReadTimeout and http.Server.WriteTimeout deals with misbehaving clients. See this https://blog.cloudflare.com/the-complete-guide-to-golang-net-http-timeouts/

If you are concerned about long running server side stuff then use context with timeout to stop execution when execution deadline is reached.

ctx, cancel := context.WithTimeout(c.Request().Context(), 5 * time.Second)

that same context will be cancelled when client also disconnects.

Note: timeout middleware does not stop endless loops in you application - it just makes sure that client gets 503 at certain deadline.

NB: do you have loadbalancers/proxys in front of you apps? Ala Nginx/Apache http etc? These will actually (could) kill also long running requests.

to be honest: I would advise against using timeout middleware. It raises more problems than it solves.

[gmattcrowley]

I suppose my concern is mostly around making sure my logs actually say what happened with the request.

We do have an internal load balancer, I can check on it's config and see if it will cover this concern.

Otherwise, I think you're right, using http.Server.[Read|Write]Timeout to handle misbehaving clients works. However, if the server closes the connection, the handler still completes and logger middleware reports it as a 200 -- that feels misleading.

Any other thoughts on logging that case appropriately? Or maybe someone cares to make the case that because the handler finished that a 200 is actually correct even if the user didn't receive it?

If the context was closed by the server when the connection times out, I could do something like:

	e.POST("/sleep", func(c echo.Context) error {
		log.Info("Before sleeping in /sleep")
		select {
		case <-time.After(time.Duration(10) * time.Second):
			log.Info("After sleeping in /sleep")
			return nil
		case <-c.Request().Context().Done():
			return echo.NewHTTPError(http.StatusRequestTimeout, "Request Timeout")
		}
	})

Which would at least force the logging middleware to log that a timeout happened, even if that error can't get back to the client in that particular scenario.

[aldas]

I have not tested but I shooting from hip I assume problem with timeout and logger is that when handler executes it is done is separate coroutine and has actually different writer. Writer is responsible for writing headers (status) and body to client. So middlewares are not aware what happened in/after handler.

As you see - for seemingly simple requirement there is so much complexity with timeout middleware to take into account. So if your requirement is to send early responses to clients (this is what pretty much timeout mw does) then it is probably easier to rely on upstream proxy (nginx,apache,haproxy etc) to disconnect and reply.

If you are using Nginx maybe http://nginx.org/en/docs/http/ngx_http_proxy_module.html#proxy_read_timeout would help.