Double running of echo.HTTPErrorHandler

[rattuscz]

I'm experiencing double calling of HTTPErrorHandler by lecho middleware logger.

First it's called if there was error during request processing, immediately when request is returned from middleware chain:

lecho/middleware.go

Lines 84 to 86 in 6b6fa8f

	if err = next(c); err != nil {
	c.Error(err)
	}

Next request log is produced and sent, but the middleware returns the same error again up:

lecho/middleware.go

Line 126 in 6b6fa8f

return err

This causes the error to be propagated up the chain and is again sent to HTTPErrorHandler function by echo itself:
https://github.com/labstack/echo/blob/4a1ccdfdc520eb90573a97a7d04fd9fc300c1629/echo.go#L619-L631

The "native" echo Logger middleware does not do this, the error is consumed by calling handler immediately (the same as lecho) and then error sent up the middleware chain is actual result (error) of writing the log.

Do I understand something wrongly (ie is this expected behavior and i'm supposed to somehow catch the error) or is this actual bug?

[ziflex]

Hey, thanks for bringing it up.
I'm not quite sure. I need to test it.

[sazzer]

I've just hit this exact same issue, and can confirm that it does not happen with the standard middleware.Logger() that comes with Echo.

i.e. this causes the issue:

	logger := lecho.From(log.Logger)
	lvl, _ := lecho.MatchZeroLevel(zerolog.DebugLevel)
	logger.SetLevel(lvl)
	server.Logger = logger

	server.Use(lecho.Middleware(lecho.Config{
		Logger: logger,
	}))

But this doesn't:

	lvl, _ := lecho.MatchZeroLevel(zerolog.DebugLevel) // For convenience for testing
	server.Logger.SetLevel(lvl)
	server.Use(middleware.Logger())

[ziflex]

Hey guys, sorry for such a late reply. I've been pretty busy lately.
I will try to fix it this week.

[ziflex]

Can anyone provide an example of their handlers that causes this behavior?

[rattuscz]

I ended up using echo logger functionality since i can provide log function and the middleware stuff is handled by echo.

so in echo i setup:
app.echo.Use(rest.LoggerMiddleware(&log.Logger))

where log.Logger is zerolog instance and the middleware is just the config with value function for the echo.middleware.RequestLoggerWithConfig
here is the whole thing

package rest

import (
	"strconv"

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

const formatIntBase = 10

func LoggerMiddleware(log *zerolog.Logger) echo.MiddlewareFunc {
	return middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
		LogURI:           true,
		LogStatus:        true,
		LogMethod:        true,
		LogUserAgent:     true,
		LogHost:          true,
		LogRequestID:     true,
		LogLatency:       true,
		LogResponseSize:  true,
		LogContentLength: true,
		LogReferer:       true,
		LogError:         true,
		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
			bytesIn := v.ContentLength
			if bytesIn == "" {
				bytesIn = "0"
			}

			log.Info().
				Str("id", v.RequestID).
				Int("status", v.Status).
				Str("method", v.Method).
				Str("URI", v.URI).
				Str("remote_ip", c.RealIP()).
				Err(v.Error).
				Str("host", v.Host).
				Str("user_agent", v.UserAgent).
				Str("referer", v.Referer).
				Str("bytes_in", bytesIn).
				Str("bytes_out", strconv.FormatInt(v.ResponseSize, formatIntBase)).
				Dur("latency", v.Latency).
				Str("latency_human", v.Latency.String()).
				Send()

			return nil
		},
	})
}

[aldas]

I am adding some context to

 if err = next(c); err != nil { 
 	c.Error(err) 
 } 

Calling c.Error(err) and therefore invoking global error handler e.HTTPErrorHandler(err) is necessary evil for middlewares that need to get accurate response status code. This is necessary in cases when you have global error handler that can decide different status code other than what was stored inside err that middleware chain returned. There are multiple ways to stop global error handler to be invoke multiple times.

