Merge pull request #111961 from pohly/e2e-klog-output

e2e: klog output

test/e2e/e2e.go

@@ -95,8 +95,18 @@ var _ = ginkgo.SynchronizedAfterSuite(func() {
 // generated in this directory, and cluster logs will also be saved.
 // This function is called on each Ginkgo node in parallel mode.
 func RunE2ETests(t *testing.T) {
+	// InitLogs disables contextual logging, without a way to enable it again
+	// in the E2E test suite because it has no feature gates. It used to have a
+	// misleading --feature-gates parameter but that didn't do what users
+	// and developers expected (define which features the cluster supports)
+	// and therefore got removed.
+	//
+	// Because contextual logging is useful and should get tested, it gets
+	// re-enabled here unconditionally.
 	logs.InitLogs()
 	defer logs.FlushLogs()
+	klog.EnableContextualLogging(true)
+
 	progressReporter = e2ereporters.NewProgressReporter(framework.TestContext.ProgressReportURL)
 	gomega.RegisterFailHandler(framework.Fail)
 

test/e2e/framework/internal/output/output.go

@@ -44,7 +44,7 @@ func TestGinkgoOutput(t *testing.T, expected SuiteResults, runSpecsArgs ...inter
 	// Now check the output.
 	actual := normalizeReport(report)
 
-	if assert.Equal(t, len(expected), len(actual), "Should have %d test results, got: %v", actual) {
+	if assert.Equal(t, len(expected), len(actual), "Should have %d test results, got: %v", len(expected), actual) {
 		for i := 0; i < len(expected); i++ {
 			assert.Equal(t, expected[i].Name, actual[i].Name, "name from test #%d", i)
 			output := actual[i].Output
@@ -127,6 +127,9 @@ var stackLocation = regexp.MustCompile(`(?:/|vendor/|test/|GOROOT/).*/([[:^space
 // functionArgs matches "<function name>(...)".
 var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`)
 
+// klogPrefix matches "I0822 16:10:39.343790  989127 "
+var klogPrefix = regexp.MustCompile(`(?m)^[IEF][[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}[[:space:]]+[[:digit:]]+ `)
+
 // testFailureOutput matches TestFailureOutput() and its source followed by additional stack entries:
 //
 // k8s.io/kubernetes/test/e2e/framework/pod/pod_test.TestFailureOutput(0xc000558800)
@@ -149,5 +152,6 @@ func normalizeLocation(in string) string {
 	out = stackLocation.ReplaceAllString(out, "$1")
 	out = functionArgs.ReplaceAllString(out, "$1()")
 	out = testFailureOutput.ReplaceAllString(out, "")
+	out = klogPrefix.ReplaceAllString(out, "<klog> ")
 	return out
 }

test/e2e/framework/log_test.go

@@ -18,10 +18,15 @@ package framework_test
 
 import (
 	"errors"
+	"os"
+	"path"
 	"testing"
 
 	"github.com/onsi/ginkgo/v2"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 
+	"k8s.io/klog/v2"
 	"k8s.io/kubernetes/test/e2e/framework"
 	"k8s.io/kubernetes/test/e2e/framework/internal/output"
 )
@@ -31,11 +36,6 @@ import (
 // Here are some intentionally blank lines that can be removed to compensate
 // for future additional import statements.
 //
-//
-//
-//
-//
-//
 // This must be line #39.
 
 // This is included in a stack backtrace.
@@ -69,6 +69,10 @@ var _ = ginkgo.Describe("log", func() {
 	ginkgo.It("fails with helper", func() {
 		failHelper("I'm failing with helper.")
 	})
+	ginkgo.It("redirects klog", func() {
+		klog.Info("hello world")
+		klog.Error(nil, "not really an error")
+	})
 })
 
 func TestFailureOutput(t *testing.T) {
@@ -172,7 +176,43 @@ k8s.io/kubernetes/test/e2e/framework_test.glob..func1.7()
 k8s.io/kubernetes/test/e2e/framework_test.glob..func1.7()
 	log_test.go:70`,
 		},
+		output.TestResult{
+			Name: "log redirects klog",
+			Output: `INFO: before
+<klog> log_test.go:73] hello world
+<klog> log_test.go:74] <nil>not really an error` + commonOutput,
+			Failure: `true is never false either
+Expected
+    <bool>: true
+to equal
+    <bool>: false`,
+			Stack: `k8s.io/kubernetes/test/e2e/framework_test.glob..func1.2()
+	log_test.go:52`,
+		},
 	}
 
+	// Simulate the test setup as in a normal e2e test which uses the
+	// framework, but remember to restore klog settings when we are done.
+	state := klog.CaptureState()
+	defer state.Restore()
+	var testContext framework.TestContextType
+	framework.AfterReadingAllFlags(&testContext)
+
+	oldStderr := os.Stderr
+	tmp := t.TempDir()
+	filename := path.Join(tmp, "stderr.log")
+	f, err := os.Create(filename)
+	require.NoError(t, err, "create temporary file")
+	os.Stderr = f
+	defer func() {
+		os.Stderr = oldStderr
+
+		err := f.Close()
+		require.NoError(t, err, "close temporary file")
+		actual, err := os.ReadFile(filename)
+		require.NoError(t, err, "read temporary file")
+		assert.Empty(t, string(actual), "no output on stderr")
+	}()
+
 	output.TestGinkgoOutput(t, expected)
 }

test/e2e/framework/test_context.go

@@ -453,6 +453,7 @@ func AfterReadingAllFlags(t *TestContextType) {
 	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)
 
 	// Only set a default host if one won't be supplied via kubeconfig