Repository: go-logr/logr
Pull request #60 (2021-08-04 07:49:26)

support alternative way of skipping frames
This is needed for log sinks where the underlying stack unwinding
doesn't support an explicit call depth, for example testing.T.Log.

One such log sink is currently pending in https://github.com/kubernetes/klog/pull/240.
It currently incorrectly logs logr.go as call site.


pohly: I'm just posting this for discussion. I still need to check whether this works as intended...
pohly: No, it doesn't :cry: 

Implementing the proposed `Helper() LogSink` runs into the same limitation as before:
```
func (l *tlogger) Helper() logr.LogSink {
	l.l.Helper()
	return l
}
```

It marks *itself* as helper, not its *caller*.

Looks like enhancements in the standard library will be necessary to address this. Scary.
pohly: This approach can be made to work by returning the underlying function that then needs to be called by the helper functions. I've pushed another commit for that and tested that it works for the testing logger.

However, the resulting API is definitely not nice and naming probably should be improved (too many "helpers"...).





pohly: I've pushed further commits to make this work in the testing logger. With those changes I now get the expected result:
```
logr/testing $ go test -v .
=== RUN   TestTestLogger
    test_test.go:28: : "level"=0 "msg"="info"
    test_test.go:29: : "level"=0 "msg"="V(0).info"
    test_test.go:31: : "msg"="error" "error"="error"
    test_test.go:33: : "level"=0 "msg"="hello world"
--- PASS: TestTestLogger (0.00s)
PASS
```

pohly: > Looks OK overall.

So we are really doing this, despite the awkward API? Okay.

>  Please squash and make sure the commit and PR messages are clean and helpful.

Will do.

>  Can you please add the following file as funcr/example/main.go:

Okay, just one question about this:
```
// If this were in another package, all it would depend on in logr, not glogr.
func example(log logr.Logger) {
```
	log.Info("hello", "val1", 1, "val2", map[string]int{"k": 1})
	log.V(1).Info("you should see this")
        ...
