Merge pull request #123444 from pohly/test-context-expect-no-error

ktesting: several fixes and better unit testing
This commit is contained in:
Kubernetes Prow Robot 2024-02-26 20:05:40 -08:00 committed by GitHub
commit e457683e6c
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
10 changed files with 445 additions and 66 deletions

View File

@ -63,17 +63,23 @@ func expect(tCtx TContext, actual interface{}, extra ...interface{}) gomega.Asse
}
func expectNoError(tCtx TContext, err error, explain ...interface{}) {
if err == nil {
return
}
tCtx.Helper()
description := buildDescription(explain)
description := buildDescription(explain...)
var failure FailureError
if errors.As(err, &failure) {
if backtrace := failure.Backtrace(); backtrace != "" {
if description != "" {
tCtx.Log(description)
if errors.Is(err, ErrFailure) {
var failure FailureError
if errors.As(err, &failure) {
if backtrace := failure.Backtrace(); backtrace != "" {
if description != "" {
tCtx.Log(description)
}
tCtx.Logf("Failed at:\n %s", strings.ReplaceAll(backtrace, "\n", "\n "))
}
tCtx.Logf("Failed at:\n %s", strings.ReplaceAll(backtrace, "\n", "\n "))
}
if description != "" {
tCtx.Fatalf("%s: %s", description, err.Error())
@ -84,7 +90,7 @@ func expectNoError(tCtx TContext, err error, explain ...interface{}) {
if description == "" {
description = "Unexpected error"
}
tCtx.Logf("%s: %s\n%s", description, format.Object(err, 1))
tCtx.Logf("%s:\n%s", description, format.Object(err, 1))
tCtx.Fatalf("%s: %v", description, err.Error())
}
@ -112,17 +118,18 @@ func buildDescription(explain ...interface{}) string {
// is passed in. For example, errors can be checked with ExpectNoError:
//
// cb := func(func(tCtx ktesting.TContext) int {
// value, err := doSomething(...)
// ktesting.ExpectNoError(tCtx, err, "something failed")
// return value
// value, err := doSomething(...)
// tCtx.ExpectNoError(err, "something failed")
// assert(tCtx, 42, value, "the answer")
// return value
// }
// tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
//
// If there is no value, then an error can be returned:
//
// cb := func(func(tCtx ktesting.TContext) error {
// err := doSomething(...)
// return err
// err := doSomething(...)
// return err
// }
// tCtx.Eventually(cb).Should(gomega.Succeed(), "foobar should succeed")
//
@ -137,12 +144,21 @@ func buildDescription(explain ...interface{}) string {
// anymore, use [gomega.StopTrying]:
//
// cb := func(func(tCtx ktesting.TContext) int {
// value, err := doSomething(...)
// if errors.Is(err, SomeFinalErr) {
// gomega.StopTrying("permanent failure).Wrap(err).Now()
// }
// ktesting.ExpectNoError(tCtx, err, "something failed")
// return value
// value, err := doSomething(...)
// if errors.Is(err, SomeFinalErr) {
// // This message completely replaces the normal
// // failure message and thus should include all
// // relevant information.
// //
// // github.com/onsi/gomega/format is a good way
// // to format arbitrary data. It uses indention
// // and falls back to YAML for Kubernetes API
// // structs for readability.
// gomega.StopTrying("permanent failure, last value:\n%s", format.Object(value, 1 /* indent one level */)).
// Wrap(err).Now()
// }
// ktesting.ExpectNoError(tCtx, err, "something failed")
// return value
// }
// tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
//
@ -150,15 +166,15 @@ func buildDescription(explain ...interface{}) string {
// particularly useful in [Consistently] to ignore some intermittent error.
//
// cb := func(func(tCtx ktesting.TContext) int {
// value, err := doSomething(...)
// var intermittentErr SomeIntermittentError
// if errors.As(err, &intermittentErr) {
// gomega.TryAgainAfter(intermittentErr.RetryPeriod).Wrap(err).Now()
// }
// ktesting.ExpectNoError(tCtx, err, "something failed")
// return value
// }
// tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
// value, err := doSomething(...)
// var intermittentErr SomeIntermittentError
// if errors.As(err, &intermittentErr) {
// gomega.TryAgainAfter(intermittentErr.RetryPeriod).Wrap(err).Now()
// }
// ktesting.ExpectNoError(tCtx, err, "something failed")
// return value
// }
// tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
func Eventually[T any](tCtx TContext, cb func(TContext) T) gomega.AsyncAssertion {
tCtx.Helper()
return gomega.NewWithT(tCtx).Eventually(tCtx, func(ctx context.Context) (val T, err error) {

View File

@ -19,21 +19,14 @@ package ktesting
import (
"errors"
"fmt"
"regexp"
"testing"
"time"
"github.com/onsi/gomega"
"github.com/stretchr/testify/assert"
)
func TestAsync(t *testing.T) {
for name, tc := range map[string]struct {
cb func(TContext)
expectNoFail bool
expectError string
expectDuration time.Duration
}{
func TestAssert(t *testing.T) {
for name, tc := range map[string]testcase{
"eventually-timeout": {
cb: func(tCtx TContext) {
Eventually(tCtx, func(tCtx TContext) int {
@ -165,30 +158,114 @@ The function passed to Consistently returned the following error:
expectError: `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))
},
expectError: `Expected
<int>: 1
to equal
<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:
<*errors.errorString | 0xXXXX>:
fake error
{s: "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`,
},
"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`,
},
"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`,
},
"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`,
},
"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:
abc
xyz
`,
},
"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:
abc
xyz
`,
},
"output": {
cb: func(tCtx TContext) {
tCtx.Log("Log", "a", "b", 42)
tCtx.Logf("Logf %s %s %d", "a", "b", 42)
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
`,
expectError: `Error a b 42
Errorf a b 42`,
},
"fatal": {
cb: func(tCtx TContext) {
tCtx.Fatal("Error", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
expectError: `Error a b 42`,
},
"fatalf": {
cb: func(tCtx TContext) {
tCtx.Fatalf("Error %s %s %d", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
expectError: `Error a b 42`,
},
} {
tc := tc
t.Run(name, func(t *testing.T) {
t.Parallel()
tCtx := Init(t)
var err error
tCtx, finalize := WithError(tCtx, &err)
start := time.Now()
func() {
defer finalize()
tc.cb(tCtx)
}()
duration := time.Since(start)
assert.InDelta(t, tc.expectDuration.Seconds(), duration.Seconds(), 0.1, fmt.Sprintf("callback invocation duration %s", duration))
assert.Equal(t, !tc.expectNoFail, tCtx.Failed(), "Failed()")
if tc.expectError == "" {
assert.NoError(t, err)
} else if assert.NotNil(t, err) {
t.Logf("Result:\n%s", err.Error())
errMsg := err.Error()
errMsg = regexp.MustCompile(`[[:digit:]]+\.[[:digit:]]+s`).ReplaceAllString(errMsg, "x.y s")
errMsg = regexp.MustCompile(`0x[[:xdigit:]]+`).ReplaceAllString(errMsg, "0xXXXX")
assert.Equal(t, tc.expectError, errMsg)
}
tc.run(t)
})
}
}

View File

@ -22,6 +22,7 @@ import (
"strings"
"sync"
"github.com/onsi/gomega"
"k8s.io/klog/v2"
)
@ -138,6 +139,16 @@ func (eCtx *errorContext) CleanupCtx(cb func(TContext)) {
cleanupCtx(eCtx, cb)
}
func (eCtx *errorContext) Expect(actual interface{}, extra ...interface{}) gomega.Assertion {
eCtx.Helper()
return expect(eCtx, actual, extra...)
}
func (eCtx *errorContext) ExpectNoError(err error, explain ...interface{}) {
eCtx.Helper()
expectNoError(eCtx, err, explain...)
}
func (eCtx *errorContext) Logger() klog.Logger {
return klog.FromContext(eCtx)
}

View File

@ -0,0 +1,92 @@
/*
Copyright 2024 The Kubernetes Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/
package ktesting
import (
"fmt"
"regexp"
"strings"
"testing"
"time"
"github.com/stretchr/testify/assert"
)
// 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
}
func (tc testcase) run(t *testing.T) {
bufferT := &logBufferT{T: t}
tCtx := Init(bufferT)
var err error
tCtx, finalize := WithError(tCtx, &err)
start := time.Now()
func() {
defer finalize()
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)
assert.InDelta(t, tc.expectDuration.Seconds(), duration.Seconds(), 0.1, fmt.Sprintf("callback invocation duration %s", duration))
assert.Equal(t, !tc.expectNoFail, tCtx.Failed(), "Failed()")
if tc.expectError == "" {
assert.NoError(t, err)
} else if assert.NotNil(t, err) {
t.Logf("Result:\n%s", err.Error())
assert.Equal(t, tc.expectError, normalize(err.Error()))
}
}
// normalize replaces parts of message texts which may vary with constant strings.
func normalize(msg string) string {
// duration
msg = regexp.MustCompile(`[[:digit:]]+\.[[:digit:]]+s`).ReplaceAllString(msg, "x.y s")
// hex pointer value
msg = regexp.MustCompile(`0x[[:xdigit:]]+`).ReplaceAllString(msg, "0xXXXX")
// per-test klog header
msg = regexp.MustCompile(`[EI][[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\]`).ReplaceAllString(msg, "<klog header>:")
return msg
}
type logBufferT struct {
*testing.T
log strings.Builder
}
func (l *logBufferT) Log(args ...any) {
l.log.WriteString(fmt.Sprintln(args...))
}
func (l *logBufferT) Logf(format string, args ...any) {
l.log.WriteString(fmt.Sprintf(format, args...))
l.log.WriteRune('\n')
}

View File

@ -0,0 +1,45 @@
/*
Copyright 2024 The Kubernetes Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/
package ktesting
import (
"flag"
"fmt"
"os"
"testing"
"go.uber.org/goleak"
)
func TestMain(m *testing.M) {
// Bail out early when -help was given as parameter.
flag.Parse()
// Must be called *before* creating new goroutines.
goleakOpts := []goleak.Option{
goleak.IgnoreCurrent(),
}
result := m.Run()
if err := goleak.Find(goleakOpts...); err != nil {
fmt.Fprintf(os.Stderr, "leaked Goroutines: %v", err)
os.Exit(1)
}
os.Exit(result)
}

View File

@ -30,6 +30,7 @@ var (
interruptCtx context.Context
defaultProgressReporter = new(progressReporter)
defaultSignalChannel chan os.Signal
)
const ginkgoSpecContextKey = "GINKGO_SPEC_CONTEXT"
@ -57,25 +58,35 @@ func init() {
// probably cannot be in either Ginkgo or Gomega).
interruptCtx = context.WithValue(cancelCtx, ginkgoSpecContextKey, defaultProgressReporter)
signalChannel := make(chan os.Signal, 1)
defaultSignalChannel = make(chan os.Signal, 1)
// progressSignals will be empty on Windows.
if len(progressSignals) > 0 {
signal.Notify(signalChannel, progressSignals...)
signal.Notify(defaultSignalChannel, progressSignals...)
}
// os.Stderr gets redirected by "go test". "go test -v" has to be
// used to see the output while a test runs.
go defaultProgressReporter.run(interruptCtx, os.Stderr, signalChannel)
defaultProgressReporter.setOutput(os.Stderr)
go defaultProgressReporter.run(interruptCtx, defaultSignalChannel)
}
type progressReporter struct {
mutex sync.Mutex
reporterCounter int64
reporters map[int64]func() string
out io.Writer
}
var _ ginkgoReporter = &progressReporter{}
func (p *progressReporter) setOutput(out io.Writer) io.Writer {
p.mutex.Lock()
defer p.mutex.Unlock()
oldOut := p.out
p.out = out
return oldOut
}
// AttachProgressReporter implements Gomega's contextWithAttachProgressReporter.
func (p *progressReporter) AttachProgressReporter(reporter func() string) func() {
p.mutex.Lock()
@ -100,13 +111,13 @@ func (p *progressReporter) detachProgressReporter(id int64) {
delete(p.reporters, id)
}
func (p *progressReporter) run(ctx context.Context, out io.Writer, progressSignalChannel chan os.Signal) {
func (p *progressReporter) run(ctx context.Context, progressSignalChannel chan os.Signal) {
for {
select {
case <-ctx.Done():
return
case <-progressSignalChannel:
p.dumpProgress(out)
p.dumpProgress()
}
}
}
@ -117,7 +128,7 @@ func (p *progressReporter) run(ctx context.Context, out io.Writer, progressSigna
//
// But perhaps dumping goroutines and their callstacks is useful anyway? TODO:
// look at how Ginkgo does it and replicate some of it.
func (p *progressReporter) dumpProgress(out io.Writer) {
func (p *progressReporter) dumpProgress() {
p.mutex.Lock()
defer p.mutex.Unlock()
@ -135,5 +146,5 @@ func (p *progressReporter) dumpProgress(out io.Writer) {
}
}
_, _ = out.Write([]byte(buffer.String()))
_, _ = p.out.Write([]byte(buffer.String()))
}

View File

@ -76,7 +76,7 @@ func (sCtx *stepContext) Fatalf(format string, args ...any) {
sCtx.TContext.Fatal(sCtx.what + ": " + strings.TrimSpace(fmt.Sprintf(format, args...)))
}
// Value intercepts a search for the special
// Value intercepts a search for the special "GINKGO_SPEC_CONTEXT".
func (sCtx *stepContext) Value(key any) any {
if s, ok := key.(string); ok && s == ginkgoSpecContextKey {
if reporter, ok := sCtx.TContext.Value(key).(ginkgoReporter); ok {

View File

@ -0,0 +1,92 @@
/*
Copyright 2024 The Kubernetes Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/
package ktesting
import (
"bytes"
"os"
"testing"
"time"
"github.com/stretchr/testify/assert"
)
func TestStepContext(t *testing.T) {
for name, tc := range map[string]testcase{
"output": {
cb: func(tCtx TContext) {
tCtx = WithStep(tCtx, "step")
tCtx.Log("Log", "a", "b", 42)
tCtx.Logf("Logf %s %s %d", "a", "b", 42)
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
`,
expectError: `step: Error a b 42
step: Errorf a b 42`,
},
"fatal": {
cb: func(tCtx TContext) {
tCtx = WithStep(tCtx, "step")
tCtx.Fatal("Error", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
expectError: `step: Error a b 42`,
},
"fatalf": {
cb: func(tCtx TContext) {
tCtx = WithStep(tCtx, "step")
tCtx.Fatalf("Error %s %s %d", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
expectError: `step: Error a b 42`,
},
"progress": {
cb: func(tCtx TContext) {
tCtx = WithStep(tCtx, "step")
var buffer bytes.Buffer
oldOut := defaultProgressReporter.setOutput(&buffer)
defer defaultProgressReporter.setOutput(oldOut)
remove := tCtx.Value("GINKGO_SPEC_CONTEXT").(ginkgoReporter).AttachProgressReporter(func() string { return "hello world" })
defer remove()
defaultSignalChannel <- os.Interrupt
// No good way to sync here, so let's just wait.
time.Sleep(5 * time.Second)
defaultProgressReporter.setOutput(oldOut)
tCtx.Log(buffer.String())
noSuchValue := tCtx.Value("some other key")
assert.Equal(tCtx, nil, noSuchValue, "value for unknown context value key")
},
expectLog: `<klog header>: step: You requested a progress report.
step: hello world
`,
expectDuration: 5 * time.Second,
expectNoFail: true,
},
} {
tc := tc
t.Run(name, func(t *testing.T) {
tc.run(t)
})
}
}

View File

@ -35,6 +35,10 @@ import (
"k8s.io/kubernetes/test/utils/ktesting/internal"
)
// Underlier is the additional interface implemented by the per-test LogSink
// behind [TContext.Logger].
type Underlier = ktesting.Underlier
// CleanupGracePeriod is the time that a [TContext] gets canceled before the
// deadline of its underlying test suite (usually determined via "go test
// -timeout"). This gives the running test(s) time to fail with an informative
@ -79,7 +83,7 @@ type TContext interface {
Cancel(cause string)
// Cleanup registers a callback that will get invoked when the test
// has finished. Callbacks get invoked in first-in-first-out order.
// has finished. Callbacks get invoked in last-in-first-out order (LIFO).
//
// Beware of context cancellation. The following cleanup code
// will use a canceled context, which is not desirable:

View File

@ -22,7 +22,11 @@ import (
"github.com/stretchr/testify/assert"
apiextensions "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset"
"k8s.io/client-go/dynamic"
clientset "k8s.io/client-go/kubernetes"
"k8s.io/client-go/rest"
"k8s.io/client-go/restmapper"
"k8s.io/klog/v2"
"k8s.io/kubernetes/test/utils/ktesting"
)
@ -81,3 +85,30 @@ func TestCancelCtx(t *testing.T) {
// Cancel, then let testing.T invoke test cleanup.
tCtx.Cancel("test is complete")
}
func TestWithTB(t *testing.T) {
tCtx := ktesting.Init(t)
cfg := new(rest.Config)
mapper := new(restmapper.DeferredDiscoveryRESTMapper)
client := clientset.New(nil)
dynamic := dynamic.New(nil)
apiextensions := apiextensions.New(nil)
tCtx = ktesting.WithClients(tCtx, cfg, mapper, client, dynamic, apiextensions)
t.Run("sub", func(t *testing.T) {
tCtx := ktesting.WithTB(tCtx, t)
assert.Equal(t, cfg, tCtx.RESTConfig(), "RESTConfig")
assert.Equal(t, mapper, tCtx.RESTMapper(), "RESTMapper")
assert.Equal(t, client, tCtx.Client(), "Client")
assert.Equal(t, dynamic, tCtx.Dynamic(), "Dynamic")
assert.Equal(t, apiextensions, tCtx.APIExtensions(), "APIExtensions")
tCtx.Cancel("test is complete")
})
if err := tCtx.Err(); err != nil {
t.Errorf("parent TContext should not have been cancelled: %v", err)
}
}