Source file 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  }
   718  

View as plain text