Adding upstream version 1.21.8.upstream/1.21.8

Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>

1 files changed, 573 insertions, 0 deletions

diff --git a/src/log/slog/logger_test.go b/src/log/slog/logger_test.go
new file mode 100644
index 0000000..2f5b319
--- /dev/null
+++ b/src/log/slog/logger_test.go
@@ -0,0 +1,573 @@
+// Copyright 2022 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package slog
+
+import (
+	"bytes"
+	"context"
+	"internal/race"
+	"internal/testenv"
+	"io"
+	"log"
+	loginternal "log/internal"
+	"path/filepath"
+	"regexp"
+	"runtime"
+	"slices"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+)
+
+const timeRE = `\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}(Z|[+-]\d{2}:\d{2})`
+
+func TestLogTextHandler(t *testing.T) {
+	ctx := context.Background()
+	var buf bytes.Buffer
+
+	l := New(NewTextHandler(&buf, nil))
+
+	check := func(want string) {
+		t.Helper()
+		if want != "" {
+			want = "time=" + timeRE + " " + want
+		}
+		checkLogOutput(t, buf.String(), want)
+		buf.Reset()
+	}
+
+	l.Info("msg", "a", 1, "b", 2)
+	check(`level=INFO msg=msg a=1 b=2`)
+
+	// By default, debug messages are not printed.
+	l.Debug("bg", Int("a", 1), "b", 2)
+	check("")
+
+	l.Warn("w", Duration("dur", 3*time.Second))
+	check(`level=WARN msg=w dur=3s`)
+
+	l.Error("bad", "a", 1)
+	check(`level=ERROR msg=bad a=1`)
+
+	l.Log(ctx, LevelWarn+1, "w", Int("a", 1), String("b", "two"))
+	check(`level=WARN\+1 msg=w a=1 b=two`)
+
+	l.LogAttrs(ctx, LevelInfo+1, "a b c", Int("a", 1), String("b", "two"))
+	check(`level=INFO\+1 msg="a b c" a=1 b=two`)
+
+	l.Info("info", "a", []Attr{Int("i", 1)})
+	check(`level=INFO msg=info a.i=1`)
+
+	l.Info("info", "a", GroupValue(Int("i", 1)))
+	check(`level=INFO msg=info a.i=1`)
+}
+
+func TestConnections(t *testing.T) {
+	var logbuf, slogbuf bytes.Buffer
+
+	// Revert any changes to the default logger. This is important because other
+	// tests might change the default logger using SetDefault. Also ensure we
+	// restore the default logger at the end of the test.
+	currentLogger := Default()
+	SetDefault(New(newDefaultHandler(loginternal.DefaultOutput)))
+	t.Cleanup(func() {
+		SetDefault(currentLogger)
+	})
+
+	// The default slog.Logger's handler uses the log package's default output.
+	log.SetOutput(&logbuf)
+	log.SetFlags(log.Lshortfile &^ log.LstdFlags)
+	Info("msg", "a", 1)
+	checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg a=1`)
+	logbuf.Reset()
+	Warn("msg", "b", 2)
+	checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: WARN msg b=2`)
+	logbuf.Reset()
+	Error("msg", "err", io.EOF, "c", 3)
+	checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: ERROR msg err=EOF c=3`)
+
+	// Levels below Info are not printed.
+	logbuf.Reset()
+	Debug("msg", "c", 3)
+	checkLogOutput(t, logbuf.String(), "")
+
+	t.Run("wrap default handler", func(t *testing.T) {
+		// It should be possible to wrap the default handler and get the right output.
+		// This works because the default handler uses the pc in the Record
+		// to get the source line, rather than a call depth.
+		logger := New(wrappingHandler{Default().Handler()})
+		logger.Info("msg", "d", 4)
+		checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: INFO msg d=4`)
+	})
+
+	// Once slog.SetDefault is called, the direction is reversed: the default
+	// log.Logger's output goes through the handler.
+	SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{AddSource: true})))
+	log.Print("msg2")
+	checkLogOutput(t, slogbuf.String(), "time="+timeRE+` level=INFO source=.*logger_test.go:\d{3}"? msg=msg2`)
+
+	// The default log.Logger always outputs at Info level.
+	slogbuf.Reset()
+	SetDefault(New(NewTextHandler(&slogbuf, &HandlerOptions{Level: LevelWarn})))
+	log.Print("should not appear")
+	if got := slogbuf.String(); got != "" {
+		t.Errorf("got %q, want empty", got)
+	}
+
+	// Setting log's output again breaks the connection.
+	logbuf.Reset()
+	slogbuf.Reset()
+	log.SetOutput(&logbuf)
+	log.SetFlags(log.Lshortfile &^ log.LstdFlags)
+	log.Print("msg3")
+	checkLogOutput(t, logbuf.String(), `logger_test.go:\d+: msg3`)
+	if got := slogbuf.String(); got != "" {
+		t.Errorf("got %q, want empty", got)
+	}
+}
+
+type wrappingHandler struct {
+	h Handler
+}
+
+func (h wrappingHandler) Enabled(ctx context.Context, level Level) bool {
+	return h.h.Enabled(ctx, level)
+}
+func (h wrappingHandler) WithGroup(name string) Handler              { return h.h.WithGroup(name) }
+func (h wrappingHandler) WithAttrs(as []Attr) Handler                { return h.h.WithAttrs(as) }
+func (h wrappingHandler) Handle(ctx context.Context, r Record) error { return h.h.Handle(ctx, r) }
+
+func TestAttrs(t *testing.T) {
+	check := func(got []Attr, want ...Attr) {
+		t.Helper()
+		if !attrsEqual(got, want) {
+			t.Errorf("got %v, want %v", got, want)
+		}
+	}
+
+	l1 := New(&captureHandler{}).With("a", 1)
+	l2 := New(l1.Handler()).With("b", 2)
+	l2.Info("m", "c", 3)
+	h := l2.Handler().(*captureHandler)
+	check(h.attrs, Int("a", 1), Int("b", 2))
+	check(attrsSlice(h.r), Int("c", 3))
+}
+
+func TestCallDepth(t *testing.T) {
+	ctx := context.Background()
+	h := &captureHandler{}
+	var startLine int
+
+	check := func(count int) {
+		t.Helper()
+		const wantFunc = "log/slog.TestCallDepth"
+		const wantFile = "logger_test.go"
+		wantLine := startLine + count*2
+		got := h.r.source()
+		gotFile := filepath.Base(got.File)
+		if got.Function != wantFunc || gotFile != wantFile || got.Line != wantLine {
+			t.Errorf("got (%s, %s, %d), want (%s, %s, %d)",
+				got.Function, gotFile, got.Line, wantFunc, wantFile, wantLine)
+		}
+	}
+
+	logger := New(h)
+	SetDefault(logger)
+
+	// Calls to check must be one line apart.
+	// Determine line where calls start.
+	f, _ := runtime.CallersFrames([]uintptr{callerPC(2)}).Next()
+	startLine = f.Line + 4
+	// Do not change the number of lines between here and the call to check(0).
+
+	logger.Log(ctx, LevelInfo, "")
+	check(0)
+	logger.LogAttrs(ctx, LevelInfo, "")
+	check(1)
+	logger.Debug("")
+	check(2)
+	logger.Info("")
+	check(3)
+	logger.Warn("")
+	check(4)
+	logger.Error("")
+	check(5)
+	Debug("")
+	check(6)
+	Info("")
+	check(7)
+	Warn("")
+	check(8)
+	Error("")
+	check(9)
+	Log(ctx, LevelInfo, "")
+	check(10)
+	LogAttrs(ctx, LevelInfo, "")
+	check(11)
+}
+
+func TestAlloc(t *testing.T) {
+	ctx := context.Background()
+	dl := New(discardHandler{})
+	defer SetDefault(Default()) // restore
+	SetDefault(dl)
+
+	t.Run("Info", func(t *testing.T) {
+		wantAllocs(t, 0, func() { Info("hello") })
+	})
+	t.Run("Error", func(t *testing.T) {
+		wantAllocs(t, 0, func() { Error("hello") })
+	})
+	t.Run("logger.Info", func(t *testing.T) {
+		wantAllocs(t, 0, func() { dl.Info("hello") })
+	})
+	t.Run("logger.Log", func(t *testing.T) {
+		wantAllocs(t, 0, func() { dl.Log(ctx, LevelDebug, "hello") })
+	})
+	t.Run("2 pairs", func(t *testing.T) {
+		s := "abc"
+		i := 2000
+		wantAllocs(t, 2, func() {
+			dl.Info("hello",
+				"n", i,
+				"s", s,
+			)
+		})
+	})
+	t.Run("2 pairs disabled inline", func(t *testing.T) {
+		l := New(discardHandler{disabled: true})
+		s := "abc"
+		i := 2000
+		wantAllocs(t, 2, func() {
+			l.Log(ctx, LevelInfo, "hello",
+				"n", i,
+				"s", s,
+			)
+		})
+	})
+	t.Run("2 pairs disabled", func(t *testing.T) {
+		l := New(discardHandler{disabled: true})
+		s := "abc"
+		i := 2000
+		wantAllocs(t, 0, func() {
+			if l.Enabled(ctx, LevelInfo) {
+				l.Log(ctx, LevelInfo, "hello",
+					"n", i,
+					"s", s,
+				)
+			}
+		})
+	})
+	t.Run("9 kvs", func(t *testing.T) {
+		s := "abc"
+		i := 2000
+		d := time.Second
+		wantAllocs(t, 11, func() {
+			dl.Info("hello",
+				"n", i, "s", s, "d", d,
+				"n", i, "s", s, "d", d,
+				"n", i, "s", s, "d", d)
+		})
+	})
+	t.Run("pairs", func(t *testing.T) {
+		wantAllocs(t, 0, func() { dl.Info("", "error", io.EOF) })
+	})
+	t.Run("attrs1", func(t *testing.T) {
+		wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Int("a", 1)) })
+		wantAllocs(t, 0, func() { dl.LogAttrs(ctx, LevelInfo, "", Any("error", io.EOF)) })
+	})
+	t.Run("attrs3", func(t *testing.T) {
+		wantAllocs(t, 0, func() {
+			dl.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
+		})
+	})
+	t.Run("attrs3 disabled", func(t *testing.T) {
+		logger := New(discardHandler{disabled: true})
+		wantAllocs(t, 0, func() {
+			logger.LogAttrs(ctx, LevelInfo, "hello", Int("a", 1), String("b", "two"), Duration("c", time.Second))
+		})
+	})
+	t.Run("attrs6", func(t *testing.T) {
+		wantAllocs(t, 1, func() {
+			dl.LogAttrs(ctx, LevelInfo, "hello",
+				Int("a", 1), String("b", "two"), Duration("c", time.Second),
+				Int("d", 1), String("e", "two"), Duration("f", time.Second))
+		})
+	})
+	t.Run("attrs9", func(t *testing.T) {
+		wantAllocs(t, 1, func() {
+			dl.LogAttrs(ctx, LevelInfo, "hello",
+				Int("a", 1), String("b", "two"), Duration("c", time.Second),
+				Int("d", 1), String("e", "two"), Duration("f", time.Second),
+				Int("d", 1), String("e", "two"), Duration("f", time.Second))
+		})
+	})
+}
+
+func TestSetAttrs(t *testing.T) {
+	for _, test := range []struct {
+		args []any
+		want []Attr
+	}{
+		{nil, nil},
+		{[]any{"a", 1}, []Attr{Int("a", 1)}},
+		{[]any{"a", 1, "b", "two"}, []Attr{Int("a", 1), String("b", "two")}},
+		{[]any{"a"}, []Attr{String(badKey, "a")}},
+		{[]any{"a", 1, "b"}, []Attr{Int("a", 1), String(badKey, "b")}},
+		{[]any{"a", 1, 2, 3}, []Attr{Int("a", 1), Int(badKey, 2), Int(badKey, 3)}},
+	} {
+		r := NewRecord(time.Time{}, 0, "", 0)
+		r.Add(test.args...)
+		got := attrsSlice(r)
+		if !attrsEqual(got, test.want) {
+			t.Errorf("%v:\ngot  %v\nwant %v", test.args, got, test.want)
+		}
+	}
+}
+
+func TestSetDefault(t *testing.T) {
+	// Verify that setting the default to itself does not result in deadlock.
+	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+	defer cancel()
+	defer func(w io.Writer) { log.SetOutput(w) }(log.Writer())
+	log.SetOutput(io.Discard)
+	go func() {
+		Info("A")
+		SetDefault(Default())
+		Info("B")
+		cancel()
+	}()
+	<-ctx.Done()
+	if err := ctx.Err(); err != context.Canceled {
+		t.Errorf("wanted canceled, got %v", err)
+	}
+}
+
+func TestLoggerError(t *testing.T) {
+	var buf bytes.Buffer
+
+	removeTime := func(_ []string, a Attr) Attr {
+		if a.Key == TimeKey {
+			return Attr{}
+		}
+		return a
+	}
+	l := New(NewTextHandler(&buf, &HandlerOptions{ReplaceAttr: removeTime}))
+	l.Error("msg", "err", io.EOF, "a", 1)
+	checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF a=1`)
+	buf.Reset()
+	// use local var 'args' to defeat vet check
+	args := []any{"err", io.EOF, "a"}
+	l.Error("msg", args...)
+	checkLogOutput(t, buf.String(), `level=ERROR msg=msg err=EOF !BADKEY=a`)
+}
+
+func TestNewLogLogger(t *testing.T) {
+	var buf bytes.Buffer
+	h := NewTextHandler(&buf, nil)
+	ll := NewLogLogger(h, LevelWarn)
+	ll.Print("hello")
+	checkLogOutput(t, buf.String(), "time="+timeRE+` level=WARN msg=hello`)
+}
+
+func TestLoggerNoOps(t *testing.T) {
+	l := Default()
+	if l.With() != l {
+		t.Error("wanted receiver, didn't get it")
+	}
+	if With() != l {
+		t.Error("wanted receiver, didn't get it")
+	}
+	if l.WithGroup("") != l {
+		t.Error("wanted receiver, didn't get it")
+	}
+}
+
+func TestContext(t *testing.T) {
+	// Verify that the context argument to log output methods is passed to the handler.
+	// Also check the level.
+	h := &captureHandler{}
+	l := New(h)
+	defer SetDefault(Default()) // restore
+	SetDefault(l)
+
+	for _, test := range []struct {
+		f         func(context.Context, string, ...any)
+		wantLevel Level
+	}{
+		{l.DebugContext, LevelDebug},
+		{l.InfoContext, LevelInfo},
+		{l.WarnContext, LevelWarn},
+		{l.ErrorContext, LevelError},
+		{DebugContext, LevelDebug},
+		{InfoContext, LevelInfo},
+		{WarnContext, LevelWarn},
+		{ErrorContext, LevelError},
+	} {
+		h.clear()
+		ctx := context.WithValue(context.Background(), "L", test.wantLevel)
+
+		test.f(ctx, "msg")
+		if gv := h.ctx.Value("L"); gv != test.wantLevel || h.r.Level != test.wantLevel {
+			t.Errorf("got context value %v, level %s; want %s for both", gv, h.r.Level, test.wantLevel)
+		}
+	}
+}
+
+func checkLogOutput(t *testing.T, got, wantRegexp string) {
+	t.Helper()
+	got = clean(got)
+	wantRegexp = "^" + wantRegexp + "$"
+	matched, err := regexp.MatchString(wantRegexp, got)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !matched {
+		t.Errorf("\ngot  %s\nwant %s", got, wantRegexp)
+	}
+}
+
+// clean prepares log output for comparison.
+func clean(s string) string {
+	if len(s) > 0 && s[len(s)-1] == '\n' {
+		s = s[:len(s)-1]
+	}
+	return strings.ReplaceAll(s, "\n", "~")
+}
+
+type captureHandler struct {
+	mu     sync.Mutex
+	ctx    context.Context
+	r      Record
+	attrs  []Attr
+	groups []string
+}
+
+func (h *captureHandler) Handle(ctx context.Context, r Record) error {
+	h.mu.Lock()
+	defer h.mu.Unlock()
+	h.ctx = ctx
+	h.r = r
+	return nil
+}
+
+func (*captureHandler) Enabled(context.Context, Level) bool { return true }
+
+func (c *captureHandler) WithAttrs(as []Attr) Handler {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	var c2 captureHandler
+	c2.r = c.r
+	c2.groups = c.groups
+	c2.attrs = concat(c.attrs, as)
+	return &c2
+}
+
+func (c *captureHandler) WithGroup(name string) Handler {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	var c2 captureHandler
+	c2.r = c.r
+	c2.attrs = c.attrs
+	c2.groups = append(slices.Clip(c.groups), name)
+	return &c2
+}
+
+func (c *captureHandler) clear() {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	c.ctx = nil
+	c.r = Record{}
+}
+
+type discardHandler struct {
+	disabled bool
+	attrs    []Attr
+}
+
+func (d discardHandler) Enabled(context.Context, Level) bool { return !d.disabled }
+func (discardHandler) Handle(context.Context, Record) error  { return nil }
+func (d discardHandler) WithAttrs(as []Attr) Handler {
+	d.attrs = concat(d.attrs, as)
+	return d
+}
+func (h discardHandler) WithGroup(name string) Handler {
+	return h
+}
+
+// concat returns a new slice with the elements of s1 followed
+// by those of s2. The slice has no additional capacity.
+func concat[T any](s1, s2 []T) []T {
+	s := make([]T, len(s1)+len(s2))
+	copy(s, s1)
+	copy(s[len(s1):], s2)
+	return s
+}
+
+// This is a simple benchmark. See the benchmarks subdirectory for more extensive ones.
+func BenchmarkNopLog(b *testing.B) {
+	ctx := context.Background()
+	l := New(&captureHandler{})
+	b.Run("no attrs", func(b *testing.B) {
+		b.ReportAllocs()
+		for i := 0; i < b.N; i++ {
+			l.LogAttrs(ctx, LevelInfo, "msg")
+		}
+	})
+	b.Run("attrs", func(b *testing.B) {
+		b.ReportAllocs()
+		for i := 0; i < b.N; i++ {
+			l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
+		}
+	})
+	b.Run("attrs-parallel", func(b *testing.B) {
+		b.ReportAllocs()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
+			}
+		})
+	})
+	b.Run("keys-values", func(b *testing.B) {
+		b.ReportAllocs()
+		for i := 0; i < b.N; i++ {
+			l.Log(ctx, LevelInfo, "msg", "a", 1, "b", "two", "c", true)
+		}
+	})
+	b.Run("WithContext", func(b *testing.B) {
+		b.ReportAllocs()
+		for i := 0; i < b.N; i++ {
+			l.LogAttrs(ctx, LevelInfo, "msg2", Int("a", 1), String("b", "two"), Bool("c", true))
+		}
+	})
+	b.Run("WithContext-parallel", func(b *testing.B) {
+		b.ReportAllocs()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				l.LogAttrs(ctx, LevelInfo, "msg", Int("a", 1), String("b", "two"), Bool("c", true))
+			}
+		})
+	})
+}
+
+// callerPC returns the program counter at the given stack depth.
+func callerPC(depth int) uintptr {
+	var pcs [1]uintptr
+	runtime.Callers(depth, pcs[:])
+	return pcs[0]
+}
+
+func wantAllocs(t *testing.T, want int, f func()) {
+	if race.Enabled {
+		t.Skip("skipping test in race mode")
+	}
+	testenv.SkipIfOptimizationOff(t)
+	t.Helper()
+	got := int(testing.AllocsPerRun(5, f))
+	if got != want {
+		t.Errorf("got %d allocs, want %d", got, want)
+	}
+}