From 2ad1fc5f8fbe0840e6975853ee9a6d815b65e85b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 13 May 2022 13:21:02 +0200 Subject: [PATCH 1/6] e2e: include expected line number in output test This makes it easier to see when comment lines must be added or removed. --- test/e2e/framework/log_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/e2e/framework/log_test.go b/test/e2e/framework/log_test.go index 5a3cee1b07f..84c17dea7db 100644 --- a/test/e2e/framework/log_test.go +++ b/test/e2e/framework/log_test.go @@ -40,7 +40,7 @@ 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. From 0e0e51d79257837b57c6b087f23b2cf46bdffb0e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 11 May 2022 17:55:22 +0200 Subject: [PATCH 2/6] e2e: refactor Ginkgo output testing The helper code will be useful for testing other parts of the e2e framework. --- test/e2e/framework/internal/output/output.go | 130 ++++++++++++++++ test/e2e/framework/log_test.go | 149 ++++--------------- 2 files changed, 160 insertions(+), 119 deletions(-) create mode 100644 test/e2e/framework/internal/output/output.go diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go new file mode 100644 index 00000000000..8cd51d1d8ca --- /dev/null +++ b/test/e2e/framework/internal/output/output.go @@ -0,0 +1,130 @@ +/* +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) + + // 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) + assert.Equal(t, expected[i].Failure, actual[i].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 +} + +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 { + out := timePrefix.ReplaceAllString(in, "") + 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 84c17dea7db..ab14cc315ba 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. @@ -40,6 +34,12 @@ import ( // // // +// +// +// +// +// +// // This must be line #43. func runTests(t *testing.T, reporter ginkgo.Reporter) { @@ -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,20 +132,20 @@ 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 + output.TestResult{ + Name: "[Top Level] log error", + Output: `INFO: before FAIL: hard-coded error Unexpected error: <*errors.errorString>: { @@ -171,22 +159,22 @@ 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 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() + 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 +182,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) } From 486744e8149763c15dcfcbf2fb16c4f8c36d56c4 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 11 May 2022 18:01:29 +0200 Subject: [PATCH 3/6] e2e: test output of e2epod wait Both output during the test and the failure message are covered. --- test/e2e/framework/internal/output/output.go | 4 + test/e2e/framework/pod/wait_test.go | 258 +++++++++++++++++++ 2 files changed, 262 insertions(+) create mode 100644 test/e2e/framework/pod/wait_test.go diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go index 8cd51d1d8ca..6bea574e396 100644 --- a/test/e2e/framework/internal/output/output.go +++ b/test/e2e/framework/internal/output/output.go @@ -90,8 +90,12 @@ func normalizeReport(report reporters.FakeReporter) SuiteResults { // 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 } diff --git a/test/e2e/framework/pod/wait_test.go b/test/e2e/framework/pod/wait_test.go new file mode 100644 index 00000000000..ab010bc975e --- /dev/null +++ b/test/e2e/framework/pod/wait_test.go @@ -0,0 +1,258 @@ +/* +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 ( + "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), "wait for pod running") + }) + + ginkgo.It("not running", func() { + framework.ExpectNoError(e2epod.WaitTimeoutForPodRunningInNamespace(clientSet, podName, podNamespace, timeout), "wait for pod running") + }) +}) + +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", + 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: 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 +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 + +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 + +`, + Failure: `wait for pod running +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() + wait_test.go:51 +`, + }, + output.TestResult{ + Name: "[Top Level] pod not running", + 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: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: +INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: +INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: +INFO: Timed out while waiting for pod default/pending-pod to be running. Last observed as: <*v1.Pod>: { + TypeMeta: {Kind: "", APIVersion: ""}, + ObjectMeta: { + Name: "pending-pod", + GenerateName: "", + Namespace: "default", + SelfLink: "", + UID: "", + ResourceVersion: "", + Generation: 0, + CreationTimestamp: { + Time: 0001-01-01T00:00:00Z, + }, + 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 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 + +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 + +`, + Failure: `wait for 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 +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() + wait_test.go:51 +`, + }, + } + + output.TestGinkgoOutput(t, runTests, expected) +} From 8e79f4ce27ef1719776df6d6e59f2447de7a3c1f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 12 May 2022 08:40:04 +0200 Subject: [PATCH 4/6] 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 | 32 ++++++++++++++++++- test/e2e/framework/log_test.go | 14 ++------- test/e2e/framework/pod/wait_test.go | 48 +++++------------------------ 3 files changed, 42 insertions(+), 52 deletions(-) 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/log_test.go b/test/e2e/framework/log_test.go index ab14cc315ba..4da841fa52d 100644 --- a/test/e2e/framework/log_test.go +++ b/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 -Unexpected error: +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`, + 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() diff --git a/test/e2e/framework/pod/wait_test.go b/test/e2e/framework/pod/wait_test.go index ab010bc975e..9e21dccfe9e 100644 --- a/test/e2e/framework/pod/wait_test.go +++ b/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 -Unexpected error: +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: { @@ -103,8 +102,7 @@ Unexpected error: }, }, } - error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found -occurred +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() @@ -113,29 +111,7 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests() wait_test.go:51 `, - Failure: `wait for pod running -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`, + 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() @@ -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 -Unexpected error: +INFO: Unexpected error: wait for pod pending-pod running: <*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 +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() @@ -239,13 +213,7 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests() wait_test.go:51 `, - Failure: `wait for 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 -occurred`, + 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() From 2b299526b24e6e50163ace169441d633b8838ca0 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 5 May 2022 16:38:02 +0200 Subject: [PATCH 5/6] e2e: include more information in pod timeout error The advantage is that the extra error information is guaranteed to be printed directly before the failure and we avoid one extra log line that would have to be correlated with the failure. --- test/e2e/framework/pod/wait.go | 30 +++--- test/e2e/framework/pod/wait_test.go | 153 ++++++++++++++-------------- 2 files changed, 94 insertions(+), 89 deletions(-) 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 index 9e21dccfe9e..99b8d8e25c6 100644 --- a/test/e2e/framework/pod/wait_test.go +++ b/test/e2e/framework/pod/wait_test.go @@ -81,7 +81,6 @@ 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: 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 INFO: Unexpected error: <*fmt.wrapError>: { msg: "error while waiting for pod default/no-such-pod to be running: pods \"no-such-pod\" not found", @@ -125,84 +124,86 @@ INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: -INFO: Timed out while waiting for pod default/pending-pod to be running. Last observed as: <*v1.Pod>: { - TypeMeta: {Kind: "", APIVersion: ""}, - ObjectMeta: { - Name: "pending-pod", - GenerateName: "", - Namespace: "default", - SelfLink: "", - UID: "", - ResourceVersion: "", - Generation: 0, - CreationTimestamp: { - Time: 0001-01-01T00:00:00Z, - }, - 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, - }, - } 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 From f02c72eaf90c24a907ebb7c62ff0efd4e71e0dc8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 3 Jun 2022 13:38:06 +0200 Subject: [PATCH 6/6] pods: more tolerant checking of poll tests Under load we might skip some of the poll events, leading to less output. Now we expect only at least one output line for polling. --- test/e2e/framework/internal/output/output.go | 23 +++++++---- test/e2e/framework/pod/wait_test.go | 41 ++++++++++++++++---- 2 files changed, 50 insertions(+), 14 deletions(-) diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go index 6bea574e396..f40b40711ae 100644 --- a/test/e2e/framework/internal/output/output.go +++ b/test/e2e/framework/internal/output/output.go @@ -44,14 +44,19 @@ func TestGinkgoOutput(t *testing.T, runTests func(t *testing.T, reporter ginkgo. // Now check the output. actual := normalizeReport(*reporter) - // 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) + 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) - assert.Equal(t, expected[i].Failure, actual[i].Failure, "failure 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) } } } @@ -67,6 +72,10 @@ type TestResult struct { // 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 diff --git a/test/e2e/framework/pod/wait_test.go b/test/e2e/framework/pod/wait_test.go index 99b8d8e25c6..da09ae2730e 100644 --- a/test/e2e/framework/pod/wait_test.go +++ b/test/e2e/framework/pod/wait_test.go @@ -17,6 +17,7 @@ limitations under the License. package pod_test import ( + "strings" "testing" "time" @@ -43,7 +44,6 @@ import ( // // // -// // This must be line #47. func runTests(t *testing.T, reporter ginkgo.Reporter) { @@ -76,11 +76,11 @@ func TestFailureOutput(t *testing.T) { 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: 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: Unexpected error: <*fmt.wrapError>: { msg: "error while waiting for pod default/no-such-pod to be running: pods \"no-such-pod\" not found", @@ -110,6 +110,9 @@ 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 @@ -119,11 +122,11 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests() }, 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: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: -INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: -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", @@ -214,6 +217,9 @@ 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 @@ -225,3 +231,24 @@ k8s.io/kubernetes/test/e2e/framework/pod_test.runTests() 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") +}