diff --git a/klog.go b/klog.go index f4af8f28..f04b85d4 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) diff --git a/klog_test.go b/klog_test.go index 1e368cba..b7f01238 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": {},