🐛 Fix some more races in the delegating logger

The delegatingLogger had a logger implementation embedded, calling any
method of that would race with FullFill(), which replaces the embedded
logger.

pkg/log/deleg.go

@@ -29,11 +29,11 @@ type loggerPromise struct {
 	childPromises []*loggerPromise
 	promisesLock  sync.Mutex
 
-	name *string
-	tags []interface{}
+	name  *string
+	tags  []interface{}
+	level int
 }
 
-// WithName provides a new Logger with the name appended
 func (p *loggerPromise) WithName(l *DelegatingLogger, name string) *loggerPromise {
 	res := &loggerPromise{
 		logger:       l,
@@ -61,6 +61,19 @@ func (p *loggerPromise) WithValues(l *DelegatingLogger, tags ...interface{}) *lo
 	return res
 }
 
+func (p *loggerPromise) V(l *DelegatingLogger, level int) *loggerPromise {
+	res := &loggerPromise{
+		logger:       l,
+		level:        level,
+		promisesLock: sync.Mutex{},
+	}
+
+	p.promisesLock.Lock()
+	defer p.promisesLock.Unlock()
+	p.childPromises = append(p.childPromises, res)
+	return res
+}
+
 // Fulfill instantiates the Logger with the provided logger
 func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
 	var logger = parentLogger
@@ -71,9 +84,12 @@ func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
 	if p.tags != nil {
 		logger = logger.WithValues(p.tags...)
 	}
+	if p.level != 0 {
+		logger = logger.V(p.level)
+	}
 
 	p.logger.lock.Lock()
-	p.logger.Logger = logger
+	p.logger.logger = logger
 	p.logger.promise = nil
 	p.logger.lock.Unlock()
 
@@ -88,21 +104,75 @@ 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
+	lock    sync.RWMutex
+	logger  logr.Logger
 	promise *loggerPromise
 }
 
+// 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 *DelegatingLogger) Enabled() bool {
+	l.lock.RLock()
+	defer l.lock.RUnlock()
+	return l.logger.Enabled()
+}
+
+// Info logs a non-error message with the given key/value pairs as context.
+//
+// The msg argument should be used to add some constant description to
+// 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 *DelegatingLogger) Info(msg string, keysAndValues ...interface{}) {
+	l.lock.RLock()
+	defer l.lock.RUnlock()
+	l.logger.Info(msg, keysAndValues...)
+}
+
+// Error logs an error, with the given message and key/value pairs as context.
+// It functions similarly to calling Info with the "error" named value, but may
+// have unique behavior, and should be preferred for logging errors (see the
+// package documentations for more information).
+//
+// 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 *DelegatingLogger) Error(err error, msg string, keysAndValues ...interface{}) {
+	l.lock.RLock()
+	defer l.lock.RUnlock()
+	l.logger.Error(err, msg, keysAndValues...)
+}
+
+// V returns an Logger value for a specific verbosity level, relative to
+// this Logger.  In other words, V values are additive.  V higher verbosity
+// level means a log message is less important.  It's illegal to pass a log
+// level less than zero.
+func (l *DelegatingLogger) V(level int) logr.Logger {
+	l.lock.RLock()
+	defer l.lock.RUnlock()
+
+	if l.promise == nil {
+		return l.logger.V(level)
+	}
+
+	res := &DelegatingLogger{logger: l.logger}
+	promise := l.promise.V(res, level)
+	res.promise = promise
+
+	return res
+}
+
 // WithName provides a new Logger with the name appended
 func (l *DelegatingLogger) WithName(name string) logr.Logger {
-	l.lock.Lock()
-	defer l.lock.Unlock()
+	l.lock.RLock()
+	defer l.lock.RUnlock()
 
 	if l.promise == nil {
-		return l.Logger.WithName(name)
+		return l.logger.WithName(name)
 	}
 
-	res := &DelegatingLogger{Logger: l.Logger}
+	res := &DelegatingLogger{logger: l.logger}
 	promise := l.promise.WithName(res, name)
 	res.promise = promise
 
@@ -111,14 +181,14 @@ 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()
+	l.lock.RLock()
+	defer l.lock.RUnlock()
 
 	if l.promise == nil {
-		return l.Logger.WithValues(tags...)
+		return l.logger.WithValues(tags...)
 	}
 
-	res := &DelegatingLogger{Logger: l.Logger}
+	res := &DelegatingLogger{logger: l.logger}
 	promise := l.promise.WithValues(res, tags...)
 	res.promise = promise
 
@@ -138,7 +208,7 @@ func (l *DelegatingLogger) Fulfill(actual logr.Logger) {
 // the given logger before it's promise is fulfilled.
 func NewDelegatingLogger(initial logr.Logger) *DelegatingLogger {
 	l := &DelegatingLogger{
-		Logger:  initial,
+		logger:  initial,
 		promise: &loggerPromise{promisesLock: sync.Mutex{}},
 	}
 	l.promise.logger = l

pkg/log/log_test.go

@@ -18,12 +18,15 @@ package log
 
 import (
 	"context"
+	"errors"
 
 	"github.com/go-logr/logr"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 )
 
+var _ logr.Logger = &DelegatingLogger{}
+
 // logInfo is the information for a particular fakeLogger message
 type logInfo struct {
 	name []string
@@ -169,6 +172,10 @@ var _ = Describe("logging", func() {
 			withNameDone := make(chan struct{})
 			withValuesDone := make(chan struct{})
 			grandChildDone := make(chan struct{})
+			logEnabledDone := make(chan struct{})
+			logInfoDone := make(chan struct{})
+			logErrorDone := make(chan struct{})
+			logVDone := make(chan struct{})
 
 			// Constructing the child in the goroutine does not reliably
 			// trigger the race detector
@@ -193,11 +200,35 @@ var _ = Describe("logging", func() {
 				child.WithValues("grandchild")
 				close(grandChildDone)
 			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.Enabled()
+				close(logEnabledDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.Info("hello world")
+				close(logInfoDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.Error(errors.New("err"), "hello world")
+				close(logErrorDone)
+			}()
+			go func() {
+				defer GinkgoRecover()
+				delegLog.V(1)
+				close(logVDone)
+			}()
 
 			<-fulfillDone
 			<-withNameDone
 			<-withValuesDone
 			<-grandChildDone
+			<-logEnabledDone
+			<-logInfoDone
+			<-logErrorDone
+			<-logVDone
 		})
 
 		It("should delegate with tags", func() {