From c80eec19dd6204d698d54c0a2ee6f253cd0059bb Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 22 Aug 2022 16:58:51 +0200 Subject: [PATCH 1/3] e2e: fix output test assertion The format string didn't match the parameters. --- test/e2e/framework/internal/output/output.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/e2e/framework/internal/output/output.go b/test/e2e/framework/internal/output/output.go index e167e05a0d1..94c98a856e1 100644 --- a/test/e2e/framework/internal/output/output.go +++ b/test/e2e/framework/internal/output/output.go @@ -44,7 +44,7 @@ func TestGinkgoOutput(t *testing.T, expected SuiteResults) { // 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 From 96e9a93a6b071d025e7c26f5c682a1da34c74e84 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 22 Aug 2022 16:05:03 +0200 Subject: [PATCH 2/3] 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 "(...)". 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, " ") 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 + log_test.go:73] hello world + log_test.go:74] not really an error` + commonOutput, + Failure: `true is never false either +Expected + : true +to equal + : 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 From 53d5c6a15b6a67be65d0eb1371b4ca558d58af67 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 18 Aug 2022 15:05:53 +0200 Subject: [PATCH 3/3] e2e: enable contextual logging Contextual logging cannot be enabled manually because there is no feature gate flag. Enabling the feature unconditionally: - should be low risk for E2E testing - if it fails, we want to know - is useful to get better log output from code which already supports it --- test/e2e/e2e.go | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/test/e2e/e2e.go b/test/e2e/e2e.go index b9df43a52d9..c48c46edf95 100644 --- a/test/e2e/e2e.go +++ b/test/e2e/e2e.go @@ -97,8 +97,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)