ktesting: allow overriding default formatter

The intended usage is to replace fmt.Sprintf("%+v") with gomega.format.Object +
YAML support, therefore the only public API change is in the (still
experimental) ktesting.

Internally the additional function pointer gets passed through via a new
Formatter struct. To minimize the impact on klog and textlogger, the
package-level functions still exist and use an empty Formatter.

Author: pohly

internal/serialize/keyvalues.go

@@ -95,9 +95,15 @@ func MergeKVs(first, second []interface{}) []interface{} {
 	return merged
 }
 
+type Formatter struct {
+	AnyToStringHook AnyToStringFunc
+}
+
+type AnyToStringFunc func(v interface{}) string
+
 // MergeKVsInto is a variant of MergeKVs which directly formats the key/value
 // pairs into a buffer.
-func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
+func (f Formatter) MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
 	if len(first) == 0 && len(second) == 0 {
 		// Nothing to do at all.
 		return
@@ -107,7 +113,7 @@ func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
 		// Nothing to be overridden, second slice is well-formed
 		// and can be used directly.
 		for i := 0; i < len(second); i += 2 {
-			KVFormat(b, second[i], second[i+1])
+			f.KVFormat(b, second[i], second[i+1])
 		}
 		return
 	}
@@ -127,24 +133,28 @@ func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
 		if overrides[key] {
 			continue
 		}
-		KVFormat(b, key, first[i+1])
+		f.KVFormat(b, key, first[i+1])
 	}
 	// Round down.
 	l := len(second)
 	l = l / 2 * 2
 	for i := 1; i < l; i += 2 {
-		KVFormat(b, second[i-1], second[i])
+		f.KVFormat(b, second[i-1], second[i])
 	}
 	if len(second)%2 == 1 {
-		KVFormat(b, second[len(second)-1], missingValue)
+		f.KVFormat(b, second[len(second)-1], missingValue)
 	}
 }
 
+func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) {
+	Formatter{}.MergeAndFormatKVs(b, first, second)
+}
+
 const missingValue = "(MISSING)"
 
 // KVListFormat serializes all key/value pairs into the provided buffer.
 // A space gets inserted before the first pair and between each pair.
-func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
+func (f Formatter) KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 	for i := 0; i < len(keysAndValues); i += 2 {
 		var v interface{}
 		k := keysAndValues[i]
@@ -153,13 +163,17 @@ func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
 		} else {
 			v = missingValue
 		}
-		KVFormat(b, k, v)
+		f.KVFormat(b, k, v)
 	}
 }
 
+func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) {
+	Formatter{}.KVListFormat(b, keysAndValues...)
+}
+
 // KVFormat serializes one key/value pair into the provided buffer.
 // A space gets inserted before the pair.
-func KVFormat(b *bytes.Buffer, k, v interface{}) {
+func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) {
 	b.WriteByte(' ')
 	// Keys are assumed to be well-formed according to
 	// https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments
@@ -203,7 +217,7 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) {
 		case string:
 			writeStringValue(b, true, value)
 		default:
-			writeStringValue(b, false, fmt.Sprintf("%+v", value))
+			writeStringValue(b, false, f.AnyToString(value))
 		}
 	case []byte:
 		// In https://github.com/kubernetes/klog/pull/237 it was decided
@@ -220,8 +234,20 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) {
 		b.WriteByte('=')
 		b.WriteString(fmt.Sprintf("%+q", v))
 	default:
-		writeStringValue(b, false, fmt.Sprintf("%+v", v))
+		writeStringValue(b, false, f.AnyToString(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 {
+	if f.AnyToStringHook != nil {
+		return f.AnyToStringHook(v)
 	}
+	return fmt.Sprintf("%+v", v)
 }
 
 // StringerToString converts a Stringer to a string,

ktesting/example_test.go

@@ -29,10 +29,13 @@ func ExampleUnderlier() {
 		ktesting.NewConfig(
 			ktesting.Verbosity(4),
 			ktesting.BufferLogs(true),
+			ktesting.AnyToString(func(value interface{}) string {
+				return fmt.Sprintf("### %+v ###", value)
+			}),
 		),
 	)
 
-	logger.Error(errors.New("failure"), "I failed", "what", "something")
+	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")
@@ -62,24 +65,24 @@ func ExampleUnderlier() {
 	}
 
 	// Output:
-	// ERROR I failed err="failure" what="something"
-	// INFO hello world request=42 anotherValue="fish"
-	// INFO hello world 2 request=42 anotherValue="fish" yetAnotherValue="thanks"
+	// 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]}
+	// 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:[]}
 	// log entry #4: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:higher verbosity Verbosity:4 Err:<nil> WithKVList:[] ParameterKVList:[]}
 }
 
-func ExampleDefaults() {
+func ExampleNewLogger() {
 	var buffer ktesting.BufferTL
 	logger := ktesting.NewLogger(&buffer, ktesting.NewConfig())
 
-	logger.Error(errors.New("failure"), "I failed", "what", "something")
+	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.")
 
@@ -92,6 +95,6 @@ func ExampleDefaults() {
 
 	// Output:
 	// >>  <<
-	// E...] I failed err="failure" what="something"
+	// E...] I failed err="failure" what="something" data={field:1}
 	// I...] Logged at level 5.
 }

ktesting/options.go

@@ -20,6 +20,7 @@ import (
 	"flag"
 	"strconv"
 
+	"k8s.io/klog/v2/internal/serialize"
 	"k8s.io/klog/v2/internal/verbosity"
 )
 
@@ -47,12 +48,27 @@ type Config struct {
 type ConfigOption func(co *configOptions)
 
 type configOptions struct {
+	anyToString       serialize.AnyToStringFunc
 	verbosityFlagName string
 	vmoduleFlagName   string
 	verbosityDefault  int
 	bufferLogs        bool
 }
 
+// AnyToString overrides the default formatter for values that are not
+// supported directly by klog. The default is `fmt.Sprintf("%+v")`.
+// The formatter must not panic.
+//
+// # Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func AnyToString(anyToString func(value interface{}) string) ConfigOption {
+	return func(co *configOptions) {
+		co.anyToString = anyToString
+	}
+}
+
 // VerbosityFlagName overrides the default -testing.v for the verbosity level.
 //
 // # Experimental

ktesting/testinglogger.go

@@ -118,6 +118,9 @@ func NewLogger(t TL, c *Config) logr.Logger {
 			config: c,
 		},
 	}
+	if c.co.anyToString != nil {
+		l.shared.formatter.AnyToStringHook = c.co.anyToString
+	}
 
 	type testCleanup interface {
 		Cleanup(func())
@@ -280,6 +283,7 @@ type tloggerShared struct {
 	// it logs after test completion.
 	goroutineWarningDone bool
 
+	formatter serialize.Formatter
 	testName  string
 	config    *Config
 	buffer    logBuffer
@@ -338,7 +342,7 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
 
 	l.shared.t.Helper()
 	buf := buffer.GetBuffer()
-	serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
+	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
 	l.log(LogInfo, msg, level, buf, nil, kvList)
 }
 
@@ -357,9 +361,9 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
 	l.shared.t.Helper()
 	buf := buffer.GetBuffer()
 	if err != nil {
-		serialize.KVFormat(&buf.Buffer, "err", err)
+		l.shared.formatter.KVFormat(&buf.Buffer, "err", err)
 	}
-	serialize.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
+	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
 	l.log(LogError, msg, 0, buf, err, kvList)
 }