zapslog: fix all with slogtest, support inline group, ignore empty group. (#1408)

This change adds a test based on testing/slogtest
that verifies compliance with the slog handler contract
(a draft of this was available in #1335),
and fixes all resulting issues.

The two remaining issues were:

- `Group("", attrs)` should inline the new fields
  instead of creating a group with an empty name.
  This was fixed with the use of `zap.Inline`.
- Groups without any attributes should not be created.
  That is, `logger.WithGroup("foo").Info("bar")` should not
  create an empty "foo" namespace (`"foo": {}`).
  This was fixed by keeping track of unapplied groups
  and applying them the first time a field is serialized.

Following this change, slogtest passes as expected.

Refs #1333
Resolves #1334, #1401, #1402
Supersedes #1263, #1335

### TESTS

- passed. arukiidou#1
- This also works in Go 1.22

---------

Signed-off-by: junya koyama <[email protected]>
Co-authored-by: Abhinav Gupta <[email protected]>

Author: arukiidou

Diff for: exp/zapslog/handler.go

@@ -39,6 +39,13 @@ type Handler struct {
 	addCaller  bool
 	addStackAt slog.Level
 	callerSkip int
+
+	// List of unapplied groups.
+	//
+	// These are applied only if we encounter a real field
+	// to avoid creating empty namespaces -- which is disallowed by slog's
+	// usage contract.
+	groups []string
 }
 
 // NewHandler builds a [Handler] that writes to the supplied [zapcore.Core]
@@ -88,6 +95,10 @@ func convertAttrToField(attr slog.Attr) zapcore.Field {
 	case slog.KindUint64:
 		return zap.Uint64(attr.Key, attr.Value.Uint64())
 	case slog.KindGroup:
+		if attr.Key == "" {
+			// Inlines recursively.
+			return zap.Inline(groupObject(attr.Value.Group()))
+		}
 		return zap.Object(attr.Key, groupObject(attr.Value.Group()))
 	case slog.KindLogValuer:
 		return convertAttrToField(slog.Attr{
@@ -157,34 +168,65 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error {
 		ce.Stack = stacktrace.Take(3 + h.callerSkip)
 	}
 
-	fields := make([]zapcore.Field, 0, record.NumAttrs())
+	fields := make([]zapcore.Field, 0, record.NumAttrs()+len(h.groups))
+
+	var addedNamespace bool
 	record.Attrs(func(attr slog.Attr) bool {
-		fields = append(fields, convertAttrToField(attr))
+		f := convertAttrToField(attr)
+		if !addedNamespace && len(h.groups) > 0 && f != zap.Skip() {
+			// Namespaces are added only if at least one field is present
+			// to avoid creating empty groups.
+			fields = h.appendGroups(fields)
+			addedNamespace = true
+		}
+		fields = append(fields, f)
 		return true
 	})
+
 	ce.Write(fields...)
 	return nil
 }
 
+func (h *Handler) appendGroups(fields []zapcore.Field) []zapcore.Field {
+	for _, g := range h.groups {
+		fields = append(fields, zap.Namespace(g))
+	}
+	return fields
+}
+
 // WithAttrs returns a new Handler whose attributes consist of
 // both the receiver's attributes and the arguments.
 func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
-	fields := make([]zapcore.Field, 0, len(attrs))
+	fields := make([]zapcore.Field, 0, len(attrs)+len(h.groups))
+	var addedNamespace bool
 	for _, attr := range attrs {
-		fields = append(fields, convertAttrToField(attr))
+		f := convertAttrToField(attr)
+		if !addedNamespace && len(h.groups) > 0 && f != zap.Skip() {
+			// Namespaces are added only if at least one field is present
+			// to avoid creating empty groups.
+			fields = h.appendGroups(fields)
+			addedNamespace = true
+		}
+		fields = append(fields, f)
+	}
+
+	cloned := *h
+	cloned.core = h.core.With(fields)
+	if addedNamespace {
+		// These groups have been applied so we can clear them.
+		cloned.groups = nil
 	}
-	return h.withFields(fields...)
+	return &cloned
 }
 
 // WithGroup returns a new Handler with the given group appended to
 // the receiver's existing groups.
 func (h *Handler) WithGroup(group string) slog.Handler {
-	return h.withFields(zap.Namespace(group))
-}
+	newGroups := make([]string, len(h.groups)+1)
+	copy(newGroups, h.groups)
+	newGroups[len(h.groups)] = group
 
-// withFields returns a cloned Handler with the given fields.
-func (h *Handler) withFields(fields ...zapcore.Field) *Handler {
 	cloned := *h
-	cloned.core = h.core.With(fields)
+	cloned.groups = newGroups
 	return &cloned
 }

Diff for: exp/zapslog/handler_test.go

@@ -23,13 +23,18 @@
 package zapslog
 
 import (
+	"bytes"
+	"encoding/json"
 	"log/slog"
+	"sync"
 	"testing"
+	"testing/slogtest"
 	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest"
 	"go.uber.org/zap/zaptest/observer"
 )
 
@@ -128,8 +133,8 @@ func TestEmptyAttr(t *testing.T) {
 }
 
 func TestWithName(t *testing.T) {
-	t.Parallel()
 	fac, observedLogs := observer.New(zapcore.DebugLevel)
+
 	t.Run("default", func(t *testing.T) {
 		sl := slog.New(NewHandler(fac))
 		sl.Info("msg")
@@ -150,6 +155,191 @@ func TestWithName(t *testing.T) {
 	})
 }
 
+func TestInlineGroup(t *testing.T) {
+	fac, observedLogs := observer.New(zapcore.DebugLevel)
+
+	t.Run("simple", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.Info("msg", "a", "b", slog.Group("", slog.String("c", "d")), "e", "f")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{
+			"a": "b",
+			"c": "d",
+			"e": "f",
+		}, logs[0].ContextMap(), "Unexpected context")
+	})
+
+	t.Run("recursive", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.Info("msg", "a", "b", slog.Group("", slog.Group("", slog.Group("", slog.String("c", "d"))), slog.Group("", "e", "f")))
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{
+			"a": "b",
+			"c": "d",
+			"e": "f",
+		}, logs[0].ContextMap(), "Unexpected context")
+	})
+}
+
+func TestWithGroup(t *testing.T) {
+	fac, observedLogs := observer.New(zapcore.DebugLevel)
+
+	// Groups can be nested inside each other.
+	t.Run("nested", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.With("a", "b").WithGroup("G").WithGroup("in").Info("msg", "c", "d")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{
+			"G": map[string]any{
+				"in": map[string]any{
+					"c": "d",
+				},
+			},
+			"a": "b",
+		}, logs[0].ContextMap(), "Unexpected context")
+	})
+
+	t.Run("nested empty", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.With("a", "b").WithGroup("G").WithGroup("in").Info("msg")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{
+			"a": "b",
+		}, logs[0].ContextMap(), "Unexpected context")
+	})
+
+	t.Run("empty group", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{
+			"G": map[string]any{
+				"c": "d",
+			},
+			"a": "b",
+		}, logs[0].ContextMap(), "Unexpected context")
+	})
+
+	t.Run("skipped field", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac))
+		sl.WithGroup("H").With(slog.Attr{}).Info("msg")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 1, "Expected exactly one entry to be logged")
+		assert.Equal(t, map[string]any{}, logs[0].ContextMap(), "Unexpected context")
+	})
+
+	t.Run("reuse", func(t *testing.T) {
+		sl := slog.New(NewHandler(fac)).WithGroup("G")
+
+		sl.With("a", "b").Info("msg1", "c", "d")
+		sl.With("e", "f").Info("msg2", "g", "h")
+
+		logs := observedLogs.TakeAll()
+		require.Len(t, logs, 2, "Expected exactly two entries to be logged")
+
+		assert.Equal(t, map[string]any{
+			"G": map[string]any{
+				"a": "b",
+				"c": "d",
+			},
+		}, logs[0].ContextMap(), "Unexpected context")
+		assert.Equal(t, "msg1", logs[0].Message, "Unexpected message")
+
+		assert.Equal(t, map[string]any{
+			"G": map[string]any{
+				"e": "f",
+				"g": "h",
+			},
+		}, logs[1].ContextMap(), "Unexpected context")
+		assert.Equal(t, "msg2", logs[1].Message, "Unexpected message")
+	})
+}
+
+// Run a few different loggers with concurrent logs
+// in an attempt to trip up 'go test -race' and discover any data races.
+func TestConcurrentLogs(t *testing.T) {
+	t.Parallel()
+
+	const (
+		NumWorkers = 10
+		NumLogs    = 100
+	)
+
+	tests := []struct {
+		name         string
+		buildHandler func(zapcore.Core) slog.Handler
+	}{
+		{
+			name: "default",
+			buildHandler: func(core zapcore.Core) slog.Handler {
+				return NewHandler(core)
+			},
+		},
+		{
+			name: "grouped",
+			buildHandler: func(core zapcore.Core) slog.Handler {
+				return NewHandler(core).WithGroup("G")
+			},
+		},
+		{
+			name: "named",
+			buildHandler: func(core zapcore.Core) slog.Handler {
+				return NewHandler(core, WithName("test-name"))
+			},
+		},
+	}
+
+	for _, tt := range tests {
+		tt := tt
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			fac, observedLogs := observer.New(zapcore.DebugLevel)
+			sl := slog.New(tt.buildHandler(fac))
+
+			// Use two wait groups to coordinate the workers:
+			//
+			// - ready: indicates when all workers should start logging.
+			// - done: indicates when all workers have finished logging.
+			var ready, done sync.WaitGroup
+			ready.Add(NumWorkers)
+			done.Add(NumWorkers)
+
+			for i := 0; i < NumWorkers; i++ {
+				i := i
+				go func() {
+					defer done.Done()
+
+					ready.Done() // I'm ready.
+					ready.Wait() // Are others?
+
+					for j := 0; j < NumLogs; j++ {
+						sl.Info("msg", "worker", i, "log", j)
+					}
+				}()
+			}
+
+			done.Wait()
+
+			// Ensure that all logs were recorded.
+			logs := observedLogs.TakeAll()
+			assert.Len(t, logs, NumWorkers*NumLogs,
+				"Wrong number of logs recorded")
+		})
+	}
+}
+
 type Token string
 
 func (Token) LogValue() slog.Value {
@@ -189,3 +379,41 @@ func TestAttrKinds(t *testing.T) {
 		},
 		entry.ContextMap())
 }
