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