src/log/slog/logger_test.go

   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.
   4
   5 package slog
   6
   7 import (
   8         "bytes"
   9         "context"
  10         "internal/race"
  11         "internal/testenv"
  12         "io"
  13         "log"
  14         loginternal "log/internal"
  15         "path/filepath"
  16         "regexp"
  17         "runtime"
  18         "slices"
  19         "strings"
  20         "sync"
  21         "testing"
  22         "time"
  23 )
  24
  25 const timeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})`
  26
  27 func TestLogTextHandler(t *testing.T) {
  28         var buf bytes.Buffer
  29
  30         l := New(NewTextHandler(&buf, nil))
  31
  32         check := func(want string) {
  33                 t.Helper()
  34                 if want != "" {
  35                         want = "time=" + timeRE + " " + want
  36                 }
  37                 checkLogOutput(t, buf.String(), want)
  38                 buf.Reset()
  39         }
  40
  41         l.Info("msg", "a", 1, "b", 2)
  42         check(`level=INFO msg=msg a=1 b=2`)
  43
  44         // By default, debug messages are not printed.
  45         l.Debug("bg", Int("a", 1), "b", 2)
  46         check("")
  47
  48         l.Warn("w", Duration("dur", 3*time.Second))
  49         check(`level=WARN msg=w dur=3s`)
  50
  51         l.Error("bad", "a", 1)
  52         check(`level=ERROR msg=bad a=1`)
  53
  54         l.Log(nil, LevelWarn+1, "w", Int("a", 1), String("b", "two"))
  55         check(`level=WARN\+1 msg=w a=1 b=two`)
  56
  57         l.LogAttrs(nil, LevelInfo+1, "a b c", Int("a", 1), String("b", "two"))
  58         check(`level=INFO\+1 msg="a b c" a=1 b=two`)
  59
  60         l.Info("info", "a", []Attr{Int("i", 1)})
  61         check(`level=INFO msg=info a.i=1`)
  62
  63         l.Info("info", "a", GroupValue(Int("i", 1)))
  64         check(`level=INFO msg=info a.i=1`)
  65 }
  66
  67 func TestConnections(t *testing.T) {
  68         var logbuf, slogbuf bytes.Buffer
  69
  70         // Revert any changes to the default logger. This is important because other
  71         // tests might change the default logger using SetDefault. Also ensure we
  72         // restore the default logger at the end of the test.
  73         currentLogger := Default()
  74         SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
  75         t.Cleanup(func() {
  76                 SetDefault(currentLogger)
  77         })
  78
  79         // The default slog.Logger's handler uses the log package's default output.
  80         log.SetOutput(&logbuf)
  81         log.SetFlags(log.Lshortfile &^ log.LstdFlags)
  82         Info("msg", "a", 1)
  83         checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg a=1`)
  84         logbuf.Reset()
  85         Warn("msg", "b", 2)
  86         checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: WARN msg b=2`)
  87         logbuf.Reset()
  88         Error("msg", "err", io.EOF, "c", 3)
  89         checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: ERROR msg err=EOF c=3`)
  90
  91         // Levels below Info are not printed.
  92         logbuf.Reset()
  93         Debug("msg", "c", 3)
  94         checkLogOutput(t, logbuf.String(), "")
  95
  96         t.Run("wrap default handler", func(t *testing.T) {
  97                 // It should be possible to wrap the default handler and get the right output.
  98                 // This works because the default handler uses the pc in the Record
  99                 // to get the source line, rather than a call depth.
 100                 logger := New(wrappingHandler{Default().Handler()})
 101                 logger.Info("msg", "d", 4)
 102                 checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg d=4`)
 103         })
 104
 105         // Once slog.SetDefault is called, the direction is reversed: the default
 106         // log.Logger's output goes through the handler.
 107         SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{AddSource: true})))
 108         log.Print("msg2")
 109         checkLogOutput(t, slogbuf.String(), "time="+timeRE+` level=INFO source=.*logger_test.go:\d{3}"? msg=msg2`)
 110
 111         // The default log.Logger always outputs at Info level.
 112         slogbuf.Reset()
 113         SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{Level: LevelWarn})))
 114         log.Print("should not appear")
 115         if got := slogbuf.String(); got != "" {
 116                 t.Errorf("got %q, want empty", got)
 117         }
 118
 119         // Setting log's output again breaks the connection.
 120         logbuf.Reset()
 121         slogbuf.Reset()
 122         log.SetOutput(&logbuf)
 123         log.SetFlags(log.Lshortfile &^ log.LstdFlags)
 124         log.Print("msg3")
 125         checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: msg3`)
 126         if got := slogbuf.String(); got != "" {
 127                 t.Errorf("got %q, want empty", got)
 128         }
 129 }
 130
 131 type wrappingHandler struct {
 132         h Handler
 133 }
 134
 135 func (h wrappingHandler) Enabled(ctx context.Context, level Level) bool {
 136         return h.h.Enabled(ctx, level)
 137 }
 138 func (h wrappingHandler) WithGroup(name string) Handler              { return h.h.WithGroup(name) }
 139 func (h wrappingHandler) WithAttrs(as []Attr) Handler                { return h.h.WithAttrs(as) }
 140 func (h wrappingHandler) Handle(ctx context.Context, r Record) error { return h.h.Handle(ctx, r) }
 141
 142 func TestAttrs(t *testing.T) {
 143         check := func(got []Attr, want ...Attr) {
 144                 t.Helper()
 145                 if !attrsEqual(got, want) {
 146                         t.Errorf("got %v, want %v", got, want)
 147                 }
 148         }
 149
 150         l1 := New(&captureHandler{}).With("a", 1)
 151         l2 := New(l1.Handler()).With("b", 2)
 152         l2.Info("m", "c", 3)
 153         h := l2.Handler().(*captureHandler)
 154         check(h.attrs, Int("a", 1), Int("b", 2))
 155         check(attrsSlice(h.r), Int("c", 3))
 156 }
 157
 158 func TestCallDepth(t *testing.T) {
 159         h := &captureHandler{}
 160         var startLine int
 161
 162         check := func(count int) {
 163                 t.Helper()
 164                 const wantFunc = "log/slog.TestCallDepth"
 165                 const wantFile = "logger_test.go"
 166                 wantLine := startLine + count*2
 167                 got := h.r.source()
 168                 gotFile := filepath.Base(got.File)
 169                 if got.Function != wantFunc || gotFile != wantFile || got.Line != wantLine {
 170                         t.Errorf("got (%s, %s, %d), want (%s, %s, %d)",
 171                                 got.Function, gotFile, got.Line, wantFunc, wantFile, wantLine)
 172                 }
 173         }
 174
 175         logger := New(h)
 176         SetDefault(logger)
 177
 178         // Calls to check must be one line apart.
 179         // Determine line where calls start.
 180         f, _ := runtime.CallersFrames([]uintptr{callerPC(2)}).Next()
 181         startLine = f.Line + 4
 182         // Do not change the number of lines between here and the call to check(0).
 183
 184         logger.Log(nil, LevelInfo, "")
 185         check(0)
 186         logger.LogAttrs(nil, LevelInfo, "")
 187         check(1)
 188         logger.Debug("")
 189         check(2)
 190         logger.Info("")
 191         check(3)
 192         logger.Warn("")
 193         check(4)
 194         logger.Error("")
 195         check(5)
 196         Debug("")
 197         check(6)
 198         Info("")
 199         check(7)
 200         Warn("")
 201         check(8)
 202         Error("")
 203         check(9)
 204         Log(nil, LevelInfo, "")
 205         check(10)
 206         LogAttrs(nil, LevelInfo, "")
 207         check(11)
 208 }
 209
 210 func TestAlloc(t *testing.T) {
 211         dl := New(discardHandler{})
 212         defer SetDefault(Default()) // restore
 213         SetDefault(dl)
 214
 215         t.Run("Info", func(t *testing.T) {
 216                 wantAllocs(t, 0, func() { Info("hello") })
 217         })
 218         t.Run("Error", func(t *testing.T) {
 219                 wantAllocs(t, 0, func() { Error("hello") })
 220         })
 221         t.Run("logger.Info", func(t *testing.T) {
 222                 wantAllocs(t, 0, func() { dl.Info("hello") })
 223         })
 224         t.Run("logger.Log", func(t *testing.T) {
 225                 wantAllocs(t, 0, func() { dl.Log(nil, LevelDebug, "hello") })
 226         })
 227         t.Run("2 pairs", func(t *testing.T) {
 228                 s := "abc"
 229                 i := 2000
 230                 wantAllocs(t, 2, func() {
 231                         dl.Info("hello",
 232                                 "n", i,
 233                                 "s", s,
 234                         )
 235                 })
 236         })
 237         t.Run("2 pairs disabled inline", func(t *testing.T) {
 238                 l := New(discardHandler{disabled: true})
 239                 s := "abc"
 240                 i := 2000
 241                 wantAllocs(t, 2, func() {
 242                         l.Log(nil, LevelInfo, "hello",
 243                                 "n", i,
 244                                 "s", s,
 245                         )
 246                 })
 247         })
 248         t.Run("2 pairs disabled", func(t *testing.T) {
 249                 l := New(discardHandler{disabled: true})
 250                 s := "abc"
 251                 i := 2000
 252                 wantAllocs(t, 0, func() {
 253                         if l.Enabled(nil, LevelInfo) {
 254                                 l.Log(nil, LevelInfo, "hello",
 255                                         "n", i,
 256                                         "s", s,
 257                                 )
 258                         }
 259                 })
 260         })
 261         t.Run("9 kvs", func(t *testing.T) {
 262                 s := "abc"
 263                 i := 2000
 264                 d := time.Second
 265                 wantAllocs(t, 11, func() {
 266                         dl.Info("hello",
 267                                 "n", i, "s", s, "d", d,
 268                                 "n", i, "s", s, "d", d,
 269                                 "n", i, "s", s, "d", d)
 270                 })
 271         })
 272         t.Run("pairs", func(t *testing.T) {
 273                 wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) })
 274         })
 275         t.Run("attrs1", func(t *testing.T) {
 276                 wantAllocs(t, 0, func() { dl.LogAttrs(nil, LevelInfo, "", Int("a", 1)) })
 277                 wantAllocs(t, 0, func() { dl.LogAttrs(nil, LevelInfo, "", Any("error", io.EOF)) })
 278         })
 279         t.Run("attrs3", func(t *testing.T) {
 280                 wantAllocs(t, 0, func() {
 281                         dl.LogAttrs(nil, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
 282                 })
 283         })
 284         t.Run("attrs3 disabled", func(t *testing.T) {
 285                 logger := New(discardHandler{disabled: true})
 286                 wantAllocs(t, 0, func() {
 287                         logger.LogAttrs(nil, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
 288                 })
 289         })
 290         t.Run("attrs6", func(t *testing.T) {
 291                 wantAllocs(t, 1, func() {
 292                         dl.LogAttrs(nil, LevelInfo, "hello",
 293                                 Int("a", 1), String("b", "two"), Duration("c", time.Second),
 294                                 Int("d", 1), String("e", "two"), Duration("f", time.Second))
 295                 })
 296         })
 297         t.Run("attrs9", func(t *testing.T) {
 298                 wantAllocs(t, 1, func() {
 299                         dl.LogAttrs(nil, LevelInfo, "hello",
 300                                 Int("a", 1), String("b", "two"), Duration("c", time.Second),
 301                                 Int("d", 1), String("e", "two"), Duration("f", time.Second),
 302                                 Int("d", 1), String("e", "two"), Duration("f", time.Second))
 303                 })
 304         })
 305 }
 306
 307 func TestSetAttrs(t *testing.T) {
 308         for _, test := range []struct {
 309                 args []any
 310                 want []Attr
 311         }{
 312                 {nil, nil},
 313                 {[]any{"a", 1}, []Attr{Int("a", 1)}},
 314                 {[]any{"a", 1, "b", "two"}, []Attr{Int("a", 1), String("b", "two")}},
 315                 {[]any{"a"}, []Attr{String(badKey, "a")}},
 316                 {[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}},
 317                 {[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}},
 318         } {
 319                 r := NewRecord(time.Time{}, 0, "", 0)
 320                 r.Add(test.args...)
 321                 got := attrsSlice(r)
 322                 if !attrsEqual(got, test.want) {
 323                         t.Errorf("%v:\ngot  %v\nwant %v", test.args, got, test.want)
 324                 }
 325         }
 326 }
 327
 328 func TestSetDefault(t *testing.T) {
 329         // Verify that setting the default to itself does not result in deadlock.
 330         ctx, cancel := context.WithTimeout(context.Background(), time.Second)
 331         defer cancel()
 332         defer func(w io.Writer) { log.SetOutput(w) }(log.Writer())
 333         log.SetOutput(io.Discard)
 334         go func() {
 335                 Info("A")
 336                 SetDefault(Default())
 337                 Info("B")
 338                 cancel()
 339         }()
 340         <-ctx.Done()
 341         if err := ctx.Err(); err != context.Canceled {
 342                 t.Errorf("wanted canceled, got %v", err)
 343         }
 344 }
 345
 346 func TestLoggerError(t *testing.T) {
 347         var buf bytes.Buffer
 348
 349         removeTime := func(_ []string, a Attr) Attr {
 350                 if a.Key == TimeKey {
 351                         return Attr{}
 352                 }
 353                 return a
 354         }
 355         l := New(NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeTime}))
 356         l.Error("msg", "err", io.EOF, "a", 1)
 357         checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF a=1`)
 358         buf.Reset()
 359         // use local var 'args' to defeat vet check
 360         args := []any{"err", io.EOF, "a"}
 361         l.Error("msg", args...)
 362         checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`)
 363 }
 364
 365 func TestNewLogLogger(t *testing.T) {
 366         var buf bytes.Buffer
 367         h := NewTextHandler(&buf, nil)
 368         ll := NewLogLogger(h, LevelWarn)
 369         ll.Print("hello")
 370         checkLogOutput(t, buf.String(), "time="+timeRE+` level=WARN msg=hello`)
 371 }
 372
 373 func TestLoggerNoOps(t *testing.T) {
 374         l := Default()
 375         if l.With() != l {
 376                 t.Error("wanted receiver, didn't get it")
 377         }
 378         if With() != l {
 379                 t.Error("wanted receiver, didn't get it")
 380         }
 381         if l.WithGroup("") != l {
 382                 t.Error("wanted receiver, didn't get it")
 383         }
 384 }
 385
 386 func TestContext(t *testing.T) {
 387         // Verify that the context argument to log output methods is passed to the handler.
 388         // Also check the level.
 389         h := &captureHandler{}
 390         l := New(h)
 391         defer SetDefault(Default()) // restore
 392         SetDefault(l)
 393
 394         for _, test := range []struct {
 395                 f         func(context.Context, string, ...any)
 396                 wantLevel Level
 397         }{
 398                 {l.DebugContext, LevelDebug},
 399                 {l.InfoContext, LevelInfo},
 400                 {l.WarnContext, LevelWarn},
 401                 {l.ErrorContext, LevelError},
 402                 {DebugContext, LevelDebug},
 403                 {InfoContext, LevelInfo},
 404                 {WarnContext, LevelWarn},
 405                 {ErrorContext, LevelError},
 406         } {
 407                 h.clear()
 408                 ctx := context.WithValue(context.Background(), "L", test.wantLevel)
 409
 410                 test.f(ctx, "msg")
 411                 if gv := h.ctx.Value("L"); gv != test.wantLevel || h.r.Level != test.wantLevel {
 412                         t.Errorf("got context value %v, level %s; want %s for both", gv, h.r.Level, test.wantLevel)
 413                 }
 414         }
 415 }
 416
 417 func checkLogOutput(t *testing.T, got, wantRegexp string) {
 418         t.Helper()
 419         got = clean(got)
 420         wantRegexp = "^" + wantRegexp + "$"
 421         matched, err := regexp.MatchString(wantRegexp, got)
 422         if err != nil {
 423                 t.Fatal(err)
 424         }
 425         if !matched {
 426                 t.Errorf("\ngot  %s\nwant %s", got, wantRegexp)
 427         }
 428 }
 429
 430 // clean prepares log output for comparison.
 431 func clean(s string) string {
 432         if len(s) > 0 && s[len(s)-1] == '\n' {
 433                 s = s[:len(s)-1]
 434         }
 435         return strings.ReplaceAll(s, "\n", "~")
 436 }
 437
 438 type captureHandler struct {
 439         mu     sync.Mutex
 440         ctx    context.Context
 441         r      Record
 442         attrs  []Attr
 443         groups []string
 444 }
 445
 446 func (h *captureHandler) Handle(ctx context.Context, r Record) error {
 447         h.mu.Lock()
 448         defer h.mu.Unlock()
 449         h.ctx = ctx
 450         h.r = r
 451         return nil
 452 }
 453
 454 func (*captureHandler) Enabled(context.Context, Level) bool { return true }
 455
 456 func (c *captureHandler) WithAttrs(as []Attr) Handler {
 457         c.mu.Lock()
 458         defer c.mu.Unlock()
 459         var c2 captureHandler
 460         c2.r = c.r
 461         c2.groups = c.groups
 462         c2.attrs = concat(c.attrs, as)
 463         return &c2
 464 }
 465
 466 func (c *captureHandler) WithGroup(name string) Handler {
 467         c.mu.Lock()
 468         defer c.mu.Unlock()
 469         var c2 captureHandler
 470         c2.r = c.r
 471         c2.attrs = c.attrs
 472         c2.groups = append(slices.Clip(c.groups), name)
 473         return &c2
 474 }
 475
 476 func (c *captureHandler) clear() {
 477         c.mu.Lock()
 478         defer c.mu.Unlock()
 479         c.ctx = nil
 480         c.r = Record{}
 481 }
 482
 483 type discardHandler struct {
 484         disabled bool
 485         attrs    []Attr
 486 }
 487
 488 func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled }
 489 func (discardHandler) Handle(context.Context, Record) error  { return nil }
 490 func (d discardHandler) WithAttrs(as []Attr) Handler {
 491         d.attrs = concat(d.attrs, as)
 492         return d
 493 }
 494 func (h discardHandler) WithGroup(name string) Handler {
 495         return h
 496 }
 497
 498 // concat returns a new slice with the elements of s1 followed
 499 // by those of s2. The slice has no additional capacity.
 500 func concat[T any](s1, s2 []T) []T {
 501         s := make([]T, len(s1)+len(s2))
 502         copy(s, s1)
 503         copy(s[len(s1):], s2)
 504         return s
 505 }
 506
 507 // This is a simple benchmark. See the benchmarks subdirectory for more extensive ones.
 508 func BenchmarkNopLog(b *testing.B) {
 509         ctx := context.Background()
 510         l := New(&captureHandler{})
 511         b.Run("no attrs", func(b *testing.B) {
 512                 b.ReportAllocs()
 513                 for i := 0; i < b.N; i++ {
 514                         l.LogAttrs(nil, LevelInfo, "msg")
 515                 }
 516         })
 517         b.Run("attrs", func(b *testing.B) {
 518                 b.ReportAllocs()
 519                 for i := 0; i < b.N; i++ {
 520                         l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 521                 }
 522         })
 523         b.Run("attrs-parallel", func(b *testing.B) {
 524                 b.ReportAllocs()
 525                 b.RunParallel(func(pb *testing.PB) {
 526                         for pb.Next() {
 527                                 l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 528                         }
 529                 })
 530         })
 531         b.Run("keys-values", func(b *testing.B) {
 532                 b.ReportAllocs()
 533                 for i := 0; i < b.N; i++ {
 534                         l.Log(nil, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
 535                 }
 536         })
 537         b.Run("WithContext", func(b *testing.B) {
 538                 b.ReportAllocs()
 539                 for i := 0; i < b.N; i++ {
 540                         l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true))
 541                 }
 542         })
 543         b.Run("WithContext-parallel", func(b *testing.B) {
 544                 b.ReportAllocs()
 545                 b.RunParallel(func(pb *testing.PB) {
 546                         for pb.Next() {
 547                                 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 548                         }
 549                 })
 550         })
 551 }
 552
 553 // callerPC returns the program counter at the given stack depth.
 554 func callerPC(depth int) uintptr {
 555         var pcs [1]uintptr
 556         runtime.Callers(depth, pcs[:])
 557         return pcs[0]
 558 }
 559
 560 func wantAllocs(t *testing.T, want int, f func()) {
 561         if race.Enabled {
 562                 t.Skip("skipping test in race mode")
 563         }
 564         testenv.SkipIfOptimizationOff(t)
 565         t.Helper()
 566         got := int(testing.AllocsPerRun(5, f))
 567         if got != want {
 568                 t.Errorf("got %d allocs, want %d", got, want)
 569         }
 570 }