slog: backport changes from stdlib

The standard library version of slog has diverged from this
version somewhat; bring them back into sync, as much as possible.

Since moving to the standard library, a Handler rule has changed: a
Handler should ignore the zero slog.Attr, but not an Attr whose key is
empty but whose value is non-zero. Change the check in slogtest to
reflect that.

Fixes golang/go#59727.

Change-Id: Idd2084b84a3faf9b1796051af1578aee6558ed02
Reviewed-on: https://go-review.googlesource.com/c/exp/+/486795
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>

Author: jba

slog/attr.go

@@ -82,3 +82,9 @@ func (a Attr) Equal(b Attr) bool {
 func (a Attr) String() string {
 	return fmt.Sprintf("%s=%s", a.Key, a.Value)
 }
+
+// isEmpty reports whether a has an empty key and a nil value.
+// That can be written as Attr{} or Any("", nil).
+func (a Attr) isEmpty() bool {
+	return a.Key == "" && a.Value.num == 0 && a.Value.any == nil
+}

slog/benchmarks/handlers.go

@@ -48,11 +48,12 @@ func (h *fastTextHandler) Handle(_ context.Context, r slog.Record) error {
 	buf.WriteByte(' ')
 	buf.WriteString("msg=")
 	buf.WriteString(r.Message)
-	r.Attrs(func(a slog.Attr) {
+	r.Attrs(func(a slog.Attr) bool {
 		buf.WriteByte(' ')
 		buf.WriteString(a.Key)
 		buf.WriteByte('=')
 		h.appendValue(buf, a.Value)
+		return true
 	})
 	buf.WriteByte('\n')
 	_, err := h.w.Write(*buf)

slog/benchmarks/handlers_test.go

@@ -38,6 +38,6 @@ func TestHandlers(t *testing.T) {
 
 func attrSlice(r slog.Record) []slog.Attr {
 	var as []slog.Attr
-	r.Attrs(func(a slog.Attr) { as = append(as, a) })
+	r.Attrs(func(a slog.Attr) bool { as = append(as, a); return true })
 	return as
 }

slog/example_depth_test.go renamed to slog/example_wrap_test.go

@@ -17,24 +17,21 @@ import (
 
 // Infof is an example of a user-defined logging function that wraps slog.
 // The log record contains the source position of the caller of Infof.
-func Infof(format string, args ...any) {
-	l := slog.Default()
-	if !l.Enabled(context.Background(), slog.LevelInfo) {
+func Infof(logger *slog.Logger, format string, args ...any) {
+	if !logger.Enabled(context.Background(), slog.LevelInfo) {
 		return
 	}
 	var pcs [1]uintptr
 	runtime.Callers(2, pcs[:]) // skip [Callers, Infof]
 	r := slog.NewRecord(time.Now(), slog.LevelInfo, fmt.Sprintf(format, args...), pcs[0])
-	_ = l.Handler().Handle(context.Background(), r)
+	_ = logger.Handler().Handle(context.Background(), r)
 }
 
 func Example_wrapping() {
-	defer func(l *slog.Logger) { slog.SetDefault(l) }(slog.Default())
-
 	replace := func(groups []string, a slog.Attr) slog.Attr {
 		// Remove time.
 		if a.Key == slog.TimeKey && len(groups) == 0 {
-			a.Key = ""
+			return slog.Attr{}
 		}
 		// Remove the directory from the source's filename.
 		if a.Key == slog.SourceKey {
@@ -43,9 +40,8 @@ func Example_wrapping() {
 		return a
 	}
 	logger := slog.New(slog.HandlerOptions{AddSource: true, ReplaceAttr: replace}.NewTextHandler(os.Stdout))
-	slog.SetDefault(logger)
-	Infof("message, %s", "formatted")
+	Infof(logger, "message, %s", "formatted")
 
 	// Output:
-	// level=INFO source=example_depth_test.go:47 msg="message, formatted"
+	// level=INFO source=example_wrap_test.go:43 msg="message, formatted"
 }

slog/handler.go

@@ -51,8 +51,9 @@ type Handler interface {
 	// Handle methods that produce output should observe the following rules:
 	//   - If r.Time is the zero time, ignore the time.
 	//   - If r.PC is zero, ignore it.
-	//   - If an Attr's key is the empty string and the value is not a group,
-	//     ignore the Attr.
+	//   - Attr's values should be resolved.
+	//   - If an Attr's key and value are both the zero value, ignore the Attr.
+	//     This can be tested with attr.Equal(Attr{}).
 	//   - If a group's key is empty, inline the group's Attrs.
 	//   - If a group has no Attrs (even if it has a non-empty key),
 	//     ignore it.
@@ -61,7 +62,6 @@ type Handler interface {
 	// WithAttrs returns a new Handler whose attributes consist of
 	// both the receiver's attributes and the arguments.
 	// The Handler owns the slice: it may retain, modify or discard it.
-	// [Logger.With] will resolve the Attrs.
 	WithAttrs(attrs []Attr) Handler
 
 	// WithGroup returns a new Handler with the given group appended to
@@ -333,8 +333,9 @@ func (s *handleState) appendNonBuiltIns(r Record) {
 	defer s.prefix.Free()
 	s.prefix.WriteString(s.h.groupPrefix)
 	s.openGroups()
-	r.Attrs(func(a Attr) {
+	r.Attrs(func(a Attr) bool {
 		s.appendAttr(a)
+		return true
 	})
 	if s.h.json {
 		// Close all open groups.
@@ -440,26 +441,22 @@ func (s *handleState) closeGroup(name string) {
 // It handles replacement and checking for an empty key.
 // after replacement).
 func (s *handleState) appendAttr(a Attr) {
-	v := a.Value
-	// Elide a non-group with an empty key.
-	if a.Key == "" && v.Kind() != KindGroup {
-		return
-	}
-	if rep := s.h.opts.ReplaceAttr; rep != nil && v.Kind() != KindGroup {
+	if rep := s.h.opts.ReplaceAttr; rep != nil && a.Value.Kind() != KindGroup {
 		var gs []string
 		if s.groups != nil {
 			gs = *s.groups
 		}
-		a = rep(gs, Attr{a.Key, v})
-		if a.Key == "" {
-			return
-		}
-		// Although all attributes in the Record are already resolved,
-		// This one came from the user, so it may not have been.
-		v = a.Value.Resolve()
+		// Resolve before calling ReplaceAttr, so the user doesn't have to.
+		a.Value = a.Value.Resolve()
+		a = rep(gs, a)
+	}
+	a.Value = a.Value.Resolve()
+	// Elide empty Attrs.
+	if a.isEmpty() {
+		return
 	}
-	if v.Kind() == KindGroup {
-		attrs := v.Group()
+	if a.Value.Kind() == KindGroup {
+		attrs := a.Value.Group()
 		// Output only non-empty groups.
 		if len(attrs) > 0 {
 			// Inline a group with an empty key.
@@ -475,7 +472,7 @@ func (s *handleState) appendAttr(a Attr) {
 		}
 	} else {
 		s.appendKey(a.Key)
-		s.appendValue(v)
+		s.appendValue(a.Value)
 	}
 }
 

slog/handler_test.go

@@ -109,12 +109,10 @@ func TestDefaultHandle(t *testing.T) {
 func TestJSONAndTextHandlers(t *testing.T) {
 	ctx := context.Background()
 
-	// ReplaceAttr functions
-
 	// remove all Attrs
 	removeAll := func(_ []string, a Attr) Attr { return Attr{} }
 
-	attrs := []Attr{String("a", "one"), Int("b", 2), Any("", "ignore me")}
+	attrs := []Attr{String("a", "one"), Int("b", 2), Any("", nil)}
 	preAttrs := []Attr{Int("pre", 3), String("x", "y")}
 
 	for _, test := range []struct {
@@ -132,6 +130,12 @@ func TestJSONAndTextHandlers(t *testing.T) {
 			wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2",
 			wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2}`,
 		},
+		{
+			name:     "empty key",
+			attrs:    append(slices.Clip(attrs), Any("", "v")),
+			wantText: `time=2000-01-02T03:04:05.000Z level=INFO msg=message a=one b=2 ""=v`,
+			wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","a":"one","b":2,"":"v"}`,
+		},
 		{
 			name:     "cap keys",
 			replace:  upperCaseKey,
@@ -231,6 +235,16 @@ func TestJSONAndTextHandlers(t *testing.T) {
 			wantText: "msg=message a=1 name.first=Ren name.last=Hoek b=2",
 			wantJSON: `{"msg":"message","a":1,"name":{"first":"Ren","last":"Hoek"},"b":2}`,
 		},
+		{
+			// Test resolution when there is no ReplaceAttr function.
+			name: "resolve",
+			attrs: []Attr{
+				Any("", &replace{Value{}}), // should be elided
+				Any("name", logValueName{"Ren", "Hoek"}),
+			},
+			wantText: "time=2000-01-02T03:04:05.000Z level=INFO msg=message name.first=Ren name.last=Hoek",
+			wantJSON: `{"time":"2000-01-02T03:04:05Z","level":"INFO","msg":"message","name":{"first":"Ren","last":"Hoek"}}`,
+		},
 		{
 			name:     "with-group",
 			replace:  removeKeys(TimeKey, LevelKey),
@@ -297,7 +311,7 @@ func TestJSONAndTextHandlers(t *testing.T) {
 			wantJSON: `{"msg":"message","a":1,"b":2,"c":3,"d":4}`,
 		},
 	} {
-		r := NewRecord(testTime, LevelInfo, "message", 1)
+		r := NewRecord(testTime, LevelInfo, "message", 0)
 		r.AddAttrs(test.attrs...)
 		var buf bytes.Buffer
 		opts := HandlerOptions{ReplaceAttr: test.replace}

slog/internal/testutil/testutil.go

@@ -12,7 +12,7 @@ import "golang.org/x/exp/slog"
 // to make example output deterministic.
 func RemoveTime(groups []string, a slog.Attr) slog.Attr {
 	if a.Key == slog.TimeKey && len(groups) == 0 {
-		a.Key = ""
+		return slog.Attr{}
 	}
 	return a
 }

slog/json_handler.go

@@ -80,7 +80,7 @@ func (h *JSONHandler) WithGroup(name string) Handler {
 // Values are formatted as with encoding/json.Marshal, with the following
 // exceptions:
 //   - Floating-point NaNs and infinities are formatted as one of the strings
-//     "NaN", "+Inf" or "-Inf".
+//     "NaN", "Infinity" or "-Infinity".
 //   - Levels are formatted as with Level.String.
 //   - HTML characters are not escaped.
 //
@@ -114,9 +114,9 @@ func appendJSONValue(s *handleState, v Value) error {
 		// json.Marshal fails on special floats, so handle them here.
 		switch {
 		case math.IsInf(f, 1):
-			s.buf.WriteString(`"+Inf"`)
+			s.buf.WriteString(`"Infinity"`)
 		case math.IsInf(f, -1):
-			s.buf.WriteString(`"-Inf"`)
+			s.buf.WriteString(`"-Infinity"`)
 		case math.IsNaN(f):
 			s.buf.WriteString(`"NaN"`)
 		default:
@@ -136,13 +136,14 @@ func appendJSONValue(s *handleState, v Value) error {
 		s.appendTime(v.Time())
 	case KindAny:
 		a := v.Any()
-		if err, ok := a.(error); ok {
+		_, jm := a.(json.Marshaler)
+		if err, ok := a.(error); ok && !jm {
 			s.appendString(err.Error())
 		} else {
 			return appendJSONMarshal(s.buf, a)
 		}
 	default:
-		panic(fmt.Sprintf("bad kind: %d", v.Kind()))
+		panic(fmt.Sprintf("bad kind: %s", v.Kind()))
 	}
 	return nil
 }

slog/json_handler_test.go

@@ -13,6 +13,7 @@ import (
 	"io"
 	"math"
 	"os"
+	"path/filepath"
 	"strings"
 	"testing"
 	"time"
@@ -67,6 +68,12 @@ func (j jsonMarshaler) MarshalJSON() ([]byte, error) {
 	return []byte(fmt.Sprintf(`[%q]`, j.s)), nil
 }
 
+type jsonMarshalerError struct {
+	jsonMarshaler
+}
+
+func (jsonMarshalerError) Error() string { return "oops" }
+
 func TestAppendJSONValue(t *testing.T) {
 	// On most values, jsonAppendAttrValue should agree with json.Marshal.
 	for _, value := range []any{
@@ -82,6 +89,7 @@ func TestAppendJSONValue(t *testing.T) {
 		time.Minute,
 		testTime,
 		jsonMarshaler{"xyz"},
+		jsonMarshalerError{jsonMarshaler{"pqr"}},
 	} {
 		got := jsonValueString(t, AnyValue(value))
 		want, err := marshalJSON(value)
@@ -111,8 +119,8 @@ func TestJSONAppendAttrValueSpecial(t *testing.T) {
 		want  string
 	}{
 		{math.NaN(), `"NaN"`},
-		{math.Inf(+1), `"+Inf"`},
-		{math.Inf(-1), `"-Inf"`},
+		{math.Inf(+1), `"Infinity"`},
+		{math.Inf(-1), `"-Infinity"`},
 		{LevelWarn, `"WARN"`},
 	} {
 		got := jsonValueString(t, AnyValue(test.value))
@@ -202,7 +210,7 @@ func BenchmarkPreformatting(b *testing.B) {
 		}),
 	}
 
-	outFile, err := os.Create("/tmp/bench.log")
+	outFile, err := os.Create(filepath.Join(b.TempDir(), "bench.log"))
 	if err != nil {
 		b.Fatal(err)
 	}

slog/logger.go

@@ -89,7 +89,7 @@ func (l *Logger) clone() *Logger {
 func (l *Logger) Handler() Handler { return l.handler }
 
 // With returns a new Logger that includes the given arguments, converted to
-// Attrs as in [Logger.Log] and resolved.
+// Attrs as in [Logger.Log].
 // The Attrs will be added to each output from the Logger.
 // The new Logger shares the old Logger's context.
 // The new Logger's handler is the result of calling WithAttrs on the receiver's
@@ -110,6 +110,8 @@ func (l *Logger) With(args ...any) *Logger {
 
 // WithGroup returns a new Logger that starts a group. The keys of all
 // attributes added to the Logger will be qualified by the given name.
+// (How that qualification happens depends on the [Handler.WithGroup]
+// method of the Logger's Handler.)
 // The new Logger shares the old Logger's context.
 //
 // The new Logger's handler is the result of calling WithGroup on the receiver's

slog/logger_test.go

@@ -13,6 +13,7 @@ import (
 	"regexp"
 	"runtime"
 	"strings"
+	"sync"
 	"testing"
 	"time"
 
@@ -398,27 +399,38 @@ func clean(s string) string {
 }
 
 type captureHandler struct {
+	mu     sync.Mutex
 	r      Record
 	attrs  []Attr
 	groups []string
 }
 
 func (h *captureHandler) Handle(ctx context.Context, r Record) error {
+	h.mu.Lock()
+	defer h.mu.Unlock()
 	h.r = r
 	return nil
 }
 
 func (*captureHandler) Enabled(context.Context, Level) bool { return true }
 
 func (c *captureHandler) WithAttrs(as []Attr) Handler {
-	c2 := *c
-	c2.attrs = concat(c2.attrs, as)
+	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 {
-	c2 := *c
-	c2.groups = append(slices.Clip(c2.groups), name)
+	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
 }