diff --git a/test/e2e/BUILD b/test/e2e/BUILD index d9573888c86..348d404fd89 100644 --- a/test/e2e/BUILD +++ b/test/e2e/BUILD @@ -65,7 +65,6 @@ go_library( "//test/e2e/common:go_default_library", "//test/e2e/framework:go_default_library", "//test/e2e/framework/auth:go_default_library", - "//test/e2e/framework/ginkgowrapper:go_default_library", "//test/e2e/framework/log:go_default_library", "//test/e2e/framework/pod:go_default_library", "//test/e2e/framework/providers/aws:go_default_library", 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/BUILD b/test/e2e/framework/log/BUILD index 74015368eca..f0ea02bfb32 100644 --- a/test/e2e/framework/log/BUILD +++ b/test/e2e/framework/log/BUILD @@ -1,4 +1,4 @@ -load("@io_bazel_rules_go//go:def.bzl", "go_library") +load("@io_bazel_rules_go//go:def.bzl", "go_library", "go_test") go_library( name = "go_default_library", @@ -24,3 +24,16 @@ filegroup( tags = ["automanaged"], visibility = ["//visibility:public"], ) + +go_test( + name = "go_default_test", + srcs = ["logger_test.go"], + embed = [":go_default_library"], + deps = [ + "//test/e2e/framework:go_default_library", + "//vendor/github.com/onsi/ginkgo:go_default_library", + "//vendor/github.com/onsi/ginkgo/config:go_default_library", + "//vendor/github.com/onsi/ginkgo/reporters:go_default_library", + "//vendor/github.com/onsi/gomega:go_default_library", + ], +) 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 new file mode 100644 index 00000000000..76439c06298 --- /dev/null +++ b/test/e2e/framework/log/logger_test.go @@ -0,0 +1,169 @@ +/* +Copyright 2019 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 log_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" + + "k8s.io/kubernetes/test/e2e/framework" + "k8s.io/kubernetes/test/e2e/framework/log" +) + +var _ = ginkgo.Describe("log", func() { + ginkgo.BeforeEach(func() { + log.Logf("before") + }) + ginkgo.It("fails", func() { + func() { + log.Failf("I'm failing.") + }() + }) + ginkgo.It("asserts", func() { + gomega.Expect(false).To(gomega.Equal(true), "false is never true") + }) + ginkgo.It("error", func() { + err := errors.New("an error with a long, useless description") + framework.ExpectNoError(err, "hard-coded error") + }) + ginkgo.AfterEach(func() { + log.Logf("after") + gomega.Expect(true).To(gomega.Equal(false), "true is never false either") + }) +}) + +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(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) + actual := normalizeReport(*reporter) + expected := suiteResults{ + testResult{ + 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: 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", + 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", + 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: 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 { + 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: 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:]]+)\(.*\)`) + +// testingStackEntries matches "testing.tRunner" and "created by" entries. +var testingStackEntries = regexp.MustCompile(`(?m)(?:testing\.|created by).*\n\t.*\n`) + +// 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 = testingStackEntries.ReplaceAllString(out, "") + return out +} 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...) }