RequestLogger middleware can log wrong status codes

[stevenvegt]

Issue Description

The RequestLogger has 2 problems:

1. If a handler returns another error than a echo.HTTPError the status logged is alway 200. This is because of these lines https://github.com/labstack/echo/blob/d604704563de63e42a352ffc51b6d633d9d595e3/middleware/request_logger.go#L264-L271.

2. The RequestLogger is middleware, so If the error handler (or another middleware) writes a different status code (after the logger middleware), the logged status code is wrong.

Working code to debug

Code to reproduce 1

func main() {
	e := echo.New()
	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
		LogStatus: true,
		LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error {
			fmt.Println(values.Status)
			return nil
		},
	}))

	e.GET("/fail", func(context echo.Context) error {
		return errors.New("failed")
	})
	e.Start(":1323")
}

GET http://localhost:1323/fail -> 500 Prints 200

Code to reproduce 2:

e := echo.New()

	e.HTTPErrorHandler = func(err error, context echo.Context) {
		context.NoContent(404)
	}

	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
		LogURI:    true,
		LogStatus: true,
		LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error {
			fmt.Println(values.Status)
			return nil
		},
	}))

	e.GET("/fail", func(context echo.Context) error {
		return echo.NewHTTPError(400, "failed")
	})
	e.Start(":1323")

GET http://localhost:1323/fail -> 404 Prints 400

Version

Version 4.6.1

[aldas]

First example could be fixed to set some other status code (ala http.StatusInternalServerError) when err != nil. It is little bit bettern than 200 but still incomplete has you application can have your own error types with http codes.

@stevenvegt you can check status before you log like this and handle your application specific error types

	log := logrus.New()
	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
		LogURI:    true,
		LogStatus: true,
		LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error {
			status := values.Status
			if values.Error != nil {
				switch errWithStatus := values.Error.(type) {
				case *echo.HTTPError:
					status = errWithStatus.Code
				case httpStatusCodeError:
					status = errWithStatus.statusCode
				default:
					status = http.StatusInternalServerError
				}
			}
			
			log.WithFields(logrus.Fields{
				"URI":    values.URI,
				"status": status,
			}).Info("request")

			return nil
		},
	}))

---

Second example is how middleware chaining and stuff works. Middleware wrapping inner middleware/handler can always change stuff that have not been sent to the client.

[reinkrul]

@aldas this solution works for us 👍 Thanks.

[markhildreth-gravity]

@aldas This workaround of duplicating the status logic of the error handler works if you control both the middleware and the error handler. However, if we use custom error handling logic, and are using a third-party middleware, this workaround won't work.

It seems that the only way a third-party middleware can get the status (and what I've seen some third-party middles rely on, for example the opentelemetry echo middleware) is to call the error handler and then view the response status. Of course, they would then return nil as the error, causing other middlewares to potentially work incorrectly (e.g,. the logging middleware not logging that there was an error).

How should a middleware designed to be used in multiple projects be able to gather the status of the response without using the workaround I see of calling the error handler and essentially "swallowing" the error for upstream middleware? Does it make sense for them to use the error handler but also return the error (rather than returning nil)?

[lammel]

How should a middleware designed to be used in multiple projects be able to gather the status of the response without using the workaround I see of calling the error handler and essentially "swallowing" the error for upstream middleware? Does it make sense for them to use the error handler but also return the error (rather than returning nil)?

As the middleware is actually a chain of middleware functions a "final" result code or error can not be assumed by any middleware in the chain as the next middleware function might change it. So if the middleware needs to know the final status it should be last in the chain or call the global error handler.

[aldas]

https://github.com/labstack/echo/pull/2341 is related to this question.

@lammel is correct. Middleware that absolutely needs to know the actual status code that was sent to the client must be placed in middleware chain before middleware that commits the Request by writing status code to the client. These middleware are for example those that call c.Error(). That is why I now added middleware.RequestLoggerConfig.HandleError field so RequestLogger middleware can be made to commit the request like Logger middleware does it.

Order should be something like that:

e := echo.New()

e.Use(myOpenTelemetryMiddleware()) // when logger returns we have status code that is commited (written to the client)
e.Use(middleware.Logger()) // will call `c.Error(err)` and by doing it "commits" the request by sending status to the client
e.Use(middleware.Recover()) // will catch panics and convert them to errors so Logger can log them

[Omkar-C]

e := echo.New()

e.Use(myOpenTelemetryMiddleware()) // when logger returns we have status code that is commited (written to the client)
e.Use(middleware.Logger()) // will call `c.Error(err)` and by doing it "commits" the request by sending status to the client
e.Use(middleware.Recover()) // will catch panics and convert them to errors so Logger can log them

@aldas In your example, doesn't middleware.Recover() call c.Error(err) itself, so all the upstream middlewares (logger or others) have no access to the error ? What if I want to do something else with that panic error after recovering ? The only option is then to write custom recovery middleware, which will use deferred closure function to return the error ?

[aldas]

@Omkar-C you are right. I did not remember that recover is calling c.Error. I think we can add flag to disable that behavior.

[Omkar-C]

@aldas any chance I can contribute to this ?

[aldas]

I do not know if you want to bother. I have already done this locally, just finished writing test for it.

[Omkar-C]

If you are done with it then no worries, I have been wanting to contribute to open source for a while, and this seemed a good start, that's why I asked.

[aldas]

alright, send the PR and I will review it.

[Omkar-C]

https://github.com/labstack/echo/pull/2410 @aldas Thanks for the opportunity.