ktesting: handle test completion #337

pohly · 2022-06-29T11:31:47Z

What this PR does / why we need it:

When testing.T.Log gets called after the test has completed, it panics. There's
also a data race (kubernetes/kubernetes#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. Now when a test is completed, ktesting will automatically cause all
future usage of the testing.T instance to be redirected
to klog with a prefix that indicates that a goroutine has leaked.

Which issue(s) this PR fixes:

Related-to #kubernetes/kubernetes#110811

Special notes for your reviewer:

Release note:

Tests using ktesting and goroutines which continue to log through it after test completion used to trigger a data race in testing.T and a panic. Now such output goes to the global klog logger with `<test name> leaked goroutine` as prefix.

It makes it more obvious what calls to the ktesting API will look like in real code.

pohly · 2022-06-29T11:42:15Z

ktesting/testinglogger.go

+func (l *tlogger) stop() {
+	l.mutex.Lock()
+	defer l.mutex.Unlock()
+	l.t = nil


Commenting out this line triggers the problem in the new unit test:

panic: Log in goroutine after TestStop/Sub has completed: INFO hello world goroutine 22 [running]: testing.(*common).logDepth(0xc0000f8000, {0xc000124000, 0x11}, 0x3) /nvme/gopath/go-1.18.1/src/testing/testing.go:887 +0x4c7 testing.(*common).log(...) /nvme/gopath/go-1.18.1/src/testing/testing.go:869 testing.(*common).Log(0xc0000f8000, {0xc00011c000?, 0x50?, 0x1?}) /nvme/gopath/go-1.18.1/src/testing/testing.go:910 +0x4e k8s.io/klog/v2/ktesting.(*tlogger).log(0xc0000aae60, {0x52990b, 0x4}, {0x52af37, 0xb}, 0x0, 0xc0000aeed8, {0x0, 0x0}, {0x0, ...}) /nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:328 +0x36c k8s.io/klog/v2/ktesting.(*tlogger).Info(0xc0000aae60, 0x558008?, {0x52af37, 0xb}, {0x0, 0x0, 0x0}) /nvme/gopath/src/k8s.io/klog/ktesting/testinglogger.go:293 +0x1d6 github.com/go-logr/logr.Logger.Info({{0x558008?, 0xc0000aae60?}, 0x0?}, {0x52af37, 0xb}, {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:169 +0x65 created by k8s.io/klog/v2/ktesting_test.TestStop.func1 /nvme/gopath/src/k8s.io/klog/ktesting/testinglogger_test.go:166 +0x105 FAIL k8s.io/klog/v2/ktesting 0.008s FAIL

pohly · 2022-06-29T19:34:43Z

I verified that adding defer ktesting.Stop(logger) to the kubelet shutdown test avoids the panic and data race in testing. However, the test had other problems because of the leaking goroutines.

pohly · 2022-06-29T19:36:33Z

/assign @serathius

pohly · 2022-06-30T06:08:20Z

ktesting/testinglogger.go

@@ -94,6 +105,25 @@ func NewLogger(t TL, c *Config) logr.Logger {
 	})
 }

+// Stop ensures that all future log entries get discarded. This is necessary


Discarding output will make it hard to see that goroutines have leaked and debug why they are still running.

I think a better solution will be to redirect output to the global klog logger with a unique prefix. Something like

<test>: leaked goroutine: <message>

Also, this entire new API call is unnecessary.

There is testing.T.Cleanup, so ktesting itself can ensure that it gets notified when the test is done.

/hold

/hold cancel

Using testing.T.Cleanup implies extending out TL interface, which is an API change. ktesting is still experimental, so I think it is okay and worth it.

I found a way around the API break: instead of requiring Name and Cleanup, the constructor now only uses them if implemented.

ktesting/testinglogger.go

ktesting/testinglogger_test.go

It turned out that using testing.T for logging had a race condition and potential panic because the tests keep goroutines running and testing.T is not supposed to be used anymore after test completion (kubernetes#110854). Either the code must be fixed to terminate all goroutines before a test ends (seems non-trivial because the usage of goroutines is fairly complex in the shutdown manager code), or ktesting must handle this case. A solution for this is pending in kubernetes/klog#337. Either way, solving this will take a bit longer. In the meantime, we should revert the change to get unit testing stable again. In order to make this a local change, ktesting is kept as a dependency of the test and thus Kubernetes.

pohly · 2022-06-30T10:18:05Z

ktesting/testinglogger.go

+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		l.fallbackLogger().V(level).Info(msg, kvList...)
+		return


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.

Due a missing space, _TL was a variable of type NopTL instead of asserting that NopTL implements the TL interface.

ktesting/testinglogger.go

harshanarayana · 2022-07-05T06:12:13Z

ktesting/testinglogger.go

+	l.shared.mutex.Lock()
+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		l.fallbackLogger().V(level).Info(msg, kvList...)


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?

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.

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

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

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.

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

Please mark this as resolved

harshanarayana · 2022-07-05T06:38:33Z

ktesting/testinglogger.go

+		},
+	}
+
+	type testCleanup interface {


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 ?

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.

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.

harshanarayana · 2022-07-05T09:48:08Z

ktesting/testinglogger.go

+		},
+	}
+
+	type testCleanup interface {


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.

ktesting/testinglogger.go

harshanarayana · 2022-07-05T09:52:04Z

ktesting/testinglogger.go

+	l.shared.mutex.Lock()
+	defer l.shared.mutex.Unlock()
+	if l.shared.t == nil {
+		l.fallbackLogger().V(level).Info(msg, kvList...)


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

harshanarayana · 2022-07-05T09:59:06Z

ktesting/testinglogger.go

@@ -227,35 +247,85 @@ func (b *buffer) Data() Log {
 	return b.log.DeepCopy()
 }

+// tloggerShared holds values that are the same for all instances.


// loggerShared holds values that are common across all instances.

Might be a small rewording required here to make it read a bit better ?

Added some more text.

Please mark this as resolved

harshanarayana · 2022-07-05T10:01:12Z

ktesting/testinglogger_test.go

+	// Ensure that goroutine has completed.
+	wg2.Wait()
+
+	actual := output.String()


Can we please also extend this test to show that these lines are not captured in the buffer?

If we setup your ktesting.NewTestContext(t) to a global logger logr.Logger we can do the following to show how things work when someone writes to logger post test context. Would this be useful to have ?

testingLogger, _ := logger.GetSink().(ktesting.Underlier) if len(testingLogger.GetBuffer().Data()) != 1 { t.Error("Expected this one to not catch logs from leaked goroutines") }

Please mark this as resolved

When testing.T.Log gets called after the test has completed, it panics. There's also a data race (kubernetes/kubernetes#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.

pohly · 2022-07-06T09:12:26Z

@harshanarayana : I have pushed the enhancements, please take another look: https://github.com/kubernetes/klog/compare/5564ba3b4f48cccaf8d7faf0b11ffe5663f04c88..9405f8edad47f2b2bef7caa3cea95c8278fbea44

harshanarayana

@pohly I went through the changes. Looks good to me. I have no more comments to add at this point.

I will do one more scan of this to make sure I did not miss anything and update back if I find anything else.

pohly · 2022-07-06T15:47:18Z

@harshanarayana I appreciate your thoroughness, thanks. When you are done, then please assign to dims.

BTW, are you okay with adding you to the reviewers of the OWNERS file?

harshanarayana · 2022-07-06T18:48:50Z

@pohly No more comments from me on the changes that are part of this PR. It looks great.

harshanarayana · 2022-07-06T18:50:06Z

@pohly

BTW, are you okay with adding you to the reviewers of the OWNERS file?

Sure. I am fine with that. Thanks for the consideration.

harshanarayana · 2022-07-06T18:50:20Z

/cc @dims

harshanarayana · 2022-07-06T18:50:38Z

/assign @dims

dims · 2022-07-06T18:55:13Z

/approve
/lgtm

thanks @pohly @harshanarayana

k8s-ci-robot · 2022-07-06T18:55:31Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, pohly

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [dims]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

ktesting: use black box testing

66544b3

It makes it more obvious what calls to the ktesting API will look like in real code.

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Jun 29, 2022

k8s-ci-robot requested review from serathius and thockin June 29, 2022 11:32

pohly mentioned this pull request Jun 29, 2022

testing: testing.T.Log panics when called after test completion go-logr/logr#145

Closed

pohly commented Jun 29, 2022

View reviewed changes

harry1064 mentioned this pull request Jun 29, 2022

data race in nodeshutdown tests kubernetes/kubernetes#110854

Closed

k8s-ci-robot assigned serathius Jun 29, 2022

pohly mentioned this pull request Jun 29, 2022

kubelet: revert contextual logging support kubernetes/kubernetes#110869

Closed

pohly commented Jun 30, 2022

View reviewed changes

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jun 30, 2022

pohly force-pushed the testing-logger-stop branch from 20d9229 to 09b28a2 Compare June 30, 2022 07:12

k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. labels Jun 30, 2022

pohly commented Jun 30, 2022

View reviewed changes

ktesting/testinglogger.go Outdated Show resolved Hide resolved

pohly commented Jun 30, 2022

View reviewed changes

ktesting/testinglogger_test.go Show resolved Hide resolved

pohly force-pushed the testing-logger-stop branch 2 times, most recently from 965b786 to 7ac2aed Compare June 30, 2022 07:35

pohly mentioned this pull request Jun 30, 2022

WIP: scheduler: contextual logging kubernetes/kubernetes#110833

Closed

pohly changed the title ~~ktesting: add Stop~~ ktesting: handle test completion Jun 30, 2022

pohly force-pushed the testing-logger-stop branch from 7ac2aed to 82bc4a3 Compare June 30, 2022 09:27

pohly commented Jun 30, 2022

View reviewed changes

ktesting: fix type assertion

78f38f6

Due a missing space, _TL was a variable of type NopTL instead of asserting that NopTL implements the TL interface.

pohly force-pushed the testing-logger-stop branch from 82bc4a3 to 5564ba3 Compare July 4, 2022 12:58

harshanarayana reviewed Jul 5, 2022

View reviewed changes

ktesting/testinglogger.go Show resolved Hide resolved

harshanarayana reviewed Jul 5, 2022

View reviewed changes

pohly force-pushed the testing-logger-stop branch from 5564ba3 to 9405f8e Compare July 6, 2022 09:11

harshanarayana reviewed Jul 6, 2022

View reviewed changes

k8s-ci-robot requested a review from dims July 6, 2022 18:50

k8s-ci-robot assigned dims Jul 6, 2022

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jul 6, 2022

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jul 6, 2022

k8s-ci-robot merged commit ea66a13 into kubernetes:main Jul 6, 2022

pohly mentioned this pull request Jul 7, 2022

[Flaky test] ci-kubernetes-unit kubernetes/kubernetes#110962

Closed

ktesting: handle test completion #337

ktesting: handle test completion #337

Conversation

pohly commented Jun 29, 2022 • edited Loading

pohly Jun 29, 2022 • edited Loading

Choose a reason for hiding this comment

pohly commented Jun 29, 2022

pohly commented Jun 29, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly commented Jul 6, 2022

harshanarayana left a comment

Choose a reason for hiding this comment

pohly commented Jul 6, 2022

harshanarayana commented Jul 6, 2022 • edited Loading

harshanarayana commented Jul 6, 2022

harshanarayana commented Jul 6, 2022

harshanarayana commented Jul 6, 2022

dims commented Jul 6, 2022

k8s-ci-robot commented Jul 6, 2022

pohly commented Jun 29, 2022 •

edited

Loading

pohly Jun 29, 2022 •

edited

Loading

harshanarayana commented Jul 6, 2022 •

edited

Loading