```

I don't understand the comment. There's no reference to glogr in the file. Looks like a cut-and-paste problem, I'll simply drop the comment unless I hear otherwise.

thockin: The comment is a cut-paste error and can be removed, thanks

On Thu, Aug 5, 2021, 12:27 AM Patrick Ohly ***@***.***> wrote:

> Looks OK overall.
>
> So we are really doing this, despite the awkward API? Okay.
>
> Please squash and make sure the commit and PR messages are clean and
> helpful.
>
> Will do.
>
> Can you please add the following file as funcr/example/main.go:
>
> Okay, just one question about this:
>
> // If this were in another package, all it would depend on in logr, not glogr.
> func example(log logr.Logger) {
>
> log.Info("hello", "val1", 1, "val2", map[string]int{"k": 1})
> log.V(1).Info("you should see this")
>     ...
>
>
> I don't understand the comment. There's no reference to glogr in the file. Looks like a cut-and-paste problem, I'll simply drop the comment unless I hear otherwise.
>
> —
> You are receiving this because you commented.
> Reply to this email directly, view it on GitHub
> <https://github.com/go-logr/logr/pull/60#issuecomment-893231668>, or
> unsubscribe
> <https://github.com/notifications/unsubscribe-auth/ABKWAVE6MBKQXS4KWEFODNLT3I4PHANCNFSM5BQPPGHA>
> .
> Triage notifications on the go with GitHub Mobile for iOS
> <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675>
> or Android
> <https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email>
> .
>

thockin: > So we are really doing this, despite the awkward API? Okay.

I don't love it, but given how testing.T is implemented, I really don't see any other answer - the func HAS to be called from the helper-func's stack frame.

Before we merge this, I'll let it sit for a bit and see if anyone else has creative alternatives.  I am doubtful, but maybe...
thockin: and if we merge this, I guess we'll want a 1.1.0 tag.
pohly: > Please squash to 1 commit

I think that's too aggressive. 40bd6cd and 5bd8e58 are both stand-alone changes. We might even merge them already now, independently of the Helper API change. I'll put them into separate PRs so that we don't forget about them if we close this one here without merging.

Implementing the API and using it in testing can be squashed. I tend to prefer to keep that separate because it sometimes makes cherry-picking simpler, but that's subjective. Let's wait for more review feedback before I touch this PR again.
thockin: Fine, then :)  Squash to the smallest set of whole commits that makes sense and make sure the comments are good ;)
wojas: ```go
func myWrapper(logger logr.Logger, msg string) {
    helper, logger := logger.Helper()
    helper()
    logger.Info(msg)
}
```

As an API this is horrible, but it does not look like we have much choice given how the Go testing package works.

Perhaps at least make the name on the logr side clearer. Given that this is a hack specifically added for the testing package, perhaps use something like `WithTestingHelper` instead? No need to pretend that this is some generic solution if this is really just a workaround for the testing package. Explicitly mentioning this in the comments would make it a less cryptic addition.

This would change the example as follows:

```go
func myWrapper(logger logr.Logger, msg string) {
    helper, logger := logger.WithTestingHelper()
    helper()
    logger.Info(msg)
}
```

Would this be used in any other context?

Do I understand correctly that when not using the testing log sink, would you still need to use `WithCallDepth`? In that case you would need to use both this helper and `WithCallDepth` for a generic helper?

If this can be make more generic and completely replace the `WithCallDepth` call if no custom helper is provided, perhaps call it `WithCallDepthHelper`?


pohly: > ```go
> func myWrapper(logger logr.Logger, msg string) {
>     helper, logger := logger.Helper()
>     helper()
>     logger.Info(msg)
> }
> ```
> 
> As an API this is horrible, but it does not look like we have much choice given how the Go testing package works.
> 
> Perhaps at least make the name on the logr side clearer. Given that this is a hack specifically added for the testing package, perhaps use something like `WithTestingHelper` instead?

I agree that naming in the new API is sub-optimal (too much "helpers"). I just tried to get something working to get a feeling for how horrible it would be.

I like `WithTestingHelper` better (consistent with other `Logger.With*` functions, clearer reference to `testing`).

One concern I have is that users might get the impression that they should only use this when using `testing`. The function is also useful with other logging backends (see below).

> No need to pretend that this is some generic solution if this is really just a workaround for the testing package. Explicitly mentioning this in the comments would make it a less cryptic addition.

Okay.

> Would this be used in any other context?

I don't know of one. OTOH, that doesn't mean that there is no other logging backend that uses the same approach.

> Do I understand correctly that when not using the testing log sink, would you still need to use `WithCallDepth`?
WithTestingHelper
No. A wrapper function must call either `WithCallDepth(1)` *or* `WithTestingHelper()`, but not both. `Helper` (= `WithTestingHelper`) is written so that it does the right thing for skipping the caller regardless of how the LogSink achieves that.

> If this can be make more generic and completely replace the `WithCallDepth` call if no custom helper is provided, perhaps call it `WithCallDepthHelper`?

There's still a need for `WithCallDepth` when the parameter is greater than 1. Log wrappers which need that then don't work properly with `testing`.

wojas: OK, given that it calls `WithCallDepth(1)` if no helper is defined, it's basically a replacement for calling that directly and it should not have testing in the name.

I would then argue that calling something `WithCallDepthHelper()` would be the recommended way of implementing any helper function in your code. If you use this, it will work automatically for both testing loggers and for sinks that use the call depth approach. It also allows a log sink to implement to implement a similar mechanism as testing uses if it desires so.

We should then update the `WithCallDepth` documentation to recommend using the new helper approach instead.

Given the fragility of the API, perhaps add some extra checks there. It is too easy to forget to call the helper function and someone may find out that it 'still works' if you just ignore that return value with `_`. How about a descriptive `panic()` if the helper function was not called before using the new logger? 

pohly: > OK, given that it calls `WithCallDepth(1)` if no helper is defined, it's basically a replacement for calling that directly and it should not have testing in the name.
> 
> I would then argue that calling something `WithCallDepthHelper()` would be the recommended way of implementing any helper function in your code. If you use this, it will work automatically for both testing loggers and for sinks that use the call depth approach. It also allows a log sink to implement to implement a similar mechanism as testing uses if it desires so.

Correct. So replace `Helper` with `WithCallDepthHelper`?

> We should then update the `WithCallDepth` documentation to recommend using the new helper approach instead.

That's already in the current PR :smile: ("Helper should be used instead of WithCallDepth(1) because ...")

> Given the fragility of the API, perhaps add some extra checks there. It is too easy to forget to call the helper function and someone may find out that it 'still works' if you just ignore that return value with `_`. How about a descriptive `panic()` if the helper function was not called before using the new logger?

That would be nice, but cannot be implemented because the returned function intentionally doesn't go through the logger because `testing.T.Helper` cannot be wrapped, i.e. the logger cannot know whether it was called or not.

wojas: > Correct. So replace `Helper` with `WithCallDepthHelper`?

That would be my preferred name choice. @thockin?
 
> > We should then update the `WithCallDepth` documentation to recommend using the new helper approach instead.
> 
> That's already in the current PR 😄 ("Helper should be used instead of WithCallDepth(1) because ...")

Ah, perfect, missed that. 😄 
 
> > Given the fragility of the API, perhaps add some extra checks there. It is too easy to forget to call the helper function and someone may find out that it 'still works' if you just ignore that return value with `_`. How about a descriptive `panic()` if the helper function was not called before using the new logger?
> 
> That would be nice, but cannot be implemented because the returned function intentionally doesn't go through the logger because `testing.T.Helper` cannot be wrapped, i.e. the logger cannot know whether it was called or not.

Hmm, that's annoying. We could check it for situations where no helper was defined by the log sink and we return our own function, which could set some internal variable to false. But I don't like this inconsistency, because then you will get situations where code panics in production, even though it 'worked fine' in tests.

Perhaps just depend on Go's unused variable check then.

pohly: > Perhaps just depend on Go's unused variable check then.

Yes. Hopefully programmers will think before discarding the helper function return value with `_`. What we would need to prevent that is https://github.com/golang/go/issues/20803

thockin: I'm not 100% sure on names:

`With*()` implies some attribute of the Logger (WithName changes the Loggers name), which isn't really the case here.  I'd expect `WithCallDepthHelper` to take an argument that was a "CallDepthHelper" and save that in the Logger.

`Helper()` has the advantage of following *a* convention (better than making something up).  We don't really have examples of other implementations that are similar, so we don't know if there's actually a pattern to follow. 

We're proposing that "best practice" be to call  `Helper()` and run the returned function in (almost?) all cases of intermediate helper funcs.  Given that, it seems to me that making it easier to use is important.

```
   log.Helper()()
