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

View as plain text