Merge pull request #122865 from pohly/e2e-framework-logging

e2e framework: unify logging, support skipping helpers

test/e2e/framework/expect.go

@@ -350,9 +350,9 @@ func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) {
 	// because it is not included in the failure message.
 	var failure FailureError
 	if errors.As(err, &failure) && failure.Backtrace() != "" {
-		Logf("Failed inside E2E framework:\n    %s", strings.ReplaceAll(failure.Backtrace(), "\n", "\n    "))
+		log(offset+1, fmt.Sprintf("Failed inside E2E framework:\n    %s", strings.ReplaceAll(failure.Backtrace(), "\n", "\n    ")))
 	} else if !errors.Is(err, ErrFailure) {
-		Logf("Unexpected error: %s\n%s", prefix, format.Object(err, 1))
+		log(offset+1, fmt.Sprintf("Unexpected error: %s\n%s", prefix, format.Object(err, 1)))
 	}
 	Fail(prefix+err.Error(), 1+offset)
 }

test/e2e/framework/ginkgologger.go

@@ -0,0 +1,100 @@
+/*
+Copyright 2015 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 framework contains provider-independent helper code for
+// building and running E2E tests with Ginkgo. The actual Ginkgo test
+// suites gets assembled by combining this framework, the optional
+// provider support code and specific tests via a separate .go file
+// like Kubernetes' test/e2e.go.
+package framework
+
+import (
+	"flag"
+	"fmt"
+	"os"
+	"strings"
+	"time"
+
+	"github.com/onsi/ginkgo/v2"
+	ginkgotypes "github.com/onsi/ginkgo/v2/types"
+
+	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/textlogger"
+
+	_ "k8s.io/component-base/logs/testinit" // Ensure command line flags are registered.
+)
+
+var (
+	logConfig = textlogger.NewConfig(
+		textlogger.Output(ginkgo.GinkgoWriter),
+		textlogger.Backtrace(unwind),
+	)
+	ginkgoLogger = textlogger.NewLogger(logConfig)
+	TimeNow      = time.Now    // Can be stubbed out for testing.
+	Pid          = os.Getpid() // Can be stubbed out for testing.
+)
+
+func init() {
+	// ktesting and testinit already registered the -v and -vmodule
+	// command line flags. To configure the textlogger instead, we
+	// need to swap out the flag.Value for those.
+	var fs flag.FlagSet
+	logConfig.AddFlags(&fs)
+	fs.VisitAll(func(loggerFlag *flag.Flag) {
+		klogFlag := flag.CommandLine.Lookup(loggerFlag.Name)
+		if klogFlag != nil {
+			klogFlag.Value = loggerFlag.Value
+		}
+	})
+
+	// Now install the textlogger as the klog default logger.
+	// Calls like klog.Info then will write to ginkgo.GingoWriter
+	// through the textlogger.
+	//
+	// However, stack unwinding is then still being done by klog and thus
+	// ignores ginkgo.GingkoHelper. Tests should use framework.Logf or
+	// structured, contextual logging.
+	writer, _ := ginkgoLogger.GetSink().(textlogger.KlogBufferWriter)
+	opts := []klog.LoggerOption{
+		klog.ContextualLogger(true),
+		klog.WriteKlogBuffer(writer.WriteKlogBuffer),
+	}
+	klog.SetLoggerWithOptions(ginkgoLogger, opts...)
+}
+
+func unwind(skip int) (string, int) {
+	location := ginkgotypes.NewCodeLocation(skip + 1)
+	return location.FileName, location.LineNumber
+}
+
+// log re-implements klog.Info: same header, but stack unwinding
+// with support for ginkgo.GinkgoWriter and skipping stack levels.
+func log(offset int, msg string) {
+	now := TimeNow()
+	file, line := unwind(offset + 1)
+	if file == "" {
+		file = "???"
+		line = 1
+	} else if slash := strings.LastIndex(file, "/"); slash >= 0 {
+		file = file[slash+1:]
+	}
+	_, month, day := now.Date()
+	hour, minute, second := now.Clock()
+	header := fmt.Sprintf("I%02d%02d %02d:%02d:%02d.%06d %d %s:%d]",
+		month, day, hour, minute, second, now.Nanosecond()/1000, Pid, file, line)
+
+	fmt.Fprintln(ginkgo.GinkgoWriter, header, msg)
+}

test/e2e/framework/internal/unittests/cleanup/cleanup_test.go

@@ -61,7 +61,7 @@ func init() {
 
 var _ = ginkgo.Describe("e2e", func() {
 	ginkgo.BeforeEach(func() {
-		framework.Logf("before")
+		logBeforeHelper()
 	})
 
 	f := framework.NewDefaultFramework("test-namespace")
@@ -107,35 +107,42 @@ var _ = ginkgo.Describe("e2e", func() {
 	})
 })
 
+// logBeforeHelper must be skipped when doing stack unwinding in the logging
+// implementation.
+func logBeforeHelper() {
+	ginkgo.GinkgoHelper()
+	framework.Logf("before")
+}
+
 const (
 	ginkgoOutput = `> Enter [BeforeEach] e2e - cleanup_test.go:63 <time>
-INFO: before
+<klog> cleanup_test.go:64] before
 < Exit [BeforeEach] e2e - cleanup_test.go:63 <time>
 > Enter [BeforeEach] e2e - set up framework | framework.go:xxx <time>
 STEP: Creating a kubernetes client - framework.go:xxx <time>
-INFO: >>> kubeConfig: yyy/kube.config
+<klog> util.go:xxx] >>> kubeConfig: yyy/kube.config
 STEP: Building a namespace api object, basename test-namespace - framework.go:xxx <time>
-INFO: Skipping waiting for service account
+<klog> framework.go:xxx] Skipping waiting for service account
 < Exit [BeforeEach] e2e - set up framework | framework.go:xxx <time>
 > Enter [BeforeEach] e2e - cleanup_test.go:56 <time>
-INFO: extension before
+<klog> cleanup_test.go:56] extension before
 < Exit [BeforeEach] e2e - cleanup_test.go:56 <time>
 > Enter [BeforeEach] e2e - cleanup_test.go:71 <time>
-INFO: before #1
+<klog> cleanup_test.go:72] before #1
 < Exit [BeforeEach] e2e - cleanup_test.go:71 <time>
 > Enter [BeforeEach] e2e - cleanup_test.go:75 <time>
-INFO: before #2
+<klog> cleanup_test.go:76] before #2
 < Exit [BeforeEach] e2e - cleanup_test.go:75 <time>
 > Enter [It] works - cleanup_test.go:90 <time>
 < Exit [It] works - cleanup_test.go:90 <time>
 > Enter [AfterEach] e2e - cleanup_test.go:57 <time>
-INFO: extension after
+<klog> cleanup_test.go:57] extension after
 < Exit [AfterEach] e2e - cleanup_test.go:57 <time>
 > Enter [AfterEach] e2e - cleanup_test.go:79 <time>
-INFO: after #1
+<klog> cleanup_test.go:80] after #1
 < Exit [AfterEach] e2e - cleanup_test.go:79 <time>
 > Enter [AfterEach] e2e - cleanup_test.go:86 <time>
-INFO: after #2
+<klog> cleanup_test.go:87] after #2
 < Exit [AfterEach] e2e - cleanup_test.go:86 <time>
 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:103 <time>
 [FAILED] DeferCleanup callback returned error: fake error for "failure"
@@ -144,10 +151,10 @@ In [DeferCleanup (Each)] at: cleanup_test.go:103 <time>
 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:99 <time>
 < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:99 <time>
 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:95 <time>
-INFO: cleanup first
+<klog> cleanup_test.go:96] cleanup first
 < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:95 <time>
 > Enter [DeferCleanup (Each)] e2e - cleanup_test.go:92 <time>
-INFO: cleanup last
+<klog> cleanup_test.go:93] cleanup last
 < Exit [DeferCleanup (Each)] e2e - cleanup_test.go:92 <time>
 > Enter [DeferCleanup (Each)] e2e - dump namespaces | framework.go:xxx <time>
 < Exit [DeferCleanup (Each)] e2e - dump namespaces | framework.go:xxx <time>
@@ -228,7 +235,7 @@ In [DeferCleanup (Each)] at: cleanup_test.go:103 <time>
 func normalizeOutput(output string) string {
 	for exp, replacement := range map[string]string{
 		// Ignore line numbers inside framework source code (likely to change).
-		`framework\.go:\d+`: `framework.go:xxx`,
+		`(framework|util)\.go:\d+`: `$1.go:xxx`,
 		// Config file name varies for each run.
 		`kubeConfig: .*/kube.config`: `kubeConfig: yyy/kube.config`,
 		// Random suffix for namespace.

test/e2e/framework/log.go

@@ -18,22 +18,17 @@ package framework
 
 import (
 	"fmt"
-	"time"
 
 	"github.com/onsi/ginkgo/v2"
 )
 
-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.
+//
+// Use this instead of `klog.Infof` because stack unwinding automatically
+// skips over helper functions which marked themselves as helper by
+// calling [ginkgo.GinkgoHelper].
 func Logf(format string, args ...interface{}) {
-	log("INFO", format, args...)
+	log(1, fmt.Sprintf(format, args...))
 }
 
 // Failf logs the fail info, including a stack trace starts with its direct caller

test/e2e/framework/log_test.go

@@ -98,14 +98,14 @@ There were additional failures detected after the initial failure. These are vis
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] fails - log_test.go:55 <time>
 [FAILED] I'm failing.
 In [It] at: log_test.go:57 <time>
 < Exit [It] fails - log_test.go:55 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true
@@ -129,7 +129,7 @@ There were additional failures detected after the initial failure. These are vis
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] asserts - log_test.go:60 <time>
 [FAILED] false is never true
@@ -139,7 +139,7 @@ to be true
 In [It] at: log_test.go:61 <time>
 < Exit [It] asserts - log_test.go:60 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true
@@ -160,10 +160,10 @@ There were additional failures detected after the initial failure. These are vis
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] error - log_test.go:63 <time>
-INFO: Unexpected error: hard-coded error: 
+<klog> log_test.go:65] Unexpected error: hard-coded error: 
     <*errors.errorString>: 
     an error with a long, useless description
     {
@@ -173,7 +173,7 @@ INFO: Unexpected error: hard-coded error:
 In [It] at: log_test.go:65 <time>
 < Exit [It] error - log_test.go:63 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true
@@ -198,7 +198,7 @@ There were additional failures detected after the initial failure. These are vis
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] equal - log_test.go:67 <time>
 [FAILED] of course it's not equal...
@@ -209,7 +209,7 @@ to equal
 In [It] at: log_test.go:68 <time>
 < Exit [It] equal - log_test.go:67 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true
@@ -230,14 +230,14 @@ There were additional failures detected after the initial failure. These are vis
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] fails with helper - log_test.go:70 <time>
 [FAILED] I'm failing with helper.
 In [It] at: log_test.go:44 <time>
 < Exit [It] fails with helper - log_test.go:70 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true
@@ -259,14 +259,14 @@ In [AfterEach] at: log_test.go:53 <time>
 `,
 					},
 					SystemErr: `> Enter [BeforeEach] log - log_test.go:48 <time>
-INFO: before
+<klog> log_test.go:49] before
 < Exit [BeforeEach] log - log_test.go:48 <time>
 > Enter [It] redirects klog - log_test.go:73 <time>
 <klog> log_test.go:74] hello world
 <klog> log_test.go:75] <nil>not really an error
 < Exit [It] redirects klog - log_test.go:73 <time>
 > Enter [AfterEach] log - log_test.go:51 <time>
-INFO: after
+<klog> log_test.go:52] after
 [FAILED] true is never false either
 Expected
     <bool>: true

test/e2e/framework/pod/wait_test.go

@@ -173,7 +173,7 @@ In [It] at: wait_test.go:58 <time>
 `,
 					},
 					SystemErr: `> Enter [It] not found, retry - wait_test.go:57 <time>
-INFO: Failed inside E2E framework:
+<klog> wait_test.go:58] Failed inside E2E framework:
     k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
     	wait.go
     k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.2()
@@ -340,7 +340,7 @@ In [It] at: wait_test.go:71 <time>
 					},
 					SystemErr: `> Enter [It] not running - wait_test.go:69 <time>
 STEP: waiting for pod pending-pod to run - wait_test.go:70 <time>
