1
16
17 package log
18
19 import (
20 "context"
21 "errors"
22
23 "github.com/go-logr/logr"
24 . "github.com/onsi/ginkgo/v2"
25 . "github.com/onsi/gomega"
26 )
27
28 var _ logr.LogSink = &delegatingLogSink{}
29
30
31 type logInfo struct {
32 name []string
33 tags []interface{}
34 msg string
35 }
36
37
38 type fakeLoggerRoot struct {
39 messages []logInfo
40 }
41
42
43
44
45 type fakeLogger struct {
46 name []string
47 tags []interface{}
48
49 root *fakeLoggerRoot
50 }
51
52 func (f *fakeLogger) Init(info logr.RuntimeInfo) {
53 }
54
55 func (f *fakeLogger) WithName(name string) logr.LogSink {
56 names := append([]string(nil), f.name...)
57 names = append(names, name)
58 return &fakeLogger{
59 name: names,
60 tags: f.tags,
61 root: f.root,
62 }
63 }
64
65 func (f *fakeLogger) WithValues(vals ...interface{}) logr.LogSink {
66 tags := append([]interface{}(nil), f.tags...)
67 tags = append(tags, vals...)
68 return &fakeLogger{
69 name: f.name,
70 tags: tags,
71 root: f.root,
72 }
73 }
74
75 func (f *fakeLogger) Error(err error, msg string, vals ...interface{}) {
76 tags := append([]interface{}(nil), f.tags...)
77 tags = append(tags, "error", err)
78 tags = append(tags, vals...)
79 f.root.messages = append(f.root.messages, logInfo{
80 name: append([]string(nil), f.name...),
81 tags: tags,
82 msg: msg,
83 })
84 }
85
86 func (f *fakeLogger) Info(level int, msg string, vals ...interface{}) {
87 tags := append([]interface{}(nil), f.tags...)
88 tags = append(tags, vals...)
89 f.root.messages = append(f.root.messages, logInfo{
90 name: append([]string(nil), f.name...),
91 tags: tags,
92 msg: msg,
93 })
94 }
95
96 func (f *fakeLogger) Enabled(level int) bool { return true }
97
98 var _ = Describe("logging", func() {
99
100 Describe("top-level logger", func() {
101 It("hold newly created loggers until a logger is set", func() {
102 By("grabbing a new sub-logger and logging to it")
103 l1 := Log.WithName("runtimeLog").WithValues("newtag", "newvalue1")
104 l1.Info("before msg")
105
106 By("actually setting the logger")
107 logger := &fakeLogger{root: &fakeLoggerRoot{}}
108 SetLogger(logr.New(logger))
109
110 By("grabbing another sub-logger and logging to both loggers")
111 l2 := Log.WithName("runtimeLog").WithValues("newtag", "newvalue2")
112 l1.Info("after msg 1")
113 l2.Info("after msg 2")
114
115 By("ensuring that messages after the logger was set were logged")
116 Expect(logger.root.messages).To(ConsistOf(
117 logInfo{name: []string{"runtimeLog"}, tags: []interface{}{"newtag", "newvalue1"}, msg: "after msg 1"},
118 logInfo{name: []string{"runtimeLog"}, tags: []interface{}{"newtag", "newvalue2"}, msg: "after msg 2"},
119 ))
120 })
121 })
122
123 Describe("lazy logger initialization", func() {
124 var (
125 root *fakeLoggerRoot
126 baseLog logr.LogSink
127 delegLog *delegatingLogSink
128 )
129
130 BeforeEach(func() {
131 root = &fakeLoggerRoot{}
132 baseLog = &fakeLogger{root: root}
133 delegLog = newDelegatingLogSink(NullLogSink{})
134 })
135
136 It("should delegate with name", func() {
137 By("asking for a logger with a name before fulfill, and logging")
138 befFulfill1 := logr.New(delegLog).WithName("before-fulfill")
139 befFulfill2 := befFulfill1.WithName("two")
140 befFulfill1.Info("before fulfill")
141
142 By("logging on the base logger before fulfill")
143 logr.New(delegLog).Info("before fulfill base")
144
145 By("ensuring that no messages were actually recorded")
146 Expect(root.messages).To(BeEmpty())
147
148 By("fulfilling the promise")
149 delegLog.Fulfill(baseLog)
150
151 By("logging with the existing loggers after fulfilling")
152 befFulfill1.Info("after 1")
153 befFulfill2.Info("after 2")
154
155 By("grabbing a new sub-logger of a previously constructed logger and logging to it")
156 befFulfill1.WithName("after-from-before").Info("after 3")
157
158 By("logging with new loggers")
159 logr.New(delegLog).WithName("after-fulfill").Info("after 4")
160
161 By("ensuring that the messages are appropriately named")
162 Expect(root.messages).To(ConsistOf(
163 logInfo{name: []string{"before-fulfill"}, msg: "after 1"},
164 logInfo{name: []string{"before-fulfill", "two"}, msg: "after 2"},
165 logInfo{name: []string{"before-fulfill", "after-from-before"}, msg: "after 3"},
166 logInfo{name: []string{"after-fulfill"}, msg: "after 4"},
167 ))
168 })
169
170
171
172 It("should be threadsafe", func() {
173 fulfillDone := make(chan struct{})
174 withNameDone := make(chan struct{})
175 withValuesDone := make(chan struct{})
176 grandChildDone := make(chan struct{})
177 logEnabledDone := make(chan struct{})
178 logInfoDone := make(chan struct{})
179 logErrorDone := make(chan struct{})
180 logVDone := make(chan struct{})
181
182
183
184 child := logr.New(delegLog).WithName("child")
185 go func() {
186 defer GinkgoRecover()
187 delegLog.Fulfill(NullLogSink{})
188 close(fulfillDone)
189 }()
190 go func() {
191 defer GinkgoRecover()
192 delegLog.WithName("with-name")
193 close(withNameDone)
194 }()
195 go func() {
196 defer GinkgoRecover()
197 delegLog.WithValues("with-value")
198 close(withValuesDone)
199 }()
200 go func() {
201 defer GinkgoRecover()
202 child.WithValues("grandchild")
203 close(grandChildDone)
204 }()
205 go func() {
206 defer GinkgoRecover()
207 logr.New(delegLog).Enabled()
208 close(logEnabledDone)
209 }()
210 go func() {
211 defer GinkgoRecover()
212 logr.New(delegLog).Info("hello world")
213 close(logInfoDone)
214 }()
215 go func() {
216 defer GinkgoRecover()
217 delegLog.Error(errors.New("err"), "hello world")
218 close(logErrorDone)
219 }()
220 go func() {
221 defer GinkgoRecover()
222 logr.New(delegLog).V(1)
223 close(logVDone)
224 }()
225
226 <-fulfillDone
227 <-withNameDone
228 <-withValuesDone
229 <-grandChildDone
230 <-logEnabledDone
231 <-logInfoDone
232 <-logErrorDone
233 <-logVDone
234 })
235
236 It("should delegate with tags", func() {
237 By("asking for a logger with a name before fulfill, and logging")
238 befFulfill1 := logr.New(delegLog).WithValues("tag1", "val1")
239 befFulfill2 := befFulfill1.WithValues("tag2", "val2")
240 befFulfill1.Info("before fulfill")
241
242 By("logging on the base logger before fulfill")
243 logr.New(delegLog).Info("before fulfill base")
244
245 By("ensuring that no messages were actually recorded")
246 Expect(root.messages).To(BeEmpty())
247
248 By("fulfilling the promise")
249 delegLog.Fulfill(baseLog)
250
251 By("logging with the existing loggers after fulfilling")
252 befFulfill1.Info("after 1")
253 befFulfill2.Info("after 2")
254
255 By("grabbing a new sub-logger of a previously constructed logger and logging to it")
256 befFulfill1.WithValues("tag3", "val3").Info("after 3")
257
258 By("logging with new loggers")
259 logr.New(delegLog).WithValues("tag3", "val3").Info("after 4")
260
261 By("ensuring that the messages are appropriately named")
262 Expect(root.messages).To(ConsistOf(
263 logInfo{tags: []interface{}{"tag1", "val1"}, msg: "after 1"},
264 logInfo{tags: []interface{}{"tag1", "val1", "tag2", "val2"}, msg: "after 2"},
265 logInfo{tags: []interface{}{"tag1", "val1", "tag3", "val3"}, msg: "after 3"},
266 logInfo{tags: []interface{}{"tag3", "val3"}, msg: "after 4"},
267 ))
268 })
269
270 It("shouldn't fulfill twice", func() {
271 By("fulfilling once")
272 delegLog.Fulfill(baseLog)
273
274 By("logging a bit")
275 logr.New(delegLog).Info("msg 1")
276
277 By("fulfilling with a new logger")
278 delegLog.Fulfill(&fakeLogger{})
279
280 By("logging some more")
281 logr.New(delegLog).Info("msg 2")
282
283 By("checking that all log messages are present")
284 Expect(root.messages).To(ConsistOf(
285 logInfo{msg: "msg 1"},
286 logInfo{msg: "msg 2"},
287 ))
288 })
289
290 It("should handle nil sinks", func() {
291 By("fulfilling once")
292 delegLog.Fulfill(logr.Discard().GetSink())
293 By("grabbing a sub-logger and logging")
294 l1 := logr.New(delegLog).WithName("nilsink").WithValues("newtag", "newvalue2")
295 l1.Info("test")
296 })
297 })
298
299 Describe("logger from context", func() {
300 It("should return default logger when context is empty", func() {
301 gotLog := FromContext(context.Background())
302 Expect(gotLog).To(Not(BeNil()))
303 })
304
305 It("should return existing logger", func() {
306 root := &fakeLoggerRoot{}
307 baseLog := &fakeLogger{root: root}
308
309 wantLog := logr.New(baseLog).WithName("my-logger")
310 ctx := IntoContext(context.Background(), wantLog)
311
312 gotLog := FromContext(ctx)
313 Expect(gotLog).To(Not(BeNil()))
314
315 gotLog.Info("test message")
316 Expect(root.messages).To(ConsistOf(
317 logInfo{name: []string{"my-logger"}, msg: "test message"},
318 ))
319 })
320
321 It("should have added key-values", func() {
322 root := &fakeLoggerRoot{}
323 baseLog := &fakeLogger{root: root}
324
325 wantLog := logr.New(baseLog).WithName("my-logger")
326 ctx := IntoContext(context.Background(), wantLog)
327
328 gotLog := FromContext(ctx, "tag1", "value1")
329 Expect(gotLog).To(Not(BeNil()))
330
331 gotLog.Info("test message")
332 Expect(root.messages).To(ConsistOf(
333 logInfo{name: []string{"my-logger"}, tags: []interface{}{"tag1", "value1"}, msg: "test message"},
334 ))
335 })
336 })
337
338 })
339
View as plain text