1
2
3
4
5
6
7 package slog
8
9 import (
10 "bytes"
11 "context"
12 "encoding/json"
13 "io"
14 "path/filepath"
15 "strconv"
16 "strings"
17 "testing"
18 "time"
19
20 "golang.org/x/exp/slices"
21 "golang.org/x/exp/slog/internal/buffer"
22 )
23
24 func TestDefaultHandle(t *testing.T) {
25 ctx := context.Background()
26 preAttrs := []Attr{Int("pre", 0)}
27 attrs := []Attr{Int("a", 1), String("b", "two")}
28 for _, test := range []struct {
29 name string
30 with func(Handler) Handler
31 attrs []Attr
32 want string
33 }{
34 {
35 name: "no attrs",
36 want: "INFO message",
37 },
38 {
39 name: "attrs",
40 attrs: attrs,
41 want: "INFO message a=1 b=two",
42 },
43 {
44 name: "preformatted",
45 with: func(h Handler) Handler { return h.WithAttrs(preAttrs) },
46 attrs: attrs,
47 want: "INFO message pre=0 a=1 b=two",
48 },
49 {
50 name: "groups",
51 attrs: []Attr{
52 Int("a", 1),
53 Group("g",
54 Int("b", 2),
55 Group("h", Int("c", 3)),
56 Int("d", 4)),
57 Int("e", 5),
58 },
59 want: "INFO message a=1 g.b=2 g.h.c=3 g.d=4 e=5",
60 },
61 {
62 name: "group",
63 with: func(h Handler) Handler { return h.WithAttrs(preAttrs).WithGroup("s") },
64 attrs: attrs,
65 want: "INFO message pre=0 s.a=1 s.b=two",
66 },
67 {
68 name: "preformatted groups",
69 with: func(h Handler) Handler {
70 return h.WithAttrs([]Attr{Int("p1", 1)}).
71 WithGroup("s1").
72 WithAttrs([]Attr{Int("p2", 2)}).
73 WithGroup("s2")
74 },
75 attrs: attrs,
76 want: "INFO message p1=1 s1.p2=2 s1.s2.a=1 s1.s2.b=two",
77 },
78 {
79 name: "two with-groups",
80 with: func(h Handler) Handler {
81 return h.WithAttrs([]Attr{Int("p1", 1)}).
82 WithGroup("s1").
83 WithGroup("s2")
84 },
85 attrs: attrs,
86 want: "INFO message p1=1 s1.s2.a=1 s1.s2.b=two",
87 },
88 } {
89 t.Run(test.name, func(t *testing.T) {
90 var got string
91 var h Handler = newDefaultHandler(func(_ int, s string) error {
92 got = s
93 return nil
94 })
95 if test.with != nil {
96 h = test.with(h)
97 }
98 r := NewRecord(time.Time{}, LevelInfo, "message", 0)
99 r.AddAttrs(test.attrs...)
100 if err := h.Handle(ctx, r); err != nil {
101 t.Fatal(err)
102 }
103 if got != test.want {
104 t.Errorf("\ngot %s\nwant %s", got, test.want)
105 }
106 })
107 }
108 }
109
110
111 func TestJSONAndTextHandlers(t *testing.T) {
112 ctx := context.Background()
113
114
115 removeAll := func(_ []string, a Attr) Attr { return Attr{} }
116
117 attrs := []Attr{String("a", "one"), Int("b", 2), Any("", nil)}
118 preAttrs := []Attr{Int("pre", 3), String("x", "y")}
119
120 for _, test := range []struct {
121 name string
122 replace func([]string, Attr) Attr
123 addSource bool
124 with func(Handler) Handler
125 preAttrs []Attr
126 attrs []Attr
127 wantText string
128 wantJSON string
129 }{
130 {
131 name: "basic",
132 attrs: attrs,
133 wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2",
134 wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2}`,
135 },
136 {
137 name: "empty key",
138 attrs: append(slices.Clip(attrs), Any("", "v")),
139 wantText: `time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2 ""=v`,
140 wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2,"":"v"}`,
141 },
142 {
143 name: "cap keys",
144 replace: upperCaseKey,
145 attrs: attrs,
146 wantText: "TIME=2000-01-02T03:04:05.000Z LEVEL=INFO MSG=message A=one B=2",
147 wantJSON: `{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"message","A":"one","B":2}`,
148 },
149 {
150 name: "remove all",
151 replace: removeAll,
152 attrs: attrs,
153 wantText: "",
154 wantJSON: `{}`,
155 },
156 {
157 name: "preformatted",
158 with: func(h Handler) Handler { return h.WithAttrs(preAttrs) },
159 preAttrs: preAttrs,
160 attrs: attrs,
161 wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message pre=3 x=y a=one b=2",
162 wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","pre":3,"x":"y","a":"one","b":2}`,
163 },
164 {
165 name: "preformatted cap keys",
166 replace: upperCaseKey,
167 with: func(h Handler) Handler { return h.WithAttrs(preAttrs) },
168 preAttrs: preAttrs,
169 attrs: attrs,
170 wantText: "TIME=2000-01-02T03:04:05.000Z LEVEL=INFO MSG=message PRE=3 X=y A=one B=2",
171 wantJSON: `{"TIME":"2000-01-02T03:04:05Z","LEVEL":"INFO","MSG":"message","PRE":3,"X":"y","A":"one","B":2}`,
172 },
173 {
174 name: "preformatted remove all",
175 replace: removeAll,
176 with: func(h Handler) Handler { return h.WithAttrs(preAttrs) },
177 preAttrs: preAttrs,
178 attrs: attrs,
179 wantText: "",
180 wantJSON: "{}",
181 },
182 {
183 name: "remove built-in",
184 replace: removeKeys(TimeKey, LevelKey, MessageKey),
185 attrs: attrs,
186 wantText: "a=one b=2",
187 wantJSON: `{"a":"one","b":2}`,
188 },
189 {
190 name: "preformatted remove built-in",
191 replace: removeKeys(TimeKey, LevelKey, MessageKey),
192 with: func(h Handler) Handler { return h.WithAttrs(preAttrs) },
193 attrs: attrs,
194 wantText: "pre=3 x=y a=one b=2",
195 wantJSON: `{"pre":3,"x":"y","a":"one","b":2}`,
196 },
197 {
198 name: "groups",
199 replace: removeKeys(TimeKey, LevelKey),
200 attrs: []Attr{
201 Int("a", 1),
202 Group("g",
203 Int("b", 2),
204 Group("h", Int("c", 3)),
205 Int("d", 4)),
206 Int("e", 5),
207 },
208 wantText: "msg=message a=1 g.b=2 g.h.c=3 g.d=4 e=5",
209 wantJSON: `{"msg":"message","a":1,"g":{"b":2,"h":{"c":3},"d":4},"e":5}`,
210 },
211 {
212 name: "empty group",
213 replace: removeKeys(TimeKey, LevelKey),
214 attrs: []Attr{Group("g"), Group("h", Int("a", 1))},
215 wantText: "msg=message h.a=1",
216 wantJSON: `{"msg":"message","h":{"a":1}}`,
217 },
218 {
219 name: "escapes",
220 replace: removeKeys(TimeKey, LevelKey),
221 attrs: []Attr{
222 String("a b", "x\t\n\000y"),
223 Group(" b.c=\"\\x2E\t",
224 String("d=e", "f.g\""),
225 Int("m.d", 1)),
226 },
227 wantText: `msg=message "a b"="x\t\n\x00y" " b.c=\"\\x2E\t.d=e"="f.g\"" " b.c=\"\\x2E\t.m.d"=1`,
228 wantJSON: `{"msg":"message","a b":"x\t\n\u0000y"," b.c=\"\\x2E\t":{"d=e":"f.g\"","m.d":1}}`,
229 },
230 {
231 name: "LogValuer",
232 replace: removeKeys(TimeKey, LevelKey),
233 attrs: []Attr{
234 Int("a", 1),
235 Any("name", logValueName{"Ren", "Hoek"}),
236 Int("b", 2),
237 },
238 wantText: "msg=message a=1 name.first=Ren name.last=Hoek b=2",
239 wantJSON: `{"msg":"message","a":1,"name":{"first":"Ren","last":"Hoek"},"b":2}`,
240 },
241 {
242
243 name: "resolve",
244 attrs: []Attr{
245 Any("", &replace{Value{}}),
246 Any("name", logValueName{"Ren", "Hoek"}),
247 },
248 wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message name.first=Ren name.last=Hoek",
249 wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","name":{"first":"Ren","last":"Hoek"}}`,
250 },
251 {
252 name: "with-group",
253 replace: removeKeys(TimeKey, LevelKey),
254 with: func(h Handler) Handler { return h.WithAttrs(preAttrs).WithGroup("s") },
255 attrs: attrs,
256 wantText: "msg=message pre=3 x=y s.a=one s.b=2",
257 wantJSON: `{"msg":"message","pre":3,"x":"y","s":{"a":"one","b":2}}`,
258 },
259 {
260 name: "preformatted with-groups",
261 replace: removeKeys(TimeKey, LevelKey),
262 with: func(h Handler) Handler {
263 return h.WithAttrs([]Attr{Int("p1", 1)}).
264 WithGroup("s1").
265 WithAttrs([]Attr{Int("p2", 2)}).
266 WithGroup("s2")
267 },
268 attrs: attrs,
269 wantText: "msg=message p1=1 s1.p2=2 s1.s2.a=one s1.s2.b=2",
270 wantJSON: `{"msg":"message","p1":1,"s1":{"p2":2,"s2":{"a":"one","b":2}}}`,
271 },
272 {
273 name: "two with-groups",
274 replace: removeKeys(TimeKey, LevelKey),
275 with: func(h Handler) Handler {
276 return h.WithAttrs([]Attr{Int("p1", 1)}).
277 WithGroup("s1").
278 WithGroup("s2")
279 },
280 attrs: attrs,
281 wantText: "msg=message p1=1 s1.s2.a=one s1.s2.b=2",
282 wantJSON: `{"msg":"message","p1":1,"s1":{"s2":{"a":"one","b":2}}}`,
283 },
284 {
285 name: "GroupValue as Attr value",
286 replace: removeKeys(TimeKey, LevelKey),
287 attrs: []Attr{{"v", AnyValue(IntValue(3))}},
288 wantText: "msg=message v=3",
289 wantJSON: `{"msg":"message","v":3}`,
290 },
291 {
292 name: "byte slice",
293 replace: removeKeys(TimeKey, LevelKey),
294 attrs: []Attr{Any("bs", []byte{1, 2, 3, 4})},
295 wantText: `msg=message bs="\x01\x02\x03\x04"`,
296 wantJSON: `{"msg":"message","bs":"AQIDBA=="}`,
297 },
298 {
299 name: "json.RawMessage",
300 replace: removeKeys(TimeKey, LevelKey),
301 attrs: []Attr{Any("bs", json.RawMessage([]byte("1234")))},
302 wantText: `msg=message bs="1234"`,
303 wantJSON: `{"msg":"message","bs":1234}`,
304 },
305 {
306 name: "inline group",
307 replace: removeKeys(TimeKey, LevelKey),
308 attrs: []Attr{
309 Int("a", 1),
310 Group("", Int("b", 2), Int("c", 3)),
311 Int("d", 4),
312 },
313 wantText: `msg=message a=1 b=2 c=3 d=4`,
314 wantJSON: `{"msg":"message","a":1,"b":2,"c":3,"d":4}`,
315 },
316 {
317 name: "Source",
318 replace: func(gs []string, a Attr) Attr {
319 if a.Key == SourceKey {
320 s := a.Value.Any().(*Source)
321 s.File = filepath.Base(s.File)
322 return Any(a.Key, s)
323 }
324 return removeKeys(TimeKey, LevelKey)(gs, a)
325 },
326 addSource: true,
327 wantText: `source=handler_test.go:$LINE msg=message`,
328 wantJSON: `{"source":{"function":"golang.org/x/exp/slog.TestJSONAndTextHandlers","file":"handler_test.go","line":$LINE},"msg":"message"}`,
329 },
330 } {
331 r := NewRecord(testTime, LevelInfo, "message", callerPC(2))
332 line := strconv.Itoa(r.source().Line)
333 r.AddAttrs(test.attrs...)
334 var buf bytes.Buffer
335 opts := HandlerOptions{ReplaceAttr: test.replace, AddSource: test.addSource}
336 t.Run(test.name, func(t *testing.T) {
337 for _, handler := range []struct {
338 name string
339 h Handler
340 want string
341 }{
342 {"text", NewTextHandler(&buf, &opts), test.wantText},
343 {"json", NewJSONHandler(&buf, &opts), test.wantJSON},
344 } {
345 t.Run(handler.name, func(t *testing.T) {
346 h := handler.h
347 if test.with != nil {
348 h = test.with(h)
349 }
350 buf.Reset()
351 if err := h.Handle(ctx, r); err != nil {
352 t.Fatal(err)
353 }
354 want := strings.ReplaceAll(handler.want, "$LINE", line)
355 got := strings.TrimSuffix(buf.String(), "\n")
356 if got != want {
357 t.Errorf("\ngot %s\nwant %s\n", got, want)
358 }
359 })
360 }
361 })
362 }
363 }
364
365
366
367 func removeKeys(keys ...string) func([]string, Attr) Attr {
368 return func(_ []string, a Attr) Attr {
369 for _, k := range keys {
370 if a.Key == k {
371 return Attr{}
372 }
373 }
374 return a
375 }
376 }
377
378 func upperCaseKey(_ []string, a Attr) Attr {
379 a.Key = strings.ToUpper(a.Key)
380 return a
381 }
382
383 type logValueName struct {
384 first, last string
385 }
386
387 func (n logValueName) LogValue() Value {
388 return GroupValue(
389 String("first", n.first),
390 String("last", n.last))
391 }
392
393 func TestHandlerEnabled(t *testing.T) {
394 levelVar := func(l Level) *LevelVar {
395 var al LevelVar
396 al.Set(l)
397 return &al
398 }
399
400 for _, test := range []struct {
401 leveler Leveler
402 want bool
403 }{
404 {nil, true},
405 {LevelWarn, false},
406 {&LevelVar{}, true},
407 {levelVar(LevelWarn), false},
408 {LevelDebug, true},
409 {levelVar(LevelDebug), true},
410 } {
411 h := &commonHandler{opts: HandlerOptions{Level: test.leveler}}
412 got := h.enabled(LevelInfo)
413 if got != test.want {
414 t.Errorf("%v: got %t, want %t", test.leveler, got, test.want)
415 }
416 }
417 }
418
419 func TestSecondWith(t *testing.T) {
420
421
422 var buf bytes.Buffer
423 h := NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeKeys(TimeKey)})
424 logger := New(h).With(
425 String("app", "playground"),
426 String("role", "tester"),
427 Int("data_version", 2),
428 )
429 appLogger := logger.With("type", "log")
430 _ = logger.With("type", "metric")
431 appLogger.Info("foo")
432 got := strings.TrimSpace(buf.String())
433 want := `level=INFO msg=foo app=playground role=tester data_version=2 type=log`
434 if got != want {
435 t.Errorf("\ngot %s\nwant %s", got, want)
436 }
437 }
438
439 func TestReplaceAttrGroups(t *testing.T) {
440
441 type ga struct {
442 groups string
443 key string
444 val string
445 }
446
447 var got []ga
448
449 h := NewTextHandler(io.Discard, &HandlerOptions{ReplaceAttr: func(gs []string, a Attr) Attr {
450 v := a.Value.String()
451 if a.Key == TimeKey {
452 v = "<now>"
453 }
454 got = append(got, ga{strings.Join(gs, ","), a.Key, v})
455 return a
456 }})
457 New(h).
458 With(Int("a", 1)).
459 WithGroup("g1").
460 With(Int("b", 2)).
461 WithGroup("g2").
462 With(
463 Int("c", 3),
464 Group("g3", Int("d", 4)),
465 Int("e", 5)).
466 Info("m",
467 Int("f", 6),
468 Group("g4", Int("h", 7)),
469 Int("i", 8))
470
471 want := []ga{
472 {"", "a", "1"},
473 {"g1", "b", "2"},
474 {"g1,g2", "c", "3"},
475 {"g1,g2,g3", "d", "4"},
476 {"g1,g2", "e", "5"},
477 {"", "time", "<now>"},
478 {"", "level", "INFO"},
479 {"", "msg", "m"},
480 {"g1,g2", "f", "6"},
481 {"g1,g2,g4", "h", "7"},
482 {"g1,g2", "i", "8"},
483 }
484 if !slices.Equal(got, want) {
485 t.Errorf("\ngot %v\nwant %v", got, want)
486 }
487 }
488
489 const rfc3339Millis = "2006-01-02T15:04:05.000Z07:00"
490
491 func TestWriteTimeRFC3339(t *testing.T) {
492 for _, tm := range []time.Time{
493 time.Date(2000, 1, 2, 3, 4, 5, 0, time.UTC),
494 time.Date(2000, 1, 2, 3, 4, 5, 400, time.Local),
495 time.Date(2000, 11, 12, 3, 4, 500, 5e7, time.UTC),
496 } {
497 want := tm.Format(rfc3339Millis)
498 buf := buffer.New()
499 defer buf.Free()
500 writeTimeRFC3339Millis(buf, tm)
501 got := buf.String()
502 if got != want {
503 t.Errorf("got %s, want %s", got, want)
504 }
505 }
506 }
507
508 func BenchmarkWriteTime(b *testing.B) {
509 buf := buffer.New()
510 defer buf.Free()
511 tm := time.Date(2022, 3, 4, 5, 6, 7, 823456789, time.Local)
512 b.ResetTimer()
513 for i := 0; i < b.N; i++ {
514 writeTimeRFC3339Millis(buf, tm)
515 buf.Reset()
516 }
517 }
518
View as plain text