-INFO: Failed inside E2E framework:
+<klog> wait_test.go:71] Failed inside E2E framework:
     k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
     	wait.go
     k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.5()
@@ -372,7 +372,7 @@ In [It] at: wait_test.go:75 <time>
 						Type: "failed",
 					},
 					SystemErr: `> Enter [It] failed - wait_test.go:74 <time>
-INFO: Failed inside E2E framework:
+<klog> wait_test.go:75] Failed inside E2E framework:
     k8s.io/kubernetes/test/e2e/framework/pod.WaitTimeoutForPodRunningInNamespace()
     	wait.go
     k8s.io/kubernetes/test/e2e/framework/pod_test.glob..func1.6()

test/e2e/framework/test_context.go

@@ -465,10 +465,10 @@ func RegisterClusterFlags(flags *flag.FlagSet) {
 	flags.DurationVar(&nodeKiller.SimulatedDowntime, "node-killer-simulated-downtime", 10*time.Minute, "A delay between node death and recreation")
 }
 
-// GenerateSecureToken returns a string of length tokenLen, consisting
+// generateSecureToken returns a string of length tokenLen, consisting
 // of random bytes encoded as base64 for use as a Bearer Token during
 // communication with an APIServer
-func GenerateSecureToken(tokenLen int) (string, error) {
+func generateSecureToken(tokenLen int) (string, error) {
 	// Number of bytes to be tokenLen when base64 encoded.
 	tokenSize := math.Ceil(float64(tokenLen) * 6 / 8)
 	rawToken := make([]byte, int(tokenSize))
@@ -492,13 +492,6 @@ func AfterReadingAllFlags(t *TestContextType) {
 	if t.KubeTestRepoList != "" {
 		image.Init(t.KubeTestRepoList)
 	}
-	var fs flag.FlagSet
-	klog.InitFlags(&fs)
-	fs.Set("logtostderr", "false")
-	fs.Set("alsologtostderr", "false")
-	fs.Set("one_output", "true")
-	fs.Set("stderrthreshold", "10" /* higher than any of the severities -> none pass the threshold */)
-	klog.SetOutput(ginkgo.GinkgoWriter)
 
 	if t.ListImages {
 		for _, v := range image.GetImageConfigs() {
@@ -548,7 +541,7 @@ func AfterReadingAllFlags(t *TestContextType) {
 	}
 	if len(t.BearerToken) == 0 {
 		var err error
-		t.BearerToken, err = GenerateSecureToken(16)
+		t.BearerToken, err = generateSecureToken(16)
 		ExpectNoError(err, "Failed to generate bearer token")
 	}
 

test/e2e/network/service.go

@@ -2773,7 +2773,7 @@ var _ = common.SIGDescribe("Services", func() {
 			cmd := fmt.Sprintf(`curl -s -o /dev/null -w "%%{http_code}" --max-time 5 http://%s/healthz`, healthCheckNodePortAddr)
 			out, err := e2eoutput.RunHostCmd(pausePod0.Namespace, pausePod0.Name, cmd)
 			if err != nil {
-				framework.Logf("unexpected error trying to connect to nodeport %d : %v", healthCheckNodePortAddr, err)
+				framework.Logf("unexpected error trying to connect to nodeport %s : %v", healthCheckNodePortAddr, err)
 				return false, nil
 			}
 
