Repository: kubernetes/klog
Pull request #207 (2021-01-25 08:15:17)

klogr call depth
**What this PR does / why we need it**:

Exposing the call depth support from klog also through the logr interface makes it possible to write generic helper functions around logr instances with correct call locations in the final log messages.

**Special notes for your reviewer**:

Based on https://github.com/kubernetes/klog/pull/197

**Release note**:
```release-note
implement logr.WithCallDepth
```

k8s-ci-robot: [APPROVALNOTIFIER] This PR is **NOT APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/207#" title="Author self-approved">pohly</a>*
To complete the [pull request process](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process), please assign **thockin** after the PR has been reviewed.
You can assign the PR to them by writing `/assign @thockin` in a comment when ready.

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

<details open>
Needs approval from an approver in each of these files:

- **[OWNERS](https://github.com/kubernetes/klog/blob/master/OWNERS)**

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":["thockin"]} -->
dims: @pohly thanks to @thockin we have a new tag https://github.com/go-logr/logr/releases/tag/v0.4.0 please go ahead and update this PR

Patch:
diff --git a/go.mod b/go.mod
index 52c5c24..eb297b6 100644
--- a/go.mod
+++ b/go.mod
@@ -2,4 +2,4 @@ module k8s.io/klog/v2
 
 go 1.13
 
-require github.com/go-logr/logr v0.2.1
+require github.com/go-logr/logr v0.4.0
diff --git a/go.sum b/go.sum
index a685729..5778f81 100644
--- a/go.sum
+++ b/go.sum
@@ -1,2 +1,2 @@
-github.com/go-logr/logr v0.2.1 h1:fV3MLmabKIZ383XifUjFSwcoGee0v9qgPp8wy5svibE=
-github.com/go-logr/logr v0.2.1/go.mod h1:z6/tIYblkpsD+a4lm/fGIIU9mZ+XfAiaFtq7xTgseGU=
+github.com/go-logr/logr v0.4.0 h1:K7/B1jt6fIBQVd4Owv2MqGQClcgf0R266+7C/QjRcLc=
+github.com/go-logr/logr v0.4.0/go.mod h1:z6/tIYblkpsD+a4lm/fGIIU9mZ+XfAiaFtq7xTgseGU=
diff --git a/klogr/klogr.go b/klogr/klogr.go
index a774aee..afd478d 100644
--- a/klogr/klogr.go
+++ b/klogr/klogr.go
@@ -61,10 +61,11 @@ func NewWithOptions(options ...Option) logr.Logger {
 }
 
 type klogger struct {
-	level  int
-	prefix string
-	values []interface{}
-	format Format
+	level     int
+	callDepth int
+	prefix    string
+	values    []interface{}
+	format    Format
 }
 
 func (l klogger) clone() klogger {
@@ -88,6 +89,10 @@ const autogeneratedFrameName = "<autogenerated>"
 // Discover how many frames we need to climb to find the caller. This approach
 // was suggested by Ian Lance Taylor of the Go team, so it *should* be safe
 // enough (famous last words).
+//
+// It is needed because binding the specific klogger functions to the
+// logr interface creates one additional call frame that neither we nor
+// our caller know about.
 func framesToCaller() int {
 	// 1 is the immediate caller.  3 should be too many.
 	for i := 1; i < 3; i++ {
@@ -194,13 +199,13 @@ func (l klogger) Info(msg string, kvList ...interface{}) {
 			trimmed := trimDuplicates(l.values, kvList)
 			fixedStr := flatten(trimmed[0]...)
 			userStr := flatten(trimmed[1]...)
-			klog.InfoDepth(framesToCaller(), l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
+			klog.InfoDepth(framesToCaller()+l.callDepth, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr)
 		case FormatKlog:
 			trimmed := trimDuplicates(l.values, kvList)
 			if l.prefix != "" {
 				msg = l.prefix + ": " + msg
 			}
-			klog.InfoSDepth(framesToCaller(), msg, append(trimmed[0], trimmed[1]...)...)
+			klog.InfoSDepth(framesToCaller()+l.callDepth, msg, append(trimmed[0], trimmed[1]...)...)
 		}
 	}
 }
@@ -221,13 +226,13 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) {
 		trimmed := trimDuplicates(l.values, kvList)
 		fixedStr := flatten(trimmed[0]...)
 		userStr := flatten(trimmed[1]...)
-		klog.ErrorDepth(framesToCaller(), l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
+		klog.ErrorDepth(framesToCaller()+l.callDepth, l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr)
 	case FormatKlog:
 		trimmed := trimDuplicates(l.values, kvList)
 		if l.prefix != "" {
 			msg = l.prefix + ": " + msg
 		}
-		klog.ErrorSDepth(framesToCaller(), err, msg, append(trimmed[0], trimmed[1]...)...)
+		klog.ErrorSDepth(framesToCaller()+l.callDepth, err, msg, append(trimmed[0], trimmed[1]...)...)
 	}
 }
 
@@ -255,4 +260,11 @@ func (l klogger) WithValues(kvList ...interface{}) logr.Logger {
 	return new
 }
 
+func (l klogger) WithCallDepth(depth int) logr.Logger {
+	new := l.clone()
+	new.callDepth += depth
+	return new
+}
+
 var _ logr.Logger = klogger{}
+var _ logr.CallDepthLogger = klogger{}


Test patch:
diff --git a/klogr/calldepth-test/call_depth_helper_test.go b/klogr/calldepth-test/call_depth_helper_test.go
new file mode 100644
index 0000000..be605fb
--- /dev/null
+++ b/klogr/calldepth-test/call_depth_helper_test.go
@@ -0,0 +1,16 @@
+package calldepth
+
+import (
+	"github.com/go-logr/logr"
+)
+
+// Putting these functions into a separate file makes it possible to validate that
+// their source code file is *not* logged because of WithCallDepth(1).
+
+func myInfo(l logr.Logger, msg string) {
+	logr.WithCallDepth(l, 1).Info(msg)
+}
+
+func myInfo2(l logr.Logger, msg string) {
+	myInfo(logr.WithCallDepth(l, 1), msg)
+}
diff --git a/klogr/calldepth-test/call_depth_main_test.go b/klogr/calldepth-test/call_depth_main_test.go
new file mode 100644
index 0000000..6d7e59f
--- /dev/null
+++ b/klogr/calldepth-test/call_depth_main_test.go
@@ -0,0 +1,57 @@
+// Package calldepth does black-box testing.
+//
+// Another intentional effect is that "go test" compiles
+// this into a separate binary which we need because
+// we have to configure klog differently that TestOutput.
+
+package calldepth
+
+import (
+	"bytes"
+	"flag"
+	"strings"
+	"testing"
+
+	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/klogr"
+)
+
+func TestCallDepth(t *testing.T) {
+	klog.InitFlags(nil)
+	flag.CommandLine.Set("v", "10")
+	flag.CommandLine.Set("skip_headers", "false")
+	flag.CommandLine.Set("logtostderr", "false")
+	flag.CommandLine.Set("alsologtostderr", "false")
+	flag.CommandLine.Set("stderrthreshold", "10")
+	flag.Parse()
+
+	t.Run("call-depth", func(t *testing.T) {
+		logr := klogr.New()
+
+		// hijack the klog output
+		tmpWriteBuffer := bytes.NewBuffer(nil)
+		klog.SetOutput(tmpWriteBuffer)
+
+		validate := func(t *testing.T) {
+			output := tmpWriteBuffer.String()
+			if !strings.Contains(output, "call_depth_main_test.go:") {
+				t.Fatalf("output should have contained call_depth_main_test.go, got instead: %s", output)
+			}
+		}
+
+		t.Run("direct", func(t *testing.T) {
+			logr.Info("hello world")
+			validate(t)
+		})
+
+		t.Run("indirect", func(t *testing.T) {
+			myInfo(logr, "hello world")
+			validate(t)
+		})
+
+		t.Run("nested", func(t *testing.T) {
+			myInfo2(logr, "hello world")
+			validate(t)
+		})
+	})
+}