From 9405f8edad47f2b2bef7caa3cea95c8278fbea44 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 29 Jun 2022 13:23:07 +0200 Subject: [PATCH] ktesting: stop using testing.T when test completes 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. ktesting now automatically protects against that by registering a cleanup function and redirecting all future output into klog. --- internal/dbg/dbg.go | 42 +++++++++ klog.go | 26 +----- ktesting/testinglogger.go | 163 ++++++++++++++++++++++++--------- ktesting/testinglogger_test.go | 102 +++++++++++++++++++++ 4 files changed, 269 insertions(+), 64 deletions(-) create mode 100644 internal/dbg/dbg.go diff --git a/internal/dbg/dbg.go b/internal/dbg/dbg.go new file mode 100644 index 00000000..f27bd144 --- /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 8305e252..b96f7752 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 diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index cf9fbdfe..b3272845 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" ) @@ -80,18 +82,36 @@ 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 +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 c4efa462..bb1efe6a 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,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) + } +}