From a5fdadba76cfc5915dc60529476c0f92390dd7fb 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 drops slog attributes: Handle never reads the record's attributes, and WithAttrs and WithGroup return the receiver unchanged. So slog.Info("casting", "device", d) loses its field. The test checks the bytes each handler writes, directly and through MultiplexHandler: record attributes, WithAttrs, WithGroup, slog.Group nesting and LogValuer resolution. It also pins what a fix must not break: logged values are never modified, durations are nanoseconds in JSON and "3s" on the console, and the record's own field names win a key collision. Console keys and values are quoted as slog.NewTextHandler quotes them, invalid UTF-8 included. This commit adds only the test, and it fails; the fix follows. Rule suppressed: paralleltest; the tests swap the process-wide os.Stdout. Refs: https://git.eeqj.de/sneak/simplelog/issues/19 Model: opus-5-5 --- attrs_test.go | 912 ++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 912 insertions(+) create mode 100644 attrs_test.go diff --git a/attrs_test.go b/attrs_test.go new file mode 100644 index 0000000..5f440cc --- /dev/null +++ b/attrs_test.go @@ -0,0 +1,912 @@ +//nolint:paralleltest // tests swap the process-wide os.Stdout to read handler output +package simplelog_test + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "maps" + "net/http" + "net/http/httptest" + "os" + "reflect" + "slices" + "strings" + "testing" + "time" + + "sneak.berlin/go/simplelog" +) + +// 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. os.Stdout is shared by the +// whole process, so a test that uses this must not run in parallel. +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 + + err = w.Close() + if 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 +} + +// handle passes record to handler and fails the test if Handle returns an +// error. +func handle(t *testing.T, handler slog.Handler, record slog.Record) { + t.Helper() + + err := handler.Handle(context.Background(), record) + if err != nil { + t.Fatalf("Handle: %v", err) + } +} + +// 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 + + err := json.Unmarshal([]byte(line), &decoded) + if 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{} + +// errConnectionRefused is the error the ResolvesValues tests log. +var errConnectionRefused = errors.New("connection refused") + +func TestJSONHandlerEmitsRecordAttrs(t *testing.T) { + output := captureStdout(t, func() { + handler := simplelog.NewJSONHandler() + record := testRecord( + "casting", + slog.String("device", "livingroom"), + slog.String("file", "movie.mp4"), + slog.Int("attempt", 3), + ) + handle(t, handler, record) + }) + + 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 := simplelog.NewJSONHandler(). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithAttrs([]slog.Attr{slog.String("component", "caster")}) + record := testRecord("casting", slog.String("device", "livingroom")) + handle(t, handler, record) + }) + + 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 := simplelog.NewJSONHandler() + first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) + second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) + + firstOutput := captureStdout(t, func() { + handle(t, first, testRecord("work")) + }) + secondOutput := captureStdout(t, func() { + handle(t, second, testRecord("work")) + }) + parentOutput := captureStdout(t, func() { + handle(t, parent, testRecord("work")) + }) + + 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 := simplelog.NewJSONHandler(). + WithGroup("cast"). + WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) + record := testRecord("casting", slog.String("file", "movie.mp4")) + handle(t, handler, record) + }) + + 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 := simplelog.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", errConnectionRefused), + ) + handle(t, handler, record) + }) + + 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 := simplelog.NewConsoleHandler() + record := testRecord( + "casting", + slog.String("device", "livingroom"), + slog.String("file", "movie.mp4"), + slog.Int("attempt", 3), + ) + handle(t, handler, record) + }) + + 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 := simplelog.NewConsoleHandler() + record := testRecord("casting", slog.String("file", "The Movie.mp4")) + handle(t, handler, record) + }) + + wantContains(t, output, `file="The Movie.mp4"`) +} + +// TestConsoleHandlerQuotesKeysNeedingIt pins the key side of the same rule. +// A key is quoted on the same terms as a value, and as one token including +// its group prefix, so that the "=" separating the pair is always the first +// one outside quotes. Every case here was compared against +// slog.NewTextHandler, which renders each of them identically. +func TestConsoleHandlerQuotesKeysNeedingIt(t *testing.T) { + tests := []struct { + name string + build func() slog.Handler + attrs []slog.Attr + want string + notWant string + }{ + { + name: "an ordinary key is left bare", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String("device", "livingroom")}, + want: " device=livingroom", + notWant: `"device"`, + }, + { + name: "a key containing an equals sign is quoted", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String("a=b", "v2")}, + want: ` "a=b"=v2`, + notWant: " a=b=v2", + }, + { + name: "a key containing a space is quoted", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String("my key", "v")}, + want: ` "my key"=v`, + notWant: " my key=v", + }, + { + name: "a key containing a quote is escaped", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String(`he"llo`, "v")}, + want: ` "he\"llo"=v`, + notWant: ` he"llo=v`, + }, + { + name: "a printable non-ascii key is left bare", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String("キー", "v")}, + want: " キー=v", + notWant: `"キー"`, + }, + { + name: "a group prefix is quoted together with its key", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{ + slog.Group("grp", slog.String("a=b", "v")), + }, + want: ` "grp.a=b"=v`, + notWant: " grp.a=b=v", + }, + { + name: "a WithGroup prefix needing quotes is quoted with its key", + build: func() slog.Handler { + return simplelog.NewConsoleHandler().WithGroup("my grp") + }, + attrs: []slog.Attr{slog.String("k", "v")}, + want: ` "my grp.k"=v`, + notWant: " my grp.k=v", + }, + { + name: "an empty key is quoted rather than left as a gap", + build: func() slog.Handler { return simplelog.NewConsoleHandler() }, + attrs: []slog.Attr{slog.String("", "v")}, + want: ` ""=v`, + notWant: " =v", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + output := captureStdout(t, func() { + handle(t, test.build(), testRecord("casting", test.attrs...)) + }) + + wantContains(t, output, test.want) + wantNotContains(t, output, test.notWant) + }) + } +} + +// TestConsoleHandlerQuotesInvalidUTF8 checks that a key or a value holding +// invalid UTF-8 is quoted with the bad byte escaped, as slog.NewTextHandler +// does, so the raw byte never reaches the terminal. Valid non-ASCII stays bare. +func TestConsoleHandlerQuotesInvalidUTF8(t *testing.T) { + output := captureStdout(t, func() { + handler := simplelog.NewConsoleHandler() + record := testRecord( + "casting", + slog.String("bad\xffkey", "v"), + slog.String("raw", "bad\xffvalue"), + slog.String("title", "Amélie"), + ) + handle(t, handler, record) + }) + + wantContains(t, output, ` "bad\xffkey"=v`) + wantContains(t, output, ` raw="bad\xffvalue"`) + wantContains(t, output, " title=Amélie") + wantNotContains(t, output, "\xff") +} + +func TestConsoleHandlerWithAttrsAccumulates(t *testing.T) { + output := captureStdout(t, func() { + handler := simplelog.NewConsoleHandler(). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithAttrs([]slog.Attr{slog.String("component", "caster")}) + record := testRecord("casting", slog.String("device", "livingroom")) + handle(t, handler, record) + }) + + wantContains(t, output, "service=cattbox") + wantContains(t, output, "component=caster") + wantContains(t, output, "device=livingroom") +} + +func TestConsoleHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) { + parent := simplelog.NewConsoleHandler() + first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")}) + second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")}) + + firstOutput := captureStdout(t, func() { + handle(t, first, testRecord("work")) + }) + secondOutput := captureStdout(t, func() { + handle(t, second, testRecord("work")) + }) + parentOutput := captureStdout(t, func() { + handle(t, parent, testRecord("work")) + }) + + 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 := simplelog.NewConsoleHandler(). + WithGroup("cast"). + WithAttrs([]slog.Attr{slog.String("device", "livingroom")}) + record := testRecord("casting", slog.String("file", "movie.mp4")) + handle(t, handler, record) + }) + + wantContains(t, output, "cast.device=livingroom") + wantContains(t, output, "cast.file=movie.mp4") +} + +func TestConsoleHandlerResolvesValues(t *testing.T) { + output := captureStdout(t, func() { + handler := simplelog.NewConsoleHandler() + record := testRecord( + "cast failed", + slog.Group("request", slog.Int("status", 502)), + slog.Any("target", castTarget{id: "chromecast-7"}), + slog.Any("error", errConnectionRefused), + ) + handle(t, handler, record) + }) + + wantContains(t, output, "request.status=502") + wantContains(t, output, "target=chromecast-7") + wantContains(t, output, `error="connection refused"`) +} + +func TestWebhookHandlerEmitsAttrs(t *testing.T) { + t.Parallel() + + 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 := simplelog.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")) + handle(t, withAttrs, record) + + 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. It is +// built while stdout is the capture pipe, which is not a terminal, so it +// writes through the JSON handler. +func TestMultiplexHandlerPassesAttrsThrough(t *testing.T) { + output := captureStdout(t, func() { + handler := simplelog.NewMultiplexHandler(). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}) + record := testRecord("casting", slog.String("device", "livingroom")) + handle(t, handler, record) + }) + + 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"} + want := maps.Clone(caller) + + output := captureStdout(t, func() { + handler := simplelog.NewJSONHandler() + record := testRecord( + "casting", + slog.Any("g", caller), + slog.Group("g", slog.Int("injected", 1)), + ) + handle(t, handler, record) + }) + + wantUnchanged(t, "map", caller, want) + + // 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"} + want := maps.Clone(caller) + + output := captureStdout(t, func() { + handler := simplelog.NewJSONHandler(). + WithAttrs([]slog.Attr{slog.Any("req", caller)}). + WithGroup("req") + record := testRecord("cast failed", slog.Int("status", 502)) + handle(t, handler, record) + }) + + wantUnchanged(t, "map", caller, want) + + 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" + backing := slices.Clone(caller[:cap(caller)]) + + output := captureStdout(t, func() { + handler := simplelog.NewJSONHandler() + record := testRecord( + "casting", + slog.Any("s", caller), + slog.Group("s", slog.Int("injected", 1)), + ) + handle(t, handler, record) + }) + + wantUnchanged(t, "slice", caller, backing[:2]) + wantUnchanged(t, "slice backing array", caller[:cap(caller)], backing) + + group := wantGroup(t, decodeLine(t, output), "s") + wantField(t, group, "injected", float64(1)) +} + +func TestConsoleHandlerDoesNotMutateCallerMap(t *testing.T) { + caller := map[string]any{"mine": "untouched"} + want := maps.Clone(caller) + + output := captureStdout(t, func() { + handler := simplelog.NewConsoleHandler() + record := testRecord( + "casting", + slog.Any("g", caller), + slog.Group("g", slog.Int("injected", 1)), + ) + handle(t, handler, record) + }) + + wantUnchanged(t, "map", caller, want) + wantContains(t, output, "g.injected=1") +} + +func TestWebhookHandlerDoesNotMutateCallerMap(t *testing.T) { + t.Parallel() + + caller := map[string]any{"id": "req-1"} + want := maps.Clone(caller) + + 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 := simplelog.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)) + handle(t, derived, record) + + var body []byte + select { + case body = <-bodies: + case <-time.After(5 * time.Second): + t.Fatal("webhook handler posted nothing") + } + + wantUnchanged(t, "map", caller, want) + + 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 := simplelog.NewJSONHandler() + record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) + handle(t, handler, record) + }) + + 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 := simplelog.NewConsoleHandler() + record := testRecord("casting", slog.Duration("elapsed", 3*time.Second)) + handle(t, handler, record) + }) + + 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 simplelog.NewJSONHandler() }, + attrs: []slog.Attr{{}, slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + t.Helper() + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "") + }, + }, + { + name: "empty group is elided along with its key", + build: func() slog.Handler { + return simplelog.NewJSONHandler(). + WithAttrs([]slog.Attr{slog.Group("empty")}) + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + t.Helper() + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "empty") + }, + }, + { + name: "group with an empty key is inlined", + build: func() slog.Handler { return simplelog.NewJSONHandler() }, + attrs: []slog.Attr{ + slog.Group("", slog.String("inner", "yes")), + }, + verify: func(t *testing.T, decoded map[string]any) { + t.Helper() + wantField(t, decoded, "inner", "yes") + wantNoField(t, decoded, "") + }, + }, + { + name: "WithGroup with an empty name is a no-op", + build: func() slog.Handler { + return simplelog.NewJSONHandler().WithGroup("") + }, + attrs: []slog.Attr{slog.String("kept", "yes")}, + verify: func(t *testing.T, decoded map[string]any) { + t.Helper() + wantField(t, decoded, "kept", "yes") + wantNoField(t, decoded, "") + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + output := captureStdout(t, func() { + handle(t, test.build(), testRecord("casting", test.attrs...)) + }) + + 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 simplelog.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 simplelog.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 simplelog.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 simplelog.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() { + handle(t, test.build(), testRecord("casting", test.attrs...)) + }) + + 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 := simplelog.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"), + ) + handle(t, handler, record) + }) + + 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 := simplelog.NewJSONHandler() + record := testRecord( + "casting", + slog.String("device", "kitchen"), + slog.String("device", "livingroom"), + ) + handle(t, handler, record) + }) + + 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 := simplelog.NewConsoleHandler() + record := testRecord( + "casting", + slog.String("device", "kitchen"), + slog.String("device", "livingroom"), + ) + handle(t, handler, record) + }) + + wantContains(t, output, "device=kitchen") + wantContains(t, output, "device=livingroom") +}