From 009a04a3c02d8e53d467c07af1d1450688e9489f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 23 Oct 2023 21:03:30 +0200 Subject: [PATCH] output: handle WithName like zapr does Previously, all names set via `WithNames` were concatenated with / and added to the main message string as a `: ` prefix. Now klog in all of its incarnations (internal logger in klog, klogr, textlogger) behaves like zapr and adds a "logger" key with the names concatenated by a dot as value. The main advantage, besides consistency, is that code which does a full string match against some message string still works even when contextual logging is enabled and `WithName` is used, at least as long as that code doesn't also match all key/value pairs. --- klogr.go | 41 +++++++++++++++++++-------- klogr/klogr.go | 51 ++++++++++++++++++++++------------ klogr/klogr_test.go | 38 +++++++++++++------------ ktesting/testinglogger_test.go | 10 +++---- test/output.go | 18 ++++++------ test/zapr.go | 12 ++++---- textlogger/textlogger.go | 41 +++++++++++++++++++-------- 7 files changed, 133 insertions(+), 78 deletions(-) diff --git a/klogr.go b/klogr.go index 784f7de1..a3e5f977 100644 --- a/klogr.go +++ b/klogr.go @@ -22,6 +22,11 @@ import ( "k8s.io/klog/v2/internal/serialize" ) +const ( + // nameKey is used to log the `WithName` values as an additional attribute. + nameKey = "logger" +) + // NewKlogr returns a logger that is functionally identical to // klogr.NewWithOptions(klogr.FormatKlog), i.e. it passes through to klog. The // difference is that it uses a simpler implementation. @@ -33,8 +38,13 @@ func NewKlogr() Logger { // import cycle (klogr wants to use klog, and klog wants to use klogr). type klogger struct { callDepth int - prefix string - values []interface{} + + // hasPrefix is true if the first entry in values is the special + // nameKey key/value. Such an entry gets added and later updated in + // WithName. + hasPrefix bool + + values []interface{} } func (l *klogger) Init(info logr.RuntimeInfo) { @@ -43,9 +53,6 @@ func (l *klogger) Init(info logr.RuntimeInfo) { func (l *klogger) Info(level int, msg string, kvList ...interface{}) { merged := serialize.MergeKVs(l.values, kvList) - if l.prefix != "" { - msg = l.prefix + ": " + msg - } // Skip this function. VDepth(l.callDepth+1, Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } @@ -57,20 +64,30 @@ func (l *klogger) Enabled(level int) bool { func (l *klogger) Error(err error, msg string, kvList ...interface{}) { merged := serialize.MergeKVs(l.values, kvList) - if l.prefix != "" { - msg = l.prefix + ": " + msg - } ErrorSDepth(l.callDepth+1, err, msg, merged...) } // WithName returns a new logr.Logger with the specified name appended. klogr -// uses '/' characters to separate name elements. Callers should not pass '/' +// 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.LogSink { - if len(l.prefix) > 0 { - l.prefix = l.prefix + "/" + if l.hasPrefix { + // Copy slice and modify value. No length checks and type + // assertions are needed because hasPrefix is only true if the + // first two elements exist and are key/value strings. + v := make([]interface{}, 0, len(l.values)) + v = append(v, l.values...) + prefix, _ := v[1].(string) + v[1] = prefix + "." + name + l.values = v + } else { + // Preprend new key/value pair. + v := make([]interface{}, 0, 2+len(l.values)) + v = append(v, nameKey, name) + v = append(v, l.values...) + l.values = v + l.hasPrefix = true } - l.prefix += name return &l } diff --git a/klogr/klogr.go b/klogr/klogr.go index d80e44fd..73b0de25 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -15,6 +15,11 @@ import ( "k8s.io/klog/v2/internal/serialize" ) +const ( + // nameKey is used to log the `WithName` values as an additional attribute. + nameKey = "logger" +) + // Option is a functional option that reconfigures the logger created with New. type Option func(*klogger) @@ -23,7 +28,7 @@ type Format string const ( // FormatSerialize tells klogr to turn key/value pairs into text itself - // before invoking klog. + // before invoking klog. Key/value pairs are sorted by key. FormatSerialize Format = "Serialize" // FormatKlog tells klogr to pass all text messages and key/value pairs @@ -51,7 +56,6 @@ func New() logr.Logger { func NewWithOptions(options ...Option) logr.Logger { l := klogger{ level: 0, - prefix: "", values: nil, format: FormatKlog, } @@ -64,9 +68,14 @@ func NewWithOptions(options ...Option) logr.Logger { type klogger struct { level int callDepth int - prefix string - values []interface{} - format Format + + // hasPrefix is true if the first entry in values is the special + // nameKey key/value. Such an entry gets added and later updated in + // WithName. + hasPrefix bool + + values []interface{} + format Format } func (l *klogger) Init(info logr.RuntimeInfo) { @@ -127,12 +136,9 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { msgStr := flatten("msg", msg) merged := serialize.MergeKVs(l.values, kvList) kvStr := flatten(merged...) - klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr) + klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, msgStr, " ", kvStr) case FormatKlog: merged := serialize.MergeKVs(l.values, kvList) - if l.prefix != "" { - msg = l.prefix + ": " + msg - } klog.VDepth(l.callDepth+1, klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } } @@ -153,24 +159,35 @@ func (l *klogger) Error(err error, msg string, kvList ...interface{}) { errStr := flatten("error", loggableErr) merged := serialize.MergeKVs(l.values, kvList) kvStr := flatten(merged...) - klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", kvStr) + klog.ErrorDepth(l.callDepth+1, msgStr, " ", errStr, " ", kvStr) case FormatKlog: merged := serialize.MergeKVs(l.values, kvList) - if l.prefix != "" { - msg = l.prefix + ": " + msg - } klog.ErrorSDepth(l.callDepth+1, err, msg, merged...) } } // WithName returns a new logr.Logger with the specified name appended. klogr -// uses '/' characters to separate name elements. Callers should not pass '/' +// 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.LogSink { - if len(l.prefix) > 0 { - l.prefix = l.prefix + "/" + if l.hasPrefix { + // Copy slice and modify value. No length checks and type + // assertions are needed because hasPrefix is only true if the + // first two elements exist and are key/value strings. + v := make([]interface{}, 0, len(l.values)) + v = append(v, l.values...) + prefix, _ := v[1].(string) + prefix = prefix + "." + name + v[1] = prefix + l.values = v + } else { + // Preprend new key/value pair. + v := make([]interface{}, 0, 2+len(l.values)) + v = append(v, nameKey, name) + v = append(v, l.values...) + l.values = v + l.hasPrefix = true } - l.prefix += name return &l } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 0aeec030..57ebf7a2 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -42,7 +42,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: `"msg"="test" "akey"="avalue" `, expectedKlogOutput: `"test" akey="avalue" `, @@ -51,25 +51,29 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0).WithName("me"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `me "msg"="test" "akey"="avalue" + // Sorted by keys. + expectedOutput: `"msg"="test" "akey"="avalue" "logger"="me" `, - expectedKlogOutput: `"me: test" akey="avalue" + // Not sorted by keys. + expectedKlogOutput: `"test" logger="me" akey="avalue" `, }, "should log with multiple names and values passed to keysAndValues": { klogr: createLogger().V(0).WithName("hello").WithName("world"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `hello/world "msg"="test" "akey"="avalue" + // Sorted by keys. + expectedOutput: `"msg"="test" "akey"="avalue" "logger"="hello.world" `, - expectedKlogOutput: `"hello/world: test" akey="avalue" + // Not sorted by keys. + expectedKlogOutput: `"test" logger="hello.world" akey="avalue" `, }, "may print duplicate keys with the same value": { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: `"msg"="test" "akey"="avalue" `, expectedKlogOutput: `"test" akey="avalue" akey="avalue" `, @@ -78,7 +82,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: ` "msg"="test" "akey"="avalue2" + expectedOutput: `"msg"="test" "akey"="avalue2" `, expectedKlogOutput: `"test" akey="avalue" akey="avalue2" `, @@ -87,7 +91,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().WithValues("akey", "avalue"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: `"msg"="test" "akey"="avalue" `, expectedKlogOutput: `"test" akey="avalue" `, @@ -96,7 +100,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"), text: "test", keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"}, - expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9" + expectedOutput: `"msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9" `, expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" `, @@ -105,7 +109,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().WithValues("akey", "avalue"), text: "test", keysAndValues: []interface{}{"akey", "avalue2"}, - expectedOutput: ` "msg"="test" "akey"="avalue2" + expectedOutput: `"msg"="test" "akey"="avalue2" `, expectedKlogOutput: `"test" akey="avalue2" `, @@ -114,7 +118,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger(), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" + expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" `, expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)" `, @@ -124,7 +128,7 @@ func testOutput(t *testing.T, format string) { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, // klogr format sorts all key/value pairs. - expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)" + expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)" `, expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)" `, @@ -133,7 +137,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger(), text: "test", keysAndValues: []interface{}{"akey", "<&>"}, - expectedOutput: ` "msg"="test" "akey"="<&>" + expectedOutput: `"msg"="test" "akey"="<&>" `, expectedKlogOutput: `"test" akey="<&>" `, @@ -143,7 +147,7 @@ func testOutput(t *testing.T, format string) { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, // klogr format sorts all key/value pairs. - expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)" + expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)" `, expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" `, @@ -152,7 +156,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"err", errors.New("whoops")}, - expectedOutput: ` "msg"="test" "err"="whoops" + expectedOutput: `"msg"="test" "err"="whoops" `, expectedKlogOutput: `"test" err="whoops" `, @@ -161,7 +165,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}}, - expectedOutput: ` "msg"="test" "err"="WHOOPS" + expectedOutput: `"msg"="test" "err"="WHOOPS" `, expectedKlogOutput: `"test" err="whoops" `, @@ -170,7 +174,7 @@ func testOutput(t *testing.T, format string) { klogr: createLogger().V(0), text: "test", err: errors.New("whoops"), - expectedOutput: ` "msg"="test" "error"="whoops" + expectedOutput: `"msg"="test" "error"="whoops" `, expectedKlogOutput: `"test" err="whoops" `, diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 1ec709b5..01769261 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -216,7 +216,7 @@ func TestStop(t *testing.T) { // have the < > markers. // // Full output: - // testinglogger_test.go:194] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=< + // testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=< // goroutine 23 [running]: // k8s.io/klog/v2/internal/dbg.Stacks(0x0) // /nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a @@ -233,11 +233,11 @@ func TestStop(t *testing.T) { // > actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``) - expected := fmt.Sprintf(`testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=< + expected := fmt.Sprintf(`testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=< > -testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: simple info message" -testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: error message" -testinglogger_test.go:%d] "TestStop/Sub leaked goroutine/me: complex info message" completed=true anotherValue=1 +testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine" +testinglogger_test.go:%d] "error message" logger="TestStop/Sub leaked goroutine" +testinglogger_test.go:%d] "complex info message" logger="TestStop/Sub leaked goroutine.me" completed=true anotherValue=1 `, line+1, line+1, line+2, line+3) if actual != expected { diff --git a/test/output.go b/test/output.go index ce769dc5..da80b81a 100644 --- a/test/output.go +++ b/test/output.go @@ -165,14 +165,14 @@ var tests = map[string]testcase{ withNames: []string{"me"}, text: "test", values: []interface{}{"akey", "avalue"}, - expectedOutput: `I output.go:] "me: test" akey="avalue" + expectedOutput: `I output.go:] "test" logger="me" akey="avalue" `, }, "log with multiple names and values": { withNames: []string{"hello", "world"}, text: "test", values: []interface{}{"akey", "avalue"}, - expectedOutput: `I output.go:] "hello/world: test" akey="avalue" + expectedOutput: `I output.go:] "test" logger="hello.world" akey="avalue" `, }, "override single value": { @@ -486,7 +486,7 @@ func printWithKlog(test testcase) { } return false } - appendKV := func(withValues []interface{}) { + appendKV := func(withValues ...interface{}) { if len(withValues)%2 != 0 { withValues = append(withValues, "(MISSING)") } @@ -497,15 +497,18 @@ func printWithKlog(test testcase) { } } // Here we need to emulate the handling of WithValues above. - appendKV(test.withValues) + if len(test.withNames) > 0 { + appendKV("logger", strings.Join(test.withNames, ".")) + } + appendKV(test.withValues...) kvs := [][]interface{}{copySlice(kv)} if test.moreValues != nil { - appendKV(test.moreValues) + appendKV(test.moreValues...) kvs = append(kvs, copySlice(kv), copySlice(kvs[0])) } if test.evenMoreValues != nil { kv = copySlice(kvs[0]) - appendKV(test.evenMoreValues) + appendKV(test.evenMoreValues...) kvs = append(kvs, copySlice(kv)) } for _, kv := range kvs { @@ -513,9 +516,6 @@ func printWithKlog(test testcase) { kv = append(kv, test.values...) } text := test.text - if len(test.withNames) > 0 { - text = strings.Join(test.withNames, "/") + ": " + text - } if test.withHelper { klogHelper(klog.Level(test.v), text, kv) } else if test.err != nil { diff --git a/test/zapr.go b/test/zapr.go index dcd35755..96f175f4 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -36,7 +36,7 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue","akey":"avalue2"} `, - `I output.go:] "hello/world: test" akey="avalue" + `I output.go:] "test" logger="hello.world" akey="avalue" `: `{"logger":"hello.world","caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} `, @@ -92,7 +92,7 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} `, - `I output.go:] "me: test" akey="avalue" + `I output.go:] "test" logger="me" akey="avalue" `: `{"logger":"me","caller":"test/output.go:","msg":"test","v":0,"akey":"avalue"} `, @@ -281,12 +281,12 @@ func ZaprOutputMappingIndirect() map[string]string { mapping := ZaprOutputMappingDirect() for key, value := range map[string]string{ - `I output.go:] "hello/world: test" akey="avalue" -`: `{"caller":"test/output.go:","msg":"hello/world: test","v":0,"akey":"avalue"} + `I output.go:] "test" logger="hello.world" akey="avalue" +`: `{"caller":"test/output.go:","msg":"test","v":0,"logger":"hello.world","akey":"avalue"} `, - `I output.go:] "me: test" akey="avalue" -`: `{"caller":"test/output.go:","msg":"me: test","v":0,"akey":"avalue"} + `I output.go:] "test" logger="me" akey="avalue" +`: `{"caller":"test/output.go:","msg":"test","v":0,"logger":"me","akey":"avalue"} `, `I output.go:] "odd parameters" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 08235ab9..809b4553 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -38,13 +38,17 @@ var ( TimeNow = time.Now ) +const ( + // nameKey is used to log the `WithName` values as an additional attribute. + nameKey = "logger" +) + // NewLogger constructs a new logger. // // Verbosity can be modified at any time through the Config.V and // Config.VModule API. func NewLogger(c *Config) logr.Logger { return logr.New(&tlogger{ - prefix: "", values: nil, config: c, }) @@ -52,9 +56,14 @@ func NewLogger(c *Config) logr.Logger { type tlogger struct { callDepth int - prefix string - values []interface{} - config *Config + + // hasPrefix is true if the first entry in values is the special + // nameKey key/value. Such an entry gets added and later updated in + // WithName. + hasPrefix bool + + values []interface{} + config *Config } func (l *tlogger) Init(info logr.RuntimeInfo) { @@ -103,11 +112,6 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int now := TimeNow() b.FormatHeader(s, file, line, now) - // Inject WithName names into message. - if l.prefix != "" { - msg = l.prefix + ": " + msg - } - // The message is always quoted, even if it contains line breaks. // If developers want multi-line output, they should use a small, fixed // message and put the multi-line output into a value. @@ -131,10 +135,23 @@ func (l *tlogger) WriteKlogBuffer(data []byte) { // in the provided name string, but this library does not actually enforce that. func (l *tlogger) WithName(name string) logr.LogSink { clone := *l - if len(l.prefix) > 0 { - clone.prefix = l.prefix + "/" + if l.hasPrefix { + // Copy slice and modify value. No length checks and type + // assertions are needed because hasPrefix is only true if the + // first two elements exist and are key/value strings. + v := make([]interface{}, 0, len(l.values)) + v = append(v, l.values...) + prefix, _ := v[1].(string) + v[1] = prefix + "." + name + clone.values = v + } else { + // Preprend new key/value pair. + v := make([]interface{}, 0, 2+len(l.values)) + v = append(v, nameKey, name) + v = append(v, l.values...) + clone.values = v + clone.hasPrefix = true } - clone.prefix += name return &clone }