Rewrite the whole thing with atomics

Signed-off-by: Vince Prignano <vincepri@redhat.com>

pkg/log/deleg.go

@@ -17,7 +17,11 @@ limitations under the License.
 package log
 
 import (
+	"fmt"
+	"os"
+	"runtime/debug"
 	"sync"
+	"sync/atomic"
 	"time"
 
 	"github.com/go-logr/logr"
@@ -26,7 +30,7 @@ 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
+	delegating    *DelegatingLogSink
 	childPromises []*loggerPromise
 	promisesLock  sync.Mutex
 
@@ -36,9 +40,8 @@ type loggerPromise struct {
 
 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()
@@ -50,9 +53,8 @@ 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 {
 	res := &loggerPromise{
-		logger:       l,
-		tags:         tags,
-		promisesLock: sync.Mutex{},
+		delegating: l,
+		tags:       tags,
 	}
 
 	p.promisesLock.Lock()
@@ -72,14 +74,15 @@ 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)
 	}
@@ -91,35 +94,27 @@ func (p *loggerPromise) Fulfill(parentLogSink logr.LogSink) {
 // 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 {
-	created time.Time
-	lock    sync.RWMutex
-	logger  logr.LogSink
-	promise *loggerPromise
-	info    logr.RuntimeInfo
-}
+	eventuallyFulfill func()
 
-func (l *DelegatingLogSink) eventuallyFulfill() {
-	if l.promise == nil && time.Since(l.created).Seconds() >= 30 {
-		l.Fulfill(NullLogSink{})
-	}
+	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.eventuallyFulfill()
-	l.info = info
+	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()
 	l.eventuallyFulfill()
-	return l.logger.Enabled(level)
+	return (*l.logger.Load()).Enabled(level)
 }
 
 // Info logs a non-error message with the given key/value pairs as context.
@@ -129,10 +124,8 @@ func (l *DelegatingLogSink) Enabled(level int) bool {
 // 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.eventuallyFulfill()
-	l.logger.Info(level, msg, keysAndValues...)
+	(*l.logger.Load()).Info(level, msg, keysAndValues...)
 }
 
 // Error logs an error, with the given message and key/value pairs as context.
@@ -144,71 +137,78 @@ func (l *DelegatingLogSink) Info(level int, msg string, keysAndValues ...interfa
 // 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.eventuallyFulfill()
-	l.logger.Error(err, msg, keysAndValues...)
+	(*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()
 	l.eventuallyFulfill()
 
-	if l.promise == nil {
-		sink := l.logger.WithName(name)
-		if withCallDepth, ok := sink.(logr.CallDepthLogSink); ok {
-			sink = withCallDepth.WithCallDepth(-1)
+	switch {
+	case l.promise.Load() != nil:
+		res := &DelegatingLogSink{eventuallyFulfill: l.eventuallyFulfill}
+		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()
 	l.eventuallyFulfill()
 
-	if l.promise == nil {
-		sink := l.logger.WithValues(tags...)
-		if withCallDepth, ok := sink.(logr.CallDepthLogSink); ok {
-			sink = withCallDepth.WithCallDepth(-1)
+	switch {
+	case l.promise.Load() != nil:
+		res := &DelegatingLogSink{eventuallyFulfill: l.eventuallyFulfill}
+		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)
+	if promise := l.promise.Load(); promise != nil {
+		promise.Fulfill(actual)
+		l.fulfilled.Store(true)
 	}
 }
 
 // NewDelegatingLogSink constructs a new DelegatingLogSink which uses
 // the given logger before its promise is fulfilled.
 func NewDelegatingLogSink(initial logr.LogSink) *DelegatingLogSink {
-	l := &DelegatingLogSink{
-		created: time.Now(),
-		logger:  initial,
-		promise: &loggerPromise{promisesLock: sync.Mutex{}},
+	root := &DelegatingLogSink{}
+	root.logger.Store(&initial)
+	root.promise.Store(&loggerPromise{delegating: root})
+	{
+		var fulfillOnce sync.Once
+		created := time.Now()
+		root.eventuallyFulfill = func() {
+			if !root.fulfilled.Load() && time.Since(created).Seconds() >= 30 {
+				fmt.Fprintf(os.Stderr, "[controller-runtime] log.SetLogger(...) was never called, logs will not be displayed:\n%s", debug.Stack())
+				fulfillOnce.Do(func() {
+					root.Fulfill(NullLogSink{})
+					root.fulfilled.Store(true)
+				})
+			}
+		}
 	}
-	l.promise.logger = l
-	return l
+	return root
 }