c.Response().Status value not set properly in middleware when use echo.NewHTTPError

[waynez]

Issue Description

When use echo.NewHTTPError to generate HTTP errors in the API handler, the status code read in the middleware is not set properly. This behavior differs from c.JSON

Checklist

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

Expected behaviour

The c.Response().Status should set to the value returned with the echo.NewHTTPError

Actual behaviour

c.Response().Status is always 200

Steps to reproduce

Below is an example to reproduce the issue and shows the different results observed using echo.NewHTTPErro v.s. c.JSON in an API handler

Working code to debug

package main

import (
    "net/http"
    "github.com/labstack/echo/v4"
    "github.com/labstack/gommon/log"
)

var e *echo.Echo

func Logger(next echo.HandlerFunc) echo.HandlerFunc {
    return func(c echo.Context) error {
        defer func() {
            resp := c.Response()
            e.Logger.Infof("URI: %v; Resp code: %v", c.Request().URL, resp.Status)
        }()
        return next(c)
    }
}

func main() {
    e = echo.New()
    e.Logger.SetLevel(log.DEBUG)
    e.Use(Logger)
    e.GET("/test1", func(c echo.Context) error {
        return c.JSON(http.StatusNotFound, "test 1")
    })
    e.GET("/test2", func(_ echo.Context) error {
        return echo.NewHTTPError(http.StatusNotFound, "test 2")
    })
    log.Panic(e.Start(":8080"))
}

Access the server with curl http://localhost:8080/test1 & curl http://localhost:8080/test gets results as

{"time":"2021-04-08T00:18:21.68735263+08:00","level":"INFO","prefix":"echo","file":"main.go","line":"15","message":"URI: /test1; Resp code: 404"}
{"time":"2021-04-08T00:18:24.795359144+08:00","level":"INFO","prefix":"echo","file":"main.go","line":"15","message":"URI: /test2; Resp code: 200"}

Version/commit

echo version: v4.2.1
go version: go1.16.3 linux/amd64

[aldas]

This is how middleware chain works. When handler or middleware returns an error it bubbles up in chain until it is handled/discarded or it reaches the global errorhandler.

Here is part where returned error reaches global errorhandler:

echo/echo.go

Line 647 in 10d8c53

e.HTTPErrorHandler(err, c)

and inside errorhandler response status is written (if it is not already written by handler or middleware earlier).

echo/echo.go

Line 379 in 10d8c53

if !c.Response().Committed {

When you use c.JSON(http.StatusNotFound, "test 1") it means that response status+body is written to client and no other middleware should/will write to client anymore.

[waynez]

Thanks for the explanation.

In my case I have a custom ErrorHandler to capture the HTTPError from handler, do proper formatting, then eventually invoke c.JSON(). I noticed my Logger middleware was executed before it reaches to the ErrorHandler, thus not able to capture the response code set in the ErrorHandler.

      if !c.Response().Committed {
          if c.Request().Method == http.MethodHead {
              err = c.NoContent(he.Code)
          } else {
              err = c.JSON(he.Code, m)
          }
          if err != nil {
              e.Logger.Error(err)
          }
      }

Checking the implementation of the middleware chain, it looks like this is not the right approach? How can I capture the response code sent to client in the server side?

[aldas]

Check this discussion about custom middleware for getting response status #1820 (comment) assuming your middleware chain returns errors of type echo.HTTPError you can check for it and extract status code from it.

Example from that discussion:

	customMiddleware := func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {
			timeStarted := time.Now()
			err := next(c)

			status := c.Response().Status

			httpErr := new(echo.HTTPError)
			if errors.As(err, &httpErr) {
				status = httpErr.Code
			}

			fields := map[string]interface{}{
				"latency": int64(time.Since(timeStarted) / time.Millisecond),
				"method":  c.Request().Method,
				"path":    c.Request().URL.Path,
				"query":   c.Request().URL.RawQuery,
				"status":  status,
			}

			if err != nil {
				fmt.Printf("on error: %v\n", fields)
				//s.logger.SendErrorWithFields(err, fields)
				return err
			}
			fmt.Printf("fields: %v\n", fields)
			//s.logger.SendWithFields(fields)
			return nil
		}
	}

[waynez]

Thanks, but it's a bit weird though. I'm now able to get response code in the middleware, but that response code didn't make it to the client side, client now always sees 200.

It looks like the CustomErrorHandler was not invoked by using this approach.

[aldas]

I recommend you to debug which path is taken out of that middleware function. If it is return err then maybe something else is dropping that error.

I do not know what IDE are you using but learning how to debug is best choice in your carer as it will help you so much.

• VScode debugger: https://code.visualstudio.com/docs/languages/go#_debugging
• GoLand: https://blog.jetbrains.com/go/2019/02/06/debugging-with-goland-getting-started/
• https://golang.cafe/blog/golang-debugging-with-delve.html
• https://golang.org/doc/gdb

[waynez]

DUH, I missed that part to return error after print in your example.

			if err != nil {
				fmt.Printf("on error: %v\n", fields)
				//s.logger.SendErrorWithFields(err, fields)
				return err
			}

Now it works, thanks for the help!