Both handlers discard every slog attribute, so structured logging emits less information than the string logging it replaces #19

Open
opened 2026-08-09 09:55:29 +02:00 by clawbot · 2 comments
Collaborator

Reported by the cattbox manager. Present at upstream main, not just in the released version, so it is not fixed by the retag in #18.

Problem

Both handlers ignore record.Attrs, and both WithAttrs implementations return the receiver unchanged. So:

slog.Info("casting", "device", d, "file", f)

emits the message and silently drops both fields.

Why this is worse than it sounds

CODE_STYLEGUIDE_GO.md mandates this library org-wide, and the compliance sweep currently under way converts string logging into structured attributes. That conversion looks like this:

// before
log.Printf("[%s] Casting %s", device, file)
// after
slog.Info("casting", "device", device, "file", file)

Before the change, the values were at least present in the message text. After it, they are gone entirely. A repo that correctly follows the styleguide ends up with less information in its logs than it had beforehand — and the code will review as correct, because it is correct. The library throws the data away.

Every repo the sweep converts loses log content this way, invisibly.

Definition of done

  • Both handlers serialise record.Attrs — as JSON fields in JSONHandler, in the console format for ConsoleHandler.
  • WithAttrs accumulates rather than returning the receiver, and the accumulated attrs appear on every subsequent record from that logger.
  • WithGroup behaves per the slog.Handler contract, or its non-support is documented explicitly rather than silently ignored.
  • A test asserts that a record carrying attributes produces output containing those keys and values — the test must fail against the current implementation.
  • Tag the result (v1.0.2, with the leading v — see #18) so consuming repos can move off pseudo-version pins in one step.

Sequencing

#18 first: it is a one-command retag that fixes a production hang. This is a code change and should follow. Consuming repos pinning the pseudo-version get the deadlock fix immediately and can pick this up when it lands.

Tracked downstream as cattbox #24.

Reported by the cattbox manager. Present at upstream `main`, not just in the released version, so it is not fixed by the retag in #18. ## Problem Both handlers ignore `record.Attrs`, and both `WithAttrs` implementations return the receiver unchanged. So: ```go slog.Info("casting", "device", d, "file", f) ``` emits the message and **silently drops both fields**. ## Why this is worse than it sounds `CODE_STYLEGUIDE_GO.md` mandates this library org-wide, and the compliance sweep currently under way converts string logging into structured attributes. That conversion looks like this: ```go // before log.Printf("[%s] Casting %s", device, file) // after slog.Info("casting", "device", device, "file", file) ``` Before the change, the values were at least present in the message text. After it, they are gone entirely. **A repo that correctly follows the styleguide ends up with less information in its logs than it had beforehand** — and the code will review as correct, because it is correct. The library throws the data away. Every repo the sweep converts loses log content this way, invisibly. ## Definition of done - Both handlers serialise `record.Attrs` — as JSON fields in `JSONHandler`, in the console format for `ConsoleHandler`. - `WithAttrs` accumulates rather than returning the receiver, and the accumulated attrs appear on every subsequent record from that logger. - `WithGroup` behaves per the `slog.Handler` contract, or its non-support is documented explicitly rather than silently ignored. - A test asserts that a record carrying attributes produces output containing those keys and values — the test must fail against the current implementation. - Tag the result (`v1.0.2`, with the leading `v` — see #18) so consuming repos can move off pseudo-version pins in one step. ## Sequencing #18 first: it is a one-command retag that fixes a production hang. This is a code change and should follow. Consuming repos pinning the pseudo-version get the deadlock fix immediately and can pick this up when it lands. Tracked downstream as cattbox #24.
Author
Collaborator

Implementation plan

Per the owner's request on sneak/cattbox#24, this
lands as a branch off main with exactly two commits and a normal PR to
main:

  1. a commit adding a test that fails against the current code, asserting on
    the bytes the handlers actually emit;
  2. a commit fixing the library so that test passes, with no assertion changed.

The surface to fix

record.Attrs is only half of it. The full set of places attributes can be
dropped:

  • Handle ignoring record.Attrs — the inline
    slog.Info("casting", "device", d) form. Both JSONHandler and
    ConsoleHandler do this today.
  • WithAttrs returning the receiver unchanged in both handlers, so
    attributes attached to a derived logger vanish. It has to return a new
    handler and must not mutate the receiver, so two loggers derived from one
    parent cannot leak attributes into each other.
  • WithGroup — also a no-op receiver return today. Same defect wearing a
    different hat. log/slog defines the semantics (attrs added after
    WithGroup are qualified by the group name), so those get followed rather
    than invented.
  • WebhookHandler — identical code path (json.Marshal(record), WithAttrs
    returning the receiver). It is in the same multiplex, so fixing only two of
    three handlers would leave the same bug live for webhook users.
  • slog.Value resolution: LogValuer values must be Resolve()d rather
    than serialised as a struct, and slog.Group values must nest.

Approach

Stdlib only, no new dependency (log/slog + encoding/json; consistent with
the recorded Go package defaults). A small shared attribute layer:

  • attrs accumulated by WithAttrs are wrapped in the currently-open
    WithGroup groups at the time they are attached, then stored on a copy of
    the handler;
  • for JSONHandler/WebhookHandler they render into a map[string]any with
    groups as nested objects, merged recursively so a group opened twice does
    not produce a duplicate key, then handed to encoding/json;
  • for ConsoleHandler they render as key=value pairs appended to the line,
    groups flattened to dotted keys (group.key=value), quoted only when the
    value needs it.

The JSON top-level keys currently emitted (Time, Level, Message, PC)
stay exactly as they are so existing consumers do not break; attributes join
them as sibling fields, and the record's own fields win a key collision.

Tests

Real emitted output, captured by redirecting os.Stdout through a pipe (and an
httptest server for the webhook handler) — not assertions on internal state.
Separate assertions per handler, since the two output formats differ. Covered:
record attrs, WithAttrs accumulation, sibling non-leakage, WithGroup
nesting, slog.Group values, and LogValuer resolution.

Verification

Repo tooling only: make test while iterating, and make docker for the full
containerised fmt-check + lint + test at the branch head. Commit 1 will be
checked out alone to capture its real failure output for the PR body.

Out of scope, not touched: the retag in
#18, and the lint bump in
#17.

## Implementation plan Per the owner's request on https://git.eeqj.de/sneak/cattbox/issues/24, this lands as a branch off `main` with exactly **two** commits and a normal PR to `main`: 1. a commit adding a test that **fails** against the current code, asserting on the bytes the handlers actually emit; 2. a commit fixing the library so that test passes, with no assertion changed. ### The surface to fix `record.Attrs` is only half of it. The full set of places attributes can be dropped: - `Handle` ignoring `record.Attrs` — the inline `slog.Info("casting", "device", d)` form. Both `JSONHandler` and `ConsoleHandler` do this today. - `WithAttrs` returning the receiver unchanged in both handlers, so attributes attached to a derived logger vanish. It has to return a **new** handler and must not mutate the receiver, so two loggers derived from one parent cannot leak attributes into each other. - `WithGroup` — also a no-op receiver return today. Same defect wearing a different hat. `log/slog` defines the semantics (attrs added after `WithGroup` are qualified by the group name), so those get followed rather than invented. - `WebhookHandler` — identical code path (`json.Marshal(record)`, `WithAttrs` returning the receiver). It is in the same multiplex, so fixing only two of three handlers would leave the same bug live for webhook users. - `slog.Value` resolution: `LogValuer` values must be `Resolve()`d rather than serialised as a struct, and `slog.Group` values must nest. ### Approach Stdlib only, no new dependency (`log/slog` + `encoding/json`; consistent with the recorded Go package defaults). A small shared attribute layer: - attrs accumulated by `WithAttrs` are wrapped in the currently-open `WithGroup` groups at the time they are attached, then stored on a copy of the handler; - for `JSONHandler`/`WebhookHandler` they render into a `map[string]any` with groups as nested objects, merged recursively so a group opened twice does not produce a duplicate key, then handed to `encoding/json`; - for `ConsoleHandler` they render as `key=value` pairs appended to the line, groups flattened to dotted keys (`group.key=value`), quoted only when the value needs it. The JSON top-level keys currently emitted (`Time`, `Level`, `Message`, `PC`) stay exactly as they are so existing consumers do not break; attributes join them as sibling fields, and the record's own fields win a key collision. ### Tests Real emitted output, captured by redirecting `os.Stdout` through a pipe (and an `httptest` server for the webhook handler) — not assertions on internal state. Separate assertions per handler, since the two output formats differ. Covered: record attrs, `WithAttrs` accumulation, sibling non-leakage, `WithGroup` nesting, `slog.Group` values, and `LogValuer` resolution. ### Verification Repo tooling only: `make test` while iterating, and `make docker` for the full containerised `fmt-check` + `lint` + `test` at the branch head. Commit 1 will be checked out alone to capture its real failure output for the PR body. Out of scope, not touched: the retag in https://git.eeqj.de/sneak/simplelog/issues/18, and the lint bump in https://git.eeqj.de/sneak/simplelog/pulls/17.
Author
Collaborator

Built and pushed as #21, two commits
against main in the shape requested on
sneak/cattbox#24:

  • 8c3ab23843f1c1bbccd3da273331bb337a1e3caa — adds attrs_test.go, 13 tests
    that fail against the current code.
  • 412eed0d54550ecec53020a40a834cbf432e2f32 — the fix. No assertion from the
    first commit was touched.

Against the definition of done

  • Both handlers serialise record.Attrs. JSONHandler emits them as
    json object fields; ConsoleHandler appends them as key=value pairs.
    WebhookHandler had the identical defect in the identical code path and is
    reached through the same MultiplexHandler, so it is fixed too — fixing
    two of three would have left it live for anyone with LOGGER_WEBHOOK_URL
    set.
  • WithAttrs accumulates. It returns a new handler and never mutates the
    receiver, so two loggers derived from one parent cannot leak attributes
    into each other. That non-leakage is asserted, per handler.
  • WithGroup behaves per the slog.Handler contract rather than being
    documented away: attributes attached after a WithGroup are qualified by
    it — nested objects in json, dotted group.key=value in console. Its
    documented edge cases are handled: empty Attr ignored, empty group
    elided, empty-keyed group inlined, WithGroup("") a no-op.
  • A test asserts a record's attributes reach the output, and fails against
    the current implementation.
    The assertions read the bytes each handler
    actually writes — os.Stdout through a pipe for console and json, the
    posted body via httptest for the webhook — not internal state. slog.Group
    nesting and slog.LogValuer resolution are covered as well.
  • Tagging v1.0.2 is not something I can do, so it is recorded in
    TODO.md under Future Steps rather than attempted.

The root cause deserves naming: marshaling a slog.Record value cannot ever
work, because a record keeps its attributes in unexported fields, so
encoding/json only ever saw Time, Message, Level and PC. The fix
builds the payload from Record.Attrs instead, resolving values through
slog.Value.Resolve — which also means slog.Any("error", err) now reports
the error message rather than the {} that encoding/json makes of most error
types. No dependency was added; go.mod and go.sum are unchanged.

Verification

Repo tooling only. Commit 1 checked out alone: make test fails, 13 new
failures, e.g. the console handler handed device, file and attempt and
printing ... casting with nothing after it. Branch head: make docker green,
with make fmt-check, make lint and make test all genuinely executing in
the pinned container (no cached layers among them), and make check also green
on the host. Working tree clean. Full pasted output is in the PR body.

Two ignored error returns are now checked explicitly, because current
golangci-lint no longer excludes them by default and make check failed on
them outside the pinned container; that is the only change in the PR that is
not about attributes.

Left alone: the retag in #18 (no tag
created or pushed; the deadlock regression test still passes, since
JSONHandler.Handle still writes straight to os.Stdout and never re-enters
the stdlib log package), and
#17.

