🐛 Fix a race in the delegating logger

For as long as the delegating loggers Fullfill wasn't called, it holds a
loggerPromise and that loggerPromise holds the same delegating logger.

Calls to With{Name,Field} and FullFill of such a loggerPromise and
delegatingLogger pair have to be serialized, because the former accesses
the actual logger and promise, while the latter sets and unsets them.

Furthermore, a call to With{Name,Field} of such a pair returns a new
pair that is attached to the parent pair by making the original promise
keep a reference to the new promise. Because of that, the aforementioned
serialization has to happen recursively for each pair.

Author: alvaroaleman

pkg/log/deleg.go

@@ -72,8 +72,10 @@ func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
 		logger = logger.WithValues(p.tags...)
 	}
 
+	p.logger.lock.Lock()
 	p.logger.Logger = logger
 	p.logger.promise = nil
+	p.logger.lock.Unlock()
 
 	for _, childPromise := range p.childPromises {
 		childPromise.Fulfill(logger)
@@ -86,12 +88,16 @@ func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
 // logger.  It expects to have *some* logr.Logger set at all times (generally
 // a no-op logger before the promises are fulfilled).
 type DelegatingLogger struct {
+	lock sync.Mutex
 	logr.Logger
 	promise *loggerPromise
 }
 
 // WithName provides a new Logger with the name appended
 func (l *DelegatingLogger) WithName(name string) logr.Logger {
+	l.lock.Lock()
+	defer l.lock.Unlock()
+
 	if l.promise == nil {
 		return l.Logger.WithName(name)
 	}
@@ -105,6 +111,9 @@ func (l *DelegatingLogger) WithName(name string) logr.Logger {
 
 // WithValues provides a new Logger with the tags appended
 func (l *DelegatingLogger) WithValues(tags ...interface{}) logr.Logger {
+	l.lock.Lock()
+	defer l.lock.Unlock()
+
 	if l.promise == nil {
 		return l.Logger.WithValues(tags...)
 	}

pkg/log/log_test.go

@@ -162,6 +162,44 @@ var _ = Describe("logging", func() {
 			))
 		})
 
+		// This test in itself will always succeed, a failure will be indicated by the
+		// race detector going off
+		It("should be threadsafe", func() {
+			fulfillDone := make(chan struct{})
+			withNameDone := make(chan struct{})
+			withValuesDone := make(chan struct{})
+			grandChildDone := make(chan struct{})
+
+			// Constructing the child in the goroutine does not reliably
+			// trigger the race detector
+			child := delegLog.WithName("child")
+			go func() {
+				defer GinkgoRecover()
+				delegLog.Fulfill(NullLogger{})
+				close(fulfillDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.WithName("with-name")
+				close(withNameDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.WithValues("with-value")
+				close(withValuesDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				child.WithValues("grandchild")
+				close(grandChildDone)
+			}()
+
+			<-fulfillDone
+			<-withNameDone
+			<-withValuesDone
+			<-grandChildDone
+		})
+
 		It("should delegate with tags", func() {
 			By("asking for a logger with a name before fulfill, and logging")
 			befFulfill1 := delegLog.WithValues("tag1", "val1")