Existing zerolog instance is not reflected with full functionality

andygrunwald commented 3 years ago

First of all, thanks for this middleware!

While providing an exsiting zerolog instance to lecho, it seems that the functionality is not fully used: When using

output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}
logger := zerolog.New(output).With().Timestamp().Logger()

The following output is producted

2021-03-22T08:09:42+01:00 INF booting foo=true
2021-03-22T08:09:42+01:00 ??? {"message":"⇨ http server started on [::]:8282"}

If you apply a HTTP handler to the echo framework and make a HTTP call, it outputs:

2021-03-22T08:09:16+01:00 ??? {"level":"info","id":"mISgzePvkoXF02jSSNdiAn8Ns2IBjfvX","remote_ip":"3.135.189.179","host":"8dc74f618941.ngrok.io","method":"GET","uri":"/favicon.ico","user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.150 Safari/537.36","status":404,"referer":"","error":"code=404, message=Not Found","latency":0.139483,"latency_human":"139.483µs","bytes_in":"0","bytes_out":"24"}

A few things are not reflected:

level is part of the message, rather then after the timestamp (see ???)
No default level is provided (see "http server started" message)
Request information is still in json format rather than as single logging attributes

Is it a mistake from my side or a (valid) limitation of this library? Thank you @ziflex!

Code to reproduce

package main

import (
    "os"
    "time"

    "github.com/labstack/echo/v4"
    "github.com/rs/zerolog"
    "github.com/ziflex/lecho/v2"
)

func main() {
    output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}
    logger := zerolog.New(output).With().Timestamp().Logger()

    logger.Info().Bool("foo", true).Msg("booting")

    e := echo.New()
    e.HideBanner = true

    lechoLogger := lecho.New(logger)
    e.Logger = lechoLogger

    e.Use(lecho.Middleware(lecho.Config{
        Logger: lechoLogger,
    }))

    e.Start(":8282")
}

ziflex commented 3 years ago

Hey, thanks for using lecho!

First of all, if you want to use lecho with preconfigured instance of zerolog, you should use lecho.From method instead.

Second, the reason why you are getting ??? is that echo calls a given Logger without a status (by using its output). Maybe we should use default level for that?

I will update lecho.New to avoid such confusion in the future.

andygrunwald commented 3 years ago

Hey @ziflex, thanks for the response and for pointing me in the right direction of lecho.From. Now it works as expected like

2021-03-28T18:43:31+02:00 INF  bytes_in=0 bytes_out=11797 host=ID.ngrok.io id=rb1qN0Mq7GyIykif1vUhJsuovaaeEsEn latency=22.833632 latency_human=22.833632ms method=GET referer=https://ID.ngrok.io/url remote_ip=ipv6 status=200 uri=uri user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36"

Just for reference (and others), the change for lecho.New was applied in https://github.com/ziflex/lecho/commit/5b04e5071c4b8af939582da4f8f99ba50b51ee99 Thanks a lot for taking care!

About the log level ???, I created a PR in the echo framework: https://github.com/labstack/echo/pull/1826 Let us see what comes out of this.

In my opinion, this issue can be closed. Please reopen, if you think differently. Thanks again!

ziflex / lecho

Existing zerolog instance is not reflected with full functionality #7

Code to reproduce