Skip to content

Commit 409909e

Browse files
pohlypohly
committed
formatting: replace Sprintf("%+v") with JSON
The output of Sprintf("%+v") is neither readable nor parseable. JSON encoding is better in both regards. There are some downsides: - Unexported fields don't get encoded anymore. However, the same happens with other backends (in particular, zapr), so one could also argue that making the text format behave like those others is good because developers notice early that they custom String and MarshalLog methods if they want to log such fields. - The result KObjs (a slice) now gets encoded as array of structs. KObjs already got deprecated a year ago. KObjSlice should be used instead.
1 parent 6bb2990 commit 409909e

File tree

7 files changed

+86
-58
lines changed

7 files changed

+86
-58
lines changed

‎internal/serialize/keyvalues.go

Lines changed: 27 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ package serialize
1818

1919
import (
2020
"bytes"
21+
"encoding/json"
2122
"fmt"
2223
"strconv"
2324

@@ -196,11 +197,11 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) {
196197
case textWriter:
197198
writeTextWriterValue(b, v)
198199
case fmt.Stringer:
199-
writeStringValue(b, true, StringerToString(v))
200+
writeStringValue(b, StringerToString(v))
200201
case string:
201-
writeStringValue(b, true, v)
202+
writeStringValue(b, v)
202203
case error:
203-
writeStringValue(b, true, ErrorToString(v))
204+
writeStringValue(b, ErrorToString(v))
204205
case logr.Marshaler:
205206
value := MarshalerToValue(v)
206207
// A marshaler that returns a string is useful for
@@ -215,9 +216,9 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) {
215216
// value directly.
216217
switch value := value.(type) {
217218
case string:
218-
writeStringValue(b, true, value)
219+
writeStringValue(b, value)
219220
default:
220-
writeStringValue(b, false, f.AnyToString(value))
221+
f.formatAny(b, value)
221222
}
222223
case []byte:
223224
// In https://github.com/kubernetes/klog/pull/237 it was decided
@@ -234,20 +235,32 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) {
234235
b.WriteByte('=')
235236
b.WriteString(fmt.Sprintf("%+q", v))
236237
default:
237-
writeStringValue(b, false, f.AnyToString(v))
238+
f.formatAny(b, v)
238239
}
239240
}
240241

241242
func KVFormat(b *bytes.Buffer, k, v interface{}) {
242243
Formatter{}.KVFormat(b, k, v)
243244
}
244245

