Skip to content

Commit ab23736

Browse files
committed
⚠️ 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.
1 parent 9e78e65 commit ab23736

File tree

2 files changed

+116
-15
lines changed

2 files changed

+116
-15
lines changed

pkg/log/deleg.go

+85-15
Original file line numberDiff line numberDiff line change
@@ -29,11 +29,11 @@ type loggerPromise struct {
2929
childPromises []*loggerPromise
3030
promisesLock sync.Mutex
3131

32-
name *string
33-
tags []interface{}
32+
name *string
33+
tags []interface{}
34+
level int
3435
}
3536

36-
// WithName provides a new Logger with the name appended
3737
func (p *loggerPromise) WithName(l *DelegatingLogger, name string) *loggerPromise {
3838
res := &loggerPromise{
3939
logger: l,
@@ -61,6 +61,19 @@ func (p *loggerPromise) WithValues(l *DelegatingLogger, tags ...interface{}) *lo
6161
return res
6262
}
6363

64+
func (p *loggerPromise) V(l *DelegatingLogger, level int) *loggerPromise {
65+
res := &loggerPromise{
66+
logger: l,
67+
level: level,
68+
promisesLock: sync.Mutex{},
69+
}
70+
71+
p.promisesLock.Lock()
72+
defer p.promisesLock.Unlock()
73+
p.childPromises = append(p.childPromises, res)
74+
return res
75+
}
76+
6477
// Fulfill instantiates the Logger with the provided logger
6578
func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
6679
var logger = parentLogger
@@ -71,9 +84,12 @@ func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
7184
if p.tags != nil {
7285
logger = logger.WithValues(p.tags...)
7386
}
87+
if p.level != 0 {
88+
logger = logger.V(p.level)
89+
}
7490

7591
p.logger.lock.Lock()
76-
p.logger.Logger = logger
92+
p.logger.logger = logger
7793
p.logger.promise = nil
7894
p.logger.lock.Unlock()
7995

@@ -88,21 +104,75 @@ func (p *loggerPromise) Fulfill(parentLogger logr.Logger) {
88104
// logger. It expects to have *some* logr.Logger set at all times (generally
89105
// a no-op logger before the promises are fulfilled).
90106
type DelegatingLogger struct {
91-
lock sync.Mutex
92-
logr.Logger
107+
lock sync.RWMutex
108+
logger logr.Logger
93109
promise *loggerPromise
94110
}
95111

112+
// Enabled tests whether this Logger is enabled. For example, commandline
113+
// flags might be used to set the logging verbosity and disable some info
114+
// logs.
115+
func (l *DelegatingLogger) Enabled() bool {
116+
l.lock.RLock()
117+
defer l.lock.RUnlock()
118+
return l.logger.Enabled()
119+
}
120+
121+
// Info logs a non-error message with the given key/value pairs as context.
122+
//
123+
// The msg argument should be used to add some constant description to
124+
// the log line. The key/value pairs can then be used to add additional
125+
// variable information. The key/value pairs should alternate string
126+
// keys and arbitrary values.
127+
func (l *DelegatingLogger) Info(msg string, keysAndValues ...interface{}) {
128+
l.lock.RLock()
129+
defer l.lock.RUnlock()
130+
l.logger.Info(msg, keysAndValues...)
131+
}
132+
133+
// Error logs an error, with the given message and key/value pairs as context.
134+
// It functions similarly to calling Info with the "error" named value, but may
135+
// have unique behavior, and should be preferred for logging errors (see the
136+
// package documentations for more information).
137+
//
138+
// The msg field should be used to add context to any underlying error,
139+
// while the err field should be used to attach the actual error that
140+
// triggered this log line, if present.
141+
func (l *DelegatingLogger) Error(err error, msg string, keysAndValues ...interface{}) {
142+
l.lock.RLock()
143+
defer l.lock.RUnlock()
144+
l.logger.Error(err, msg, keysAndValues...)
145+
}
146+
147+
// V returns an Logger value for a specific verbosity level, relative to
148+
// this Logger. In other words, V values are additive. V higher verbosity
149+
// level means a log message is less important. It's illegal to pass a log
150+
// level less than zero.
151+
func (l *DelegatingLogger) V(level int) logr.Logger {
152+
l.lock.RLock()
153+
defer l.lock.RUnlock()
154+
155+
if l.promise == nil {
156+
return l.logger.V(level)
157+
}
158+
159+
res := &DelegatingLogger{logger: l.logger}
160+
promise := l.promise.V(res, level)
161+
res.promise = promise
162+
163+
return res
164+
}
165+
96166
// WithName provides a new Logger with the name appended
97167
func (l *DelegatingLogger) WithName(name string) logr.Logger {
98-
l.lock.Lock()
99-
defer l.lock.Unlock()
168+
l.lock.RLock()
169+
defer l.lock.RUnlock()
100170

101171
if l.promise == nil {
102-
return l.Logger.WithName(name)
172+
return l.logger.WithName(name)
103173
}
104174

105-
res := &DelegatingLogger{Logger: l.Logger}
175+
res := &DelegatingLogger{logger: l.logger}
106176
promise := l.promise.WithName(res, name)
107177
res.promise = promise
108178

@@ -111,14 +181,14 @@ func (l *DelegatingLogger) WithName(name string) logr.Logger {
111181

112182
// WithValues provides a new Logger with the tags appended
113183
func (l *DelegatingLogger) WithValues(tags ...interface{}) logr.Logger {
114-
l.lock.Lock()
115-
defer l.lock.Unlock()
184+
l.lock.RLock()
185+
defer l.lock.RUnlock()
116186

117187
if l.promise == nil {
118-
return l.Logger.WithValues(tags...)
188+
return l.logger.WithValues(tags...)
119189
}
120190

121-
res := &DelegatingLogger{Logger: l.Logger}
191+
res := &DelegatingLogger{logger: l.logger}
122192
promise := l.promise.WithValues(res, tags...)
123193
res.promise = promise
124194

@@ -138,7 +208,7 @@ func (l *DelegatingLogger) Fulfill(actual logr.Logger) {
138208
// the given logger before it's promise is fulfilled.
139209
func NewDelegatingLogger(initial logr.Logger) *DelegatingLogger {
140210
l := &DelegatingLogger{
141-
Logger: initial,
211+
logger: initial,
142212
promise: &loggerPromise{promisesLock: sync.Mutex{}},
143213
}
144214
l.promise.logger = l

pkg/log/log_test.go

+31
Original file line numberDiff line numberDiff line change
@@ -18,12 +18,15 @@ package log
1818

1919
import (
2020
"context"
21+
"errors"
2122

2223
"github.com/go-logr/logr"
2324
. "github.com/onsi/ginkgo"
2425
. "github.com/onsi/gomega"
2526
)
2627

28+
var _ logr.Logger = &DelegatingLogger{}
29+
2730
// logInfo is the information for a particular fakeLogger message
2831
type logInfo struct {
2932
name []string
@@ -169,6 +172,10 @@ var _ = Describe("logging", func() {
169172
withNameDone := make(chan struct{})
170173
withValuesDone := make(chan struct{})
171174
grandChildDone := make(chan struct{})
175+
logEnabledDone := make(chan struct{})
176+
logInfoDone := make(chan struct{})
177+
logErrorDone := make(chan struct{})
178+
logVDone := make(chan struct{})
172179

173180
// Constructing the child in the goroutine does not reliably
174181
// trigger the race detector
@@ -193,11 +200,35 @@ var _ = Describe("logging", func() {
193200
child.WithValues("grandchild")
194201
close(grandChildDone)
195202
}()
203+
go func() {
204+
defer GinkgoRecover()
205+
delegLog.Enabled()
206+
close(logEnabledDone)
207+
}()
208+
go func() {
209+
defer GinkgoRecover()
210+
delegLog.Info("hello world")
211+
close(logInfoDone)
212+
}()
213+
go func() {
214+
defer GinkgoRecover()
215+
delegLog.Error(errors.New("err"), "hello world")
216+
close(logErrorDone)
217+
}()
218+
go func() {
219+
defer GinkgoRecover()
220+
delegLog.V(1)
221+
close(logVDone)
222+
}()
196223

197224
<-fulfillDone
198225
<-withNameDone
199226
<-withValuesDone
200227
<-grandChildDone
228+
<-logEnabledDone
229+
<-logInfoDone
230+
<-logErrorDone
231+
<-logVDone
201232
})
202233

203234
It("should delegate with tags", func() {

0 commit comments

Comments
 (0)