From 5fc919e5233c21c3ea740de1149fb3657a48ce23 Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 10 Aug 2026 12:59:58 +0000 Subject: [PATCH] Add a failing test pinning the discarded slog attributes Every handler in this package accepts slog attributes and then throws them away: Handle never reads record.Attrs, and WithAttrs and WithGroup return the receiver unchanged in ConsoleHandler, JSONHandler and WebhookHandler alike. So slog.Info("casting", "device", d, "file", f) emits the message and silently loses both fields, which makes properly structured logging carry less information than the interpolated log.Printf calls it replaces. The test asserts on the bytes the handlers actually write - os.Stdout for the console and JSON handlers, the posted body for the webhook handler - rather than on internal state, because the output is where the loss is observable. It covers record attributes, WithAttrs accumulation, WithAttrs not mutating its receiver so sibling loggers cannot leak attributes into each other, WithGroup qualification, slog.Group nesting, and LogValuer resolution, for each handler and through MultiplexHandler. It also pins the properties a fix must not get wrong on the way past. A value the caller logged is read and never written to, even when a group later claims the same key - for maps and for slices, through the record path and the derived-logger path, in all three handlers. A duration is a number of nanoseconds in the json payload and the readable "3s" form on the console. The four slog.Handler contract edge cases hold: an empty Attr is ignored, an empty group is elided with its key, a group with an empty key is inlined, and WithGroup("") is a no-op. And the two rules that follow from the json payload being an object hold too: the record's own field names win a collision, and a repeated key keeps its last value, where the console line keeps both. This commit adds only the test, and it fails. The fix follows. Refs: https://git.eeqj.de/sneak/simplelog/issues/19 --- attrs_test.go | 814 ++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 814 insertions(+) create mode 100644 attrs_test.go diff --git a/attrs_test.go b/attrs_test.go new file mode 100644 index 0000000..efd010f --- /dev/null +++ b/attrs_test.go @@ -0,0 +1,814 @@ +package simplelog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "os" + "reflect" + "strings" + "testing" + "time" +) + +// These tests assert on the bytes the handlers actually emit, because that is +// where the defect lives: the handlers accept attributes and then throw them +// away, so nothing short of reading the output proves they survived. + +// captureStdout redirects os.Stdout for the duration of fn and returns what was +// written to it. Both the console and the JSON handler write to os.Stdout, so +// this is the only way to see their real output. +func captureStdout(t *testing.T, fn func()) string { + t.Helper() + + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("os.Pipe: %v", err) + } + + original := os.Stdout + os.Stdout = w + + collected := make(chan string, 1) + go func() { + var buf bytes.Buffer + _, _ = io.Copy(&buf, r) + collected <- buf.String() + }() + + defer func() { + os.Stdout = original + _ = r.Close() + }() + + fn() + + os.Stdout = original + if err := w.Close(); err != nil { + t.Fatalf("close pipe writer: %v", err) + } + + return <-collected +} + +// testRecord builds an INFO record carrying the given attributes. +func testRecord(message string, attrs ...slog.Attr) slog.Record { + record := slog.NewRecord(time.Now(), slog.LevelInfo, message, 0) + record.AddAttrs(attrs...) + return record +} + +// decodeLine parses a single line of JSON handler output. +func decodeLine(t *testing.T, output string) map[string]any { + t.Helper() + + line := strings.TrimSpace(output) + if line == "" { + t.Fatal("handler emitted no output") + } + + var decoded map[string]any + if err := json.Unmarshal([]byte(line), &decoded); err != nil { + t.Fatalf("output is not valid JSON: %v\noutput: %s", err, line) + } + return decoded +} + +// wantField asserts that a decoded JSON object has key with the given value. +func wantField(t *testing.T, decoded map[string]any, key string, want any) { + t.Helper() + + got, ok := decoded[key] + if !ok { + t.Fatalf("field %q missing from output: %v", key, decoded) + } + if got != want { + t.Fatalf("field %q = %v, want %v", key, got, want) + } +} + +// wantGroup asserts that a decoded JSON object has key holding a nested object. +func wantGroup(t *testing.T, decoded map[string]any, key string) map[string]any { + t.Helper() + + got, ok := decoded[key] + if !ok { + t.Fatalf("group %q missing from output: %v", key, decoded) + } + group, ok := got.(map[string]any) + if !ok { + t.Fatalf("field %q = %v, want a nested object", key, got) + } + return group +} + +// wantNoField asserts that a decoded JSON object does not carry key. +func wantNoField(t *testing.T, decoded map[string]any, key string) { + t.Helper() + + if got, present := decoded[key]; present { + t.Fatalf("field %q unexpectedly present as %v: %v", key, got, decoded) + } +} + +// wantUnchanged asserts that a value the caller still owns was not written to +// by the handler. Logging must read what it is handed, never modify it. +func wantUnchanged(t *testing.T, what string, got, want any) { + t.Helper() + + if !reflect.DeepEqual(got, want) { + t.Fatalf("handler mutated the caller's %s: got %v, want %v", what, got, want) + } +} + +// wantContains asserts that console output contains a fragment. +func wantContains(t *testing.T, output, fragment string) { + t.Helper() + + if !strings.Contains(output, fragment) { + t.Fatalf("output does not contain %q\noutput: %s", fragment, output) + } +} + +// wantNotContains asserts that console output does not contain a fragment. +func wantNotContains(t *testing.T, output, fragment string) { + t.Helper() + + if strings.Contains(output, fragment) { + t.Fatalf("output unexpectedly contains %q\noutput: %s", fragment, output) + } +} + +// castTarget is a slog.LogValuer: the handler must resolve it rather than +// serialising the struct itself. +type castTarget struct { + id string +} + +func (c castTarget) LogValue() slog.Value { + return slog.StringValue(c.id) +} + +var _ slog.LogValuer = castTarget{} + +func TestJSONHandlerEmitsRecordAttrs(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "casting", + slog.String("device", "livingroom"), + slog.String("file", "movie.mp4"), + slog.Int("attempt", 3), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "Message", "casting") + wantField(t, decoded, "device", "livingroom") + wantField(t, decoded, "file", "movie.mp4") + wantField(t, decoded, "attempt", float64(3)) +} + +func TestJSONHandlerWithAttrsAccumulates(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler(). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithAttrs([]slog.Attr{slog.String("component", "caster")}) + record := testRecord("casting", slog.String("device", "livingroom")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "service", "cattbox") + wantField(t, decoded, "component", "caster") + wantField(t, decoded, "device", "livingroom") +} + +func TestJSONHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) { + parent := NewJSONHandler() + first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) + second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) + + firstOutput := captureStdout(t, func() { + if err := first.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + secondOutput := captureStdout(t, func() { + if err := second.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + parentOutput := captureStdout(t, func() { + if err := parent.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantField(t, decodeLine(t, firstOutput), "worker", "first") + wantField(t, decodeLine(t, secondOutput), "worker", "second") + + if _, present := decodeLine(t, parentOutput)["worker"]; present { + t.Fatalf("parent handler leaked an attribute from a derived handler: %s", parentOutput) + } +} + +func TestJSONHandlerWithGroupNestsAttrs(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler(). + WithGroup("cast"). + WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) + record := testRecord("casting", slog.String("file", "movie.mp4")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "Message", "casting") + + group := wantGroup(t, decoded, "cast") + wantField(t, group, "device", "livingroom") + wantField(t, group, "file", "movie.mp4") +} + +func TestJSONHandlerResolvesValues(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "cast failed", + slog.Group("request", slog.Int("status", 502), slog.String("method", "POST")), + slog.Any("target", castTarget{id: "chromecast-7"}), + slog.Any("error", errors.New("connection refused")), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "target", "chromecast-7") + wantField(t, decoded, "error", "connection refused") + + group := wantGroup(t, decoded, "request") + wantField(t, group, "status", float64(502)) + wantField(t, group, "method", "POST") +} + +func TestConsoleHandlerEmitsRecordAttrs(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord( + "casting", + slog.String("device", "livingroom"), + slog.String("file", "movie.mp4"), + slog.Int("attempt", 3), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "casting") + wantContains(t, output, "device=livingroom") + wantContains(t, output, "file=movie.mp4") + wantContains(t, output, "attempt=3") +} + +func TestConsoleHandlerQuotesValuesNeedingIt(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord("casting", slog.String("file", "The Movie.mp4")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, `file="The Movie.mp4"`) +} + +func TestConsoleHandlerWithAttrsAccumulates(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler(). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithAttrs([]slog.Attr{slog.String("component", "caster")}) + record := testRecord("casting", slog.String("device", "livingroom")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "service=cattbox") + wantContains(t, output, "component=caster") + wantContains(t, output, "device=livingroom") +} + +func TestConsoleHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) { + parent := NewConsoleHandler() + first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) + second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) + + firstOutput := captureStdout(t, func() { + if err := first.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + secondOutput := captureStdout(t, func() { + if err := second.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + parentOutput := captureStdout(t, func() { + if err := parent.Handle(context.Background(), testRecord("work")); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, firstOutput, "worker=first") + wantNotContains(t, firstOutput, "worker=second") + wantContains(t, secondOutput, "worker=second") + wantNotContains(t, secondOutput, "worker=first") + wantNotContains(t, parentOutput, "worker=") +} + +func TestConsoleHandlerWithGroupQualifiesAttrs(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler(). + WithGroup("cast"). + WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) + record := testRecord("casting", slog.String("file", "movie.mp4")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "cast.device=livingroom") + wantContains(t, output, "cast.file=movie.mp4") +} + +func TestConsoleHandlerResolvesValues(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord( + "cast failed", + slog.Group("request", slog.Int("status", 502)), + slog.Any("target", castTarget{id: "chromecast-7"}), + slog.Any("error", errors.New("connection refused")), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "request.status=502") + wantContains(t, output, "target=chromecast-7") + wantContains(t, output, `error="connection refused"`) +} + +func TestWebhookHandlerEmitsAttrs(t *testing.T) { + bodies := make(chan []byte, 1) + server := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + body, err := io.ReadAll(r.Body) + if err != nil { + t.Errorf("read webhook body: %v", err) + } + bodies <- body + w.WriteHeader(http.StatusOK) + }, + )) + defer server.Close() + + handler, err := NewWebhookHandler(server.URL) + if err != nil { + t.Fatalf("NewWebhookHandler: %v", err) + } + + withAttrs := handler.WithAttrs([]slog.Attr{slog.String("service", "cattbox")}) + record := testRecord("casting", slog.String("device", "livingroom")) + if err := withAttrs.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + + var body []byte + select { + case body = <-bodies: + case <-time.After(5 * time.Second): + t.Fatal("webhook handler posted nothing") + } + + decoded := decodeLine(t, string(body)) + wantField(t, decoded, "service", "cattbox") + wantField(t, decoded, "device", "livingroom") +} + +// TestMultiplexHandlerPassesAttrsThrough guards the composite handler that +// package init installs: attributes must survive the multiplex too. +func TestMultiplexHandlerPassesAttrsThrough(t *testing.T) { + output := captureStdout(t, func() { + handler := (&MultiplexHandler{handlers: []ExtendedHandler{NewJSONHandler()}}). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}) + record := testRecord("casting", slog.String("device", "livingroom")) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "service", "cattbox") + wantField(t, decoded, "device", "livingroom") +} + +// A logging library must read the values it is handed and never write to them. +// The dangerous shape is a group that shares a key with something the caller +// logged by reference: merging the group's members into whatever already sits +// at that key would reach straight back into the caller's own data structure. +// The next four tests hold every handler to that, through both the record path +// and the derived-logger path. + +func TestJSONHandlerDoesNotMutateCallerMap(t *testing.T) { + caller := map[string]any{"mine": "untouched"} + + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "casting", + slog.Any("g", caller), + slog.Group("g", slog.Int("injected", 1)), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantUnchanged(t, "map", caller, map[string]any{"mine": "untouched"}) + + // The later attribute wins the key outright, as any repeated key does. + group := wantGroup(t, decodeLine(t, output), "g") + wantField(t, group, "injected", float64(1)) + wantNoField(t, group, "mine") +} + +func TestJSONHandlerDoesNotMutateCallerMapThroughWithAttrs(t *testing.T) { + caller := map[string]any{"id": "req-1"} + + output := captureStdout(t, func() { + handler := NewJSONHandler(). + WithAttrs([]slog.Attr{slog.Any("req", caller)}). + WithGroup("req") + record := testRecord("cast failed", slog.Int("status", 502)) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantUnchanged(t, "map", caller, map[string]any{"id": "req-1"}) + + group := wantGroup(t, decodeLine(t, output), "req") + wantField(t, group, "status", float64(502)) + wantNoField(t, group, "id") +} + +// TestJSONHandlerDoesNotMutateCallerSlice is the slice form of the same +// hazard: a caller's slice is also handed over by reference, and appending +// into its spare capacity would be just as visible to the caller as writing +// into its map. The slice is built with room to spare so that an append within +// capacity cannot hide behind an unchanged length. +func TestJSONHandlerDoesNotMutateCallerSlice(t *testing.T) { + caller := make([]any, 2, 4) + caller[0] = "first" + caller[1] = "second" + + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "casting", + slog.Any("s", caller), + slog.Group("s", slog.Int("injected", 1)), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantUnchanged(t, "slice", caller, []any{"first", "second"}) + wantUnchanged( + t, + "slice backing array", + caller[:cap(caller)], + []any{"first", "second", nil, nil}, + ) + + group := wantGroup(t, decodeLine(t, output), "s") + wantField(t, group, "injected", float64(1)) +} + +func TestConsoleHandlerDoesNotMutateCallerMap(t *testing.T) { + caller := map[string]any{"mine": "untouched"} + + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord( + "casting", + slog.Any("g", caller), + slog.Group("g", slog.Int("injected", 1)), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantUnchanged(t, "map", caller, map[string]any{"mine": "untouched"}) + wantContains(t, output, "g.injected=1") +} + +func TestWebhookHandlerDoesNotMutateCallerMap(t *testing.T) { + caller := map[string]any{"id": "req-1"} + + bodies := make(chan []byte, 1) + server := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + body, err := io.ReadAll(r.Body) + if err != nil { + t.Errorf("read webhook body: %v", err) + } + bodies <- body + w.WriteHeader(http.StatusOK) + }, + )) + defer server.Close() + + handler, err := NewWebhookHandler(server.URL) + if err != nil { + t.Fatalf("NewWebhookHandler: %v", err) + } + + derived := handler. + WithAttrs([]slog.Attr{slog.Any("req", caller)}). + WithGroup("req") + record := testRecord("cast failed", slog.Int("status", 502)) + if err := derived.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + + var body []byte + select { + case body = <-bodies: + case <-time.After(5 * time.Second): + t.Fatal("webhook handler posted nothing") + } + + wantUnchanged(t, "map", caller, map[string]any{"id": "req-1"}) + + group := wantGroup(t, decodeLine(t, string(body)), "req") + wantField(t, group, "status", float64(502)) +} + +// TestJSONHandlerRendersDurationAsNanoseconds pins the json rendering of a +// duration to a number of nanoseconds, which is what slog.NewJSONHandler +// emits. A consumer that sums or compares the field needs a number; the "3s" +// form would silently arrive as a string. +func TestJSONHandlerRendersDurationAsNanoseconds(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + if _, isNumber := decoded["elapsed"].(float64); !isNumber { + t.Fatalf("field \"elapsed\" = %#v, want a json number", decoded["elapsed"]) + } + wantField(t, decoded, "elapsed", float64((3 * time.Second).Nanoseconds())) +} + +// TestConsoleHandlerRendersDurationReadably is the other half of that choice: +// the console line is read by a person, so it carries the same human-readable +// form slog.NewTextHandler uses. +func TestConsoleHandlerRendersDurationReadably(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "elapsed=3s") +} + +// TestJSONHandlerContractEdgeCases pins the slog.Handler contract's four +// edge cases. Every case carries a control attribute as well, so a handler +// that emitted no attributes at all would fail rather than pass by omission. +// +// The empty group is attached through WithAttrs rather than to the record, +// because slog.Record.AddAttrs elides empty groups itself: routed through the +// record, the case would never reach the handler at all. +func TestJSONHandlerContractEdgeCases(t *testing.T) { + tests := []struct { + name string + build func() slog.Handler + attrs []slog.Attr + verify func(t *testing.T, decoded map[string]any) + }{ + { + name: "empty attr is ignored", + build: func() slog.Handler { return NewJSONHandler() }, + attrs: []slog.Attr{{}, slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "") + }, + }, + { + name: "empty group is elided along with its key", + build: func() slog.Handler { + return NewJSONHandler(). + WithAttrs([]slog.Attr{slog.Group("empty")}) + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "empty") + }, + }, + { + name: "group with an empty key is inlined", + build: func() slog.Handler { return NewJSONHandler() }, + attrs: []slog.Attr{ + slog.Group("", slog.String("inner", "yes")), + }, + verify: func(t *testing.T, decoded map[string]any) { + wantField(t, decoded, "inner", "yes") + wantNoField(t, decoded, "") + }, + }, + { + name: "WithGroup with an empty name is a no-op", + build: func() slog.Handler { + return NewJSONHandler().WithGroup("") + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "") + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + output := captureStdout(t, func() { + handler := test.build() + record := testRecord("casting", test.attrs...) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + test.verify(t, decodeLine(t, output)) + }) + } +} + +// TestConsoleHandlerContractEdgeCases holds the console handler to the same +// four rules, since it renders attributes through its own code path. +func TestConsoleHandlerContractEdgeCases(t *testing.T) { + tests := []struct { + name string + build func() slog.Handler + attrs []slog.Attr + want string + notWant string + }{ + { + name: "empty attr is ignored", + build: func() slog.Handler { return NewConsoleHandler() }, + attrs: []slog.Attr{{}, slog.String("kept", "yes")}, + want: "kept=yes", + notWant: " =", + }, + { + name: "empty group is elided along with its key", + build: func() slog.Handler { + return NewConsoleHandler(). + WithAttrs([]slog.Attr{slog.Group("empty")}) + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + want: "kept=yes", + notWant: "empty=", + }, + { + name: "group with an empty key is inlined", + build: func() slog.Handler { return NewConsoleHandler() }, + attrs: []slog.Attr{ + slog.Group("", slog.String("inner", "yes")), + }, + want: " inner=yes", + notWant: ".inner=", + }, + { + name: "WithGroup with an empty name is a no-op", + build: func() slog.Handler { + return NewConsoleHandler().WithGroup("") + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + want: " kept=yes", + notWant: ".kept=", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + output := captureStdout(t, func() { + handler := test.build() + record := testRecord("casting", test.attrs...) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, test.want) + wantNotContains(t, output, test.notWant) + }) + } +} + +// TestJSONHandlerRecordFieldsWinKeyCollision pins a caller-visible surprise: +// the json payload is an object, so the record's own fields own their names +// and an attribute keyed after one of them is dropped rather than emitted. +func TestJSONHandlerRecordFieldsWinKeyCollision(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "the real message", + slog.String("Time", "hijacked"), + slog.String("Level", "hijacked"), + slog.String("Message", "hijacked"), + slog.String("PC", "hijacked"), + slog.String("kept", "yes"), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + decoded := decodeLine(t, output) + wantField(t, decoded, "kept", "yes") + wantField(t, decoded, "Message", "the real message") + wantField(t, decoded, "Level", "INFO") + for _, reserved := range []string{"Time", "PC"} { + if decoded[reserved] == "hijacked" { + t.Fatalf("attribute overwrote the record's own %q field: %v", reserved, decoded) + } + } +} + +// TestJSONHandlerDuplicateKeysKeepLast pins the other consequence of the +// payload being an object: a key logged twice collapses to its last value. +func TestJSONHandlerDuplicateKeysKeepLast(t *testing.T) { + output := captureStdout(t, func() { + handler := NewJSONHandler() + record := testRecord( + "casting", + slog.String("device", "kitchen"), + slog.String("device", "livingroom"), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantField(t, decodeLine(t, output), "device", "livingroom") +} + +// TestConsoleHandlerKeepsDuplicateKeys is the console counterpart: a line of +// text is not an object, so both pairs survive there. +func TestConsoleHandlerKeepsDuplicateKeys(t *testing.T) { + output := captureStdout(t, func() { + handler := NewConsoleHandler() + record := testRecord( + "casting", + slog.String("device", "kitchen"), + slog.String("device", "livingroom"), + ) + if err := handler.Handle(context.Background(), record); err != nil { + t.Fatalf("Handle: %v", err) + } + }) + + wantContains(t, output, "device=kitchen") + wantContains(t, output, "device=livingroom") +}