From dd0cee4895580c40f2ef7ab9d822757424d9bf09 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 19 Jan 2024 19:04:02 +0100 Subject: [PATCH 1/2] e2e node runner: remove dependency on e2e/framework A stand-alone binary shouldn't import the test/e2e/framework, which is targeted towards usage in a Ginkgo test suite. This currently works, but will break once test/e2e/framework becomes more opinionated about how to configure logging. The simplest solution is to duplicate the one short function that the binary was calling in the framework. --- test/e2e/framework/test_context.go | 6 +++--- test/e2e_node/remote/node_conformance.go | 21 +++++++++++++++++++-- 2 files changed, 22 insertions(+), 5 deletions(-) diff --git a/test/e2e/framework/test_context.go b/test/e2e/framework/test_context.go index 6ffb4d18bf3..bdca80299a9 100644 --- a/test/e2e/framework/test_context.go +++ b/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)) @@ -548,7 +548,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") } diff --git a/test/e2e_node/remote/node_conformance.go b/test/e2e_node/remote/node_conformance.go index 551499972d6..2f9a9e8100c 100644 --- a/test/e2e_node/remote/node_conformance.go +++ b/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 +} From 43539c855f59f3318de73602d091c62ee5863cda Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 11 Jan 2024 12:45:51 +0100 Subject: [PATCH 2/2] e2e framework: unify logging, support skipping helpers ginkgo.GinkgoHelper is a recent addition to ginkgo which allows functions to mark themselves as helper. This then changes which callstack gets reported for failures. It makes sense to support the same mechanism also for logging. There's also no reason why framework.Logf should produce output that is in a different format than klog log entries. Having time stamps formatted differently makes it hard to read test output which uses a mixture of both. Another user-visible advantage is that the error log entry from framework.ExpectNoError now references the test source code. With textlogger there is a simple replacement for klog that can be reconfigured to let the caller handle stack unwinding. klog itself doesn't support that and should be modified to support it (feature freeze). Emitting printf-style output via that logger would work, but become less readable because the message string would get quoted instead of printing it verbatim as before. So instead, the traditional klog header gets reproduced in the framework code. In this example, the first line is from klog, the second from Logf: I0111 11:00:54.088957 332873 factory.go:193] Registered Plugin "containerd" ... I0111 11:00:54.987534 332873 util.go:506] >>> kubeConfig: /var/run/kubernetes/admin.kubeconfig Indention is a bit different because the initial output is printed before installing the logger which writes through ginkgo.GinkgoWriter. One welcome side effect is that now "go vet" detects mismatched parameters for framework.Logf because fmt.Sprintf is called without mangling the format string. Some of the calls were incorrect. --- test/e2e/framework/expect.go | 4 +- test/e2e/framework/ginkgologger.go | 100 ++++++++++++++++++ .../unittests/cleanup/cleanup_test.go | 33 +++--- test/e2e/framework/log.go | 15 +-- test/e2e/framework/log_test.go | 26 ++--- test/e2e/framework/pod/wait_test.go | 6 +- test/e2e/framework/test_context.go | 7 -- test/e2e/network/service.go | 4 +- test/e2e/storage/csi_mock/base.go | 2 +- test/e2e_node/node_shutdown_linux_test.go | 2 +- test/e2e_node/topology_manager_test.go | 2 +- 11 files changed, 148 insertions(+), 53 deletions(-) create mode 100644 test/e2e/framework/ginkgologger.go diff --git a/test/e2e/framework/expect.go b/test/e2e/framework/expect.go index 726e754b33f..aec75b3fb6a 100644 --- a/test/e2e/framework/expect.go +++ b/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) } diff --git a/test/e2e/framework/ginkgologger.go b/test/e2e/framework/ginkgologger.go new file mode 100644 index 00000000000..05f22eff387 --- /dev/null +++ b/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) +} diff --git a/test/e2e/framework/internal/unittests/cleanup/cleanup_test.go b/test/e2e/framework/internal/unittests/cleanup/cleanup_test.go index d86bdcc3bee..a0a2059b6bb 100644 --- a/test/e2e/framework/internal/unittests/cleanup/cleanup_test.go +++ b/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