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