Merge pull request #401 from pohly/ktesting-warning-delay

ktesting: tone down warning about leaked test goroutine

ktesting/testinglogger.go

@@ -217,8 +217,19 @@ type tloggerShared struct {
 	// t gets cleared when the test is completed.
 	t TL
 
-	// We warn once when a leaked goroutine is detected because
-	// it logs after test completion.
+	// The time when the test completed.
+	stopTime time.Time
+
+	// We warn once when a leaked goroutine logs after test completion.
+	//
+	// Not terminating immediately is fairly normal: many controllers
+	// log "terminating" messages while they shut down, which often is
+	// right after test completion, if that is when the test cancels the
+	// context and then doesn't wait for goroutines (which is often
+	// not possible).
+	//
+	// Therefore there is the [stopGracePeriod] during which messages get
+	// logged to the global logger without the warning.
 	goroutineWarningDone bool
 
 	formatter serialize.Formatter
@@ -228,10 +239,15 @@ type tloggerShared struct {
 	callDepth int
 }
 
+// Log output of a leaked goroutine during this period after test completion
+// does not trigger the warning.
+const stopGracePeriod = 10 * time.Second
+
 func (ls *tloggerShared) stop() {
 	ls.mutex.Lock()
 	defer ls.mutex.Unlock()
 	ls.t = nil
+	ls.stopTime = time.Now()
 }
 
 // tlogger is the actual LogSink implementation.
@@ -241,6 +257,8 @@ type tlogger struct {
 	values []interface{}
 }
 
+// fallbackLogger is called while l.shared.mutex is locked and after it has
+// been determined that the original testing.TB is no longer usable.
 func (l tlogger) fallbackLogger() logr.Logger {
 	logger := klog.Background().WithValues(l.values...).WithName(l.shared.testName + " leaked goroutine")
 	if l.prefix != "" {
@@ -250,8 +268,12 @@ func (l tlogger) fallbackLogger() logr.Logger {
 	logger = logger.WithCallDepth(l.shared.callDepth + 1)
 
 	if !l.shared.goroutineWarningDone {
-		logger.WithCallDepth(1).Error(nil, "WARNING: test kept at least one goroutine running after test completion", "callstack", string(dbg.Stacks(false)))
-		l.shared.goroutineWarningDone = true
+		duration := time.Since(l.shared.stopTime)
+		if duration > stopGracePeriod {
+
+			logger.WithCallDepth(1).Info("WARNING: test kept at least one goroutine running after test completion", "timeSinceCompletion", duration.Round(time.Second), "callstack", string(dbg.Stacks(false)))
+			l.shared.goroutineWarningDone = true
+		}
 	}
 	return logger
 }

ktesting/testinglogger_test.go

@@ -16,6 +16,7 @@ import (
 	"runtime"
 	"sync"
 	"testing"
+	"time"
 
 	"k8s.io/klog/v2"
 	"k8s.io/klog/v2/internal/test/require"
@@ -198,6 +199,7 @@ func TestStop(t *testing.T) {
 			_, _, line, _ = runtime.Caller(0)
 			logger.Info("simple info message")
 			logger.Error(nil, "error message")
+			time.Sleep(15 * time.Second)
 			logger.WithName("me").WithValues("completed", true).Info("complex info message", "anotherValue", 1)
 		}()
 	})
@@ -212,11 +214,14 @@ func TestStop(t *testing.T) {
 	// Strip time and pid prefix.
 	actual = regexp.MustCompile(`(?m)^.* testinglogger_test.go:`).ReplaceAllString(actual, `testinglogger_test.go:`)
 
+	// Strip duration.
+	actual = regexp.MustCompile(`timeSinceCompletion="\d+s"`).ReplaceAllString(actual, `timeSinceCompletion="<...>s"`)
+
 	// All lines from the callstack get stripped. We can be sure that it was non-empty because otherwise we wouldn't
 	// have the < > markers.
 	//
 	// Full output:
-	// 	testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
+	// 	testinglogger_test.go:194] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine.me" completed=true timeSinceCompletion="15s" callstack=<
 	//        	goroutine 23 [running]:
 	//        	k8s.io/klog/v2/internal/dbg.Stacks(0x0)
 	//        		/nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a
@@ -233,13 +238,13 @@ func TestStop(t *testing.T) {
 	//         >
 	actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``)
 
-	expected := fmt.Sprintf(`testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine" callstack=<
- >
-testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine"
+	expected := fmt.Sprintf(`testinglogger_test.go:%d] "simple info message" logger="TestStop/Sub leaked goroutine"
 testinglogger_test.go:%d] "error message" logger="TestStop/Sub leaked goroutine"
+testinglogger_test.go:%d] "WARNING: test kept at least one goroutine running after test completion" logger="TestStop/Sub leaked goroutine.me" completed=true timeSinceCompletion="<...>s" callstack=<
+ >
 testinglogger_test.go:%d] "complex info message" logger="TestStop/Sub leaked goroutine.me" completed=true anotherValue=1
 `,
-		line+1, line+1, line+2, line+3)
+		line+1, line+2, line+4, line+4)
 	if actual != expected {
 		t.Errorf("Output does not match. Expected:\n%s\nActual:\n%s\n", expected, actual)
 	}