Repository: kubernetes/klog
Pull request #337 (2022-06-29 11:31:47)

ktesting: handle test completion
**What this PR does / why we need it**:

When testing.T.Log gets called after the test has completed, it panics. There's
also a data race (https://github.com/kubernetes/kubernetes/issues/110854).

Normally that should never happen because tests should ensure that all
goroutines have stopped before returning. But sometimes it is not possible to
do that. Now when a test is completed, ktesting will automatically cause all
future usage of the testing.T instance to be redirected
to klog with a prefix that indicates that a goroutine has leaked.

**Which issue(s) this PR fixes**:

Related-to #https://github.com/kubernetes/kubernetes/pull/110811

**Special notes for your reviewer**:

**Release note**:
```release-note
Tests using ktesting and goroutines which continue to log through it after test completion used to trigger a data race in testing.T and a panic. Now such output goes to the global klog logger with `<test name> leaked goroutine` as prefix.
```


Patch:
diff --git a/internal/dbg/dbg.go b/internal/dbg/dbg.go
new file mode 100644
index 0000000..f27bd14
--- /dev/null
+++ b/internal/dbg/dbg.go
@@ -0,0 +1,42 @@
+// Go support for leveled logs, analogous to https://code.google.com/p/google-glog/
+//
+// Copyright 2013 Google Inc. All Rights Reserved.
+//
+// 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 dbg provides some helper code for call traces.
+package dbg
+
+import (
+	"runtime"
+)
+
+// Stacks is a wrapper for runtime.Stack that attempts to recover the data for
+// all goroutines or the calling one.
+func Stacks(all bool) []byte {
+	// We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
+	n := 10000
+	if all {
+		n = 100000
+	}
+	var trace []byte
+	for i := 0; i < 5; i++ {
+		trace = make([]byte, n)
+		nbytes := runtime.Stack(trace, all)
+		if nbytes < len(trace) {
+			return trace[:nbytes]
+		}
+		n *= 2
+	}
+	return trace
+}
diff --git a/klog.go b/klog.go
index 8305e25..b96f775 100644
--- a/klog.go
+++ b/klog.go
@@ -96,6 +96,7 @@ import (
 
 	"k8s.io/klog/v2/internal/buffer"
 	"k8s.io/klog/v2/internal/clock"
+	"k8s.io/klog/v2/internal/dbg"
 	"k8s.io/klog/v2/internal/serialize"
 	"k8s.io/klog/v2/internal/severity"
 )
@@ -859,7 +860,7 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf
 
 	if l.traceLocation.isSet() {
 		if l.traceLocation.match(file, line) {
-			buf.Write(stacks(false))
+			buf.Write(dbg.Stacks(false))
 		}
 	}
 	data := buf.Bytes()
@@ -928,11 +929,11 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf
 		// If -logtostderr has been specified, the loop below will do that anyway
 		// as the first stack in the full dump.
 		if !l.toStderr {
-			os.Stderr.Write(stacks(false))
+			os.Stderr.Write(dbg.Stacks(false))
 		}
 
 		// Write the stack trace for all goroutines to the files.
-		trace := stacks(true)
+		trace := dbg.Stacks(true)
 		logExitFunc = func(error) {} // If we get a write error, we'll still exit below.
 		for log := severity.FatalLog; log >= severity.InfoLog; log-- {
 			if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set.
@@ -952,25 +953,6 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf
 	}
 }
 
-// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
-func stacks(all bool) []byte {
-	// We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
-	n := 10000
-	if all {
-		n = 100000
-	}
-	var trace []byte
-	for i := 0; i < 5; i++ {
-		trace = make([]byte, n)
-		nbytes := runtime.Stack(trace, all)
-		if nbytes < len(trace) {
-			return trace[:nbytes]
-		}
-		n *= 2
-	}
-	return trace
-}
-
 // logExitFunc provides a simple mechanism to override the default behavior
 // of exiting on error. Used in testing and to guarantee we reach a required exit
 // for fatal logs. Instead, exit could be a function rather than a method but that


Test patch:
diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go
index 905c1d6..b327284 100644
--- a/ktesting/testinglogger.go
+++ b/ktesting/testinglogger.go
@@ -49,6 +49,8 @@ import (
 
 	"github.com/go-logr/logr"
 
+	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/internal/dbg"
 	"k8s.io/klog/v2/internal/serialize"
 	"k8s.io/klog/v2/internal/verbosity"
 )
@@ -76,22 +78,40 @@ type NopTL struct{}
 func (n NopTL) Helper()                 {}
 func (n NopTL) Log(args ...interface{}) {}
 
