8c3ab23843
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: #19
411 lines
12 KiB
Go
411 lines
12 KiB
Go
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")
|
|
}
|