Merge pull request #391 from pohly/with-name-output

output: handle WithName like zapr does

Author: k8s-ci-robot

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
 }
 

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
 }
 

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"
 `,

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 {