Merge pull request #375 from pohly/json-fallback

JSON as fallback encoding

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": {
@@ -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
+}