From 311b66ada1e1382158a2b35690fce322a33e8f6a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 17 Jul 2019 11:49:17 +0200 Subject: [PATCH] e2e: unit test for logger.go and ginkgowrapper.go MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This test runs a fake Ginkgo suite with various errors and checks how logger.go respectively ginkgowrapper.go handle this. Right now, the outcome is sub-optimal: - some test failures (those that use framework.Failf or framework.ExpectNoError) are logged immediately, Gomega failures are not - framework.ExpectNoError logs just the error, which is often useless without the additional explanation - failures that occur after some others are not reported at all; this can happen in cleanup code and while that code should better be written so that it contines instead of failing on an assertion, in practice quite a lot of code fails and when it does, the output would be useful to have - the full stack trace is odd and doesn't start with the expected function name Example output: • Failure [0.002 seconds] log /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35 fails [It] /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:39 Jul 17 12:00:52.545: I'm failing. /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:41 Full Stack Trace /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:51 +0x143 k8s.io/kubernetes/test/e2e/framework/log.Failf(...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:43 k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:41 k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2() /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:42 +0x52 k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b020, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8 testing.tRunner(0xc000358600, 0x19818c0) /nvme/gopath/go/src/testing/testing.go:865 +0xc0 created by testing.(*T).Run /nvme/gopath/go/src/testing/testing.go:916 +0x35a ------------------------------ Jul 17 12:00:52.545: INFO: before Jul 17 12:00:52.545: INFO: I'm failing. Jul 17 12:00:52.547: INFO: after • Failure [0.002 seconds] log /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35 asserts [It] /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:44 false is never true Expected : false to equal : true /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:45 Full Stack Trace /nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:75 +0x1f1 k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc00035f6c0, 0x1b42140, 0xc000350dd0, 0xc000350de0, 0x1, 0x1, 0x42e35f) /nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7 k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3() /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:45 +0x17e k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b0e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8 testing.tRunner(0xc000358600, 0x19818c0) /nvme/gopath/go/src/testing/testing.go:865 +0xc0 created by testing.(*T).Run /nvme/gopath/go/src/testing/testing.go:916 +0x35a ------------------------------ Jul 17 12:00:52.548: INFO: before Jul 17 12:00:52.549: INFO: after • Failure [0.002 seconds] log /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35 error [It] /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:47 hard-coded error Unexpected error: <*errors.errorString | 0xc000351930>: { s: "I'm an error, nice to meet to.", } I'm an error, nice to meet to. occurred /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:49 Full Stack Trace /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/util.go:1376 +0x191 k8s.io/kubernetes/test/e2e/framework.ExpectNoError(...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/util.go:1367 k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4() /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:49 +0xc9 k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b200, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...) /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8 testing.tRunner(0xc000358600, 0x19818c0) /nvme/gopath/go/src/testing/testing.go:865 +0xc0 created by testing.(*T).Run /nvme/gopath/go/src/testing/testing.go:916 +0x35a ------------------------------ Jul 17 12:00:52.550: INFO: before Jul 17 12:00:52.550: INFO: Unexpected error occurred: I'm an error, nice to meet to. Jul 17 12:00:52.551: INFO: after --- test/e2e/framework/log/logger_test.go | 158 ++++++++++++++++++++++++++ 1 file changed, 158 insertions(+) create mode 100644 test/e2e/framework/log/logger_test.go diff --git a/test/e2e/framework/log/logger_test.go b/test/e2e/framework/log/logger_test.go new file mode 100644 index 00000000000..834db0457d9 --- /dev/null +++ b/test/e2e/framework/log/logger_test.go @@ -0,0 +1,158 @@ +/* +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/ginkgowrapper" + "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("I'm an error, nice to meet to.") + 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(ginkgowrapper.Fail) + fakeT := &testing.T{} + reporter := reporters.NewFakeReporter() + ginkgo.RunSpecsWithDefaultAndCustomReporters(fakeT, "Logging Suite", []ginkgo.Reporter{reporter}) + + // Now check the output. + g := gomega.NewGomegaWithT(t) + g.Expect(normalizeReport(*reporter)).To(gomega.Equal(suiteResults{ + testResult{ + name: "[Top Level] log asserts", + // TODO: also log the failed assertion as it happens + output: "INFO: before\nINFO: after\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", + }, + 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. + 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", + failure: "I'm failing.", + // TODO: ginkowrapper.Fail should also prune this stack. + 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", + }, + })) +} + +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 "\t//.go:75 +0x1f1". +var stackLocation = regexp.MustCompile(`/.*/([[:^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 +}