⚠️ Unexport delegating logger, remove async init

pkg/log/deleg.go

@@ -25,15 +25,15 @@ import (
 // loggerPromise knows how to populate a concrete logr.Logger
 // with options, given an actual base logger later on down the line.
 type loggerPromise struct {
-	logger        *DelegatingLogSink
+	logger        *delegatingLogSink
 	childPromises []*loggerPromise
 	promisesLock  sync.Mutex
 
 	name *string
 	tags []interface{}
 }
 
-func (p *loggerPromise) WithName(l *DelegatingLogSink, name string) *loggerPromise {
+func (p *loggerPromise) WithName(l *delegatingLogSink, name string) *loggerPromise {
 	res := &loggerPromise{
 		logger:       l,
 		name:         &name,
@@ -47,7 +47,7 @@ func (p *loggerPromise) WithName(l *DelegatingLogSink, name string) *loggerPromi
 }
 
 // WithValues provides a new Logger with the tags appended.
-func (p *loggerPromise) WithValues(l *DelegatingLogSink, tags ...interface{}) *loggerPromise {
+func (p *loggerPromise) WithValues(l *delegatingLogSink, tags ...interface{}) *loggerPromise {
 	res := &loggerPromise{
 		logger:       l,
 		tags:         tags,
@@ -84,20 +84,21 @@ func (p *loggerPromise) Fulfill(parentLogSink logr.LogSink) {
 	}
 }
 
-// DelegatingLogSink is a logsink that delegates to another logr.LogSink.
+// delegatingLogSink is a logsink that delegates to another logr.LogSink.
 // If the underlying promise is not nil, it registers calls to sub-loggers with
 // the logging factory to be populated later, and returns a new delegating
 // logger.  It expects to have *some* logr.Logger set at all times (generally
 // a no-op logger before the promises are fulfilled).
-type DelegatingLogSink struct {
+type delegatingLogSink struct {
 	lock    sync.RWMutex
 	logger  logr.LogSink
 	promise *loggerPromise
 	info    logr.RuntimeInfo
 }
 
 // Init implements logr.LogSink.
-func (l *DelegatingLogSink) Init(info logr.RuntimeInfo) {
+func (l *delegatingLogSink) Init(info logr.RuntimeInfo) {
+	eventuallyFulfillRoot()
 	l.lock.Lock()
 	defer l.lock.Unlock()
 	l.info = info
@@ -106,7 +107,8 @@ func (l *DelegatingLogSink) Init(info logr.RuntimeInfo) {
 // Enabled tests whether this Logger is enabled.  For example, commandline
 // flags might be used to set the logging verbosity and disable some info
 // logs.
-func (l *DelegatingLogSink) Enabled(level int) bool {
+func (l *delegatingLogSink) Enabled(level int) bool {
+	eventuallyFulfillRoot()
 	l.lock.RLock()
 	defer l.lock.RUnlock()
 	return l.logger.Enabled(level)
@@ -118,7 +120,8 @@ func (l *DelegatingLogSink) Enabled(level int) bool {
 // the log line.  The key/value pairs can then be used to add additional
 // variable information.  The key/value pairs should alternate string
 // keys and arbitrary values.
-func (l *DelegatingLogSink) Info(level int, msg string, keysAndValues ...interface{}) {
+func (l *delegatingLogSink) Info(level int, msg string, keysAndValues ...interface{}) {
+	eventuallyFulfillRoot()
 	l.lock.RLock()
 	defer l.lock.RUnlock()
 	l.logger.Info(level, msg, keysAndValues...)
@@ -132,14 +135,16 @@ func (l *DelegatingLogSink) Info(level int, msg string, keysAndValues ...interfa
 // The msg field should be used to add context to any underlying error,
 // while the err field should be used to attach the actual error that
 // triggered this log line, if present.
-func (l *DelegatingLogSink) Error(err error, msg string, keysAndValues ...interface{}) {
+func (l *delegatingLogSink) Error(err error, msg string, keysAndValues ...interface{}) {
+	eventuallyFulfillRoot()
 	l.lock.RLock()
 	defer l.lock.RUnlock()
 	l.logger.Error(err, msg, keysAndValues...)
 }
 
 // WithName provides a new Logger with the name appended.
-func (l *DelegatingLogSink) WithName(name string) logr.LogSink {
+func (l *delegatingLogSink) WithName(name string) logr.LogSink {
+	eventuallyFulfillRoot()
 	l.lock.RLock()
 	defer l.lock.RUnlock()
 
@@ -151,15 +156,16 @@ func (l *DelegatingLogSink) WithName(name string) logr.LogSink {
 		return sink
 	}
 
-	res := &DelegatingLogSink{logger: l.logger}
+	res := &delegatingLogSink{logger: l.logger}
 	promise := l.promise.WithName(res, name)
 	res.promise = promise
 
 	return res
 }
 
 // WithValues provides a new Logger with the tags appended.
-func (l *DelegatingLogSink) WithValues(tags ...interface{}) logr.LogSink {
+func (l *delegatingLogSink) WithValues(tags ...interface{}) logr.LogSink {
+	eventuallyFulfillRoot()
 	l.lock.RLock()
 	defer l.lock.RUnlock()
 
@@ -171,7 +177,7 @@ func (l *DelegatingLogSink) WithValues(tags ...interface{}) logr.LogSink {
 		return sink
 	}
 
-	res := &DelegatingLogSink{logger: l.logger}
+	res := &delegatingLogSink{logger: l.logger}
 	promise := l.promise.WithValues(res, tags...)
 	res.promise = promise
 
@@ -181,16 +187,16 @@ func (l *DelegatingLogSink) WithValues(tags ...interface{}) logr.LogSink {
 // Fulfill switches the logger over to use the actual logger
 // provided, instead of the temporary initial one, if this method
 // has not been previously called.
-func (l *DelegatingLogSink) Fulfill(actual logr.LogSink) {
+func (l *delegatingLogSink) Fulfill(actual logr.LogSink) {
 	if l.promise != nil {
 		l.promise.Fulfill(actual)
 	}
 }
 
-// NewDelegatingLogSink constructs a new DelegatingLogSink which uses
+// newDelegatingLogSink constructs a new DelegatingLogSink which uses
 // the given logger before its promise is fulfilled.
-func NewDelegatingLogSink(initial logr.LogSink) *DelegatingLogSink {
-	l := &DelegatingLogSink{
+func newDelegatingLogSink(initial logr.LogSink) *delegatingLogSink {
+	l := &delegatingLogSink{
 		logger:  initial,
 		promise: &loggerPromise{promisesLock: sync.Mutex{}},
 	}

pkg/log/log.go

@@ -35,43 +35,35 @@ package log
 
 import (
 	"context"
-	"sync"
+	"fmt"
+	"os"
+	"runtime/debug"
+	"sync/atomic"
 	"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
-	dlog.Fulfill(l.GetSink())
+	logFullfilled.Store(true)
+	rootLog.Fulfill(l.GetSink())
 }
 
-// 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 DelegatingLogSink causes a high number of memory
-// allocations when not given an actual Logger, so we set a NullLogSink to avoid that.
-//
-// We need to keep the DelegatingLogSink 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 {
-			dlog.Fulfill(NullLogSink{})
+func eventuallyFulfillRoot() {
+	if logFullfilled.Load() {
+		return
+	}
+	if time.Since(rootLogCreated).Seconds() >= 30 {
+		if logFullfilled.CompareAndSwap(false, true) {
+			fmt.Fprintf(os.Stderr, "[controller-runtime] log.SetLogger(...) was never called, logs will not be displayed:\n%s", debug.Stack())
+			SetLogger(logr.New(NullLogSink{}))
 		}
-	}()
+	}
 }
 
 var (
-	loggerWasSetLock sync.Mutex
-	loggerWasSet     bool
+	logFullfilled atomic.Bool
 )
 
 // Log is the base logger used by kubebuilder.  It delegates
@@ -80,8 +72,10 @@ var (
 // the first 30 seconds of a binaries lifetime, it will get
 // set to a NullLogSink.
 var (
-	dlog = NewDelegatingLogSink(NullLogSink{})
-	Log  = logr.New(dlog)
+	rootLog, rootLogCreated = func() (*delegatingLogSink, time.Time) {
+		return newDelegatingLogSink(NullLogSink{}), time.Now()
+	}()
+	Log = logr.New(rootLog)
 )
 
 // FromContext returns a logger with predefined values from a context.Context.

pkg/log/log_test.go

@@ -25,7 +25,7 @@ import (
 	. "github.com/onsi/gomega"
 )
 
-var _ logr.LogSink = &DelegatingLogSink{}
+var _ logr.LogSink = &delegatingLogSink{}
 
 // logInfo is the information for a particular fakeLogger message.
 type logInfo struct {
@@ -124,13 +124,13 @@ var _ = Describe("logging", func() {
 		var (
 			root     *fakeLoggerRoot
 			baseLog  logr.LogSink
-			delegLog *DelegatingLogSink
+			delegLog *delegatingLogSink
 		)
 
 		BeforeEach(func() {
 			root = &fakeLoggerRoot{}
 			baseLog = &fakeLogger{root: root}
-			delegLog = NewDelegatingLogSink(NullLogSink{})
+			delegLog = newDelegatingLogSink(NullLogSink{})
 		})
 
 		It("should delegate with name", func() {