diff --git a/test/e2e/framework/log.go b/test/e2e/framework/log.go index 2208a8f9b27..845e0a7cb16 100644 --- a/test/e2e/framework/log.go +++ b/test/e2e/framework/log.go @@ -18,24 +18,88 @@ package framework import ( "fmt" + "regexp" + "runtime/debug" + "strings" + "time" + + "github.com/onsi/ginkgo" "k8s.io/kubernetes/test/e2e/framework/ginkgowrapper" ) +func nowStamp() string { + return time.Now().Format(time.StampMilli) +} + +func log(level string, format string, args ...interface{}) { + fmt.Fprintf(ginkgo.GinkgoWriter, nowStamp()+": "+level+": "+format+"\n", args...) +} + // Logf logs the info. func Logf(format string, args ...interface{}) { log("INFO", format, args...) } -// Failf logs the fail info. +// Failf logs the fail info, including a stack trace. func Failf(format string, args ...interface{}) { FailfWithOffset(1, format, args...) } -// FailfWithOffset calls "Fail" and logs the error at "offset" levels above its caller +// FailfWithOffset calls "Fail" and logs the error with a stack trace that starts 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("INFO", 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 +// together with a stack trace and then calls ginkgowrapper.Fail. +func Fail(msg string, callerSkip ...int) { + skip := 1 + if len(callerSkip) > 0 { + skip += callerSkip[0] + } + 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 modified copy of PruneStack in https://github.com/onsi/ginkgo/blob/f90f37d87fa6b1dd9625e2b1e83c23ffae3de228/internal/codelocation/code_location.go#L25: +// - simplified API and thus renamed (calls debug.Stack() instead of taking a parameter) +// - source code filtering updated to be specific to Kubernetes +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.go b/test/e2e/framework/log/logger.go index b1efb9d4585..51a8663704d 100644 --- a/test/e2e/framework/log/logger.go +++ b/test/e2e/framework/log/logger.go @@ -14,14 +14,12 @@ See the License for the specific language governing permissions and limitations under the License. */ -// Package log should be removed after switching to use core framework log. +// Package log will be removed after switching to use core framework log. +// Do not make further changes here! package log import ( "fmt" - "regexp" - "runtime/debug" - "strings" "time" "github.com/onsi/ginkgo" @@ -51,9 +49,8 @@ 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...) - skip := offset + 1 - log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip)) - ginkgowrapper.Fail(nowStamp()+": "+msg, skip) + log("FAIL", msg) + ginkgowrapper.Fail(nowStamp()+": "+msg, 1+offset) } // Fail is a replacement for ginkgo.Fail which logs the problem as it occurs @@ -63,42 +60,6 @@ func Fail(msg string, callerSkip ...int) { if len(callerSkip) > 0 { skip += callerSkip[0] } - log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip)) + log("FAIL", msg) 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_test.go similarity index 74% rename from test/e2e/framework/log/logger_test.go rename to test/e2e/framework/log_test.go index f2eb8e50f64..8664aee14a6 100644 --- a/test/e2e/framework/log/logger_test.go +++ b/test/e2e/framework/log_test.go @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ -package log_test +package framework_test import ( "errors" @@ -29,9 +29,19 @@ import ( "github.com/onsi/gomega" "k8s.io/kubernetes/test/e2e/framework" - "k8s.io/kubernetes/test/e2e/framework/log" ) +// The line number of the following code is checked in TestFailureOutput below. +// Be careful when moving it around or changing the import statements above. +// Here are some intentionally blank lines that can be removed to compensate +// for future additional import statements. +// +// +// +// +// +// + 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}) @@ -39,11 +49,11 @@ func runTests(t *testing.T, reporter ginkgo.Reporter) { var _ = ginkgo.Describe("log", func() { ginkgo.BeforeEach(func() { - log.Logf("before") + framework.Logf("before") }) ginkgo.It("fails", func() { func() { - log.Failf("I'm failing.") + framework.Failf("I'm failing.") }() }) ginkgo.It("asserts", func() { @@ -57,7 +67,7 @@ var _ = ginkgo.Describe("log", func() { framework.ExpectEqual(0, 1, "of course it's not equal...") }) ginkgo.AfterEach(func() { - log.Logf("after") + framework.Logf("after") gomega.Expect(true).To(gomega.Equal(false), "true is never false either") }) }) @@ -67,7 +77,7 @@ 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(log.Fail) + gomega.RegisterFailHandler(framework.Fail) fakeT := &testing.T{} reporter := reporters.NewFakeReporter() runTests(fakeT, reporter) @@ -77,33 +87,33 @@ func TestFailureOutput(t *testing.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" + 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_test.glob..func1.6()\n\tlog_test.go:71\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47\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\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, + 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_test.glob..func1.3()\n\tlog_test.go:60\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47" + commonOutput, failure: "false is never true\nExpected\n : false\nto equal\n : true", - stack: "k8s.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", + stack: "k8s.io/kubernetes/test/e2e/framework_test.glob..func1.3()\n\tlog_test.go:60\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47\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, + 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_test.glob..func1.5()\n\tlog_test.go:67\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47" + commonOutput, failure: "of course it's not equal...\nExpected\n : 0\nto equal\n : 1", - stack: "k8s.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", + stack: "k8s.io/kubernetes/test/e2e/framework_test.glob..func1.5()\n\tlog_test.go:67\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47\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\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, + 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_test.glob..func1.4()\n\tlog_test.go:64\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47" + 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", - stack: "k8s.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", + stack: "k8s.io/kubernetes/test/e2e/framework_test.glob..func1.4()\n\tlog_test.go:64\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47\n", }, testResult{ name: "[Top Level] log fails", - 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, + output: "INFO: before\nFAIL: I'm failing.\n\nFull Stack Trace\nk8s.io/kubernetes/test/e2e/framework_test.glob..func1.2.1(...)\n\tlog_test.go:56\nk8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()\n\tlog_test.go:57\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47" + commonOutput, failure: "I'm failing.", - stack: "k8s.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", + stack: "k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2.1(...)\n\tlog_test.go:56\nk8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()\n\tlog_test.go:57\nk8s.io/kubernetes/test/e2e/framework_test.runTests()\n\tlog_test.go:47\n", }, } // Compare individual fields. Comparing the slices leads to unreadable error output when there is any mismatch. @@ -172,13 +182,13 @@ var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`) // 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 +// k8s.io/kubernetes/test/e2e/framework_test.TestFailureOutput(0xc000558800) +// /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/log_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.*)*`) +var testFailureOutput = regexp.MustCompile(`(?m)^k8s.io/kubernetes/test/e2e/framework_test\.TestFailureOutput\(.*\n\t.*(\n.*\n\t.*)*`) // normalizeLocation removes path prefix and function parameters and certain stack entries // that we don't care about. diff --git a/test/e2e/framework/util.go b/test/e2e/framework/util.go index 5a2d0139ecb..fa767dfb147 100644 --- a/test/e2e/framework/util.go +++ b/test/e2e/framework/util.go @@ -209,14 +209,6 @@ func GetMasterHost() string { return masterURL.Hostname() } -func nowStamp() string { - return time.Now().Format(time.StampMilli) -} - -func log(level string, format string, args ...interface{}) { - fmt.Fprintf(ginkgo.GinkgoWriter, nowStamp()+": "+level+": "+format+"\n", args...) -} - // RunIfContainerRuntimeIs runs if the container runtime is included in the runtimes. func RunIfContainerRuntimeIs(runtimes ...string) { for _, containerRuntime := range runtimes {