🐛 Remove goroutine from logger init

pkg/log/deleg.go

@@ -18,26 +18,27 @@ package log
 
 import (
 	"sync"
+	"sync/atomic"
+	"time"
 
 	"github.com/go-logr/logr"
 )
 
 // 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
+	delegating    *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,
-		promisesLock: sync.Mutex{},
+		delegating: l,
+		name:       &name,
 	}
 
 	p.promisesLock.Lock()
@@ -47,11 +48,10 @@ 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,
-		promisesLock: sync.Mutex{},
+		delegating: l,
+		tags:       tags,
 	}
 
 	p.promisesLock.Lock()
@@ -71,45 +71,47 @@ func (p *loggerPromise) Fulfill(parentLogSink logr.LogSink) {
 		sink = sink.WithValues(p.tags...)
 	}
 
-	p.logger.lock.Lock()
-	p.logger.logger = sink
+	p.delegating.logger.Store(&sink)
 	if withCallDepth, ok := sink.(logr.CallDepthLogSink); ok {
-		p.logger.logger = withCallDepth.WithCallDepth(1)
+		sinkWithCallDepth := withCallDepth.WithCallDepth(1)
+		p.delegating.logger.Store(&sinkWithCallDepth)
 	}
-	p.logger.promise = nil
-	p.logger.lock.Unlock()
+	p.delegating.promise.Store(nil)
 
+	p.promisesLock.Lock()
+	defer p.promisesLock.Unlock()
 	for _, childPromise := range p.childPromises {
 		childPromise.Fulfill(sink)
 	}
 }
 
-// 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 {
-	lock    sync.RWMutex
-	logger  logr.LogSink
-	promise *loggerPromise
-	info    logr.RuntimeInfo
+type delegatingLogSink struct {
+	created time.Time
+
+	info   atomic.Pointer[logr.RuntimeInfo]
+	logger atomic.Pointer[logr.LogSink]
+
+	fulfilled atomic.Bool
+	promise   atomic.Pointer[loggerPromise]
 }
 
 // Init implements logr.LogSink.
