Merge pull request #109828 from pohly/polling-failures

[E2E] enhance pod polling failures

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/internal/output/output.go

@@ -0,0 +1,143 @@
+/*
+Copyright 2022 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 output
+
+import (
+	"regexp"
+	"sort"
+	"strings"
+	"testing"
+
+	"github.com/onsi/ginkgo"
+	"github.com/onsi/ginkgo/config"
+	"github.com/onsi/ginkgo/reporters"
+	"github.com/onsi/gomega"
+	"github.com/stretchr/testify/assert"
+
+	"k8s.io/kubernetes/test/e2e/framework"
+)
+
+func TestGinkgoOutput(t *testing.T, runTests func(t *testing.T, reporter ginkgo.Reporter), expected SuiteResults) {
+	// Run the Ginkgo suite with output collected by a custom
+	// reporter in adddition to the default one. To see what the full
+	// Ginkgo report looks like, run this test with "go test -v".
+	config.DefaultReporterConfig.FullTrace = true
+	gomega.RegisterFailHandler(framework.Fail)
+	fakeT := &testing.T{}
+	reporter := reporters.NewFakeReporter()
+	runTests(fakeT, reporter)
+
+	// Now check the output.
+	actual := normalizeReport(*reporter)
+
+	if assert.Equal(t, len(expected), len(actual), "Should have %d test results, got: %v", actual) {
+		for i := 0; i < len(expected); i++ {
+			output := actual[i].Output
+			if expected[i].NormalizeOutput != nil {
+				output = expected[i].NormalizeOutput(output)
+			}
+			assert.Equal(t, expected[i].Output, output, "output from test #%d (%s)", i, expected[i].Name)
+			assert.Equal(t, expected[i].Stack, actual[i].Stack, "stack from test #%d (%s)", i, expected[i].Name)
+			failure := actual[i].Failure
+			if expected[i].NormalizeFailure != nil {
+				failure = expected[i].NormalizeFailure(failure)
+			}
+			assert.Equal(t, expected[i].Failure, failure, "failure from test #%d (%s)", i, expected[i].Name)
+		}
+	}
+}
+
+// TestResult is the outcome of one It spec.
+type TestResult struct {
+	// Name is the full string for a Ginkgo It, including the "[Top Level]" prefix.
+	Name string
+	// Output written to GinkgoWriter during test.
+	Output string
+	// Failure is SpecSummary.Failure.Message with varying parts stripped.
+	Failure string
+	// Stack is a normalized version (just file names, function parametes stripped) of
+	// Ginkgo's FullStackTrace of a failure. Empty if no failure.
+	Stack string
+	// Called to normalize the actual output string before comparison if non-nil.
+	NormalizeOutput func(string) string
+	// Called to normalize the actual failure string before comparison if non-nil.
+	NormalizeFailure func(string) string
+}
+
+type SuiteResults []TestResult
+
+func normalizeReport(report reporters.FakeReporter) SuiteResults {
+	var results SuiteResults
+	for _, spec := range report.SpecSummaries {
+		results = append(results, TestResult{
+			Name:    strings.Join(spec.ComponentTexts, " "),
+			Output:  normalizeLocation(stripAddresses(stripTimes(spec.CapturedOutput))),
+			Failure: stripAddresses(stripTimes(spec.Failure.Message)),
+			Stack:   normalizeLocation(spec.Failure.Location.FullStackTrace),
+		})
+	}
+	sort.Slice(results, func(i, j int) bool {
+		return strings.Compare(results[i].Name, results[j].Name) < 0
+	})
+	return results
+}
+
+// timePrefix matches "Jul 17 08:08:25.950: " at the beginning of each line.
+var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} +[[:digit:]]{1,2} +[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}.[[:digit:]]{3}: `)
+
+// elapsedSuffix matches "Elapsed: 16.189µs"
+var elapsedSuffix = regexp.MustCompile(`Elapsed: [[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)`)
+
+func stripTimes(in string) string {
+	out := timePrefix.ReplaceAllString(in, "")
+	out = elapsedSuffix.ReplaceAllString(out, "Elapsed: <elapsed>")
+	return out
+}
+
+// instanceAddr matches " | 0xc0003dec60>"
+var instanceAddr = regexp.MustCompile(` \| 0x[0-9a-fA-F]+>`)
+
+func stripAddresses(in string) string {
+	return instanceAddr.ReplaceAllString(in, ">")
+}
+
+// stackLocation matches "<some path>/<file>.go:75 +0x1f1" after a slash (built
+// locally) or one of a few relative paths (built in the Kubernetes CI).
+var stackLocation = regexp.MustCompile(`(?:/|vendor/|test/|GOROOT/).*/([[:^space:]]+.go:[[:digit:]]+)( \+0x[0-9a-fA-F]+)?`)
+
+// functionArgs matches "<function name>(...)".
+var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`)
+
+// testFailureOutput matches TestFailureOutput() and its source followed by additional stack entries:
+//
+// k8s.io/kubernetes/test/e2e/framework/pod/pod_test.TestFailureOutput(0xc000558800)
+//	/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/pod/wait_test.go:73 +0x1c9
+// testing.tRunner(0xc000558800, 0x1af2848)
+// 	/nvme/gopath/go/src/testing/testing.go:865 +0xc0
+// created by testing.(*T).Run
+//	/nvme/gopath/go/src/testing/testing.go:916 +0x35a
+var testFailureOutput = regexp.MustCompile(`(?m)^k8s.io/kubernetes/test/e2e/framework/internal/output\.TestGinkgoOutput\(.*\n\t.*(\n.*\n\t.*)*`)
+
+// normalizeLocation removes path prefix and function parameters and certain stack entries
+// that we don't care about.
+func normalizeLocation(in string) string {
+	out := in
+	out = stackLocation.ReplaceAllString(out, "$1")
+	out = functionArgs.ReplaceAllString(out, "$1()")
+	out = testFailureOutput.ReplaceAllString(out, "")
+	return out
+}

