Fix goroutine leak: make flushDaemon stoppable #293

katexochen · 2022-02-10T22:56:39Z

What this PR does / why we need it:
Previously, klog's init function started a goroutine to continuously flush buffers. This goroutine couldn't be stopped and made a shutdown without leaking goroutines impossible.

This PR makes it possible to stop and test the flushDaemon. It adds an API function so users can stop the daemon as well.

There was a previous attempt to fix this issue by someone else in #190.

In #190, someone requested to add goleak to detect leaking goroutines in the future, so this PR introduces such validation.

Which issue(s) this PR fixes:
fixes #282, fixes #188

Release note:

Make flushDaemon stoppable to prevent goroutine leak

linux-foundation-easycla · 2022-02-10T22:56:42Z

The committers are authorized under a signed CLA.

✅ katexochen (6d93ff0, b8f32b4, 397e3c9, 3321b2f)

k8s-ci-robot · 2022-02-10T22:56:47Z

Welcome @katexochen!

It looks like this is your first PR to kubernetes/klog 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/klog has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

pohly · 2022-02-11T10:57:32Z

I prefer the approach suggested in #282 (comment)

pohly · 2022-02-11T11:01:53Z

klog_test.go

@@ -35,11 +35,24 @@ import (
 	"time"

 	"github.com/go-logr/logr"
+	"go.uber.org/goleak"


We can't have go.uber.org/goleak as dependency of klog itself.

You can create an examples/flushing directory where you provide a main.go file which shows how to use the new API and a test that uses goleak.

Sure, I already thought so. I'll move this in into a separate directory.

katexochen · 2022-02-11T11:14:28Z

I prefer the approach suggested in #282 (comment)

sorry @pohly, it was my intention to stick to your suggestion. Maybe I misunderstood your proposal.

That means that we can move the flush daemon startup from init into createFiles #282 (comment)

This is what is happening now, the flushDaemon is started in createFiles.

Of course it must only be started once. #282 (comment)

FlushDaemon's run function will only start a new flushing goroutine if it isn't already running.

An API for stopping and waiting for it to stop can be added as an API extension at the same time. #282 (comment)

I've added the API extension you proposed.

Adding some unit tests for this would be good. #282 (comment)

The new code is easily testable. I don't have a lot of experience testing packages with global state. Maybe there is a better way to do this.

I'd be happy if you could clarify how I could improve this PR in the direction of your initial proposal. 🙂

pohly

it was my intention to stick to your suggestion. Maybe I misunderstood your proposal.

No, you got it right. I just didn't read the entire PR and didn't see that newFlushDaemon doesn't start a goroutine.

pohly · 2022-02-11T11:39:11Z

klog.go

+// run starts a goroutine that periodically calls the daemons flush function.
+// Calling run on an already running daemon will have no effect.
+func (f *flushDaemon) run() {
+	if f.isRunning() {


Some more code and/or documentation is needed to ensure that this code is thread-safe.

As it stands now, the user might call StopFlushDaemon while the daemon is being started. Not very likely, but still...

We can probably require that logging.mu must be held when calling run, stop or isRunning and then lock that mutex in StopFlushDaemon.

I'd prefer to lock the flushDaemon separate from the loggingT, by giving the daemon its own mutex. This way, flushDaemon can do the locking itself, which reduces complexity for the caller.

I agree, this better. I was worried that run might be called frequently, but because createFile itself is under an if check, that won't be the case.

pohly · 2022-02-11T11:39:41Z

klog.go

+			case <-ticker.C:
+				f.flush()
+			case <-f.stopC:
+				ticker.Stop()


nit: I prefer to have this in a defer directly after setting up the ticker.

pohly · 2022-02-11T11:40:02Z

klog.go

+				f.flush()
+			case <-f.stopC:
+				ticker.Stop()
+				f.stopDone <- struct{}{}


nit: also a candidate for a defer.

pohly · 2022-02-11T11:43:14Z

BTW, as far as I am concerned you can squash right away and force-push a single commit. Then we can merge it right away when it is done.

pohly · 2022-02-12T11:40:41Z

/ok-to-test

examples/flushing/flushing_test.go

pohly

/lgtm

/assign @dims

Still needs ok-to-test, it looks like I can't add that.

pohly · 2022-02-16T10:45:21Z

/lgtm

dims · 2022-02-17T15:06:24Z

/approve
/assign @thockin

/hold let's give Tim a chance to peek, please remove hold in a couple of days.

thockin

No objections

thockin · 2022-02-18T23:00:09Z

klog.go

@@ -1022,6 +1024,9 @@ const bufferSize = 256 * 1024
 // createFiles creates all the log files for severity from sev down to infoLog.
 // l.mu is held.
 func (l *loggingT) createFiles(sev severity.Severity) error {
+	if l.flushD != nil {


under what conditions would this be nil?

I guess it shouldn't happen during normal operation, I will remove the check.

Refactor flushDaemon function into a seperate struct. Instead of starting the daemon in the init function, it is now started during createFile, where it is only used. Add function to stop daemon. This way, users can gracefully shut down klog and prevent goroutine leakage. Test daemon flushing.

katexochen · 2022-02-19T08:47:01Z

Since TestFlushDaemon failed, I've increased the sleep duration to give the flushDaemon more time to start and lowered the expected flush count.

klog.go

thockin · 2022-02-20T21:24:27Z

klog_test.go

+			t.Error("expected flushD to be running")
+		}
+
+		time.Sleep(400 * time.Millisecond)


Comment on why sleep? This is usually a smell...

Or inject a fake ticket so you can manually "advance time" rather than sleep. Deterministic tests FTW

Thanks for your feedback. I'm not quite sure what you mean by "fake ticket". Did you mean ticker? I think the problem here is the startup time of the goroutine, not the flush interval, so I don't understand how a fake ticker could help with that.
But I agree that tests should be deterministic if possible and I'd be glad if you could give me some more hints on how to make it deterministic. 🙂

Sorry, I meant "ticker".

e.g. staging/src/k8s.io/client-go/util/workqueue/rate_limiting_queue_test.go - it uses testingclock.NewFakeClock (k8s.io/utils/clock/testing) which has a NewTicker method.

Pass a k8s.io/utils/clock.WithTicker to newFlushDaemon() (passing nil means "use time.NewTicker()") and store that in the flushDaemon struct. In run() you can check if the passed-in clock.WithTicker is nil. If so, do what this does now (use a real ticker) but if it is not nil, use it instead.

Then your test manipulates the fake clock's time to cause ticks when you expect them.

As for the daemon startup - you already call isRunning(), so you know it's alive...

I've added the clock, thanks for the great tip.
In addition, I had to move the creation of the ticker out of the go function and add a channel for communication between the spy function and the test.

thockin · 2022-02-24T17:14:10Z

klog.go

+	stopDone chan struct{}
+}
+
+// newFlushDaemon retrun a new flushDaemon.


s/retrun/return

thockin · 2022-02-24T17:14:22Z

klog.go

+}
+
+// newFlushDaemon retrun a new flushDaemon.
+func newFlushDaemon(interval time.Duration, flush func()) *flushDaemon {


I think you should take a clock.WithTicker argument, and if it is passed in as nil, use clock.RealClock. And document it in the comment above :)

klog_test.go

thockin · 2022-02-24T17:18:07Z

klog_test.go

+		}
+
+		testClock.Step(time.Second)
+		<-flushed


Should this be verifying something? What happens if there was a bug and flush-daemon did not call the func properly, what would this test report?

The statement verifies that flush was called and let's the test wait until the flush execution finished. If the function isn't called, the test will time out. If I don't wait for the function here, the testClock.Step() statements will be all executed directly after each other, without flushDaemon having time to flush in between, so the flushDaemon would only enter the case <-ticker.C() once, regardless of how many steps the clock does.

What I meant is maybe we should control the timeout and produce an error ourselves. The default is something like 10 minutes, right? It seems like we could wrap these reads in a timeout of 10 seconds and produce a better error.

thockin

I'm going to go ahead an approve - my last comment is pretty incremental :)

/approve
/lgtm

thockin · 2022-02-24T23:36:22Z

klog_test.go

+		}
+
+		testClock.Step(time.Second)
+		<-flushed


