Repository: kubernetes/klog
Pull request #210 (2021-02-08 23:19:47)

Call backing logr with call depth
**What this PR does / why we need it**:
When a backing `logr` implementation is in use, take advantage of the `CallDepthLogger` interface to pass along contextual information that might be useful to the `logr` implementation.

**Release note**:
```release-note
When backing `logr` implementation is a `CallDepthLogger`, pass call depth
```

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

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/210#" title="Author self-approved">sunjayBhatia</a>*
To complete the [pull request process](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process), please assign **lavalamp** after the PR has been reviewed.
You can assign the PR to them by writing `/assign @lavalamp` 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":["lavalamp"]} -->
dims: /assign @DirectXMan12 
/approve
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/210#issuecomment-775553061" title="Approved">dims</a>*, *<a href="https://github.com/kubernetes/klog/pull/210#" title="Author self-approved">sunjayBhatia</a>*

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

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

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

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

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":[]} -->
sunjayBhatia: @DirectXMan12 have you had a chance to review this yet?
sunjayBhatia: @dims @DirectXMan12 have you gotten a chance to review this?
dims: @DirectXMan12 ping.
dims: @sunjayBhatia please ping me after you have addressed @pohly 's comments and an `/lgtm` :)
sunjayBhatia: Thanks for the review @pohly! I should be able to get to resolving things today or monday 👍🏽 
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/210#issuecomment-775553061" title="Approved">dims</a>*, *<a href="https://github.com/kubernetes/klog/pull/210#pullrequestreview-650933624" title="Approved">pohly</a>*, *<a href="https://github.com/kubernetes/klog/pull/210#" title="Author self-approved">sunjayBhatia</a>*

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

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

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

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

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":[]} -->
dims: /hold for squash

Patch:
diff --git a/klog.go b/klog.go
index f4af8f2..f04b85d 100644
--- a/klog.go
+++ b/klog.go
@@ -708,7 +708,7 @@ func (l *loggingT) println(s severity, logr logr.Logger, filter LogFilter, args
 		args = filter.Filter(args)
 	}
 	fmt.Fprintln(buf, args...)
