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 905c1d63..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" ) @@ -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 +// ` 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 6c7ae187..bb1efe6a 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) + } +}