a) make sure that your error handler has this as first condition

	if c.Response().Committed {
		return
	}

this will make sure that Response that has already been sent to the client (already executed through error handler) is not executed twice.

This case you can make sure that your middleware can call c.Error() and return that error to middleware up in chain (ie. do not swallow the error)

Note: this has its shortcomings - for example if you successfully write response to the client and some middleware up in handler chains errors out - you will not catch that as your error handler acts only for cases when you are able to write to the client.

Think conceptionally - what purpose your error handler serves - is it to write error responses to client or log+? errors.

b) call c.Error() in your middleware and do not return that error to middleware up in chain. In that case make sure that middlewares that you have added before that "swallowing" middleware do not need get returned errors.

basically - use this middleware as very first middleware.

Note: set panic recovering middleware after that middleware so you are actually executing return parts. For example Echo own middleware.Recover will recover panics and convert them to errors - therefore use

	e.Use(lecho.Middleware(lecho.Config{
		Logger: logger,
	}))
	e.Use(middleware.Recover()) // <-- after logger so panics are converted to errors and returned to logger middleware

Reference: labstack/echo#2341 this exaple of Echo PR that addresses similar issues with RequestLogger middleware.

[ziflex]

I am adding some context to

 if err = next(c); err != nil { 
 	c.Error(err) 
 } 

Calling c.Error(err) and therefore invoking global error handler e.HTTPErrorHandler(err) is necessary evil for middlewares that need to get accurate response status code. This is necessary in cases when you have global error handler that can decide different status code other than what was stored inside err that middleware chain returned. There are multiple ways to stop global error handler to be invoke multiple times.

a) make sure that your error handler has this as first condition

	if c.Response().Committed {
		return
	}

this will make sure that Response that has already been sent to the client (already executed through error handler) is not executed twice.

This case you can make sure that your middleware can call c.Error() and return that error to middleware up in chain (ie. do not swallow the error)

Note: this has its shortcomings - for example if you successfully write response to the client and some middleware up in handler chains errors out - you will not catch that as your error handler acts only for cases when you are able to write to the client.

Think conceptionally - what purpose your error handler serves - is it to write error responses to client or log+? errors.

b) call c.Error() in your middleware and do not return that error to middleware up in chain. In that case make sure that middlewares that you have added before that "swallowing" middleware do not need get returned errors.

basically - use this middleware as very first middleware.

Note: set panic recovering middleware after that middleware so you are actually executing return parts. For example Echo own middleware.Recover will recover panics and convert them to errors - therefore use

	e.Use(lecho.Middleware(lecho.Config{
		Logger: logger,
	}))
	e.Use(middleware.Recover()) // <-- after logger so panics are converted to errors and returned to logger middleware

Reference: labstack/echo#2341 this exaple of Echo PR that addresses similar issues with RequestLogger middleware.

I decided to get rid of this call altogether. To me, it seems like a violation of the single responsibility principle.
Moreover, Echo will call the error handler anyway, so no need to duplicate the logic.

[aldas]

This is OK. It would be probably better to add comment somewhere that middleware probably reports status incorrectly on error.

lecho/middleware.go

Line 142 in 967237f

evt.Int("status", res.Status)

In that case it is probably 200 (default status) and actual status code is decided when request it is run through error handler.

[ziflex]

This is OK. It would be probably better to add comment somewhere that middleware probably reports status incorrectly on error.

lecho/middleware.go

Line 142 in 967237f

evt.Int("status", res.Status)

In that case it is probably 200 (default status) and actual status code is decided when request it is run through error handler.

Good catch.

Maybe I could add an optional error handler and pass Echo context into it, so if for someone it's breaking change, they could easily revert the old behavior.

[ziflex]

Okay, I added a new flag, pretty much the same one that Echo has, to enable-disable this 'feature'.

https://github.com/ziflex/lecho#errors