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