From 4171f3c1be1b60901704dfbd140b9f03161427b1 Mon Sep 17 00:00:00 2001 From: Davanum Srinivas Date: Sat, 29 May 2021 22:41:17 -0400 Subject: [PATCH] Switching to logr tag v1.0.0 Signed-off-by: Davanum Srinivas --- go.mod | 2 +- go.sum | 6 +- klog.go | 66 +++++----- klog_test.go | 54 ++++---- .../calldepth-test/call_depth_helper_test.go | 4 +- klogr/klogr.go | 115 ++++++------------ klogr/klogr_test.go | 10 +- 7 files changed, 117 insertions(+), 140 deletions(-) diff --git a/go.mod b/go.mod index eb297b6a..08a2d0f3 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.4.0 +require github.com/go-logr/logr v1.0.0 diff --git a/go.sum b/go.sum index 5778f817..a1b90e4b 100644 --- a/go.sum +++ b/go.sum @@ -1,2 +1,4 @@ -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= +github.com/go-logr/logr v1.0.0-rc1 h1:+ul9F74rBkPajeP8m4o3o0tiglmzNFsPnuhYyBCQ0Sc= +github.com/go-logr/logr v1.0.0-rc1/go.mod h1:z6/tIYblkpsD+a4lm/fGIIU9mZ+XfAiaFtq7xTgseGU= +github.com/go-logr/logr v1.0.0 h1:kH951GinvFVaQgy/ki/B3YYmQtRpExGigSJg6O8z5jo= +github.com/go-logr/logr v1.0.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= diff --git a/klog.go b/klog.go index d24087de..d6f52bd4 100644 --- a/klog.go +++ b/klog.go @@ -509,7 +509,7 @@ type loggingT struct { addDirHeader bool // If set, all output will be redirected unconditionally to the provided logr.Logger - logr logr.Logger + logr *logr.Logger // If true, messages will not be propagated to lower severity log levels oneOutput bool @@ -698,11 +698,11 @@ func (buf *buffer) someDigits(i, d int) int { return copy(buf.tmp[i:], buf.tmp[j:]) } -func (l *loggingT) println(s severity, logr logr.Logger, filter LogFilter, args ...interface{}) { +func (l *loggingT) println(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { buf, file, line := l.header(s, 0) - // if logr is set, we clear the generated header as we rely on the backing - // logr implementation to print headers - if logr != nil { + // if logger is set, we clear the generated header as we rely on the backing + // logger implementation to print headers + if logger != nil { l.putBuffer(buf) buf = l.getBuffer() } @@ -710,18 +710,18 @@ 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, 0 /* depth */, file, line, false) + l.output(s, logger, buf, 0 /* depth */, file, line, false) } -func (l *loggingT) print(s severity, logr logr.Logger, filter LogFilter, args ...interface{}) { - l.printDepth(s, logr, filter, 1, args...) +func (l *loggingT) print(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { + l.printDepth(s, logger, filter, 1, args...) } -func (l *loggingT) printDepth(s severity, logr logr.Logger, filter LogFilter, depth int, args ...interface{}) { +func (l *loggingT) printDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) { buf, file, line := l.header(s, depth) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers - if logr != nil { + if logger != nil { l.putBuffer(buf) buf = l.getBuffer() } @@ -732,14 +732,14 @@ 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, depth, file, line, false) + l.output(s, logger, buf, depth, file, line, false) } -func (l *loggingT) printf(s severity, logr logr.Logger, filter LogFilter, format string, args ...interface{}) { +func (l *loggingT) printf(s severity, logger *logr.Logger, filter LogFilter, format string, args ...interface{}) { buf, file, line := l.header(s, 0) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers - if logr != nil { + if logger != nil { l.putBuffer(buf) buf = l.getBuffer() } @@ -750,17 +750,17 @@ 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, 0 /* depth */, file, line, false) + l.output(s, logger, buf, 0 /* depth */, file, line, false) } // printWithFileLine behaves like print but uses the provided file and line number. If // alsoLogToStderr is true, the log message always appears on standard error; it // will also appear in the log file unless --logtostderr is set. -func (l *loggingT) printWithFileLine(s severity, logr logr.Logger, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) { +func (l *loggingT) printWithFileLine(s severity, logger *logr.Logger, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) { buf := l.formatHeader(s, file, line) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers - if logr != nil { + if logger != nil { l.putBuffer(buf) buf = l.getBuffer() } @@ -771,28 +771,28 @@ 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, 2 /* depth */, file, line, alsoToStderr) + l.output(s, logger, buf, 2 /* depth */, file, line, alsoToStderr) } // if loggr is specified, will call loggr.Error, otherwise output with logging module. -func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) { +func (l *loggingT) errorS(err error, logger *logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) { if filter != nil { msg, keysAndValues = filter.FilterS(msg, keysAndValues) } - if loggr != nil { - logr.WithCallDepth(loggr, depth+2).Error(err, msg, keysAndValues...) + if logger != nil { + logger.WithCallDepth(depth+2).Error(err, msg, keysAndValues...) return } l.printS(err, errorLog, depth+1, msg, keysAndValues...) } // if loggr is specified, will call loggr.Info, otherwise output with logging module. -func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) { +func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg string, keysAndValues ...interface{}) { if filter != nil { msg, keysAndValues = filter.FilterS(msg, keysAndValues) } - if loggr != nil { - logr.WithCallDepth(loggr, depth+2).Info(msg, keysAndValues...) + if logger != nil { + logger.WithCallDepth(depth+2).Info(msg, keysAndValues...) return } l.printS(nil, infoLog, depth+1, msg, keysAndValues...) @@ -866,7 +866,14 @@ func SetLogger(logr logr.Logger) { logging.mu.Lock() defer logging.mu.Unlock() - logging.logr = logr + logging.logr = &logr +} + +func clearLogger() { + logging.mu.Lock() + defer logging.mu.Unlock() + + logging.logr = nil } // SetOutput sets the output destination for all severities @@ -904,7 +911,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, depth int, 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) { @@ -916,9 +923,9 @@ func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, depth int, f // TODO: set 'severity' and caller information as structured log info // keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line} if s == errorLog { - logr.WithCallDepth(l.logr, depth+3).Error(nil, string(data)) + l.logr.WithCallDepth(depth+3).Error(nil, string(data)) } else { - logr.WithCallDepth(log, depth+3).Info(string(data)) + log.WithCallDepth(depth + 3).Info(string(data)) } } else if l.toStderr { os.Stderr.Write(data) @@ -1269,7 +1276,7 @@ func (l *loggingT) setV(pc uintptr) Level { // See the documentation of V for more information. type Verbose struct { enabled bool - logr logr.Logger + logr *logr.Logger filter LogFilter } @@ -1277,7 +1284,8 @@ func newVerbose(level Level, b bool) Verbose { if logging.logr == nil { return Verbose{b, nil, logging.filter} } - return Verbose{b, logging.logr.V(int(level)), logging.filter} + v := logging.logr.V(int(level)) + return Verbose{b, &v, logging.filter} } // V reports whether verbosity at the call site is at least the requested level. diff --git a/klog_test.go b/klog_test.go index 7f6a6471..0df1420f 100644 --- a/klog_test.go +++ b/klog_test.go @@ -446,7 +446,7 @@ func testVmoduleGlob(pat string, match bool, t *testing.T) { defer logging.vmodule.Set("") logging.vmodule.Set(pat) if V(2).Enabled() != match { - t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match) + t.Errorf("incorrect match for %q: got %#v expected %#v", pat, V(2), match) } } @@ -1375,8 +1375,9 @@ func TestInfoSWithLogr(t *testing.T) { for _, data := range testDataInfo { t.Run(data.msg, func(t *testing.T) { - SetLogger(logger) - defer SetLogger(nil) + l := logr.New(logger) + SetLogger(l) + defer clearLogger() defer logger.reset() InfoS(data.msg, data.keysValues...) @@ -1442,8 +1443,9 @@ func TestErrorSWithLogr(t *testing.T) { for _, data := range testDataInfo { t.Run(data.msg, func(t *testing.T) { - SetLogger(logger) - defer SetLogger(nil) + l := logr.New(logger) + SetLogger(l) + defer clearLogger() defer logger.reset() ErrorS(data.err, data.msg, data.keysValues...) @@ -1499,8 +1501,9 @@ func TestCallDepthLogr(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { - SetLogger(logger) - defer SetLogger(nil) + l := logr.New(logger) + SetLogger(l) + defer clearLogger() defer logger.reset() defer logger.resetCallDepth() @@ -1520,7 +1523,8 @@ func TestCallDepthLogr(t *testing.T) { func TestCallDepthLogrInfoS(t *testing.T) { logger := &callDepthTestLogr{} logger.resetCallDepth() - SetLogger(logger) + l := logr.New(logger) + SetLogger(l) // Add wrapper to ensure callDepthTestLogr +2 offset is correct. logFunc := func() { @@ -1541,7 +1545,8 @@ func TestCallDepthLogrInfoS(t *testing.T) { func TestCallDepthLogrErrorS(t *testing.T) { logger := &callDepthTestLogr{} logger.resetCallDepth() - SetLogger(logger) + l := logr.New(logger) + SetLogger(l) // Add wrapper to ensure callDepthTestLogr +2 offset is correct. logFunc := func() { @@ -1562,7 +1567,8 @@ func TestCallDepthLogrErrorS(t *testing.T) { func TestCallDepthLogrGoLog(t *testing.T) { logger := &callDepthTestLogr{} logger.resetCallDepth() - SetLogger(logger) + l := logr.New(logger) + SetLogger(l) CopyStandardLogTo("INFO") // Add wrapper to ensure callDepthTestLogr +2 offset is correct. @@ -1588,7 +1594,7 @@ func TestCallDepthTestLogr(t *testing.T) { logger.resetCallDepth() logFunc := func() { - logger.Info("some info log") + logger.Info(0, "some info log") } // Keep these lines together. _, wantFile, wantLine, _ := runtime.Caller(0) @@ -1634,7 +1640,7 @@ func (l *testLogr) reset() { l.entries = []testLogrEntry{} } -func (l *testLogr) Info(msg string, keysAndValues ...interface{}) { +func (l *testLogr) Info(level int, msg string, keysAndValues ...interface{}) { l.mutex.Lock() defer l.mutex.Unlock() l.entries = append(l.entries, testLogrEntry{ @@ -1655,12 +1661,15 @@ func (l *testLogr) Error(err error, msg string, keysAndValues ...interface{}) { }) } -func (l *testLogr) Enabled() bool { panic("not implemented") } -func (l *testLogr) V(int) logr.Logger { panic("not implemented") } -func (l *testLogr) WithName(string) logr.Logger { panic("not implemented") } -func (l *testLogr) WithValues(...interface{}) logr.Logger { - panic("not implemented") -} +func (l *testLogr) Init(info logr.RuntimeInfo) {} +func (l *testLogr) Enabled(level int) bool { return true } +func (l *testLogr) V(int) logr.Logger { panic("not implemented") } +func (l *testLogr) WithName(string) logr.LogSink { panic("not implemented") } +func (l *testLogr) WithValues(...interface{}) logr.LogSink { panic("not implemented") } +func (l *testLogr) WithCallDepth(depth int) logr.LogSink { return l } + +var _ logr.LogSink = &testLogr{} +var _ logr.CallDepthLogSink = &testLogr{} type callDepthTestLogr struct { testLogr @@ -1673,17 +1682,17 @@ func (l *callDepthTestLogr) resetCallDepth() { l.callDepth = 0 } -func (l *callDepthTestLogr) WithCallDepth(depth int) logr.Logger { +func (l *callDepthTestLogr) WithCallDepth(depth int) logr.LogSink { 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 + l.callDepth = depth + 1 return l } -func (l *callDepthTestLogr) Info(msg string, keysAndValues ...interface{}) { +func (l *callDepthTestLogr) Info(level int, msg string, keysAndValues ...interface{}) { l.mutex.Lock() defer l.mutex.Unlock() // Add 2 to depth for the wrapper function caller and for invocation in @@ -1710,6 +1719,9 @@ func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interf }) } +var _ logr.LogSink = &callDepthTestLogr{} +var _ logr.CallDepthLogSink = &callDepthTestLogr{} + func checkLogrEntryCorrectCaller(t *testing.T, wantFile string, wantLine int, entry testLogrEntry) { t.Helper() diff --git a/klogr/calldepth-test/call_depth_helper_test.go b/klogr/calldepth-test/call_depth_helper_test.go index be605fb7..03326bf5 100644 --- a/klogr/calldepth-test/call_depth_helper_test.go +++ b/klogr/calldepth-test/call_depth_helper_test.go @@ -8,9 +8,9 @@ import ( // their source code file is *not* logged because of WithCallDepth(1). func myInfo(l logr.Logger, msg string) { - logr.WithCallDepth(l, 1).Info(msg) + l.WithCallDepth(2).Info(msg) } func myInfo2(l logr.Logger, msg string) { - myInfo(logr.WithCallDepth(l, 1), msg) + myInfo(l.WithCallDepth(2), msg) } diff --git a/klogr/klogr.go b/klogr/klogr.go index 4cf80dd1..a347a884 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -6,12 +6,10 @@ import ( "bytes" "encoding/json" "fmt" - "runtime" - "sort" - "strings" - "github.com/go-logr/logr" "k8s.io/klog/v2" + "sort" + "strings" ) // Option is a functional option that reconfigures the logger created with New. @@ -57,7 +55,7 @@ func NewWithOptions(options ...Option) logr.Logger { for _, option := range options { option(&l) } - return l + return logr.New(&l) } type klogger struct { @@ -68,40 +66,8 @@ type klogger struct { format Format } -func (l klogger) clone() klogger { - return klogger{ - level: l.level, - prefix: l.prefix, - values: copySlice(l.values), - format: l.format, - } -} - -func copySlice(in []interface{}) []interface{} { - out := make([]interface{}, len(in)) - copy(out, in) - return out -} - -// Magic string for intermediate frames that we should ignore. -const autogeneratedFrameName = "" - -// 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++ { - _, file, _, _ := runtime.Caller(i + 1) // +1 for this function's frame - if file != autogeneratedFrameName { - return i - } - } - return 1 // something went wrong, this is safe +func (l *klogger) Init(info logr.RuntimeInfo) { + l.callDepth += info.CallDepth } // trimDuplicates will deduplicate elements provided in multiple KV tuple @@ -191,27 +157,25 @@ func pretty(value interface{}) string { return strings.TrimSpace(string(buffer.Bytes())) } -func (l klogger) Info(msg string, kvList ...interface{}) { - if l.Enabled() { - switch l.format { - case FormatSerialize: - msgStr := flatten("msg", msg) - trimmed := trimDuplicates(l.values, kvList) - fixedStr := flatten(trimmed[0]...) - userStr := flatten(trimmed[1]...) - 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()+l.callDepth, msg, append(trimmed[0], trimmed[1]...)...) +func (l klogger) Info(level int, msg string, kvList ...interface{}) { + switch l.format { + case FormatSerialize: + msgStr := flatten("msg", msg) + trimmed := trimDuplicates(l.values, kvList) + fixedStr := flatten(trimmed[0]...) + userStr := flatten(trimmed[1]...) + klog.InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr) + case FormatKlog: + trimmed := trimDuplicates(l.values, kvList) + if l.prefix != "" { + msg = l.prefix + ": " + msg } + klog.InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...) } } -func (l klogger) Enabled() bool { - return bool(klog.V(klog.Level(l.level)).Enabled()) +func (l klogger) Enabled(level int) bool { + return klog.V(klog.Level(level)).Enabled() } func (l klogger) Error(err error, msg string, kvList ...interface{}) { @@ -226,45 +190,38 @@ 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.callDepth, l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr) + klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr) case FormatKlog: trimmed := trimDuplicates(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - klog.ErrorSDepth(framesToCaller()+l.callDepth, err, msg, append(trimmed[0], trimmed[1]...)...) + klog.ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...) } } -func (l klogger) V(level int) logr.Logger { - new := l.clone() - new.level = level - return new -} - // WithName returns a new logr.Logger with the specified name appended. klogr // uses '/' characters to separate name elements. Callers should not pass '/' // in the provided name string, but this library does not actually enforce that. -func (l klogger) WithName(name string) logr.Logger { - new := l.clone() +func (l klogger) WithName(name string) logr.LogSink { if len(l.prefix) > 0 { - new.prefix = l.prefix + "/" + l.prefix = l.prefix + "/" } - new.prefix += name - return new + l.prefix += name + return &l } -func (l klogger) WithValues(kvList ...interface{}) logr.Logger { - new := l.clone() - new.values = append(new.values, kvList...) - return new +func (l klogger) WithValues(kvList ...interface{}) logr.LogSink { + // Three slice args forces a copy. + n := len(l.values) + l.values = append(l.values[:n:n], kvList...) + return &l } -func (l klogger) WithCallDepth(depth int) logr.Logger { - new := l.clone() - new.callDepth += depth - return new +func (l klogger) WithCallDepth(depth int) logr.LogSink { + l.callDepth += depth + return &l } -var _ logr.Logger = klogger{} -var _ logr.CallDepthLogger = klogger{} +var _ logr.LogSink = &klogger{} +var _ logr.CallDepthLogSink = &klogger{} diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index cb86cc30..7775b436 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -110,6 +110,7 @@ func testOutput(t *testing.T, format string) { `, }, "should correctly handle odd-numbers of KVs": { + klogr: new(), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"=null @@ -118,6 +119,7 @@ func testOutput(t *testing.T, format string) { `, }, "should correctly html characters": { + klogr: new(), text: "test", keysAndValues: []interface{}{"akey", "<&>"}, expectedOutput: ` "msg"="test" "akey"="<&>" @@ -169,19 +171,15 @@ func testOutput(t *testing.T, format string) { } for n, test := range tests { t.Run(n, func(t *testing.T) { - klogr := test.klogr - if klogr == nil { - klogr = new() - } // hijack the klog output tmpWriteBuffer := bytes.NewBuffer(nil) klog.SetOutput(tmpWriteBuffer) if test.err != nil { - klogr.Error(test.err, test.text, test.keysAndValues...) + test.klogr.Error(test.err, test.text, test.keysAndValues...) } else { - klogr.Info(test.text, test.keysAndValues...) + test.klogr.Info(test.text, test.keysAndValues...) } // call Flush to ensure the text isn't still buffered