Skip to content

Commit 009a04a

Browse files
pohlypohly
committed
output: handle WithName like zapr does
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.
1 parent b588475 commit 009a04a

File tree

7 files changed

+133
-78
lines changed

7 files changed

+133
-78
lines changed

‎klogr.go

+29-12
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,11 @@ import (
2222
"k8s.io/klog/v2/internal/serialize"
2323
)
2424

25+
const (
26+
// nameKey is used to log the `WithName` values as an additional attribute.
27+
nameKey = "logger"
28+
)
29+
2530
// NewKlogr returns a logger that is functionally identical to
2631
// klogr.NewWithOptions(klogr.FormatKlog), i.e. it passes through to klog. The
2732
// difference is that it uses a simpler implementation.
@@ -33,8 +38,13 @@ func NewKlogr() Logger {
3338
// import cycle (klogr wants to use klog, and klog wants to use klogr).
3439
type klogger struct {
3540
callDepth int
36-
prefix string
37-
values []interface{}
41+
42+
// hasPrefix is true if the first entry in values is the special
43+
// nameKey key/value. Such an entry gets added and later updated in
44+
// WithName.
45+
hasPrefix bool
46+
47+
values []interface{}
3848
}
3949

4050
func (l *klogger) Init(info logr.RuntimeInfo) {
@@ -43,9 +53,6 @@ func (l *klogger) Init(info logr.RuntimeInfo) {
4353

4454
func (l *klogger) Info(level int, msg string, kvList ...interface{}) {
4555
merged := serialize.MergeKVs(l.values, kvList)
46-
if l.prefix != "" {
47-
msg = l.prefix + ": " + msg
48-
}
4956
// Skip this function.
5057
VDepth(l.callDepth+1, Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
5158
}
@@ -57,20 +64,30 @@ func (l *klogger) Enabled(level int) bool {
5764

5865
func (l *klogger) Error(err error, msg string, kvList ...interface{}) {
5966
merged := serialize.MergeKVs(l.values, kvList)
60-
if l.prefix != "" {
61-
msg = l.prefix + ": " + msg
62-
}
6367
ErrorSDepth(l.callDepth+1, err, msg, merged...)
6468
}
6569

6670
// WithName returns a new logr.Logger with the specified name appended. klogr
67-
// uses '/' characters to separate name elements. Callers should not pass '/'
71+
// uses '.' characters to separate name elements. Callers should not pass '.'
6872
// in the provided name string, but this library does not actually enforce that.
6973
func (l klogger) WithName(name string) logr.LogSink {
70-
if len(l.prefix) > 0 {
71-
l.prefix = l.prefix + "/"
74+
if l.hasPrefix {
75+
// Copy slice and modify value. No length checks and type
76+
// assertions are needed because hasPrefix is only true if the
77+
// first two elements exist and are key/value strings.
78+
v := make([]interface{}, 0, len(l.values))
79+
v = append(v, l.values...)
80+
prefix, _ := v[1].(string)
81+
v[1] = prefix + "." + name
82+
l.values = v
83+
} else {
84+
// Preprend new key/value pair.
85+
v := make([]interface{}, 0, 2+len(l.values))
86+
v = append(v, nameKey, name)
87+
v = append(v, l.values...)
88+
l.values = v
89+
l.hasPrefix = true
7290
}
73-
l.prefix += name
7491
return &l
7592
}
7693

‎klogr/klogr.go

+34-17
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,11 @@ import (
1515
"k8s.io/klog/v2/internal/serialize"
1616
)
1717

18+
const (
19+
// nameKey is used to log the `WithName` values as an additional attribute.
20+
nameKey = "logger"
21+
)
22+
1823
// Option is a functional option that reconfigures the logger created with New.
1924
type Option func(*klogger)
2025

@@ -23,7 +28,7 @@ type Format string
2328

2429
const (
2530
// FormatSerialize tells klogr to turn key/value pairs into text itself
26-
// before invoking klog.
31+
// before invoking klog. Key/value pairs are sorted by key.
2732
FormatSerialize Format = "Serialize"
2833

2934
// FormatKlog tells klogr to pass all text messages and key/value pairs
@@ -51,7 +56,6 @@ func New() logr.Logger {
5156
func NewWithOptions(options ...Option) logr.Logger {
5257
l := klogger{
5358
level: 0,
54-
prefix: "",
5559
values: nil,
5660
format: FormatKlog,
5761
}
@@ -64,9 +68,14 @@ func NewWithOptions(options ...Option) logr.Logger {
6468
type klogger struct {
6569
level int
6670
callDepth int
67-
prefix string
68-
values []interface{}
69-
format Format
71+
72+
// hasPrefix is true if the first entry in values is the special
73+
// nameKey key/value. Such an entry gets added and later updated in
74+
// WithName.
75+
hasPrefix bool
76+
77+
values []interface{}
78+
format Format
7079
}
7180

7281
func (l *klogger) Init(info logr.RuntimeInfo) {
@@ -127,12 +136,9 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) {
127136
msgStr := flatten("msg", msg)
128137
merged := serialize.MergeKVs(l.values, kvList)
129138
kvStr := flatten(merged...)
130-
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr)
139+
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, msgStr, " ", kvStr)
131140
case FormatKlog:
132141
merged := serialize.MergeKVs(l.values, kvList)
133-
if l.prefix != "" {
134-
msg = l.prefix + ": " + msg
135-
}
136142
klog.VDepth(l.callDepth+1, klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...)
137143
}
138144
}
@@ -153,24 +159,35 @@ func (l *klogger) Error(err error, msg string, kvList ...interface{}) {
153159
errStr := flatten("error", loggableErr)
154160
merged := serialize.MergeKVs(l.values, kvList)
155161
kvStr := flatten(merged...)
156-
klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", kvStr)
162+
klog.ErrorDepth(l.callDepth+1, msgStr, " ", errStr, " ", kvStr)
157163
case FormatKlog:
158164
merged := serialize.MergeKVs(l.values, kvList)
159-
if l.prefix != "" {
160-
msg = l.prefix + ": " + msg
161-
}
162165
klog.ErrorSDepth(l.callDepth+1, err, msg, merged...)
163166
}
164167
}
165168

166169
// WithName returns a new logr.Logger with the specified name appended. klogr
167-
// uses '/' characters to separate name elements. Callers should not pass '/'
170+
// uses '.' characters to separate name elements. Callers should not pass '.'
168171
// in the provided name string, but this library does not actually enforce that.
169172
func (l klogger) WithName(name string) logr.LogSink {
170-
if len(l.prefix) > 0 {
171-
l.prefix = l.prefix + "/"
173+
if l.hasPrefix {
174+
// Copy slice and modify value. No length checks and type
175+
// assertions are needed because hasPrefix is only true if the
176+
// first two elements exist and are key/value strings.
177+
v := make([]interface{}, 0, len(l.values))
178+
v = append(v, l.values...)
179+
prefix, _ := v[1].(string)
180+
prefix = prefix + "." + name
181+
v[1] = prefix
182+
l.values = v
183+
} else {
184+
// Preprend new key/value pair.
185+
v := make([]interface{}, 0, 2+len(l.values))
186+
v = append(v, nameKey, name)
187+
v = append(v, l.values...)
188+
l.values = v
189+
l.hasPrefix = true
172190
}
173-
l.prefix += name
174191
return &l
175192
}
176193

‎klogr/klogr_test.go

+21-17
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ func testOutput(t *testing.T, format string) {
4242
klogr: createLogger().V(0),
4343
text: "test",
4444
keysAndValues: []interface{}{"akey", "avalue"},
45-
expectedOutput: ` "msg"="test" "akey"="avalue"
45+
expectedOutput: `"msg"="test" "akey"="avalue"
4646
`,
4747
expectedKlogOutput: `"test" akey="avalue"
4848
`,
@@ -51,25 +51,29 @@ func testOutput(t *testing.T, format string) {
5151
klogr: createLogger().V(0).WithName("me"),
5252
text: "test",
5353
keysAndValues: []interface{}{"akey", "avalue"},
54-
expectedOutput: `me "msg"="test" "akey"="avalue"
54+
// Sorted by keys.
55+
expectedOutput: `"msg"="test" "akey"="avalue" "logger"="me"
5556
`,
56-
expectedKlogOutput: `"me: test" akey="avalue"
57+
// Not sorted by keys.
58+
expectedKlogOutput: `"test" logger="me" akey="avalue"
5759
`,
5860
},
5961
"should log with multiple names and values passed to keysAndValues": {
6062
klogr: createLogger().V(0).WithName("hello").WithName("world"),
6163
text: "test",
6264
keysAndValues: []interface{}{"akey", "avalue"},
63-
expectedOutput: `hello/world "msg"="test" "akey"="avalue"
65+
// Sorted by keys.
66+
expectedOutput: `"msg"="test" "akey"="avalue" "logger"="hello.world"
6467
`,
65-
expectedKlogOutput: `"hello/world: test" akey="avalue"
68+
// Not sorted by keys.
69+
expectedKlogOutput: `"test" logger="hello.world" akey="avalue"
6670
`,
6771
},
6872
"may print duplicate keys with the same value": {
6973
klogr: createLogger().V(0),
7074
text: "test",
7175
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
72-
expectedOutput: ` "msg"="test" "akey"="avalue"
76+
expectedOutput: `"msg"="test" "akey"="avalue"
7377
`,
7478
expectedKlogOutput: `"test" akey="avalue" akey="avalue"
7579
`,
@@ -78,7 +82,7 @@ func testOutput(t *testing.T, format string) {
7882
klogr: createLogger().V(0),
7983
text: "test",
8084
keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
81-
expectedOutput: ` "msg"="test" "akey"="avalue2"
85+
expectedOutput: `"msg"="test" "akey"="avalue2"
8286
`,
8387
expectedKlogOutput: `"test" akey="avalue" akey="avalue2"
8488
`,
@@ -87,7 +91,7 @@ func testOutput(t *testing.T, format string) {
8791
klogr: createLogger().WithValues("akey", "avalue"),
8892
text: "test",
8993
keysAndValues: []interface{}{"akey", "avalue"},
90-
expectedOutput: ` "msg"="test" "akey"="avalue"
94+
expectedOutput: `"msg"="test" "akey"="avalue"
9195
`,
9296
expectedKlogOutput: `"test" akey="avalue"
9397
`,
@@ -96,7 +100,7 @@ func testOutput(t *testing.T, format string) {
96100
klogr: createLogger().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"),
97101
text: "test",
98102
keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"},
99-
expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9"
103+
expectedOutput: `"msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9"
100104
`,
101105
expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4"
102106
`,
@@ -105,7 +109,7 @@ func testOutput(t *testing.T, format string) {
105109
klogr: createLogger().WithValues("akey", "avalue"),
106110
text: "test",
107111
keysAndValues: []interface{}{"akey", "avalue2"},
108-
expectedOutput: ` "msg"="test" "akey"="avalue2"
112+
expectedOutput: `"msg"="test" "akey"="avalue2"
109113
`,
110114
expectedKlogOutput: `"test" akey="avalue2"
111115
`,
@@ -114,7 +118,7 @@ func testOutput(t *testing.T, format string) {
114118
klogr: createLogger(),
115119
text: "test",
116120
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
117-
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)"
121+
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)"
118122
`,
119123
expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)"
120124
`,
@@ -124,7 +128,7 @@ func testOutput(t *testing.T, format string) {
124128
text: "test",
125129
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
126130
// klogr format sorts all key/value pairs.
127-
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)"
131+
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)"
128132
`,
129133
expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)"
130134
`,
@@ -133,7 +137,7 @@ func testOutput(t *testing.T, format string) {
133137
klogr: createLogger(),
134138
text: "test",
135139
keysAndValues: []interface{}{"akey", "<&>"},
136-
expectedOutput: ` "msg"="test" "akey"="<&>"
140+
expectedOutput: `"msg"="test" "akey"="<&>"
137141
`,
138142
expectedKlogOutput: `"test" akey="<&>"
139143
`,
@@ -143,7 +147,7 @@ func testOutput(t *testing.T, format string) {
143147
text: "test",
144148
keysAndValues: []interface{}{"akey", "avalue", "akey2"},
145149
// klogr format sorts all key/value pairs.
146-
expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)"
150+
expectedOutput: `"msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)"
147151
`,
148152
expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
149153
`,
@@ -152,7 +156,7 @@ func testOutput(t *testing.T, format string) {
152156
klogr: createLogger().V(0),
153157
text: "test",
154158
keysAndValues: []interface{}{"err", errors.New("whoops")},
155-
expectedOutput: ` "msg"="test" "err"="whoops"
159+
expectedOutput: `"msg"="test" "err"="whoops"
156160
`,
157161
expectedKlogOutput: `"test" err="whoops"
158162
`,
@@ -161,7 +165,7 @@ func testOutput(t *testing.T, format string) {
161165
klogr: createLogger().V(0),
162166
text: "test",
163167
keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}},
164-
expectedOutput: ` "msg"="test" "err"="WHOOPS"
168+
expectedOutput: `"msg"="test" "err"="WHOOPS"
165169
`,
166170
expectedKlogOutput: `"test" err="whoops"
167171
`,
@@ -170,7 +174,7 @@ func testOutput(t *testing.T, format string) {
170174
klogr: createLogger().V(0),
171175
text: "test",
172176
err: errors.New("whoops"),
173-
expectedOutput: ` "msg"="test" "error"="whoops"
177+
expectedOutput: `"msg"="test" "error"="whoops"
174178
`,
175179
expectedKlogOutput: `"test" err="whoops"
176180
`,

‎ktesting/testinglogger_test.go

+5-5
Original file line numberDiff line numberDiff line change
@@ -216,7 +216,7 @@ func TestStop(t *testing.T) {
216216
// have the < > markers.
217217
//
218218
// Full output:
219-
// testinglogger_test.go:194] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
219+
// testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
220220
// goroutine 23 [running]:
221221
// k8s.io/klog/v2/internal/dbg.Stacks(0x0)
222222
// /nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a
@@ -233,11 +233,11 @@ func TestStop(t *testing.T) {
233233
// >
234234
actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``)
235235

236-
expected := fmt.Sprintf(`testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
236+
expected := fmt.Sprintf(`testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
237237
>
238-
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: simple info message"
239-
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: error message"
240-
testinglogger_test.go:%d] "TestStop/Sub leaked goroutine/me: complex info message" completed=true anotherValue=1
238+
testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine"
239+
testinglogger_test.go:%d] "error message" logger="TestStop/Sub leaked goroutine"
240+
testinglogger_test.go:%d] "complex info message" logger="TestStop/Sub leaked goroutine.me" completed=true anotherValue=1
241241
`,
242242
line+1, line+1, line+2, line+3)
243243
if actual != expected {

0 commit comments

Comments
 (0)