From e57554019b4bd70efa62e0dfff9af5307af4c97a Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sat, 3 Feb 2024 07:58:09 +0900 Subject: [PATCH 1/9] zapslog: inline group if empty key #1402 Signed-off-by: junya koyama --- exp/zapslog/handler.go | 4 ++++ exp/zapslog/handler_test.go | 33 +++++++++++++++++++++++++++++++++ 2 files changed, 37 insertions(+) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 982d9bccd..5abef1c0d 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -88,6 +88,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{ diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 68339df62..4011e3ae2 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -150,6 +150,39 @@ func TestWithName(t *testing.T) { }) } +func TestInlineGroup(t *testing.T) { + t.Parallel() + fac, observedLogs := observer.New(zapcore.DebugLevel) + t.Run("inline-group", 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") + entry := logs[0] + assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") + assert.Equal(t, map[string]any{ + "a": "b", + "c": "d", + "e": "f", + }, logs[0].ContextMap(), "Unexpected context") + }) + t.Run("inline-group-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") + entry := logs[0] + assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") + assert.Equal(t, map[string]any{ + "a": "b", + "c": "d", + "e": "f", + }, logs[0].ContextMap(), "Unexpected context") + }) +} + type Token string func (Token) LogValue() slog.Value { From 28b05cb63c318c9e27c80a22fb78efd64c6d2e2b Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sat, 3 Feb 2024 08:14:16 +0900 Subject: [PATCH 2/9] zapslog: Ignore groups if empty Record #1401 Signed-off-by: junya koyama --- exp/zapslog/handler.go | 26 ++++++++++++++++++++++---- exp/zapslog/handler_test.go | 30 ++++++++++++++++++++++++++++++ 2 files changed, 52 insertions(+), 4 deletions(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 5abef1c0d..591744423 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -26,6 +26,7 @@ import ( "context" "log/slog" "runtime" + "slices" "go.uber.org/zap" "go.uber.org/zap/internal/stacktrace" @@ -39,6 +40,7 @@ type Handler struct { addCaller bool addStackAt slog.Level callerSkip int + holdGroup string // holds latest group. } // NewHandler builds a [Handler] that writes to the supplied [zapcore.Core] @@ -161,11 +163,17 @@ 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()+1) record.Attrs(func(attr slog.Attr) bool { - fields = append(fields, convertAttrToField(attr)) + f := convertAttrToField(attr) + if h.holdGroup != "" && f != zap.Skip() { + fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + h.holdGroup = "" + } + fields = append(fields, f) return true }) + ce.Write(fields...) return nil } @@ -175,7 +183,12 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { fields := make([]zapcore.Field, 0, len(attrs)) for _, attr := range attrs { - fields = append(fields, convertAttrToField(attr)) + f := convertAttrToField(attr) + if h.holdGroup != "" && f != zap.Skip() { + fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + h.holdGroup = "" + } + fields = append(fields, f) } return h.withFields(fields...) } @@ -183,7 +196,12 @@ func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { // 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)) + cloned := *h + if h.holdGroup != "" { + cloned.core = h.core.With([]zapcore.Field{zap.Namespace(group)}) + } + cloned.holdGroup = group + return &cloned } // withFields returns a cloned Handler with the given fields. diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 4011e3ae2..2a02e7f34 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -183,6 +183,36 @@ func TestInlineGroup(t *testing.T) { }) } +func TestWithGroup(t *testing.T) { + t.Parallel() + fac, observedLogs := observer.New(zapcore.DebugLevel) + t.Run("empty-group-record", 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") + entry := logs[0] + assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") + assert.Equal(t, map[string]any{ + "G": map[string]any{ + "c": "d", + }, + "a": "b", + }, logs[0].ContextMap(), "Unexpected context") + }) + t.Run("only-records-to-ignore", 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") + entry := logs[0] + assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") + assert.Equal(t, map[string]any{}, logs[0].ContextMap(), "Unexpected context") + }) +} + type Token string func (Token) LogValue() slog.Value { From f09e134fcb97760c2b2f27bdc52dffdc63e53148 Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sat, 3 Feb 2024 08:16:32 +0900 Subject: [PATCH 3/9] zapslog: Test with slogtest, fix all failures #1334 Signed-off-by: junya koyama --- exp/zapslog/handler_test.go | 42 +++++++++++++++++++++++++++++++++++++ 1 file changed, 42 insertions(+) diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 2a02e7f34..67005d04a 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -23,13 +23,17 @@ package zapslog import ( + "bytes" + "encoding/json" "log/slog" "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" ) @@ -252,3 +256,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") +} From 104e04f3c1340f50f6b93dbee5b1680d12278742 Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sat, 3 Feb 2024 23:46:47 +0900 Subject: [PATCH 4/9] refactor: fixed inefficient []zapcore.Field insertion Signed-off-by: junya koyama --- exp/zapslog/handler.go | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 591744423..84f43539e 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -26,7 +26,6 @@ import ( "context" "log/slog" "runtime" - "slices" "go.uber.org/zap" "go.uber.org/zap/internal/stacktrace" @@ -167,7 +166,7 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { record.Attrs(func(attr slog.Attr) bool { f := convertAttrToField(attr) if h.holdGroup != "" && f != zap.Skip() { - fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + fields = append(fields, zap.Namespace(h.holdGroup)) h.holdGroup = "" } fields = append(fields, f) @@ -181,11 +180,11 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { // 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)+1) for _, attr := range attrs { f := convertAttrToField(attr) if h.holdGroup != "" && f != zap.Skip() { - fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + fields = append(fields, zap.Namespace(h.holdGroup)) h.holdGroup = "" } fields = append(fields, f) From baa935c7f992201eb1fc6c1dc455b8a2dfabea09 Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sun, 4 Feb 2024 22:24:17 +0900 Subject: [PATCH 5/9] zapslog: add test coverage - WithGroup in WithGroup Signed-off-by: junya koyama --- exp/zapslog/handler.go | 2 +- exp/zapslog/handler_test.go | 17 +++++++++++++++++ 2 files changed, 18 insertions(+), 1 deletion(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 84f43539e..6445aca5f 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -197,7 +197,7 @@ func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { func (h *Handler) WithGroup(group string) slog.Handler { cloned := *h if h.holdGroup != "" { - cloned.core = h.core.With([]zapcore.Field{zap.Namespace(group)}) + cloned.core = h.core.With([]zapcore.Field{zap.Namespace(h.holdGroup)}) } cloned.holdGroup = group return &cloned diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 67005d04a..67f41c776 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -190,6 +190,23 @@ func TestInlineGroup(t *testing.T) { func TestWithGroup(t *testing.T) { t.Parallel() fac, observedLogs := observer.New(zapcore.DebugLevel) + t.Run("group-in-group", 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") + entry := logs[0] + assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") + 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("empty-group-record", func(t *testing.T) { sl := slog.New(NewHandler(fac)) sl.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg") From e10aad114b3a3f579804690fde2fa95e0c68d55d Mon Sep 17 00:00:00 2001 From: junya koyama Date: Sun, 4 Feb 2024 23:36:53 +0900 Subject: [PATCH 6/9] zapslog: fix handler state management problems. Signed-off-by: junya koyama --- exp/zapslog/handler.go | 35 ++++++++++++++++++++++------------- 1 file changed, 22 insertions(+), 13 deletions(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index 6445aca5f..a29efbcff 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -26,6 +26,7 @@ import ( "context" "log/slog" "runtime" + "slices" "go.uber.org/zap" "go.uber.org/zap/internal/stacktrace" @@ -163,15 +164,19 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { } fields := make([]zapcore.Field, 0, record.NumAttrs()+1) + var addedNamespace bool record.Attrs(func(attr slog.Attr) bool { f := convertAttrToField(attr) - if h.holdGroup != "" && f != zap.Skip() { - fields = append(fields, zap.Namespace(h.holdGroup)) - h.holdGroup = "" + if !addedNamespace && f != zap.Skip() { + addedNamespace = true } fields = append(fields, f) return true }) + if h.holdGroup != "" && addedNamespace { + // group is before than other fields. + fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + } ce.Write(fields...) return nil @@ -181,31 +186,35 @@ func (h *Handler) Handle(ctx context.Context, record slog.Record) error { // both the receiver's attributes and the arguments. func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { fields := make([]zapcore.Field, 0, len(attrs)+1) + var addedNamespace bool for _, attr := range attrs { f := convertAttrToField(attr) - if h.holdGroup != "" && f != zap.Skip() { - fields = append(fields, zap.Namespace(h.holdGroup)) - h.holdGroup = "" + if !addedNamespace && f != zap.Skip() { + addedNamespace = true } fields = append(fields, f) } - return h.withFields(fields...) + if h.holdGroup != "" && addedNamespace { + // group is before than other fields. + fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) + return h.withFields("", fields...) + } + return h.withFields(h.holdGroup, fields...) } // WithGroup returns a new Handler with the given group appended to // the receiver's existing groups. func (h *Handler) WithGroup(group string) slog.Handler { - cloned := *h if h.holdGroup != "" { - cloned.core = h.core.With([]zapcore.Field{zap.Namespace(h.holdGroup)}) + return h.withFields(group, zap.Namespace(h.holdGroup)) } - cloned.holdGroup = group - return &cloned + return h.withFields(group) } -// withFields returns a cloned Handler with the given fields. -func (h *Handler) withFields(fields ...zapcore.Field) *Handler { +// withFields returns a cloned Handler with the given groups and fields. +func (h *Handler) withFields(newGroup string, fields ...zapcore.Field) *Handler { cloned := *h + cloned.holdGroup = newGroup cloned.core = h.core.With(fields) return &cloned } From b2e66d23f2df8cce4eb8fb89d0f103faf53dc71d Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Sun, 4 Feb 2024 10:21:28 -0800 Subject: [PATCH 7/9] test nits: Adjust test names, remove unnecessary LoggerName checks Logger name is already tested in WithName. It doesn't need to be duplicated in every test. --- exp/zapslog/handler_test.go | 29 +++++++++++------------------ 1 file changed, 11 insertions(+), 18 deletions(-) diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 67f41c776..b3f99be3e 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -132,8 +132,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") @@ -155,30 +155,27 @@ func TestWithName(t *testing.T) { } func TestInlineGroup(t *testing.T) { - t.Parallel() fac, observedLogs := observer.New(zapcore.DebugLevel) - t.Run("inline-group", func(t *testing.T) { + + 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") - entry := logs[0] - assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") assert.Equal(t, map[string]any{ "a": "b", "c": "d", "e": "f", }, logs[0].ContextMap(), "Unexpected context") }) - t.Run("inline-group-recursive", func(t *testing.T) { + + 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") - entry := logs[0] - assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") assert.Equal(t, map[string]any{ "a": "b", "c": "d", @@ -188,16 +185,15 @@ func TestInlineGroup(t *testing.T) { } func TestWithGroup(t *testing.T) { - t.Parallel() fac, observedLogs := observer.New(zapcore.DebugLevel) - t.Run("group-in-group", func(t *testing.T) { + + // 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") - entry := logs[0] - assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") assert.Equal(t, map[string]any{ "G": map[string]any{ "in": map[string]any{ @@ -207,14 +203,12 @@ func TestWithGroup(t *testing.T) { "a": "b", }, logs[0].ContextMap(), "Unexpected context") }) - t.Run("empty-group-record", func(t *testing.T) { + 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") - entry := logs[0] - assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") assert.Equal(t, map[string]any{ "G": map[string]any{ "c": "d", @@ -222,14 +216,13 @@ func TestWithGroup(t *testing.T) { "a": "b", }, logs[0].ContextMap(), "Unexpected context") }) - t.Run("only-records-to-ignore", func(t *testing.T) { + + 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") - entry := logs[0] - assert.Equal(t, "", entry.LoggerName, "Unexpected logger name") assert.Equal(t, map[string]any{}, logs[0].ContextMap(), "Unexpected context") }) } From 8ba79ba0ff69468c93a239f8c106547599c58ceb Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Sun, 4 Feb 2024 10:22:03 -0800 Subject: [PATCH 8/9] fix: WithGroup.WithGroup.Info should not create an empty group This requires holding onto a slice instead of a single string to create the nested namespaces. The slice is cloned on each WithGroup call. We could probably do this more efficiently with an immutable tree of references, but deferring that for now. In the process, also make the addedNamespace business append during the record.Attrs loop instead of after. This is more efficient because we don't have to shift the slice over afterwards. --- exp/zapslog/handler.go | 60 ++++++++++++++++++++++--------------- exp/zapslog/handler_test.go | 12 ++++++++ 2 files changed, 48 insertions(+), 24 deletions(-) diff --git a/exp/zapslog/handler.go b/exp/zapslog/handler.go index a29efbcff..f893455a9 100644 --- a/exp/zapslog/handler.go +++ b/exp/zapslog/handler.go @@ -26,7 +26,6 @@ import ( "context" "log/slog" "runtime" - "slices" "go.uber.org/zap" "go.uber.org/zap/internal/stacktrace" @@ -40,7 +39,13 @@ type Handler struct { addCaller bool addStackAt slog.Level callerSkip int - holdGroup string // holds latest group. + + // 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] @@ -163,58 +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()+1) + fields := make([]zapcore.Field, 0, record.NumAttrs()+len(h.groups)) + var addedNamespace bool record.Attrs(func(attr slog.Attr) bool { f := convertAttrToField(attr) - if !addedNamespace && f != zap.Skip() { + 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 }) - if h.holdGroup != "" && addedNamespace { - // group is before than other fields. - fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) - } 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)+1) + fields := make([]zapcore.Field, 0, len(attrs)+len(h.groups)) var addedNamespace bool for _, attr := range attrs { f := convertAttrToField(attr) - if !addedNamespace && f != zap.Skip() { + 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) } - if h.holdGroup != "" && addedNamespace { - // group is before than other fields. - fields = slices.Insert(fields, 0, zap.Namespace(h.holdGroup)) - return h.withFields("", fields...) + + 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(h.holdGroup, 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 { - if h.holdGroup != "" { - return h.withFields(group, zap.Namespace(h.holdGroup)) - } - return h.withFields(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 groups and fields. -func (h *Handler) withFields(newGroup string, fields ...zapcore.Field) *Handler { cloned := *h - cloned.holdGroup = newGroup - 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 b3f99be3e..2727f4000 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -203,6 +203,18 @@ func TestWithGroup(t *testing.T) { "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") From 8466cda889faa8190d0b6be441f183b55b7aae2d Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Sun, 4 Feb 2024 10:34:05 -0800 Subject: [PATCH 9/9] test: Run logger concurrently --- exp/zapslog/handler_test.go | 101 ++++++++++++++++++++++++++++++++++++ 1 file changed, 101 insertions(+) diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 2727f4000..a40d59f56 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -26,6 +26,7 @@ import ( "bytes" "encoding/json" "log/slog" + "sync" "testing" "testing/slogtest" "time" @@ -237,6 +238,106 @@ func TestWithGroup(t *testing.T) { 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