Unsafe assumptions and leaked goroutine in logging

[howardjohn]

This code is problematic:

controller-runtime/pkg/log/log.go

Lines 53 to 70 in 498ee8a

	// It is safe to assume that if this wasn't set within the first 30 seconds of a binaries
	// lifetime, it will never get set. The DelegatingLogger causes a high number of memory
	// allocations when not given an actual Logger, so we set a NullLogger to avoid that.
	//
	// We need to keep the DelegatingLogger because we have various inits() that get a logger from
	// here. They will always get executed before any code that imports controller-runtime
	// has a chance to run and hence to set an actual logger.
	func init() {
	// Init is blocking, so start a new goroutine
	go func() {
	time.Sleep(30 * time.Second)
	loggerWasSetLock.Lock()
	defer loggerWasSetLock.Unlock()
	if !loggerWasSet {
	Log.Fulfill(NullLogger{})
	}
	}()
	}

First, it leaks a goroutine for 30s just by importing the library. Generally its assumed an import is not creating goroutines. The real world impact of this is that various projects (Istio, gRPC, etc) have tests that assert no goroutines are leaking; these fail if controller-runtime is so much as imported.

Another issue is It is safe to assume that if this wasn't set within the first 30 seconds of a binaries. This seems not safe to assert. There is certainly no reason that I cannot set a logger 31s or 30h into the process lifetime. The controller-runtime library can and is used as a small piece of larger binaries; its not always the sole thing running in the process.

[coderanger]

The controller-runtime library can and is used as a small piece of larger binaries; its not always the sole thing running in the process

While we want to improve the use cases around this, especially because the controller-runtime client is so much nicer to work with than client-go for many use cases, we do still largely optimize for writing operators with tools like Kubebuilder and Operator-SDK where controller-runtime is indeed in overarching control of the universe. This code was added to fix some substantial memory leak issues due to dangling loggers. If you have suggestions on how to improve this without hurting the primary use cases, please do let us know.

[alvaroaleman]

Hey @howardjohn ,

The reason this logic exists is that the DelegatingLogger ends up consuming a huge amount of memory if no Logger gets set: #1122

The current logic is the best we could come up with to deal with that situation and "leaking" a goroutine for 30 seconds/not allowing to set a logger after that is definitely less of an issue than the memory consumption.

If you have any ideas on how to improve things here, they are very welcome.

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle stale
• Mark this issue or PR as rotten with /lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue or PR with /reopen
• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close

[k8s-ci-robot]

@k8s-triage-robot: Closing this issue.

In response to this:

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue or PR with /reopen
• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close

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.

[ash2k]

I just found this weird goroutine in a debugging session.

If you have any ideas on how to improve things here, they are very welcome.

Why not use klog, like Kubernetes? That would be consistent and not a surprise at all. Most apps that care about logs and use Kubernetes libraries set klog logger via klog.SetOutput().

/reopen
/remove-lifecycle rotten

[k8s-ci-robot]

@ash2k: Reopened this issue.

In response to this:

I just found this weird goroutine in a debugging session.

If you have any ideas on how to improve things here, they are very welcome.

Why not use klog, like Kubernetes? That would be consistent and not a surprise at all. Most apps that care about logs and use Kubernetes libraries set klog logger via klog.SetOutput().

/reopen
/remove-lifecycle rotten

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.

[k8s-triage-robot]

The Kubernetes project currently lacks enough contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle stale
• Mark this issue or PR as rotten with /lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue with /reopen
• Mark this issue as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

[k8s-ci-robot]

@k8s-triage-robot: Closing this issue, marking it as "Not Planned".

In response to this:

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Reopen this issue with /reopen
• Mark this issue as fresh with /remove-lifecycle rotten
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/close not-planned

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.

[ash2k]

/reopen
/remove-lifecycle rotten

[k8s-ci-robot]

@ash2k: Reopened this issue.

In response to this:

/reopen
/remove-lifecycle rotten

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.