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

View as plain text