From b3366ce8952daae4a69865134e3180825107cebc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 23 Jan 2023 09:37:36 +0100 Subject: [PATCH 01/18] e2e storage: remove WaitForPodTerminatedInNamespace Calling WaitForPodTerminatedInNamespace after testFlexVolume is useless because the client pod that it waits for always gets deleted by testVolumeClient: https://github.com/kubernetes/kubernetes/blob/0fcc3dbd55732c501d4948840f639e00a2fe33c5/test/e2e/framework/volume/fixtures.go#L541-L546 Worse, because WaitForPodTerminatedInNamespace treats "not found" as "must keep polling", these two tests always kept waiting for 5 minutes: Kubernetes e2e suite: [It] [sig-storage] Flexvolumes should be mountable when non-attachable 6m4s The only reason why these tests passed is that WaitForPodTerminatedInNamespace used to return the "not found" API error. That is not guaranteed and about to change. --- test/e2e/storage/flexvolume.go | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/test/e2e/storage/flexvolume.go b/test/e2e/storage/flexvolume.go index 0065c406eb3..ce5efba1597 100644 --- a/test/e2e/storage/flexvolume.go +++ b/test/e2e/storage/flexvolume.go @@ -26,7 +26,6 @@ import ( "github.com/onsi/ginkgo/v2" v1 "k8s.io/api/core/v1" - apierrors "k8s.io/apimachinery/pkg/api/errors" clientset "k8s.io/client-go/kubernetes" "k8s.io/kubernetes/test/e2e/framework" e2enode "k8s.io/kubernetes/test/e2e/framework/node" @@ -197,11 +196,6 @@ var _ = utils.SIGDescribe("Flexvolumes", func() { testFlexVolume(ctx, driverInstallAs, config, f) - ginkgo.By("waiting for flex client pod to terminate") - if err := e2epod.WaitForPodTerminatedInNamespace(ctx, f.ClientSet, config.Prefix+"-client", "", f.Namespace.Name); !apierrors.IsNotFound(err) { - framework.ExpectNoError(err, "Failed to wait client pod terminated: %v", err) - } - ginkgo.By(fmt.Sprintf("uninstalling flexvolume %s from node %s", driverInstallAs, node.Name)) uninstallFlex(ctx, cs, node, "k8s", driverInstallAs) }) @@ -217,11 +211,6 @@ var _ = utils.SIGDescribe("Flexvolumes", func() { testFlexVolume(ctx, driverInstallAs, config, f) - ginkgo.By("waiting for flex client pod to terminate") - if err := e2epod.WaitForPodTerminatedInNamespace(ctx, f.ClientSet, config.Prefix+"-client", "", f.Namespace.Name); !apierrors.IsNotFound(err) { - framework.ExpectNoError(err, "Failed to wait client pod terminated: %v", err) - } - // Detach might occur after pod deletion. Wait before deleting driver. time.Sleep(detachTimeout) From 0872e8d9272300b5a05b89488b3f5bcd65afb6b0 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 6 Jan 2023 20:41:43 +0100 Subject: [PATCH 02/18] e2e framework: gomega assertions as errors Calling gomega.Expect/Eventually/Consistently deep inside a helper call chain has several challenges: - the stack offset must be tracked correctly, otherwise the callstack for the failure starts at some helper code, which is often not informative - augmenting the failure message with additional information from each caller implies that each caller must pass down a string and/or format string plus arguments Both challenges can be solved by returning errors: - the stacktrace is taken at that level where the error is treated as a failure instead of passing back an error, i.e. inside the It callback - traditional error wrapping can add additional information, if desirable What was missing was some easy way to generate an error via a gomega assertion. The new infrastructure achieves that by mirroring the Gomega/Assertion/AsyncAssertion interfaces with errors as return values instead of calling a fail handler. It is intentionally less flexible than the gomega APIs: - A context must be passed to Eventually/Consistently as first parameter because that is needed for proper timeout handling. - No additional text can be added to the failure through this API because error wrapping is meant to be used for this. - No need to adjust the callstack offset because no backtrace is recorded when a failure occurs. To avoid the useless "unexpected error" log message when passing back a gomega failure, ExpectNoError gets extended to recognize such errors and then skips the logging. --- test/e2e/framework/expect.go | 206 +++++++++++++++++++++++++++++- test/e2e/framework/expect_test.go | 41 ++++++ 2 files changed, 246 insertions(+), 1 deletion(-) create mode 100644 test/e2e/framework/expect_test.go diff --git a/test/e2e/framework/expect.go b/test/e2e/framework/expect.go index 7b7fe7f416a..ed554cfdf5d 100644 --- a/test/e2e/framework/expect.go +++ b/test/e2e/framework/expect.go @@ -17,12 +17,211 @@ limitations under the License. package framework import ( + "context" + "errors" "fmt" + "time" "github.com/onsi/gomega" "github.com/onsi/gomega/format" + "github.com/onsi/gomega/types" ) +// Gomega returns an interface that can be used like gomega to express +// assertions. The difference is that failed assertions are returned as an +// error: +// +// if err := Gomega().Expect(pod.Status.Phase).To(gomega.BeEqual(v1.Running)); err != nil { +// return fmt.Errorf("test pod not running: %w", err) +// } +// +// This error can get wrapped to provide additional context for the +// failure. The test then should use ExpectNoError to turn a non-nil error into +// a failure. +// +// When using this approach, there is no need for call offsets and extra +// descriptions for the Expect call because the call stack will be dumped when +// ExpectNoError is called and the additional description(s) can be added by +// wrapping the error. +// +// Asynchronous assertions use the framework's Poll interval and PodStart timeout +// by default. +func Gomega() GomegaInstance { + return gomegaInstance{} +} + +type GomegaInstance interface { + Expect(actual interface{}) Assertion + Eventually(ctx context.Context, args ...interface{}) AsyncAssertion + Consistently(ctx context.Context, args ...interface{}) AsyncAssertion +} + +type Assertion interface { + Should(matcher types.GomegaMatcher) error + ShouldNot(matcher types.GomegaMatcher) error + To(matcher types.GomegaMatcher) error + ToNot(matcher types.GomegaMatcher) error + NotTo(matcher types.GomegaMatcher) error +} + +type AsyncAssertion interface { + Should(matcher types.GomegaMatcher) error + ShouldNot(matcher types.GomegaMatcher) error + + WithTimeout(interval time.Duration) AsyncAssertion + WithPolling(interval time.Duration) AsyncAssertion +} + +type gomegaInstance struct{} + +var _ GomegaInstance = gomegaInstance{} + +func (g gomegaInstance) Expect(actual interface{}) Assertion { + return assertion{actual: actual} +} + +func (g gomegaInstance) Eventually(ctx context.Context, args ...interface{}) AsyncAssertion { + return newAsyncAssertion(ctx, args, false) +} + +func (g gomegaInstance) Consistently(ctx context.Context, args ...interface{}) AsyncAssertion { + return newAsyncAssertion(ctx, args, true) +} + +func newG() (*FailureError, gomega.Gomega) { + var failure FailureError + g := gomega.NewGomega(func(msg string, callerSkip ...int) { + failure = FailureError(msg) + }) + + return &failure, g +} + +type assertion struct { + actual interface{} +} + +func (a assertion) Should(matcher types.GomegaMatcher) error { + err, g := newG() + if !g.Expect(a.actual).Should(matcher) { + return *err + } + return nil +} + +func (a assertion) ShouldNot(matcher types.GomegaMatcher) error { + err, g := newG() + if !g.Expect(a.actual).ShouldNot(matcher) { + return *err + } + return nil +} + +func (a assertion) To(matcher types.GomegaMatcher) error { + err, g := newG() + if !g.Expect(a.actual).To(matcher) { + return *err + } + return nil +} + +func (a assertion) ToNot(matcher types.GomegaMatcher) error { + err, g := newG() + if !g.Expect(a.actual).ToNot(matcher) { + return *err + } + return nil +} + +func (a assertion) NotTo(matcher types.GomegaMatcher) error { + err, g := newG() + if !g.Expect(a.actual).NotTo(matcher) { + return *err + } + return nil +} + +type asyncAssertion struct { + ctx context.Context + args []interface{} + timeout time.Duration + interval time.Duration + consistently bool +} + +func newAsyncAssertion(ctx context.Context, args []interface{}, consistently bool) asyncAssertion { + return asyncAssertion{ + ctx: ctx, + args: args, + // PodStart is used as default because waiting for a pod is the + // most common operation. + timeout: TestContext.timeouts.PodStart, + interval: TestContext.timeouts.Poll, + } +} + +func (a asyncAssertion) newAsync() (*FailureError, gomega.AsyncAssertion) { + err, g := newG() + var assertion gomega.AsyncAssertion + if a.consistently { + assertion = g.Consistently(a.ctx, a.args...) + } else { + assertion = g.Eventually(a.ctx, a.args...) + } + assertion = assertion.WithTimeout(a.timeout).WithPolling(a.interval) + return err, assertion +} + +func (a asyncAssertion) Should(matcher types.GomegaMatcher) error { + err, assertion := a.newAsync() + if !assertion.Should(matcher) { + return *err + } + return nil +} + +func (a asyncAssertion) ShouldNot(matcher types.GomegaMatcher) error { + err, assertion := a.newAsync() + if !assertion.ShouldNot(matcher) { + return *err + } + return nil +} + +func (a asyncAssertion) WithTimeout(timeout time.Duration) AsyncAssertion { + a.timeout = timeout + return a +} + +func (a asyncAssertion) WithPolling(interval time.Duration) AsyncAssertion { + a.interval = interval + return a +} + +// FailureError is an error where the error string is meant to be passed to +// ginkgo.Fail directly, i.e. adding some prefix like "unexpected error" is not +// necessary. It is also not necessary to dump the error struct. +type FailureError string + +func (f FailureError) Error() string { + return string(f) +} + +func (f FailureError) Is(target error) bool { + return target == ErrFailure +} + +// ErrFailure is an empty error that can be wrapped to indicate that an error +// is a FailureError. It can also be used to test for a FailureError:. +// +// return fmt.Errorf("some problem%w", ErrFailure) +// ... +// err := someOperation() +// if errors.Is(err, ErrFailure) { +// ... +// } +var ErrFailure error = FailureError("") + // ExpectEqual expects the specified two are the same, otherwise an exception raises func ExpectEqual(actual interface{}, extra interface{}, explain ...interface{}) { gomega.ExpectWithOffset(1, actual).To(gomega.Equal(extra), explain...) @@ -72,7 +271,12 @@ func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) { // failures at the same code line might not be matched in // https://go.k8s.io/triage because the error details are too // different. - Logf("Unexpected error: %s\n%s", prefix, format.Object(err, 1)) + // + // Some errors include all relevant information in the Error + // string. For those we can skip the redundant log message. + if !errors.Is(err, ErrFailure) { + Logf("Unexpected error: %s\n%s", prefix, format.Object(err, 1)) + } Fail(prefix+err.Error(), 1+offset) } diff --git a/test/e2e/framework/expect_test.go b/test/e2e/framework/expect_test.go new file mode 100644 index 00000000000..4d2f6f4feab --- /dev/null +++ b/test/e2e/framework/expect_test.go @@ -0,0 +1,41 @@ +/* +Copyright 2023 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 framework + +import ( + "errors" + "testing" + + "github.com/onsi/gomega" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestNewGomega(t *testing.T) { + if err := Gomega().Expect("hello").To(gomega.Equal("hello")); err != nil { + t.Errorf("unexpected failure: %s", err.Error()) + } + err := Gomega().Expect("hello").ToNot(gomega.Equal("hello")) + require.NotNil(t, err) + assert.Equal(t, `Expected + : hello +not to equal + : hello`, err.Error()) + if !errors.Is(err, ErrFailure) { + t.Errorf("expected error that is ErrFailure, got %T: %+v", err, err) + } +} From e8a50b0583bb554ac4d32e6793761bb7d8a7be55 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 24 Oct 2022 08:24:55 +0200 Subject: [PATCH 03/18] e2e framework: implement pod polling with gomega.Eventually gomega.Eventually provides better progress reports: instead of filling up the log with rather useless one-line messages that are not enough to to understand the current state, it integrates with Gingko's progress reporting (SIGUSR1, --poll-progress-after) and then dumps the same complete failure message as after a timeout. That makes it possible to understand why progress isn't getting made without having to wait for the timeout. The other advantage is that the failure message for some unexpected pod state becomes more readable: instead of encapsulating it as "observed object" inside an error, it directly gets rendered by gomega. --- test/e2e/framework/internal/output/output.go | 4 + test/e2e/framework/pod/wait.go | 16 +- test/e2e/framework/pod/wait_test.go | 377 +++++++++++-------- 3 files changed, 230 insertions(+), 167 deletions(-) diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go index cc26c079677..053c36012a7 100644 --- a/test/e2e/framework/internal/output/output.go +++ b/test/e2e/framework/internal/output/output.go @@ -122,6 +122,9 @@ var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} +[[:digit:]]{1,2} +[[:d // elapsedSuffix matches "Elapsed: 16.189µs" var elapsedSuffix = regexp.MustCompile(`Elapsed: [[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)`) +// afterSuffix matches "after 5.001s." +var afterSuffix = regexp.MustCompile(`after [[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m).`) + // timeSuffix matches "@ 09/06/22 15:36:43.44 (5.001s)" as printed by Ginkgo v2 for log output, with the duration being optional. var timeSuffix = regexp.MustCompile(`(?m)@[[:space:]][[:digit:]]{2}/[[:digit:]]{2}/[[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}(\.[[:digit:]]{1,3})?( \([[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)\))?$`) @@ -129,6 +132,7 @@ func stripTimes(in string) string { out := timePrefix.ReplaceAllString(in, "") out = elapsedSuffix.ReplaceAllString(out, "Elapsed: ") out = timeSuffix.ReplaceAllString(out, "