e2e: make failure message for unexpected errors more readable

The failure message from Gomega was hard to read because explanation and error
text were separated by the error dump. In many cases, that error dump doesn't
add any relevant information.

Now the error is dumped first as info message (just in case that it is
relevant) and then a shorter failure message is created from explanation and
error text.

test/e2e/framework/expect.go

@@ -17,7 +17,10 @@ limitations under the License.
 package framework
 
 import (
+	"fmt"
+
 	"github.com/onsi/gomega"
+	"github.com/onsi/gomega/format"
 )
 
 // ExpectEqual expects the specified two are the same, otherwise an exception raises
@@ -43,7 +46,34 @@ func ExpectNoError(err error, explain ...interface{}) {
 // ExpectNoErrorWithOffset checks if "err" is set, and if so, fails assertion while logging the error at "offset" levels above its caller
 // (for example, for call chain f -> g -> ExpectNoErrorWithOffset(1, ...) error would be logged for "f").
 func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) {
-	gomega.ExpectWithOffset(1+offset, err).NotTo(gomega.HaveOccurred(), explain...)
+	if err == nil {
+		return
+	}
+
+	// Errors usually contain unexported fields. We have to use
+	// a formatter here which can print those.
+	prefix := ""
+	if len(explain) > 0 {
+		if str, ok := explain[0].(string); ok {
+			prefix = fmt.Sprintf(str, explain[1:]...) + ": "
+		} else {
+			prefix = fmt.Sprintf("unexpected explain arguments, need format string: %v", explain)
+		}
+	}
+
+	// This intentionally doesn't use gomega.Expect. Instead we take
+	// full control over what information is presented where:
+	// - The complete error object is logged because it may contain
+	//   additional information that isn't included in its error
+	//   string.
+	// - It is not included in the failure message because
+	//   it might make the failure message very large and/or
+	//   cause error aggregation to work less well: two
+	//   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))
+	Fail(prefix+err.Error(), 1+offset)
 }
 
 // ExpectConsistOf expects actual contains precisely the extra elements.  The ordering of the elements does not matter.

test/e2e/framework/log_test.go

@@ -146,26 +146,18 @@ k8s.io/kubernetes/test/e2e/framework_test.runTests()
 		output.TestResult{
 			Name: "[Top Level] log error",
 			Output: `INFO: before
-FAIL: hard-coded error
+INFO: Unexpected error: hard-coded error: 
-Unexpected error:
     <*errors.errorString>: {
         s: "an error with a long, useless description",
     }
-    an error with a long, useless description
+FAIL: hard-coded error: an error with a long, useless description
-occurred
 
 Full Stack Trace
 k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4()
 	log_test.go:64
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47` + commonOutput,
-			Failure: `hard-coded error
+			Failure: `hard-coded error: an error with a long, useless description`,
-Unexpected error:
-    <*errors.errorString>: {
-        s: "an error with a long, useless description",
-    }
-    an error with a long, useless description
-occurred`,
 			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4()
 	log_test.go:64
 k8s.io/kubernetes/test/e2e/framework_test.runTests()

test/e2e/framework/pod/wait_test.go

@@ -53,11 +53,11 @@ func runTests(t *testing.T, reporter ginkgo.Reporter) {
 
 var _ = ginkgo.Describe("pod", func() {
 	ginkgo.It("not found", func() {
-		framework.ExpectNoError(e2epod.WaitTimeoutForPodRunningInNamespace(clientSet, "no-such-pod", "default", timeout), "wait for pod running")
+		framework.ExpectNoError(e2epod.WaitTimeoutForPodRunningInNamespace(clientSet, "no-such-pod", "default", timeout /* no explanation here to cover that code path */))
 	})
 
 	ginkgo.It("not running", func() {
-		framework.ExpectNoError(e2epod.WaitTimeoutForPodRunningInNamespace(clientSet, podName, podNamespace, timeout), "wait for pod running")
+		framework.ExpectNoError(e2epod.WaitTimeoutForPodRunningInNamespace(clientSet, podName, podNamespace, timeout), "wait for pod %s running", podName /* tests printf formatting */)
 	})
 })
 
@@ -82,8 +82,7 @@ INFO: Ignoring NotFound error while getting pod default/no-such-pod
 INFO: Ignoring NotFound error while getting pod default/no-such-pod
 INFO: Ignoring NotFound error while getting pod default/no-such-pod
 INFO: Timed out while waiting for pod default/no-such-pod to be running. Last observed as:     <*v1.Pod>: nil
-FAIL: wait for pod running
+INFO: Unexpected error: 
-Unexpected error:
     <*fmt.wrapError>: {
         msg: "error while waiting for pod default/no-such-pod to be running: pods \"no-such-pod\" not found",
         err: {
@@ -103,8 +102,7 @@ Unexpected error:
             },
         },
     }
-    error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
+FAIL: error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
-occurred
 
 Full Stack Trace
 k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.1()
@@ -113,29 +111,7 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()
 	wait_test.go:51
 
 `,
-			Failure: `wait for pod running
+			Failure: `error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found`,
-Unexpected error:
-    <*fmt.wrapError>: {
-        msg: "error while waiting for pod default/no-such-pod to be running: pods \"no-such-pod\" not found",
-        err: {
-            ErrStatus: {
-                TypeMeta: {Kind: "", APIVersion: ""},
-                ListMeta: {
-                    SelfLink: "",
-                    ResourceVersion: "",
-                    Continue: "",
-                    RemainingItemCount: nil,
-                },
-                Status: "Failure",
-                Message: "pods \"no-such-pod\" not found",
-                Reason: "NotFound",
-                Details: {Name: "no-such-pod", Group: "", Kind: "pods", UID: "", Causes: nil, RetryAfterSeconds: 0},
-                Code: 404,
-            },
-        },
-    }
-    error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
-occurred`,
 			Stack: `k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.1()
 	wait_test.go:56
 k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()
@@ -224,13 +200,11 @@ INFO: Timed out while waiting for pod default/pending-pod to be running. Last ob
             EphemeralContainerStatuses: nil,
         },
     }
-FAIL: wait for pod running
+INFO: Unexpected error: wait for pod pending-pod running: 
-Unexpected error:
     <*pod.timeoutError>: {
         msg: "timed out while waiting for pod default/pending-pod to be running",
     }
-    timed out while waiting for pod default/pending-pod to be running
+FAIL: wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running
-occurred
 
 Full Stack Trace
 k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
@@ -239,13 +213,7 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()
 	wait_test.go:51
 
 `,
-			Failure: `wait for pod running
+			Failure: `wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running`,
-Unexpected error:
-    <*pod.timeoutError>: {
-        msg: "timed out while waiting for pod default/pending-pod to be running",
-    }
-    timed out while waiting for pod default/pending-pod to be running
-occurred`,
 			Stack: `k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
 	wait_test.go:60
 k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()