-	l.output(s, logr, buf, file, line, false)
+	l.output(s, logr, buf, 0 /* depth */, file, line, false)
 }
 
 func (l *loggingT) print(s severity, logr logr.Logger, filter LogFilter, args ...interface{}) {
@@ -730,7 +730,7 @@ func (l *loggingT) printDepth(s severity, logr logr.Logger, filter LogFilter, de
 	if buf.Bytes()[buf.Len()-1] != '\n' {
 		buf.WriteByte('\n')
 	}
-	l.output(s, logr, buf, file, line, false)
+	l.output(s, logr, buf, depth, file, line, false)
 }
 
 func (l *loggingT) printf(s severity, logr logr.Logger, filter LogFilter, format string, args ...interface{}) {
@@ -748,7 +748,7 @@ func (l *loggingT) printf(s severity, logr logr.Logger, filter LogFilter, format
 	if buf.Bytes()[buf.Len()-1] != '\n' {
 		buf.WriteByte('\n')
 	}
-	l.output(s, logr, buf, file, line, false)
+	l.output(s, logr, buf, 0 /* depth */, file, line, false)
 }
 
 // printWithFileLine behaves like print but uses the provided file and line number.  If
@@ -769,7 +769,7 @@ func (l *loggingT) printWithFileLine(s severity, logr logr.Logger, filter LogFil
 	if buf.Bytes()[buf.Len()-1] != '\n' {
 		buf.WriteByte('\n')
 	}
-	l.output(s, logr, buf, file, line, alsoToStderr)
+	l.output(s, logr, buf, 2 /* depth */, file, line, alsoToStderr)
 }
 
 // if loggr is specified, will call loggr.Error, otherwise output with logging module.
@@ -778,7 +778,7 @@ func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, depth
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
 	if loggr != nil {
-		loggr.Error(err, msg, keysAndValues...)
+		logr.WithCallDepth(loggr, depth+2).Error(err, msg, keysAndValues...)
 		return
 	}
 	l.printS(err, errorLog, depth+1, msg, keysAndValues...)
@@ -790,7 +790,7 @@ func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, depth int, msg str
 		msg, keysAndValues = filter.FilterS(msg, keysAndValues)
 	}
 	if loggr != nil {
-		loggr.Info(msg, keysAndValues...)
+		logr.WithCallDepth(loggr, depth+2).Info(msg, keysAndValues...)
 		return
 	}
 	l.printS(nil, infoLog, depth+1, msg, keysAndValues...)
@@ -855,8 +855,6 @@ func (rb *redirectBuffer) Write(bytes []byte) (n int, err error) {
 // SetLogger will set the backing logr implementation for klog.
 // If set, all log lines will be suppressed from the regular Output, and
 // redirected to the logr implementation.
-// All log lines include the 'severity', 'file' and 'line' values attached as
-// structured logging values.
 // Use as:
 //   ...
 //   klog.SetLogger(zapr.NewLogger(zapLog))
@@ -902,7 +900,7 @@ func LogToStderr(stderr bool) {
 }
 
 // output writes the data to the log files and releases the buffer.
-func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, file string, line int, alsoToStderr bool) {
+func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, depth int, file string, line int, alsoToStderr bool) {
 	l.mu.Lock()
 	if l.traceLocation.isSet() {
 		if l.traceLocation.match(file, line) {
@@ -914,9 +912,9 @@ func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, file string,
 		// TODO: set 'severity' and caller information as structured log info
 		// keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line}
 		if s == errorLog {
-			l.logr.Error(nil, string(data))
+			logr.WithCallDepth(l.logr, depth+3).Error(nil, string(data))
 		} else {
-			log.Info(string(data))
+			logr.WithCallDepth(log, depth+3).Info(string(data))
 		}
 	} else if l.toStderr {
 		os.Stderr.Write(data)


Test patch:
diff --git a/klog_test.go b/klog_test.go
index 1e368cb..b7f0123 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -1447,6 +1447,167 @@ func TestErrorSWithLogr(t *testing.T) {
 	}
 }
 
+func TestCallDepthLogr(t *testing.T) {
+	logger := &callDepthTestLogr{}
+	logger.resetCallDepth()
+
+	testCases := []struct {
+		name  string
+		logFn func()
+	}{
+		{
+			name:  "Info log",
+			logFn: func() { Info("info log") },
+		},
+		{
+			name:  "InfoDepth log",
+			logFn: func() { InfoDepth(0, "infodepth log") },
+		},
+		{
+			name:  "InfoSDepth log",
+			logFn: func() { InfoSDepth(0, "infoSDepth log") },
+		},
+		{
+			name:  "Warning log",
+			logFn: func() { Warning("warning log") },
+		},
+		{
+			name:  "WarningDepth log",
+			logFn: func() { WarningDepth(0, "warningdepth log") },
+		},
+		{
+			name:  "Error log",
+			logFn: func() { Error("error log") },
+		},
+		{
+			name:  "ErrorDepth log",
+			logFn: func() { ErrorDepth(0, "errordepth log") },
+		},
+		{
+			name:  "ErrorSDepth log",
+			logFn: func() { ErrorSDepth(0, errors.New("some error"), "errorSDepth log") },
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			SetLogger(logger)
+			defer SetLogger(nil)
+			defer logger.reset()
+			defer logger.resetCallDepth()
+
+			// Keep these lines together.
+			_, wantFile, wantLine, _ := runtime.Caller(0)
+			tc.logFn()
+			wantLine++
+
+			if len(logger.entries) != 1 {
+				t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+			}
+			checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+		})
+	}
+}
+
+func TestCallDepthLogrInfoS(t *testing.T) {
+	logger := &callDepthTestLogr{}
+	logger.resetCallDepth()
+	SetLogger(logger)
+
+	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
+	logFunc := func() {
+		InfoS("infoS log")
+	}
+
+	// Keep these lines together.
+	_, wantFile, wantLine, _ := runtime.Caller(0)
+	logFunc()
+	wantLine++
+
+	if len(logger.entries) != 1 {
+		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+	}
+	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+}
+
+func TestCallDepthLogrErrorS(t *testing.T) {
+	logger := &callDepthTestLogr{}
+	logger.resetCallDepth()
+	SetLogger(logger)
+
+	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
+	logFunc := func() {
+		ErrorS(errors.New("some error"), "errorS log")
+	}
+
+	// Keep these lines together.
+	_, wantFile, wantLine, _ := runtime.Caller(0)
+	logFunc()
+	wantLine++
+
+	if len(logger.entries) != 1 {
+		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+	}
+	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+}
+
+func TestCallDepthLogrGoLog(t *testing.T) {
+	logger := &callDepthTestLogr{}
+	logger.resetCallDepth()
+	SetLogger(logger)
+	CopyStandardLogTo("INFO")
+
+	// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
+	logFunc := func() {
+		stdLog.Print("some log")
+	}
+
+	// Keep these lines together.
+	_, wantFile, wantLine, _ := runtime.Caller(0)
+	logFunc()
+	wantLine++
+
+	if len(logger.entries) != 1 {
+		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+	}
+	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+	fmt.Println(logger.entries[0])
+}
+
+// Test callDepthTestLogr logs the expected offsets.
+func TestCallDepthTestLogr(t *testing.T) {
+	logger := &callDepthTestLogr{}
+	logger.resetCallDepth()
+
+	logFunc := func() {
+		logger.Info("some info log")
+	}
+	// Keep these lines together.
+	_, wantFile, wantLine, _ := runtime.Caller(0)
+	logFunc()
+	wantLine++
+
+	if len(logger.entries) != 1 {
+		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+	}
+	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+
+	logger.reset()
+
+	logFunc = func() {
+		logger.Error(errors.New("error"), "some error log")
+	}
+	// Keep these lines together.
+	_, wantFile, wantLine, _ = runtime.Caller(0)
+	logFunc()
+	wantLine++
+
+	if len(logger.entries) != 1 {
+		t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
+	}
+	checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
+}
+
 type testLogr struct {
 	entries []testLogrEntry
 	mutex   sync.Mutex
@@ -1493,6 +1654,66 @@ func (l *testLogr) WithValues(...interface{}) logr.Logger {
 	panic("not implemented")
 }
 
+type callDepthTestLogr struct {
+	testLogr
+	callDepth int
+}
+
+func (l *callDepthTestLogr) resetCallDepth() {
+	l.mutex.Lock()
+	defer l.mutex.Unlock()
+	l.callDepth = 0
+}
+
+func (l *callDepthTestLogr) WithCallDepth(depth int) logr.Logger {
+	l.mutex.Lock()
+	defer l.mutex.Unlock()
+	// Note: Usually WithCallDepth would be implemented by cloning l
+	// and setting the call depth on the clone. We modify l instead in
+	// this test helper for simplicity.
+	l.callDepth = depth
+	return l
+}
+
+func (l *callDepthTestLogr) Info(msg string, keysAndValues ...interface{}) {
+	l.mutex.Lock()
+	defer l.mutex.Unlock()
+	// Add 2 to depth for the wrapper function caller and for invocation in
+	// test case.
+	_, file, line, _ := runtime.Caller(l.callDepth + 2)
+	l.entries = append(l.entries, testLogrEntry{
+		severity:      infoLog,
+		msg:           msg,
+		keysAndValues: append([]interface{}{file, line}, keysAndValues...),
+	})
+}
+
+func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interface{}) {
+	l.mutex.Lock()
+	defer l.mutex.Unlock()
+	// Add 2 to depth for the wrapper function caller and for invocation in
+	// test case.
+	_, file, line, _ := runtime.Caller(l.callDepth + 2)
+	l.entries = append(l.entries, testLogrEntry{
+		severity:      errorLog,
+		msg:           msg,
+		keysAndValues: append([]interface{}{file, line}, keysAndValues...),
+		err:           err,
+	})
+}
+
+func checkLogrEntryCorrectCaller(t *testing.T, wantFile string, wantLine int, entry testLogrEntry) {
+	t.Helper()
+
+	want := fmt.Sprintf("%s:%d", wantFile, wantLine)
+	// Log fields contain file and line number as first elements.
+	got := fmt.Sprintf("%s:%d", entry.keysAndValues[0], entry.keysAndValues[1])
+
+	if want != got {
+		t.Errorf("expected file and line %q but got %q", want, got)
+	}
+}
+
 // existedFlag contains all existed flag, without KlogPrefix
 var existedFlag = map[string]struct{}{
 	"log_dir":           {},