```

vs

```
  log, helper := log.WithHelper()
  helper()
```

Which is more likely to be correct more often?  The `WithFoo()` pattern is strongly associated with "catch the return value", where as `t.Helper()` is strongly associated with fire-and-forget.  OTOH 1 line vs 2 lines and named variables.

Thoughts?
pohly: > Helper() has the advantage of following a convention (better than making something up).

You mean `testing.T.Helper`? That's exactly the fire-and-forget semantic that we don't want to follow here because the return values must both be used. For me that's a strong argument to use `With*` because then using the return value is a familiar pattern.

I agree that `WithCallDepthHelper` sounds like it should have a parameter. How about `WithOneMoreCallDepth`? "One" implies that the parameter is not needed because it would be `1` and "More" implies that it is additive. It rolls of the tongue better than `WithOneCallDepth`, too.








wojas: The main issue with `log.Helper()()` is that this way we cannot increment the call depth for non-testing backends. It would the require every helper to both call `log.Helper()()` and `WithCallDepth`, the second one returning a new instance like the proposed `WithCallDepthHelper` or whatever the name ends up being:

Compare

```go
func myWrapper(logger logr.Logger, msg string) {
    helper, logger := logger.WithCallDepthHelper()
    helper()
    logger.Info(msg)
}
```

with

```go
func myWrapper(logger logr.Logger, msg string) {
    logger.Helper()()
    logger.WithCallDepthHelper(1).Info(msg)
}
```

And as @pohly mentioned, the Go compiler will also not help you if you just call `logger.Helper()` by mistake without using the returned function, see https://play.golang.org/p/lfwo09sbGkh

pohly: > logger, helper := ... vs helper, logger := ...

I don't have a strong opinion either way. At the end, both is arbitrary.

Regarding names:

My understand is that in `testing`, "the helper" is the log wrapper function. `testing.T.Helper` is just that API for marking the helper function. I wouldn't call that method "the helper", therefore a -1 from me for `GetHelperFunc`. I don't have a good suggestion for naming the variable, though. For consistency with `t.Helper()` in normal test code I probably would stick with `helper()`.

All of other examples might look okay at first glance when called without using the return values although such usage is incorrect. Therefore I still prefer `WithOneMoreCallDepth`.



thockin: WithOneMoreCallDepth really doesn't "feel good" to me.  I'm not really looking to rush this, so I'll let it percolate for a bit.
wojas: > `logger, helper := ...` vs `helper, logger := ...`

Perhaps `logger, helper :=` is better, because the `context` package also does this: 

```
func WithCancel(parent Context) (ctx Context, cancel CancelFunc)
```

> x, y := log.AsHelper()
> x, y := log.AsHelperFunc()

To me `As` suggests a conversion, but we do not only return the cancel function and there is no actual conversion happening.

> x, y :=log.IsHelper()

Feels like a check if this is a helper. I would expect a `bool` return value.

> x, y := log.ThisIsAHelperFunc()

Suggests that this actual call marks it as a helper func. I would also not expect any return value here.

> x, y := log.GetHelperFunc()

This would be fine is it would just return a helper func.

I think something starting with `With` would still be most clear. This is what we do with `WithCallDepth` and the pattern mirrors `context.WithCancel`. It suggests that you are adding something to the current object and receiving a new object.

@pohly is right that the calling function is the helper in the testing naming, but  I think the function can still be seen as a helper to determine that call stack depth to subtract.

I still have a preference for `WithCallDepthHelper`, because like in `WithCancel`, it tells something about the extra return value. 
`WithOneMoreCallDepth` does not tell you anything about the weird extra return value.

Come to think of it, this is a pretty common pattern:

```go
ctx, cancel := context.WithCancel(ctx)
defer cancel()
```

This does not look too weird next to that:

```go
logger, helper := logger.WithCallDepthHelper()
helper()
```

thockin: I guess I buy that reasoning for `With*`.

WithCallDepthHelper()

WithCallStackHelper()

WithCallerHelper()

WithHelper()

wojas: One more:

WithCallDepthMarkerFunc()
thockin: rebase needed :)
pohly: > rebase needed :)

Can you merge PRs https://github.com/go-logr/logr/pull/61 and https://github.com/go-logr/logr/pull/62 first? Then a rebase will make this PR smaller.


thockin: Done
pohly: @wojas: @thockin and I chatted about this a bit more and agreed on `WithCallStackHelper` because `WithCallDepthHelper` sounds like it should have a numeric depth argument, similar to `WithCallDepth`. I'll rename accordingly.



Patch:
diff --git a/funcr/funcr.go b/funcr/funcr.go
index d2913ec..69972bc 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -46,7 +46,7 @@ type Underlier interface {
 }
 
 func newSink(fn func(prefix, args string), opts Options) logr.LogSink {
-	return &fnlogger{
+	l := &fnlogger{
 		prefix:       "",
 		values:       nil,
 		depth:        0,
@@ -54,7 +54,14 @@ func newSink(fn func(prefix, args string), opts Options) logr.LogSink {
 		logCaller:    opts.LogCaller,
 		logTimestamp: opts.LogTimestamp,
 		verbosity:    opts.Verbosity,
+		helper:       opts.Helper,
 	}
+	if l.helper == nil {
+		// We have to have a valid function for GetCallStackHelper, so
+		// we might as well just cover the nil case once here.
+		l.helper = func() {}
+	}
+	return l
 }
 
 // Options carries parameters which influence the way logs are generated.
@@ -70,6 +77,10 @@ type Options struct {
 	// Verbosity tells funcr which V logs to be write.  Higher values enable
 	// more logs.
 	Verbosity int
+
+	// Helper is an optional function that funcr will call to mark its own
+	// stack frames as helper functions.
+	Helper func()
 }
 
 // MessageClass indicates which category or categories of messages to consider.
@@ -89,6 +100,7 @@ type fnlogger struct {
 	values       []interface{}
 	depth        int
 	write        func(prefix, args string)
+	helper       func()
 	logCaller    MessageClass
 	logTimestamp bool
 	verbosity    int
@@ -98,6 +110,7 @@ type fnlogger struct {
 var _ logr.LogSink = &fnlogger{}
 var _ logr.CallDepthLogSink = &fnlogger{}
 var _ Underlier = &fnlogger{}
+var _ logr.CallStackHelperLogSink = &fnlogger{}
 
 func flatten(kvList ...interface{}) string {
 	if len(kvList)%2 != 0 {
@@ -293,6 +306,7 @@ func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
 	args = append(args, l.values...)
 	args = append(args, kvList...)
 	argsStr := flatten(args...)
+	l.helper()
 	l.write(l.prefix, argsStr)
 }
 
@@ -313,6 +327,7 @@ func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
 	args = append(args, l.values...)
 	args = append(args, kvList...)
 	argsStr := flatten(args...)
+	l.helper()
 	l.write(l.prefix, argsStr)
 }
 
@@ -342,3 +357,7 @@ func (l fnlogger) WithCallDepth(depth int) logr.LogSink {
 func (l fnlogger) GetUnderlying() func(prefix, args string) {
 	return l.write
 }
+
+func (l fnlogger) GetCallStackHelper() func() {
+	return l.helper
+}
diff --git a/logr.go b/logr.go
index 4b0effb..a2ce519 100644
--- a/logr.go
+++ b/logr.go
@@ -209,10 +209,11 @@ func New(sink LogSink) Logger {
 // accessed concurrently.
 func (l *Logger) setSink(sink LogSink) {
 	l.sink = sink
-	// Always update the cached value to ensure that it matches
+	// Always update the cached values to ensure that they match
 	// the new sink, either with a valid implementation of the
 	// additional interface or nil.
 	l.withCallDepth, _ = sink.(CallDepthLogSink)
+	l.withHelper, _ = sink.(CallStackHelperLogSink)
 }
 
 // GetSink returns the stored sink.
@@ -238,8 +239,20 @@ func (l Logger) WithSink(sink LogSink) Logger {
 type Logger struct {
 	sink LogSink
 
-	level         int
+	level int
+
+	// withCallDepth is set by setSink if the log sink supports
+	// the CallDepthLogSink interface.
 	withCallDepth CallDepthLogSink
+
+	// withHelper is set by setSink if the log sink supports the
+	// CallStackHelperLogSink interface.
+	//
+	// We only need the function returned by
+	// withHelper.GetCallStackHelper(), but cannot store it here
+	// because that makes Logger non-comparable, which is
+	// something we want to guarantee.
+	withHelper CallStackHelperLogSink
 }
 
 // Enabled tests whether this Logger is enabled.  For example, commandline
@@ -257,6 +270,9 @@ func (l Logger) Enabled() bool {
 // keys and arbitrary values.
 func (l Logger) Info(msg string, keysAndValues ...interface{}) {
 	if l.Enabled() {
+		if l.withHelper != nil {
+			l.withHelper.GetCallStackHelper()()
+		}
 		l.sink.Info(l.level, msg, keysAndValues...)
 	}
 }
@@ -270,6 +286,9 @@ func (l Logger) Info(msg string, keysAndValues ...interface{}) {
 // while the err argument should be used to attach the actual error that
 // triggered this log line, if present.
 func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) {
+	if l.withHelper != nil {
+		l.withHelper.GetCallStackHelper()()
+	}
 	l.sink.Error(err, msg, keysAndValues...)
 }
 
@@ -313,6 +332,10 @@ func (l Logger) WithName(name string) Logger {
 // If the underlying log implementation supports a WithCallDepth(int) method,
 // it will be called and the result returned.  If the implementation does not
 // support CallDepthLogSink, the original Logger will be returned.
+//
+// To skip one level, WithCallStackHelper() should be used instead of
+// WithCallDepth(1) because it works with implementions that support
+// the CallDepthLogSink and/or CallStackHelperLogSink interfaces.
 func (l Logger) WithCallDepth(depth int) Logger {
 	if l.withCallDepth == nil {
 		return l
@@ -321,6 +344,34 @@ func (l Logger) WithCallDepth(depth int) Logger {
 	return l
 }
 
+// WithCallStackHelper returns a new Logger instance that skips the
+// direct caller when logging call site information, if possible.
+// This is useful for users who have helper functions between the
+// "real" call site and the actual calls to Logger methods and want to
+// support loggers which depend on marking each individual helper
+// function, like loggers based on testing.T.
+//
+// In addition to using that new logger instance, callers also must
+// call the returned function.
+//
+// If the underlying log implementation supports a WithCallDepth(int)
+// method, WithCallDepth(1) will be called to produce a new logger. If
+// it supports a WithCallStackHelper() method, that will be also
+// called. If the implementation does not support either of these, the
+// original Logger will be returned.
+func (l Logger) Helper() (func(), Logger) {
+	var helper func()
+	if l.withCallDepth != nil {
+		l.sink = l.withCallDepth.WithCallDepth(1)
+	}
+	if l.withHelper != nil {
+		helper = l.withHelper.GetCallStackHelper()
+	} else {
+		helper = func() {}
+	}
+	return helper, l
+}
+
 // contextKey is how we find Loggers in a context.Context.
 type contextKey struct{}
 
@@ -430,3 +481,27 @@ type CallDepthLogSink interface {
 	// Successive calls to this are additive.
 	WithCallDepth(depth int) LogSink
 }
+
+// CallStackHelperLogSink represents a Logger that knows how to climb
+// the call stack to identify the original call site and can skip
+// intermediate helper functions if they mark themselves as
+// helper. Go's testing package uses that approach.
+//
+// This is useful for users who have helper functions between the
+// "real" call site and the actual calls to Logger methods.
+// Implementations that log information about the call site (such as
+// file, function, or line) would otherwise log information about the
+// intermediate helper functions.
+//
+// This is an optional interface and implementations are not required
+// to support it. Implementations that choose to support this must not
+// simply implement it as WithCallDepth(1), because
+// Logger.WithCallStackHelper will call both methods if they are
+// present. This should only be implemented for LogSinks that actually
+// need it, as with testing.T.
+type CallStackHelperLogSink interface {
+	// GetCallStackHelper returns a function that must be called
+	// to mark the direct caller as helper function when logging
+	// call site information.
+	GetCallStackHelper() func()
+}


Test patch:
diff --git a/testing/test.go b/testing/test.go
index 98f7f78..861357f 100644
--- a/testing/test.go
+++ b/testing/test.go
@@ -27,7 +27,8 @@ import (
 // Info logs are only enabled at V(0).
 func NewTestLogger(t *testing.T) logr.Logger {
 	fn := func(prefix, args string) {
+		t.Helper()
 		t.Logf("%s: %s", prefix, args)
 	}
-	return funcr.New(fn, funcr.Options{})
+	return funcr.New(fn, funcr.Options{Helper: t.Helper})
 }
diff --git a/testing/test_test.go b/testing/test_test.go
index 467518d..e4678c3 100644
--- a/testing/test_test.go
+++ b/testing/test_test.go
@@ -19,12 +19,27 @@ package testing
 import (
 	"fmt"
 	"testing"
+
+	"github.com/go-logr/logr"
 )
 
 func TestTestLogger(t *testing.T) {
-	logger := NewTestLogger(t)
-	logger.Info("info")
-	logger.V(0).Info("V(0).info")
-	logger.V(1).Info("v(1).info")
-	logger.Error(fmt.Errorf("error"), "error")
+	log := NewTestLogger(t)
+	log.Info("info")
+	log.V(0).Info("V(0).info")
+	log.V(1).Info("v(1).info")
+	log.Error(fmt.Errorf("error"), "error")
+	Helper(log, "hello world")
+}
+
+func Helper(log logr.Logger, msg string) {
+	helper, log := log.Helper()
+	helper()
+	helper2(log, msg)
+}
+
+func helper2(log logr.Logger, msg string) {
+	helper, log := log.Helper()
+	helper()
+	log.Info(msg)
 }