-var _TL = NopTL{}
+var _ TL = NopTL{}
 
 // NewLogger constructs a new logger for the given test interface.
 //
+// Beware that testing.T does not support logging after the test that
+// it was created for has completed. If a test leaks goroutines
+// and those goroutines log something after test completion,
+// that output will be printed via the global klog logger with
+// `<test name> leaked goroutine` as prefix.
+//
 // Experimental
 //
 // Notice: This type is EXPERIMENTAL and may be changed or removed in a
 // later release.
 func NewLogger(t TL, c *Config) logr.Logger {
-	return logr.New(&tlogger{
-		t:      t,
-		prefix: "",
-		values: nil,
-		config: c,
-		buffer: new(buffer),
-	})
+	l := tlogger{
+		shared: &tloggerShared{
+			t:      t,
+			config: c,
+		},
+	}
+
+	type testCleanup interface {
+		Cleanup(func())
+		Name() string
+	}
+
+	// Stopping the logging is optional and only done (and required)
+	// for testing.T/B/F.
+	if tb, ok := t.(testCleanup); ok {
+		tb.Cleanup(l.shared.stop)
+		l.shared.testName = tb.Name()
+	}
+	return logr.New(l)
 }
 
 // Buffer stores log entries as formatted text and structured data.
@@ -203,6 +223,7 @@ const (
 // later release.
 type Underlier interface {
 	// GetUnderlying returns the testing instance that logging goes to.
+	// It returns nil when the test has completed already.
 	GetUnderlying() TL
 
 	// GetBuffer grants access to the in-memory copy of the log entries.
@@ -227,35 +248,95 @@ func (b *buffer) Data() Log {
 	return b.log.DeepCopy()
 }
 
+// tloggerShared holds values that are the same for all LogSink instances. It
+// gets referenced by pointer in the tlogger struct.
+type tloggerShared struct {
+	// mutex protects access to t.
+	mutex sync.Mutex
+
+	// 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.
+	goroutineWarningDone bool
+
+	testName  string
+	config    *Config
+	buffer    buffer
+	callDepth int
+}
+
+func (ls *tloggerShared) stop() {
+	ls.mutex.Lock()
+	defer ls.mutex.Unlock()
+	ls.t = nil
+}
+
+// tlogger is the actual LogSink implementation.
 type tlogger struct {
-	t      TL
+	shared *tloggerShared
 	prefix string
 	values []interface{}
-	config *Config
-	buffer *buffer
 }
 
-func (l *tlogger) Init(info logr.RuntimeInfo) {
+func (l tlogger) fallbackLogger() logr.Logger {
+	logger := klog.Background().WithValues(l.values...).WithName(l.shared.testName + " leaked goroutine")
+	if l.prefix != "" {
+		logger = logger.WithName(l.prefix)
+	}
+	// Skip direct caller (= Error or Info) plus the logr wrapper.
+	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
+	}
+	return logger
 }
 
-func (l *tlogger) GetCallStackHelper() func() {
-	return l.t.Helper
+func (l tlogger) Init(info logr.RuntimeInfo) {
+	l.shared.callDepth = info.CallDepth
 }
 
-func (l *tlogger) Info(level int, msg string, kvList ...interface{}) {
-	l.t.Helper()
+func (l tlogger) GetCallStackHelper() func() {
+	l.shared.mutex.Lock()
+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		return func() {}
+	}
+
+	return l.shared.t.Helper
+}
+
+func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
+	l.shared.mutex.Lock()
+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		l.fallbackLogger().V(level).Info(msg, kvList...)
+		return
+	}
+
+	l.shared.t.Helper()
 	buffer := &bytes.Buffer{}
 	merged := serialize.MergeKVs(l.values, kvList)
 	serialize.KVListFormat(buffer, merged...)
 	l.log(LogInfo, msg, level, buffer, nil, kvList)
 }
 
-func (l *tlogger) Enabled(level int) bool {
-	return l.config.vstate.Enabled(verbosity.Level(level), 1)
+func (l tlogger) Enabled(level int) bool {
+	return l.shared.config.vstate.Enabled(verbosity.Level(level), 1)
 }
 
-func (l *tlogger) Error(err error, msg string, kvList ...interface{}) {
-	l.t.Helper()
+func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
+	l.shared.mutex.Lock()
+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		l.fallbackLogger().Error(err, msg, kvList...)
+		return
+	}
+
+	l.shared.t.Helper()
 	buffer := &bytes.Buffer{}
 	if err != nil {
 		serialize.KVListFormat(buffer, "err", err)
@@ -265,8 +346,8 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) {
 	l.log(LogError, msg, 0, buffer, err, kvList)
 }
 
-func (l *tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) {
-	l.t.Helper()
+func (l tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer, err error, kvList []interface{}) {
+	l.shared.t.Helper()
 	args := []interface{}{what}
 	if l.prefix != "" {
 		args = append(args, l.prefix+":")
@@ -276,24 +357,24 @@ func (l *tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer,
 		// Skip leading space inserted by serialize.KVListFormat.
 		args = append(args, string(buffer.Bytes()[1:]))
 	}
-	l.t.Log(args...)
+	l.shared.t.Log(args...)
 
-	l.buffer.mutex.Lock()
-	defer l.buffer.mutex.Unlock()
+	l.shared.buffer.mutex.Lock()
+	defer l.shared.buffer.mutex.Unlock()
 
 	// Store as text.
-	l.buffer.text.WriteString(string(what))
+	l.shared.buffer.text.WriteString(string(what))
 	for i := 1; i < len(args); i++ {
-		l.buffer.text.WriteByte(' ')
-		l.buffer.text.WriteString(args[i].(string))
+		l.shared.buffer.text.WriteByte(' ')
+		l.shared.buffer.text.WriteString(args[i].(string))
 	}
 	lastArg := args[len(args)-1].(string)
 	if lastArg[len(lastArg)-1] != '\n' {
-		l.buffer.text.WriteByte('\n')
+		l.shared.buffer.text.WriteByte('\n')
 	}
 
 	// Store as raw data.
-	l.buffer.log = append(l.buffer.log,
+	l.shared.buffer.log = append(l.shared.buffer.log,
 		LogEntry{
 			Timestamp:       time.Now(),
 			Type:            what,
@@ -310,27 +391,25 @@ func (l *tlogger) log(what LogType, msg string, level int, buffer *bytes.Buffer,
 // WithName returns a new logr.Logger with the specified name appended.  klogr
 // uses '/' characters to separate name elements.  Callers should not pass '/'
 // in the provided name string, but this library does not actually enforce that.
-func (l *tlogger) WithName(name string) logr.LogSink {
-	new := *l
+func (l tlogger) WithName(name string) logr.LogSink {
 	if len(l.prefix) > 0 {
-		new.prefix = l.prefix + "/"
+		l.prefix = l.prefix + "/"
 	}
-	new.prefix += name
-	return &new
+	l.prefix += name
+	return l
 }
 
-func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink {
-	new := *l
-	new.values = serialize.WithValues(l.values, kvList)
-	return &new
+func (l tlogger) WithValues(kvList ...interface{}) logr.LogSink {
+	l.values = serialize.WithValues(l.values, kvList)
+	return l
 }
 
-func (l *tlogger) GetUnderlying() TL {
-	return l.t
+func (l tlogger) GetUnderlying() TL {
+	return l.shared.t
 }
 
-func (l *tlogger) GetBuffer() Buffer {
-	return l.buffer
+func (l tlogger) GetBuffer() Buffer {
+	return &l.shared.buffer
 }
 
 var _ logr.LogSink = &tlogger{}
diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go
index 6c7ae18..bb1efe6 100644
--- a/ktesting/testinglogger_test.go
+++ b/ktesting/testinglogger_test.go
@@ -5,13 +5,20 @@ Copyright 2020 Intel Coporation.
 SPDX-License-Identifier: Apache-2.0
 */
 
-package ktesting
+package ktesting_test
 
 import (
 	"bytes"
 	"errors"
+	"flag"
 	"fmt"
+	"regexp"
+	"runtime"
+	"sync"
 	"testing"
+
+	"k8s.io/klog/v2"
+	"k8s.io/klog/v2/ktesting"
 )
 
 func TestInfo(t *testing.T) {
@@ -104,7 +111,7 @@ func TestInfo(t *testing.T) {
 	for n, test := range tests {
 		t.Run(n, func(t *testing.T) {
 			var buffer logToBuf
-			klogr := NewLogger(&buffer, NewConfig())
+			klogr := ktesting.NewLogger(&buffer, ktesting.NewConfig())
 			for _, name := range test.names {
 				klogr = klogr.WithName(name)
 			}
@@ -125,11 +132,12 @@ func TestInfo(t *testing.T) {
 }
 
 func TestCallDepth(t *testing.T) {
-	logger := NewLogger(t, NewConfig())
+	logger := ktesting.NewLogger(t, ktesting.NewConfig())
 	logger.Info("hello world")
 }
 
 type logToBuf struct {
+	ktesting.NopTL
 	bytes.Buffer
 }
 
@@ -145,3 +153,99 @@ func (l *logToBuf) Log(args ...interface{}) {
 	}
 	l.Write([]byte("\n"))
 }
+
+func TestStop(t *testing.T) {
+	// This test is set up so that a subtest spawns a goroutine and that
+	// goroutine logs through ktesting *after* the subtest has
+	// completed. This is not supported by testing.T.Log and normally
+	// leads to:
+	//   panic: Log in goroutine after TestGoroutines/Sub has completed: INFO hello world
+	//
+	// It works with ktesting if (and only if) logging gets redirected to klog
+	// before returning from the test.
+
+	// Capture output for testing.
+	state := klog.CaptureState()
+	defer state.Restore()
+	var output bytes.Buffer
+	var fs flag.FlagSet
+	klog.InitFlags(&fs)
+	fs.Set("alsologtostderr", "false")
+	fs.Set("logtostderr", "false")
+	fs.Set("stderrthreshold", "FATAL")
+	fs.Set("one_output", "true")
+	klog.SetOutput(&output)
+
+	var logger klog.Logger
+	var line int
+	var wg1, wg2 sync.WaitGroup
+	wg1.Add(1)
+	wg2.Add(1)
+	t.Run("Sub", func(t *testing.T) {
+		logger, _ = ktesting.NewTestContext(t)
+		go func() {
+			defer wg2.Done()
+
+			// Wait for test to have returned.
+			wg1.Wait()
+
+			// This output must go to klog because the test has
+			// completed.
+			_, _, line, _ = runtime.Caller(0)
+			logger.Info("simple info message")
+			logger.Error(nil, "error message")
+			logger.WithName("me").WithValues("completed", true).Info("complex info message", "anotherValue", 1)
+		}()
+	})
+	// Allow goroutine above to proceed.
+	wg1.Done()
+
+	// Ensure that goroutine has completed.
+	wg2.Wait()
+
+	actual := output.String()
+
+	// Strip time and pid prefix.
+	actual = regexp.MustCompile(`(?m)^.* testinglogger_test.go:`).ReplaceAllString(actual, `testinglogger_test.go:`)
+
+	// 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] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
+	//        	goroutine 23 [running]:
+	//        	k8s.io/klog/v2/internal/dbg.Stacks(0x0)
+	//        		/nvme/gopath/src/k8s.io/klog/internal/dbg/dbg.go:34 +0x8a
+	//        	k8s.io/klog/v2/ktesting.tlogger.fallbackLogger({0xc0000f2780, {0x0, 0x0}, {0x0, 0x0, 0x0}})
+	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:292 +0x232
+	//        	k8s.io/klog/v2/ktesting.tlogger.Info({0xc0000f2780, {0x0, 0x0}, {0x0, 0x0, 0x0}}, 0x0, {0x5444a5, 0x13}, {0x0, ...})
+	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:316 +0x28a
+	//        	github.com/go-logr/logr.Logger.Info({{0x572438?, 0xc0000c0ff0?}, 0x0?}, {0x5444a5, 0x13}, {0x0, 0x0, 0x0})
+	//        		/nvme/gopath/pkg/mod/github.com/go-logr/logr@v1.2.0/logr.go:249 +0xd0
+	//        	k8s.io/klog/v2/ktesting_test.TestStop.func1.1()
+	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:194 +0xe5
+	//        	created by k8s.io/klog/v2/ktesting_test.TestStop.func1
+	//        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:185 +0x105
+	//         >
+	actual = regexp.MustCompile(`(?m)^\t.*?\n`).ReplaceAllString(actual, ``)
+
+	expected := fmt.Sprintf(`testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
+ >
+testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: simple info message"
+testinglogger_test.go:%d] "TestStop/Sub leaked goroutine: error message"
+testinglogger_test.go:%d] "TestStop/Sub leaked goroutine/me: complex info message" completed=true anotherValue=1
+`,
+		line+1, line+1, line+2, line+3)
+	if actual != expected {
+		t.Errorf("Output does not match. Expected:\n%s\nActual:\n%s\n", expected, actual)
+	}
+
+	testingLogger, ok := logger.GetSink().(ktesting.Underlier)
+	if !ok {
+		t.Fatal("should have had a ktesting logger")
+	}
+	captured := testingLogger.GetBuffer().String()
+	if captured != "" {
+		t.Errorf("testing logger should not have captured any output, got instead:\n%s", captured)
+	}
+}