upstream/kubernetes
1
0
Fork 0
mirror of https://github.com/kubernetes/kubernetes.git synced 2026-05-28 04:04:39 -04:00
Code Issues Projects Releases Packages Wiki Activity Actions

ktesting: rewrite unit testing with mock TB

Browse source 
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:

     <klog header>: 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.
This commit is contained in:
Patrick Ohly 2025-12-08 08:19:39 +01:00
parent 1a866b8795
commit 095475485f
3 changed files with 179 additions and 94 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

110
test/utils/ktesting/assert_test.go
View file

@ -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) <klog header>: FATAL ERROR:
Timed out after x.y s.
Expected
<int>: 0
to equal
<int>: 1`,
<int>: 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) <klog header>: 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) <klog header>: 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) <klog header>: 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) <klog header>: FATAL ERROR:
Failed after x.y s.
Expected
<float64>: 0
to equal
<float64>: 1`,
<float64>: 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) <klog header>: 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) <klog header>: 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) <klog header>: 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) <klog header>: FATAL ERROR:
Expected
<int>: 1
to equal
<int>: 42`,
<int>: 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: `<klog header>: Unexpected error:
expectTrace: `(LOG) <klog header>: Unexpected error:
<*errors.errorString | 0xXXXX>:
fake error
{s: "fake error"}
(FATAL) <klog header>: 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) <klog header>: 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) <klog header>: 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) <klog header>: 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) <klog header>: 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: `<klog header>: Failed at:
expectTrace: `(LOG) <klog header>: Failed at:
abc
xyz
(FATAL) <klog header>: 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: `<klog header>: testing error checking
<klog header>: Failed at:
expectTrace: `(LOG) <klog header>: testing error checking
(LOG) <klog header>: Failed at:
abc
xyz
(FATAL) <klog header>: 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: `<klog header>: Log a b 42
<klog header>: Logf a b 42
expectTrace: `(LOG) <klog header>: Log a b 42
(LOG) <klog header>: Logf a b 42
(ERROR) <klog header>: ERROR: Error a b 42
(ERROR) <klog header>: 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) <klog header>: 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) <klog header>: FATAL ERROR: Error a b 42
`,
},
} {
tc := tc

146
test/utils/ktesting/helper_test.go
View file

@ -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"
)

17
test/utils/ktesting/stepcontext_test.go
View file

@ -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: `<klog header>: step: Log a b 42
<klog header>: step: Logf a b 42
expectTrace: `(LOG) <klog header>: step: Log a b 42
(LOG) <klog header>: step: Logf a b 42
(ERROR) <klog header>: ERROR: step: Error a b 42
(ERROR) <klog header>: 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) <klog header>: 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) <klog header>: 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: `<klog header>: step: You requested a progress report.
expectTrace: `(LOG) <klog header>: step: You requested a progress report.
step: hello world
`,
expectDuration: 5 * time.Second,
expectNoFail: true,
},
} {
tc := tc