ktesting: capture log entries only if requested

Most users won't need this feature. It was enabled by default to keep the API
simple and because the primary goal was unit testing, but benchmarks also need
this and there unnecessary overhead needs to be avoided.

Author: pohly

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)

ktesting/example_test.go

@@ -25,7 +25,12 @@ 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),
+		),
+	)
 
 	logger.Error(errors.New("failure"), "I failed", "what", "something")
 	logger.WithValues("request", 42).WithValues("anotherValue", "fish").Info("hello world")
@@ -69,3 +74,24 @@ func ExampleUnderlier() {
 	// 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() {
+	var buffer ktesting.BufferTL
+	logger := ktesting.NewLogger(&buffer, ktesting.NewConfig())
+
+	logger.Error(errors.New("failure"), "I failed", "what", "something")
+	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"
+	// I...] Logged at level 5.
+}

ktesting/options.go

@@ -50,6 +50,7 @@ type configOptions struct {
 	verbosityFlagName string
 	vmoduleFlagName   string
 	verbosityDefault  int
+	bufferLogs        bool
 }
 
 // VerbosityFlagName overrides the default -testing.v for the verbosity level.
@@ -94,6 +95,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.
 //

ktesting/testinglogger.go

@@ -42,6 +42,7 @@ limitations under the License.
 package ktesting
 
 import (
+	"fmt"
 	"strings"
 	"sync"
 	"time"
@@ -81,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
@@ -362,6 +380,10 @@ func (l tlogger) log(what LogType, msg string, level int, buf *buffer.Buffer, er
 	}
 	l.shared.t.Log(args...)
 
+	if !l.shared.config.co.bufferLogs {
+		return
+	}
+
 	l.shared.buffer.mutex.Lock()
 	defer l.shared.buffer.mutex.Unlock()
 

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
@@ -124,7 +126,7 @@ func TestInfo(t *testing.T) {
 			}
 
 			actual := buffer.String()
-			actual = regexp.MustCompile(`([IE])[[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\] `).ReplaceAllString(actual, `${1}xxx `)
+			actual = headerRe.ReplaceAllString(actual, `${1}xxx `)
 			if actual != test.expectedOutput {
 				t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual)
 			}