Merge pull request kubernetes#123444 from pohly/test-context-expect-no-error

ktesting: several fixes and better unit testing

Author: k8s-ci-robot

test/utils/ktesting/assert.go

@@ -63,17 +63,23 @@ func expect(tCtx TContext, actual interface{}, extra ...interface{}) gomega.Asse
 }
 
 func expectNoError(tCtx TContext, err error, explain ...interface{}) {
+	if err == nil {
+		return
+	}
+
 	tCtx.Helper()
 
-	description := buildDescription(explain)
+	description := buildDescription(explain...)
 
-	var failure FailureError
-	if errors.As(err, &failure) {
-		if backtrace := failure.Backtrace(); backtrace != "" {
-			if description != "" {
-				tCtx.Log(description)
+	if errors.Is(err, ErrFailure) {
+		var failure FailureError
+		if errors.As(err, &failure) {
+			if backtrace := failure.Backtrace(); backtrace != "" {
+				if description != "" {
+					tCtx.Log(description)
+				}
+				tCtx.Logf("Failed at:\n    %s", strings.ReplaceAll(backtrace, "\n", "\n    "))
 			}
-			tCtx.Logf("Failed at:\n    %s", strings.ReplaceAll(backtrace, "\n", "\n    "))
 		}
 		if description != "" {
 			tCtx.Fatalf("%s: %s", description, err.Error())
@@ -84,7 +90,7 @@ func expectNoError(tCtx TContext, err error, explain ...interface{}) {
 	if description == "" {
 		description = "Unexpected error"
 	}
-	tCtx.Logf("%s: %s\n%s", description, format.Object(err, 1))
+	tCtx.Logf("%s:\n%s", description, format.Object(err, 1))
 	tCtx.Fatalf("%s: %v", description, err.Error())
 }
 
@@ -112,17 +118,18 @@ func buildDescription(explain ...interface{}) string {
 // is passed in. For example, errors can be checked with ExpectNoError:
 //
 //	cb := func(func(tCtx ktesting.TContext) int {
-//	   value, err := doSomething(...)
-//	   ktesting.ExpectNoError(tCtx, err, "something failed")
-//	   return value
+//	    value, err := doSomething(...)
+//	    tCtx.ExpectNoError(err, "something failed")
+//	    assert(tCtx, 42, value, "the answer")
+//	    return value
 //	}
 //	tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
 //
 // If there is no value, then an error can be returned:
 //
 //	cb := func(func(tCtx ktesting.TContext) error {
-//	   err := doSomething(...)
-//	   return err
+//	    err := doSomething(...)
+//	    return err
 //	}
 //	tCtx.Eventually(cb).Should(gomega.Succeed(), "foobar should succeed")
 //
@@ -137,28 +144,37 @@ func buildDescription(explain ...interface{}) string {
 // anymore, use [gomega.StopTrying]:
 //
 //	cb := func(func(tCtx ktesting.TContext) int {
-//	   value, err := doSomething(...)
-//	   if errors.Is(err, SomeFinalErr) {
-//	    gomega.StopTrying("permanent failure).Wrap(err).Now()
-//	   }
-//	   ktesting.ExpectNoError(tCtx, err, "something failed")
-//	   return value
+//	    value, err := doSomething(...)
+//	    if errors.Is(err, SomeFinalErr) {
+//	        // This message completely replaces the normal
+//	        // failure message and thus should include all
+//	        // relevant information.
+//	        //
+//	        // github.com/onsi/gomega/format is a good way
+//	        // to format arbitrary data. It uses indention
+//	        // and falls back to YAML for Kubernetes API
+//	        // structs for readability.
+//	        gomega.StopTrying("permanent failure, last value:\n%s", format.Object(value, 1 /* indent one level */)).
+//	            Wrap(err).Now()
+//	    }
+//	    ktesting.ExpectNoError(tCtx, err, "something failed")
+//	    return value
 //	}
 //	tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
 //
 // To poll again after some specific timeout, use [gomega.TryAgainAfter]. This is
 // particularly useful in [Consistently] to ignore some intermittent error.
 //
 //	cb := func(func(tCtx ktesting.TContext) int {
-//	   value, err := doSomething(...)
-//	   var intermittentErr SomeIntermittentError
-//	   if errors.As(err, &intermittentErr) {
-//	       gomega.TryAgainAfter(intermittentErr.RetryPeriod).Wrap(err).Now()
-//	   }
-//	   ktesting.ExpectNoError(tCtx, err, "something failed")
-//	   return value
-//	}
-//	tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
+//	    value, err := doSomething(...)
+//	    var intermittentErr SomeIntermittentError
+//	    if errors.As(err, &intermittentErr) {
+//	        gomega.TryAgainAfter(intermittentErr.RetryPeriod).Wrap(err).Now()
+//	    }
+//	    ktesting.ExpectNoError(tCtx, err, "something failed")
+//	    return value
+//	 }
+//	 tCtx.Eventually(cb).Should(gomega.Equal(42), "should be the answer to everything")
 func Eventually[T any](tCtx TContext, cb func(TContext) T) gomega.AsyncAssertion {
 	tCtx.Helper()
 	return gomega.NewWithT(tCtx).Eventually(tCtx, func(ctx context.Context) (val T, err error) {

test/utils/ktesting/assert_test.go

@@ -19,21 +19,14 @@ package ktesting
 import (
 	"errors"
 	"fmt"
-	"regexp"
 	"testing"
 	"time"
 
 	"github.com/onsi/gomega"
-	"github.com/stretchr/testify/assert"
 )
 
-func TestAsync(t *testing.T) {
-	for name, tc := range map[string]struct {
-		cb             func(TContext)
-		expectNoFail   bool
-		expectError    string
-		expectDuration time.Duration
-	}{
+func TestAssert(t *testing.T) {
+	for name, tc := range map[string]testcase{
 		"eventually-timeout": {
 			cb: func(tCtx TContext) {
 				Eventually(tCtx, func(tCtx TContext) int {
@@ -165,30 +158,114 @@ The function passed to Consistently returned the following error:
 			expectError: `Timed out while waiting on TryAgainAfter after x.y s.
 told to try again after 1ms: intermittent error`,
 		},
+
+		"expect-equal": {
+			cb: func(tCtx TContext) {
+				tCtx.Expect(1).To(gomega.Equal(42))
+			},
+			expectError: `Expected
+    <int>: 1
+to equal
+    <int>: 42`,
+		},
+
+		"expect-no-error-success": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(nil)
+			},
+			expectNoFail: true,
+		},
+		"expect-no-error-normal-error": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(errors.New("fake error"))
+			},
+			expectError: `Unexpected error: fake error`,
+			expectLog: `<klog header>: Unexpected error:
+    <*errors.errorString | 0xXXXX>: 
+    fake error
+    {s: "fake error"}
+`,
+		},
+		"expect-no-error-failure": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}))
+			},
+			expectError: `doing something: fake error`,
+		},
+		"expect-no-error-explanation-string": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), "testing error checking")
+			},
+			expectError: `testing error checking: doing something: fake error`,
+		},
+		"expect-no-error-explanation-printf": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), "testing %s %d checking", "error", 42)
+			},
+			expectError: `testing error 42 checking: doing something: fake error`,
+		},
+		"expect-no-error-explanation-callback": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error"}), func() string { return "testing error checking" })
+			},
+			expectError: `testing error checking: doing something: fake error`,
+		},
+		"expect-no-error-backtrace": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error", FullStackTrace: "abc\nxyz"}))
+			},
+			expectError: `doing something: fake error`,
+			expectLog: `<klog header>: Failed at:
+    abc
+    xyz
+`,
+		},
+		"expect-no-error-backtrace-and-explanation": {
+			cb: func(tCtx TContext) {
+				tCtx.ExpectNoError(fmt.Errorf("doing something: %w", FailureError{Msg: "fake error", FullStackTrace: "abc\nxyz"}), "testing error checking")
+			},
+			expectError: `testing error checking: doing something: fake error`,
+			expectLog: `<klog header>: testing error checking
+<klog header>: Failed at:
+    abc
+    xyz
+`,
+		},
+
+		"output": {
+			cb: func(tCtx TContext) {
+				tCtx.Log("Log", "a", "b", 42)
+				tCtx.Logf("Logf %s %s %d", "a", "b", 42)
+				tCtx.Error("Error", "a", "b", 42)
+				tCtx.Errorf("Errorf %s %s %d", "a", "b", 42)
+			},
+			expectLog: `<klog header>: Log a b 42
+<klog header>: Logf a b 42
+`,
+			expectError: `Error a b 42
+Errorf a b 42`,
+		},
+		"fatal": {
+			cb: func(tCtx TContext) {
+				tCtx.Fatal("Error", "a", "b", 42)
+				// not reached
+				tCtx.Log("Log")
+			},
+			expectError: `Error a b 42`,
+		},
+		"fatalf": {
+			cb: func(tCtx TContext) {
+				tCtx.Fatalf("Error %s %s %d", "a", "b", 42)
+				// not reached
+				tCtx.Log("Log")
+			},
+			expectError: `Error a b 42`,
+		},
 	} {
 		tc := tc
 		t.Run(name, func(t *testing.T) {
 			t.Parallel()
-			tCtx := Init(t)
-			var err error
-			tCtx, finalize := WithError(tCtx, &err)
-			start := time.Now()
-			func() {
-				defer finalize()
-				tc.cb(tCtx)
-			}()
-			duration := time.Since(start)
-			assert.InDelta(t, tc.expectDuration.Seconds(), duration.Seconds(), 0.1, fmt.Sprintf("callback invocation duration %s", duration))
-			assert.Equal(t, !tc.expectNoFail, tCtx.Failed(), "Failed()")
-			if tc.expectError == "" {
-				assert.NoError(t, err)
-			} else if assert.NotNil(t, err) {
-				t.Logf("Result:\n%s", err.Error())
-				errMsg := err.Error()
-				errMsg = regexp.MustCompile(`[[:digit:]]+\.[[:digit:]]+s`).ReplaceAllString(errMsg, "x.y s")
-				errMsg = regexp.MustCompile(`0x[[:xdigit:]]+`).ReplaceAllString(errMsg, "0xXXXX")
-				assert.Equal(t, tc.expectError, errMsg)
-			}
+			tc.run(t)
 		})
 	}
 }