@@ -2796,7 +2796,7 @@ var _ = common.SIGDescribe("Services", func() {
 			cmd := fmt.Sprintf(`curl -s -o /dev/null -w "%%{http_code}" --max-time 5 http://%s/healthz`, healthCheckNodePortAddr)
 			out, err := e2eoutput.RunHostCmd(pausePod0.Namespace, pausePod0.Name, cmd)
 			if err != nil {
-				framework.Logf("unexpected error trying to connect to nodeport %d : %v", healthCheckNodePortAddr, err)
+				framework.Logf("unexpected error trying to connect to nodeport %s : %v", healthCheckNodePortAddr, err)
 				return false, nil
 			}
 

test/e2e/storage/csi_mock/base.go

@@ -854,7 +854,7 @@ func compareCSICalls(ctx context.Context, trackedCalls []string, expectedCallSeq
 	for i, c := range calls {
 		if i >= len(expectedCallSequence) {
 			// Log all unexpected calls first, return error below outside the loop.
-			framework.Logf("Unexpected CSI driver call: %s (%d)", c.Method, c.FullError)
+			framework.Logf("Unexpected CSI driver call: %s (%v)", c.Method, c.FullError)
 			continue
 		}
 

test/e2e_node/node_shutdown_linux_test.go

@@ -298,7 +298,7 @@ var _ = SIGDescribe("GracefulNodeShutdown", framework.WithSerial(), nodefeature.
 						}
 					} else {
 						if !isPodShutdown(&pod) {
-							framework.Logf("Expecting non-critical pod (%v/%v) to be shutdown, but it's not currently. Pod Status %+v", pod.Name, pod.Status)
+							framework.Logf("Expecting non-critical pod (%v/%v) to be shutdown, but it's not currently. Pod Status %+v", pod.Namespace, pod.Name, pod.Status)
 							return fmt.Errorf("pod (%v/%v) should be shutdown, phase: %s", pod.Namespace, pod.Name, pod.Status.Phase)
 						}
 					}

test/e2e_node/remote/node_conformance.go

@@ -17,7 +17,10 @@ limitations under the License.
 package remote
 
 import (
+	"crypto/rand"
+	"encoding/base64"
 	"fmt"
+	"math"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -27,7 +30,6 @@ import (
 
 	"k8s.io/klog/v2"
 
-	"k8s.io/kubernetes/test/e2e/framework"
 	"k8s.io/kubernetes/test/e2e_node/builder"
 	"k8s.io/kubernetes/test/utils"
 )
@@ -280,7 +282,7 @@ func (c *ConformanceRemote) RunTest(host, workspace, results, imageDesc, junitFi
 		return "", err
 	}
 
-	bearerToken, err := framework.GenerateSecureToken(16)
+	bearerToken, err := generateSecureToken(16)
 	if err != nil {
 		return "", err
 	}
@@ -304,3 +306,18 @@ func (c *ConformanceRemote) RunTest(host, workspace, results, imageDesc, junitFi
 		timeout.Seconds(), podManifestPath, podManifestPath, results, junitFilePrefix, extraEnvs, bearerToken, getConformanceTestImageName(systemSpecName))
 	return SSH(host, "sh", "-c", cmd)
 }
+
+// generateSecureToken returns a string of length tokenLen, consisting
+// of random bytes encoded as base64 for use as a Bearer Token during
+// communication with an APIServer
+func generateSecureToken(tokenLen int) (string, error) {
+	// Number of bytes to be tokenLen when base64 encoded.
+	tokenSize := math.Ceil(float64(tokenLen) * 6 / 8)
+	rawToken := make([]byte, int(tokenSize))
+	if _, err := rand.Read(rawToken); err != nil {
+		return "", err
+	}
+	encoded := base64.RawURLEncoding.EncodeToString(rawToken)
+	token := encoded[:tokenLen]
+	return token, nil
+}

test/e2e_node/topology_manager_test.go

@@ -239,7 +239,7 @@ func configureTopologyManagerInKubelet(oldCfg *kubeletconfig.KubeletConfiguratio
 		}
 	}
 	// Dump the config -- debug
-	framework.Logf("New kubelet config is %s", *newCfg)
+	framework.Logf("New kubelet config is %s", newCfg.String())
 
 	return newCfg, newCfg.ReservedSystemCPUs
 }