diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 905c1d634..99a816715 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -49,6 +49,7 @@ import ( "github.com/go-logr/logr" + "k8s.io/klog/v2" "k8s.io/klog/v2/internal/serialize" "k8s.io/klog/v2/internal/verbosity" ) @@ -76,22 +77,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 +// ` 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 +222,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 +247,85 @@ func (b *buffer) Data() Log { return b.log.DeepCopy() } +// tloggerShared holds values that are the same for all instances. +type tloggerShared struct { + // mutex protects access to t. + mutex sync.Mutex + + // t gets cleared when the test is completed. + t TL + + 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) + return logger +} + +func (l tlogger) Init(info logr.RuntimeInfo) { + l.shared.callDepth = info.CallDepth } -func (l *tlogger) GetCallStackHelper() func() { - return 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.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 +335,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 +346,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 +380,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 c4efa4629..de2a2817e 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -10,9 +10,14 @@ package ktesting_test import ( "bytes" "errors" + "flag" "fmt" + "regexp" + "runtime" + "sync" "testing" + "k8s.io/klog/v2" "k8s.io/klog/v2/ktesting" ) @@ -132,6 +137,7 @@ func TestCallDepth(t *testing.T) { } type logToBuf struct { + ktesting.NopTL bytes.Buffer } @@ -147,3 +153,63 @@ 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 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() + actual = regexp.MustCompile(`(?m)^.* testinglogger_test.go:`).ReplaceAllString(actual, `testinglogger_test.go:`) + expected := fmt.Sprintf(`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+2, line+3) + if actual != expected { + t.Errorf("Output does not match. Expected:\n%s\nActual:\n%s\n", expected, actual) + } +}