proposal: log/slog: builtin support for helper functions

[pohly]

When calling a Logger method inside a helper function, the recorded source code is the source code of the helper:

func Foo() {
   logSomething("hello world", "key": 1, "value": "xyz")
}

func logSomething(msg string, kvs ...any) {
   slog.Default().Info("logging " + msg", kvs...)
}

Other logging libraries (zap, go-logr) have a WithCallDepth call for this. testing.T has Helper, but that is less flexible.

It would be useful to add Logger.WithCallDepth, then this example would become:

func logSomething(msg string, kvs ...any) {
   slog.Default().WithCallDepth(1).Info("logging " + msg", kvs...)
}

The only solution right now is for logSomething to translate its arguments into a Record, do stack unwinding, then call Handler.Handle. This is doable, but implies copying quite a bit of code from slog because the helper functions which do that in Logger are not exported (and probably shouldn't be).

cc @jba

[toffaletti]

I raised a similar concern that 3rd party Handlers don't benefit from HandlerOptions #56345 (comment)

[telemachus]

I raised this on the slog proposal, and jba seemed open to the idea, but he wanted to wait and see what the demand was.

Just to repeat something I said there, several of the logging libraries mentioned in the initial slog proposal as "Prior Work" offer an easy way to adjust call depth: pohly mentions zap and logr, but I'll copy my full list below. (I removed logr and hclog from the original list since as jba pointed out, the methods in those libraries modify the original logger.)

• zap provides AddCallerSkip—this plus WithOptions allows for a simple adjustment in helpers as shown here
• zerolog provides Caller and CallerSkipFrame
• go-kit/log provides Caller (and there's some discussion of making Caller even more helpful to users)
• glog provides several X-Depth functions that allow the user to adjust the depth
• the stdlib log provides Output

[pohly]

There's one thing to consider when implementing this: the call depth needs to become an attribute of Logger because its methods needs that information when doing stack unwinding. When converting a Logger instance to some other front-end API, the conversion code needs access to that new attribute, otherwise the conversion is incomplete.

Bottom line: in addition to WithCallDepth, a GetCallDepth would also be needed.

[jba]

Right now, it's not a lot of code to create your own helper. For reference, here's the code from the wrapping example:

func Infof(format string, args ...any) {
    l := slog.Default()
    if !l.Enabled(context.Background(), slog.LevelInfo) {
        return
    }
    var pcs [1]uintptr
    runtime.Callers(2, pcs[:]) // skip [Callers, Infof]
    r := slog.NewRecord(time.Now(), slog.LevelInfo, fmt.Sprintf(format, args...), pcs[0])
    _ = l.Handler().Handle(context.Background(), r)
}

That's not great, but as you say, it's doable.

How could we make it better?

We could add a method to Logger, like the suggested WithCallDepth. What is the return type of that method? If it's Logger, then that would let people create a logger with a call depth in it and pass it around, which makes no sense. If it's some other type, then we'd have to duplicate all the output methods of Logger (Info, LogAttrs and so on). That is not pretty.

We could add a Helper function to Logger that behaved like testing.T.Helper. This would be a nice solution: it would be easy to use and wouldn't interfere with other uses of the Logger. But it is expensive to implement, at least if we do it like the testing package does it. Every call to Helper requires fetching the pc and adding it to a map in the Logger. That has to be done with locking, since it has to be safe for use by multiple goroutines. And if there is even one Helper call on a logger, then all the output methods would have to get the pcs for the stack and search for the first non-helper.

We could add a special slog.Value to indicate the depth. This is basically the idea of go-kit/log's Caller mentioned above. For example, you could write

func LogHelper(...) {
    logger.LogAttrs(ctx, slog.LevelInfo, "msg", "at", slog.PC(1))
}

and slog would figure out that the PC should refer to the line calling LogHelper, not to the LogAttrs call. This is tempting, but it has a few problems. It would be a strange kind of Value, for one thing. It couldn't be a LogValuer, because in code like

l2 := l.With("pc", slog.PC(1))

The LogValue method is called before Logger.With returns, but we want to delay getting the pc until an output method is called. Also, l2 in the above code is the same sort of thing as l.WithCallDepth(1), a logger that always reports the pc one call higher in the stack, and as I said, that's sort of a weird thing. Basically, an Attr for getting the pc has too many degrees of freedom, too many ways to shoot yourself in the foot.

Lastly, there are the XXXDepth functions, as we had originally. Maybe that is the best solution.

[AndrewHarrisSPU]

Basically, an Attr for getting the pc has too many degrees of freedom, too many ways to shoot yourself in the foot.

I even find the degrees of freedom alluring, but definitely agree about the foot-gunning. Just to toss out an idea ... a pretty narrow function with an implementation small enough to fit into its own doc string:

func Caller(depth int) (fileAndLine slog.Value) {
	if _, file, line, ok := runtime.Caller(depth + 1); ok {
		fileAndLine = slog.StringValue(fmt.Sprintf("%s:%d", file, line))
	}
	return
}

[pohly]

it's not a lot of code to create your own helper

That depends. Your example is simple only because it does printf-style handling of its arguments. When doing the same for a helper that takes key/value pairs like Logger.Info, then converting those parameters into a record becomes harder. If more of the Logger implementation (taking a PC, converting key/value pairs) was exported, then writing such a helper would be easier.

We could add a method to Logger, like the suggested WithCallDepth. What is the return type of that method? If it's Logger, then that would let people create a logger with a call depth in it and pass it around, which makes no sense.

To me that makes sense. Here's an example:

func main() {
    logger := ...
    
    helperA(logger, "some message", "key", 1)
    helperB(logger, "some other message", "key", 2)
}

func helperA(logger slog.Logger, msg string, kv ...any) {
    logger = logger.WithCallDepth(1)
    helperB(logger, "A: " + msg, kv...)
}

func helperB(logger slog.Logger, msg string, kv ...any) {
    logger = logger.WithCallDepth(1)
    logger.Info("B: " + msg, kv...)
}

In this example, both helpers emit log records that point towards where they are called. When helperB gets called by a helper, that helper also gets skipped, so we end up with log records that point to main.

The caveat is passing such a logger into a function which isn't considered a helper doesn't work as expected: helperA -> someOtherFunction then would end up logging the call site in helperA when someOtherFunction doesn't also do a WithCallDepth(1). In my experience this isn't a problem because helper functions are typically very simple, i.e. either self-contained or only depend on some related helper functions.

We could add a Helper function to Logger that behaved like testing.T.Helper .... Every call to Helper requires fetching the pc and adding it to a map in the Logger.

That's a problem. Every single function along the call chain has to know that it needs to call this function. It's not possible to optimize cases where a helper is always called n functions down from some top-level API call such that there is a single WithCallDepth(n) when needed.

[jba]

When doing the same for a helper that takes key/value pairs like Logger.Info, then converting those parameters into a record becomes harder

We now have Record.Add, which should make it easy.

[jba]

func Caller(depth int) (fileAndLine slog.Value) {
	if _, file, line, ok := runtime.Caller(depth + 1); ok {
		fileAndLine = slog.StringValue(fmt.Sprintf("%s:%d", file, line))
	}
	return
}

@AndrewHarrisSPU, this is like the slog.PC function I mentioned in my comment above. It has two problems: it does too much work before the Enabled check (runtime.Caller and string formatting), and it only works if you write it inline in a log output line. It would give the wrong value if you used it in Logger.With or stored it in a variable somewhere for later use elsewhere.

[rsc]

I believe it would be a mistake to tie the call depth into the logger as a WithCallDepth method implies. More generally we went through the whole problem with WithContext of trying to provide a fluent API, and we walked away from that. I think we would need a very good reason to go back to fluent-style APIs. Let's focus on solutions that don't overload Logger with extra state.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[rsc]

Based on the discussion above, this proposal seems like a likely decline.
— rsc for the proposal review group

[rsc]

No change in consensus, so declined.
— rsc for the proposal review group

[mattdowdell]

I've evidently late to the party, but my use case is to provide a consistent structured logging whilst using packages that use a variety of logging interfaces. That boils down to the requirement to set a 'depth' value when initialising the logger which is not modified thereafter. It would be nice to see that supported here to reduce our reliance on third-party packages where possible. It could take years for log/slog to become the de facto logging solution in Go, and support to achieve that by stealth would be helpful.

As an example, sarama expects an interface similar to that of log, but you can implement it however you want. Today, we wrap zap and it's WithCallerSkip functionality to achieve that. We wouldn't get goodness like request-specific attributes being passed around, but most of those logs are for exceptional behaviour anyway.

[jba]

@mattdowdell, why wouldn't the approach in my earlier comment work?