Make log level configurable with Logger Middleware for any logs

[ymotongpoo]

Issue Description

As of today, Logger Middleware does not support log level in the custom logger format. This makes all access logs being without log levels.

#1649 is relevant to this issue.

Quoting all available tags for Logger Middleware from the doc:

// LoggerConfig defines the config for Logger middleware.
LoggerConfig struct {
  // Skipper defines a function to skip middleware.
  Skipper Skipper

  // Tags to construct the logger format.
  //
  // - time_unix
  // - time_unix_nano
  // - time_rfc3339
  // - time_rfc3339_nano
  // - time_custom
  // - id (Request ID)
  // - remote_ip
  // - uri
  // - host
  // - method
  // - path
  // - protocol
  // - referer
  // - user_agent
  // - status
  // - error
  // - latency (In nanoseconds)
  // - latency_human (Human readable)
  // - bytes_in (Bytes received)
  // - bytes_out (Bytes sent)
  // - header:<NAME>
  // - query:<NAME>
  // - form:<NAME>
  //
  // Example "${remote_ip} ${status}"
  //
  // Optional. Default value DefaultLoggerConfig.Format.
  Format string `yaml:"format"`

  // Optional. Default value DefaultLoggerConfig.CustomTimeFormat.
  CustomTimeFormat string `yaml:"custom_time_format"`

  // Output is a writer where logs in JSON format are written.
  // Optional. Default value os.Stdout.
  Output io.Writer
}

Checklist

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

Expected behaviour

level tag is available in the LoggerConfig#Format.

Actual behaviour

level tag is not available. I tried it just in case and I confirmed it doesn't work.

Steps to reproduce

I added "severity": "${level}" to the DefaultLoggerConfig.Format and used that format in CustomConfig, then I called LoggerMiddleware like this:

e.Use(middleware.LoggerWithConfig(CustomConfig))

Then launched the app and accessed to the server. The output of the access log is as the following:

{"severity":"", "time":"2021-09-17T11:51:30.18712593+09:00","id":"","remote_ip":"::1","host":"localhost:1323","method":"GET","uri":"/","user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36","status":200,"error":"","latency":53214,"latency_human":"53.214µs","bytes_in":0,"bytes_out":13}

As you see, because ${level} is not available, it just generates blank strings.

Working code to debug

package main

import (
	"github.com/labstack/echo/v4"
	"github.com/labstack/echo/v4/middleware"
)

var CustomConfig = middleware.LoggerConfig{
	Format: `{"severity":"${level}", "time":"${time_rfc3339_nano}","id":"${id}","remote_ip":"${remote_ip}",` +
		`"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
		`"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"` +
		`,"bytes_in":${bytes_in},"bytes_out":${bytes_out}}` + "\n",
}

func main() {
	e := echo.New()
	e.Debug = true
	e.Logger.SetLevel(0)

	// Middleware
	e.Use(middleware.LoggerWithConfig(CustomConfig))

	// Routes
	e.GET("/", func(c echo.Context) error {
		e.Logger.Info("access")
		return c.String(200, "Hello, World!")
	})

	// Start server
	e.Logger.Fatal(e.Start(":1323"))
}

Version/commit

v4.5.0

[aldas]

@ymotongpoo Logger middleware and echo.Logger are 2 different things. So e.Logger.SetLevel(0) is not related to what specifically Logger mw logs. Logger mw is about logging request/response related info but logger.SetLevel is setting threshold of which logging calls will not produce output to logs (are discarded).

If you want to add hardcoded severity field to log line then add it into LoggerConfig.Format:

var CustomConfig = middleware.LoggerConfig{
	Format: `{"severity":"INFO", "time":"${time_rfc3339_nano}","id":"${id}","remote_ip":"${remote_ip}",` +
		`"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
		`"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"` +
		`,"bytes_in":${bytes_in},"bytes_out":${bytes_out}}` + "\n",
}

[ymotongpoo]

Thanks for the reply, @aldas. I added e.Logger.SetLevel(0) for e.Logger.Info("access") to compare normal logs and access logs; that part is nothing to do with the issue.

Adding the hardcoded section in the format could be one solution, but it only works for the case where all accesses are neither 4xx nor 5xx. In many cases, 4xx and 5xx are treated as "warning" or more severe levels. For example, this is the case with go-chi/chi

{"level":"warn","service":"app","httpRequest":{"proto":"HTTP/1.1","remoteIP":"127.0.0.1:49672","requestID":"yoshi/oX9X7p0J5r-000003","requestMethod":"GET","requestPath":"/favicon.ico","requestURL":"http://127.0.0.1:8888/favicon.ico"},"httpResponse":{"body":"404 page not found\n","bytes":19,"elapsed":0.04479,"header":{"content-type":"text/plain; charset=utf-8","x-content-type-options":"nosniff"},"status":404},"timestamp":"2021-09-17T20:55:16.372330036+09:00","message":"Response: 404 Client Error"}

Given that, do you have any plans to support access log levels in the future?

[aldas]

we could add some callback that takes in that line buff, context and error and developer can add whatever he/she chooses by that.

Currently we have in unreleased state this new middleware https://github.com/labstack/echo/blob/master/middleware/request_logger.go it will be soon included in v4.6.0.

[aldas]

@ymotongpoo v4.6.0 has been released. You might want to try request logger middleware

[ymotongpoo]

@aldas Thank you for the feature! I'll try it out and leave feedback here!

[ymotongpoo]

@aldas Where can we get the timestamp from the RequestLoggerValues? Do you expect users to call time.Now() in the callback function?

https://github.com/labstack/echo/blob/master/middleware/request_logger.go#L126-L169

[aldas]

assumption was that timestamps are added by logging library but I get what you mean - are timestamps for beginning of the request or end of request. I'll add field to get the beginning of the request.

current workaround is to subtract v.latency from time.now(). which gets you "almost" that time. But I'll add start time to values.

[aldas]

Time when Request Logger middleware started can be read here

echo/middleware/request_logger.go

Line 128 in c32fafa

StartTime time.Time

Since there will be many middleware, there is no way to know which middleware is executing first, so the timing of the execution from the middleware may not be correct, because it may be executing some other logic before it.

Logger middleware is best set as first middleware and recover after that. But anyway - latency will give you number how long everything that logger middleware is wrapping around took time to execute. So if you are doing a lot of work/waiting before logger middleware scope, it will not be included in latency number.

[aldas]

This is where latency is calculated.

echo/middleware/request_logger.go

Lines 213 to 225 in c32fafa

	start := now()
	if config.BeforeNextFunc != nil {
	config.BeforeNextFunc(c)
	}
	err := next(c)
	v := RequestLoggerValues{
	StartTime: start,
	}
	if config.LogLatency {
	v.Latency = now().Sub(start)
	}

[aldas]

I would not say it is inaccurate. it is good enough without delving into philosophical discussions what is accurate request time and what is not and when does request actually starts and when it ends.