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