+
+func TestSlogtest(t *testing.T) {
+	var buff bytes.Buffer
+	core := zapcore.NewCore(
+		zapcore.NewJSONEncoder(zapcore.EncoderConfig{
+			TimeKey:     slog.TimeKey,
+			MessageKey:  slog.MessageKey,
+			LevelKey:    slog.LevelKey,
+			EncodeLevel: zapcore.CapitalLevelEncoder,
+			EncodeTime:  zapcore.RFC3339TimeEncoder,
+		}),
+		zapcore.AddSync(&buff),
+		zapcore.DebugLevel,
+	)
+
+	// zaptest doesn't expose the underlying core,
+	// so we'll extract it from the logger.
+	testCore := zaptest.NewLogger(t).Core()
+
+	handler := NewHandler(zapcore.NewTee(core, testCore))
+	err := slogtest.TestHandler(
+		handler,
+		func() []map[string]any {
+			// Parse the newline-delimted JSON in buff.
+			var entries []map[string]any
+
+			dec := json.NewDecoder(bytes.NewReader(buff.Bytes()))
+			for dec.More() {
+				var ent map[string]any
+				require.NoError(t, dec.Decode(&ent), "Error decoding log message")
+				entries = append(entries, ent)
+			}
+
+			return entries
+		},
+	)
+	require.NoError(t, err, "Unexpected error from slogtest.TestHandler")
+}