Emit slog attributes from every handler #21
Closed
clawbot
wants to merge 2 commits from
fix/handler-attrs into main
pull from: fix/handler-attrs
merge into: sneak:main
sneak:main
sneak:next
2 Commits
| Author | SHA1 | Message | Date | |
|---|---|---|---|---|
| 430bd76230 |
Emit slog attributes from every handler (closes #19)
The handlers took attributes and dropped them on the floor. Handle never
read record.Attrs, so the inline slog.Info("casting", "device", d) form
lost its fields; WithAttrs returned the receiver unchanged, so anything
attached to a derived logger vanished; and WithGroup did the same, so
grouping silently did nothing. The JSON and webhook handlers marshaled
the slog.Record value directly, which cannot work: a record keeps its
attributes in unexported fields, so encoding/json only ever saw Time,
Message, Level and PC.
The consequence was perverse. Converting log.Printf("[%s] Casting %s",
device, file) into structured attributes, as the Go styleguide asks,
left the output with strictly less information than before, and the
calling code reviewed as correct because it was correct.
A small shared attribute layer now holds the accumulated attributes and
open groups. It is copy-on-write, so two loggers derived from one parent
cannot leak attributes into each other, and it qualifies attributes by
the groups open at the time they were attached, per the slog.Handler
contract. Rendering follows each handler's format: the JSON and webhook
handlers emit attributes as object fields with groups as nested objects,
merging a group named twice rather than duplicating its key; the console
handler appends key=value pairs, groups flattened to dotted keys, with
key and value each quoted where leaving it bare would be ambiguous. The
key is quoted as one token, prefix included, so the "=" that separates
the pair is always the first one outside quotes: a key of "a=b" reads as
"a=b"=v rather than as a=b=v, which parses as the key "a" holding the
value "b=v". That is what slog.NewTextHandler does, and the console
rendering was compared against it key by key.
Values the caller logged go into the json payload by reference, because
rendering only reads them, which leaves the group merge as the one place
a value already in the payload is written to. It merges only into the
unexported groupMap type this package allocates for its own groups: a
caller's map[string]any is a different type and can never satisfy that
type assertion, so it is replaced rather than written into. The
invariant holds by construction - nothing reachable from the caller is
modified by logging it.
Values are resolved through slog.Value.Resolve, so LogValuer values are
reported as the value they stand for instead of as a struct, and errors
are reported as their message rather than as the empty object
encoding/json makes of them. Anything encoding/json cannot marshal falls
back to its slog string form rather than rendering as an empty object.
A duration is nanoseconds as a number in the json and webhook payloads,
matching slog.NewJSONHandler, so a consumer can compare and aggregate
the field without parsing it first. The console line keeps the readable
"3s" form, matching slog.NewTextHandler, because a person reads that
one.
The record's own fields keep the names they have always had - Time,
Level, Message, PC - and win a collision with an attribute key, so
existing consumers of the json output see no change beyond the added
fields. That, and a repeated key keeping its last value - except where
both are groups, which merge - are the two ways an attribute can go
missing from the json output; both are now written down in the README,
merge exception included, rather than left to be discovered.
All three handlers are covered, including WebhookHandler, which had the
same defect and is reached through the same MultiplexHandler.
|
|||
| 3dbe6954d7 |
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.
It also pins the properties a fix must not get wrong on the way past. A
value the caller logged is read and never written to, even when a group
later claims the same key - for maps and for slices, through the record
path and the derived-logger path, in all three handlers. A duration is
a number of nanoseconds in the json payload and the readable "3s" form
on the console. A console key is quoted on the same terms as a console
value, and as one token including its group prefix, so that the "=" that
separates the pair is always the first one outside quotes: a key of
"a=b" reads as "a=b"=v rather than the ambiguous a=b=v. The four
slog.Handler contract edge cases hold: an empty Attr is ignored, an
empty group is elided with its key, a group with an empty key is
inlined, and WithGroup("") is a no-op. And the two rules that follow
from the json payload being an object hold too: the record's own field
names win a collision, and a repeated key keeps its last value - except
where both are groups, which merge - while the console line keeps both.
This commit adds only the test, and it fails. The fix follows.
Refs: #19
|
