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))
  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(HandlerOptions{AddSource: true}.NewTextHandler(&slogbuf)))
 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(HandlerOptions{Level: LevelWarn}.NewTextHandler(&slogbuf)))
 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 sourceLine(r Record) (string, int) {
 159         f := r.frame()
 160         return f.File, f.Line
 161 }
 162
 163 func TestCallDepth(t *testing.T) {
 164         h := &captureHandler{}
 165         var startLine int
 166
 167         check := func(count int) {
 168                 t.Helper()
 169                 const wantFile = "logger_test.go"
 170                 wantLine := startLine + count*2
 171                 gotFile, gotLine := sourceLine(h.r)
 172                 gotFile = filepath.Base(gotFile)
 173                 if gotFile != wantFile || gotLine != wantLine {
 174                         t.Errorf("got (%s, %d), want (%s, %d)", gotFile, gotLine, wantFile, wantLine)
 175                 }
 176         }
 177
 178         logger := New(h)
 179         SetDefault(logger)
 180
 181         // Calls to check must be one line apart.
 182         // Determine line where calls start.
 183         f, _ := runtime.CallersFrames([]uintptr{callerPC(2)}).Next()
 184         startLine = f.Line + 4
 185         // Do not change the number of lines between here and the call to check(0).
 186
 187         logger.Log(nil, LevelInfo, "")
 188         check(0)
 189         logger.LogAttrs(nil, LevelInfo, "")
 190         check(1)
 191         logger.Debug("")
 192         check(2)
 193         logger.Info("")
 194         check(3)
 195         logger.Warn("")
 196         check(4)
 197         logger.Error("")
 198         check(5)
 199         Debug("")
 200         check(6)
 201         Info("")
 202         check(7)
 203         Warn("")
 204         check(8)
 205         Error("")
 206         check(9)
 207         Log(nil, LevelInfo, "")
 208         check(10)
 209         LogAttrs(nil, LevelInfo, "")
 210         check(11)
 211 }
 212
 213 func TestAlloc(t *testing.T) {
 214         dl := New(discardHandler{})
 215         defer func(d *Logger) { SetDefault(d) }(Default())
 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(nil, 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(nil, 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(nil, LevelInfo) {
 257                                 l.Log(nil, 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(nil, LevelInfo, "", Int("a", 1)) })
 280                 wantAllocs(t, 0, func() { dl.LogAttrs(nil, LevelInfo, "", Any("error", io.EOF)) })
 281         })
 282         t.Run("attrs3", func(t *testing.T) {
 283                 wantAllocs(t, 0, func() {
 284                         dl.LogAttrs(nil, 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(nil, 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(nil, 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(nil, 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(HandlerOptions{ReplaceAttr: removeTime}.NewTextHandler(&buf))
 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         l.Error("msg", "err", io.EOF, "a")
 363         checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`)
 364 }
 365
 366 func TestNewLogLogger(t *testing.T) {
 367         var buf bytes.Buffer
 368         h := NewTextHandler(&buf)
 369         ll := NewLogLogger(h, LevelWarn)
 370         ll.Print("hello")
 371         checkLogOutput(t, buf.String(), "time="+timeRE+` level=WARN msg=hello`)
 372 }
 373
 374 func checkLogOutput(t *testing.T, got, wantRegexp string) {
 375         t.Helper()
 376         got = clean(got)
 377         wantRegexp = "^" + wantRegexp + "$"
 378         matched, err := regexp.MatchString(wantRegexp, got)
 379         if err != nil {
 380                 t.Fatal(err)
 381         }
 382         if !matched {
 383                 t.Errorf("\ngot  %s\nwant %s", got, wantRegexp)
 384         }
 385 }
 386
 387 // clean prepares log output for comparison.
 388 func clean(s string) string {
 389         if len(s) > 0 && s[len(s)-1] == '\n' {
 390                 s = s[:len(s)-1]
 391         }
 392         return strings.ReplaceAll(s, "\n", "~")
 393 }
 394
 395 type captureHandler struct {
 396         mu     sync.Mutex
 397         r      Record
 398         attrs  []Attr
 399         groups []string
 400 }
 401
 402 func (h *captureHandler) Handle(ctx context.Context, r Record) error {
 403         h.mu.Lock()
 404         defer h.mu.Unlock()
 405         h.r = r
 406         return nil
 407 }
 408
 409 func (*captureHandler) Enabled(context.Context, Level) bool { return true }
 410
 411 func (c *captureHandler) WithAttrs(as []Attr) Handler {
 412         c.mu.Lock()
 413         defer c.mu.Unlock()
 414         var c2 captureHandler
 415         c2.r = c.r
 416         c2.groups = c.groups
 417         c2.attrs = concat(c.attrs, as)
 418         return &c2
 419 }
 420
 421 func (c *captureHandler) WithGroup(name string) Handler {
 422         c.mu.Lock()
 423         defer c.mu.Unlock()
 424         var c2 captureHandler
 425         c2.r = c.r
 426         c2.attrs = c.attrs
 427         c2.groups = append(slices.Clip(c.groups), name)
 428         return &c2
 429 }
 430
 431 type discardHandler struct {
 432         disabled bool
 433         attrs    []Attr
 434 }
 435
 436 func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled }
 437 func (discardHandler) Handle(context.Context, Record) error  { return nil }
 438 func (d discardHandler) WithAttrs(as []Attr) Handler {
 439         d.attrs = concat(d.attrs, as)
 440         return d
 441 }
 442 func (h discardHandler) WithGroup(name string) Handler {
 443         return h
 444 }
 445
 446 // concat returns a new slice with the elements of s1 followed
 447 // by those of s2. The slice has no additional capacity.
 448 func concat[T any](s1, s2 []T) []T {
 449         s := make([]T, len(s1)+len(s2))
 450         copy(s, s1)
 451         copy(s[len(s1):], s2)
 452         return s
 453 }
 454
 455 // This is a simple benchmark. See the benchmarks subdirectory for more extensive ones.
 456 func BenchmarkNopLog(b *testing.B) {
 457         ctx := context.Background()
 458         l := New(&captureHandler{})
 459         b.Run("no attrs", func(b *testing.B) {
 460                 b.ReportAllocs()
 461                 for i := 0; i < b.N; i++ {
 462                         l.LogAttrs(nil, LevelInfo, "msg")
 463                 }
 464         })
 465         b.Run("attrs", func(b *testing.B) {
 466                 b.ReportAllocs()
 467                 for i := 0; i < b.N; i++ {
 468                         l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 469                 }
 470         })
 471         b.Run("attrs-parallel", func(b *testing.B) {
 472                 b.ReportAllocs()
 473                 b.RunParallel(func(pb *testing.PB) {
 474                         for pb.Next() {
 475                                 l.LogAttrs(nil, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 476                         }
 477                 })
 478         })
 479         b.Run("keys-values", func(b *testing.B) {
 480                 b.ReportAllocs()
 481                 for i := 0; i < b.N; i++ {
 482                         l.Log(nil, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
 483                 }
 484         })
 485         b.Run("WithContext", func(b *testing.B) {
 486                 b.ReportAllocs()
 487                 for i := 0; i < b.N; i++ {
 488                         l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true))
 489                 }
 490         })
 491         b.Run("WithContext-parallel", func(b *testing.B) {
 492                 b.ReportAllocs()
 493                 b.RunParallel(func(pb *testing.PB) {
 494                         for pb.Next() {
 495                                 l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
 496                         }
 497                 })
 498         })
 499 }
 500
 501 // callerPC returns the program counter at the given stack depth.
 502 func callerPC(depth int) uintptr {
 503         var pcs [1]uintptr
 504         runtime.Callers(depth, pcs[:])
 505         return pcs[0]
 506 }
 507
 508 func wantAllocs(t *testing.T, want int, f func()) {
 509         if race.Enabled {
 510                 t.Skip("skipping test in race mode")
 511         }
 512         testenv.SkipIfOptimizationOff(t)
 513         t.Helper()
 514         got := int(testing.AllocsPerRun(5, f))
 515         if got != want {
 516                 t.Errorf("got %d allocs, want %d", got, want)
 517         }
 518 }