Repository: kubernetes/klog
Pull request #375 (2023-04-26 13:56:25)

JSON as fallback encoding
**What this PR does / why we need it**:

The output of `Sprintf("%+v")` is neither readable nor parseable. JSON encoding
is better in both regards.

Because JSON follows pointers instead of printing their value, output becomes more useful, too.
 
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 need 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.

**Which issue(s) this PR fixes**:

Fixes #https://github.com/kubernetes/klog/issues/352

**Special notes for your reviewer**:

The first commit introduces some new output unit tests, the second has the actual change.

**Release note**:
```release-note
Structured logging now uses JSON encoding for structs, slices and maps. For pointers embedded in those, the thing they point to gets printed, not the pointer values. Unexported fields in structs no longer get included in the output. Implement `String` and `MarshalLog` for structs if such fields are important.
```


Patch:
diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go
index 1dc81a1..bcdf5f8 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(`"<internal error: %v>"`, 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, `"<panic: %s>"`, 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/k8s_references.go b/k8s_references.go
index ecd3f8b..786af74 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("<nil>")
+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, "<KObjSlice needs a slice of values implementing KMetadata, got type %T>", item)
+			fmt.Fprintf(out, `"<KObjSlice needs a slice of values implementing KMetadata, got type %T>"`, item)
 			return
 		}
 	}


Test patch:
diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go
index 1bf4842..b9e066c 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/klog_test.go b/klog_test.go
index 58eeb26..76303e0 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 9d88793..34844ef 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:<nil> 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:<nil> 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:<nil> 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 dff4d42..e3bc181 100644
--- a/test/output.go
+++ b/test/output.go
@@ -275,30 +275,30 @@ I output.go:<LINE>] "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:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
+		expectedOutput: `I output.go:<LINE>] "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:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
+		expectedOutput: `I output.go:<LINE>] "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:<LINE>] "test" pods=[]
+		expectedOutput: `I output.go:<LINE>] "test" pods=null
 `,
 	},
 	"KObjSlice int arg": {
@@ -315,14 +315,14 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 				&kmeta{Name: "pod-1", Namespace: "kube-system"},
 				nil,
 			})},
-		expectedOutput: `I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
+		expectedOutput: `I output.go:<LINE>] "test" pods=["kube-system/pod-1",null]
 `,
 	},
 	"KObjSlice ints": {
 		text: "test",
 		values: []interface{}{"ints",
 			klog.KObjSlice([]int{1, 2, 3})},
-		expectedOutput: `I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
+		expectedOutput: `I output.go:<LINE>] "test" ints=["<KObjSlice needs a slice of values implementing KMetadata, got type int>"]
 `,
 	},
 	"regular error types as value": {
@@ -404,6 +404,41 @@ I output.go:<LINE>] "test" firstKey=1 secondKey=3
 		text:       "map keys",
 		values:     []interface{}{map[string]bool{"test": true}, "test"},
 		expectedOutput: `I output.go:<LINE>] "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:<LINE>] "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:<LINE>] "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:<LINE>] "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:<LINE>] "klog.Format" s=<
+	{
+	  "Name": "worker",
+	  "Kind": "pod"
+	}
+ >
+`,
+	},
+	"cyclic list": {
+		text:   "cycle",
+		values: []interface{}{"list", newCyclicList()},
+		expectedOutput: `I output.go:<LINE>] "cycle" list="<internal error: json: unsupported value: encountered a cycle via *test.myList>"
 `,
 	},
 }
@@ -1001,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 c9d47fc..7b15944 100644
--- a/test/zapr.go
+++ b/test/zapr.go
@@ -69,11 +69,15 @@ func ZaprOutputMappingDirect() map[string]string {
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}}
 `,
 
-		`I output.go:<LINE>] "test" pods=[kube-system/pod-1 kube-system/pod-2]
-`: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
+		`I output.go:<LINE>] "KObjs" pods=[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]
+`: `{"caller":"test/output.go:<LINE>","msg":"KObjs","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
 `,
 
-		`I output.go:<LINE>] "test" pods=[]
+		`I output.go:<LINE>] "KObjSlice" pods=["kube-system/pod-1","kube-system/pod-2"]
+`: `{"caller":"test/output.go:<LINE>","msg":"KObjSlice","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}
+`,
+
+		`I output.go:<LINE>] "test" pods=null
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":null}
 `,
 
@@ -81,11 +85,11 @@ func ZaprOutputMappingDirect() map[string]string {
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":"<KObjSlice needs a slice, got type int>"}
 `,
 
-		`I output.go:<LINE>] "test" ints=[<KObjSlice needs a slice of values implementing KMetadata, got type int>]
+		`I output.go:<LINE>] "test" ints=["<KObjSlice needs a slice of values implementing KMetadata, got type int>"]
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"ints":"<KObjSlice needs a slice of values implementing KMetadata, got type int>"}
 `,
 
-		`I output.go:<LINE>] "test" pods=[kube-system/pod-1 <nil>]
+		`I output.go:<LINE>] "test" pods=["kube-system/pod-1",null]
 `: `{"caller":"test/output.go:<LINE>","msg":"test","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},null]}
 `,
 
@@ -237,6 +241,28 @@ I output.go:<LINE>] "odd WithValues" keyWithoutValue="(MISSING)"
 	}
  >
 `: `{"caller":"test/output.go:<LINE>","msg":"Format","v":0,"config":{"Kind":"config","RealField":42}}
+`,
+		`I output.go:<LINE>] "maps" s={"hello":"world"} i={"1":2,"3":4}
+`: `{"caller":"test/output.go:<LINE>","msg":"maps","v":0,"s":{"hello":"world"},"i":{"1":2,"3":4}}
+`,
+
+		`I output.go:<LINE>] "slices" s=["hello","world"] i=[1,2,3]
+`: `{"caller":"test/output.go:<LINE>","msg":"slices","v":0,"s":["hello","world"],"i":[1,2,3]}
+`,
+		`I output.go:<LINE>] "structs" s={"Name":"worker","Kind":"pod"}
+`: `{"caller":"test/output.go:<LINE>","msg":"structs","v":0,"s":{"Name":"worker","Kind":"pod"}}
+`,
+		`I output.go:<LINE>] "klog.Format" s=<
+	{
+	  "Name": "worker",
+	  "Kind": "pod"
+	}
+ >
+`: `{"caller":"test/output.go:<LINE>","msg":"klog.Format","v":0,"s":{"Name":"worker","Kind":"pod"}}
+`,
+
+		`I output.go:<LINE>] "cycle" list="<internal error: json: unsupported value: encountered a cycle via *test.myList>"
+`: `{"caller":"test/output.go:<LINE>","msg":"cycle","v":0,"listError":"json: unsupported value: encountered a cycle via *test.myList"}
 `,
 	}
 }