245-
// AnyToString is the historic fallback formatter.
246-
func (f Formatter) AnyToString(v interface{}) string {
246+
// formatAny is the fallback formatter for a value. It supports a hook (for
247+
// example, for YAML encoding) and itself uses JSON encoding.
248+
func (f Formatter) formatAny(b *bytes.Buffer, v interface{}) {
249+
b.WriteRune('=')
247250
if f.AnyToStringHook != nil {
248-
return f.AnyToStringHook(v)
251+
b.WriteString(f.AnyToStringHook(v))
252+
return
253+
}
254+
encoder := json.NewEncoder(b)
255+
l := b.Len()
256+
if err := encoder.Encode(v); err != nil {
257+
// This shouldn't happen. We discard whatever the encoder
258+
// wrote and instead dump an error string.
259+
b.Truncate(l)
260+
b.WriteString(fmt.Sprintf("<internal error: %v>", err))
249261
}
250-
return fmt.Sprintf("%+v", v)
262+
// Remove trailing newline.
263+
b.Truncate(b.Len() - 1)
251264
}
252265

253266
// StringerToString converts a Stringer to a string,
@@ -287,7 +300,7 @@ func ErrorToString(err error) (ret string) {
287300
}
288301

289302
func writeTextWriterValue(b *bytes.Buffer, v textWriter) {
290-
b.WriteRune('=')
303+
b.WriteByte('=')
291304
defer func() {
292305
if err := recover(); err != nil {
293306
fmt.Fprintf(b, `"<panic: %s>"`, err)
@@ -296,18 +309,13 @@ func writeTextWriterValue(b *bytes.Buffer, v textWriter) {
296309
v.WriteText(b)
297310
}
298311

299-
func writeStringValue(b *bytes.Buffer, quote bool, v string) {
312+
func writeStringValue(b *bytes.Buffer, v string) {
300313
data := []byte(v)
301314
index := bytes.IndexByte(data, '\n')
302315
if index == -1 {
303316
b.WriteByte('=')
304-
if quote {
305-
// Simple string, quote quotation marks and non-printable characters.
306-
b.WriteString(strconv.Quote(v))
307-
return
308-
}
309-
// Non-string with no line breaks.
310-
b.WriteString(v)
317+
// Simple string, quote quotation marks and non-printable characters.
318+
b.WriteString(strconv.Quote(v))
311319
return
312320
}
313321

‎internal/serialize/keyvalues_test.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ func TestKvListFormat(t *testing.T) {
6969
}{
7070
{
7171
keysValues: []interface{}{"data", &dummyStruct{key: "test", value: "info"}},
72-
want: " data=map[key-data:test value-data:info]",
72+
want: ` data={"key-data":"test","value-data":"info"}`,
7373
},
7474
{
7575
keysValues: []interface{}{"data", &dummyStructWithStringMarshal{key: "test", value: "info"}},
@@ -89,15 +89,15 @@ func TestKvListFormat(t *testing.T) {
8989
Y string
9090
N time.Time
9191
}{X: 76, Y: "strval", N: time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.UTC)}},
92-
want: " pod=\"kubedns\" spec={X:76 Y:strval N:2006-01-02 15:04:05.06789 +0000 UTC}",
92+
want: ` pod="kubedns" spec={"X":76,"Y":"strval","N":"2006-01-02T15:04:05.06789Z"}`,
9393
},
9494
{
9595
keysValues: []interface{}{"pod", "kubedns", "values", []int{8, 6, 7, 5, 3, 0, 9}},
96-
want: " pod=\"kubedns\" values=[8 6 7 5 3 0 9]",
96+
want: " pod=\"kubedns\" values=[8,6,7,5,3,0,9]",
9797
},
9898
{
9999
keysValues: []interface{}{"pod", "kubedns", "values", []string{"deployment", "svc", "configmap"}},
100-
want: " pod=\"kubedns\" values=[deployment svc configmap]",
100+
want: ` pod="kubedns" values=["deployment","svc","configmap"]`,
101101
},
102102
{
103103
keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("test case for byte array")},
@@ -123,7 +123,7 @@ No whitespace.`,
123123
},
124124
{
125125
keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}},
126-
want: " pod=\"kubedns\" maps=map[three:4]",
126+
want: ` pod="kubedns" maps={"three":4}`,
127127
},
128128
{
129129
keysValues: []interface{}{"pod", klog.KRef("kube-system", "kubedns"), "status", "ready"},
@@ -163,7 +163,7 @@ No whitespace.`,
163163
Name: "mi-conf",
164164
},
165165
})},
166-
want: " pods=[kube-system/kube-dns mi-conf]",
166+
want: ` pods=[{"name":"kube-dns","namespace":"kube-system"},{"name":"mi-conf"}]`,
167167
},
168168
{
169169
keysValues: []interface{}{"point-1", point{100, 200}, "point-2", emptyPoint},

‎k8s_references.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -178,14 +178,14 @@ func (ks kobjSlice) process() (objs []interface{}, err string) {
178178
return objectRefs, ""
179179
}
180180

181-
var nilToken = []byte("<nil>")
181+
var nilToken = []byte("null")
182182

183183
func (ks kobjSlice) WriteText(out *bytes.Buffer) {
184184
s := reflect.ValueOf(ks.arg)
185185
switch s.Kind() {
186186
case reflect.Invalid:
187-
// nil parameter, print as empty slice.
188-
out.WriteString("[]")
187+
// nil parameter, print as null.
188+
out.Write(nilToken)
189189
return
190190
case reflect.Slice:
191191
// Okay, handle below.
@@ -197,15 +197,15 @@ func (ks kobjSlice) WriteText(out *bytes.Buffer) {
197197
defer out.Write([]byte{']'})
198198
for i := 0; i < s.Len(); i++ {
199199
if i > 0 {
200-
out.Write([]byte{' '})
200+
out.Write([]byte{','})
201201
}
202202
item := s.Index(i).Interface()
203203
if item == nil {
204204
out.Write(nilToken)
205205
} else if v, ok := item.(KMetadata); ok {
206-
KObj(v).writeUnquoted(out)
206+
KObj(v).WriteText(out)
207207
} else {
208-
fmt.Fprintf(out, "<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
208+
fmt.Fprintf(out, `"<KObjSlice needs a slice of values implementing KMetadata, got type %T>"`, item)
209209
return
210210
}
211211
}

‎klog_test.go

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1164,10 +1164,7 @@ second value line`},
11641164
},
11651165
{
11661166
msg: `message`,
1167-
format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "message" myData=<
1168-
{Data:This is some long text
1169-
with a line break.}
1170-
>
1167+
format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "message" myData={"Data":"This is some long text\nwith a line break."}
11711168
`,
11721169
keysValues: []interface{}{"myData", myData},
11731170
},

‎ktesting/example_test.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ func ExampleUnderlier() {
3535
),
3636
)
3737

38-
logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1})
38+
logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ Field int }{Field: 1})
3939
logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world")
4040
logger.WithValues("request", 42, "anotherValue", "fish").Info("hello world 2", "yetAnotherValue", "thanks")
4141
logger.WithName("example").Info("with name")
@@ -65,13 +65,13 @@ func ExampleUnderlier() {
6565
}
6666

