Repository: kubernetes/klog
Pull request #365 (2023-02-02 15:17:15)

ktesting improvements
**What this PR does / why we need it**:

I've been using ktesting in the context of k8s.io/kubernetes/test/integration/scheduler_perf and would like to suggest some enhancements:
- add time stamps
- less overhead by default
- better formatting during tests in Kubernetes where gomega.format.Object is available: depends on hook in ktesting

**Special notes for your reviewer**:

Here's how this will be used in Kubernetes: https://github.com/kubernetes/kubernetes/pull/115506


**Release note**:

```release-note
NONE
```


Patch:
diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go
index d53b49d..121cbf7 100644
--- a/internal/buffer/buffer.go
+++ b/internal/buffer/buffer.go
@@ -99,7 +99,8 @@ func (buf *Buffer) someDigits(i, d int) int {
 	return copy(buf.Tmp[i:], buf.Tmp[j:])
 }
 
-// FormatHeader formats a log header using the provided file name and line number.
+// FormatHeader formats a log header using the provided file name and line number
+// and writes it into the buffer.
 func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now time.Time) {
 	if line < 0 {
 		line = 0 // not a real line number, but acceptable to someDigits
@@ -135,3 +136,30 @@ func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now
 	buf.Tmp[n+2] = ' '
 	buf.Write(buf.Tmp[:n+3])
 }
+
+// SprintHeader formats a log header and returns a string. This is a simpler
+// version of FormatHeader for use in ktesting.
+func (buf *Buffer) SprintHeader(s severity.Severity, now time.Time) string {
+	if s > severity.FatalLog {
+		s = severity.InfoLog // for safety.
+	}
+
+	// Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand.
+	// It's worth about 3X. Fprintf is hard.
+	_, month, day := now.Date()
+	hour, minute, second := now.Clock()
+	// Lmmdd hh:mm:ss.uuuuuu threadid file:line]
+	buf.Tmp[0] = severity.Char[s]
+	buf.twoDigits(1, int(month))
+	buf.twoDigits(3, day)
+	buf.Tmp[5] = ' '
+	buf.twoDigits(6, hour)
+	buf.Tmp[8] = ':'
+	buf.twoDigits(9, minute)
+	buf.Tmp[11] = ':'
+	buf.twoDigits(12, second)
+	buf.Tmp[14] = '.'
+	buf.nDigits(6, 15, now.Nanosecond()/1000, '0')
+	buf.Tmp[21] = ']'
+	return string(buf.Tmp[:22])
+}
diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go
index f9558c3..1dc81a1 100644
--- a/internal/serialize/keyvalues.go
+++ b/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,


Test patch:
diff --git a/ktesting/contextual_test.go b/ktesting/contextual_test.go
index f260fb0..1b927e8 100644
--- a/ktesting/contextual_test.go
+++ b/ktesting/contextual_test.go
@@ -16,7 +16,8 @@ import (
 )
 
 func TestContextual(t *testing.T) {
-	logger, ctx := ktesting.NewTestContext(t)
+	var buffer ktesting.BufferTL
+	logger, ctx := ktesting.NewTestContext(&buffer)
 
 	doSomething(ctx)
 
@@ -33,8 +34,14 @@ func TestContextual(t *testing.T) {
 	}
 
 	actual := testingLogger.GetBuffer().String()
-	expected := `INFO hello world
-INFO foo: hello also from me
+	if actual != "" {
+		t.Errorf("testinglogger should not have buffered, got:\n%s", actual)
+	}
+
+	actual = buffer.String()
+	actual = headerRe.ReplaceAllString(actual, "${1}xxx] ")
+	expected := `Ixxx] hello world
+Ixxx] foo: hello also from me
 `
 	if actual != expected {
 		t.Errorf("mismatch in captured output, expected:\n%s\ngot:\n%s\n", expected, actual)
diff --git a/ktesting/example_test.go b/ktesting/example_test.go
index c2fa390..3fc688b 100644
--- a/ktesting/example_test.go
+++ b/ktesting/example_test.go
@@ -25,9 +25,17 @@ import (
 )
 
 func ExampleUnderlier() {
-	logger := ktesting.NewLogger(ktesting.NopTL{}, ktesting.NewConfig(ktesting.Verbosity(4)))
+	logger := ktesting.NewLogger(ktesting.NopTL{},
+		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")
@@ -57,15 +65,36 @@ 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 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.V(5).Info("Logged at level 5.")
+	logger.V(6).Info("Not logged at level 6.")
+
+	testingLogger, ok := logger.GetSink().(ktesting.Underlier)
+	if !ok {
+		panic("Should have had a ktesting LogSink!?")
+	}
+	fmt.Printf(">> %s <<\n", testingLogger.GetBuffer().String())       // Should be empty.
+	fmt.Print(headerRe.ReplaceAllString(buffer.String(), "${1}...] ")) // Should not be empty.
+
+	// Output:
+	// >>  <<
+	// E...] I failed err="failure" what="something" data={field:1}
+	// I...] Logged at level 5.
+}
diff --git a/ktesting/options.go b/ktesting/options.go
index 743b51e..c9bb3da 100644
--- a/ktesting/options.go
+++ b/ktesting/options.go
@@ -20,6 +20,7 @@ import (
 	"flag"
 	"strconv"
 
+	"k8s.io/klog/v2/internal/serialize"
 	"k8s.io/klog/v2/internal/verbosity"
 )
 
@@ -47,9 +48,25 @@ 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.
@@ -94,6 +111,21 @@ func Verbosity(level int) ConfigOption {
 	}
 }
 
+// BufferLogs controls whether log entries are captured in memory in addition
+// to being printed. Off by default. Unit tests that want to verify that
+// log entries are emitted as expected can turn this on and then retrieve
+// the captured log through the Underlier LogSink interface.
+//
+// # Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func BufferLogs(enabled bool) ConfigOption {
+	return func(co *configOptions) {
+		co.bufferLogs = enabled
+	}
+}
+
 // NewConfig returns a configuration with recommended defaults and optional
 // modifications. Command line flags are not bound to any FlagSet yet.
 //
diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go
index 0c87a95..434b153 100644
--- a/ktesting/testinglogger.go
+++ b/ktesting/testinglogger.go
@@ -42,7 +42,7 @@ limitations under the License.
 package ktesting
 
 import (
-	"bytes"
+	"fmt"
 	"strings"
 	"sync"
 	"time"
@@ -50,8 +50,10 @@ import (
 	"github.com/go-logr/logr"
 
 	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/internal/buffer"
 	"k8s.io/klog/v2/internal/dbg"
 	"k8s.io/klog/v2/internal/serialize"
+	"k8s.io/klog/v2/internal/severity"
 	"k8s.io/klog/v2/internal/verbosity"
 )
 
@@ -80,6 +82,23 @@ func (n NopTL) Log(args ...interface{}) {}
 
 var _ TL = NopTL{}
 
+// BufferTL implements TL with an in-memory buffer.
+//
+// # Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type BufferTL struct {
+	strings.Builder
+}
+
+func (n *BufferTL) Helper() {}
+func (n *BufferTL) Log(args ...interface{}) {
+	n.Builder.WriteString(fmt.Sprintln(args...))
+}
+
+var _ TL = &BufferTL{}
+
 // NewLogger constructs a new logger for the given test interface.
 //
 // Beware that testing.T does not support logging after the test that
@@ -99,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())
@@ -230,19 +252,19 @@ type Underlier interface {
 	GetBuffer() Buffer
 }
 
-type buffer struct {
+type logBuffer struct {
 	mutex sync.Mutex
 	text  strings.Builder
 	log   Log
 }
 
-func (b *buffer) String() string {
+func (b *logBuffer) String() string {
 	b.mutex.Lock()
 	defer b.mutex.Unlock()
 	return b.text.String()
 }
 
-func (b *buffer) Data() Log {
+func (b *logBuffer) Data() Log {
 	b.mutex.Lock()
 	defer b.mutex.Unlock()
 	return b.log.DeepCopy()
@@ -261,9 +283,10 @@ type tloggerShared struct {
 	// it logs after test completion.
 	goroutineWarningDone bool
 
+	formatter serialize.Formatter
 	testName  string
 	config    *Config
-	buffer    buffer
+	buffer    logBuffer
 	callDepth int
 }
 
@@ -318,9 +341,9 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
 	}
 
 	l.shared.t.Helper()
-	buffer := &bytes.Buffer{}
-	serialize.MergeAndFormatKVs(buffer, l.values, kvList)
-	l.log(LogInfo, msg, level, buffer, nil, kvList)
+	buf := buffer.GetBuffer()
+	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
+	l.log(LogInfo, msg, level, buf, nil, kvList)
 }
 
 func (l tlogger) Enabled(level int) bool {
@@ -336,27 +359,35 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
 	}
 
 	l.shared.t.Helper()
-	buffer := &bytes.Buffer{}
+	buf := buffer.GetBuffer()
 	if err != nil {
-		serialize.KVFormat(buffer, "err", err)
+		l.shared.formatter.KVFormat(&buf.Buffer, "err", err)
 	}
-	serialize.MergeAndFormatKVs(buffer, l.values, kvList)
-	l.log(LogError, msg, 0, buffer, err, kvList)
+	l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList)
+	l.log(LogError, msg, 0, buf, err, kvList)
 }
 
-func (l tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) {
+func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, err error, kvList []interface{}) {
 	l.shared.t.Helper()
-	args := []interface{}{what}
+	s := severity.InfoLog
+	if what == LogError {
+		s = severity.ErrorLog
+	}
+	args := []interface{}{buf.SprintHeader(s, time.Now())}
 	if l.prefix != "" {
 		args = append(args, l.prefix+":")
 	}
 	args = append(args, msg)
-	if buffer.Len() > 0 {
+	if buf.Len() > 0 {
 		// Skip leading space inserted by serialize.KVListFormat.
-		args = append(args, string(buffer.Bytes()[1:]))
+		args = append(args, string(buf.Bytes()[1:]))
 	}
 	l.shared.t.Log(args...)
 
+	if !l.shared.config.co.bufferLogs {
+		return
+	}
+
 	l.shared.buffer.mutex.Lock()
 	defer l.shared.buffer.mutex.Unlock()
 
diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go
index bb1efe6..6de1834 100644
--- a/ktesting/testinglogger_test.go
+++ b/ktesting/testinglogger_test.go
@@ -21,6 +21,8 @@ import (
 	"k8s.io/klog/v2/ktesting"
 )
 
+var headerRe = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `)
+
 func TestInfo(t *testing.T) {
 	tests := map[string]struct {
 		text           string
@@ -33,78 +35,78 @@ func TestInfo(t *testing.T) {
 		"should log with values passed to keysAndValues": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
-			expectedOutput: `INFO test akey="avalue"
+			expectedOutput: `Ixxx test akey="avalue"
 `,
 		},
 		"should support single name": {
 			names:         []string{"hello"},
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
-			expectedOutput: `INFO hello: test akey="avalue"
+			expectedOutput: `Ixxx hello: test akey="avalue"
 `,
 		},
 		"should support multiple names": {
 			names:         []string{"hello", "world"},
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
-			expectedOutput: `INFO hello/world: test akey="avalue"
+			expectedOutput: `Ixxx hello/world: test akey="avalue"
 `,
 		},
 		"should not print duplicate keys with the same value": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"},
-			expectedOutput: `INFO test akey="avalue" akey="avalue"
+			expectedOutput: `Ixxx test akey="avalue" akey="avalue"
 `,
 		},
 		"should only print the last duplicate key when the values are passed to Info": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"},
-			expectedOutput: `INFO test akey="avalue" akey="avalue2"
+			expectedOutput: `Ixxx test akey="avalue" akey="avalue2"
 `,
 		},
 		"should only print the duplicate key that is passed to Info if one was passed to the logger": {
 			withValues:    []interface{}{"akey", "avalue"},
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue"},
-			expectedOutput: `INFO test akey="avalue"
+			expectedOutput: `Ixxx test akey="avalue"
 `,
 		},
 		"should only print the key passed to Info when one is already set on the logger": {
 			withValues:    []interface{}{"akey", "avalue"},
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue2"},
-			expectedOutput: `INFO test akey="avalue2"
+			expectedOutput: `Ixxx test akey="avalue2"
 `,
 		},
 		"should correctly handle odd-numbers of KVs": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
-			expectedOutput: `INFO test akey="avalue" akey2="(MISSING)"
+			expectedOutput: `Ixxx test akey="avalue" akey2="(MISSING)"
 `,
 		},
 		"should correctly html characters": {
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "<&>"},
-			expectedOutput: `INFO test akey="<&>"
+			expectedOutput: `Ixxx test akey="<&>"
 `,
 		},
 		"should correctly handle odd-numbers of KVs in both log values and Info args": {
 			withValues:    []interface{}{"basekey1", "basevar1", "basekey2"},
 			text:          "test",
 			keysAndValues: []interface{}{"akey", "avalue", "akey2"},
-			expectedOutput: `INFO test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
+			expectedOutput: `Ixxx test basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)"
 `,
 		},
 		"should correctly print regular error types": {
 			text:          "test",
 			keysAndValues: []interface{}{"err", errors.New("whoops")},
-			expectedOutput: `INFO test err="whoops"
+			expectedOutput: `Ixxx test err="whoops"
 `,
 		},
 		"should correctly print regular error types when using logr.Error": {
 			text: "test",
 			err:  errors.New("whoops"),
-			expectedOutput: `ERROR test err="whoops"
+			expectedOutput: `Exxx test err="whoops"
 `,
 		},
 	}
@@ -124,6 +126,7 @@ func TestInfo(t *testing.T) {
 			}
 
 			actual := buffer.String()
+			actual = headerRe.ReplaceAllString(actual, `${1}xxx `)
 			if actual != test.expectedOutput {
 				t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual)
 			}