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

View as plain text