rs / zerolog

Zero Allocation JSON Logger
MIT License
10.33k stars 564 forks source link

Caller confusion when using caller multiple times #649

Open sruehl opened 6 months ago

sruehl commented 6 months ago

when using the .Caller like this

package main

import (
    "github.com/rs/zerolog"
    "github.com/rs/zerolog/log"
)

func main() {
    logger := log.With().Caller().Logger()
    logger.Info().Msg("Should be 10")
    UtilSomething(logger)
    logger.Info().Str("field1", "left").Str("field1", "right").Msg("Test")
}

func UtilSomething(logger zerolog.Logger) {
    logger.Info().Caller(1).Msg("Should be 11")
}

src: https://go.dev/play/p/nyLsISEzVhV we are getting this output:

{"level":"info","time":"2009-11-10T23:00:00Z","caller":"/tmp/sandbox2691989628/prog.go:10","message":"Should be 10"}
{"level":"info","caller":"/tmp/sandbox2691989628/prog.go:11","time":"2009-11-10T23:00:00Z","caller":"/tmp/sandbox2691989628/prog.go:16","message":"Should be 11"}
{"level":"info","field1":"left","field1":"right","time":"2009-11-10T23:00:00Z","caller":"/tmp/sandbox2691989628/prog.go:12","message":"Test"}

Program exited.

as you can see the second skip set in the UtilSomething funktion is getting put to the right and therefore when collapsing using the wrong line number. Is that a issue in zerolog or a missunderstanding how to use the API for such a case?

sruehl commented 6 months ago

And for clarification: The first .Caller() is set on the root logger to always display caller lines and the second one is used in util functions to get the right line number.

sruehl commented 6 months ago

or in other words, it seems like the order is wrong for caller (ref https://github.com/rs/zerolog/issues/40#issuecomment-371180715)