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