1 // Copyright 2022 The Go Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style
3 // license that can be found in the LICENSE file.
14 loginternal "log/internal"
25 // textTimeRE is a regexp to match log timestamps for Text handler.
26 // This is RFC3339Nano with the fixed 3 digit sub-second precision.
27 const textTimeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})`
29 // jsonTimeRE is a regexp to match log timestamps for Text handler.
30 // This is RFC3339Nano with an arbitrary sub-second precision.
31 const jsonTimeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d+)?(Z|[+-]\d{2}:\d{2})`
33 func TestLogTextHandler(t *testing.T) {
34 ctx := context.Background()
37 l := New(NewTextHandler(&buf, nil))
39 check := func(want string) {
42 want = "time=" + textTimeRE + " " + want
44 checkLogOutput(t, buf.String(), want)
48 l.Info("msg", "a", 1, "b", 2)
49 check(`level=INFO msg=msg a=1 b=2`)
51 // By default, debug messages are not printed.
52 l.Debug("bg", Int("a", 1), "b", 2)
55 l.Warn("w", Duration("dur", 3*time.Second))
56 check(`level=WARN msg=w dur=3s`)
58 l.Error("bad", "a", 1)
59 check(`level=ERROR msg=bad a=1`)
61 l.Log(ctx, LevelWarn+1, "w", Int("a", 1), String("b", "two"))
62 check(`level=WARN\+1 msg=w a=1 b=two`)
64 l.LogAttrs(ctx, LevelInfo+1, "a b c", Int("a", 1), String("b", "two"))
65 check(`level=INFO\+1 msg="a b c" a=1 b=two`)
67 l.Info("info", "a", []Attr{Int("i", 1)})
68 check(`level=INFO msg=info a.i=1`)
70 l.Info("info", "a", GroupValue(Int("i", 1)))
71 check(`level=INFO msg=info a.i=1`)
74 func TestConnections(t *testing.T) {
75 var logbuf, slogbuf bytes.Buffer
77 // Revert any changes to the default logger. This is important because other
78 // tests might change the default logger using SetDefault. Also ensure we
79 // restore the default logger at the end of the test.
80 currentLogger := Default()
81 currentLogWriter := log.Writer()
82 currentLogFlags := log.Flags()
83 SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
85 SetDefault(currentLogger)
86 log.SetOutput(currentLogWriter)
87 log.SetFlags(currentLogFlags)
90 // The default slog.Logger's handler uses the log package's default output.
91 log.SetOutput(&logbuf)
92 log.SetFlags(log.Lshortfile &^ log.LstdFlags)
94 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg a=1`)
97 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg p=<nil>`)
101 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg r=<nil>`)
104 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: WARN msg b=2`)
106 Error("msg", "err", io.EOF, "c", 3)
107 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: ERROR msg err=EOF c=3`)
109 // Levels below Info are not printed.
112 checkLogOutput(t, logbuf.String(), "")
114 t.Run("wrap default handler", func(t *testing.T) {
115 // It should be possible to wrap the default handler and get the right output.
116 // This works because the default handler uses the pc in the Record
117 // to get the source line, rather than a call depth.
118 logger := New(wrappingHandler{Default().Handler()})
119 logger.Info("msg", "d", 4)
120 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg d=4`)
123 // Once slog.SetDefault is called, the direction is reversed: the default
124 // log.Logger's output goes through the handler.
125 SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{AddSource: true})))
127 checkLogOutput(t, slogbuf.String(), "time="+textTimeRE+` level=INFO source=.*logger_test.go:\d{3}"? msg=msg2`)
129 // The default log.Logger always outputs at Info level.
131 SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{Level: LevelWarn})))
132 log.Print("should not appear")
133 if got := slogbuf.String(); got != "" {
134 t.Errorf("got %q, want empty", got)
137 // Setting log's output again breaks the connection.
140 log.SetOutput(&logbuf)
141 log.SetFlags(log.Lshortfile &^ log.LstdFlags)
143 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: msg3`)
144 if got := slogbuf.String(); got != "" {
145 t.Errorf("got %q, want empty", got)
149 type wrappingHandler struct {
153 func (h wrappingHandler) Enabled(ctx context.Context, level Level) bool {
154 return h.h.Enabled(ctx, level)
156 func (h wrappingHandler) WithGroup(name string) Handler { return h.h.WithGroup(name) }
157 func (h wrappingHandler) WithAttrs(as []Attr) Handler { return h.h.WithAttrs(as) }
158 func (h wrappingHandler) Handle(ctx context.Context, r Record) error { return h.h.Handle(ctx, r) }
160 func TestAttrs(t *testing.T) {
161 check := func(got []Attr, want ...Attr) {
163 if !attrsEqual(got, want) {
164 t.Errorf("got %v, want %v", got, want)
168 l1 := New(&captureHandler{}).With("a", 1)
169 l2 := New(l1.Handler()).With("b", 2)
171 h := l2.Handler().(*captureHandler)
172 check(h.attrs, Int("a", 1), Int("b", 2))
173 check(attrsSlice(h.r), Int("c", 3))
176 func TestCallDepth(t *testing.T) {
177 ctx := context.Background()
178 h := &captureHandler{}
181 check := func(count int) {
183 const wantFunc = "log/slog.TestCallDepth"
184 const wantFile = "logger_test.go"
185 wantLine := startLine + count*2
187 gotFile := filepath.Base(got.File)
188 if got.Function != wantFunc || gotFile != wantFile || got.Line != wantLine {
189 t.Errorf("got (%s, %s, %d), want (%s, %s, %d)",
190 got.Function, gotFile, got.Line, wantFunc, wantFile, wantLine)
194 defer SetDefault(Default()) // restore
198 // Calls to check must be one line apart.
199 // Determine line where calls start.
200 f, _ := runtime.CallersFrames([]uintptr{callerPC(2)}).Next()
201 startLine = f.Line + 4
202 // Do not change the number of lines between here and the call to check(0).
204 logger.Log(ctx, LevelInfo, "")
206 logger.LogAttrs(ctx, LevelInfo, "")
224 Log(ctx, LevelInfo, "")
226 LogAttrs(ctx, LevelInfo, "")
230 func TestAlloc(t *testing.T) {
231 ctx := context.Background()
232 dl := New(discardHandler{})
233 defer SetDefault(Default()) // restore
236 t.Run("Info", func(t *testing.T) {
237 wantAllocs(t, 0, func() { Info("hello") })
239 t.Run("Error", func(t *testing.T) {
240 wantAllocs(t, 0, func() { Error("hello") })
242 t.Run("logger.Info", func(t *testing.T) {
243 wantAllocs(t, 0, func() { dl.Info("hello") })
245 t.Run("logger.Log", func(t *testing.T) {
246 wantAllocs(t, 0, func() { dl.Log(ctx, LevelDebug, "hello") })
248 t.Run("2 pairs", func(t *testing.T) {
251 wantAllocs(t, 2, func() {
258 t.Run("2 pairs disabled inline", func(t *testing.T) {
259 l := New(discardHandler{disabled: true})
262 wantAllocs(t, 2, func() {
263 l.Log(ctx, LevelInfo, "hello",
269 t.Run("2 pairs disabled", func(t *testing.T) {
270 l := New(discardHandler{disabled: true})
273 wantAllocs(t, 0, func() {
274 if l.Enabled(ctx, LevelInfo) {
275 l.Log(ctx, LevelInfo, "hello",
282 t.Run("9 kvs", func(t *testing.T) {
286 wantAllocs(t, 10, func() {
288 "n", i, "s", s, "d", d,
289 "n", i, "s", s, "d", d,
290 "n", i, "s", s, "d", d)
293 t.Run("pairs", func(t *testing.T) {
294 wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) })
296 t.Run("attrs1", func(t *testing.T) {
297 wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Int("a", 1)) })
298 wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Any("error", io.EOF)) })
300 t.Run("attrs3", func(t *testing.T) {
301 wantAllocs(t, 0, func() {
302 dl.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
305 t.Run("attrs3 disabled", func(t *testing.T) {
306 logger := New(discardHandler{disabled: true})
307 wantAllocs(t, 0, func() {
308 logger.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
311 t.Run("attrs6", func(t *testing.T) {
312 wantAllocs(t, 1, func() {
313 dl.LogAttrs(ctx, LevelInfo, "hello",
314 Int("a", 1), String("b", "two"), Duration("c", time.Second),
315 Int("d", 1), String("e", "two"), Duration("f", time.Second))
318 t.Run("attrs9", func(t *testing.T) {
319 wantAllocs(t, 1, func() {
320 dl.LogAttrs(ctx, LevelInfo, "hello",
321 Int("a", 1), String("b", "two"), Duration("c", time.Second),
322 Int("d", 1), String("e", "two"), Duration("f", time.Second),
323 Int("d", 1), String("e", "two"), Duration("f", time.Second))
328 func TestSetAttrs(t *testing.T) {
329 for _, test := range []struct {
334 {[]any{"a", 1}, []Attr{Int("a", 1)}},
335 {[]any{"a", 1, "b", "two"}, []Attr{Int("a", 1), String("b", "two")}},
336 {[]any{"a"}, []Attr{String(badKey, "a")}},
337 {[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}},
338 {[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}},
340 r := NewRecord(time.Time{}, 0, "", 0)
343 if !attrsEqual(got, test.want) {
344 t.Errorf("%v:\ngot %v\nwant %v", test.args, got, test.want)
349 func TestSetDefault(t *testing.T) {
350 // Verify that setting the default to itself does not result in deadlock.
351 ctx, cancel := context.WithTimeout(context.Background(), time.Second)
353 defer func(w io.Writer) { log.SetOutput(w) }(log.Writer())
354 log.SetOutput(io.Discard)
357 SetDefault(Default())
362 if err := ctx.Err(); err != context.Canceled {
363 t.Errorf("wanted canceled, got %v", err)
367 // Test defaultHandler minimum level without calling slog.SetDefault.
368 func TestLogLoggerLevelForDefaultHandler(t *testing.T) {
369 // Revert any changes to the default logger, flags, and level of log and slog.
370 currentLogLoggerLevel := logLoggerLevel.Level()
371 currentLogWriter := log.Writer()
372 currentLogFlags := log.Flags()
374 logLoggerLevel.Set(currentLogLoggerLevel)
375 log.SetOutput(currentLogWriter)
376 log.SetFlags(currentLogFlags)
379 var logBuf bytes.Buffer
380 log.SetOutput(&logBuf)
383 for _, test := range []struct {
385 logFn func(string, ...any)
388 {LevelDebug, Debug, "DEBUG a"},
389 {LevelDebug, Info, "INFO a"},
390 {LevelInfo, Debug, ""},
391 {LevelInfo, Info, "INFO a"},
393 SetLogLoggerLevel(test.logLevel)
395 checkLogOutput(t, logBuf.String(), test.want)
400 // Test handlerWriter minimum level by calling slog.SetDefault.
401 func TestLogLoggerLevelForHandlerWriter(t *testing.T) {
402 removeTime := func(_ []string, a Attr) Attr {
403 if a.Key == TimeKey {
409 // Revert any changes to the default logger. This is important because other
410 // tests might change the default logger using SetDefault. Also ensure we
411 // restore the default logger at the end of the test.
412 currentLogger := Default()
413 currentLogLoggerLevel := logLoggerLevel.Level()
414 currentLogWriter := log.Writer()
415 currentFlags := log.Flags()
417 SetDefault(currentLogger)
418 logLoggerLevel.Set(currentLogLoggerLevel)
419 log.SetOutput(currentLogWriter)
420 log.SetFlags(currentFlags)
423 var logBuf bytes.Buffer
424 log.SetOutput(&logBuf)
426 SetLogLoggerLevel(LevelError)
427 SetDefault(New(NewTextHandler(&logBuf, &HandlerOptions{ReplaceAttr: removeTime})))
429 checkLogOutput(t, logBuf.String(), `level=ERROR msg=error`)
432 func TestLoggerError(t *testing.T) {
435 removeTime := func(_ []string, a Attr) Attr {
436 if a.Key == TimeKey {
441 l := New(NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeTime}))
442 l.Error("msg", "err", io.EOF, "a", 1)
443 checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF a=1`)
445 // use local var 'args' to defeat vet check
446 args := []any{"err", io.EOF, "a"}
447 l.Error("msg", args...)
448 checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`)
451 func TestNewLogLogger(t *testing.T) {
453 h := NewTextHandler(&buf, nil)
454 ll := NewLogLogger(h, LevelWarn)
456 checkLogOutput(t, buf.String(), "time="+textTimeRE+` level=WARN msg=hello`)
459 func TestLoggerNoOps(t *testing.T) {
462 t.Error("wanted receiver, didn't get it")
465 t.Error("wanted receiver, didn't get it")
467 if l.WithGroup("") != l {
468 t.Error("wanted receiver, didn't get it")
472 func TestContext(t *testing.T) {
473 // Verify that the context argument to log output methods is passed to the handler.
474 // Also check the level.
475 h := &captureHandler{}
477 defer SetDefault(Default()) // restore
480 for _, test := range []struct {
481 f func(context.Context, string, ...any)
484 {l.DebugContext, LevelDebug},
485 {l.InfoContext, LevelInfo},
486 {l.WarnContext, LevelWarn},
487 {l.ErrorContext, LevelError},
488 {DebugContext, LevelDebug},
489 {InfoContext, LevelInfo},
490 {WarnContext, LevelWarn},
491 {ErrorContext, LevelError},
494 ctx := context.WithValue(context.Background(), "L", test.wantLevel)
497 if gv := h.ctx.Value("L"); gv != test.wantLevel || h.r.Level != test.wantLevel {
498 t.Errorf("got context value %v, level %s; want %s for both", gv, h.r.Level, test.wantLevel)
503 func checkLogOutput(t *testing.T, got, wantRegexp string) {
506 wantRegexp = "^" + wantRegexp + "$"
507 matched, err := regexp.MatchString(wantRegexp, got)
512 t.Errorf("\ngot %s\nwant %s", got, wantRegexp)
516 // clean prepares log output for comparison.
517 func clean(s string) string {
518 if len(s) > 0 && s[len(s)-1] == '\n' {
521 return strings.ReplaceAll(s, "\n", "~")
524 type captureHandler struct {
532 func (h *captureHandler) Handle(ctx context.Context, r Record) error {
540 func (*captureHandler) Enabled(context.Context, Level) bool { return true }
542 func (c *captureHandler) WithAttrs(as []Attr) Handler {
545 var c2 captureHandler
548 c2.attrs = concat(c.attrs, as)
552 func (c *captureHandler) WithGroup(name string) Handler {
555 var c2 captureHandler
558 c2.groups = append(slices.Clip(c.groups), name)
562 func (c *captureHandler) clear() {
569 type discardHandler struct {
574 func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled }
575 func (discardHandler) Handle(context.Context, Record) error { return nil }
576 func (d discardHandler) WithAttrs(as []Attr) Handler {
577 d.attrs = concat(d.attrs, as)
580 func (h discardHandler) WithGroup(name string) Handler {
584 // concat returns a new slice with the elements of s1 followed
585 // by those of s2. The slice has no additional capacity.
586 func concat[T any](s1, s2 []T) []T {
587 s := make([]T, len(s1)+len(s2))
589 copy(s[len(s1):], s2)
593 // This is a simple benchmark. See the benchmarks subdirectory for more extensive ones.
594 func BenchmarkNopLog(b *testing.B) {
595 ctx := context.Background()
596 l := New(&captureHandler{})
597 b.Run("no attrs", func(b *testing.B) {
599 for i := 0; i < b.N; i++ {
600 l.LogAttrs(ctx, LevelInfo, "msg")
603 b.Run("attrs", func(b *testing.B) {
605 for i := 0; i < b.N; i++ {
606 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
609 b.Run("attrs-parallel", func(b *testing.B) {
611 b.RunParallel(func(pb *testing.PB) {
613 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
617 b.Run("keys-values", func(b *testing.B) {
619 for i := 0; i < b.N; i++ {
620 l.Log(ctx, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
623 b.Run("WithContext", func(b *testing.B) {
625 for i := 0; i < b.N; i++ {
626 l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true))
629 b.Run("WithContext-parallel", func(b *testing.B) {
631 b.RunParallel(func(pb *testing.PB) {
633 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
639 // callerPC returns the program counter at the given stack depth.
640 func callerPC(depth int) uintptr {
642 runtime.Callers(depth, pcs[:])
646 func wantAllocs(t *testing.T, want int, f func()) {
648 t.Skip("skipping test in race mode")
650 testenv.SkipIfOptimizationOff(t)
652 got := int(testing.AllocsPerRun(5, f))
654 t.Errorf("got %d allocs, want %d", got, want)
658 // panicTextAndJsonMarshaler is a type that panics in MarshalText and MarshalJSON.
659 type panicTextAndJsonMarshaler struct {
663 func (p panicTextAndJsonMarshaler) MarshalText() ([]byte, error) {
667 func (p panicTextAndJsonMarshaler) MarshalJSON() ([]byte, error) {
671 func TestPanics(t *testing.T) {
672 // Revert any changes to the default logger. This is important because other
673 // tests might change the default logger using SetDefault. Also ensure we
674 // restore the default logger at the end of the test.
675 currentLogger := Default()
676 currentLogWriter := log.Writer()
677 currentLogFlags := log.Flags()
679 SetDefault(currentLogger)
680 log.SetOutput(currentLogWriter)
681 log.SetFlags(currentLogFlags)
684 var logBuf bytes.Buffer
685 log.SetOutput(&logBuf)
686 log.SetFlags(log.Lshortfile &^ log.LstdFlags)
688 SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
689 for _, pt := range []struct {
693 {(*panicTextAndJsonMarshaler)(nil), `logger_test.go:\d+: INFO msg p=<nil>`},
694 {panicTextAndJsonMarshaler{io.ErrUnexpectedEOF}, `logger_test.go:\d+: INFO msg p="!PANIC: unexpected EOF"`},
695 {panicTextAndJsonMarshaler{"panicking"}, `logger_test.go:\d+: INFO msg p="!PANIC: panicking"`},
696 {panicTextAndJsonMarshaler{42}, `logger_test.go:\d+: INFO msg p="!PANIC: 42"`},
698 Info("msg", "p", pt.in)
699 checkLogOutput(t, logBuf.String(), pt.out)
703 SetDefault(New(NewJSONHandler(&logBuf, nil)))
704 for _, pt := range []struct {
708 {(*panicTextAndJsonMarshaler)(nil), `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":null}`},
709 {panicTextAndJsonMarshaler{io.ErrUnexpectedEOF}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: unexpected EOF"}`},
710 {panicTextAndJsonMarshaler{"panicking"}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: panicking"}`},
711 {panicTextAndJsonMarshaler{42}, `{"time":"` + jsonTimeRE + `","level":"INFO","msg":"msg","p":"!PANIC: 42"}`},
713 Info("msg", "p", pt.in)
714 checkLogOutput(t, logBuf.String(), pt.out)