Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ktesting: handle test completion #337

Merged
merged 3 commits into from Jul 6, 2022
Merged

ktesting: handle test completion #337

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
66544b3
ktesting: use black box testing
pohly Jun 29, 2022
78f38f6
ktesting: fix type assertion
pohly Jul 4, 2022
9405f8e
ktesting: stop using testing.T when test completes
pohly Jun 29, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
42 changes: 42 additions & 0 deletions internal/dbg/dbg.go
View file
Open in desktop
@@ -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
}
26 changes: 4 additions & 22 deletions klog.go
View file
Open in desktop
Expand Up @@ -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"
)
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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.
Expand All @@ -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
Expand Down
165 changes: 122 additions & 43 deletions ktesting/testinglogger.go
View file
Open in desktop
Expand Up @@ -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"
)
Expand Down Expand Up @@ -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 {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can this be made a global interface so that eventually we can decide it this can be integrated into the standard TL interface ? Any advantages of keeping this local ?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TL is part of the ktesting API. Changing it triggers an apidiff error.

We could ignore that error because the ktesting API is still marked EXPERIMENTAL, but I think it is simpler to make implementation of these additional methods optional. There are some TL implementations in our own ktesting code which then don''t need to be modified.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am fine with not making this part of the default TL interface. I was only suggesting moving this interface definition outside of the local scope. But that is mostly a cosmetic thing.

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.
Expand Down Expand Up @@ -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.
Expand All @@ -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() {
pohly marked this conversation as resolved.
Show resolved Hide resolved
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...)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it be better to log this message without using the V(level) switch? Would that help catch some of the issue with tests where things are still getting written to log after test is done?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's an interesting idea. I'm just worried that this might increase the log volume of tests which currently have no way of cleaning up goroutines.

What if we instead print one warning per test logger the first time that a leaked goroutine is detected? That warning then can provide information about that goroutine, which is more than a developer gets from the prefix.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is a better option for sure. Do we need to handle the cases where more than one go-routine is trying to still write to test logger? It would be one line of warning per leaked go routine per test

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think one warning is enough. That gives some indication that something is amiss without overwhelming with output.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added:

        testinglogger_test.go:195] "TestStop/Sub leaked goroutine: WARNING: test kept at least one goroutine running after test completion" callstack=<
        	goroutine 35 [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({0xc000160780, {0x0, 0x0}, {0x0, 0x0, 0x0}})
        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:292 +0x232
        	k8s.io/klog/v2/ktesting.tlogger.Info({0xc000160780, {0x0, 0x0}, {0x0, 0x0, 0x0}}, 0x0, {0x5454f1, 0x13}, {0x0, ...})
        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:316 +0x28a
        	github.com/go-logr/logr.Logger.Info({{0x5735f8?, 0xc00011d020?}, 0x0?}, {0x5454f1, 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:195 +0xd0
        	created by k8s.io/klog/v2/ktesting_test.TestStop.func1
        		/nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:186 +0xf8
         >

This could be made a bit nicer by skipping frames, but I want to keep the code simple, so I am just using the same helper as for goroutine dumps in klog (= wrapper around runtime.Stacks), except that I am only dumping one goroutine.

Dumping only one is intentional: "go test" itself uses goroutines and the test suite might run other tests in parallel.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Makes sense. This already give us good enough good information to start digging into failures better.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please mark this as resolved

return
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Returning here without capturing the output in the buffer is intentional: if the test has completed, there is no-one left who needs the additional log entries.

}

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)
Expand All @@ -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+":")
Expand All @@ -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,
Expand All @@ -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{}
Expand Down