diff --git a/README.md b/README.md index 3f6222e..fcc7e09 100644 --- a/README.md +++ b/README.md @@ -18,6 +18,13 @@ Released v1.0.0 2024-06-14. Works as intended. No known bugs. - if output is a tty, outputs pretty color logs - if output is not a tty, outputs json - supports delivering each log message via a webhook +- emits every `slog` attribute: those passed to a log call, those + accumulated with `WithAttrs`, and those qualified by `WithGroup`. + `slog.Group` values nest, and `slog.LogValuer` values are resolved. In + json output attributes are object fields (groups become nested objects); + in console output they are appended as `key=value` pairs, with grouped + keys written as `group.key=value`. See + [Attribute output](#attribute-output) for the details worth knowing ## Planned Features @@ -60,6 +67,43 @@ func main() { } ``` +## Attribute output + +Attributes reach every handler: the ones passed to the log call, the ones +accumulated with `WithAttrs`, and the ones qualified by the groups open at +the time they were attached. `slog.Group` values nest, and +`slog.LogValuer` values are resolved to the value they stand for. A few +behaviours are worth knowing before you rely on them. + +**Your values are never modified.** Whatever you log is read and rendered, +never written to. A map or a slice you pass to `slog.Any` comes back from +the logger exactly as you handed it over, even when a group later uses the +same key. + +**Durations are nanoseconds in json, and readable on the console.** The +json and webhook payloads emit a `slog.Duration` as a number of +nanoseconds, matching `slog.NewJSONHandler`, so a consumer can compare and +aggregate the field without parsing it. The console line emits the same +duration as `3s`, matching `slog.NewTextHandler`, because a person reads +it. + +**The json payload is an object, with the consequences an object has.** +The record's own fields are named `Time`, `Level`, `Message` and `PC`, and +they own those names: an attribute keyed after one of them is dropped from +the json and webhook output. A key logged more than once keeps its last +value there for the same reason, with one exception: when both are +`slog.Group` values sharing a key, the two groups are merged into one +object holding the members of both, rather than the second replacing the +first. Neither the collision nor the merge applies to the console output, +which is a line of text: every pair appears, in order. If you need a field +called `message`, pick a key that does not collide - the collision is +silent. + +**Empty things follow the `slog.Handler` contract.** An empty `Attr` is +ignored, an empty group is elided along with its key, a group with an +empty key is inlined into its parent, and `WithGroup("")` returns the +handler unchanged. + ## License [WTFPL](./LICENSE) diff --git a/TODO.md b/TODO.md index 69b39fc..41fd9b7 100644 --- a/TODO.md +++ b/TODO.md @@ -24,6 +24,11 @@ files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig, # Completed Steps +* 2026-08-10: fixed every handler discarding slog attributes: console, + JSON and webhook handlers now emit record attributes, accumulate + WithAttrs without mutating the receiver, and honour WithGroup; + slog.Group values nest and LogValuer values are resolved; console + keys and values holding invalid UTF-8 are quoted * 2026-08-07: added canonical `.golangci.yml` (v2 schema), pinned the `Dockerfile` lint stage to golangci-lint v2.12.2 (tag+digest), and fixed all findings the v1→v2 jump surfaced without changing any @@ -50,6 +55,8 @@ files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig, the working tree * Pick one tag scheme before the next release (v1.0.0 vs 1.0.1 are inconsistent) +* Tag v1.0.2, with the leading v, once the attribute fix lands, so + consuming repos can move off pseudo-version pins in one step * Fix RELP output to cache (from old TODO) * Re-add RELP delivery over TCP to remote rsyslog imrelp; removed 2024-06-14 because it did not build (README planned feature) diff --git a/attrs.go b/attrs.go new file mode 100644 index 0000000..3b84a54 --- /dev/null +++ b/attrs.go @@ -0,0 +1,285 @@ +package simplelog + +import ( + "encoding/json" + "log/slog" + "strconv" + "strings" + "unicode" + "unicode/utf8" +) + +// handlerAttrs is the attribute state every handler carries: the attributes +// accumulated by WithAttrs, plus the groups opened by WithGroup. Its methods +// never mutate the receiver, so handlers derived from a common parent stay +// independent of each other. +type handlerAttrs struct { + attrs []slog.Attr + groups []string +} + +// withAttrs returns a copy carrying attrs in addition to those already held. +// The attributes are qualified by the groups that are open at the time they +// are attached, as the slog.Handler contract requires. +func (h handlerAttrs) withAttrs(attrs []slog.Attr) handlerAttrs { + qualified := qualifyAttrs(h.groups, attrs) + combined := make([]slog.Attr, 0, len(h.attrs)+len(qualified)) + combined = append(combined, h.attrs...) + combined = append(combined, qualified...) + + return handlerAttrs{attrs: combined, groups: h.groups} +} + +// withGroup returns a copy with a further group open. An empty name is a no-op, +// per the slog.Handler contract. +func (h handlerAttrs) withGroup(name string) handlerAttrs { + if name == "" { + return h + } + + groups := make([]string, 0, len(h.groups)+1) + groups = append(groups, h.groups...) + groups = append(groups, name) + + return handlerAttrs{attrs: h.attrs, groups: groups} +} + +// forRecord returns the accumulated attributes followed by the record's own, +// the latter qualified by any open groups. +func (h handlerAttrs) forRecord(record slog.Record) []slog.Attr { + own := qualifyAttrs(h.groups, recordAttrs(record)) + all := make([]slog.Attr, 0, len(h.attrs)+len(own)) + all = append(all, h.attrs...) + all = append(all, own...) + + return all +} + +// qualifyAttrs nests attrs inside the given open groups, innermost last. +func qualifyAttrs(groups []string, attrs []slog.Attr) []slog.Attr { + for i := len(groups) - 1; i >= 0; i-- { + attrs = []slog.Attr{{ + Key: groups[i], + Value: slog.GroupValue(attrs...), + }} + } + + return attrs +} + +// recordAttrs collects the attributes a record carries. They live in +// unexported fields, so they are only reachable through Record.Attrs - which +// is why marshaling a slog.Record directly loses every one of them. +func recordAttrs(record slog.Record) []slog.Attr { + attrs := make([]slog.Attr, 0, record.NumAttrs()) + record.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + + return true + }) + + return attrs +} + +// groupMap is a JSON object this package built for itself: the payload of a +// record, or one of the nested objects a slog.Group becomes. +// +// The distinct type is what keeps the handler from writing into data the +// caller still owns. A value handed to slog.Any goes into the payload by +// reference - copying every logged map and slice would be a real cost for no +// gain, since rendering only reads. The one place the handler writes into a +// value already in the payload is the group merge below, and a type assertion +// to groupMap can only succeed on a map this package allocated: a caller's +// map[string]any is a different type and never matches, however it was keyed. +// So the invariant holds by construction - nothing reachable from the caller +// is ever written to, only read. +type groupMap map[string]any + +// recordToMap renders a record, with its handler's attributes, as the JSON +// object the JSON and webhook handlers emit. The record's own fields keep the +// names they have always had, and win a collision with an attribute key. +func recordToMap(record slog.Record, attrs handlerAttrs) groupMap { + fields := attrsToMap(attrs.forRecord(record)) + fields["Time"] = record.Time + fields["Level"] = record.Level + fields["Message"] = record.Message + fields["PC"] = record.PC + + return fields +} + +// attrsToMap renders attributes as a JSON object in which groups are nested +// objects. A group named more than once is merged rather than duplicated; +// any other repeated key keeps the last value, as a JSON object must. +func attrsToMap(attrs []slog.Attr) groupMap { + fields := make(groupMap, len(attrs)) + for _, attr := range attrs { + addAttrToMap(fields, attr) + } + + return fields +} + +func addAttrToMap(fields groupMap, attr slog.Attr) { + value := attr.Value.Resolve() + if attr.Key == "" && value.Any() == nil { + // An empty Attr is ignored, per the slog.Handler contract. + return + } + + if value.Kind() == slog.KindGroup { + group := value.Group() + if len(group) == 0 { + // An empty group is elided, as is its key. + return + } + // A group with an empty key is inlined into its parent. + target := fields + if attr.Key != "" { + // Merge only into a group this package built. Anything else + // at this key - including a map the caller logged - is + // replaced rather than written into, so the caller's own + // data structure is never touched. + nested, ok := fields[attr.Key].(groupMap) + if !ok { + nested = make(groupMap, len(group)) + fields[attr.Key] = nested + } + + target = nested + } + + for _, member := range group { + addAttrToMap(target, member) + } + + return + } + + fields[attr.Key] = jsonValue(value) +} + +// jsonValue converts a resolved slog.Value into something encoding/json can +// render usefully. Values it cannot marshal - and errors, which marshal to an +// empty object - fall back to their slog string form, so a value is never +// rendered as an empty object. +// +// Values are returned as they were given, not copied: nothing here or in its +// callers writes to a value the caller supplied. +func jsonValue(value slog.Value) any { + switch value.Kind() { + case slog.KindString: + return value.String() + case slog.KindInt64: + return value.Int64() + case slog.KindUint64: + return value.Uint64() + case slog.KindFloat64: + return value.Float64() + case slog.KindBool: + return value.Bool() + case slog.KindDuration: + // Nanoseconds as a number, which is what slog.NewJSONHandler + // emits. A JSON consumer can then compare and aggregate the + // field; the "3s" form would have to be parsed first, and no + // common log pipeline knows how. + return value.Duration().Nanoseconds() + case slog.KindTime: + return value.Time() + case slog.KindAny, slog.KindGroup, slog.KindLogValuer: + // Only KindAny arrives here in practice: addAttrToMap renders + // groups itself and resolves every value first. + return jsonAnyValue(value) + default: + // Anything a future Go release adds. + return jsonAnyValue(value) + } +} + +func jsonAnyValue(value slog.Value) any { + held := value.Any() + if _, ok := held.(json.Marshaler); !ok { + if err, ok := held.(error); ok { + return err.Error() + } + } + + _, err := json.Marshal(held) + if err != nil { + return value.String() + } + + return held +} + +// attrsToText renders attributes as the space separated key=value pairs the +// console handler appends to a log line. Groups become dotted key prefixes. +// +// Values take their slog string form, so a duration reads as "3s" here where +// the json output carries nanoseconds as a number. That is the same split the +// stdlib makes between slog.NewTextHandler and slog.NewJSONHandler: the +// console line is read by a person, the json line by a program. +func attrsToText(attrs []slog.Attr) string { + var out strings.Builder + for _, attr := range attrs { + appendAttrText(&out, "", attr) + } + + return out.String() +} + +func appendAttrText(out *strings.Builder, prefix string, attr slog.Attr) { + value := attr.Value.Resolve() + if attr.Key == "" && value.Any() == nil { + return + } + + if value.Kind() == slog.KindGroup { + group := value.Group() + if len(group) == 0 { + return + } + + nested := prefix + if attr.Key != "" { + nested = prefix + attr.Key + "." + } + + for _, member := range group { + appendAttrText(out, nested, member) + } + + return + } + + out.WriteString(" ") + // The key is quoted on the same terms as the value, and as a whole + // including its group prefix, because that is the token a reader has to + // find the "=" in. slog.NewTextHandler quotes "prefix+key" the same way, + // so a key like "a=b" reads as "a=b"=v2 rather than the ambiguous + // a=b=v2, which parses as the key "a" with the value "b=v2". + out.WriteString(quoteIfNeeded(prefix + attr.Key)) + out.WriteString("=") + out.WriteString(quoteIfNeeded(value.String())) +} + +// quoteIfNeeded quotes a key or a value, as slog.NewTextHandler does, when +// leaving it bare would make the key=value pairs ambiguous or would write a +// control character or invalid UTF-8 to the terminal. Unlike the stdlib, it +// also quotes DEL (0x7f), which is a control character too. +func quoteIfNeeded(text string) string { + if text == "" { + return `""` + } + + // Ranging over a string yields utf8.RuneError for each invalid byte; + // strconv.Quote then escapes that byte, as in "bad\xffkey". + for _, r := range text { + if unicode.IsSpace(r) || !unicode.IsPrint(r) || + r == utf8.RuneError || r == '"' || r == '=' { + return strconv.Quote(text) + } + } + + return text +} 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") +} diff --git a/console_handler.go b/console_handler.go index 264b53e..f26c209 100644 --- a/console_handler.go +++ b/console_handler.go @@ -16,7 +16,9 @@ import ( const callerSkipFrames = 4 // ConsoleHandler writes human-readable, colored log lines to stdout. -type ConsoleHandler struct{} +type ConsoleHandler struct { + attrs handlerAttrs +} // NewConsoleHandler returns a new ConsoleHandler. func NewConsoleHandler() *ConsoleHandler { @@ -24,7 +26,8 @@ func NewConsoleHandler() *ConsoleHandler { } // Handle writes the record to stdout as a colored, timestamped line -// including the caller file and line. +// including the caller file and line, followed by the attributes as +// key=value pairs. func (c *ConsoleHandler) Handle( _ context.Context, record slog.Record, @@ -56,12 +59,13 @@ func (c *ConsoleHandler) Handle( _, _ = fmt.Fprintln( os.Stdout, colorFunc( - "%s [%s] %s:%d: %s", + "%s [%s] %s:%d: %s%s", timestamp, record.Level, file, line, record.Message, + attrsToText(c.attrs.forRecord(record)), ), ) @@ -77,12 +81,22 @@ func (c *ConsoleHandler) Enabled( return true } -// WithAttrs returns the handler unchanged; attributes are not rendered. -func (c *ConsoleHandler) WithAttrs(_ []slog.Attr) slog.Handler { - return c +// WithAttrs returns a new handler that also emits attrs, qualified by the +// groups open now. The receiver is not modified. +func (c *ConsoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return c + } + + return &ConsoleHandler{attrs: c.attrs.withAttrs(attrs)} } -// WithGroup returns the handler unchanged; groups are not rendered. -func (c *ConsoleHandler) WithGroup(_ string) slog.Handler { - return c +// WithGroup returns a new handler that qualifies later attributes with +// the group name. An empty name returns the receiver. +func (c *ConsoleHandler) WithGroup(name string) slog.Handler { + if name == "" { + return c + } + + return &ConsoleHandler{attrs: c.attrs.withGroup(name)} } diff --git a/json_handler.go b/json_handler.go index d66c3d6..093e503 100644 --- a/json_handler.go +++ b/json_handler.go @@ -9,16 +9,19 @@ import ( ) // JSONHandler writes each log record to stdout as a JSON document. -type JSONHandler struct{} +type JSONHandler struct { + attrs handlerAttrs +} // NewJSONHandler returns a new JSONHandler. func NewJSONHandler() *JSONHandler { return &JSONHandler{} } -// Handle marshals the record to JSON and writes it to stdout. +// Handle marshals the record, with its attributes, to one JSON object and +// writes it to stdout. func (j *JSONHandler) Handle(_ context.Context, record slog.Record) error { - jsonData, err := json.Marshal(record) + jsonData, err := json.Marshal(recordToMap(record, j.attrs)) if err != nil { return err } @@ -34,12 +37,22 @@ func (j *JSONHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } -// WithAttrs returns the handler unchanged; attributes are not rendered. -func (j *JSONHandler) WithAttrs(_ []slog.Attr) slog.Handler { - return j +// WithAttrs returns a new handler that also emits attrs, qualified by the +// groups open now. The receiver is not modified. +func (j *JSONHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return j + } + + return &JSONHandler{attrs: j.attrs.withAttrs(attrs)} } -// WithGroup returns the handler unchanged; groups are not rendered. -func (j *JSONHandler) WithGroup(_ string) slog.Handler { - return j +// WithGroup returns a new handler that nests later attributes in an +// object named after the group. An empty name returns the receiver. +func (j *JSONHandler) WithGroup(name string) slog.Handler { + if name == "" { + return j + } + + return &JSONHandler{attrs: j.attrs.withGroup(name)} } diff --git a/webhook_handler.go b/webhook_handler.go index 7213b6c..d73f9ad 100644 --- a/webhook_handler.go +++ b/webhook_handler.go @@ -14,6 +14,7 @@ import ( // URL. type WebhookHandler struct { webhookURL string + attrs handlerAttrs } // NewWebhookHandler returns a WebhookHandler that delivers records to @@ -33,19 +34,36 @@ func (w *WebhookHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } -// WithAttrs returns the handler unchanged; attributes are not rendered. -func (w *WebhookHandler) WithAttrs(_ []slog.Attr) slog.Handler { - return w +// WithAttrs returns a new handler that also emits attrs, qualified by the +// groups open now. The receiver is not modified. +func (w *WebhookHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return w + } + + return &WebhookHandler{ + webhookURL: w.webhookURL, + attrs: w.attrs.withAttrs(attrs), + } } -// WithGroup returns the handler unchanged; groups are not rendered. -func (w *WebhookHandler) WithGroup(_ string) slog.Handler { - return w +// WithGroup returns a new handler that nests later attributes in an +// object named after the group. An empty name returns the receiver. +func (w *WebhookHandler) WithGroup(name string) slog.Handler { + if name == "" { + return w + } + + return &WebhookHandler{ + webhookURL: w.webhookURL, + attrs: w.attrs.withGroup(name), + } } -// Handle marshals the record to JSON and POSTs it to the webhook URL. +// Handle marshals the record, with its attributes, to one JSON object and +// POSTs it to the webhook URL. func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error { - jsonData, err := json.Marshal(record) + jsonData, err := json.Marshal(recordToMap(record, w.attrs)) if err != nil { return fmt.Errorf("error marshaling event: %w", err) }