labstack / gommon

Common packages for Go
MIT License
540 stars 101 forks source link

Why set runtime caller to 3? #18

Closed Mr-Dai closed 6 years ago

Mr-Dai commented 6 years ago

I was trying out echo, and I used e.Logger to as my application's logger, but I found that file locations in the log output were wrong, they all reported the upper layers of their real locations.

Then I found this commit, which changed runtime.Caller(2) to runtime.Caller(3). I set it back to 2, then everything works just fine.

I wonder why it was set to 3 back then.

vishr commented 6 years ago

@Mr-Dai Can you provide an example to debug?

Mr-Dai commented 6 years ago

Test file main.go:

package main

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

func main() {
    e := echo.New()
    e.Logger.SetLevel(log.INFO)
    e.Logger.Infof("Hello, World!")
}

Run it with go run main.go, got:

{"time":"2018-03-12T10:57:54.8390043+08:00","level":"INFO","prefix":"echo","file":"proc.go","line":"185","message":"Hello, World!"}

This is proc.go, basically it's where the go runtime invokes the main function.

vishr commented 6 years ago

Thanks for the information, I have reverted the changed.

baba2k commented 6 years ago

@vishr I have the issuse with caller level 2, because I use the log command:

import (
    "github.com/labstack/gommon/log"
)
func main() {
    log.Info("Hello, World!")
}

With caller level 3 all is fine again. All my projects where I used the logger show the wrong file and line now

This code in log.go could fix it:

_, file, line,_ := runtime.Caller(2)
    if strings.Contains(file, "github.com/labstack/gommon/log/log.go") {
        _, file, line,_ = runtime.Caller(3)
    }
vishr commented 6 years ago

@alexandreStein Can you please help me with it?

weissra commented 6 years ago

I have the same problem in my project.

func main() { // Echo instance e := echo.New()

// Middleware
e.Use(middleware.Logger())
e.Use(middleware.Recover())

//correct line etc
e.Logger.Info("Testlog")
//wrong line etc
log.Info("Wrong log")

}

e.Logger.Info produces correct line number: {"time":"...","level":"INFO","prefix":"echo","file":"main.go","line":"20","message":"Testlog"}

log.Info produces wrong file and line number: {"time":"...","level":"INFO","prefix":"-","file":"log.go","line":"285","message":"Wrong log"}

baba2k`s change fixes it locally.

Mr-Dai commented 6 years ago

@baba2k I think the better way to fix this is to store an extraLevel field in logger struct, which defaults to 0, and change the runtime.Caller invocation in log.go to

_, file, line, _ := runtime.Caller(2 + l.extraLevel)

Another way to do this is to add a calldepth parameter to the log method, like the log.Output method from the standard library.

Point is, this should become a generic parameter/configuration, instead of just adding special processing just for invocations from github.com/labstack/gommon/log/log.go.

alexandrestein commented 6 years ago

@vishr I made a pull request about this issue #21.

The problem is that when you use the default logger you add an other layer. So you need to switch between level 3 and 2 if it's default logger or not.

Look at the pull request and check the test file I call the default logger directly.

I think that merging the pull request would solve the issue.

alexandrestein commented 6 years ago

Hey @vishr. It does fix the issue of the caller level.

But same kind of issue could be reintroduce in the future.

In the test, you are not checking that the give response display the correct file or line. I think this must be check to prevent any future bug related to this.

vishr commented 6 years ago

@alexaandru thanks for pointing that out, I will put the test back soon.