High latency route

[jamesli2021]

I came across httplog with examples of different routes framework:
https://github.com/MadAppGang/httplog/tree/main/examples/echo

On macOS with M1, I've found echo returns 404 for a /not_found is of >100 microseconds which is significant large than other framework. I presume it could be helpful to improve latency for logging.

alice
28.708µs

chi
17.708µs

echo
139.792µs

gin
26.709µs

goji
21.542µs

httprouter
17µs

gorilla
27.375µs

negroni
34.666µs

[aldas]

TLDR:

Echo serves by default all errors as JSON responses (from default global error handler) and JSON serialization has its cost. Other examples write response with status code for 404 directly as string in handler to the client.

Longer:

You are somewhat comparing apples to oranges.

Concept of Echo handlers and middlewares is that when something wrong/unexpected happens you return an error and let calling middleware or eventually global error handler to handle it. Default global error handler returns errors responses to the client as JSON.

Returning HTTP status code and response body in handler (as http.NotFoundHandler() does) completely circumvents/breaks next middleware/handler could return an error chain.
Errors as JSON in case of unsuccessful request is always less performant than returning string.

so other examples use http.NotFoundHandler() as response for that route but for Echo you use echo.NotFoundHandler. If your intention is to write error response directly in handler then the direct comparison for Echo would be to use e.GET("/not_found", echo.WrapHandler(http.NotFoundHandler())).

http.NotFoundHandler() and echo.NotFoundHandler are different things.

• http.NotFoundHandler() writes status (in this case status code for 404) and message immediately into response and to the client. This disables your ability to handle errors in middlewares calling the handler.
• echo.NotFoundHandler returns an error instance that is handled by Echos global error handler (if any of middlewares do not handle/swallow it before) and that error is then serialized as JSON response.

httplog middleware is calling global error handler here and doing the serialization

			if err := next(c); err != nil {
				c.Error(err)  // <-- error gets written to the client as JSON. middlewares up in chain are screwed now if they are intended to interact with errors
			}

NB: You must add warning somewhere that by using e.Use(loggerMiddleware) developer must use that middleware always as very first middleware as this middleware breaks chain of returning of errors with c.Error(err) usage.

NB: c.Error(err) will be removed in v5 and you really should not use it even in v4 as it commits (sends) response to the client and no upstream middleware is able to change the response anymore (which they might be intended to do)

---

p.s. these examples are butchering how Echo/Gin etc handlers are written. This is more Echolike example

func happyHandler(c echo.Context) error {
	return c.String(http.StatusOK, "I am happy!")
}

func routeWithError(c echo.Context) error {
	return echo.NewHTTPError(http.StatusInternalServerError, "I am unhappy!")
}

using c.Response().Writer.Write([]byte("I am happy!")) is not how Echo users write handlers.

Gin example:

var happyHandler = func(c *gin.Context) {
	fmt.Println("I am happy handler")
	c.Writer.Write([]byte("I am happy!"))
}

should be

var happyHandler = func(c *gin.Context) {
	fmt.Println("I am happy handler")
        c.String(http.StatusOK, "I am happy!")
}

or how Gin handles middleware execution chains and errors

	g.GET("/error", func(c *gin.Context) {
		c.AbortWithError(http.StatusNotFound, errors.New("I am unhappy!"))
	})

etc. I think these examples should be idiomatic to their frameworks/libraries way of doing things

---

p.s.s. I think you should not use /not_found as demonstration how your request logger handles errors. This is confusing as "not found" overlaps with "HTTP" frameworks and routers feature when requests do not match any application route. For example Gin has concept of adding NoRoute handler

	g.NoRoute(func(c *gin.Context) {
		c.String(http.StatusNotFound, "custom not Found")
	})

NB: Echo has also concept of handling cases for when no route is found.

	e.RouteNotFound("/*", func(c echo.Context) error {
		return c.String(http.StatusNotFound, "custom not found")
	})

so usage of r.GET("/not_found", gin.WrapF(http.NotFound)) is obfuscating the intention here - I assume it is to showcase how unsuccessful requests are logged. Probably something along the lines /error would be better for path, in my opinion.

[aldas]

I think it would be better to combine this httplog library with https://github.com/labstack/echo/blob/master/middleware/request_logger.go but allowing RequestLogger to fill httplog.LogFormatterParams struct and call write log line.

Something like that

	logger := httplog.NewLogger()
	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
		LogStatus: true,
		LogURI:    true,
		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
			params := httplog.LogFormatterParams{
				StatusCode: v.Status,
				Path:       v.URI,
				// other fields
			}
			logger.Write(params)
			return nil
		},
	}))

this way intricacies of framework handle/middleware logic is delegated to Echo as logic how error code is extracted is different. etc

NB: I think LoggerConfig.SkipPaths does not play well with routers that have path or catch any variables as you use r.URL.Path as path but your route path will be for example users/:id and as the URI will be /users/123 and you probably want abiltity to skipp all path what match to users/:id route.

[aldas]

anyway, if you are not related to that library then disregard this last response.