go routine created on flush logs leaks

[katexochen]

/kind bug

What steps did you take and what happened:
uber/goleak found a leaking goroutine during test run:

goleak: Errors on successful test run: found unexpected goroutines:
[Goroutine 19 in state chan receive, with k8s.io/klog/v2.(*loggingT).flushDaemon on top of the stack:
goroutine 19 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x0)
	/home/katexochen/go/pkg/mod/k8s.io/klog/v2@v2.30.0/klog.go:1181 +0x8b
created by k8s.io/klog/v2.init.0
	/home/katexochen/go/pkg/mod/k8s.io/klog/v2@v2.30.0/klog.go:420 +0x1c5
]

Previous mentioned in #188.
#190 tried to fix this.
I'm opening a new issue since both are closed now but the problem still exists.

[astoycos]

I also saw this recently when debugging unit tests for #107372

        [Goroutine 21 in state chan receive, with k8s.io/klog/v2.(*loggingT).flushDaemon on top of the stack:
        goroutine 21 [chan receive]:
        k8s.io/klog/v2.(*loggingT).flushDaemon(0x0)
                /home/astoycos/go/src/github.com/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:1283 +0x6a
        created by k8s.io/klog/v2.init.0
                /home/astoycos/go/src/github.com/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:420 +0xfb

[pohly]

Starting a goroutine in init looks really bad to me. This should be under the control of the user of the package. I recently fixed flushing in Kubernetes and had no idea that klog was also doing it internally :sad:

@dims do you think we can move that out of init into a separate function that explicitly needs to be called by those who want this? Strictly speaking, this is a user-visible change of behavior.

[pohly]

Perhaps there is a way to solve this without breaking users who currently expect automatic flushing. Flushing only does anything when createFiles is called, because that is the only place where syncBuffer is created:

klog/klog.go

Lines 1267 to 1285 in e7e4115

	// createFiles creates all the log files for severity from sev down to infoLog.
	// l.mu is held.
	func (l *loggingT) createFiles(sev severity) error {
	now := time.Now()
	// Files are created in decreasing severity order, so as soon as we find one
	// has already been created, we can stop.
	for s := sev; s >= infoLog && l.file[s] == nil; s-- {
	sb := &syncBuffer{
	logger: l,
	sev: s,
	maxbytes: CalculateMaxSize(),
	}
	if err := sb.rotateFile(now, true); err != nil {
	return err
	}
	l.file[s] = sb
	}
	return nil
	}

Without syncBuffer, there's nothing that needs to be flushed. In particular, SetOutput writes without buffering:

klog/klog.go

Lines 984 to 994 in e7e4115

	// SetOutput sets the output destination for all severities
	func SetOutput(w io.Writer) {
	logging.mu.Lock()
	defer logging.mu.Unlock()
	for s := fatalLog; s >= infoLog; s-- {
	rb := &redirectBuffer{
	w: w,
	}
	logging.file[s] = rb
	}
	}

That means that we can move the flush daemon startup from init into createFiles:

klog/klog.go

Line 420 in e7e4115

go logging.flushDaemon()

Of course it must only be started once.

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

Anyone willing to prepare a PR?

/help-wanted

[pohly]

/help

[katexochen]

Not sure if this is a good fist issue, but I will give it a try. Is there any way to test klog locally?
/remove-help

[pohly]

go test runs the existing tests, but I doubt that it covers flushing of data. Adding some unit tests for this would be good.