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.