test/e2e/framework/log_test.go

@@ -18,18 +18,12 @@ package framework_test
 
 import (
 	"errors"
-	"regexp"
-	"sort"
-	"strings"
 	"testing"
 
 	"github.com/onsi/ginkgo"
-	"github.com/onsi/ginkgo/config"
-	"github.com/onsi/ginkgo/reporters"
-	"github.com/onsi/gomega"
-	"github.com/stretchr/testify/assert"
 
 	"k8s.io/kubernetes/test/e2e/framework"
+	"k8s.io/kubernetes/test/e2e/framework/internal/output"
 )
 
 // The line number of the following code is checked in TestFailureOutput below.
@@ -41,6 +35,12 @@ import (
 //
 //
 //
+//
+//
+//
+//
+//
+// This must be line #43.
 
 func runTests(t *testing.T, reporter ginkgo.Reporter) {
 	// This source code line will be part of the stack dump comparison.
@@ -73,18 +73,6 @@ var _ = ginkgo.Describe("log", func() {
 })
 
 func TestFailureOutput(t *testing.T) {
-	// Run the Ginkgo suite with output collected by a custom
-	// reporter in adddition to the default one. To see what the full
-	// Ginkgo report looks like, run this test with "go test -v".
-	config.DefaultReporterConfig.FullTrace = true
-	gomega.RegisterFailHandler(framework.Fail)
-	fakeT := &testing.T{}
-	reporter := reporters.NewFakeReporter()
-	runTests(fakeT, reporter)
-
-	// Now check the output.
-	actual := normalizeReport(*reporter)
-
 	// output from AfterEach
 	commonOutput := `
 
@@ -104,10 +92,10 @@ k8s.io/kubernetes/test/e2e/framework_test.runTests()
 `
 
 	// Sorted by name!
-	expected := suiteResults{
+	expected := output.SuiteResults{
-		testResult{
+		output.TestResult{
-			name: "[Top Level] log asserts",
+			Name: "[Top Level] log asserts",
-			output: `INFO: before
+			Output: `INFO: before
 FAIL: false is never true
 Expected
     <bool>: false
@@ -119,20 +107,20 @@ k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()
 	log_test.go:60
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47` + commonOutput,
-			failure: `false is never true
+			Failure: `false is never true
 Expected
     <bool>: false
 to equal
     <bool>: true`,
-			stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()
+			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()
 	log_test.go:60
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47
 `,
 		},
-		testResult{
+		output.TestResult{
-			name: "[Top Level] log equal",
+			Name: "[Top Level] log equal",
-			output: `INFO: before
+			Output: `INFO: before
 FAIL: of course it's not equal...
 Expected
     <int>: 0
@@ -144,49 +132,41 @@ k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5()
 	log_test.go:67
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47` + commonOutput,
-			failure: `of course it's not equal...
+			Failure: `of course it's not equal...
 Expected
     <int>: 0
 to equal
     <int>: 1`,
-			stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5()
+			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5()
 	log_test.go:67
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47
 `,
 		},
-		testResult{
+		output.TestResult{
-			name: "[Top Level] log error",
+			Name: "[Top Level] log error",
-			output: `INFO: before
+			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:
+			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4()
-    <*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()
 	log_test.go:47
 `,
 		},
-		testResult{
+		output.TestResult{
-			name: "[Top Level] log fails",
+			Name: "[Top Level] log fails",
-			output: `INFO: before
+			Output: `INFO: before
 FAIL: I'm failing.
 
 Full Stack Trace
@@ -194,91 +174,14 @@ k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()
 	log_test.go:57
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47` + commonOutput,
-			failure: "I'm failing.",
+			Failure: "I'm failing.",
-			stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()
+			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()
 	log_test.go:57
 k8s.io/kubernetes/test/e2e/framework_test.runTests()
 	log_test.go:47
 `,
 		},
 	}
-	// assert.Equal prints a useful diff if the slices are not
+
-	// equal. However, the diff does not show changes inside the
+	output.TestGinkgoOutput(t, runTests, expected)
-	// strings. Therefore we also compare the individual fields.
-	if !assert.Equal(t, expected, actual) {
-		for i := 0; i < len(expected) && i < len(actual); i++ {
-			assert.Equal(t, expected[i].output, actual[i].output, "output from test #%d: %s", i, expected[i].name)
-			assert.Equal(t, expected[i].stack, actual[i].stack, "stack from test #%d: %s", i, expected[i].name)
-		}
-	}
-}
-
-type testResult struct {
-	name string
-	// output written to GinkgoWriter during test.
-	output string
-	// failure is SpecSummary.Failure.Message with varying parts stripped.
-	failure string
-	// stack is a normalized version (just file names, function parametes stripped) of
-	// Ginkgo's FullStackTrace of a failure. Empty if no failure.
-	stack string
-}
-
-type suiteResults []testResult
-
-func normalizeReport(report reporters.FakeReporter) suiteResults {
-	var results suiteResults
-	for _, spec := range report.SpecSummaries {
-		results = append(results, testResult{
-			name:    strings.Join(spec.ComponentTexts, " "),
-			output:  normalizeLocation(stripAddresses(stripTimes(spec.CapturedOutput))),
-			failure: stripAddresses(stripTimes(spec.Failure.Message)),
-			stack:   normalizeLocation(spec.Failure.Location.FullStackTrace),
-		})
-	}
-	sort.Slice(results, func(i, j int) bool {
-		return strings.Compare(results[i].name, results[j].name) < 0
-	})
-	return results
-}
-
-// timePrefix matches "Jul 17 08:08:25.950: " at the beginning of each line.
-var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} +[[:digit:]]{1,2} +[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}.[[:digit:]]{3}: `)
-
-func stripTimes(in string) string {
-	return timePrefix.ReplaceAllString(in, "")
-}
-
-// instanceAddr matches " | 0xc0003dec60>"
-var instanceAddr = regexp.MustCompile(` \| 0x[0-9a-fA-F]+>`)
-
-func stripAddresses(in string) string {
-	return instanceAddr.ReplaceAllString(in, ">")
-}
-
-// stackLocation matches "<some path>/<file>.go:75 +0x1f1" after a slash (built
-// locally) or one of a few relative paths (built in the Kubernetes CI).
-var stackLocation = regexp.MustCompile(`(?:/|vendor/|test/|GOROOT/).*/([[:^space:]]+.go:[[:digit:]]+)( \+0x[0-9a-fA-F]+)?`)
-
-// functionArgs matches "<function name>(...)".
-var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`)
-
-// testFailureOutput matches TestFailureOutput() and its source followed by additional stack entries:
-//
-// k8s.io/kubernetes/test/e2e/framework_test.TestFailureOutput(0xc000558800)
-//	/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/log_test.go:73 +0x1c9
-// testing.tRunner(0xc000558800, 0x1af2848)
-// 	/nvme/gopath/go/src/testing/testing.go:865 +0xc0
-// created by testing.(*T).Run
-//	/nvme/gopath/go/src/testing/testing.go:916 +0x35a
-var testFailureOutput = regexp.MustCompile(`(?m)^k8s.io/kubernetes/test/e2e/framework_test\.TestFailureOutput\(.*\n\t.*(\n.*\n\t.*)*`)
-
-// normalizeLocation removes path prefix and function parameters and certain stack entries
-// that we don't care about.
-func normalizeLocation(in string) string {
-	out := in
-	out = stackLocation.ReplaceAllString(out, "$1")
-	out = functionArgs.ReplaceAllString(out, "$1()")
-	out = testFailureOutput.ReplaceAllString(out, "")
-	return out
 }

test/e2e/framework/pod/wait.go

@@ -25,7 +25,6 @@ import (
 	"time"
 
 	"github.com/onsi/ginkgo"
-	"github.com/onsi/gomega/format"
 
 	v1 "k8s.io/api/core/v1"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
@@ -67,16 +66,18 @@ const (
 type podCondition func(pod *v1.Pod) (bool, error)
 
 type timeoutError struct {
-	msg string
+	msg             string
+	observedObjects []interface{}
 }
 
 func (e *timeoutError) Error() string {
 	return e.msg
 }
 
-func TimeoutError(format string, args ...interface{}) *timeoutError {
+func TimeoutError(msg string, observedObjects ...interface{}) *timeoutError {
 	return &timeoutError{
-		msg: fmt.Sprintf(format, args...),
+		msg:             msg,
+		observedObjects: observedObjects,
 	}
 }
 
@@ -85,7 +86,7 @@ func TimeoutError(format string, args ...interface{}) *timeoutError {
 // e.g. "waiting for pod to be running".
 func maybeTimeoutError(err error, taskFormat string, taskArgs ...interface{}) error {
 	if IsTimeout(err) {
-		return TimeoutError("timed out while "+taskFormat, taskArgs...)
+		return TimeoutError(fmt.Sprintf("timed out while "+taskFormat, taskArgs...))
 	} else if err != nil {
 		return fmt.Errorf("error while %s: %w", fmt.Sprintf(taskFormat, taskArgs...), err)
 	} else {
@@ -275,9 +276,10 @@ func WaitForPodCondition(c clientset.Interface, ns, podName, conditionDesc strin
 	if err == nil {
 		return nil
 	}
-	if IsTimeout(err) {
+	if IsTimeout(err) && lastPod != nil {
-		e2elog.Logf("Timed out while waiting for pod %s to be %s. Last observed as: %s",
+		return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to be %s", podIdentifier(ns, podName), conditionDesc),
-			podIdentifier(ns, podName), conditionDesc, format.Object(lastPod, 1))
+			lastPod,
+		)
 	}
 	if lastPodError != nil {
 		// If the last API call was an error.
@@ -494,9 +496,10 @@ func WaitForPodNotFoundInNamespace(c clientset.Interface, podName, ns string, ti
 	if err == nil {
 		return nil
 	}
-	if IsTimeout(err) {
+	if IsTimeout(err) && lastPod != nil {
-		e2elog.Logf("Timed out while waiting for pod %s to be Not Found. Last observed as: %s",
+		return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to be Not Found", podIdentifier(ns, podName)),
-			podIdentifier(ns, podName), format.Object(lastPod, 1))
+			lastPod,
+		)
 	}
 	return maybeTimeoutError(err, "waiting for pod %s not found", podIdentifier(ns, podName))
 }
@@ -530,8 +533,9 @@ func WaitForPodToDisappear(c clientset.Interface, ns, podName string, label labe
 		return nil
 	}
 	if IsTimeout(err) {
-		e2elog.Logf("Timed out while waiting for pod %s to disappear. Last observed as: %s",
+		return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to disappear", podIdentifier(ns, podName)),
-			podIdentifier(ns, podName), format.Object(lastPod, 1))
+			lastPod,
+		)
 	}
 	return maybeTimeoutError(err, "waiting for pod %s to disappear", podIdentifier(ns, podName))
 }

test/e2e/framework/pod/wait_test.go

@@ -0,0 +1,254 @@
+/*
+Copyright 2022 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 pod_test
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/onsi/ginkgo"
+
+	v1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/client-go/kubernetes/fake"
+	"k8s.io/kubernetes/test/e2e/framework"
+	"k8s.io/kubernetes/test/e2e/framework/internal/output"
+	e2epod "k8s.io/kubernetes/test/e2e/framework/pod"
+)
+
+// The line number of the following code is checked in TestFailureOutput below.
+// Be careful when moving it around or changing the import statements above.
+// Here are some intentionally blank lines that can be removed to compensate
+// for future additional import statements.
+//
+//
+//
+//
+//
+//
+//
+//
+//
+// This must be line #47.
+
+func runTests(t *testing.T, reporter ginkgo.Reporter) {
+	// This source code line will be part of the stack dump comparison.
+	ginkgo.RunSpecsWithDefaultAndCustomReporters(t, "Pod Suite", []ginkgo.Reporter{reporter})
+}
+
+var _ = ginkgo.Describe("pod", func() {
+	ginkgo.It("not found", func() {
+		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 %s running", podName /* tests printf formatting */)
+	})
+})
+
+const (
+	podName      = "pending-pod"
+	podNamespace = "default"
+	timeout      = 5 * time.Second
+)
+
+var (
+	clientSet = fake.NewSimpleClientset(&v1.Pod{ObjectMeta: metav1.ObjectMeta{Name: podName, Namespace: podNamespace}})
+)
+
+func TestFailureOutput(t *testing.T) {
+	// Sorted by name!
+	expected := output.SuiteResults{
+		output.TestResult{
+			Name: "[Top Level] pod not found",
+			// "Ignoring NotFound..." will normally occur every two seconds,
+			// but we reduce it to one line because it might occur less often
+			// on a loaded system.
+			Output: `INFO: Waiting up to 5s for pod "no-such-pod" in namespace "default" to be "running"
+INFO: Ignoring NotFound error while getting pod default/no-such-pod
+INFO: 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,
+            },
+        },
+    }
+FAIL: error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
+
+Full Stack Trace
+k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.1()
+	wait_test.go:56
+k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()
+	wait_test.go:51
+
+`,
+			NormalizeOutput: func(output string) string {
+				return trimDuplicateLines(output, "INFO: Ignoring NotFound error while getting pod default/no-such-pod")
+			},
+			Failure: `error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found`,
+			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()
+	wait_test.go:51
+`,
+		},
+		output.TestResult{
+			Name: "[Top Level] pod not running",
+			// "INFO: Pod ..." will normally occur every two seconds,
+			// but we reduce it to one line because it might occur less often
+			// on a loaded system.
+			Output: `INFO: Waiting up to 5s for pod "pending-pod" in namespace "default" to be "running"
+INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: <elapsed>
+INFO: Unexpected error: wait for pod pending-pod running: 
+    <*pod.timeoutError>: {
+        msg: "timed out while waiting for pod default/pending-pod to be running",
+        observedObjects: [
+            {
+                TypeMeta: {Kind: "", APIVersion: ""},
+                ObjectMeta: {
+                    Name: "pending-pod",
+                    GenerateName: "",
+                    Namespace: "default",
+                    SelfLink: "",
+                    UID: "",
+                    ResourceVersion: "",
+                    Generation: 0,
+                    CreationTimestamp: {
+                        Time: {wall: 0, ext: 0, loc: nil},
+                    },
+                    DeletionTimestamp: nil,
+                    DeletionGracePeriodSeconds: nil,
+                    Labels: nil,
+                    Annotations: nil,
+                    OwnerReferences: nil,
+                    Finalizers: nil,
+                    ManagedFields: nil,
+                },
+                Spec: {
+                    Volumes: nil,
+                    InitContainers: nil,
+                    Containers: nil,
+                    EphemeralContainers: nil,
+                    RestartPolicy: "",
+                    TerminationGracePeriodSeconds: nil,
+                    ActiveDeadlineSeconds: nil,
+                    DNSPolicy: "",
+                    NodeSelector: nil,
+                    ServiceAccountName: "",
+                    DeprecatedServiceAccount: "",
+                    AutomountServiceAccountToken: nil,
+                    NodeName: "",
+                    HostNetwork: false,
+                    HostPID: false,
+                    HostIPC: false,
+                    ShareProcessNamespace: nil,
+                    SecurityContext: nil,
+                    ImagePullSecrets: nil,
+                    Hostname: "",
+                    Subdomain: "",
+                    Affinity: nil,
+                    SchedulerName: "",
+                    Tolerations: nil,
+                    HostAliases: nil,
+                    PriorityClassName: "",
+                    Priority: nil,
+                    DNSConfig: nil,
+                    ReadinessGates: nil,
+                    RuntimeClassName: nil,
+                    EnableServiceLinks: nil,
+                    PreemptionPolicy: nil,
+                    Overhead: nil,
+                    TopologySpreadConstraints: nil,
+                    SetHostnameAsFQDN: nil,
+                    OS: nil,
+                },
+                Status: {
+                    Phase: "",
+                    Conditions: nil,
+                    Message: "",
+                    Reason: "",
+                    NominatedNodeName: "",
+                    HostIP: "",
+                    PodIP: "",
+                    PodIPs: nil,
+                    StartTime: nil,
+                    InitContainerStatuses: nil,
+                    ContainerStatuses: nil,
+                    QOSClass: "",
+                    EphemeralContainerStatuses: nil,
+                },
+            },
+        ],
+    }
+FAIL: wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running
+
+Full Stack Trace
+k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
+	wait_test.go:60
+k8s.io/kubernetes/test/e2e/framework/pod_test.runTests()
+	wait_test.go:51
+
+`,
+			NormalizeOutput: func(output string) string {
+				return trimDuplicateLines(output, `INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: <elapsed>`)
+			},
+			Failure: `wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running`,
+			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()
+	wait_test.go:51
+`,
+		},
+	}
+
+	output.TestGinkgoOutput(t, runTests, expected)
+}
+
+func trimDuplicateLines(output, prefix string) string {
+	lines := strings.Split(output, "\n")
+	trimming := false
+	validLines := 0
+	for i := 0; i < len(lines); i++ {
+		if strings.HasPrefix(lines[i], prefix) {
+			// Keep the first line, and only that one.
+			if !trimming {
+				trimming = true
+				lines[validLines] = lines[i]
+				validLines++
+			}
+		} else {
+			trimming = false
+			lines[validLines] = lines[i]
+			validLines++
+		}
+	}
+	return strings.Join(lines[0:validLines], "\n")
+}