6767
// Output:
68-
// ERROR I failed err="failure" what="something" data=### {field:1} ###
68+
// ERROR I failed err="failure" what="something" data=### {Field:1} ###
6969
// INFO hello world request=### 42 ### anotherValue="fish"
7070
// INFO hello world 2 request=### 42 ### anotherValue="fish" yetAnotherValue="thanks"
7171
// INFO example: with name
7272
// INFO higher verbosity
7373
//
74-
// log entry #0: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:ERROR Prefix: Message:I failed Verbosity:0 Err:failure WithKVList:[] ParameterKVList:[what something data {field:1}]}
74+
// log entry #0: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:ERROR Prefix: Message:I failed Verbosity:0 Err:failure WithKVList:[] ParameterKVList:[what something data {Field:1}]}
7575
// log entry #1: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world Verbosity:0 Err:<nil> WithKVList:[request 42 anotherValue fish] ParameterKVList:[]}
7676
// log entry #2: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world 2 Verbosity:0 Err:<nil> WithKVList:[request 42 anotherValue fish] ParameterKVList:[yetAnotherValue thanks]}
7777
// log entry #3: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix:example Message:with name Verbosity:0 Err:<nil> WithKVList:[] ParameterKVList:[]}
@@ -82,7 +82,7 @@ func ExampleNewLogger() {
8282
var buffer ktesting.BufferTL
8383
logger := ktesting.NewLogger(&buffer, ktesting.NewConfig())
8484

85-
logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1})
85+
logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ Field int }{Field: 1})
8686
logger.V(5).Info("Logged at level 5.")
8787
logger.V(6).Info("Not logged at level 6.")
8888

@@ -95,7 +95,7 @@ func ExampleNewLogger() {
9595

9696
// Output:
9797
// >> <<
98-
// E...] I failed err="failure" what="something" data={field:1}
98+
// E...] I failed err="failure" what="something" data={"Field":1}
9999
// I...] Logged at level 5.
100100
}
101101

‎test/output.go

Lines changed: 21 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -275,30 +275,30 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
275275
`,
276276
},
277277
"KObjs": {
278-
text: "test",
278+
text: "KObjs",
279279
values: []interface{}{"pods",
280280
klog.KObjs([]interface{}{
281281
&kmeta{Name: "pod-1", Namespace: "kube-system"},
282282
&kmeta{Name: "pod-2", Namespace: "kube-system"},
283283
})},
284-
expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
284+
expectedOutput: `I output.go:<LINE>] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]
285285
`,
286286
},
287287
"KObjSlice okay": {
288-
text: "test",
288+
text: "KObjSlice",
289289
values: []interface{}{"pods",
290290
klog.KObjSlice([]interface{}{
291291
&kmeta{Name: "pod-1", Namespace: "kube-system"},
292292
&kmeta{Name: "pod-2", Namespace: "kube-system"},
293293
})},
294-
expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
294+
expectedOutput: `I output.go:<LINE>] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"]
295295
`,
296296
},
297297
"KObjSlice nil arg": {
298298
text: "test",
299299
values: []interface{}{"pods",
300300
klog.KObjSlice(nil)},
301-
expectedOutput: `I output.go:<LINE>] "test" pods=[]
301+
expectedOutput: `I output.go:<LINE>] "test" pods=null
302302
`,
303303
},
304304
"KObjSlice int arg": {
@@ -315,14 +315,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
315315
&kmeta{Name: "pod-1", Namespace: "kube-system"},
316316
nil,
317317
})},
318-
expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
318+
expectedOutput: `I output.go:<LINE>] "test" pods=["kube-system/pod-1",null]
319319
`,
320320
},
321321
"KObjSlice ints": {
322322
text: "test",
323323
values: []interface{}{"ints",
324324
klog.KObjSlice([]int{1, 2, 3})},
325-
expectedOutput: `I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
325+
expectedOutput: `I output.go:<LINE>] "test" ints=["<KObjSlice needs a slice of values implementing KMetadata, got type int>"]
326326
`,
327327
},
328328
"regular error types as value": {
@@ -409,19 +409,30 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
409409
"map values": {
410410
text: "maps",
411411
values: []interface{}{"s", map[string]string{"hello": "world"}, "i", map[int]int{1: 2, 3: 4}},
412-
expectedOutput: `I output.go:<LINE>] "maps" s=map[hello:world] i=map[1:2 3:4]
412+
expectedOutput: `I output.go:<LINE>] "maps" s={"hello":"world"} i={"1":2,"3":4}
413413
`,
414414
},
415415
"slice values": {
416416
text: "slices",
417417
values: []interface{}{"s", []string{"hello", "world"}, "i", []int{1, 2, 3}},
418-
expectedOutput: `I output.go:<LINE>] "slices" s=[hello world] i=[1 2 3]
418+
expectedOutput: `I output.go:<LINE>] "slices" s=["hello","world"] i=[1,2,3]
419419
`,
420420
},
421421
"struct values": {
422422
text: "structs",
423423
values: []interface{}{"s", struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"}},
424-
expectedOutput: `I output.go:<LINE>] "structs" s={Name:worker Kind:pod hidden:ignore}
424+
expectedOutput: `I output.go:<LINE>] "structs" s={"Name":"worker","Kind":"pod"}
425+
`,
426+
},
427+
"klog.Format": {
428+
text: "klog.Format",
429+
values: []interface{}{"s", klog.Format(struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"})},
430+
expectedOutput: `I output.go:<LINE>] "klog.Format" s=<
431+
{
432+
"Name": "worker",
433+
"Kind": "pod"
434+
}
435+
>
425436
`,
426437
},
427438
}

‎test/zapr.go

Lines changed: 20 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -69,23 +69,27 @@ func ZaprOutputMappingDirect() map[string]string {
6969
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}}
7070
`,
7171

72-
`I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
73-
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
72+
`I output.go:<LINE>] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]
73+
`: `{"caller":"test/output.go:<LINE>","msg":"KObjs","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
7474
`,
7575

