From 4f587c1c67afdd2d16b0f57817947a37b6c808a4 Mon Sep 17 00:00:00 2001 From: Ronny Haryanto Date: Wed, 29 May 2024 14:59:19 +1000 Subject: [PATCH] Fix With* and dedup attrs (#5) * fixes incorrect WithAttrs and WithGroup behaviour * Deduplicate attributes with the same key https://github.com/golang/go/issues/59365 --- Makefile | 2 +- clog_test.go | 39 +++++++++++++++++++++ dedup_attrs.go | 28 ++++++++++++++++ dedup_attrs_test.go | 82 +++++++++++++++++++++++++++++++++++++++++++++ handler.go | 18 ++++++---- handler_test.go | 76 +++++++++++++++++++++++++---------------- 6 files changed, 208 insertions(+), 37 deletions(-) create mode 100644 clog_test.go create mode 100644 dedup_attrs.go create mode 100644 dedup_attrs_test.go diff --git a/Makefile b/Makefile index 7270ebf..0c295c7 100644 --- a/Makefile +++ b/Makefile @@ -4,7 +4,7 @@ test: go test -shuffle=on -coverprofile=coverage.txt -count=1 ./... bench: - go test -run=XXX -bench=. ./... + go test -run=XXX -benchmem -count=1 -bench=. ./... vet: go vet ./... diff --git a/clog_test.go b/clog_test.go new file mode 100644 index 0000000..ab4a2b4 --- /dev/null +++ b/clog_test.go @@ -0,0 +1,39 @@ +package clog_test + +type Entry map[string]any + +func (e Entry) GetAny(key string) (any, bool) { + v, ok := e[key] + if !ok { + return "", false + } + + return v, true +} + +func (e Entry) GetString(key string) (string, bool) { + v, ok := e.GetAny(key) + if !ok { + return "", false + } + + s, ok := v.(string) + if !ok { + return "", false + } + + return s, true +} + +func (e Entry) GetMap(key string) (map[string]any, bool) { + v, ok := e.GetAny(key) + if !ok { + return nil, false + } + + m, ok := v.(map[string]any) + if !ok { + return nil, false + } + return m, true +} diff --git a/dedup_attrs.go b/dedup_attrs.go new file mode 100644 index 0000000..a8b4f76 --- /dev/null +++ b/dedup_attrs.go @@ -0,0 +1,28 @@ +package clog + +import "log/slog" + +// Returns a new slog.Record with its attrs having the same key deduped. +// Keys are case sensitive. +func dedupAttrs(record slog.Record) slog.Record { + attrMap := map[string]slog.Attr{} + + record.Attrs(func(a slog.Attr) bool { + attrMap[a.Key] = a + return true + }) + + if len(attrMap) == 0 { + return record + } + + r := slog.NewRecord(record.Time, record.Level, record.Message, record.PC) + + for _, attr := range attrMap { + // We could have used an extra array to call AddAttrs() once only, but we + // want to avoid further allocs. + r.AddAttrs(attr) + } + + return r +} diff --git a/dedup_attrs_test.go b/dedup_attrs_test.go new file mode 100644 index 0000000..02b1f00 --- /dev/null +++ b/dedup_attrs_test.go @@ -0,0 +1,82 @@ +package clog_test + +import ( + "bytes" + "context" + "fmt" + "log/slog" + "strings" + "testing" + "time" + + "github.com/ronny/clog" + "github.com/stretchr/testify/assert" +) + +func TestHandler_DuplicateAttrs(t *testing.T) { + timestamp := time.Date(2024, time.May, 29, 12, 34, 56, 0, time.UTC) + + testCases := []struct { + desc string + ctx context.Context + record func() slog.Record + expected string + }{ + { + desc: "without attrs", + ctx: context.Background(), + record: func() slog.Record { + return slog.NewRecord(timestamp, slog.LevelInfo, "hello", 0) + }, + expected: `{"time":"2024-05-29T12:34:56Z","severity":"INFO","message":"hello"}`, + }, + { + desc: "without duplicate attrs", + ctx: context.Background(), + record: func() slog.Record { + r := slog.NewRecord(timestamp, slog.LevelInfo, "hello", 0) + r.AddAttrs( + slog.Attr{Key: "a", Value: slog.StringValue("one")}, + ) + return r + }, + expected: `{"time":"2024-05-29T12:34:56Z","severity":"INFO","message":"hello","a":"one"}`, + }, + { + desc: "overwrites duplicate attrs", + ctx: context.Background(), + record: func() slog.Record { + r := slog.NewRecord(timestamp, slog.LevelInfo, "hello", 0) + r.AddAttrs( + slog.Attr{Key: "a", Value: slog.StringValue("one")}, + slog.Attr{Key: "a", Value: slog.StringValue("two")}, + ) + return r + }, + expected: `{"time":"2024-05-29T12:34:56Z","severity":"INFO","message":"hello","a":"two"}`, + }, + } + for i, tc := range testCases { + tc := tc + t.Run(fmt.Sprintf("%d: %s", i, tc.desc), func(t *testing.T) { + t.Parallel() + + buf := &bytes.Buffer{} + + handler, err := clog.NewHandler(buf, clog.HandlerOptions{ + Level: clog.LevelInfo, + GoogleProjectID: "my-project-id", + }) + if !assert.Nil(t, err) { + return + } + + err = handler.Handle(tc.ctx, tc.record()) + if err != nil { + t.Fatal(err) + } + + assert.Equal(t, tc.expected, strings.TrimSpace(buf.String())) + }) + } +} diff --git a/handler.go b/handler.go index 7351688..dbb6b7b 100644 --- a/handler.go +++ b/handler.go @@ -44,9 +44,9 @@ func NewHandler(w io.Writer, opts HandlerOptions) (*Handler, error) { // Handle implements [log/slog.Handler]. func (h *Handler) Handle(ctx context.Context, record slog.Record) error { - return h.handler.Handle(ctx, - trace.NewRecord(ctx, record, h.opts.GoogleProjectID), - ) + record = trace.NewRecord(ctx, record, h.opts.GoogleProjectID) + record = dedupAttrs(record) + return h.handler.Handle(ctx, record) } // Enabled implements [log/slog.Handler]. @@ -56,12 +56,16 @@ func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool { // WithAttrs implements [log/slog.Handler]. func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { - h.handler = h.handler.WithAttrs(attrs) - return h + return &Handler{ + opts: h.opts, + handler: h.handler.WithAttrs(attrs), + } } // WithGroup implements [log/slog.Handler]. func (h *Handler) WithGroup(name string) slog.Handler { - h.handler = h.handler.WithGroup(name) - return h + return &Handler{ + opts: h.opts, + handler: h.handler.WithGroup(name), + } } diff --git a/handler_test.go b/handler_test.go index 14ed00d..44cf605 100644 --- a/handler_test.go +++ b/handler_test.go @@ -1,11 +1,13 @@ package clog_test import ( + "bytes" "context" "encoding/json" "log/slog" "strings" "testing" + "time" "github.com/ronny/clog" "github.com/stretchr/testify/assert" @@ -14,16 +16,16 @@ import ( func TestNewHandler(t *testing.T) { t.Parallel() - buf := strings.Builder{} + buf := &strings.Builder{} - _, err := clog.NewHandler(&buf, clog.HandlerOptions{}) + _, err := clog.NewHandler(buf, clog.HandlerOptions{}) if !assert.NotNil(t, err) { return } assert.ErrorIs(t, err, clog.ErrInvalidHandlerOptions) assert.ErrorContains(t, err, "missing GoogleProjectID") - handler, err := clog.NewHandler(&buf, clog.HandlerOptions{ + handler, err := clog.NewHandler(buf, clog.HandlerOptions{ AddSource: true, Level: clog.LevelInfo, GoogleProjectID: "my-project-id", @@ -126,40 +128,56 @@ func TestNewHandler(t *testing.T) { assert.Equal(t, "banana", spanID) } -type Entry map[string]any +var benchmarkJSONHandler_HandleResult error -func (e Entry) GetAny(key string) (any, bool) { - v, ok := e[key] - if !ok { - return "", false - } - - return v, true -} +func BenchmarkJSONHandler_Handle(b *testing.B) { + buf := &bytes.Buffer{} + h := slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelInfo}) -func (e Entry) GetString(key string) (string, bool) { - v, ok := e.GetAny(key) - if !ok { - return "", false - } + ctx := context.Background() - s, ok := v.(string) - if !ok { - return "", false + b.ResetTimer() + var err error + for n := 0; n < b.N; n++ { + record := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) + record.AddAttrs( + slog.Attr{Key: "a", Value: slog.StringValue("one")}, + slog.Attr{Key: "a", Value: slog.StringValue("two")}, + ) + err = h.Handle(ctx, record) } - return s, true + // Always store the result to a package level variable + // so the compiler cannot eliminate the Benchmark itself. + benchmarkJSONHandler_HandleResult = err } -func (e Entry) GetMap(key string) (map[string]any, bool) { - v, ok := e.GetAny(key) - if !ok { - return nil, false +var benchmarkHandler_HandleResult error + +func BenchmarkHandler_Handle(b *testing.B) { + buf := &bytes.Buffer{} + h, err := clog.NewHandler(buf, clog.HandlerOptions{ + Level: slog.LevelInfo, + GoogleProjectID: "example", + }) + if err != nil { + b.Fatal(err) } - m, ok := v.(map[string]any) - if !ok { - return nil, false + ctx := context.Background() + + b.ResetTimer() + var e error + for n := 0; n < b.N; n++ { + record := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) + record.AddAttrs( + slog.Attr{Key: "a", Value: slog.StringValue("one")}, + slog.Attr{Key: "a", Value: slog.StringValue("two")}, + ) + e = h.Handle(ctx, record) } - return m, true + + // Always store the result to a package level variable + // so the compiler cannot eliminate the Benchmark itself. + benchmarkHandler_HandleResult = e }