diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 905c1d634..e2c91fd8b 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" ) @@ -62,6 +63,8 @@ import ( type TL interface { Helper() Log(args ...interface{}) + Cleanup(func()) + Name() string } // NopTL implements TL with empty stubs. It can be used when only capturing @@ -75,23 +78,33 @@ type NopTL struct{} func (n NopTL) Helper() {} func (n NopTL) Log(args ...interface{}) {} +func (n NopTL) Cleanup(func()) {} +func (n NopTL) Name() string { return "" } -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, + testName: t.Name(), + }, + } + t.Cleanup(l.shared.stop) + return logr.New(l) } // Buffer stores log entries as formatted text and structured data. @@ -203,6 +216,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 +241,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) GetCallStackHelper() func() { - return l.t.Helper +func (l tlogger) Init(info logr.RuntimeInfo) { + l.shared.callDepth = info.CallDepth +} + +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 +329,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 +340,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 +374,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..5c2381e44 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -11,6 +11,7 @@ import ( "bytes" "errors" "fmt" + "sync" "testing" "k8s.io/klog/v2/ktesting" @@ -132,6 +133,7 @@ func TestCallDepth(t *testing.T) { } type logToBuf struct { + ktesting.NopTL bytes.Buffer } @@ -147,3 +149,37 @@ 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. + 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. + 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() +}