ktesting: improve unit test coverage

In particular ExpectNoError needed testing, as it was unused so far and not
functional in its initial implementation.

Author: pohly

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/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')
+}

test/utils/ktesting/main_test.go

@@ -0,0 +1,45 @@
+/*
+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 (
+	"flag"
+	"fmt"
+	"os"
+	"testing"
+
+	"go.uber.org/goleak"
+)
+
+func TestMain(m *testing.M) {
+	// Bail out early when -help was given as parameter.
+	flag.Parse()
+
+	// Must be called *before* creating new goroutines.
+	goleakOpts := []goleak.Option{
+		goleak.IgnoreCurrent(),
+	}
+
+	result := m.Run()
+
+	if err := goleak.Find(goleakOpts...); err != nil {
+		fmt.Fprintf(os.Stderr, "leaked Goroutines: %v", err)
+		os.Exit(1)
+	}
+
+	os.Exit(result)
+}

test/utils/ktesting/signals.go

@@ -30,6 +30,7 @@ var (
 	interruptCtx context.Context
 
 	defaultProgressReporter = new(progressReporter)
+	defaultSignalChannel    chan os.Signal
 )
 
 const ginkgoSpecContextKey = "GINKGO_SPEC_CONTEXT"
@@ -57,25 +58,35 @@ func init() {
 	// probably cannot be in either Ginkgo or Gomega).
 	interruptCtx = context.WithValue(cancelCtx, ginkgoSpecContextKey, defaultProgressReporter)
 
-	signalChannel := make(chan os.Signal, 1)
+	defaultSignalChannel = make(chan os.Signal, 1)
 	// progressSignals will be empty on Windows.
 	if len(progressSignals) > 0 {
-		signal.Notify(signalChannel, progressSignals...)
+		signal.Notify(defaultSignalChannel, progressSignals...)
 	}
 
 	// os.Stderr gets redirected by "go test". "go test -v" has to be
 	// used to see the output while a test runs.
-	go defaultProgressReporter.run(interruptCtx, os.Stderr, signalChannel)
+	defaultProgressReporter.setOutput(os.Stderr)
+	go defaultProgressReporter.run(interruptCtx, defaultSignalChannel)
 }
 
 type progressReporter struct {
 	mutex           sync.Mutex
 	reporterCounter int64
 	reporters       map[int64]func() string
+	out             io.Writer
 }
 
 var _ ginkgoReporter = &progressReporter{}
 
+func (p *progressReporter) setOutput(out io.Writer) io.Writer {
+	p.mutex.Lock()
+	defer p.mutex.Unlock()
+	oldOut := p.out
+	p.out = out
+	return oldOut
+}
+
 // AttachProgressReporter implements Gomega's contextWithAttachProgressReporter.
 func (p *progressReporter) AttachProgressReporter(reporter func() string) func() {
 	p.mutex.Lock()
@@ -100,13 +111,13 @@ func (p *progressReporter) detachProgressReporter(id int64) {
 	delete(p.reporters, id)
 }
 
-func (p *progressReporter) run(ctx context.Context, out io.Writer, progressSignalChannel chan os.Signal) {
+func (p *progressReporter) run(ctx context.Context, progressSignalChannel chan os.Signal) {
 	for {
 		select {
 		case <-ctx.Done():
 			return
 		case <-progressSignalChannel:
-			p.dumpProgress(out)
+			p.dumpProgress()
 		}
 	}
 }
@@ -117,7 +128,7 @@ func (p *progressReporter) run(ctx context.Context, out io.Writer, progressSigna
 //
 // But perhaps dumping goroutines and their callstacks is useful anyway?  TODO:
 // look at how Ginkgo does it and replicate some of it.
-func (p *progressReporter) dumpProgress(out io.Writer) {
+func (p *progressReporter) dumpProgress() {
 	p.mutex.Lock()
 	defer p.mutex.Unlock()
 
@@ -135,5 +146,5 @@ func (p *progressReporter) dumpProgress(out io.Writer) {
 		}
 	}
 
-	_, _ = out.Write([]byte(buffer.String()))
+	_, _ = p.out.Write([]byte(buffer.String()))
 }

test/utils/ktesting/stepcontext.go

@@ -76,7 +76,7 @@ func (sCtx *stepContext) Fatalf(format string, args ...any) {
 	sCtx.TContext.Fatal(sCtx.what + ": " + strings.TrimSpace(fmt.Sprintf(format, args...)))
 }
 
-// Value intercepts a search for the special
+// Value intercepts a search for the special "GINKGO_SPEC_CONTEXT".
 func (sCtx *stepContext) Value(key any) any {
 	if s, ok := key.(string); ok && s == ginkgoSpecContextKey {
 		if reporter, ok := sCtx.TContext.Value(key).(ginkgoReporter); ok {