From 259bb3bef5403daec1bbe44c2c9413ec17b52b6e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 17 Jul 2019 12:52:20 +0200 Subject: [PATCH] e2e: consistent failure logging All failures are worth logging immediately, not just unexpected errors. That helps understand tests that have long-running cleanup operations with their own logging, because the failure will be visible inside the test output. The logging in framework.ExpectNoError also was rather poor, because it only showed the error, but not the additional information about it. Tests suites now should use log.Fail as Gomega failure handler instead of ginkgowrapper.Fail. log.Fail will handle the logging for all failures before proceeding to record the failure in Ginkgo. Because logging is always done also after a test failure, additional failures during cleanup are now visible. Ginkgo itself just ignores them. --- test/e2e/e2e.go | 4 +-- test/e2e/framework/log/logger.go | 13 +++++++- test/e2e/framework/log/logger_test.go | 48 ++++++++++++++++----------- test/e2e/framework/util.go | 4 --- 4 files changed, 43 insertions(+), 26 deletions(-) diff --git a/test/e2e/e2e.go b/test/e2e/e2e.go index f82f557692f..38062834aa4 100644 --- a/test/e2e/e2e.go +++ b/test/e2e/e2e.go @@ -32,7 +32,7 @@ import ( "k8s.io/component-base/logs" commontest "k8s.io/kubernetes/test/e2e/common" "k8s.io/kubernetes/test/e2e/framework" - "k8s.io/kubernetes/test/e2e/framework/ginkgowrapper" + e2elog "k8s.io/kubernetes/test/e2e/framework/log" // ensure auth plugins are loaded _ "k8s.io/client-go/plugin/pkg/client/auth" @@ -71,7 +71,7 @@ func RunE2ETests(t *testing.T) { logs.InitLogs() defer logs.FlushLogs() - gomega.RegisterFailHandler(ginkgowrapper.Fail) + gomega.RegisterFailHandler(e2elog.Fail) // Disable skipped tests unless they are explicitly requested. if config.GinkgoConfig.FocusString == "" && config.GinkgoConfig.SkipString == "" { config.GinkgoConfig.SkipString = `\[Flaky\]|\[Feature:.+\]` diff --git a/test/e2e/framework/log/logger.go b/test/e2e/framework/log/logger.go index 039119e7572..c57c15d5a5d 100644 --- a/test/e2e/framework/log/logger.go +++ b/test/e2e/framework/log/logger.go @@ -48,6 +48,17 @@ func Failf(format string, args ...interface{}) { // (for example, for call chain f -> g -> FailfWithOffset(1, ...) error would be logged for "f"). func FailfWithOffset(offset int, format string, args ...interface{}) { msg := fmt.Sprintf(format, args...) - log("INFO", msg) + log("FAIL", msg) ginkgowrapper.Fail(nowStamp()+": "+msg, 1+offset) } + +// Fail is a replacement for ginkgo.Fail which logs the problem as it occurs +// and then calls ginkgowrapper.Fail. +func Fail(msg string, callerSkip ...int) { + skip := 1 + if len(callerSkip) > 0 { + skip += callerSkip[0] + } + log("FAIL", msg) + ginkgowrapper.Fail(nowStamp()+": "+msg, skip) +} diff --git a/test/e2e/framework/log/logger_test.go b/test/e2e/framework/log/logger_test.go index 834db0457d9..469a61c5c7d 100644 --- a/test/e2e/framework/log/logger_test.go +++ b/test/e2e/framework/log/logger_test.go @@ -29,7 +29,6 @@ import ( "github.com/onsi/gomega" "k8s.io/kubernetes/test/e2e/framework" - "k8s.io/kubernetes/test/e2e/framework/ginkgowrapper" "k8s.io/kubernetes/test/e2e/framework/log" ) @@ -46,7 +45,7 @@ var _ = ginkgo.Describe("log", func() { gomega.Expect(false).To(gomega.Equal(true), "false is never true") }) ginkgo.It("error", func() { - err := errors.New("I'm an error, nice to meet to.") + err := errors.New("an error with a long, useless description") framework.ExpectNoError(err, "hard-coded error") }) ginkgo.AfterEach(func() { @@ -60,39 +59,50 @@ func TestFailureOutput(t *testing.T) { // 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(ginkgowrapper.Fail) + gomega.RegisterFailHandler(log.Fail) fakeT := &testing.T{} reporter := reporters.NewFakeReporter() ginkgo.RunSpecsWithDefaultAndCustomReporters(fakeT, "Logging Suite", []ginkgo.Reporter{reporter}) // Now check the output. + // TODO: all of the stacks are currently broken because Ginkgo doesn't properly skip + // over the initial entries returned by runtime.Stack. Fix is pending in + // https://github.com/onsi/ginkgo/pull/590, "stack" texts need to be updated + // when updating to a fixed Ginkgo. g := gomega.NewGomegaWithT(t) - g.Expect(normalizeReport(*reporter)).To(gomega.Equal(suiteResults{ + actual := normalizeReport(*reporter) + expected := suiteResults{ testResult{ - name: "[Top Level] log asserts", - // TODO: also log the failed assertion as it happens - output: "INFO: before\nINFO: after\n", + name: "[Top Level] log asserts", + output: "INFO: before\nFAIL: false is never true\nExpected\n : false\nto equal\n : true\nINFO: after\nFAIL: true is never false either\nExpected\n : true\nto equal\n : false\n", failure: "false is never true\nExpected\n : false\nto equal\n : true", - // TODO: ginkowrapper.Fail should also prune this stack. - stack: "\tassertion.go:75\nk8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To()\n\tassertion.go:38\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3()\n\tlogger_test.go:46\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:66\n", + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3() + stack: "\tassertion.go:75\nk8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To()\n\tassertion.go:38\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3()\n\tlogger_test.go:45\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", }, testResult{ - name: "[Top Level] log error", - // TODO: the additional information about the error should be logged - output: "INFO: before\nINFO: Unexpected error occurred: I'm an error, nice to meet to.\nINFO: after\n", - failure: "hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"I'm an error, nice to meet to.\",\n }\n I'm an error, nice to meet to.\noccurred", - // TODO: ginkowrapper.Fail should also prune this stack. + name: "[Top Level] log error", + output: "INFO: before\nFAIL: hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"an error with a long, useless description\",\n }\n an error with a long, useless description\noccurred\nINFO: after\nFAIL: true is never false either\nExpected\n : true\nto equal\n : false\n", + failure: "hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"an error with a long, useless description\",\n }\n an error with a long, useless description\noccurred", + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4() stack: "\tutil.go:1362\nk8s.io/kubernetes/test/e2e/framework.ExpectNoError()\n\tutil.go:1356\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()\n\tlogger_test.go:49\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", }, testResult{ - name: "[Top Level] log fails", - // TODO: why is the failure log as "INFO"? - output: "INFO: before\nINFO: I'm failing.\nINFO: after\n", + name: "[Top Level] log fails", + output: "INFO: before\nFAIL: I'm failing.\nINFO: after\nFAIL: true is never false either\nExpected\n : true\nto equal\n : false\n", failure: "I'm failing.", - // TODO: ginkowrapper.Fail should also prune this stack. + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...) stack: "\tlogger.go:52\nk8s.io/kubernetes/test/e2e/framework/log.Failf()\n\tlogger.go:44\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)\n\tlogger_test.go:41\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()\n\tlogger_test.go:42\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", }, - })) + } + // Compare individual fields. Comparing the slices leads to unreadable error output when there is any mismatch. + g.Expect(len(actual)).To(gomega.Equal(len(expected)), "%d entries in %v", len(expected), actual) + for i, a := range actual { + b := expected[i] + g.Expect(a.name).To(gomega.Equal(b.name), "name in %d", i) + g.Expect(a.output).To(gomega.Equal(b.output), "output in %d", i) + g.Expect(a.failure).To(gomega.Equal(b.failure), "failure in %d", i) + g.Expect(a.stack).To(gomega.Equal(b.stack), "stack in %d", i) + } } type testResult struct { diff --git a/test/e2e/framework/util.go b/test/e2e/framework/util.go index 4891cbfc3bc..46a0aef671f 100644 --- a/test/e2e/framework/util.go +++ b/test/e2e/framework/util.go @@ -1359,10 +1359,6 @@ 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{}) { - if err != nil { - e2elog.Logf("Unexpected error occurred: %v", err) - debug.PrintStack() - } gomega.ExpectWithOffset(1+offset, err).NotTo(gomega.HaveOccurred(), explain...) }