From 35ded09102db8ce0b2eba3e87f54ba6ce14f2359 Mon Sep 17 00:00:00 2001 From: arukiidou Date: Tue, 6 Feb 2024 02:59:30 +0900 Subject: [PATCH] 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. https://github.com/arukiidou/zap/pull/1 - This also works in Go 1.22 --------- Signed-off-by: junya koyama Co-authored-by: Abhinav Gupta --- exp/zapslog/handler.go | 62 ++++++++-- exp/zapslog/handler_test.go | 230 +++++++++++++++++++++++++++++++++++- 2 files changed, 281 insertions(+), 11 deletions(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 982d9bccd..f893455a9 100644 --- a/exp/zapslog/handler.go +++ b/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 --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 68339df62..a40d59f56 100644 --- a/exp/zapslog/handler_test.go +++ b/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") +}