From d1139259a646881a7e20d0c2ffb3fe0a23170e89 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 1 Feb 2023 19:25:35 +0100 Subject: [PATCH] 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. --- ktesting/contextual_test.go | 13 ++++++++++--- ktesting/example_test.go | 28 +++++++++++++++++++++++++++- ktesting/options.go | 16 ++++++++++++++++ ktesting/testinglogger.go | 22 ++++++++++++++++++++++ ktesting/testinglogger_test.go | 4 +++- 5 files changed, 78 insertions(+), 5 deletions(-) diff --git a/ktesting/contextual_test.go b/ktesting/contextual_test.go index f260fb0aa..1b927e8ef 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 c2fa390c5..81f0a46ed 100644 --- a/ktesting/example_test.go +++ b/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: WithKVList:[] ParameterKVList:[]} // log entry #4: {Timestamp:0001-01-01 00:00:00 +0000 UTC Type:INFO Prefix: Message:higher verbosity Verbosity:4 Err: 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. +} diff --git a/ktesting/options.go b/ktesting/options.go index 743b51eba..ab78fe690 100644 --- a/ktesting/options.go +++ b/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. // diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index cbdd0f647..506485e3a 100644 --- a/ktesting/testinglogger.go +++ b/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() diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 2609bce12..6de1834d4 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 @@ -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) }