ktesting: capture log data in memory

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