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 func(d *Logger) { SetDefault(d) }(Default())
 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 checkLogOutput(t *testing.T, got, wantRegexp string) {
 374         t.Helper()
 375         got = clean(got)
 376         wantRegexp = "^" + wantRegexp + "$"
 377         matched, err := regexp.MatchString(wantRegexp, got)
 378         if err != nil {
 379                 t.Fatal(err)
 380         }
 381         if !matched {
 382                 t.Errorf("\ngot  %s\nwant %s", got, wantRegexp)
 383         }
 384 }
 385
 386 // clean prepares log output for comparison.
 387 func clean(s string) string {
 388         if len(s) > 0 && s[len(s)-1] == '\n' {
 389                 s = s[:len(s)-1]
 390         }
 391         return strings.ReplaceAll(s, "\n", "~")
 392 }
 393
 394 type captureHandler struct {
 395         mu     sync.Mutex
 396         r      Record
 397         attrs  []Attr
 398         groups []string
 399 }
 400
 401 func (h *captureHandler) Handle(ctx context.Context, r Record) error {
 402         h.mu.Lock()
 403         defer h.mu.Unlock()
 404         h.r = r
 405         return nil
 406 }
 407
 408 func (*captureHandler) Enabled(context.Context, Level) bool { return true }
 409
 410 func (c *captureHandler) WithAttrs(as []Attr) Handler {
 411         c.mu.Lock()
 412         defer c.mu.Unlock()
 413         var c2 captureHandler
 414         c2.r = c.r
 415         c2.groups = c.groups
 416         c2.attrs = concat(c.attrs, as)
 417         return &c2
 418 }
 419
 420 func (c *captureHandler) WithGroup(name string) Handler {
 421         c.mu.Lock()
 422         defer c.mu.Unlock()
 423         var c2 captureHandler
 424         c2.r = c.r
 425         c2.attrs = c.attrs
 426         c2.groups = append(slices.Clip(c.groups), name)
 427         return &c2
 428 }
 429
 430 type discardHandler struct {
 431         disabled bool
 432         attrs    []Attr
 433 }
 434
 435 func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled }
 436 func (discardHandler) Handle(context.Context, Record) error  { return nil }
 437 func (d discardHandler) WithAttrs(as []Attr) Handler {
 438         d.attrs = concat(d.attrs, as)
 439         return d
 440 }
 441 func (h discardHandler) WithGroup(name string) Handler {
 442         return h
 443 }
 444
 445 // concat returns a new slice with the elements of s1 followed
 446 // by those of s2. The slice has no additional capacity.
 447 func concat[T any](s1, s2 []T) []T {
 448         s := make([]T, len(s1)+len(s2))
 449         copy(s, s1)
 450         copy(s[len(s1):], s2)
 451         return s
 452 }
 453
 454 // This is a simple benchmark. See the benchmarks subdirectory for more extensive ones.
 455 func BenchmarkNopLog(b *testing.B) {
 456         ctx := context.Background()
 457         l := New(&captureHandler{})
 458         b.Run("no attrs", func(b *testing.B) {
 459                 b.ReportAllocs()
 460                 for i := 0; i < b.N; i++ {
 461                         l.LogAttrs(nil, LevelInfo, "msg")
 462                 }
 463         })
 464         b.Run("attrs", func(b *testing.B) {
 465                 b.ReportAllocs()
 466                 for i := 0; i < b.N; i++ {
 467                         l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 468                 }
 469         })
 470         b.Run("attrs-parallel", func(b *testing.B) {
 471                 b.ReportAllocs()
 472                 b.RunParallel(func(pb *testing.PB) {
 473                         for pb.Next() {
 474                                 l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 475                         }
 476                 })
 477         })
 478         b.Run("keys-values", func(b *testing.B) {
 479                 b.ReportAllocs()
 480                 for i := 0; i < b.N; i++ {
 481                         l.Log(nil, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
 482                 }
 483         })
 484         b.Run("WithContext", func(b *testing.B) {
 485                 b.ReportAllocs()
 486                 for i := 0; i < b.N; i++ {
 487                         l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true))
 488                 }
 489         })
 490         b.Run("WithContext-parallel", func(b *testing.B) {
 491                 b.ReportAllocs()
 492                 b.RunParallel(func(pb *testing.PB) {
 493                         for pb.Next() {
 494                                 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 495                         }
 496                 })
 497         })
 498 }
 499
 500 // callerPC returns the program counter at the given stack depth.
 501 func callerPC(depth int) uintptr {
 502         var pcs [1]uintptr
 503         runtime.Callers(depth, pcs[:])
 504         return pcs[0]
 505 }
 506
 507 func wantAllocs(t *testing.T, want int, f func()) {
 508         if race.Enabled {
 509                 t.Skip("skipping test in race mode")
 510         }
 511         testenv.SkipIfOptimizationOff(t)
 512         t.Helper()
 513         got := int(testing.AllocsPerRun(5, f))
 514         if got != want {
 515                 t.Errorf("got %d allocs, want %d", got, want)
 516         }
 517 }