Skip to content

Commit

Permalink
output: handle WithName like zapr does
Browse files Browse the repository at this point in the history 
Previously, all names set via `WithNames` were concatenated with / and added to
the main message string as a `<names>: <msg>` 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.
  • Loading branch information
@pohly
pohly committed Oct 26, 2023
1 parent b588475 commit 009a04a
Show file tree
Hide file tree
Showing 7 changed files with 133 additions and 78 deletions.
41 changes: 29 additions & 12 deletions klogr.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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) {
Expand All @@ -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...)
}
Expand All @@ -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
}

Expand Down
51 changes: 34 additions & 17 deletions klogr/klogr.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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
Expand Down Expand Up @@ -51,7 +56,6 @@ func New() logr.Logger {
func NewWithOptions(options ...Option) logr.Logger {
l := klogger{
level: 0,
prefix: "",
values: nil,
format: FormatKlog,
}
Expand All @@ -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) {
Expand Down Expand Up @@ -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...)
}
}
Expand All @@ -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
}

Expand Down
38 changes: 21 additions & 17 deletions klogr/klogr_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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)"
`,
Expand All @@ -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)"
`,
Expand All @@ -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="<&>"
`,
Expand All @@ -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)"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand All @@ -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"
`,
Expand Down
10 changes: 5 additions & 5 deletions ktesting/testinglogger_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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 {
Expand Down
Loading

0 comments on commit 009a04a

Please sign in to comment.