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

View as plain text