From 095475485f59b210f4a172f76c8f962ebddf750b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 8 Dec 2025 08:19:39 +0100 Subject: [PATCH] ktesting: rewrite unit testing with mock TB We need to see the actual effect that ktesting will have when used as wrapper around testing.T. Producing an error hid that adding the klog header makes some output sub-optimal: : FATAL ERROR: ... The problem with having the klog header at the beginning of the line is that the Kubernetes `make test` post-processing treats this as log output instead of the failure message of the test. Will be fixed separately. --- test/utils/ktesting/assert_test.go | 110 ++++++++++-------- test/utils/ktesting/helper_test.go | 146 ++++++++++++++++++------ test/utils/ktesting/stepcontext_test.go | 17 +-- 3 files changed, 179 insertions(+), 94 deletions(-) diff --git a/test/utils/ktesting/assert_test.go b/test/utils/ktesting/assert_test.go index 94db0b7bf9c..dbc0b3f6c97 100644 --- a/test/utils/ktesting/assert_test.go +++ b/test/utils/ktesting/assert_test.go @@ -36,11 +36,13 @@ func TestAssert(t *testing.T) { }).WithTimeout(time.Second).Should(gomega.Equal(1)) }, expectDuration: time.Second, - expectError: `Timed out after x.y s. + expectTrace: `(FATAL) : FATAL ERROR: +Timed out after x.y s. Expected : 0 to equal - : 1`, + : 1 +`, }, "eventually-final": { cb: func(tCtx TContext) { @@ -50,8 +52,10 @@ to equal }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: 0, - expectError: `Told to stop trying after x.y s. -final error`, + expectTrace: `(FATAL) : FATAL ERROR: +Told to stop trying after x.y s. +final error +`, }, "eventually-error": { cb: func(tCtx TContext) { @@ -61,7 +65,8 @@ final error`, }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: time.Second, - expectError: `Timed out after x.y s. + expectTrace: `(FATAL) : FATAL ERROR: +Timed out after x.y s. The function passed to Eventually returned the following error: <*errors.joinError | 0xXXXX>: some error @@ -69,7 +74,8 @@ The function passed to Eventually returned the following error: errs: [ <*errors.errorString | 0xXXXX>{s: "some error"}, ], - }`, + } +`, }, "eventually-success": { cb: func(tCtx TContext) { @@ -78,8 +84,7 @@ The function passed to Eventually returned the following error: }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: 0, - expectNoFail: true, - expectError: ``, + expectTrace: ``, }, "eventually-retry": { cb: func(tCtx TContext) { @@ -89,8 +94,10 @@ The function passed to Eventually returned the following error: }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: time.Second, - expectError: `Timed out after x.y s. -told to try again after 1ms`, + expectTrace: `(FATAL) : FATAL ERROR: +Timed out after x.y s. +told to try again after 1ms +`, }, "consistently-timeout": { cb: func(tCtx TContext) { @@ -101,11 +108,13 @@ told to try again after 1ms`, }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: 0, - expectError: `Failed after x.y s. + expectTrace: `(FATAL) : FATAL ERROR: +Failed after x.y s. Expected : 0 to equal - : 1`, + : 1 +`, }, "consistently-final": { cb: func(tCtx TContext) { @@ -116,8 +125,10 @@ to equal }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: 0, - expectError: `Told to stop trying after x.y s. -final error`, + expectTrace: `(FATAL) : FATAL ERROR: +Told to stop trying after x.y s. +final error +`, }, "consistently-error": { cb: func(tCtx TContext) { @@ -127,7 +138,8 @@ final error`, }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: 0, - expectError: `Failed after x.y s. + expectTrace: `(FATAL) : FATAL ERROR: +Failed after x.y s. The function passed to Consistently returned the following error: <*errors.joinError | 0xXXXX>: some error @@ -135,7 +147,8 @@ The function passed to Consistently returned the following error: errs: [ <*errors.errorString | 0xXXXX>{s: "some error"}, ], - }`, + } +`, }, "consistently-success": { cb: func(tCtx TContext) { @@ -144,8 +157,7 @@ The function passed to Consistently returned the following error: }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: time.Second, - expectNoFail: true, - expectError: ``, + expectTrace: ``, }, "consistently-retry": { cb: func(tCtx TContext) { @@ -155,88 +167,88 @@ The function passed to Consistently returned the following error: }).WithTimeout(time.Second).Should(gomega.Equal(1.0)) }, expectDuration: time.Second, - expectError: `Timed out while waiting on TryAgainAfter after x.y s. -told to try again after 1ms: intermittent error`, + expectTrace: `(FATAL) : FATAL ERROR: +Timed out while waiting on TryAgainAfter after x.y s. +told to try again after 1ms: intermittent error +`, }, "expect-equal": { cb: func(tCtx TContext) { tCtx.Expect(1).To(gomega.Equal(42)) + tCtx.Log("not reached") }, - expectError: `Expected + expectTrace: `(FATAL) : FATAL ERROR: +Expected : 1 to equal - : 42`, + : 42 +`, }, - "expect-no-error-success": { cb: func(tCtx TContext) { tCtx.ExpectNoError(nil) }, - expectNoFail: true, }, "expect-no-error-normal-error": { cb: func(tCtx TContext) { tCtx.ExpectNoError(errors.New("fake error")) }, - expectError: `Unexpected error: fake error`, - expectLog: `: Unexpected error: + expectTrace: `(LOG) : Unexpected error: <*errors.errorString | 0xXXXX>: fake error {s: "fake error"} +(FATAL) : FATAL ERROR: Unexpected error: fake error `, }, - "expect-no-error-normal-error-no-logging": { - suppressUnexpectedErrorLogging: true, - cb: func(tCtx TContext) { - tCtx.ExpectNoError(errors.New("fake error")) - }, - expectError: `Unexpected error: fake error`, - }, "expect-no-error-failure": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"})) }, - expectError: `doing something: fake error`, + expectTrace: `(FATAL) : FATAL ERROR: doing something: fake error +`, }, "expect-no-error-explanation-string": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), "testing error checking") }, - expectError: `testing error checking: doing something: fake error`, + expectTrace: `(FATAL) : FATAL ERROR: testing error checking: doing something: fake error +`, }, "expect-no-error-explanation-printf": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), "testing %s %d checking", "error", 42) }, - expectError: `testing error 42 checking: doing something: fake error`, + expectTrace: `(FATAL) : FATAL ERROR: testing error 42 checking: doing something: fake error +`, }, "expect-no-error-explanation-callback": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), func() string { return "testing error checking" }) }, - expectError: `testing error checking: doing something: fake error`, + expectTrace: `(FATAL) : FATAL ERROR: testing error checking: doing something: fake error +`, }, "expect-no-error-backtrace": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error", FullStackTrace: "abc\nxyz"})) }, - expectError: `doing something: fake error`, - expectLog: `: Failed at: + expectTrace: `(LOG) : Failed at: abc xyz +(FATAL) : FATAL ERROR: doing something: fake error `, }, "expect-no-error-backtrace-and-explanation": { cb: func(tCtx TContext) { tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error", FullStackTrace: "abc\nxyz"}), "testing error checking") }, - expectError: `testing error checking: doing something: fake error`, - expectLog: `: testing error checking -: Failed at: + expectTrace: `(LOG) : testing error checking +(LOG) : Failed at: abc xyz +(FATAL) : FATAL ERROR: testing error checking: doing something: fake error `, }, @@ -247,11 +259,11 @@ to equal tCtx.Error("Error", "a", "b", 42) tCtx.Errorf("Errorf %s %s %d", "a", "b", 42) }, - expectLog: `: Log a b 42 -: Logf a b 42 + expectTrace: `(LOG) : Log a b 42 +(LOG) : Logf a b 42 +(ERROR) : ERROR: Error a b 42 +(ERROR) : ERROR: Errorf a b 42 `, - expectError: `Error a b 42 -Errorf a b 42`, }, "fatal": { cb: func(tCtx TContext) { @@ -259,7 +271,8 @@ Errorf a b 42`, // not reached tCtx.Log("Log") }, - expectError: `Error a b 42`, + expectTrace: `(FATAL) : FATAL ERROR: Error a b 42 +`, }, "fatalf": { cb: func(tCtx TContext) { @@ -267,7 +280,8 @@ Errorf a b 42`, // not reached tCtx.Log("Log") }, - expectError: `Error a b 42`, + expectTrace: `(FATAL) : FATAL ERROR: Error a b 42 +`, }, } { tc := tc diff --git a/test/utils/ktesting/helper_test.go b/test/utils/ktesting/helper_test.go index 3458f5a4fcd..eb60b542d88 100644 --- a/test/utils/ktesting/helper_test.go +++ b/test/utils/ktesting/helper_test.go @@ -29,46 +29,29 @@ import ( // testcase wraps a callback which is called with a TContext that intercepts // errors and log output. Those get compared. type testcase struct { - cb func(TContext) - expectNoFail bool - expectError string - expectDuration time.Duration - expectLog string - suppressUnexpectedErrorLogging bool + cb func(TContext) + expectDuration time.Duration + expectTrace string } func (tc testcase) run(t *testing.T) { - bufferT := &logBufferT{T: t} - tCtx := Init(bufferT) - var err error - we := WithError - if !tc.suppressUnexpectedErrorLogging { - we = WithErrorLogging - } - tCtx, finalize := we(tCtx, &err) + buffer := &mockTB{} + tCtx := Init(buffer) start := time.Now() func() { - defer finalize() + defer func() { + if r := recover(); r != nil && r != logBufferStop { + panic(r) + } + }() tc.cb(tCtx) }() - - log := bufferT.log.String() - t.Logf("Log output:\n%s\n", log) - if tc.expectLog != "" { - assert.Equal(t, tc.expectLog, normalize(log)) - } else if log != "" { - t.Error("Expected no log output.") - } - duration := time.Since(start) + + trace := buffer.log.String() + t.Logf("Trace:\n%s\n", trace) assert.InDelta(t, tc.expectDuration.Seconds(), duration.Seconds(), 0.1, "callback invocation duration %s", duration) - assert.Equal(t, !tc.expectNoFail, tCtx.Failed(), "Failed()") - if tc.expectError == "" { - assert.NoError(t, err) - } else if assert.Error(t, err) { - t.Logf("Result:\n%s", err.Error()) - assert.Equal(t, tc.expectError, normalize(err.Error())) - } + assert.Equal(t, tc.expectTrace, normalize(trace)) } // normalize replaces parts of message texts which may vary with constant strings. @@ -82,16 +65,103 @@ func normalize(msg string) string { return msg } -type logBufferT struct { - *testing.T +// mockTB records which calls were made (type and parameters) +// +// The final string looks similar to the output visible in `go test -v`, +// except that it is visible how the sausage was made (Fatal vs Log + FailNow). +// Log+FailNow and Fatal are equivalent with testing.T, but not +// with Ginkgo as underlying TB because it can only properly +// capture the failure message if Fatal is used. +type mockTB struct { log strings.Builder } -func (l *logBufferT) Log(args ...any) { - l.log.WriteString(fmt.Sprintln(args...)) +func (m *mockTB) Cleanup(func()) { + // Gets called by Init all the time, not logged because it's distracting. + // m.log.WriteString("(CLEANUP)\n") } -func (l *logBufferT) Logf(format string, args ...any) { - l.log.WriteString(fmt.Sprintf(format, args...)) - l.log.WriteRune('\n') +func (m *mockTB) Error(args ...any) { + m.log.WriteString(fmt.Sprintln(append([]any{"(ERROR)"}, args...)...)) } + +func (m *mockTB) Errorf(format string, args ...any) { + m.log.WriteString(fmt.Sprintf("(ERRORF) "+format+"\n", args)) +} + +func (m *mockTB) Fail() { + m.log.WriteString("(FAIL)\n") +} + +func (m *mockTB) FailNow() { + m.log.WriteString("(FAILNOW)\n") + panic(logBufferStop) +} + +func (m *mockTB) Failed() bool { + m.log.WriteString("(FAILED)\n") + return false +} + +func (m *mockTB) Fatal(args ...any) { + m.log.WriteString(fmt.Sprintln(append([]any{"(FATAL)"}, args...)...)) + panic(logBufferStop) +} + +func (m *mockTB) Fatalf(format string, args ...any) { + m.log.WriteString(fmt.Sprintf("(FATALF) "+format+"\n", args)) + panic(logBufferStop) +} + +func (m *mockTB) Helper() { + // TODO: include stack unwinding to verify that Helper is called in the right places. + // Merely logging it is not sufficient. + // m.log.WriteString("HELPER\n") +} + +func (m *mockTB) Log(args ...any) { + m.log.WriteString(fmt.Sprintln(append([]any{"(LOG)"}, args...)...)) +} + +func (m *mockTB) Logf(format string, args ...any) { + m.log.WriteString(fmt.Sprintf("(LOGF) "+format+"\n", args)) +} + +func (m *mockTB) Name() string { + // Gets called by Init all the time, not logged because its distracting. + // m.log.WriteString("(NAME)\n") + return "logBufferT" +} + +func (m *mockTB) Setenv(key, value string) { + m.log.WriteString("(SETENV)\n") +} + +func (m *mockTB) Skip(args ...any) { + m.log.WriteString(fmt.Sprintln(append([]any{"(SKIP)"}, args...)...)) + panic(logBufferStop) +} + +func (m *mockTB) SkipNow() { + m.log.WriteString("(SKIPNOW)\n") + panic(logBufferStop) +} + +func (m *mockTB) Skipf(format string, args ...any) { + m.log.WriteString(fmt.Sprintf("(SKIPF) "+format+"\n", args...)) + panic(logBufferStop) +} + +func (m *mockTB) Skipped() bool { + m.log.WriteString("(SKIPPED)\n") + return false +} + +func (m *mockTB) TempDir() string { + m.log.WriteString("(TEMPDIR)\n") + return "/no-such-dir" +} + +var ( + logBufferStop = "STOP" +) diff --git a/test/utils/ktesting/stepcontext_test.go b/test/utils/ktesting/stepcontext_test.go index e28f24d76b0..974a1066910 100644 --- a/test/utils/ktesting/stepcontext_test.go +++ b/test/utils/ktesting/stepcontext_test.go @@ -35,11 +35,11 @@ func TestStepContext(t *testing.T) { tCtx.Error("Error", "a", "b", 42) tCtx.Errorf("Errorf %s %s %d", "a", "b", 42) }, - expectLog: `: step: Log a b 42 -: step: Logf a b 42 + expectTrace: `(LOG) : step: Log a b 42 +(LOG) : step: Logf a b 42 +(ERROR) : ERROR: step: Error a b 42 +(ERROR) : ERROR: step: Errorf a b 42 `, - expectError: `step: Error a b 42 -step: Errorf a b 42`, }, "fatal": { cb: func(tCtx TContext) { @@ -48,7 +48,8 @@ step: Errorf a b 42`, // not reached tCtx.Log("Log") }, - expectError: `step: Error a b 42`, + expectTrace: `(FATAL) : FATAL ERROR: step: Error a b 42 +`, }, "fatalf": { cb: func(tCtx TContext) { @@ -57,7 +58,8 @@ step: Errorf a b 42`, // not reached tCtx.Log("Log") }, - expectError: `step: Error a b 42`, + expectTrace: `(FATAL) : FATAL ERROR: step: Error a b 42 +`, }, "progress": { cb: func(tCtx TContext) { @@ -76,12 +78,11 @@ step: Errorf a b 42`, noSuchValue := tCtx.Value("some other key") assert.Nil(tCtx, noSuchValue, "value for unknown context value key") }, - expectLog: `: step: You requested a progress report. + expectTrace: `(LOG) : step: You requested a progress report. step: hello world `, expectDuration: 5 * time.Second, - expectNoFail: true, }, } { tc := tc