Enabled + stack unwinding

[pohly]

RuntimeInfo.CallDepth is documented as:

	// CallDepth is the number of call frames the logr library adds between the
	// end-user and the LogSink.  LogSink implementations which choose to print
	// the original logging site (e.g. file & line) should climb this many
	// additional frames to find it.

It's 1, which is correct for the LogSink.Info and LogSink.Error calls, e.g.

logr/logr.go

Line 278 in eea184c

l.sink.Info(l.level, msg, keysAndValues...)

But it is not correct for the LogSink.Enabled call in Logger.Info:

logr/logr.go

Line 274 in eea184c

if l.Enabled() {

There the call chain is <user code> -> Logger.Info -> Logger.Enabled -> LogSink.Enabled.

It is correct again for <user code> -> Logger.Enabled -> LogSink.Enabled.

[pohly]

My initial reaction was that Logger.Info needs to be changed, but existing code is more likely to have tests for that code path and thus might have been written so that it compensates for the bug. Fixing the bug will break that code.

I'll check with klog, which does stack unwinding in Enabled for -vmodule.

I noticed because I am using the if loggerV := logger.V(6); loggerV.Enabled() pattern and didn't get the expected output when combining that with -vmodule.

[pohly]

I did indeed adapt to this in kubernetes/klog@125ecfe.

The Enabled methods skip one additional stack frame to match the behavior of Logger.Info. What I hadn't realized at that time is that they also get called through Logger.Enabled directly by the user code.

[thockin]

Why does Enabled() care about call depth?

[pohly]

Because -v=3 -vmodule=mysourcefile=6 increases the verbosity threshold in mysourcefile.go to 6 while it is 3 elsewhere.

mysourcefile.go might contains this:

   if loggerV := logger.V(6); loggerV.Enabled(); { loggerV.Info("Log message with details", .... }

Here Enabled must do correct stack unwinding to find mysourcefile.go as caller.

[thockin]

Ahh, I see. It's not that Error() or Info() find the wrong caller, but some (out of tree) implementations of Enabled() need to know the caller.

We can either inline the impl of Enabled() into Info/Error or we can force them all thru a common helper and document why.

Or we can just document it, but that seems unfortunate

[pohly]

We have to make it consistent, otherwise LogSink.Enabled won't know how much it should skip. I prefer to not break usage of the more common logger.Info and logger.Error: #216

Let's not decide yet, I first want to test this with klog.

[thockin]

We should not need to break anything - we might need to change the depth that is passed to init