e2e log: move back to framework, part II

This continues the work in
https://github.com/kubernetes/kubernetes/pull/81426 by also moving the
logger_test.go, moving the log helper code from util.go to log.go (a
more logical place, as it is only used there) and updating comments.

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)
+	skip := offset + 1
-	ginkgowrapper.Fail(nowStamp()+": "+msg, 1+offset)
+	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")
 }

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", msg)
-	log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip))
+	ginkgowrapper.Fail(nowStamp()+": "+msg, 1+offset)
-	ginkgowrapper.Fail(nowStamp()+": "+msg, skip)
 }
 
 // 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")
-}

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    <bool>: true\nto equal\n    <bool>: 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    <bool>: true\nto equal\n    <bool>: 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    <bool>: false\nto equal\n    <bool>: 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    <bool>: false\nto equal\n    <bool>: 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    <bool>: false\nto equal\n    <bool>: 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    <int>: 0\nto equal\n    <int>: 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    <int>: 0\nto equal\n    <int>: 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    <int>: 0\nto equal\n    <int>: 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)
+// k8s.io/kubernetes/test/e2e/framework_test.TestFailureOutput(0xc000558800)
-//	/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:73 +0x1c9
+//	/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.

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 {