test/utils/ktesting/errorcontext.go

@@ -22,6 +22,7 @@ import (
 	"strings"
 	"sync"
 
+	"github.com/onsi/gomega"
 	"k8s.io/klog/v2"
 )
 
@@ -138,6 +139,16 @@ func (eCtx *errorContext) CleanupCtx(cb func(TContext)) {
 	cleanupCtx(eCtx, cb)
 }
 
+func (eCtx *errorContext) Expect(actual interface{}, extra ...interface{}) gomega.Assertion {
+	eCtx.Helper()
+	return expect(eCtx, actual, extra...)
+}
+
+func (eCtx *errorContext) ExpectNoError(err error, explain ...interface{}) {
+	eCtx.Helper()
+	expectNoError(eCtx, err, explain...)
+}
+
 func (eCtx *errorContext) Logger() klog.Logger {
 	return klog.FromContext(eCtx)
 }

test/utils/ktesting/helper_test.go

@@ -0,0 +1,92 @@
+/*
+Copyright 2024 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 ktesting
+
+import (
+	"fmt"
+	"regexp"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+)
+
+// testcase wraps a callback which is called with a TContext that intercepts
+// errors and log output. Those get compared.
+type testcase struct {
+	cb             func(TContext)
+	expectNoFail   bool
+	expectError    string
+	expectDuration time.Duration
+	expectLog      string
+}
+
+func (tc testcase) run(t *testing.T) {
+	bufferT := &logBufferT{T: t}
+	tCtx := Init(bufferT)
+	var err error
+	tCtx, finalize := WithError(tCtx, &err)
+	start := time.Now()
+	func() {
+		defer finalize()
+		tc.cb(tCtx)
+	}()
+
+	log := bufferT.log.String()
+	t.Logf("Log output:\n%s\n", log)
+	if tc.expectLog != "" {
+		assert.Equal(t, tc.expectLog, normalize(log))
+	} else if log != "" {
+		t.Error("Expected no log output.")
+	}
+
+	duration := time.Since(start)
+	assert.InDelta(t, tc.expectDuration.Seconds(), duration.Seconds(), 0.1, fmt.Sprintf("callback invocation duration %s", duration))
+	assert.Equal(t, !tc.expectNoFail, tCtx.Failed(), "Failed()")
+	if tc.expectError == "" {
+		assert.NoError(t, err)
+	} else if assert.NotNil(t, err) {
+		t.Logf("Result:\n%s", err.Error())
+		assert.Equal(t, tc.expectError, normalize(err.Error()))
+	}
+}
+
+// normalize replaces parts of message texts which may vary with constant strings.
+func normalize(msg string) string {
+	// duration
+	msg = regexp.MustCompile(`[[:digit:]]+\.[[:digit:]]+s`).ReplaceAllString(msg, "x.y s")
+	// hex pointer value
+	msg = regexp.MustCompile(`0x[[:xdigit:]]+`).ReplaceAllString(msg, "0xXXXX")
+	// per-test klog header
+	msg = regexp.MustCompile(`[EI][[:digit:]]{4} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}\.[[:digit:]]{6}\]`).ReplaceAllString(msg, "<klog header>:")
+	return msg
+}
+
+type logBufferT struct {
+	*testing.T
+	log strings.Builder
+}
+
+func (l *logBufferT) Log(args ...any) {
+	l.log.WriteString(fmt.Sprintln(args...))
+}
+
+func (l *logBufferT) Logf(format string, args ...any) {
+	l.log.WriteString(fmt.Sprintf(format, args...))
+	l.log.WriteRune('\n')
+}