From f70c81c9f2c40186794729643e44c4400296c3a6 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 30 Aug 2019 15:28:48 +0200 Subject: [PATCH] e2e log: consistent logging of stack backtrace and failure, part II After merging https://github.com/kubernetes/kubernetes/commit/259bb3bef5403daec1bbe44c2c9413ec17b52b6e#diff-eb7b79470992813ea1905e96c298b47b ExpectEqual and some of the other wrappers logged the failure twice, once inside the wrapper itself and once in the failure handler. Logging the stack backtrace is useful because many assertions still don't contain an explanation and therefore knowing where they occur is crucial. Now all failures are logged with a "Full Stack Trace", not just those with a wrapper. The stack is pruned to skip over wrapper functions and removes Ginkgo internal functions to keep the stack trace smaller. Failures occuring in the wrappers were recorded as occuring in those wrappers. Now the wrappers are skipped and the caller is recorded instead. The full stack trace recorded by Ginkgo 1.10.0 is currently off by one entry. This needs to be fixed in Ginkgo, then the test can be updated. --- test/e2e/framework/log/logger.go | 48 ++++++++++++++++++++-- test/e2e/framework/log/logger_test.go | 57 ++++++++++++++++++++------- test/e2e/framework/util.go | 18 ++------- 3 files changed, 90 insertions(+), 33 deletions(-) diff --git a/test/e2e/framework/log/logger.go b/test/e2e/framework/log/logger.go index d2a4ce45de4..b1efb9d4585 100644 --- a/test/e2e/framework/log/logger.go +++ b/test/e2e/framework/log/logger.go @@ -19,6 +19,9 @@ package log import ( "fmt" + "regexp" + "runtime/debug" + "strings" "time" "github.com/onsi/ginkgo" @@ -41,15 +44,16 @@ func Logf(format string, args ...interface{}) { // Failf logs the fail info. func Failf(format string, args ...interface{}) { - FailfWithOffset(2, format, args...) + FailfWithOffset(1, format, args...) } // FailfWithOffset calls "Fail" and logs the error at "offset" levels above its caller // (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("FAIL", msg) - ginkgowrapper.Fail(nowStamp()+": "+msg, 1+offset) + skip := offset + 1 + log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip)) + ginkgowrapper.Fail(nowStamp()+": "+msg, skip) } // Fail is a replacement for ginkgo.Fail which logs the problem as it occurs @@ -59,6 +63,42 @@ func Fail(msg string, callerSkip ...int) { if len(callerSkip) > 0 { skip += callerSkip[0] } - log("FAIL", msg) + log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip)) ginkgowrapper.Fail(nowStamp()+": "+msg, skip) } + +var codeFilterRE = regexp.MustCompile(`/github.com/onsi/ginkgo/`) + +// PrunedStack is a wrapper around debug.Stack() that removes information +// about the current goroutine and optionally skips some of the initial stack entries. +// With skip == 0, the returned stack will start with the caller of PruneStack. +// From the remaining entries it automatically filters out useless ones like +// entries coming from Ginkgo. +// +// This is a copy of https://github.com/onsi/ginkgo/blob/f90f37d87fa6b1dd9625e2b1e83c23ffae3de228/internal/codelocation/code_location.go#L25 +func PrunedStack(skip int) string { + fullStackTrace := string(debug.Stack()) + stack := strings.Split(fullStackTrace, "\n") + // Ensure that the even entries are the method names and the + // the odd entries the source code information. + if len(stack) > 0 && strings.HasPrefix(stack[0], "goroutine ") { + // Ignore "goroutine 29 [running]:" line. + stack = stack[1:] + } + // The "+2" is for skipping over: + // - runtime/debug.Stack() + // - PrunedStack() + skip += 2 + if len(stack) > 2*skip { + stack = stack[2*skip:] + } + prunedStack := []string{} + for i := 0; i < len(stack)/2; i++ { + // We filter out based on the source code file name. + if !codeFilterRE.Match([]byte(stack[i*2+1])) { + prunedStack = append(prunedStack, stack[i*2]) + prunedStack = append(prunedStack, stack[i*2+1]) + } + } + return strings.Join(prunedStack, "\n") +} diff --git a/test/e2e/framework/log/logger_test.go b/test/e2e/framework/log/logger_test.go index 11770c8a332..1e2a6a31e46 100644 --- a/test/e2e/framework/log/logger_test.go +++ b/test/e2e/framework/log/logger_test.go @@ -32,6 +32,11 @@ import ( "k8s.io/kubernetes/test/e2e/framework/log" ) +func runTests(t *testing.T, reporter ginkgo.Reporter) { + // This source code line will be part of the stack dump comparison. + ginkgo.RunSpecsWithDefaultAndCustomReporters(t, "Logging Suite", []ginkgo.Reporter{reporter}) +} + var _ = ginkgo.Describe("log", func() { ginkgo.BeforeEach(func() { log.Logf("before") @@ -46,7 +51,10 @@ var _ = ginkgo.Describe("log", func() { }) ginkgo.It("error", func() { err := errors.New("an error with a long, useless description") - framework.ExpectNoErrorWithOffset(1, err, "hard-coded error") // ExpectNoError includes util.go in the full stack trace with a varying line number, which we don't want as it makes this test sensitive to unrelated changes. + framework.ExpectNoError(err, "hard-coded error") + }) + ginkgo.It("equal", func() { + framework.ExpectEqual(0, 1, "of course it's not equal...") }) ginkgo.AfterEach(func() { log.Logf("after") @@ -62,7 +70,7 @@ func TestFailureOutput(t *testing.T) { gomega.RegisterFailHandler(log.Fail) fakeT := &testing.T{} reporter := reporters.NewFakeReporter() - ginkgo.RunSpecsWithDefaultAndCustomReporters(fakeT, "Logging Suite", []ginkgo.Reporter{reporter}) + runTests(fakeT, reporter) // Now check the output. // TODO: all of the stacks are currently broken because Ginkgo doesn't properly skip @@ -71,25 +79,39 @@ func TestFailureOutput(t *testing.T) { // when updating to a fixed Ginkgo. g := gomega.NewGomegaWithT(t) actual := normalizeReport(*reporter) + + // output from AfterEach + commonOutput := "\n\nINFO: after\nFAIL: true is never false either\nExpected\n : true\nto equal\n : false\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.6()\n\tlogger_test.go:61\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37\n\n" + + // Sorted by name! 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", + output: "INFO: before\nFAIL: false is never true\nExpected\n : false\nto equal\n : true\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3()\n\tlogger_test.go:50\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37" + commonOutput, failure: "false is never true\nExpected\n : false\nto equal\n : true", - stack: "k8s.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/test/e2e/framework/log_test.TestFailureOutput()\n\tlogger_test.go:65", + // TODO: off-by-one error in Ginkgo, it should skip that first stack entry. + stack: "k8s.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:50\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37\n", + }, + testResult{ + name: "[Top Level] log equal", + output: "INFO: before\nFAIL: of course it's not equal...\nExpected\n : 0\nto equal\n : 1\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.5()\n\tlogger_test.go:57\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37" + commonOutput, + failure: "of course it's not equal...\nExpected\n : 0\nto equal\n : 1", + // TODO: off-by-one error in Ginkgo, it should skip that first stack entry. + stack: "k8s.io/kubernetes/test/e2e/framework.ExpectEqual()\n\tutil.go:1335\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.5()\n\tlogger_test.go:57\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37\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", + 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\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()\n\tlogger_test.go:54\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37" + commonOutput, 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: this skips framework/util.go only because we ExpectNoErrorWithOffset. Should ExpectNoError skip itself? - stack: "k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()\n\tlogger_test.go:49\nk8s.io/kubernetes/test/e2e/framework/log_test.TestFailureOutput()\n\tlogger_test.go:65", + // TODO: off-by-one error in Ginkgo, it should skip that first stack entry. + stack: "k8s.io/kubernetes/test/e2e/framework.ExpectNoError()\n\tutil.go:1350\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()\n\tlogger_test.go:54\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37\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", + output: "INFO: before\nFAIL: I'm failing.\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)\n\tlogger_test.go:46\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()\n\tlogger_test.go:47\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37" + commonOutput, failure: "I'm failing.", - stack: "k8s.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/test/e2e/framework/log_test.TestFailureOutput()\n\tlogger_test.go:65", + // TODO: off-by-one error in Ginkgo, it should skip that first stack entry. + stack: "k8s.io/kubernetes/test/e2e/framework/log.Failf()\n\tlogger.go:47\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)\n\tlogger_test.go:46\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()\n\tlogger_test.go:47\nk8s.io/kubernetes/test/e2e/framework/log_test.runTests()\n\tlogger_test.go:37\n", }, } // Compare individual fields. Comparing the slices leads to unreadable error output when there is any mismatch. @@ -102,7 +124,7 @@ func TestFailureOutput(t *testing.T) { // There may be additional stack entries from the "testing" package at the // end. We ignore those in the comparison because the line number in them // varies. - g.Expect(a.stack).To(gomega.HavePrefix(b.stack), "stack in %d: %s", i, a.stack) + g.Expect(a.stack).To(gomega.Equal(b.stack), "stack in %d: %s", i, a.stack) } } @@ -124,7 +146,7 @@ func normalizeReport(report reporters.FakeReporter) suiteResults { for _, spec := range report.SpecSummaries { results = append(results, testResult{ name: strings.Join(spec.ComponentTexts, " "), - output: stripAddresses(stripTimes(spec.CapturedOutput)), + output: normalizeLocation(stripAddresses(stripTimes(spec.CapturedOutput))), failure: stripAddresses(stripTimes(spec.Failure.Message)), stack: normalizeLocation(spec.Failure.Location.FullStackTrace), }) @@ -156,8 +178,15 @@ var stackLocation = regexp.MustCompile(`(?:/|vendor/|test/|GOROOT/).*/([[:^space // 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`) +// testFailureOutput matches TestFailureOutput() and its source followed by additional stack entries: +// +// k8s.io/kubernetes/test/e2e/framework/log_test.TestFailureOutput(0xc000558800) +// /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_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/log_test\.TestFailureOutput\(.*\n\t.*(\n.*\n\t.*)*`) // normalizeLocation removes path prefix and function parameters and certain stack entries // that we don't care about. @@ -165,6 +194,6 @@ func normalizeLocation(in string) string { out := in out = stackLocation.ReplaceAllString(out, "$1") out = functionArgs.ReplaceAllString(out, "$1()") - out = testingStackEntries.ReplaceAllString(out, "") + out = testFailureOutput.ReplaceAllString(out, "") return out } diff --git a/test/e2e/framework/util.go b/test/e2e/framework/util.go index 294341ff9cd..5a2d0139ecb 100644 --- a/test/e2e/framework/util.go +++ b/test/e2e/framework/util.go @@ -947,29 +947,17 @@ func RandomSuffix() string { // ExpectEqual expects the specified two are the same, otherwise an exception raises func ExpectEqual(actual interface{}, extra interface{}, explain ...interface{}) { - if isEqual, _ := gomega.Equal(extra).Match(actual); !isEqual { - Logf("Unexpected unequal occurred: %v and %v", actual, extra) - debug.PrintStack() - } - gomega.Expect(actual).To(gomega.Equal(extra), explain...) + gomega.ExpectWithOffset(1, actual).To(gomega.Equal(extra), explain...) } // ExpectNotEqual expects the specified two are not the same, otherwise an exception raises func ExpectNotEqual(actual interface{}, extra interface{}, explain ...interface{}) { - if isEqual, _ := gomega.Equal(extra).Match(actual); isEqual { - Logf("Expect to be unequal: %v and %v", actual, extra) - debug.PrintStack() - } - gomega.Expect(actual).NotTo(gomega.Equal(extra), explain...) + gomega.ExpectWithOffset(1, actual).NotTo(gomega.Equal(extra), explain...) } // ExpectError expects an error happens, otherwise an exception raises func ExpectError(err error, explain ...interface{}) { - if err == nil { - Logf("Expect error to occur.") - debug.PrintStack() - } - gomega.Expect(err).To(gomega.HaveOccurred(), explain...) + gomega.ExpectWithOffset(1, err).To(gomega.HaveOccurred(), explain...) } // ExpectNoError checks if "err" is set, and if so, fails assertion while logging the error.