Why set runtime caller to 3?

[Mr-Dai]

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]

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

[Mr-Dai]

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]

Thanks for the information, I have reverted the changed.

[baba2k]

@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]

@alexandrestein Can you please help me with it?

[weissra]

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]

@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]

@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]

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]

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