What I meant is maybe we should control the timeout and produce an error ourselves. The default is something like 10 minutes, right? It seems like we could wrap these reads in a timeout of 10 seconds and produce a better error.

thockin · 2022-02-27T21:14:36Z

/lgtm

k8s-ci-robot · 2022-02-27T21:14:56Z

[APPROVALNOTIFIER] This PR is APPROVED

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

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,thockin]

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

liggitt · 2022-03-18T15:16:40Z

go.mod

-require github.com/go-logr/logr v1.2.0
+require (
+	github.com/go-logr/logr v1.2.0
+	k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9


this adds a circular dependency... utils already depends on klog, we should avoid making klog also depend on utils

I think the test is useful enough that we should not remove it and instead carry a copy of the clock code -> #310

thockin · 2022-10-11T07:34:37Z

More reasons to break up utils further.

…

On Fri, Mar 18, 2022 at 10:11 AM Patrick Ohly ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In go.mod <#293 (comment)>: > @@ -2,4 +2,7 @@ module k8s.io/klog/v2 go 1.13 -require github.com/go-logr/logr v1.2.0 +require ( + github.com/go-logr/logr v1.2.0 + k8s.io/utils v0.0.0-20220210201930-3a6ce19ff2f9 I think the test is useful enough that we should not remove it and instead carry a copy of the clock code -> #310 <#310> — Reply to this email directly, view it on GitHub <#293 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVFPOQTBNGOCYQASHODVAS2NDANCNFSM5OCLIXJQ> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>. You are receiving this because you were assigned.Message ID: ***@***.***>

k8s-ci-robot added the cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. label Feb 10, 2022

k8s-ci-robot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Feb 10, 2022

k8s-ci-robot requested review from andyxning and detiber February 10, 2022 22:56

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. and removed cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. labels Feb 10, 2022

pohly reviewed Feb 11, 2022

View reviewed changes

pohly reviewed Feb 16, 2022

View reviewed changes

examples/flushing/flushing_test.go Show resolved Hide resolved

k8s-ci-robot assigned dims Feb 16, 2022

pohly approved these changes Feb 16, 2022

View reviewed changes

k8s-ci-robot assigned pohly Feb 16, 2022

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

k8s-ci-robot assigned thockin Feb 17, 2022

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

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

thockin reviewed Feb 18, 2022

View reviewed changes

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 19, 2022

thockin reviewed Feb 20, 2022

View reviewed changes

klog.go Show resolved Hide resolved

thockin reviewed Feb 20, 2022

View reviewed changes

fixup! Make flushDaemon stoppable and testable

7ad18de

thockin reviewed Feb 24, 2022

View reviewed changes

fixup! Make flushDaemon stoppable and testable

b6757a5

thockin reviewed Feb 24, 2022

View reviewed changes

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

fixup! Make flushDaemon stoppable and testable

31a05ea

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Feb 26, 2022

fixup! Make flushDaemon stoppable and testable

ec08484

thockin added tide/merge-method-squash Denotes a PR that should be squashed by tide when it merges. and removed do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. labels Feb 27, 2022

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

k8s-ci-robot merged commit 7ea6d6a into kubernetes:main Feb 27, 2022

liggitt reviewed Mar 18, 2022

View reviewed changes

pohly mentioned this pull request Mar 21, 2022

klog v2.60.1 kubernetes/kubernetes#108725

Merged

janisz mentioned this pull request May 25, 2023

Goroutine leak in glog consider switching to klog grpc/grpc-go#6316

Closed

Fix goroutine leak: make flushDaemon stoppable #293

Fix goroutine leak: make flushDaemon stoppable #293

Conversation

katexochen commented Feb 10, 2022

linux-foundation-easycla bot commented Feb 10, 2022 • edited Loading

k8s-ci-robot commented Feb 10, 2022

pohly commented Feb 11, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

katexochen commented Feb 11, 2022

pohly left a 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 Feb 11, 2022

pohly commented Feb 12, 2022

pohly left a comment

Choose a reason for hiding this comment

pohly commented Feb 16, 2022

dims commented Feb 17, 2022

thockin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

katexochen commented Feb 19, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thockin Feb 22, 2022 • edited Loading

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

thockin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thockin commented Feb 27, 2022

k8s-ci-robot commented Feb 27, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thockin commented Oct 11, 2022 via email

linux-foundation-easycla bot commented Feb 10, 2022 •

edited

Loading

thockin Feb 22, 2022 •

edited

Loading