ktesting: tone down warning about leaked test goroutine #401

pohly · 2024-03-08T17:11:45Z

What this PR does / why we need it:

Not terminating immediately is fairly normal: many controllers log "terminating" messages while they shut down, which often is right after test completion, if that is when the test cancels the context and then doesn't wait for goroutines (which is often not possible).

Therefore the warning now only gets printed if that happens after more than 10 seconds since test completion, and then the warning is only printed as an info message, not an error.

Release note:

ktesting: the warning about leaked goroutine is only shown after 10 or more seconds and is no longer an error message.

/cc @aojea @soltysh @kerthcet

k8s-ci-robot · 2024-03-08T17:11:53Z

This issue is currently awaiting triage.

If klog contributors determine this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.

The triage/accepted label can be added by org members by writing /triage accepted in a comment.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

pohly · 2024-03-11T08:39:06Z

Let's fix the linter issues first, see #402

kerthcet · 2024-05-17T10:02:02Z

ktesting/testinglogger.go

-		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
+		duration := time.Since(l.shared.stopTime)
+		if duration > stopGracePeriod {


This seems will bury the real goroutine leakage if the duration is less than stopGracePeriod, do I understand right here?

Another point I can't get here is if the test completes, why will it wait for another 10s?

If the "leaked" goroutine stops after less than stopGracePeriod, then it wasn't really a leak. It was "just" a test that didn't block and wait for goroutines at the end. This is very common.

Totally misunderstood the meaning here. I'm not quite understand how it works but I still have a silly question like: Will we wait and detect the goroutine leakage after test completes? Or why the duration from stop will be greater than stopGracePeriod.

No, we don't wait. That is something that uber/goleak does, but not this code. This code is merely reporting on leaked goroutines if and when it detects them, which is when they keep logging.

The stopGracePeriod is the grace period that goroutines have before their log output triggers this warning. I can rename it if you have a better suggestion.

I recalled goleak has maxRetries, then can't we just configure the goleak? It's configurable now. Both the retry times and sleep duration. I think somehow the same as stopGracePeriod. Will this lead to other problems?

keep the warning for goroutines that are more likely to be real leaks while not printing it for goroutines which terminate quickly after test completion.

Definitely agree.

We cannot depend on goleak here

Yes for klog... I mean for callers, like test framework. I suggested in this way is just because the goroutine leakage detection duration is mostly decided by goleak, the maxRetries(default to 20), maxSleep(default to 100ms) specifically, the duration ~= maxRetries * (maxSleep + filterStacks), have no idea whether 10s fits here. However, the feature is reverted... uber-go/goleak#116, so no way to configure now.

As a user of klog, happy with either way to avoid confusion.

Definitely agree.

So LGTM?

I mean for callers, like test framework.

Leak detection with goleak only works when tests run sequentially or in TestMain. I'm not sure how useful it is in an E2E test suite, because the actual code under test runs elsewhere. For integration and unit tests, individual test owners have to integrate goleak. Some apiserver-based tests have it.

have no idea whether 10s fits here

So this is about how klog will interact with goleak. I don't have a strong opinion here. I picked 10 seconds because it should be long enough to no produce "false positives" for the "I am shutting down after test completion" goroutines and short enough to give feedback for others. Because it's not causing a test failure, it can be lower than the goleak timeouts.

are these 10s added to the test duration? 10s sounds like a lot to me

No, they are not added. At the time that this gets called, the test has already completed.

pohly · 2024-06-10T12:11:18Z

/assign @dims

For approval. A new release for Kubernetes 1.31 also makes sense.

pohly · 2024-06-10T12:12:52Z

Hmm, we want a few more things for a new release, like #404

pohly · 2024-06-10T13:01:11Z

/retest

Does that work for GitHub actions? The linter wasn't happy, for some reason.

pohly · 2024-06-10T15:25:58Z

Linter failures fixed in main.

aojea · 2024-06-10T20:02:01Z

ktesting/testinglogger.go

@@ -250,8 +266,12 @@ func (l tlogger) fallbackLogger() logr.Logger {
 	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
+		duration := time.Since(l.shared.stopTime)


does this access need to be locked?

Yes! Good catch, thanks.

/lgtm cancel

Hrrm, no. fallbackLogger gets called while the mutex is locked. This wasn't clear here, so I've added a comment explaining that (https://github.com/kubernetes/klog/compare/83145e470293dc67bede46353012cededd97e031..ed62027e604261af3e9c42c7a50092a0db074f19).

@aojea: Okay for another LGTM?

k8s-ci-robot · 2024-06-11T07:59:22Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: kerthcet
Once this PR has been reviewed and has the lgtm label, please ask for approval from dims. For more information see the Kubernetes Code Review Process.

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

Needs approval from an approver in each of these files:

OWNERS

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

pohly · 2024-06-11T12:35:17Z

/hold

For second approval.

Not terminating immediately is fairly normal: many controllers log "terminating" messages while they shut down, which often is right after test completion, if that is when the test cancels the context and then doesn't wait for goroutines (which is often not possible). Therefore the warning now only gets printed if that happens after more than 10 seconds since test completion, and then the warning is only printed as an info message, not an error.

k8s-ci-robot requested review from aojea, kerthcet and soltysh March 8, 2024 17:11

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. approved Indicates a PR has been approved by an approver from all required OWNERS files. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Mar 8, 2024

k8s-ci-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Mar 8, 2024

pohly mentioned this pull request Mar 11, 2024

Goroutine leakage with TestFrameworkHandler_IterateOverWaitingPods kubernetes/kubernetes#123707

Open

kerthcet reviewed May 17, 2024

View reviewed changes

k8s-ci-robot assigned kerthcet May 21, 2024

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 21, 2024

k8s-ci-robot assigned dims Jun 10, 2024

aojea reviewed Jun 10, 2024

View reviewed changes

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jun 11, 2024

k8s-ci-robot removed the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jun 11, 2024

pohly force-pushed the ktesting-warning-delay branch from 83145e4 to ed62027 Compare June 11, 2024 12:33

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 11, 2024

pohly force-pushed the ktesting-warning-delay branch from ed62027 to cd24012 Compare June 11, 2024 13:01

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ktesting: tone down warning about leaked test goroutine #401

ktesting: tone down warning about leaked test goroutine #401

pohly commented Mar 8, 2024

k8s-ci-robot commented Mar 8, 2024

pohly commented Mar 11, 2024

kerthcet May 17, 2024

pohly May 17, 2024

kerthcet May 17, 2024

pohly May 17, 2024

kerthcet May 20, 2024

kerthcet May 20, 2024

pohly May 21, 2024

kerthcet May 21, 2024

aojea Jun 10, 2024

pohly Jun 11, 2024

pohly commented Jun 10, 2024

pohly commented Jun 10, 2024

pohly commented Jun 10, 2024

pohly commented Jun 10, 2024

aojea Jun 10, 2024

pohly Jun 11, 2024

pohly Jun 11, 2024

pohly Jun 11, 2024

k8s-ci-robot commented Jun 11, 2024

pohly commented Jun 11, 2024

ktesting: tone down warning about leaked test goroutine #401

Are you sure you want to change the base?

ktesting: tone down warning about leaked test goroutine #401

Conversation

pohly commented Mar 8, 2024

k8s-ci-robot commented Mar 8, 2024

pohly commented Mar 11, 2024

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 Jun 10, 2024

pohly commented Jun 10, 2024

pohly commented Jun 10, 2024

pohly commented Jun 10, 2024

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

k8s-ci-robot commented Jun 11, 2024

pohly commented Jun 11, 2024