76-
`I output.go:<LINE>] "test" pods=[]
76+
`I output.go:<LINE>] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"]
77+
`: `{"caller":"test/output.go:<LINE>","msg":"KObjSlice","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
78+
`,
79+
80+
`I output.go:<LINE>] "test" pods=null
7781
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":null}
7882
`,
7983

8084
`I output.go:<LINE>] "test" pods="<KObjSlice needs a slice, got type int>"
8185
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":"<KObjSlice needs a slice, got type int>"}
8286
`,
8387

84-
`I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
88+
`I output.go:<LINE>] "test" ints=["<KObjSlice needs a slice of values implementing KMetadata, got type int>"]
8589
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"ints":"<KObjSlice needs a slice of values implementing KMetadata, got type int>"}
8690
`,
8791

88-
`I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
92+
`I output.go:<LINE>] "test" pods=["kube-system/pod-1",null]
8993
`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]}
9094
`,
9195

@@ -238,15 +242,23 @@ I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
238242
>
239243
`: `{"caller":"test/output.go:<LINE>","msg":"Format","v":0,"config":{"Kind":"config","RealField":42}}
240244
`,
241-
`I output.go:<LINE>] "maps" s=map[hello:world] i=map[1:2 3:4]
245+
`I output.go:<LINE>] "maps" s={"hello":"world"} i={"1":2,"3":4}
242246
`: `{"caller":"test/output.go:<LINE>","msg":"maps","v":0,"s":{"hello":"world"},"i":{"1":2,"3":4}}
243247
`,
244248

245-
`I output.go:<LINE>] "slices" s=[hello world] i=[1 2 3]
249+
`I output.go:<LINE>] "slices" s=["hello","world"] i=[1,2,3]
246250
`: `{"caller":"test/output.go:<LINE>","msg":"slices","v":0,"s":["hello","world"],"i":[1,2,3]}
247251
`,
248-
`I output.go:<LINE>] "structs" s={Name:worker Kind:pod hidden:ignore}
252+
`I output.go:<LINE>] "structs" s={"Name":"worker","Kind":"pod"}
249253
`: `{"caller":"test/output.go:<LINE>","msg":"structs","v":0,"s":{"Name":"worker","Kind":"pod"}}
254+
`,
255+
`I output.go:<LINE>] "klog.Format" s=<
256+
{
257+
"Name": "worker",
258+
"Kind": "pod"
259+
}
260+
>
261+
`: `{"caller":"test/output.go:<LINE>","msg":"klog.Format","v":0,"s":{"Name":"worker","Kind":"pod"}}
250262
`,
251263
}
252264
}

0 commit comments

Comments
 (0)