Skip to content

Commit

Permalink
Call logr with call depth
Browse files Browse the repository at this point in the history 
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.

Signed-off-by: Sunjay Bhatia <sunjayb@vmware.com>
  • Loading branch information
@sunjayBhatia
sunjayBhatia committed May 4, 2021
1 parent dda2080 commit cf22f1e
Show file tree
Hide file tree
Showing 2 changed files with 230 additions and 11 deletions.
20 changes: 9 additions & 11 deletions klog.go
View file
Expand Up @@ -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{}) {
Expand All @@ -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{}) {
Expand All @@ -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
Expand All @@ -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.
Expand All @@ -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...)
Expand All @@ -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...)
Expand Down Expand Up @@ -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))
Expand Down Expand Up @@ -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) {
Expand All @@ -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)
Expand Down
221 changes: 221 additions & 0 deletions klog_test.go
View file
Expand Up @@ -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
Expand Down Expand Up @@ -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": {},
Expand Down

0 comments on commit cf22f1e

Please sign in to comment.