e2e framework: verify JUnit result, not the in-memory structs

The old tests were no longer passing with Ginkgo v2.5.0. Instead of keeping the
old approach of checking recorded spec results, now the tests actually cover
what we care about most: the results recorded in JUnit.

This also gets rid of having to repeat the stack backtrace twice (once as part
of the output, once for the separate backtrace field).
This commit is contained in:
Patrick Ohly 2022-11-14 14:58:02 +01:00
parent f6cdd37046
commit 766e7e07da
5 changed files with 385 additions and 246 deletions

View File

@ -17,84 +17,103 @@ limitations under the License.
package output package output
import ( import (
"encoding/xml"
"io/ioutil"
"path"
"regexp" "regexp"
"sort"
"strings"
"testing" "testing"
"github.com/google/go-cmp/cmp"
"github.com/google/go-cmp/cmp/cmpopts"
"github.com/onsi/ginkgo/v2" "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/reporters"
"github.com/onsi/gomega" "github.com/onsi/gomega"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/require"
"k8s.io/kubernetes/test/e2e/framework" "k8s.io/kubernetes/test/e2e/framework"
"k8s.io/kubernetes/test/e2e/framework/internal/junit"
) )
func TestGinkgoOutput(t *testing.T, expected SuiteResults, runSpecsArgs ...interface{}) { // TestGinkgoOutput runs the current suite and verifies that the generated
// Run the Ginkgo suite with spec results collected via ReportAfterEach // JUnit file matches the expected result.
// in adddition to the default one. To see what the full //
// Ginkgo output looks like, run this test with "go test -v". // The Ginkgo output on the console (aka the test suite log) does not get
// checked. It is usually less important for the CI and more relevant when
// using test suite interactively. To see what that Ginkgo output looks like,
// run tests with "go test -v".
func TestGinkgoOutput(t *testing.T, expected TestResult, runSpecsArgs ...interface{}) {
tmpdir := t.TempDir()
junitFile := path.Join(tmpdir, "junit.xml")
gomega.RegisterFailHandler(framework.Fail) gomega.RegisterFailHandler(framework.Fail)
var report []ginkgo.SpecReport ginkgo.ReportAfterSuite("write JUnit file", func(report ginkgo.Report) {
ginkgo.ReportAfterEach(func(spec ginkgo.SpecReport) { junit.WriteJUnitReport(report, junitFile)
report = append(report, spec)
}) })
fakeT := &testing.T{} fakeT := &testing.T{}
ginkgo.RunSpecs(fakeT, "Logging Suite", runSpecsArgs...) ginkgo.RunSpecs(fakeT, "Logging Suite", runSpecsArgs...)
// Now check the output. var actual reporters.JUnitTestSuites
actual := normalizeReport(report) data, err := ioutil.ReadFile(junitFile)
require.NoError(t, err)
err = xml.Unmarshal(data, &actual)
require.NoError(t, err)
if assert.Equal(t, len(expected), len(actual), "Should have %d test results, got: %v", len(expected), actual) { if len(actual.TestSuites) != 1 {
for i := 0; i < len(expected); i++ { t.Fatalf("expected one test suite, got %d, JUnit content:\n%s", len(actual.TestSuites), string(data))
assert.Equal(t, expected[i].Name, actual[i].Name, "name from test #%d", i) }
output := actual[i].Output diff := cmp.Diff(expected.Suite, actual.TestSuites[0],
if expected[i].NormalizeOutput != nil { // Time varies.
output = expected[i].NormalizeOutput(output) // Name and Classname are "Logging Suite".
} // Package includes a varying path, not interesting.
assert.Equal(t, expected[i].Output, output, "output from test #%d (%s)", i, expected[i].Name) // Properties also too complicated to compare.
assert.Equal(t, expected[i].Stack, actual[i].Stack, "stack from test #%d (%s)", i, expected[i].Name) cmpopts.IgnoreFields(reporters.JUnitTestSuite{}, "Time", "Timestamp", "Name", "Package", "Properties"),
failure := actual[i].Failure cmpopts.IgnoreFields(reporters.JUnitTestCase{}, "Time", "Classname"),
if expected[i].NormalizeFailure != nil { cmpopts.SortSlices(func(tc1, tc2 reporters.JUnitTestCase) bool {
failure = expected[i].NormalizeFailure(failure) return tc1.Name < tc2.Name
} }),
assert.Equal(t, expected[i].Failure, failure, "failure from test #%d (%s)", i, expected[i].Name) cmpopts.AcyclicTransformer("simplify", func(in string) any {
} out := simplify(in, expected)
// Sometimes cmp.Diff does not print the full string when it is long.
// Uncommenting this here may help debug differences.
// if len(out) > 100 {
// t.Logf("%s\n---------------------------------------\n%s\n", in, out)
// }
// Same idea as in
// https://github.com/google/go-cmp/issues/192#issuecomment-605346277:
// it forces cmp.Diff to diff strings line-by-line,
// even when it normally wouldn't. The downside is
// that the output is harder to turn back into the
// expected reference string.
// if len(out) > 50 {
// return strings.Split(out, "\n")
// }
return out
}),
)
if diff != "" {
t.Fatalf("Simplified JUnit report not as expected (-want, +got):\n%s\n\nFull XML:\n%s", diff, string(data))
} }
} }
// TestResult is the outcome of one It spec. // TestResult is the expected outcome of the suite, with additional parameters that
// determine equality.
type TestResult struct { type TestResult struct {
// Name is the full string for a Ginkgo It, including the "[Top Level]" prefix. // Called to normalize all output strings before comparison if non-nil.
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 parameters 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 NormalizeOutput func(string) string
// Called to normalize the actual failure string before comparison if non-nil.
NormalizeFailure func(string) string // All test cases and overall suite results.
Suite reporters.JUnitTestSuite
} }
type SuiteResults []TestResult func simplify(in string, expected TestResult) string {
out := normalizeLocation(in)
func normalizeReport(report []ginkgo.SpecReport) SuiteResults { out = stripTimes(out)
var results SuiteResults out = stripAddresses(out)
for _, spec := range report { if expected.NormalizeOutput != nil {
results = append(results, TestResult{ out = expected.NormalizeOutput(out)
Name: strings.Join(spec.ContainerHierarchyTexts, " ") + " " + spec.LeafNodeText,
Output: normalizeLocation(stripAddresses(stripTimes(spec.CapturedGinkgoWriterOutput))),
Failure: stripAddresses(stripTimes(spec.Failure.Message)),
Stack: normalizeLocation(spec.Failure.Location.FullStackTrace),
})
} }
sort.Slice(results, func(i, j int) bool { return out
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. // timePrefix matches "Jul 17 08:08:25.950: " at the beginning of each line.
@ -103,13 +122,13 @@ var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} +[[:digit:]]{1,2} +[[:d
// elapsedSuffix matches "Elapsed: 16.189µs" // elapsedSuffix matches "Elapsed: 16.189µs"
var elapsedSuffix = regexp.MustCompile(`Elapsed: [[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)`) var elapsedSuffix = regexp.MustCompile(`Elapsed: [[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)`)
// timeSuffix matches "09/06/22 15:36:43.445" as printed by Ginkgo v2 for log output. // timeSuffix matches "@ 09/06/22 15:36:43.44 (5.001s)" as printed by Ginkgo v2 for log output, with the duration being optional.
var timeSuffix = regexp.MustCompile(`(?m)[[:space:]][[:digit:]]{2}/[[:digit:]]{2}/[[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}(\.[[:digit:]]{1,3})?$`) var timeSuffix = regexp.MustCompile(`(?m)@[[:space:]][[:digit:]]{2}/[[:digit:]]{2}/[[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}(\.[[:digit:]]{1,3})?( \([[:digit:]]+(\.[[:digit:]]+)?(µs|ns|ms|s|m)\))?$`)
func stripTimes(in string) string { func stripTimes(in string) string {
out := timePrefix.ReplaceAllString(in, "") out := timePrefix.ReplaceAllString(in, "")
out = elapsedSuffix.ReplaceAllString(out, "Elapsed: <elapsed>") out = elapsedSuffix.ReplaceAllString(out, "Elapsed: <elapsed>")
out = timeSuffix.ReplaceAllString(out, "") out = timeSuffix.ReplaceAllString(out, "<time>")
return out return out
} }

View File

@ -29,6 +29,7 @@ import (
"testing" "testing"
"github.com/onsi/ginkgo/v2" "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/reporters"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/klog/v2" "k8s.io/klog/v2"
@ -46,7 +47,6 @@ import (
// //
// //
// //
//
// This must be line #50. // This must be line #50.
func init() { func init() {
@ -100,7 +100,7 @@ var _ = ginkgo.Describe("e2e", func() {
fail := func(ctx context.Context, name string) error { fail := func(ctx context.Context, name string) error {
return fmt.Errorf("fake error for %q", name) return fmt.Errorf("fake error for %q", name)
} }
ginkgo.DeferCleanup(framework.IgnoreNotFound(fail), "failure") ginkgo.DeferCleanup(framework.IgnoreNotFound(fail), "failure") // Without a failure the output would not be shown in JUnit.
// More test cases can be added here without affeccting line numbering // More test cases can be added here without affeccting line numbering
// of existing tests. // of existing tests.
@ -108,50 +108,52 @@ var _ = ginkgo.Describe("e2e", func() {
}) })
const ( const (
ginkgoOutput = `[BeforeEach] e2e ginkgoOutput = `> Enter [BeforeEach] e2e - cleanup_test.go:63 <time>
cleanup_test.go:63
INFO: before INFO: before
[BeforeEach] e2e < Exit [BeforeEach] e2e - cleanup_test.go:63 <time>
set up framework | framework.go:xxx > Enter [BeforeEach] e2e - set up framework | framework.go:xxx <time>
STEP: Creating a kubernetes client STEP: Creating a kubernetes client - framework.go:xxx <time>
INFO: >>> kubeConfig: yyy/kube.config INFO: >>> kubeConfig: yyy/kube.config
STEP: Building a namespace api object, basename test-namespace STEP: Building a namespace api object, basename test-namespace - framework.go:xxx <time>
INFO: Skipping waiting for service account INFO: Skipping waiting for service account
[BeforeEach] e2e < Exit [BeforeEach] e2e - set up framework | framework.go:xxx <time>
cleanup_test.go:56 > Enter [BeforeEach] e2e - cleanup_test.go:56 <time>
INFO: extension before INFO: extension before
[BeforeEach] e2e < Exit [BeforeEach] e2e - cleanup_test.go:56 <time>
cleanup_test.go:71 > Enter [BeforeEach] e2e - cleanup_test.go:71 <time>
INFO: before #1 INFO: before #1
[BeforeEach] e2e < Exit [BeforeEach] e2e - cleanup_test.go:71 <time>
cleanup_test.go:75 > Enter [BeforeEach] e2e - cleanup_test.go:75 <time>
INFO: before #2 INFO: before #2
[It] works < Exit [BeforeEach] e2e - cleanup_test.go:75 <time>
cleanup_test.go:90 > Enter [It] works - cleanup_test.go:90 <time>
[AfterEach] e2e < Exit [It] works - cleanup_test.go:90 <time>
cleanup_test.go:57 > Enter [AfterEach] e2e - cleanup_test.go:57 <time>
INFO: extension after INFO: extension after
[AfterEach] e2e < Exit [AfterEach] e2e - cleanup_test.go:57 <time>
cleanup_test.go:79 > Enter [AfterEach] e2e - cleanup_test.go:79 <time>
INFO: after #1 INFO: after #1
[AfterEach] e2e < Exit [AfterEach] e2e - cleanup_test.go:79 <time>
cleanup_test.go:86 > Enter [AfterEach] e2e - cleanup_test.go:86 <time>
INFO: after #2 INFO: after #2
[DeferCleanup (Each)] e2e < Exit [AfterEach] e2e - cleanup_test.go:86 <time>
cleanup_test.go:103 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:103 <time>
[DeferCleanup (Each)] e2e [FAILED] DeferCleanup callback returned error: fake error for "failure"
cleanup_test.go:99 In [DeferCleanup (Each)] at: cleanup_test.go:103 <time>
[DeferCleanup (Each)] e2e < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:103 <time>
cleanup_test.go:95 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:99 <time>
< Exit [DeferCleanup (Each)] e2e - cleanup_test.go:99 <time>
> Enter [DeferCleanup (Each)] e2e - cleanup_test.go:95 <time>
INFO: cleanup first INFO: cleanup first
[DeferCleanup (Each)] e2e < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:95 <time>
cleanup_test.go:92 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:92 <time>
INFO: cleanup last INFO: cleanup last
[DeferCleanup (Each)] e2e < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:92 <time>
dump namespaces | framework.go:xxx > Enter [DeferCleanup (Each)] e2e - dump namespaces | framework.go:xxx <time>
[DeferCleanup (Each)] e2e < Exit [DeferCleanup (Each)] e2e - dump namespaces | framework.go:xxx <time>
tear down framework | framework.go:xxx > Enter [DeferCleanup (Each)] e2e - tear down framework | framework.go:xxx <time>
STEP: Destroying namespace "test-namespace-zzz" for this suite. STEP: Destroying namespace "test-namespace-zzz" for this suite. - framework.go:xxx <time>
< Exit [DeferCleanup (Each)] e2e - tear down framework | framework.go:xxx <time>
` `
) )
@ -195,15 +197,28 @@ func TestCleanup(t *testing.T) {
framework.AfterReadingAllFlags(&framework.TestContext) framework.AfterReadingAllFlags(&framework.TestContext)
suiteConfig, reporterConfig := framework.CreateGinkgoConfig() suiteConfig, reporterConfig := framework.CreateGinkgoConfig()
expected := output.SuiteResults{ expected := output.TestResult{
output.TestResult{ NormalizeOutput: normalizeOutput,
Name: "e2e works", Suite: reporters.JUnitTestSuite{
NormalizeOutput: normalizeOutput, Tests: 1,
Output: ginkgoOutput, Failures: 1,
// It would be nice to get the cleanup failure into the Errors: 0,
// output, but that depends on Ginkgo enhancements: Disabled: 0,
// https://github.com/onsi/ginkgo/issues/1041#issuecomment-1274611444 Skipped: 0,
Failure: `DeferCleanup callback returned error: fake error for "failure"`,
TestCases: []reporters.JUnitTestCase{
{
Name: "[It] e2e works",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] DeferCleanup callback returned error: fake error for "failure"
In [DeferCleanup (Each)] at: cleanup_test.go:103 <time>
`,
},
SystemErr: ginkgoOutput,
},
},
}, },
} }

View File

@ -23,6 +23,7 @@ import (
"testing" "testing"
"github.com/onsi/ginkgo/v2" "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/reporters"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
@ -76,122 +77,212 @@ var _ = ginkgo.Describe("log", func() {
}) })
func TestFailureOutput(t *testing.T) { func TestFailureOutput(t *testing.T) {
// output from AfterEach expected := output.TestResult{
commonOutput := ` Suite: reporters.JUnitTestSuite{
Tests: 6,
Failures: 6,
Errors: 0,
Disabled: 0,
Skipped: 0,
TestCases: []reporters.JUnitTestCase{
{
Name: "[It] log fails",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] I'm failing.
In [It] at: log_test.go:57 <time>
There were additional failures detected after the initial failure. These are visible in the timeline
`,
},
SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
INFO: before
< Exit [BeforeEach] log - log_test.go:48 <time>
> Enter [It] fails - log_test.go:55 <time>
[FAILED] I'm failing.
In [It] at: log_test.go:57 <time>
< Exit [It] fails - log_test.go:55 <time>
> Enter [AfterEach] log - log_test.go:51 <time>
INFO: after INFO: after
FAIL: true is never false either [FAILED] true is never false either
Expected Expected
<bool>: true <bool>: true
to equal to equal
<bool>: false <bool>: false
In [AfterEach] at: log_test.go:53 <time>
Full Stack Trace < Exit [AfterEach] log - log_test.go:51 <time>
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2() `,
log_test.go:52 },
` {
Name: "[It] log asserts",
// Sorted by name! Status: "failed",
expected := output.SuiteResults{ Failure: &reporters.JUnitFailure{
output.TestResult{ Type: "failed",
Name: "log asserts", Description: `[FAILED] false is never true
Output: `INFO: before
FAIL: false is never true
Expected Expected
<bool>: false <bool>: false
to equal to equal
<bool>: true <bool>: true
In [It] at: log_test.go:61 <time>
Full Stack Trace There were additional failures detected after the initial failure. These are visible in the timeline
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4() `,
log_test.go:60` + commonOutput, },
Failure: `false is never true SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
INFO: before
< Exit [BeforeEach] log - log_test.go:48 <time>
> Enter [It] asserts - log_test.go:60 <time>
[FAILED] false is never true
Expected Expected
<bool>: false <bool>: false
to equal to equal
<bool>: true`, <bool>: true
Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4() In [It] at: log_test.go:61 <time>
log_test.go:60`, < Exit [It] asserts - log_test.go:60 <time>
}, > Enter [AfterEach] log - log_test.go:51 <time>
output.TestResult{ INFO: after
Name: "log equal", [FAILED] true is never false either
Output: `INFO: before
FAIL: of course it's not equal...
Expected Expected
<int>: 0 <bool>: true
to equal to equal
<int>: 1 <bool>: false
In [AfterEach] at: log_test.go:53 <time>
< Exit [AfterEach] log - log_test.go:51 <time>
`,
},
{
Name: "[It] log error",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] hard-coded error: an error with a long, useless description
In [It] at: log_test.go:65 <time>
Full Stack Trace There were additional failures detected after the initial failure. These are visible in the timeline
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.6() `,
log_test.go:67` + commonOutput, },
Failure: `of course it's not equal... SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
Expected INFO: before
<int>: 0 < Exit [BeforeEach] log - log_test.go:48 <time>
to equal > Enter [It] error - log_test.go:63 <time>
<int>: 1`,
Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.6()
log_test.go:67`,
},
output.TestResult{
Name: "log error",
Output: `INFO: before
INFO: Unexpected error: hard-coded error: INFO: Unexpected error: hard-coded error:
<*errors.errorString>: { <*errors.errorString>: {
s: "an error with a long, useless description", s: "an error with a long, useless description",
} }
FAIL: hard-coded error: an error with a long, useless description [FAILED] hard-coded error: an error with a long, useless description
In [It] at: log_test.go:65 <time>
Full Stack Trace < Exit [It] error - log_test.go:63 <time>
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5() > Enter [AfterEach] log - log_test.go:51 <time>
log_test.go:64` + commonOutput, INFO: after
Failure: `hard-coded error: an error with a long, useless description`, [FAILED] true is never false either
Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5()
log_test.go:64`,
},
output.TestResult{
Name: "log fails",
Output: `INFO: before
FAIL: I'm failing.
Full Stack Trace
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3.1()
log_test.go:56
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()
log_test.go:57` + commonOutput,
Failure: "I'm failing.",
Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3.1()
log_test.go:56
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()
log_test.go:57`,
},
output.TestResult{
Name: "log fails with helper",
Output: `INFO: before
FAIL: I'm failing with helper.
Full Stack Trace
k8s.io/kubernetes/test/e2e/framework_test.failHelper()
log_test.go:43
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.7()
log_test.go:70` + commonOutput,
Failure: "I'm failing with helper.",
Stack: `k8s.io/kubernetes/test/e2e/framework_test.failHelper()
log_test.go:43
k8s.io/kubernetes/test/e2e/framework_test.glob..func1.7()
log_test.go:70`,
},
output.TestResult{
Name: "log redirects klog",
Output: `INFO: before
<klog> log_test.go:73] hello world
<klog> log_test.go:74] <nil>not really an error` + commonOutput,
Failure: `true is never false either
Expected Expected
<bool>: true <bool>: true
to equal to equal
<bool>: false`, <bool>: false
Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2() In [AfterEach] at: log_test.go:53 <time>
log_test.go:52`, < Exit [AfterEach] log - log_test.go:51 <time>
`,
},
{
Name: "[It] log equal",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] of course it's not equal...
Expected
<int>: 0
to equal
<int>: 1
In [It] at: log_test.go:68 <time>
There were additional failures detected after the initial failure. These are visible in the timeline
`,
},
SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
INFO: before
< Exit [BeforeEach] log - log_test.go:48 <time>
> Enter [It] equal - log_test.go:67 <time>
[FAILED] of course it's not equal...
Expected
<int>: 0
to equal
<int>: 1
In [It] at: log_test.go:68 <time>
< Exit [It] equal - log_test.go:67 <time>
> Enter [AfterEach] log - log_test.go:51 <time>
INFO: after
[FAILED] true is never false either
Expected
<bool>: true
to equal
<bool>: false
In [AfterEach] at: log_test.go:53 <time>
< Exit [AfterEach] log - log_test.go:51 <time>
`,
},
{
Name: "[It] log fails with helper",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] I'm failing with helper.
In [It] at: log_test.go:44 <time>
There were additional failures detected after the initial failure. These are visible in the timeline
`,
},
SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
INFO: before
< Exit [BeforeEach] log - log_test.go:48 <time>
> Enter [It] fails with helper - log_test.go:70 <time>
[FAILED] I'm failing with helper.
In [It] at: log_test.go:44 <time>
< Exit [It] fails with helper - log_test.go:70 <time>
> Enter [AfterEach] log - log_test.go:51 <time>
INFO: after
[FAILED] true is never false either
Expected
<bool>: true
to equal
<bool>: false
In [AfterEach] at: log_test.go:53 <time>
< Exit [AfterEach] log - log_test.go:51 <time>
`,
},
{
Name: "[It] log redirects klog",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] true is never false either
Expected
<bool>: true
to equal
<bool>: false
In [AfterEach] at: log_test.go:53 <time>
`,
},
SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
INFO: before
< Exit [BeforeEach] log - log_test.go:48 <time>
> Enter [It] redirects klog - log_test.go:73 <time>
<klog> log_test.go:74] hello world
<klog> log_test.go:75] <nil>not really an error
< Exit [It] redirects klog - log_test.go:73 <time>
> Enter [AfterEach] log - log_test.go:51 <time>
INFO: after
[FAILED] true is never false either
Expected
<bool>: true
to equal
<bool>: false
In [AfterEach] at: log_test.go:53 <time>
< Exit [AfterEach] log - log_test.go:51 <time>
`,
},
},
}, },
} }

View File

@ -23,6 +23,7 @@ import (
"time" "time"
"github.com/onsi/ginkgo/v2" "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/reporters"
v1 "k8s.io/api/core/v1" v1 "k8s.io/api/core/v1"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@ -46,10 +47,7 @@ import (
// //
// //
// //
// // This must be line #50.
//
//
// This must be line #52.
var _ = ginkgo.Describe("pod", func() { var _ = ginkgo.Describe("pod", func() {
ginkgo.It("not found", func(ctx context.Context) { ginkgo.It("not found", func(ctx context.Context) {
@ -72,14 +70,32 @@ var (
) )
func TestFailureOutput(t *testing.T) { func TestFailureOutput(t *testing.T) {
// Sorted by name!
expected := output.SuiteResults{ expected := output.TestResult{
output.TestResult{ // "INFO: Ignoring ..." or "INFO: Pod ..." will normally occur
Name: "pod not found", // every two seconds, but we reduce it to one line because it
// "Ignoring NotFound..." will normally occur every two seconds, // might occur less often on a loaded system.
// but we reduce it to one line because it might occur less often NormalizeOutput: func(output string) string {
// on a loaded system. return trimDuplicateLines(output, "INFO: ")
Output: `INFO: Waiting up to 5s for pod "no-such-pod" in namespace "default" to be "running" },
Suite: reporters.JUnitTestSuite{
Tests: 2,
Failures: 2,
Errors: 0,
Disabled: 0,
Skipped: 0,
TestCases: []reporters.JUnitTestCase{
{
Name: "[It] pod not found",
Status: "failed",
Failure: &reporters.JUnitFailure{
Type: "failed",
Description: `[FAILED] error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
In [It] at: wait_test.go:54 <time>
`,
},
SystemErr: `> Enter [It] not found - wait_test.go:53 <time>
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: Unexpected error: INFO: Unexpected error:
<*fmt.wrapError>: { <*fmt.wrapError>: {
@ -101,25 +117,22 @@ INFO: Unexpected error:
}, },
}, },
} }
FAIL: error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found [FAILED] error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found
In [It] at: wait_test.go:54 <time>
Full Stack Trace < Exit [It] not found - wait_test.go:53 <time>
k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.1()
wait_test.go:56
`, `,
NormalizeOutput: func(output string) string { },
return trimDuplicateLines(output, "INFO: Ignoring NotFound error while getting pod default/no-such-pod") {
}, Name: "[It] pod not running",
Failure: `error while waiting for pod default/no-such-pod to be running: pods "no-such-pod" not found`, Status: "failed",
Stack: `k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.1() Failure: &reporters.JUnitFailure{
wait_test.go:56`, Description: `[FAILED] wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running
}, In [It] at: wait_test.go:58 <time>
output.TestResult{ `,
Name: "pod not running", Type: "failed",
// "INFO: Pod ..." will normally occur every two seconds, },
// but we reduce it to one line because it might occur less often SystemErr: `> Enter [It] not running - wait_test.go:57 <time>
// on a loaded system. INFO: Waiting up to 5s for pod "pending-pod" in namespace "default" to be "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: <elapsed> INFO: Pod "pending-pod": Phase="", Reason="", readiness=false. Elapsed: <elapsed>
INFO: Unexpected error: wait for pod pending-pod running: INFO: Unexpected error: wait for pod pending-pod running:
<*pod.timeoutError>: { <*pod.timeoutError>: {
@ -205,21 +218,14 @@ INFO: Unexpected error: wait for pod pending-pod running:
}, },
], ],
} }
FAIL: wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running [FAILED] wait for pod pending-pod running: timed out while waiting for pod default/pending-pod to be running
In [It] at: wait_test.go:58 <time>
Full Stack Trace < Exit [It] not running - wait_test.go:57 <time>
k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
wait_test.go:60
`, `,
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`,
}, },
} }
output.TestGinkgoOutput(t, expected) output.TestGinkgoOutput(t, expected)
} }

View File

@ -22,6 +22,7 @@ import (
"testing" "testing"
"github.com/onsi/ginkgo/v2" "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/reporters"
"k8s.io/kubernetes/test/e2e/framework" "k8s.io/kubernetes/test/e2e/framework"
"k8s.io/kubernetes/test/e2e/framework/internal/output" "k8s.io/kubernetes/test/e2e/framework/internal/output"
@ -70,17 +71,24 @@ func TestSkip(t *testing.T) {
} }
framework.AfterReadingAllFlags(&framework.TestContext) framework.AfterReadingAllFlags(&framework.TestContext)
suiteConfig, reporterConfig := framework.CreateGinkgoConfig() suiteConfig, reporterConfig := framework.CreateGinkgoConfig()
reporterConfig.Verbose = true
expected := output.SuiteResults{ expected := output.TestResult{
output.TestResult{ Suite: reporters.JUnitTestSuite{
Name: "e2e skips", Tests: 1,
Output: `[It] skips Failures: 0,
skipper_test.go:53 Errors: 0,
INFO: skipping 1, 3, 4 Disabled: 0,
`, Skipped: 1,
Failure: `skipping 1, 3, 4`, TestCases: []reporters.JUnitTestCase{
Stack: `k8s.io/kubernetes/test/e2e/framework/skipper_test.glob..func1.1() {
skipper_test.go:54`, Name: "[It] e2e skips",
Status: "skipped",
Skipped: &reporters.JUnitSkipped{
Message: `skipped - skipping 1, 3, 4`,
},
},
},
}, },
} }