Merge pull request #113383 from pohly/e2e-failure-handling

e2e: improve failure handling

test/e2e/cloud/gcp/common/upgrade_mechanics.go

@@ -36,8 +36,6 @@ import (
 // ControlPlaneUpgradeFunc returns a function that performs control plane upgrade.
 func ControlPlaneUpgradeFunc(f *framework.Framework, upgCtx *upgrades.UpgradeContext, testCase *junit.TestCase, controlPlaneExtraEnvs []string) func() {
 	return func() {
-		start := time.Now()
-		defer upgrades.FinalizeUpgradeTest(start, testCase)
 		target := upgCtx.Versions[1].Version.String()
 		framework.ExpectNoError(controlPlaneUpgrade(f, target, controlPlaneExtraEnvs))
 		framework.ExpectNoError(checkControlPlaneVersion(f.ClientSet, target))
@@ -47,8 +45,6 @@ func ControlPlaneUpgradeFunc(f *framework.Framework, upgCtx *upgrades.UpgradeCon
 // ClusterUpgradeFunc returns a function that performs full cluster upgrade (both control plane and nodes).
 func ClusterUpgradeFunc(f *framework.Framework, upgCtx *upgrades.UpgradeContext, testCase *junit.TestCase, controlPlaneExtraEnvs, nodeExtraEnvs []string) func() {
 	return func() {
-		start := time.Now()
-		defer upgrades.FinalizeUpgradeTest(start, testCase)
 		target := upgCtx.Versions[1].Version.String()
 		image := upgCtx.Versions[1].NodeImage
 		framework.ExpectNoError(controlPlaneUpgrade(f, target, controlPlaneExtraEnvs))
@@ -61,8 +57,6 @@ func ClusterUpgradeFunc(f *framework.Framework, upgCtx *upgrades.UpgradeContext,
 // ClusterDowngradeFunc returns a function that performs full cluster downgrade (both nodes and control plane).
 func ClusterDowngradeFunc(f *framework.Framework, upgCtx *upgrades.UpgradeContext, testCase *junit.TestCase, controlPlaneExtraEnvs, nodeExtraEnvs []string) func() {
 	return func() {
-		start := time.Now()
-		defer upgrades.FinalizeUpgradeTest(start, testCase)
 		target := upgCtx.Versions[1].Version.String()
 		image := upgCtx.Versions[1].NodeImage
 		// Yes this really is a downgrade. And nodes must downgrade first.

test/e2e/framework/log.go

@@ -20,7 +20,6 @@ import (
 	"bytes"
 	"fmt"
 	"regexp"
-	"runtime"
 	"runtime/debug"
 	"time"
 
@@ -47,7 +46,7 @@ func Failf(format string, args ...interface{}) {
 	msg := fmt.Sprintf(format, args...)
 	skip := 1
 	log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip))
-	fail(nowStamp()+": "+msg, skip)
+	ginkgo.Fail(nowStamp()+": "+msg, skip)
 	panic("unreachable")
 }
 
@@ -59,55 +58,7 @@ func Fail(msg string, callerSkip ...int) {
 		skip += callerSkip[0]
 	}
 	log("FAIL", "%s\n\nFull Stack Trace\n%s", msg, PrunedStack(skip))
-	fail(nowStamp()+": "+msg, skip)
-}
-
-// FailurePanic is the value that will be panicked from Fail.
-type FailurePanic struct {
-	Message        string // The failure message passed to Fail
-	Filename       string // The filename that is the source of the failure
-	Line           int    // The line number of the filename that is the source of the failure
-	FullStackTrace string // A full stack trace starting at the source of the failure
-}
-
-const ginkgoFailurePanic = `
-Your test failed.
-Ginkgo panics to prevent subsequent assertions from running.
-Normally Ginkgo rescues this panic so you shouldn't see it.
-But, if you make an assertion in a goroutine, Ginkgo can't capture the panic.
-To circumvent this, you should call
-	defer GinkgoRecover()
-at the top of the goroutine that caused this panic.
-`
-
-// String makes FailurePanic look like the old Ginkgo panic when printed.
-func (FailurePanic) String() string { return ginkgoFailurePanic }
-
-// fail wraps ginkgo.Fail so that it panics with more useful
-// information about the failure. This function will panic with a
-// FailurePanic.
-func fail(message string, callerSkip ...int) {
-	skip := 1
-	if len(callerSkip) > 0 {
-		skip += callerSkip[0]
-	}
-
-	_, file, line, _ := runtime.Caller(skip)
-	fp := FailurePanic{
-		Message:        message,
-		Filename:       file,
-		Line:           line,
-		FullStackTrace: string(PrunedStack(skip)),
-	}
-
-	defer func() {
-		e := recover()
-		if e != nil {
-			panic(fp)
-		}
-	}()
-
-	ginkgo.Fail(message, skip)
+	ginkgo.Fail(nowStamp()+": "+msg, skip)
 }
 
 var codeFilterRE = regexp.MustCompile(`/github.com/onsi/ginkgo/v2/`)

test/e2e/framework/skipper/skipper.go

@@ -17,14 +17,8 @@ limitations under the License.
 package skipper
 
 import (
-	"bufio"
-	"bytes"
 	"context"
 	"fmt"
-	"regexp"
-	"runtime"
-	"runtime/debug"
-	"strings"
 
 	"github.com/onsi/ginkgo/v2"
 
@@ -44,87 +38,14 @@ import (
 
 func skipInternalf(caller int, format string, args ...interface{}) {
 	msg := fmt.Sprintf(format, args...)
+	// Long term this should get replaced with https://github.com/onsi/ginkgo/issues/1069.
 	framework.Logf(msg)
-	skip(msg, caller+1)
-}
-
-// SkipPanic is the value that will be panicked from Skip.
-type SkipPanic struct {
-	Message        string // The failure message passed to Fail
-	Filename       string // The filename that is the source of the failure
-	Line           int    // The line number of the filename that is the source of the failure
-	FullStackTrace string // A full stack trace starting at the source of the failure
-}
-
-const ginkgoSkipPanic = `
-Your test was skipped.
-Ginkgo panics to prevent subsequent assertions from running.
-Normally Ginkgo rescues this panic so you shouldn't see it.
-But, if you make an assertion in a goroutine, Ginkgo can't capture the panic.
-To circumvent this, you should call
-	defer GinkgoRecover()
-at the top of the goroutine that caused this panic.
-`
-
-// String makes SkipPanic look like the old Ginkgo panic when printed.
-func (SkipPanic) String() string { return ginkgoSkipPanic }
-
-// Skip wraps ginkgo.Skip so that it panics with more useful
-// information about why the test is being skipped. This function will
-// panic with a SkipPanic.
-func skip(message string, callerSkip ...int) {
-	skip := 1
-	if len(callerSkip) > 0 {
-		skip += callerSkip[0]
-	}
-
-	_, file, line, _ := runtime.Caller(skip)
-	sp := SkipPanic{
-		Message:        message,
-		Filename:       file,
-		Line:           line,
-		FullStackTrace: pruneStack(skip),
-	}
-
-	defer func() {
-		e := recover()
-		if e != nil {
-			panic(sp)
-		}
-	}()
-
-	ginkgo.Skip(message, skip)
-}
-
-// ginkgo adds a lot of test running infrastructure to the stack, so
-// we filter those out
-var stackSkipPattern = regexp.MustCompile(`onsi/ginkgo/v2`)
-
-func pruneStack(skip int) string {
-	skip += 2 // one for pruneStack and one for debug.Stack
-	stack := debug.Stack()
-	scanner := bufio.NewScanner(bytes.NewBuffer(stack))
-	var prunedStack []string
-
-	// skip the top of the stack
-	for i := 0; i < 2*skip+1; i++ {
-		scanner.Scan()
-	}
-
-	for scanner.Scan() {
-		if stackSkipPattern.Match(scanner.Bytes()) {
-			scanner.Scan() // these come in pairs
-		} else {
-			prunedStack = append(prunedStack, scanner.Text())
-			scanner.Scan() // these come in pairs
-			prunedStack = append(prunedStack, scanner.Text())
-		}
-	}
-
-	return strings.Join(prunedStack, "\n")
+	ginkgo.Skip(msg, caller+1)
+	panic("unreachable")
 }
 
 // Skipf skips with information about why the test is being skipped.
+// The direct caller is recorded in the callstack.
 func Skipf(format string, args ...interface{}) {
 	skipInternalf(1, format, args...)
 	panic("unreachable")

test/e2e/framework/skipper/skipper_test.go

@@ -0,0 +1,88 @@
+/*
+Copyright 2022 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 skipper_test
+
+import (
+	"flag"
+	"testing"
+
+	"github.com/onsi/ginkgo/v2"
+
+	"k8s.io/kubernetes/test/e2e/framework"
+	"k8s.io/kubernetes/test/e2e/framework/internal/output"
+	e2eskipper "k8s.io/kubernetes/test/e2e/framework/skipper"
+)
+
+// The line number of the following code is checked in TestFailureOutput below.
+// Be careful when moving it around or changing the import statements above.
+// Here are some intentionally blank lines that can be removed to compensate
+// for future additional import statements.
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+// This must be line #50.
+
+var _ = ginkgo.Describe("e2e", func() {
+	ginkgo.It("skips", func() {
+		e2eskipper.Skipf("skipping %d, %d, %d", 1, 3, 4)
+	})
+})
+
+func TestSkip(t *testing.T) {
+	// This simulates how test/e2e uses the framework and how users
+	// invoke test/e2e.
+	framework.RegisterCommonFlags(flag.CommandLine)
+	framework.RegisterClusterFlags(flag.CommandLine)
+	for flagname, value := range map[string]string{
+		// This simplifies the text comparison.
+		"ginkgo.no-color": "true",
+	} {
+		if err := flag.Set(flagname, value); err != nil {
+			t.Fatalf("set %s: %v", flagname, err)
+		}
+	}
+	framework.AfterReadingAllFlags(&framework.TestContext)
+	suiteConfig, reporterConfig := framework.CreateGinkgoConfig()
+
+	expected := output.SuiteResults{
+		output.TestResult{
+			Name: "e2e skips",
+			Output: `[It] skips
+  skipper_test.go:53
+INFO: skipping 1, 3, 4
+`,
+			Failure: `skipping 1, 3, 4`,
+			Stack: `k8s.io/kubernetes/test/e2e/framework/skipper_test.glob..func1.1()
+	skipper_test.go:54`,
+		},
+	}
+
+	output.TestGinkgoOutput(t, expected, suiteConfig, reporterConfig)
+}

test/e2e/upgrades/upgrade_suite.go

@@ -28,7 +28,6 @@ import (
 
 	"k8s.io/kubernetes/test/e2e/chaosmonkey"
 	"k8s.io/kubernetes/test/e2e/framework"
-	e2eskipper "k8s.io/kubernetes/test/e2e/framework/skipper"
 	"k8s.io/kubernetes/test/utils/junit"
 	admissionapi "k8s.io/pod-security-admission/api"
 
@@ -37,25 +36,21 @@ import (
 
 type chaosMonkeyAdapter struct {
 	test        Test
-	testReport  *junit.TestCase
 	framework   *framework.Framework
 	upgradeType UpgradeType
 	upgCtx      UpgradeContext
 }
 
 func (cma *chaosMonkeyAdapter) Test(sem *chaosmonkey.Semaphore) {
-	start := time.Now()
 	var once sync.Once
 	ready := func() {
 		once.Do(func() {
 			sem.Ready()
 		})
 	}
-	defer FinalizeUpgradeTest(start, cma.testReport)
 	defer ready()
 	if skippable, ok := cma.test.(Skippable); ok && skippable.Skip(cma.upgCtx) {
 		ginkgo.By("skipping test " + cma.test.Name())
-		cma.testReport.Skipped = "skipping test " + cma.test.Name()
 		return
 	}
 
@@ -65,36 +60,6 @@ func (cma *chaosMonkeyAdapter) Test(sem *chaosmonkey.Semaphore) {
 	cma.test.Test(cma.framework, sem.StopCh, cma.upgradeType)
 }
 
-// FinalizeUpgradeTest fills the necessary information about junit.TestCase.
-func FinalizeUpgradeTest(start time.Time, tc *junit.TestCase) {
-	tc.Time = time.Since(start).Seconds()
-	r := recover()
-	if r == nil {
-		return
-	}
-
-	switch r := r.(type) {
-	case framework.FailurePanic:
-		tc.Failures = []*junit.Failure{
-			{
-				Message: r.Message,
-				Type:    "Failure",
-				Value:   fmt.Sprintf("%s\n\n%s", r.Message, r.FullStackTrace),
-			},
-		}
-	case e2eskipper.SkipPanic:
-		tc.Skipped = fmt.Sprintf("%s:%d %q", r.Filename, r.Line, r.Message)
-	default:
-		tc.Errors = []*junit.Error{
-			{
-				Message: fmt.Sprintf("%v", r),
-				Type:    "Panic",
-				Value:   fmt.Sprintf("%v", r),
-			},
-		}
-	}
-}
-
 func CreateUpgradeFrameworks(tests []Test) map[string]*framework.Framework {
 	nsFilter := regexp.MustCompile("[^[:word:]-]+") // match anything that's not a word character or hyphen
 	testFrameworks := map[string]*framework.Framework{}
@@ -126,7 +91,6 @@ func RunUpgradeSuite(
 		testSuite.TestCases = append(testSuite.TestCases, testCase)
 		cma := chaosMonkeyAdapter{
 			test:        t,
-			testReport:  testCase,
 			framework:   testFrameworks[t.Name()],
 			upgradeType: upgradeType,
 			upgCtx:      *upgCtx,