Skip to content

Commit 34518d5

Browse files
DirectXMan12DirectXMan12
committed
Fix delegating logger tag handling and test
This fixes the tag handling of the delegating logger, which was missing a splat operator, and thus causing the tags to be misinterpretted. This also adds proper testing of the delegating functionality, so that this doesn't happen again.
1 parent 19b9f17 commit 34518d5

File tree

3 files changed

+242
-43
lines changed

3 files changed

+242
-43
lines changed

‎pkg/runtime/log/deleg.go

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -79,12 +79,32 @@ func (l *DelegatingLogger) WithName(name string) logr.Logger {
7979
// WithValues provides a new Logger with the tags appended
8080
func (l *DelegatingLogger) WithValues(tags ...interface{}) logr.Logger {
8181
if l.promise == nil {
82-
return l.Logger.WithValues(tags)
82+
return l.Logger.WithValues(tags...)
8383
}
8484

8585
res := &DelegatingLogger{Logger: l.Logger}
86-
promise := l.promise.WithValues(res, tags)
86+
promise := l.promise.WithValues(res, tags...)
8787
res.promise = promise
8888

8989
return res
9090
}
91+
92+
// Fulfill switches the logger over to use the actual logger
93+
// provided, instead of the temporary initial one, if this method
94+
// has not been previously called.
95+
func (l *DelegatingLogger) Fulfill(actual logr.Logger) {
96+
if l.promise != nil {
97+
l.promise.Fulfill(actual)
98+
}
99+
}
100+
101+
// NewDelegatingLogger constructs a new DelegatingLogger which uses
102+
// the given logger before it's promise is fulfilled.
103+
func NewDelegatingLogger(initial logr.Logger) *DelegatingLogger {
104+
l := &DelegatingLogger{
105+
Logger: initial,
106+
promise: &loggerPromise{},
107+
}
108+
l.promise.logger = l
109+
return l
110+
}

‎pkg/runtime/log/log.go

Lines changed: 4 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -37,12 +37,8 @@ func ZapLogger(development bool) logr.Logger {
3737
// ZapLogger.
3838
func ZapLoggerTo(destWriter io.Writer, development bool) logr.Logger {
3939
// this basically mimics New<type>Config, but with a custom sink
40-
var sink zapcore.WriteSyncer
41-
if asSyncer, isSyncer := destWriter.(zapcore.WriteSyncer); isSyncer {
42-
sink = asSyncer
43-
} else {
44-
sink = zapcore.AddSync(destWriter)
45-
}
40+
sink := zapcore.AddSync(destWriter)
41+
4642
var enc zapcore.Encoder
4743
var lvl zap.AtomicLevel
4844
var opts []zap.Option
@@ -74,23 +70,17 @@ func fatalIfErr(err error, f func(format string, v ...interface{})) {
7470

7571
// SetLogger sets a concrete logging implementation for all deferred Loggers.
7672
func SetLogger(l logr.Logger) {
77-
if Log.promise != nil {
78-
Log.promise.Fulfill(l)
79-
}
73+
Log.Fulfill(l)
8074
}
8175

8276
// Log is the base logger used by kubebuilder. It delegates
8377
// to another logr.Logger. You *must* call SetLogger to
8478
// get any actual logging.
85-
var Log = &DelegatingLogger{
86-
Logger: NullLogger{},
87-
promise: &loggerPromise{},
88-
}
79+
var Log = NewDelegatingLogger(NullLogger{})
8980

9081
// KBLog is a base parent logger.
9182
var KBLog logr.Logger
9283

9384
func init() {
94-
Log.promise.logger = Log
9585
KBLog = Log.WithName("kubebuilder")
9686
}

‎pkg/runtime/log/log_test.go

Lines changed: 216 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -18,47 +18,236 @@ package log
1818

1919
import (
2020
"fmt"
21+
"io/ioutil"
2122

22-
tlogr "github.com/go-logr/logr/testing"
23+
"github.com/go-logr/logr"
2324
. "github.com/onsi/ginkgo"
2425
. "github.com/onsi/gomega"
2526
)
2627

28+
// fakeSyncWriter is a fake zap.SyncerWriter that lets us test if sync was called
29+
type fakeSyncWriter bool
30+
31+
func (w *fakeSyncWriter) Write(p []byte) (int, error) {
32+
return len(p), nil
33+
}
34+
func (w *fakeSyncWriter) Sync() error {
35+
*w = true
36+
return nil
37+
}
38+
39+
// logInfo is the information for a particular fakeLogger message
40+
type logInfo struct {
41+
name []string
42+
tags []interface{}
43+
msg string
44+
}
45+
46+
// fakeLoggerRoot is the root object to which all fakeLoggers record their messages.
47+
type fakeLoggerRoot struct {
48+
messages []logInfo
49+
}
50+
51+
// fakeLogger is a fake implementation of logr.Logger that records
52+
// messages, tags, and names,
53+
// just records the name.
54+
type fakeLogger struct {
55+
name []string
56+
tags []interface{}
57+
58+
root *fakeLoggerRoot
59+
}
60+
61+
func (f *fakeLogger) WithName(name string) logr.Logger {
62+
names := append([]string(nil), f.name...)
63+
names = append(names, name)
64+
return &fakeLogger{
65+
name: names,
66+
tags: f.tags,
67+
root: f.root,
68+
}
69+
}
70+
71+
func (f *fakeLogger) WithValues(vals ...interface{}) logr.Logger {
72+
tags := append([]interface{}(nil), f.tags...)
73+
tags = append(tags, vals...)
74+
return &fakeLogger{
75+
name: f.name,
76+
tags: tags,
77+
root: f.root,
78+
}
79+
}
80+
81+
func (f *fakeLogger) Error(err error, msg string, vals ...interface{}) {
82+
tags := append([]interface{}(nil), f.tags...)
83+
tags = append(tags, "error", err)
84+
tags = append(tags, vals...)
85+
f.root.messages = append(f.root.messages, logInfo{
86+
name: append([]string(nil), f.name...),
87+
tags: tags,
88+
msg: msg,
89+
})
90+
}
91+
92+
func (f *fakeLogger) Info(msg string, vals ...interface{}) {
93+
tags := append([]interface{}(nil), f.tags...)
94+
tags = append(tags, vals...)
95+
f.root.messages = append(f.root.messages, logInfo{
96+
name: append([]string(nil), f.name...),
97+
tags: tags,
98+
msg: msg,
99+
})
100+
}
101+
102+
func (f *fakeLogger) Enabled() bool { return true }
103+
func (f *fakeLogger) V(lvl int) logr.InfoLogger { return f }
104+
27105
var _ = Describe("runtime log", func() {
28106

29-
Context("Test Logger", func() {
30-
It("shoud set and fulfill with logger", func() {
31-
logger := ZapLogger(false)
32-
Expect(logger).NotTo(BeNil())
33-
Log.WithName("runtimeLog").WithValues("newtag", "newvalue")
107+
Describe("top-level logger", func() {
108+
It("hold newly created loggers until a logger is set", func() {
109+
By("grabbing a new sub-logger and logging to it")
110+
l1 := Log.WithName("runtimeLog").WithValues("newtag", "newvalue1")
111+
l1.Info("before msg")
112+
113+
By("actually setting the logger")
114+
logger := &fakeLogger{root: &fakeLoggerRoot{}}
34115
SetLogger(logger)
35-
logger.WithName("runtimeLog").WithValues("newtag", "newvalue")
36-
Expect(Log.promise).To(BeNil())
37-
Expect(Log.Logger).To(Equal(logger))
38-
devLogger := ZapLogger(true)
39-
Expect(devLogger).NotTo(BeNil())
116+
117+
By("grabbing another sub-logger and logging to both loggers")
118+
l2 := Log.WithName("runtimeLog").WithValues("newtag", "newvalue2")
119+
l1.Info("after msg 1")
120+
l2.Info("after msg 2")
121+
122+
By("ensuring that messages after the logger was set were logged")
123+
Expect(logger.root.messages).To(ConsistOf(
124+
logInfo{name: []string{"runtimeLog"}, tags: []interface{}{"newtag", "newvalue1"}, msg: "after msg 1"},
125+
logInfo{name: []string{"runtimeLog"}, tags: []interface{}{"newtag", "newvalue2"}, msg: "after msg 2"},
126+
))
127+
})
128+
})
129+
130+
Describe("lazy logger initialization", func() {
131+
var (
132+
root *fakeLoggerRoot
133+
baseLog logr.Logger
134+
delegLog *DelegatingLogger
135+
)
136+
137+
BeforeEach(func() {
138+
root = &fakeLoggerRoot{}
139+
baseLog = &fakeLogger{root: root}
140+
delegLog = NewDelegatingLogger(NullLogger{})
40141
})
41142

42143
It("should delegate with name", func() {
43-
var name = "NoPromise"
44-
test := tlogr.NullLogger{}
45-
test.WithName(name)
46-
Log = &DelegatingLogger{
47-
Logger: tlogr.NullLogger{},
48-
}
49-
Log.WithName(name)
50-
Expect(Log.Logger).To(Equal(test))
144+
By("asking for a logger with a name before fulfill, and logging")
145+
befFulfill1 := delegLog.WithName("before-fulfill")
146+
befFulfill2 := befFulfill1.WithName("two")
147+
befFulfill1.Info("before fulfill")
148+
149+
By("logging on the base logger before fulfill")
150+
delegLog.Info("before fulfill base")
151+
152+
By("ensuring that no messages were actually recorded")
153+
Expect(root.messages).To(BeEmpty())
154+
155+
By("fulfilling the promise")
156+
delegLog.Fulfill(baseLog)
157+
158+
By("logging with the existing loggers after fulfilling")
159+
befFulfill1.Info("after 1")
160+
befFulfill2.Info("after 2")
161+
162+
By("grabbing a new sub-logger of a previously constructed logger and logging to it")
163+
befFulfill1.WithName("after-from-before").Info("after 3")
164+
165+
By("logging with new loggers")
166+
delegLog.WithName("after-fulfill").Info("after 4")
167+
168+
By("ensuring that the messages are appropriately named")
169+
Expect(root.messages).To(ConsistOf(
170+
logInfo{name: []string{"before-fulfill"}, msg: "after 1"},
171+
logInfo{name: []string{"before-fulfill", "two"}, msg: "after 2"},
172+
logInfo{name: []string{"before-fulfill", "after-from-before"}, msg: "after 3"},
173+
logInfo{name: []string{"after-fulfill"}, msg: "after 4"},
174+
))
51175
})
52176

53177
It("should delegate with tags", func() {
54-
tags := []interface{}{"new", "tags"}
55-
test := tlogr.NullLogger{}
56-
test.WithValues(tags)
57-
Log = &DelegatingLogger{
58-
Logger: tlogr.NullLogger{},
59-
}
60-
Log.WithValues(tags)
61-
Expect(Log.Logger).To(Equal(test))
178+
By("asking for a logger with a name before fulfill, and logging")
179+
befFulfill1 := delegLog.WithValues("tag1", "val1")
180+
befFulfill2 := befFulfill1.WithValues("tag2", "val2")
181+
befFulfill1.Info("before fulfill")
182+
183+
By("logging on the base logger before fulfill")
184+
delegLog.Info("before fulfill base")
185+
186+
By("ensuring that no messages were actually recorded")
187+
Expect(root.messages).To(BeEmpty())
188+
189+
By("fulfilling the promise")
190+
delegLog.Fulfill(baseLog)
191+
192+
By("logging with the existing loggers after fulfilling")
193+
befFulfill1.Info("after 1")
194+
befFulfill2.Info("after 2")
195+
196+
By("grabbing a new sub-logger of a previously constructed logger and logging to it")
197+
befFulfill1.WithValues("tag3", "val3").Info("after 3")
198+
199+
By("logging with new loggers")
200+
delegLog.WithValues("tag3", "val3").Info("after 4")
201+
202+
By("ensuring that the messages are appropriately named")
203+
Expect(root.messages).To(ConsistOf(
204+
logInfo{tags: []interface{}{"tag1", "val1"}, msg: "after 1"},
205+
logInfo{tags: []interface{}{"tag1", "val1", "tag2", "val2"}, msg: "after 2"},
206+
logInfo{tags: []interface{}{"tag1", "val1", "tag3", "val3"}, msg: "after 3"},
207+
logInfo{tags: []interface{}{"tag3", "val3"}, msg: "after 4"},
208+
))
209+
})
210+
211+
It("shouldn't fulfill twice", func() {
212+
By("fulfilling once")
213+
delegLog.Fulfill(baseLog)
214+
215+
By("logging a bit")
216+
delegLog.Info("msg 1")
217+
218+
By("fulfilling with a new logger")
219+
delegLog.Fulfill(&fakeLogger{})
220+
221+
By("logging some more")
222+
delegLog.Info("msg 2")
223+
224+
By("checking that all log messages are present")
225+
Expect(root.messages).To(ConsistOf(
226+
logInfo{msg: "msg 1"},
227+
logInfo{msg: "msg 2"},
228+
))
229+
})
230+
})
231+
232+
Describe("Zap logger setup", func() {
233+
Context("with the default output", func() {
234+
It("shouldn't fail when setting up production", func() {
235+
Expect(ZapLogger(false)).NotTo(BeNil())
236+
})
237+
238+
It("shouldn't fail when setting up development", func() {
239+
Expect(ZapLogger(true)).NotTo(BeNil())
240+
})
241+
})
242+
243+
Context("with custom non-sync output", func() {
244+
It("shouldn't fail when setting up production", func() {
245+
Expect(ZapLoggerTo(ioutil.Discard, false)).NotTo(BeNil())
246+
})
247+
248+
It("shouldn't fail when setting up development", func() {
249+
Expect(ZapLoggerTo(ioutil.Discard, true)).NotTo(BeNil())
250+
})
62251
})
63252
})
64253

0 commit comments

Comments
 (0)