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.

Author: pohly

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,20 +235,33 @@ 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)
 	}
 }
 
 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
 	}
 

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},

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
 		}
 	}

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},
 		},

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.
 }
 

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": {
@@ -409,19 +409,36 @@ I output.go:<LINE>] "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:<LINE>] "maps" s=map[hello:world] i=map[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]
+		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 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>"
 `,
 	},
 }
@@ -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
+}