diff --git a/test/e2e/framework/expect.go b/test/e2e/framework/expect.go index b7584e654fa..7b7fe7f416a 100644 --- a/test/e2e/framework/expect.go +++ b/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. diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go new file mode 100644 index 00000000000..f40b40711ae --- /dev/null +++ b/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: ") + 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 "/.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 "(...)". +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 +} diff --git a/test/e2e/framework/log_test.go b/test/e2e/framework/log_test.go index 5a3cee1b07f..4da841fa52d 100644 --- a/test/e2e/framework/log_test.go +++ b/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{ - testResult{ - name: "[Top Level] log asserts", - output: `INFO: before + expected := output.SuiteResults{ + output.TestResult{ + Name: "[Top Level] log asserts", + Output: `INFO: before FAIL: false is never true Expected : 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 : false to equal : 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{ - name: "[Top Level] log equal", - output: `INFO: before + output.TestResult{ + Name: "[Top Level] log equal", + Output: `INFO: before FAIL: of course it's not equal... Expected : 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 : 0 to equal : 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{ - name: "[Top Level] log error", - output: `INFO: before -FAIL: hard-coded error -Unexpected error: + output.TestResult{ + Name: "[Top Level] log error", + Output: `INFO: before +INFO: Unexpected error: hard-coded error: <*errors.errorString>: { s: "an error with a long, useless description", } - an error with a long, useless description -occurred +FAIL: hard-coded error: an error with a long, useless description 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 -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() + Failure: `hard-coded error: an error with a long, useless description`, + 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{ - name: "[Top Level] log fails", - output: `INFO: before + output.TestResult{ + Name: "[Top Level] log fails", + 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.", - stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2() + Failure: "I'm failing.", + 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 - // 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 "/.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 "(...)". -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 + + output.TestGinkgoOutput(t, runTests, expected) } diff --git a/test/e2e/framework/pod/wait.go b/test/e2e/framework/pod/wait.go index f3ebc56a922..ccdaa3d2d5c 100644 --- a/test/e2e/framework/pod/wait.go +++ b/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) { - e2elog.Logf("Timed out while waiting for pod %s to be %s. Last observed as: %s", - podIdentifier(ns, podName), conditionDesc, format.Object(lastPod, 1)) + if IsTimeout(err) && lastPod != nil { + return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to be %s", podIdentifier(ns, podName), conditionDesc), + 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) { - e2elog.Logf("Timed out while waiting for pod %s to be Not Found. Last observed as: %s", - podIdentifier(ns, podName), format.Object(lastPod, 1)) + if IsTimeout(err) && lastPod != nil { + return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to be Not Found", podIdentifier(ns, podName)), + 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", - podIdentifier(ns, podName), format.Object(lastPod, 1)) + return TimeoutError(fmt.Sprintf("timed out while waiting for pod %s to disappear", podIdentifier(ns, podName)), + lastPod, + ) } return maybeTimeoutError(err, "waiting for pod %s to disappear", podIdentifier(ns, podName)) } diff --git a/test/e2e/framework/pod/wait_test.go b/test/e2e/framework/pod/wait_test.go new file mode 100644 index 00000000000..da09ae2730e --- /dev/null +++ b/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: +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: `) + }, + 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") +}