From 96e9a93a6b071d025e7c26f5c682a1da34c74e84 Mon Sep 17 00:00:00 2001
From: Patrick Ohly <patrick.ohly@intel.com>
Date: Mon, 22 Aug 2022 16:05:03 +0200
Subject: [PATCH] e2e: disable double printing of errors

We don't want klog to print to anything other than GinkgoWriter, but it still
used os.Stderr in addition to GinkgoWriter when printing log entries with
severity >= error. Changing "stderrthreshold" fixes that.

The unit test for framework output handling didn't test klog behavior. Now it
does:
- os.Stderr is redirected, should be empty
- a new test invokes klog
---
 test/e2e/framework/internal/output/output.go |  4 ++
 test/e2e/framework/log_test.go               | 50 ++++++++++++++++++--
 test/e2e/framework/test_context.go           |  1 +
 3 files changed, 50 insertions(+), 5 deletions(-)

diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go
index 94c98a856e1..288a21bc748 100644
--- a/test/e2e/framework/internal/output/output.go
+++ b/test/e2e/framework/internal/output/output.go
@@ -123,6 +123,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)
@@ -145,5 +148,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
 }
diff --git a/test/e2e/framework/log_test.go b/test/e2e/framework/log_test.go
index 5009b597682..e1efb52131b 100644
--- a/test/e2e/framework/log_test.go
+++ b/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)
 }
diff --git a/test/e2e/framework/test_context.go b/test/e2e/framework/test_context.go
index 6d8e1c7e12e..6d5e2a52fd3 100644
--- a/test/e2e/framework/test_context.go
+++ b/test/e2e/framework/test_context.go
@@ -491,6 +491,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