From 8181f97eccab7d8dd5d611606b5e49359c09237f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 19 Jan 2023 12:57:25 +0100 Subject: [PATCH] e2e framework: include additional stack backtrace in failures When a Gomega failure is converted to an error, the stack at the time when the failure occurs may be useful: error wrapping provides some bread crumbs that can be followed to determine where the failure really occurred, but error wrapping may be missing or ambiguous. To provide the additional information, a FailureError now includes a full stack backtrace. The backtrace intentionally makes no attempt to exclude framework functions besides the gomega support itself because helpers like e2e/framework/pod may be relevant. That backtrace is not included in the failure message for the sake of brevity. Instead, it gets logged as part of the test's output. --- test/e2e/framework/expect.go | 37 +++++++++++++++++++++++++---- test/e2e/framework/expect_test.go | 21 ++++++++++++++++ test/e2e/framework/pod/wait_test.go | 20 +++++++++++++++- 3 files changed, 72 insertions(+), 6 deletions(-) diff --git a/test/e2e/framework/expect.go b/test/e2e/framework/expect.go index ed554cfdf5d..21f1b24af38 100644 --- a/test/e2e/framework/expect.go +++ b/test/e2e/framework/expect.go @@ -20,8 +20,10 @@ import ( "context" "errors" "fmt" + "strings" "time" + ginkgotypes "github.com/onsi/ginkgo/v2/types" "github.com/onsi/gomega" "github.com/onsi/gomega/format" "github.com/onsi/gomega/types" @@ -91,7 +93,9 @@ func (g gomegaInstance) Consistently(ctx context.Context, args ...interface{}) A func newG() (*FailureError, gomega.Gomega) { var failure FailureError g := gomega.NewGomega(func(msg string, callerSkip ...int) { - failure = FailureError(msg) + failure = FailureError{ + msg: msg, + } }) return &failure, g @@ -104,6 +108,7 @@ type assertion struct { func (a assertion) Should(matcher types.GomegaMatcher) error { err, g := newG() if !g.Expect(a.actual).Should(matcher) { + err.backtrace() return *err } return nil @@ -112,6 +117,7 @@ func (a assertion) Should(matcher types.GomegaMatcher) error { func (a assertion) ShouldNot(matcher types.GomegaMatcher) error { err, g := newG() if !g.Expect(a.actual).ShouldNot(matcher) { + err.backtrace() return *err } return nil @@ -120,6 +126,7 @@ func (a assertion) ShouldNot(matcher types.GomegaMatcher) error { func (a assertion) To(matcher types.GomegaMatcher) error { err, g := newG() if !g.Expect(a.actual).To(matcher) { + err.backtrace() return *err } return nil @@ -128,6 +135,7 @@ func (a assertion) To(matcher types.GomegaMatcher) error { func (a assertion) ToNot(matcher types.GomegaMatcher) error { err, g := newG() if !g.Expect(a.actual).ToNot(matcher) { + err.backtrace() return *err } return nil @@ -136,6 +144,7 @@ func (a assertion) ToNot(matcher types.GomegaMatcher) error { func (a assertion) NotTo(matcher types.GomegaMatcher) error { err, g := newG() if !g.Expect(a.actual).NotTo(matcher) { + err.backtrace() return *err } return nil @@ -175,6 +184,7 @@ func (a asyncAssertion) newAsync() (*FailureError, gomega.AsyncAssertion) { func (a asyncAssertion) Should(matcher types.GomegaMatcher) error { err, assertion := a.newAsync() if !assertion.Should(matcher) { + err.backtrace() return *err } return nil @@ -183,6 +193,7 @@ func (a asyncAssertion) Should(matcher types.GomegaMatcher) error { func (a asyncAssertion) ShouldNot(matcher types.GomegaMatcher) error { err, assertion := a.newAsync() if !assertion.ShouldNot(matcher) { + err.backtrace() return *err } return nil @@ -201,16 +212,27 @@ func (a asyncAssertion) WithPolling(interval time.Duration) AsyncAssertion { // 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 +type FailureError struct { + msg string + fullStackTrace string +} func (f FailureError) Error() string { - return string(f) + return f.msg +} + +func (f FailureError) Backtrace() string { + return f.fullStackTrace } func (f FailureError) Is(target error) bool { return target == ErrFailure } +func (f *FailureError) backtrace() { + f.fullStackTrace = ginkgotypes.NewCodeLocationWithStackTrace(2).FullStackTrace +} + // 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:. // @@ -220,7 +242,7 @@ func (f FailureError) Is(target error) bool { // if errors.Is(err, ErrFailure) { // ... // } -var ErrFailure error = FailureError("") +var ErrFailure error = FailureError{} // ExpectEqual expects the specified two are the same, otherwise an exception raises func ExpectEqual(actual interface{}, extra interface{}, explain ...interface{}) { @@ -274,7 +296,12 @@ func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) { // // Some errors include all relevant information in the Error // string. For those we can skip the redundant log message. - if !errors.Is(err, ErrFailure) { + // For our own failures we only log the additional stack backtrace + // because it is not included in the failure message. + var failure FailureError + if errors.As(err, &failure) && failure.Backtrace() != "" { + Logf("Failed inside E2E framework:\n %s", strings.ReplaceAll(failure.Backtrace(), "\n", "\n ")) + } else 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 index 4d2f6f4feab..c64980fd128 100644 --- a/test/e2e/framework/expect_test.go +++ b/test/e2e/framework/expect_test.go @@ -25,6 +25,20 @@ import ( "github.com/stretchr/testify/require" ) +// This test is sensitive to line numbering. +// The following lines can be removed to compensate for import changes. +// +// +// +// +// +// +// +// +// +// +// This must be line #40. + func TestNewGomega(t *testing.T) { if err := Gomega().Expect("hello").To(gomega.Equal("hello")); err != nil { t.Errorf("unexpected failure: %s", err.Error()) @@ -38,4 +52,11 @@ not to equal if !errors.Is(err, ErrFailure) { t.Errorf("expected error that is ErrFailure, got %T: %+v", err, err) } + var failure FailureError + if !errors.As(err, &failure) { + t.Errorf("expected error that can be copied to FailureError, got %T: %+v", err, err) + } else { + assert.Regexp(t, `^k8s.io/kubernetes/test/e2e/framework.TestNewGomega\(0x[0-9A-Fa-f]*\) + .*/test/e2e/framework/expect_test.go:46`, failure.Backtrace()) + } } diff --git a/test/e2e/framework/pod/wait_test.go b/test/e2e/framework/pod/wait_test.go index a455460fe11..c091e3e69c3 100644 --- a/test/e2e/framework/pod/wait_test.go +++ b/test/e2e/framework/pod/wait_test.go @@ -19,6 +19,7 @@ package pod_test import ( "context" "fmt" + "regexp" "testing" "time" @@ -46,7 +47,6 @@ import ( // // // -// // This must be line #50. var _ = ginkgo.Describe("pod", func() { @@ -97,6 +97,9 @@ var ( func TestFailureOutput(t *testing.T) { expected := output.TestResult{ + NormalizeOutput: func(in string) string { + return regexp.MustCompile(`wait.go:[[:digit:]]*`).ReplaceAllString(in, `wait.go`) + }, Suite: reporters.JUnitTestSuite{ Tests: 6, Failures: 6, @@ -151,6 +154,11 @@ In [It] at: wait_test.go:58