From 6bb29905d7950cfec2998b4885589ec72d13eaf4 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 26 Apr 2023 09:15:26 +0200 Subject: [PATCH 1/2] test: add more test cases for map, slice, struct Those are types for which the Sprintf("%+v") catchall code is used. --- test/output.go | 18 ++++++++++++++++++ test/zapr.go | 10 ++++++++++ 2 files changed, 28 insertions(+) diff --git a/test/output.go b/test/output.go index dff4d421..7cd536fc 100644 --- a/test/output.go +++ b/test/output.go @@ -404,6 +404,24 @@ I output.go:] "test" firstKey=1 secondKey=3 text: "map keys", values: []interface{}{map[string]bool{"test": true}, "test"}, expectedOutput: `I output.go:] "map keys" map[test:%!s(bool=true)]="test" +`, + }, + "map values": { + text: "maps", + values: []interface{}{"s", map[string]string{"hello": "world"}, "i", map[int]int{1: 2, 3: 4}}, + expectedOutput: `I output.go:] "maps" s=map[hello:world] i=map[1:2 3:4] +`, + }, + "slice values": { + text: "slices", + values: []interface{}{"s", []string{"hello", "world"}, "i", []int{1, 2, 3}}, + expectedOutput: `I output.go:] "slices" s=[hello world] i=[1 2 3] +`, + }, + "struct values": { + text: "structs", + values: []interface{}{"s", struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"}}, + expectedOutput: `I output.go:] "structs" s={Name:worker Kind:pod hidden:ignore} `, }, } diff --git a/test/zapr.go b/test/zapr.go index c9d47fcc..7d889943 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -237,6 +237,16 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" } > `: `{"caller":"test/output.go:","msg":"Format","v":0,"config":{"Kind":"config","RealField":42}} +`, + `I output.go:] "maps" s=map[hello:world] i=map[1:2 3:4] +`: `{"caller":"test/output.go:","msg":"maps","v":0,"s":{"hello":"world"},"i":{"1":2,"3":4}} +`, + + `I output.go:] "slices" s=[hello world] i=[1 2 3] +`: `{"caller":"test/output.go:","msg":"slices","v":0,"s":["hello","world"],"i":[1,2,3]} +`, + `I output.go:] "structs" s={Name:worker Kind:pod hidden:ignore} +`: `{"caller":"test/output.go:","msg":"structs","v":0,"s":{"Name":"worker","Kind":"pod"}} `, } } From d731661702a8af746c0ac12e04df075d11e67b42 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 26 Apr 2023 09:50:36 +0200 Subject: [PATCH 2/2] 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. --- internal/serialize/keyvalues.go | 47 +++++++++++++++----------- internal/serialize/keyvalues_test.go | 12 +++---- k8s_references.go | 12 +++---- klog_test.go | 5 +-- ktesting/example_test.go | 10 +++--- test/output.go | 50 ++++++++++++++++++++++------ test/zapr.go | 32 +++++++++++++----- 7 files changed, 110 insertions(+), 58 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index 1dc81a15..bcdf5f8e 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -18,6 +18,7 @@ package serialize import ( "bytes" + "encoding/json" "fmt" "strconv" @@ -196,11 +197,11 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { case textWriter: writeTextWriterValue(b, v) case fmt.Stringer: - writeStringValue(b, true, StringerToString(v)) + writeStringValue(b, StringerToString(v)) case string: - writeStringValue(b, true, v) + writeStringValue(b, v) case error: - writeStringValue(b, true, ErrorToString(v)) + writeStringValue(b, ErrorToString(v)) case logr.Marshaler: value := MarshalerToValue(v) // A marshaler that returns a string is useful for @@ -215,9 +216,9 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { // value directly. switch value := value.(type) { case string: - writeStringValue(b, true, value) + writeStringValue(b, value) default: - writeStringValue(b, false, f.AnyToString(value)) + f.formatAny(b, value) } case []byte: // In https://github.com/kubernetes/klog/pull/237 it was decided @@ -234,7 +235,7 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { b.WriteByte('=') b.WriteString(fmt.Sprintf("%+q", v)) default: - writeStringValue(b, false, f.AnyToString(v)) + f.formatAny(b, v) } } @@ -242,12 +243,25 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { Formatter{}.KVFormat(b, k, v) } -// AnyToString is the historic fallback formatter. -func (f Formatter) AnyToString(v interface{}) string { +// formatAny is the fallback formatter for a value. It supports a hook (for +// example, for YAML encoding) and itself uses JSON encoding. +func (f Formatter) formatAny(b *bytes.Buffer, v interface{}) { + b.WriteRune('=') if f.AnyToStringHook != nil { - return f.AnyToStringHook(v) + b.WriteString(f.AnyToStringHook(v)) + return + } + encoder := json.NewEncoder(b) + l := b.Len() + if err := encoder.Encode(v); err != nil { + // This shouldn't happen. We discard whatever the encoder + // wrote and instead dump an error string. + b.Truncate(l) + b.WriteString(fmt.Sprintf(`""`, err)) + return } - return fmt.Sprintf("%+v", v) + // Remove trailing newline. + b.Truncate(b.Len() - 1) } // StringerToString converts a Stringer to a string, @@ -287,7 +301,7 @@ func ErrorToString(err error) (ret string) { } func writeTextWriterValue(b *bytes.Buffer, v textWriter) { - b.WriteRune('=') + b.WriteByte('=') defer func() { if err := recover(); err != nil { fmt.Fprintf(b, `""`, err) @@ -296,18 +310,13 @@ func writeTextWriterValue(b *bytes.Buffer, v textWriter) { v.WriteText(b) } -func writeStringValue(b *bytes.Buffer, quote bool, v string) { +func writeStringValue(b *bytes.Buffer, v string) { data := []byte(v) index := bytes.IndexByte(data, '\n') if index == -1 { b.WriteByte('=') - if quote { - // Simple string, quote quotation marks and non-printable characters. - b.WriteString(strconv.Quote(v)) - return - } - // Non-string with no line breaks. - b.WriteString(v) + // Simple string, quote quotation marks and non-printable characters. + b.WriteString(strconv.Quote(v)) return } diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index 1bf4842b..b9e066c6 100644 --- a/internal/serialize/keyvalues_test.go +++ b/internal/serialize/keyvalues_test.go @@ -69,7 +69,7 @@ func TestKvListFormat(t *testing.T) { }{ { keysValues: []interface{}{"data", &dummyStruct{key: "test", value: "info"}}, - want: " data=map[key-data:test value-data:info]", + want: ` data={"key-data":"test","value-data":"info"}`, }, { keysValues: []interface{}{"data", &dummyStructWithStringMarshal{key: "test", value: "info"}}, @@ -89,15 +89,15 @@ func TestKvListFormat(t *testing.T) { Y string N time.Time }{X: 76, Y: "strval", N: time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.UTC)}}, - want: " pod=\"kubedns\" spec={X:76 Y:strval N:2006-01-02 15:04:05.06789 +0000 UTC}", + want: ` pod="kubedns" spec={"X":76,"Y":"strval","N":"2006-01-02T15:04:05.06789Z"}`, }, { keysValues: []interface{}{"pod", "kubedns", "values", []int{8, 6, 7, 5, 3, 0, 9}}, - want: " pod=\"kubedns\" values=[8 6 7 5 3 0 9]", + want: " pod=\"kubedns\" values=[8,6,7,5,3,0,9]", }, { keysValues: []interface{}{"pod", "kubedns", "values", []string{"deployment", "svc", "configmap"}}, - want: " pod=\"kubedns\" values=[deployment svc configmap]", + want: ` pod="kubedns" values=["deployment","svc","configmap"]`, }, { keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("test case for byte array")}, @@ -123,7 +123,7 @@ No whitespace.`, }, { keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}}, - want: " pod=\"kubedns\" maps=map[three:4]", + want: ` pod="kubedns" maps={"three":4}`, }, { keysValues: []interface{}{"pod", klog.KRef("kube-system", "kubedns"), "status", "ready"}, @@ -163,7 +163,7 @@ No whitespace.`, Name: "mi-conf", }, })}, - want: " pods=[kube-system/kube-dns mi-conf]", + want: ` pods=[{"name":"kube-dns","namespace":"kube-system"},{"name":"mi-conf"}]`, }, { keysValues: []interface{}{"point-1", point{100, 200}, "point-2", emptyPoint}, diff --git a/k8s_references.go b/k8s_references.go index ecd3f8b6..786af74b 100644 --- a/k8s_references.go +++ b/k8s_references.go @@ -178,14 +178,14 @@ func (ks kobjSlice) process() (objs []interface{}, err string) { return objectRefs, "" } -var nilToken = []byte("") +var nilToken = []byte("null") func (ks kobjSlice) WriteText(out *bytes.Buffer) { s := reflect.ValueOf(ks.arg) switch s.Kind() { case reflect.Invalid: - // nil parameter, print as empty slice. - out.WriteString("[]") + // nil parameter, print as null. + out.Write(nilToken) return case reflect.Slice: // Okay, handle below. @@ -197,15 +197,15 @@ func (ks kobjSlice) WriteText(out *bytes.Buffer) { defer out.Write([]byte{']'}) for i := 0; i < s.Len(); i++ { if i > 0 { - out.Write([]byte{' '}) + out.Write([]byte{','}) } item := s.Index(i).Interface() if item == nil { out.Write(nilToken) } else if v, ok := item.(KMetadata); ok { - KObj(v).writeUnquoted(out) + KObj(v).WriteText(out) } else { - fmt.Fprintf(out, "", item) + fmt.Fprintf(out, `""`, item) return } } diff --git a/klog_test.go b/klog_test.go index 58eeb267..76303e06 100644 --- a/klog_test.go +++ b/klog_test.go @@ -1164,10 +1164,7 @@ second value line`}, }, { msg: `message`, - format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "message" myData=< - {Data:This is some long text - with a line break.} - > + format: `I0102 15:04:05.067890 1234 klog_test.go:%d] "message" myData={"Data":"This is some long text\nwith a line break."} `, keysValues: []interface{}{"myData", myData}, }, diff --git a/ktesting/example_test.go b/ktesting/example_test.go index 9d887932..34844ef6 100644 --- a/ktesting/example_test.go +++ b/ktesting/example_test.go @@ -35,7 +35,7 @@ func ExampleUnderlier() { ), ) - logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1}) + logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ Field int }{Field: 1}) logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world") logger.WithValues("request", 42, "anotherValue", "fish").Info("hello world 2", "yetAnotherValue", "thanks") logger.WithName("example").Info("with name") @@ -65,13 +65,13 @@ func ExampleUnderlier() { } // Output: - // ERROR I failed err="failure" what="something" data=### {field:1} ### + // ERROR I failed err="failure" what="something" data=### {Field:1} ### // INFO hello world request=### 42 ### anotherValue="fish" // INFO hello world 2 request=### 42 ### anotherValue="fish" yetAnotherValue="thanks" // INFO example: with name // INFO higher verbosity // - // 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}]} + // 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}]} // log entry #1: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world Verbosity:0 Err: WithKVList:[request 42 anotherValue fish] ParameterKVList:[]} // log entry #2: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:hello world 2 Verbosity:0 Err: WithKVList:[request 42 anotherValue fish] ParameterKVList:[yetAnotherValue thanks]} // log entry #3: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix:example Message:with name Verbosity:0 Err: WithKVList:[] ParameterKVList:[]} @@ -82,7 +82,7 @@ func ExampleNewLogger() { var buffer ktesting.BufferTL logger := ktesting.NewLogger(&buffer, ktesting.NewConfig()) - logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ field int }{field: 1}) + logger.Error(errors.New("failure"), "I failed", "what", "something", "data", struct{ Field int }{Field: 1}) logger.V(5).Info("Logged at level 5.") logger.V(6).Info("Not logged at level 6.") @@ -95,7 +95,7 @@ func ExampleNewLogger() { // Output: // >> << - // E...] I failed err="failure" what="something" data={field:1} + // E...] I failed err="failure" what="something" data={"Field":1} // I...] Logged at level 5. } diff --git a/test/output.go b/test/output.go index 7cd536fc..e3bc181b 100644 --- a/test/output.go +++ b/test/output.go @@ -275,30 +275,30 @@ I output.go:] "test" firstKey=1 secondKey=3 `, }, "KObjs": { - text: "test", + text: "KObjs", values: []interface{}{"pods", klog.KObjs([]interface{}{ &kmeta{Name: "pod-1", Namespace: "kube-system"}, &kmeta{Name: "pod-2", Namespace: "kube-system"}, })}, - expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] + expectedOutput: `I output.go:] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}] `, }, "KObjSlice okay": { - text: "test", + text: "KObjSlice", values: []interface{}{"pods", klog.KObjSlice([]interface{}{ &kmeta{Name: "pod-1", Namespace: "kube-system"}, &kmeta{Name: "pod-2", Namespace: "kube-system"}, })}, - expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] + expectedOutput: `I output.go:] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"] `, }, "KObjSlice nil arg": { text: "test", values: []interface{}{"pods", klog.KObjSlice(nil)}, - expectedOutput: `I output.go:] "test" pods=[] + expectedOutput: `I output.go:] "test" pods=null `, }, "KObjSlice int arg": { @@ -315,14 +315,14 @@ I output.go:] "test" firstKey=1 secondKey=3 &kmeta{Name: "pod-1", Namespace: "kube-system"}, nil, })}, - expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 ] + expectedOutput: `I output.go:] "test" pods=["kube-system/pod-1",null] `, }, "KObjSlice ints": { text: "test", values: []interface{}{"ints", klog.KObjSlice([]int{1, 2, 3})}, - expectedOutput: `I output.go:] "test" ints=[] + expectedOutput: `I output.go:] "test" ints=[""] `, }, "regular error types as value": { @@ -409,19 +409,36 @@ I output.go:] "test" firstKey=1 secondKey=3 "map values": { text: "maps", values: []interface{}{"s", map[string]string{"hello": "world"}, "i", map[int]int{1: 2, 3: 4}}, - expectedOutput: `I output.go:] "maps" s=map[hello:world] i=map[1:2 3:4] + expectedOutput: `I output.go:] "maps" s={"hello":"world"} i={"1":2,"3":4} `, }, "slice values": { text: "slices", values: []interface{}{"s", []string{"hello", "world"}, "i", []int{1, 2, 3}}, - expectedOutput: `I output.go:] "slices" s=[hello world] i=[1 2 3] + expectedOutput: `I output.go:] "slices" s=["hello","world"] i=[1,2,3] `, }, "struct values": { text: "structs", values: []interface{}{"s", struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"}}, - expectedOutput: `I output.go:] "structs" s={Name:worker Kind:pod hidden:ignore} + expectedOutput: `I output.go:] "structs" s={"Name":"worker","Kind":"pod"} +`, + }, + "klog.Format": { + text: "klog.Format", + values: []interface{}{"s", klog.Format(struct{ Name, Kind, hidden string }{Name: "worker", Kind: "pod", hidden: "ignore"})}, + expectedOutput: `I output.go:] "klog.Format" s=< + { + "Name": "worker", + "Kind": "pod" + } + > +`, + }, + "cyclic list": { + text: "cycle", + values: []interface{}{"list", newCyclicList()}, + expectedOutput: `I output.go:] "cycle" list="" `, }, } @@ -1019,3 +1036,16 @@ type myConfig struct { var _ logr.Marshaler = myConfig{} var _ fmt.Stringer = myConfig{} + +// This is a linked list. It can contain a cycle, which cannot be expressed in JSON. +type myList struct { + Value int + Next *myList +} + +func newCyclicList() *myList { + a := &myList{Value: 1} + b := &myList{Value: 2, Next: a} + a.Next = b + return a +} diff --git a/test/zapr.go b/test/zapr.go index 7d889943..7b159442 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -69,11 +69,15 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}} `, - `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] -`: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} + `I output.go:] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}] +`: `{"caller":"test/output.go:","msg":"KObjs","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} `, - `I output.go:] "test" pods=[] + `I output.go:] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"] +`: `{"caller":"test/output.go:","msg":"KObjSlice","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]} +`, + + `I output.go:] "test" pods=null `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":null} `, @@ -81,11 +85,11 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":""} `, - `I output.go:] "test" ints=[] + `I output.go:] "test" ints=[""] `: `{"caller":"test/output.go:","msg":"test","v":0,"ints":""} `, - `I output.go:] "test" pods=[kube-system/pod-1 ] + `I output.go:] "test" pods=["kube-system/pod-1",null] `: `{"caller":"test/output.go:","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]} `, @@ -238,15 +242,27 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" > `: `{"caller":"test/output.go:","msg":"Format","v":0,"config":{"Kind":"config","RealField":42}} `, - `I output.go:] "maps" s=map[hello:world] i=map[1:2 3:4] + `I output.go:] "maps" s={"hello":"world"} i={"1":2,"3":4} `: `{"caller":"test/output.go:","msg":"maps","v":0,"s":{"hello":"world"},"i":{"1":2,"3":4}} `, - `I output.go:] "slices" s=[hello world] i=[1 2 3] + `I output.go:] "slices" s=["hello","world"] i=[1,2,3] `: `{"caller":"test/output.go:","msg":"slices","v":0,"s":["hello","world"],"i":[1,2,3]} `, - `I output.go:] "structs" s={Name:worker Kind:pod hidden:ignore} + `I output.go:] "structs" s={"Name":"worker","Kind":"pod"} `: `{"caller":"test/output.go:","msg":"structs","v":0,"s":{"Name":"worker","Kind":"pod"}} +`, + `I output.go:] "klog.Format" s=< + { + "Name": "worker", + "Kind": "pod" + } + > +`: `{"caller":"test/output.go:","msg":"klog.Format","v":0,"s":{"Name":"worker","Kind":"pod"}} +`, + + `I output.go:] "cycle" list="" +`: `{"caller":"test/output.go:","msg":"cycle","v":0,"listError":"json: unsupported value: encountered a cycle via *test.myList"} `, } }