Repository: go-logr/logr (go)

Issue:
Enabled + stack unwinding
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.
https://github.com/go-logr/logr/blob/eea184c40063709bc85c75834aa3305555441171/logr.go#L278

But it is not correct for the `LogSink.Enabled` call in `Logger.Info`:
https://github.com/go-logr/logr/blob/eea184c40063709bc85c75834aa3305555441171/logr.go#L274

There the call chain is `<user code> -> Logger.Info -> Logger.Enabled -> LogSink.Enabled`.

It is correct again for `<user code> -> Logger.Enabled -> LogSink.Enabled`.



Pull request description:
Use same call depth for Enabled, Info, Error
klog does stack unwinding in `LogSink.Enabled` to implement per-source code verbosity thresholds (`-vmodule`). This worked for `logger.Info` and `logger.Error` because the code was written such that it matches how logr is implemented (Logger.Info -> Logger.Enabled -> LogSink.Enabled).

It did not work for direct calls (`if logger.Enabled`) because then the call chain is `Logger.Enabled -> LogSink.Enabled`.  Now it uses the same depth (as passed to LogSink.Init) for all paths to Enabled.

NOTE: callers who have worked around this bug will need to remove their workarounds.

Fixes #215
Alternative to #216 

Patch:
diff --git a/.github/workflows/apidiff.yaml b/.github/workflows/apidiff.yaml
index 6d19493..f6c6b79 100644
--- a/.github/workflows/apidiff.yaml
+++ b/.github/workflows/apidiff.yaml
@@ -19,12 +19,12 @@ jobs:
       - name: Install dependencies
         run: GO111MODULE=off go get golang.org/x/exp/cmd/apidiff
       - name: Checkout old code
-        uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
+        uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # v3.5.3
         with:
           ref: ${{ github.base_ref }}
           path: "old"
       - name: Checkout new code
-        uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
+        uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # v3.5.3
         with:
           path: "new"
       - name: APIDiff
diff --git a/.github/workflows/lint.yaml b/.github/workflows/lint.yaml
index 5059c12..91cf6ff 100644
--- a/.github/workflows/lint.yaml
+++ b/.github/workflows/lint.yaml
@@ -10,7 +10,7 @@ jobs:
     runs-on: ubuntu-latest
     steps:
       - name: Checkout code
-        uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
+        uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # v3.5.3
       - name: Lint
         uses: golangci/golangci-lint-action@3a919529898de77ec3da873e3063ca4b10e7f5cc # v3.7.0
         with:
diff --git a/.github/workflows/scorecard.yml b/.github/workflows/scorecard.yml
index 467c2e9..bdeb925 100644
--- a/.github/workflows/scorecard.yml
+++ b/.github/workflows/scorecard.yml
@@ -29,7 +29,7 @@ jobs:
 
     steps:
       - name: "Checkout code"
-        uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
+        uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # v3.5.3
         with:
           persist-credentials: false
 
@@ -59,6 +59,6 @@ jobs:
 
       # Upload the results to GitHub's code scanning dashboard.
       - name: "Upload to code-scanning"
-        uses: github/codeql-action/upload-sarif@00e563ead9f72a8461b24876bee2d0c2e8bd2ee8 # v2.21.5
+        uses: github/codeql-action/upload-sarif@a09933a12a80f87b87005513f0abb1494c27a716 # v2.21.4
         with:
           sarif_file: results.sarif
diff --git a/logr.go b/logr.go
index b6f4049..2a5075a 100644
--- a/logr.go
+++ b/logr.go
@@ -258,6 +258,12 @@ type Logger struct {
 // Enabled tests whether this Logger is enabled.  For example, commandline
 // flags might be used to set the logging verbosity and disable some info logs.
 func (l Logger) Enabled() bool {
+	// Some implementations of LogSink look at the caller in Enabled (e.g.
+	// different verbosity levels per package or file), but we only pass one
+	// CallDepth in (via Init).  This means that all calls from Logger to the
+	// LogSink's Enabled, Info, and Error methods must have the same number of
+	// frames.  In other words, Logger methods can't call other Logger methods
+	// which call these LogSink methods unless we do it the same in all paths.
 	return l.sink != nil && l.sink.Enabled(l.level)
 }
 
@@ -271,7 +277,7 @@ func (l Logger) Info(msg string, keysAndValues ...any) {
 	if l.sink == nil {
 		return
 	}
-	if l.Enabled() {
+	if l.sink.Enabled(l.level) { // see comment in Enabled
 		if withHelper, ok := l.sink.(CallStackHelperLogSink); ok {
 			withHelper.GetCallStackHelper()()
 		}


Test patch:
diff --git a/.github/workflows/tests.yaml b/.github/workflows/tests.yaml
index 80ff32c..d27e3c5 100644
--- a/.github/workflows/tests.yaml
+++ b/.github/workflows/tests.yaml
@@ -18,7 +18,7 @@ jobs:
       with:
         go-version: ${{ matrix.version }}
     - name: Checkout code
-      uses: actions/checkout@f43a0e5ff2bd294095638e18286ca9a3d1956744 # v3.6.0
+      uses: actions/checkout@c85c95e3d7251135ab7dc9ce3241c5835cc595a9 # v3.5.3
     - name: Build
       run: go build -v ./...
     - name: Test
diff --git a/logr_test.go b/logr_test.go
index af5b2be..30f0b8f 100644
--- a/logr_test.go
+++ b/logr_test.go
@@ -21,6 +21,7 @@ import (
 	"errors"
 	"fmt"
 	"reflect"
+	"runtime"
 	"testing"
 )
 
@@ -443,6 +444,49 @@ func TestZeroValue(t *testing.T) {
 	_, _ = l.WithCallStackHelper()
 }
 
+func TestCallDepthConsistent(t *testing.T) {
+	sink := &testLogSink{}
+
+	depth := 0
+	expect := "github.com/go-logr/logr.TestCallDepthConsistent"
+	sink.fnInit = func(ri RuntimeInfo) {
+		depth = ri.CallDepth + 1 // 1 for these function pointers
+		if caller := getCaller(depth); caller != expect {
+			t.Errorf("identified wrong caller %q", caller)
+		}
+
+	}
+	sink.fnEnabled = func(_ int) bool {
+		if caller := getCaller(depth); caller != expect {
+			t.Errorf("identified wrong caller %q", caller)
+		}
+		return true
+	}
+	sink.fnError = func(_ error, _ string, _ ...any) {
+		if caller := getCaller(depth); caller != expect {
+			t.Errorf("identified wrong caller %q", caller)
+		}
+	}
+	l := New(sink)
+
+	l.Enabled()
+	l.Info("msg")
+	l.Error(nil, "msg")
+}
+
+func getCaller(depth int) string {
+	// +1 for this frame, +1 for Info/Error/Enabled.
+	pc, _, _, ok := runtime.Caller(depth + 2)
+	if !ok {
+		return "<runtime.Caller failed>"
+	}
+	fp := runtime.FuncForPC(pc)
+	if fp == nil {
+		return "<runtime.FuncForPC failed>"
+	}
+	return fp.Name()
+}
+
 func expectEqual[T comparable](tb testing.TB, msg string, expected, actual T) bool {
 	if expected == actual {
 		return true