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

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

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())
+	}
 }

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 <time>
 `,
 					},
 					SystemErr: `> Enter [It] not found, retry - wait_test.go:57 <time>
+INFO: Failed inside E2E framework:
+    k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
+    	wait.go
+    k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
+    	wait_test.go:58
 [FAILED] Timed out after <after>.
 The function passed to Eventually returned the following error:
 pods "no-such-pod" not found
@@ -308,6 +316,11 @@ In [It] at: wait_test.go:71 <time>
 					},
 					SystemErr: `> Enter [It] not running - wait_test.go:69 <time>
 STEP: waiting for pod pending-pod to run - wait_test.go:70 <time>
+INFO: Failed inside E2E framework:
+    k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
+    	wait.go
+    k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.5()
+    	wait_test.go:71
 [FAILED] Timed out after <after>.
 Expected Pod to be in <v1.PodPhase>: "Running"
 Got instead:
@@ -335,6 +348,11 @@ In [It] at: wait_test.go:75 <time>
 						Type: "failed",
 					},
 					SystemErr: `> Enter [It] failed - wait_test.go:74 <time>
+INFO: Failed inside E2E framework:
+    k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
+    	wait.go
+    k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.6()
+    	wait_test.go:75
 [FAILED] Told to stop trying after <after>.
 Expected pod to reach phase "Running", got final phase "Failed" instead.
 In [It] at: wait_test.go:75 <time>