Fix With* and dedup attrs (#5)

* fixes incorrect WithAttrs and WithGroup behaviour

* Deduplicate attributes with the same key

golang/go#59365

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 ./...

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
+}

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
+}

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()))
+		})
+	}
+}

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),
+	}
 }

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
 }