Idea: 'Helper' method for Caller

[bboreham]

Currently, it is necessary to figure out how each log method will be called in order to specify a count of stack frames to Caller.

log/value.go

Lines 82 to 84 in 5739c26

	// Caller returns a Valuer that returns a file and line from a specified depth
	// in the callstack. Users will probably want to use DefaultCaller.
	func Caller(depth int) Valuer {

This makes functions that wrap or forward to go-kit/log hard to use.

Suggestion: have a Helper method like in testing, which tells Caller to skip that function from the count.

This would be relatively expensive – a stack walk, lock and map lookup each time the helper is entered, and more map lookups when actually logging – but much more pleasant to use.

[ChrisHines]

Do you think it would be possible to implement this idea without changing the implementations of log.With and friends?

[bboreham]

What I had in mind would change Caller and add Helper, plus there needs to be somewhere on the logger data structure to hold the set of helpers.
I can’t immediately see that this implies a change to With.

[ChrisHines]

OK. What if instead of changing Caller there was a new SlowButConvenientCaller (not the real name) and a new implementation of Logger that worked together to do what you describe? That would then be a new feature instead of changing any existing features. Maybe it could also be implemented in a separate package initially to see how it works. Is something like that possible?

[peterbourgon]

I have an idea, but I'm not yet sure it's feasible. @bboreham @ChrisHines — could you provide a small program that demonstrates the problem cases you've got in mind?

[bboreham]

One real case is
https://github.com/grafana/dskit/blob/9956e2453a9fc2e88246578adafee7c6d7de176a/spanlogger/spanlogger.go#L80

where we want to send the same log message to tracing and to a go-kit logger; we have a lot of caller=spanlogger.go:80 in our logs.

Similar, but where we do manage to adjust Caller to avoid the problem:
https://github.com/weaveworks/common/blob/c65105d60b185cfaa7ef23269a257db392da0b37/logging/gokit.go#L79

Trivial self-contained program:

package main

import (
	"os"

	"github.com/go-kit/log"
)

// Some function that wraps a logging operation, e.g. to send a trace or bump a metric.
func utility(logger log.Logger, reason string) {
	logger.Log("msg", "important "+reason)
}

func main() {
	var logger log.Logger
	logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
	logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)

	logger.Log("msg", "hello")
	utility(logger, "hello")
}

[peterbourgon]

@bboreham Thank you!

[peterbourgon]

@bboreham Do I understand correctly that you don't want the current output of

ts=2009-11-10T23:00:00Z caller=prog.go:19 msg=hello
ts=2009-11-10T23:00:00Z caller=prog.go:11 msg="important hello"

and instead want

ts=2009-11-10T23:00:00Z caller=prog.go:19 msg=hello
ts=2009-11-10T23:00:00Z caller=prog.go:20 msg="important hello"

?

[bboreham]

Exactly.

[oliverpool]

@bboreham since utility is a helper, could you also do:

func utility(logger log.Logger, reason string) {
	logger.Log("msg", "important "+reason, "caller", log.Caller(4))
}

[bboreham]

How would I know 4 is the correct number, in general?

[oliverpool]

You would need to somehow pass this around you utilities, I guess.

[bboreham]

I don't think that is realistic in a large program made up of many packages.

[peterbourgon]

I'm sharing this experiment rather prematurely in order to solicit feedback. Here's the gist. And here's the gist:

The basic idea is to embed more "smarts" into the logged value. The log.Valuer is defined as a method on a Context struct, which holds an optional call frame representing the point in the stack where SetHelper was called. The value, which is lazy-evaluated as in @bboreham's example, consults that state in order to determine which frame to return as the caller.

There are a couple of outstanding issues. At the moment, you have to call SetHelper on the Context struct, which basically doesn't solve the problem: you should be able to flag Helper on a log.Logger directly. I think this is solvable, by making the Context a log.Logger itself, and providing a func Helper(log.Logger) function in package caller, which would be able to decorate/wrap the logger with a Context that set the helper frame. There are also some issues, noted in the test, related to decorators, which I think are also solvable by stack introspection.

I'll keep poking at this, but if anyone is inspired to take the ball and run with it, please do. Or, if anyone sees a problem I haven't noticed, feedback appreciated.