Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

馃悰 pkg/log: Set Log to NullLogger after 30 seconds #1309

Merged
merged 1 commit into from
Jan 6, 2021
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
36 changes: 34 additions & 2 deletions pkg/log/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -35,18 +35,50 @@ package log

import (
"context"
"sync"
"time"

"github.com/go-logr/logr"
)

// SetLogger sets a concrete logging implementation for all deferred Loggers.
func SetLogger(l logr.Logger) {
loggerWasSetLock.Lock()
defer loggerWasSetLock.Unlock()

loggerWasSet = true
Log.Fulfill(l)
}

// 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{})
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want to print out a warning or error of some sort before transitioning the logger?

It seems that the delegating logger default might not be the best choice if it could potentially fill up memory if used for a long period of time.

We could also change direction here and default to a well known logger instead?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want to print out a warning or error of some sort before transitioning the logger?

Hm good idea, but what logger should we use? Generally, this doesn't change anything unless someone changed the logger after more than 30 seconds before which I think is unlikely

It seems that the delegating logger default might not be the best choice if it could potentially fill up memory if used for a long period of time.

See the description in the PR, we need it because various packages construct a logger via init which always happens before any non-controller-runtime code is executed. Without the delegating logger it is impossible to set the logger for those. It is only inefficient if no logger is set.

We could also change direction here and default to a well known logger instead?

Sure

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah that makes sense, I was thinking when we're transitioning we could print an error to stderr via the stdlib log package

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The alternative is to just default to klogr and let folks use a different logger if they want to, we could do the init of the default logger early when the package loads up, which should solve the problem described above

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think it properly solves the problem, because right now you can set the global base logger for everything via SetLogger (which IMHO is convenient and useful). What you describe would only allow to override the default logger within the components.

Also, c-r doesn't use klogr anywhere that I am aware, it uses zap with a logr.Logger wrapper.

So right now the whole thing is documented as not logging anything if SetLogger is not called, so changing that would make this PR break compatibility, hence I would prefer to stick with the NullLogger so this can be backported. WDYT?

Copy link
Member

@vincepri vincepri Jan 4, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That sounds good for now yeah, I was more brainstorming for later / long term

}
}()
}

var (
loggerWasSetLock sync.Mutex
loggerWasSet bool
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could also use an atomic bool?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

atomic bool?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Meant something like https://golang.org/pkg/sync/atomic/#CompareAndSwapInt64, this is really low priority though

)

// Log is the base logger used by kubebuilder. It delegates
// to another logr.Logger. You *must* call SetLogger to
// get any actual logging.
// to another logr.Logger. You *must* call SetLogger to
// get any actual logging. If SetLogger is not called within
// the first 30 seconds of a binaries lifetime, it will get
// set to a NullLogger.
var Log = NewDelegatingLogger(NullLogger{})

// FromContext returns a logger with predefined values from a context.Context.
Expand Down