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