From 8c3ab23843f1c1bbccd3da273331bb337a1e3caa Mon Sep 17 00:00:00 2001 From: clawbot Date: Mon, 10 Aug 2026 12:33:06 +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. This commit adds only the test, and it fails. The fix follows. Refs: https://git.eeqj.de/sneak/simplelog/issues/19 --- attrs_test.go | 410 ++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 410 insertions(+) create mode 100644 attrs_test.go diff --git a/attrs_test.go b/attrs_test.go new file mode 100644 index 0000000..086a0d8 --- /dev/null +++ b/attrs_test.go @@ -0,0 +1,410 @@ +package simplelog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "os" + "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 +} + +// 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") +}