ktesting: capture log data in memory

This is useful for tests that specifically want to check for expected log
output in the code that they are testing.

Capturing log data is done unconditionally. Having a configuration option for
it would be possible, but then usage and code become more complicated
for (probably) very little performance gains in tests that don't need the
captured data.

ktesting/example_test.go

@@ -0,0 +1,71 @@
+/*
+Copyright 2022 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package ktesting_test
+
+import (
+	"errors"
+	"fmt"
+	"time"
+
+	"k8s.io/klog/v2/ktesting"
+)
+
+func ExampleUnderlier() {
+	logger := ktesting.NewLogger(ktesting.NopTL{}, ktesting.NewConfig(ktesting.Verbosity(4)))
+
+	logger.Error(errors.New("failure"), "I failed", "what", "something")
+	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")
+	logger.V(4).Info("higher verbosity")
+	logger.V(5).Info("Not captured because of ktesting.Verbosity(4) above. Normally it would be captured because default verbosity is 5.")
+
+	testingLogger, ok := logger.GetSink().(ktesting.Underlier)
+	if !ok {
+		panic("Should have had a ktesting LogSink!?")
+	}
+
+	t := testingLogger.GetUnderlying()
+	t.Log("This goes to /dev/null...")
+
+	buffer := testingLogger.GetBuffer()
+	fmt.Printf("%s\n", buffer.String())
+
+	log := buffer.Data()
+	for i, entry := range log {
+		if i > 0 &&
+			entry.Timestamp.Sub(log[i-1].Timestamp).Nanoseconds() < 0 {
+			fmt.Printf("Unexpected timestamp order: #%d %s > #%d %s", i-1, log[i-1].Timestamp, i, entry.Timestamp)
+		}
+		// Strip varying time stamp before dumping the struct.
+		entry.Timestamp = time.Time{}
+		fmt.Printf("log entry #%d: %+v\n", i, entry)
+	}
+
+	// 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"
+	// 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 #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:[]}
+}

ktesting/testinglogger.go

@@ -20,6 +20,18 @@ limitations under the License.
 // Therefore it can be used in standard Go tests and Gingko test suites
 // to ensure that output is associated with the currently running test.
 //
+// In addition, the log data is captured in a buffer and can be used by the
+// test to verify that the code under test is logging as expected. To get
+// access to that data, cast the LogSink into the Underlier type and retrieve
+// it:
+//
+//    logger := ktesting.NewLogger(...)
+//    if testingLogger, ok := logger.GetSink().(ktesting.Underlier); ok {
+//        t := testingLogger.GetUnderlying()
+//        buffer := testingLogger.GetBuffer()
+//        text := buffer.String()
+//        log := buffer.Data()
+//
 // Serialization of the structured log parameters is done in the same way
 // as for klog.InfoS.
 //
@@ -31,6 +43,9 @@ package ktesting
 
 import (
 	"bytes"
+	"strings"
+	"sync"
+	"time"
 
 	"github.com/go-logr/logr"
 
@@ -49,6 +64,20 @@ type TL interface {
 	Log(args ...interface{})
 }
 
+// NopTL implements TL with empty stubs. It can be used when only capturing
+// output in memory is relevant.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type NopTL struct{}
+
+func (n NopTL) Helper()                 {}
+func (n NopTL) Log(args ...interface{}) {}
+
+var _TL = NopTL{}
+
 // NewLogger constructs a new logger for the given test interface.
 //
 // Experimental
@@ -61,14 +90,149 @@ func NewLogger(t TL, c *Config) logr.Logger {
 		prefix: "",
 		values: nil,
 		config: c,
+		buffer: new(buffer),
 	})
 }
 
+// Buffer stores log entries as formatted text and structured data.
+// It is safe to use this concurrently.
+//
+// Experimental
+//
+// Notice: This interface is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type Buffer interface {
+	// String returns the log entries in a format that is similar to the
+	// klog text output.
+	String() string
+
+	// Data returns the log entries as structs.
+	Data() Log
+}
+
+// Log contains log entries in the order in which they were generated.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type Log []LogEntry
+
+// DeepCopy returns a copy of the log. The error instance and key/value
+// pairs remain shared.
+//
+// Experimental
+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func (l Log) DeepCopy() Log {
+	log := make(Log, 0, len(l))
+	log = append(log, l...)
+	return log
+}
+
+// LogEntry represents all information captured for a log entry.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type LogEntry struct {
+	// Timestamp stores the time when the log entry was created.
+	Timestamp time.Time
+
+	// Type is either LogInfo or LogError.
+	Type LogType
+
+	// Prefix contains the WithName strings concatenated with a slash.
+	Prefix string
+
+	// Message is the fixed log message string.
+	Message string
+
+	// Verbosity is always 0 for LogError.
+	Verbosity int
+
+	// Err is always nil for LogInfo. It may or may not be
+	// nil for LogError.
+	Err error
+
+	// WithKVList are the concatenated key/value pairs from WithValues
+	// calls. It's guaranteed to have an even number of entries because
+	// the logger ensures that when WithValues is called.
+	WithKVList []interface{}
+
+	// ParameterKVList are the key/value pairs passed into the call,
+	// without any validation.
+	ParameterKVList []interface{}
+}
+
+// LogType determines whether a log entry was created with an Error or Info
+// call.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type LogType string
+
+const (
+	// LogError is the special value used for Error log entries.
+	//
+	// Experimental
+	//
+	// Notice: This value is EXPERIMENTAL and may be changed or removed in
+	// a later release.
+	LogError = LogType("ERROR")
+
+	// LogInfo is the special value used for Info log entries.
+	//
+	// Experimental
+	//
+	// Notice: This value is EXPERIMENTAL and may be changed or removed in
+	// a later release.
+	LogInfo = LogType("INFO")
+)
+
+// Underlier is implemented by the LogSink of this logger. It provides access
+// to additional APIs that are normally hidden behind the Logger API.
+//
+// Experimental
+//
+// Notice: This type is EXPERIMENTAL and may be changed or removed in a
+// later release.
+type Underlier interface {
+	// GetUnderlying returns the testing instance that logging goes to.
+	GetUnderlying() TL
+
+	// GetBuffer grants access to the in-memory copy of the log entries.
+	GetBuffer() Buffer
+}
+
+type buffer struct {
+	mutex sync.Mutex
+	text  strings.Builder
+	log   Log
+}
+
+func (b *buffer) String() string {
+	b.mutex.Lock()
+	defer b.mutex.Unlock()
+	return b.text.String()
+}
+
+func (b *buffer) Data() Log {
+	b.mutex.Lock()
+	defer b.mutex.Unlock()
+	return b.log.DeepCopy()
+}
+
 type tlogger struct {
 	t      TL
 	prefix string
 	values []interface{}
 	config *Config
+	buffer *buffer
 }
 
 func (l *tlogger) Init(info logr.RuntimeInfo) {
@@ -83,7 +247,7 @@ func (l *tlogger) Info(level int, msg string, kvList ...interface{}) {
 	buffer := &bytes.Buffer{}
 	merged := serialize.MergeKVs(l.values, kvList)
 	serialize.KVListFormat(buffer, merged...)
-	l.log("INFO", msg, buffer)
+	l.log(LogInfo, msg, level, buffer, nil, kvList)
 }
 
 func (l *tlogger) Enabled(level int) bool {
@@ -98,10 +262,10 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) {
 	}
 	merged := serialize.MergeKVs(l.values, kvList)
 	serialize.KVListFormat(buffer, merged...)
-	l.log("ERROR", msg, buffer)
+	l.log(LogError, msg, 0, buffer, err, kvList)
 }
 
-func (l *tlogger) log(what, msg string, buffer *bytes.Buffer) {
+func (l *tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) {
 	l.t.Helper()
 	args := []interface{}{what}
 	if l.prefix != "" {
@@ -113,6 +277,34 @@ func (l *tlogger) log(what, msg string, buffer *bytes.Buffer) {
 		args = append(args, string(buffer.Bytes()[1:]))
 	}
 	l.t.Log(args...)
+
+	l.buffer.mutex.Lock()
+	defer l.buffer.mutex.Unlock()
+
+	// Store as text.
+	l.buffer.text.WriteString(string(what))
+	for i := 1; i < len(args); i++ {
+		l.buffer.text.WriteByte(' ')
+		l.buffer.text.WriteString(args[i].(string))
+	}
+	lastArg := args[len(args)-1].(string)
+	if lastArg[len(lastArg)-1] != '\n' {
+		l.buffer.text.WriteByte('\n')
+	}
+
+	// Store as raw data.
+	l.buffer.log = append(l.buffer.log,
+		LogEntry{
+			Timestamp:       time.Now(),
+			Type:            what,
+			Prefix:          l.prefix,
+			Message:         msg,
+			Verbosity:       level,
+			Err:             err,
+			WithKVList:      l.values,
+			ParameterKVList: kvList,
+		},
+	)
 }
 
 // WithName returns a new logr.Logger with the specified name appended.  klogr
@@ -133,5 +325,14 @@ func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink {
 	return &new
 }
 
+func (l *tlogger) GetUnderlying() TL {
+	return l.t
+}
+
+func (l *tlogger) GetBuffer() Buffer {
+	return l.buffer
+}
+
 var _ logr.LogSink = &tlogger{}
 var _ logr.CallStackHelperLogSink = &tlogger{}
+var _ Underlier = &tlogger{}