-func (l *DelegatingLogSink) Init(info logr.RuntimeInfo) {
-	l.lock.Lock()
-	defer l.lock.Unlock()
-	l.info = info
+func (l *delegatingLogSink) Init(info logr.RuntimeInfo) {
+	eventuallyFulfillRoot()
+	l.info.Store(&info)
 }
 
 // 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 {
-	l.lock.RLock()
-	defer l.lock.RUnlock()
-	return l.logger.Enabled(level)
+func (l *delegatingLogSink) Enabled(level int) bool {
+	eventuallyFulfillRoot()
+	return (*l.logger.Load()).Enabled(level)
 }
 
 // Info logs a non-error message with the given key/value pairs as context.
@@ -118,10 +120,9 @@ 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{}) {
-	l.lock.RLock()
-	defer l.lock.RUnlock()
-	l.logger.Info(level, msg, keysAndValues...)
+func (l *delegatingLogSink) Info(level int, msg string, keysAndValues ...interface{}) {
+	eventuallyFulfillRoot()
+	(*l.logger.Load()).Info(level, msg, keysAndValues...)
 }
 
 // Error logs an error, with the given message and key/value pairs as context.
@@ -132,68 +133,66 @@ 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{}) {
-	l.lock.RLock()
-	defer l.lock.RUnlock()
-	l.logger.Error(err, msg, keysAndValues...)
+func (l *delegatingLogSink) Error(err error, msg string, keysAndValues ...interface{}) {
+	eventuallyFulfillRoot()
+	(*l.logger.Load()).Error(err, msg, keysAndValues...)
 }
 
 // WithName provides a new Logger with the name appended.
-func (l *DelegatingLogSink) WithName(name string) logr.LogSink {
-	l.lock.RLock()
-	defer l.lock.RUnlock()
-
-	if l.promise == nil {
-		sink := l.logger.WithName(name)
-		if withCallDepth, ok := sink.(logr.CallDepthLogSink); ok {
-			sink = withCallDepth.WithCallDepth(-1)
+func (l *delegatingLogSink) WithName(name string) logr.LogSink {
+	eventuallyFulfillRoot()
+
+	switch {
+	case l.promise.Load() != nil:
+		res := &delegatingLogSink{}
+		res.logger.Store(l.logger.Load())
+		promise := l.promise.Load().WithName(res, name)
+		res.promise.Store(promise)
+		return res
+	default:
+		res := (*l.logger.Load()).WithName(name)
+		if withCallDepth, ok := res.(logr.CallDepthLogSink); ok {
+			res = withCallDepth.WithCallDepth(-1)
 		}
-		return sink
+		return res
 	}
-
-	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 {
-	l.lock.RLock()
-	defer l.lock.RUnlock()
-
-	if l.promise == nil {
-		sink := l.logger.WithValues(tags...)
-		if withCallDepth, ok := sink.(logr.CallDepthLogSink); ok {
-			sink = withCallDepth.WithCallDepth(-1)
+func (l *delegatingLogSink) WithValues(tags ...interface{}) logr.LogSink {
+	eventuallyFulfillRoot()
+
+	switch {
+	case l.promise.Load() != nil:
+		res := &delegatingLogSink{}
+		res.logger.Store(l.logger.Load())
+		promise := l.promise.Load().WithValues(res, tags...)
+		res.promise.Store(promise)
+		return res
+	default:
+		res := (*l.logger.Load()).WithValues(tags...)
+		if withCallDepth, ok := res.(logr.CallDepthLogSink); ok {
+			res = withCallDepth.WithCallDepth(-1)
 		}
-		return sink
+		return res
 	}
-
-	res := &DelegatingLogSink{logger: l.logger}
-	promise := l.promise.WithValues(res, tags...)
-	res.promise = promise
-
-	return res
 }
 
 // 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) {
-	if l.promise != nil {
-		l.promise.Fulfill(actual)
+func (l *delegatingLogSink) Fulfill(actual logr.LogSink) {
+	if promise := l.promise.Load(); promise != nil {
+		promise.Fulfill(actual)
+		l.fulfilled.Store(true)
 	}
 }
 
-// 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{
-		logger:  initial,
-		promise: &loggerPromise{promisesLock: sync.Mutex{}},
-	}
-	l.promise.logger = l
-	return l
+func newDelegatingRoot(initial logr.LogSink) *delegatingLogSink {
+	root := &delegatingLogSink{created: time.Now()}
+	root.logger.Store(&initial)
+	root.promise.Store(&loggerPromise{delegating: root})
+	return root
 }

pkg/log/log.go

@@ -35,55 +35,36 @@ package log
 
 import (
 	"context"
-	"sync"
+	"fmt"
+	"os"
+	"runtime/debug"
 	"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())
-}
-
-// 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{})
-		}
-	}()
-}
-
-var (
-	loggerWasSetLock sync.Mutex
-	loggerWasSet     bool
-)
-
 // Log is the base logger used by kubebuilder.  It delegates
 // 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 NullLogSink.
 var (
-	dlog = NewDelegatingLogSink(NullLogSink{})
-	Log  = logr.New(dlog)
+	rootLog = newDelegatingRoot(NullLogSink{})
+	Log     = logr.New(rootLog)
 )
 
+// SetLogger sets a concrete logging implementation for all deferred Loggers.
+func SetLogger(l logr.Logger) {
+	rootLog.Fulfill(l.GetSink())
+}
+
+func eventuallyFulfillRoot() {
+	if !rootLog.fulfilled.Load() && time.Since(rootLog.created).Seconds() >= 30 {
+		fmt.Fprintf(os.Stderr, "[controller-runtime] log.SetLogger(...) was never called, logs will not be displayed:\n%s", debug.Stack())
+		SetLogger(logr.New(NullLogSink{}))
+	}
+}
+
 // FromContext returns a logger with predefined values from a context.Context.
 func FromContext(ctx context.Context, keysAndValues ...interface{}) logr.Logger {
 	log := Log

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 = newDelegatingRoot(NullLogSink{})
 		})
 
 		It("should delegate with name", func() {