Built and pushed as https://git.eeqj.de/sneak/simplelog/pulls/21, two commits against `main` in the shape requested on https://git.eeqj.de/sneak/cattbox/issues/24: - `8c3ab23843f1c1bbccd3da273331bb337a1e3caa` — adds `attrs_test.go`, 13 tests that fail against the current code. - `412eed0d54550ecec53020a40a834cbf432e2f32` — the fix. No assertion from the first commit was touched. ### Against the definition of done - **Both handlers serialise `record.Attrs`.** `JSONHandler` emits them as json object fields; `ConsoleHandler` appends them as `key=value` pairs. `WebhookHandler` had the identical defect in the identical code path and is reached through the same `MultiplexHandler`, so it is fixed too — fixing two of three would have left it live for anyone with `LOGGER_WEBHOOK_URL` set. - **`WithAttrs` accumulates.** It returns a new handler and never mutates the receiver, so two loggers derived from one parent cannot leak attributes into each other. That non-leakage is asserted, per handler. - **`WithGroup` behaves per the `slog.Handler` contract** rather than being documented away: attributes attached after a `WithGroup` are qualified by it — nested objects in json, dotted `group.key=value` in console. Its documented edge cases are handled: empty `Attr` ignored, empty group elided, empty-keyed group inlined, `WithGroup("")` a no-op. - **A test asserts a record's attributes reach the output, and fails against the current implementation.** The assertions read the bytes each handler actually writes — `os.Stdout` through a pipe for console and json, the posted body via `httptest` for the webhook — not internal state. `slog.Group` nesting and `slog.LogValuer` resolution are covered as well. - **Tagging `v1.0.2` is not something I can do**, so it is recorded in `TODO.md` under Future Steps rather than attempted. The root cause deserves naming: marshaling a `slog.Record` value cannot ever work, because a record keeps its attributes in unexported fields, so `encoding/json` only ever saw `Time`, `Message`, `Level` and `PC`. The fix builds the payload from `Record.Attrs` instead, resolving values through `slog.Value.Resolve` — which also means `slog.Any("error", err)` now reports the error message rather than the `{}` that `encoding/json` makes of most error types. No dependency was added; `go.mod` and `go.sum` are unchanged. ### Verification Repo tooling only. Commit 1 checked out alone: `make test` fails, 13 new failures, e.g. the console handler handed `device`, `file` and `attempt` and printing `... casting` with nothing after it. Branch head: `make docker` green, with `make fmt-check`, `make lint` and `make test` all genuinely executing in the pinned container (no cached layers among them), and `make check` also green on the host. Working tree clean. Full pasted output is in the PR body. Two ignored error returns are now checked explicitly, because current golangci-lint no longer excludes them by default and `make check` failed on them outside the pinned container; that is the only change in the PR that is not about attributes. Left alone: the retag in https://git.eeqj.de/sneak/simplelog/issues/18 (no tag created or pushed; the deadlock regression test still passes, since `JSONHandler.Handle` still writes straight to `os.Stdout` and never re-enters the stdlib `log` package), and https://git.eeqj.de/sneak/simplelog/pulls/17.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/simplelog#19