Merge pull request #207 from pohly/klogr-call-depth

klogr call depth

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

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=

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)
+}

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)
+		})
+	})
+}

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{}