From 2aaa357671a88c6b34126a1fa3f135dd023e1396 Mon Sep 17 00:00:00 2001
From: Alvaro Aleman <alvaroaleman@users.noreply.github.com>
Date: Thu, 14 Jan 2021 23:36:34 -0500
Subject: [PATCH] :bug: 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.
---
 pkg/log/deleg.go    |  9 +++++++++
 pkg/log/log_test.go | 38 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 47 insertions(+)

diff --git a/pkg/log/deleg.go b/pkg/log/deleg.go
index 949117f6bb..d619a460fa 100644
--- a/pkg/log/deleg.go
+++ b/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...)
 	}
diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go
index 015bf32b78..c85e264ede 100644
--- a/pkg/log/log_test.go
+++ b/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")