amadan
Stop guessing how a value prints: scan what the real handlers emit
Third shape of this scanner, and the first that is not a guess. The
first hand-wrote a renderer and asserted the []byte type. The second
swapped in a reflect kind check and added encoding.TextMarshaler and
json.Marshaler. Review found ten more forms the second still missed,
which settles the question: this is not a list anyone finishes by hand.
The reason it cannot be finished is that JSONHandler does not call
MarshalJSON. It calls json.Marshal on the whole value, which walks
exported fields, slice elements, map values and pointers to any depth
and honours MarshalText at every one of them, while fmt — and so
slog.Value.String — consults String() at the top level and stops. So a
struct with an exported Address and a redacting String() leaks under
JSONHandler and reads clean to a hand-written renderer. So does a
slice of them, a map of them, a nested struct, a LogValuer resolving
to one, and a plain *string: fmt prints the pointer's hex, JSON prints
the string. In the other direction, TextHandler formats with %+v while
Value.String uses %v, so a fmt.Formatter can say more to production
than to the scanner.
Two more that were wrong in kind, not degree. A marshal FAILURE is not
silence — both stock handlers write "!ERROR: …", and an error text
routinely quotes the value that failed, so a MarshalText returning
errors.New("cannot marshal "+addr) printed the address in production
and person#42 here. And the hand-written renderer PANICKED where
production does not: stock slog recovers, printing <nil> for a nil
pointer with a value-receiver marshaller and "!PANIC: …" otherwise,
while this took the test binary down with a stack trace.
So the recorder now fans every record through a real slog.TextHandler
and a real slog.JSONHandler and scans their bytes. It cannot drift
from the standard library, it needs no maintenance when a new
interface is honoured, and it inherits slog's own panic recovery for
free. render and appendAttr are gone. encodings gains the
strconv.Quote form, since TextHandler quotes a value that needs it.
Separately: a declared route that answers 404 or 405 never ran its
handler, so whatever it logs went unscanned — the same "pass by not
looking" the zero-routes check already guards, one level down. It is
now an error rather than a comment. A regex-constrained parameter is
the cause it will have: the canary does not satisfy {id:[0-9]+}, and
fillParams mangles the nested-brace {id:[0-9]{2}} instead of filling
it. Proven by planting both a constrained route and a DELETE-only
route: the constrained one fails loudly, the DELETE-only one passes
because it is now driven with DELETE.
All seven new tests fail against the previous commit's renderer,
including both panic cases, and pass here.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
internal/home/logs_test.go+30 −7internal/home/logtest/logtest.go+85 −132internal/home/logtest/logtest_test.go+120 −0
CI passed — run details
Intent
<task-notification> <task-id>a8f420ce3fe415b9f</task-id> <tool-use-id>toolu_01T3EtmtonjD3Y94zPLCU3ao</tool-use-id> <output-file>/home/paulca/.cache/tmp/claude-1001/-home-paulca-amadan-net-oficina-home/d63f5ac7-6b42-48c5-a13d-34e6faf8e44c/tasks/a8f420ce3fe415b9f.output</output-file> <status>completed</status> <summary>Agent "Fable re-review: AGENTS.md" finished</summary> <note>A task-notification fires each time this agent stops with no live background children of its own. The user can send it another message and resume it, so the same task-id may notify more than once.</note> <result>VERDICT: CHANGES NEEDED One blocking finding, in the Frontend bullet. The branch's fifth commit is titled "the fix introduced a false reason of the class it removes", and the fix did it again: the replacement reason is false at the pinned version, and the sentence that says the v0.22.0 bump "falsified nothing" is false for the same reason. ## Required change (blocking) **AGENTS.md lines 189–191 and 196–197.** The text says: > "So the rule stands and the justification does not: write classes because that is what the partials we render alongside write, not because the attribute grammar is unreleased." > "The later bump to v0.22.0 changed 130 to 130 and falsified nothing." Counted in `/home/paulca/go/pkg/mod/github.com/carlosframework/rastrillo@*/ui/partials/*.html` (class-spelling = `class="rst-…"` occurrences; attribute-spelling = `rst-xxx=` / bare `rst-xxx` in tags with `class="…"` stripped first): | version | class spelling | attribute spelling | |---|---|---| | v0.20.1-…-ba9e604 (2026-08-30) | 128 | 1 | | v0.21.0 (first pin) | 128 | 1 | | **v0.22.0 (current pin)** | **6** | **118** | | v0.23.0 | 6 | 118 | The shipped partials flipped to the attribute spelling *at v0.22.0*. `ui/partials/callout.html` at v0.22.0 is `<div rst-callout rst-tone="…">`; `field-text.html` is `<div rst-field><label rst-field-label …><input rst-input …>`. This is rastrillo's design-system spec §6-v3 stage 2 ("flip the partials atomically … the breaking release, whose notes mandate a `tokens.css` refresh"); stage 1, the twins in tokens.css, was v0.21.0. So: - "write classes because that is what the partials we render alongside write" is false at the pin. The partials we render alongside write attributes. - The tokens.css header sentence AGENTS.md quotes as evidence — "the class spelling is what every app and every shipped partial writes today" — is quoted verbatim (verified, header lines 19–24) but is stale inside the library at v0.22.0 and v0.23.0; the header was not updated when the partials flipped. The file presents a stale upstream comment as a verified fact. - "The later bump to v0.22.0 … falsified nothing" is wrong. It did not falsify the *old* reason (that died at v0.21.0 — that part of the story is right), but it is exactly the bump that falsifies the *new* one. The rule itself ("write `class="rst-*"`") must stay, because spec §11 rules it and AGENTS.md follows the spec. But the reason must be true or absent. Something like: *write classes because §11 rules it; two reasons this file gave have died — "the attribute grammar is unreleased" (false since v0.21.0, this repo's first pin, where tokens.css pairs every class with an attribute twin) and "the partials write classes" (false since v0.22.0, the current pin, where the shipped partials flipped to the attribute spelling, rastrillo §6-v3 stage 2: 118 attribute vs 6 class occurrences in `ui/partials`). tokens.css's own header still says every partial writes classes; at v0.22.0 that sentence is stale.* **For Paul, not for this file:** rastrillo §6-v3 rules "One spelling, not two. No permanent class fallback" and "drop the class selectors before 1.0". Spec §11 (on both branches) rules the class vocabulary; the springboard branch's reason is "the class vocabulary is what this app uses, and a mixed codebase is worse than either" — but this app has no `rst-` markup at all yet (`page.go` is unstyled), and an app writing classes next to v0.22.0 partials *is* the mixed codebase. Neither branch's reason survives the pin. The ruling predates stage 2 and deserves a re-ruling; that is a spec decision, so I am not requiring it here. ## Item 1 — the tokens.css story, counted Cached `ui/tokens.css`, distinct bare `[rst-*]` selectors / literal `.rst-` occurrences: - v0.17.0, v0.19.0: 0 / 330 - v0.19.1-…(2026-08-30, both), v0.20.0, v0.20.1-…(both): 0 / **528** - **v0.21.0: 129 / 536** (header "TWO SPELLINGS…" first appears) - **v0.22.0: 129 / 536** (two twins renamed: `rst-btn-spin`, `rst-form-foot-note` out; `rst-form-bar`, `rst-form-bar-note` in) - v0.23.0: 130 / 594 (`rst-shell-console` added; header unchanged) `go.mod` on main: `ef8a30f` (2026-08-31) first pinned v0.21.0; `0d0262a` bumped to v0.22.0. So: twins arrived at v0.21.0 — right; first pin was v0.21.0 — right; "0 bare selectors and 528 class occurrences" on 2026-08-30 — right (that is v0.20.0 and every 2026-08-30 pseudo-version before ba9e604); "already false by the time the skeleton existed" — right. **Nit on "130 distinct ones"** (line 183, and the springboard spec line 674): strictly 129 distinct bare selectors. 130 is the count of distinct `rst-*` attribute *names* in selectors; the 130th, `rst-tone`, appears only valued (`[rst-tone~="positive"]` etc., 9 occurrences, never bare). Both files say 130, so they agree with each other; fix both or say "130 distinct `rst-*` attributes (129 bare, plus `rst-tone` which is only ever valued)". Nothing scoped to v0.22.0 goes stale at v0.23.0; the file names its version and says to re-check. ## Item 2 — `rastrillo doctor`: verified, one wording fix - `cmd/rastrillo/doctor.go` first appears in the cache at `v0.20.1-0.20260830223713-ba9e604ff80c` (a 2026-08-30 commit after the v0.20.0 tag) and is byte-identical there to v0.21.0's. v0.21.0 is the first *tagged release* carrying it, so "landed in v0.21.0" is accurate as written; `--fix` exists at v0.21.0 (`doctor.go:59`). - No `static/` directory and no `.css` file anywhere in the tree; `internal/home/page.go` lines 10–15 say no stylesheet is linked, deliberately. Verified. - `rastrillo new` does write `internal/<pkg>test/vendored_test.go` containing `TestVendoredAssetsMatchTheLibrary` (`cmd/rastrillo/new.go:137,745`; present since v0.17.0). **But this repo was not scaffolded by `rastrillo new`** (skeleton commit `ef8a30f` was hand-written; there is no `internal/hometest/`, no `vendored_test.go`), so line 202's "**keep** the `TestVendoredAssetsMatchTheLibrary` that `rastrillo new` scaffolds" names a test that does not exist here. Should be "add" (copy the scaffold's). Non-blocking. ## Item 3 — AGENTS.md vs the springboard spec Read the spec at `ba44614` on `spec/springboard-and-corrections` in full. AGENTS.md on this branch contradicts it nowhere: §0, §2.1, §2.2, §3.2–3.4, §4, §5.1, §5.3, §5.4, §5.7, §6, §9.1, §10, §11 numbers, §12 gates 1/2/9, §13 step 1, rulings 2/13/16 — all correspond. Rulings 17/18 (springboard, no activity surface) are not mentioned in AGENTS.md and nothing in it conflicts with them. The one divergence is the *reason* under §11, covered above; neither branch's reason is right. Both branches share the 129/130 nit and the stale `auth_sessions` name below. **Merge order:** this branch's spec is byte-identical to main's, and main's §11 still says "zero bare `rst-*` attribute selectors" and "until `rastrillo doctor` lands". Merging this branch before the springboard branch leaves AGENTS.md contradicting the spec on main, which by AGENTS.md's own line 7–9 makes AGENTS.md "wrong". Merge springboard first, or both together. ## Item 4 — RP ID bullet: accurate, two precision notes - Spec §4 (springboard, lines 258–265) says nearly the same words: WebAuthn permits a suffix RP ID; `oficina.works` would be accepted for `id.oficina.works`; valid at every host in the zone; collapses the split (ruling 2); "The RP ID is the full host, asserted by a test." Ruling 13's surviving half is "the RP ID is always the full host", rejected "a suffix RP ID"; ruling 16 supplies `id.oficina.works`. WebAuthn does permit any registrable-domain suffix of the origin's effective domain, and `oficina.works` is one. Correct. (The bullet cites rulings 2 and 13; the host itself comes from ruling 16 — worth adding the citation.) - `passkey/passkey.go:161` at v0.22.0: `webauthn.Config{RPID: u.Hostname(), Origin: cfg.Origin, LegacyRPID: cfg.LegacyRPID}` — straight pass-through, as claimed. `webauthn/webauthn.go:141–155` `rpMatches` accepts `sha256(LegacyRPID)` in addition to `sha256(RPID)`, constant-time, and `allowLegacy` "is true only for assertions" (line 122); registration never accepts it. So "a second accepted RP ID" is true; the bullet should say "for assertions" — the spec §5.7 does. - Precision: in `passkey.Config` the primary RP ID is **not settable** — it is always `Origin`'s hostname. The "first door" is therefore `Origin` itself (or bypassing `passkey` to build `webauthn.Config` directly), not an RP ID field. "Both halves need the test" holds, but the test asserts `Origin`'s hostname equals `id.oficina.works` and `LegacyRPID` is empty or a full host. Non-blocking. ## Non-blocking items the caller said were taken - **Gate-9 as rule:** taken. §12 gate 9 "scan log lines, error strings and metric labels" and §13 step 1 "Skeleton, `AGENTS.md`, gates 1, 2 and 9" both verified. `cmd/home/main.go` has two `logger.Error` calls and hands the logger to `rastrillo.Serve`, so "already emits log lines" is fair. **Overstated:** line 41 "**which is why** §13 step 1 puts it beside the skeleton" — §13 gives no reason, and puts gates 1 and 2 there too, which AGENTS.md says need a database the skeleton lacks. Drop "which is why". - **`auth_sessions` staleness note: NOT taken.** The Data bullet (lines 165–170) is unchanged from main. At v0.22.0, `auth/store.go:26` says "auth_sessions is no longer written to (session storage moved to the shared sessions package)"; `auth/migrations/0002_sessions_backfill.sql` copies rows into `sessions` and empties `auth_sessions`; `auth/handlers.go:136` still sets `Subject: id.Address`, which lands in `sessions.subject` (`sessions/migrations/0001_init.sql`). So "stores readable addresses in `auth_links` and `auth_sessions` — verified at source" is stale on the second table: readable addresses at rest are `auth_links.address` and `sessions.subject`. The conclusion (hand-roll; opaque Subject) is unaffected, and `auth.Config.Subject` (`auth.go:209`) is the magic-link email subject, not a subject hook, so "no subject-remapping hook" still holds. Same staleness is in spec §5.1 on both branches. Fix the bullet to name `sessions.subject`. - **`§6-v3` attribution:** verbatim from the v0.22.0 header, and §6-v3 is indeed "The markup migration" in rastrillo's `2026-08-28-design-system-design.md`. Attribution correct; the quoted sentence is the stale one above. ## Everything else in the whole file Checked against the springboard spec line by line: the one rule and its falsifiable form (§0), the two lost absolutes (§0, §3.3), the three gates (§12, §13), the four nevers and the §6 quote (§2.2, §6), review/cadence (§12), credential origin (§4), two-sided boundary test and its retraction (§5.4), 120 s and `jti` (§5.3), audience (§5.3), identity exemption (§5.4), prune rule (§9.1), no address column / sealed-before-written / `secure_delete` (§3.2, §5.1, §10), pepper (§6), additive migrations (§10), logs rule including "job status message" (§3.4), zero JS (§11), canary and `X-Carlos-Version` (§12), no hibernation (§2.1), restore drill (§10). All correspond. No further overstatements found beyond those listed.</result> <usage><subagent_tokens>133770</subagent_tokens><tool_uses>26</tool_uses><duration_ms>447437</duration_ms></usage> </task-notification>
diff --git a/internal/home/logs_test.go b/internal/home/logs_test.go| index c5662a9..0f20db5 100644 |
| --- a/internal/home/logs_test.go |
| +++ b/internal/home/logs_test.go |
| @@ -74,8 +74,15 @@ func TestNoContentInLogs(t *testing.T) { |
| type target struct{ method, path string } |
| var targets []target |
| seen := map[target]bool{} |
| - add := func(method, path string) { |
| + // declared marks the (method, path) pairs the router actually |
| + // registered, as opposed to the extra methods and synthetic paths |
| + // driven alongside them. Only those are required to reach a handler. |
| + declared := map[target]bool{} |
| + add := func(method, path string, isDeclared bool) { |
| tg := target{method: method, path: path} |
| + if isDeclared { |
| + declared[tg] = true |
| + } |
| if !seen[tg] { |
| seen[tg] = true |
| targets = append(targets, tg) |
| @@ -88,9 +95,9 @@ func TestNoContentInLogs(t *testing.T) { |
| // chi.URLParam logs content rather than the literal "{team}" — |
| // which is what it logged before, passing the gate. |
| path := fillParams(strings.ReplaceAll(route, "/*", "/x")) |
| - add(method, path) |
| - add(http.MethodGet, path) |
| - add(http.MethodPost, path) |
| + add(method, path, true) |
| + add(http.MethodGet, path, false) |
| + add(http.MethodPost, path, false) |
| return nil |
| }) |
| if err != nil { |
| @@ -101,8 +108,8 @@ func TestNoContentInLogs(t *testing.T) { |
| } |
| // A path that matches nothing, plus a path segment carrying content. |
| for _, p := range []string{"/no-such-route", "/" + url.PathEscape(logtest.Canaries[1])} { |
| - add(http.MethodGet, p) |
| - add(http.MethodPost, p) |
| + add(http.MethodGet, p, false) |
| + add(http.MethodPost, p, false) |
| } |
| for _, tg := range targets { |
| @@ -122,7 +129,23 @@ func TestNoContentInLogs(t *testing.T) { |
| req.Header.Set("X-Forwarded-For", logtest.Canaries[0]) |
| req.AddCookie(&http.Cookie{Name: "team", Value: logtest.Canaries[2]}) |
| - router.ServeHTTP(httptest.NewRecorder(), req) |
| + w := httptest.NewRecorder() |
| + router.ServeHTTP(w, req) |
| + |
| + // A declared route that answers 404 or 405 never ran its |
| + // handler, so anything it logs went unscanned and the gate |
| + // passed by not looking — the failure mode the zero-routes |
| + // check above already guards against, one level down. The |
| + // likeliest cause is a regex-constrained parameter |
| + // ({id:[0-9]+}) that the canary does not satisfy, including |
| + // the nested-brace shape {id:[0-9]{2}}, which fillParams |
| + // mangles rather than fills. Both are silent today; this makes |
| + // them loud on the day someone adds one. |
| + if declared[tg] && (w.Code == http.StatusNotFound || w.Code == http.StatusMethodNotAllowed) { |
| + t.Errorf("%s %s answered %d: the route is declared but its handler never ran, "+ |
| + "so gate 9 did not scan it. If it has a constrained parameter, fillParams "+ |
| + "needs a value that satisfies it.", tg.method, tg.path, w.Code) |
| + } |
| } |
| rec.AssertNoContent(t) |
diff --git a/internal/home/logtest/logtest.go b/internal/home/logtest/logtest.go| index 347c2f6..8037675 100644 |
| --- a/internal/home/logtest/logtest.go |
| +++ b/internal/home/logtest/logtest.go |
| @@ -54,11 +54,10 @@ package logtest |
| import ( |
| "context" |
| - "encoding" |
| - "encoding/json" |
| "log/slog" |
| + "math" |
| "net/url" |
| - "reflect" |
| + "strconv" |
| "strings" |
| "sync" |
| "testing" |
| @@ -88,9 +87,57 @@ func NewRecorder() *Recorder { return &Recorder{} } |
| // Handler returns a slog.Handler that records into r. Install it with |
| // slog.New(r.Handler()). |
| -func (r *Recorder) Handler() slog.Handler { return &handler{rec: r} } |
| +// |
| +// It fans every record out through a real slog.TextHandler AND a real |
| +// slog.JSONHandler, and scans what they produce. |
| +// |
| +// This is the third shape of this function and the first that is not a |
| +// guess. The first two hand-wrote a value renderer and tried to |
| +// enumerate the ways a value prints differently in production than |
| +// through slog.Value.String — first the []byte type, then a reflect |
| +// kind check plus encoding.TextMarshaler plus json.Marshaler. Both |
| +// were incomplete, and the second was incomplete in ten ways: any |
| +// struct with an exported field and a redacting String(), a slice or |
| +// map of such values, a *string (fmt prints the pointer, JSON prints |
| +// the string), a value whose MarshalText FAILS (both stock handlers |
| +// print the error text, which contains the value), a fmt.Formatter |
| +// that says more under %+v than %v, and so on. JSONHandler does not |
| +// call MarshalJSON — it calls json.Marshal on the whole value, which |
| +// walks exported fields, elements and map values to any depth and |
| +// honours MarshalText at every one of them. That is not a list anyone |
| +// can finish by hand. |
| +// |
| +// So do not try. The production sinks are these two handlers; run the |
| +// record through them and scan their bytes. It cannot drift from the |
| +// standard library, it needs no maintenance when a new interface is |
| +// honoured, and it inherits slog's own panic recovery — a MarshalText |
| +// that panics prints "!PANIC: …" here exactly as it would in |
| +// production, rather than taking the test binary down. |
| +func (r *Recorder) Handler() slog.Handler { |
| + // Level is set below every real level so nothing is filtered. A |
| + // handler that filtered by level would let a canary logged at Debug |
| + // pass the gate by never being formatted — the gate would succeed |
| + // by not looking. |
| + opts := &slog.HandlerOptions{Level: slog.Level(math.MinInt32)} |
| + w := recorderWriter{rec: r} |
| + return &handler{ |
| + rec: r, |
| + text: slog.NewTextHandler(w, opts), |
| + json: slog.NewJSONHandler(w, opts), |
| + } |
| +} |
| + |
| +// recorderWriter serialises both stock handlers into one buffer. Each |
| +// handler holds its own mutex, so they do not exclude each other. |
| +type recorderWriter struct{ rec *Recorder } |
| -// Text returns every record captured so far, one per line. |
| +func (w recorderWriter) Write(p []byte) (int, error) { |
| + w.rec.mu.Lock() |
| + defer w.rec.mu.Unlock() |
| + return w.rec.buf.Write(p) |
| +} |
| + |
| +// Text returns every record captured so far. |
| func (r *Recorder) Text() string { |
| r.mu.Lock() |
| defer r.mu.Unlock() |
| @@ -133,8 +180,12 @@ func (r *Recorder) found() string { |
| // a scan for the raw form misses it. Case-folding matters because an |
| // address is routinely lowercased before it is hashed, so the lowercased |
| // copy is the one likeliest to reach an error string. |
| +// |
| +// strconv.Quote covers what TextHandler does to a value that needs |
| +// quoting, and what JSONHandler does to one carrying an escape. |
| func encodings(c string) []string { |
| - return []string{c, url.QueryEscape(c), url.PathEscape(c)} |
| + q := strconv.Quote(c) |
| + return []string{c, url.QueryEscape(c), url.PathEscape(c), q[1 : len(q)-1]} |
| } |
| // AssertNoContent fails t if any canary reached a log record, naming |
| @@ -147,150 +198,52 @@ func (r *Recorder) AssertNoContent(t *testing.T) { |
| } |
| } |
| -// handler flattens each record into one scannable line. |
| -// |
| -// An earlier version of this comment claimed JSONHandler drops an error |
| -// attribute's text via json.Marshal. That is false: json_handler.go |
| -// type-asserts error and appends err.Error(). The real reason not to |
| -// reuse a stock handler is narrower — a stock handler formats for a |
| -// reader, and the gate needs a form it can scan, including values whose |
| -// printed form differs from their scanned form (see render). |
| +// handler fans one record out to both stock handlers, and records open |
| +// group names alongside. |
| type handler struct { |
| rec *Recorder |
| - attrs []slog.Attr |
| + text slog.Handler |
| + json slog.Handler |
| groups []string |
| } |
| -// Enabled answers true at every level. A handler that filtered by level |
| -// would let a canary logged at Debug pass the gate by never reaching |
| -// Handle — the gate would succeed by not looking. |
| +// Enabled answers true at every level, for the reason Handler gives. |
| func (h *handler) Enabled(context.Context, slog.Level) bool { return true } |
| -func (h *handler) Handle(_ context.Context, r slog.Record) error { |
| - var b strings.Builder |
| - b.WriteString(r.Message) |
| - // Open groups are scanned too. A group name is a key, and a key is |
| - // as capable of carrying a team slug as a value is — |
| - // logger.WithGroup(team.Slug) is a plausible thing for someone to |
| - // write, and it would otherwise never be looked at. |
| +func (h *handler) Handle(ctx context.Context, r slog.Record) error { |
| + // Open group names are written explicitly. Both stock handlers |
| + // prefix keys with them — "acme.rows=3" — so they are usually |
| + // captured anyway, but slog drops a group with no attributes under |
| + // it, and a group name is caller-supplied: WithGroup(team.Slug) is |
| + // a plausible line to write. Writing it costs a string. |
| for _, g := range h.groups { |
| - b.WriteByte(' ') |
| - b.WriteString(g) |
| + h.rec.write(g) |
| } |
| - for _, a := range h.attrs { |
| - appendAttr(&b, a) |
| + if err := h.text.Handle(ctx, r); err != nil { |
| + return err |
| } |
| - r.Attrs(func(a slog.Attr) bool { |
| - appendAttr(&b, a) |
| - return true |
| - }) |
| - h.rec.write(b.String()) |
| - return nil |
| + // A slog.Record is re-iterable, so handing the same one to a second |
| + // handler is sound. |
| + return h.json.Handle(ctx, r) |
| } |
| -// WithAttrs copies rather than appending in place: slog may call it on |
| -// one handler from several loggers, and append can share a backing array. |
| func (h *handler) WithAttrs(as []slog.Attr) slog.Handler { |
| - n := &handler{rec: h.rec} |
| - n.attrs = append(append([]slog.Attr{}, h.attrs...), as...) |
| - n.groups = append([]string{}, h.groups...) |
| - return n |
| + return &handler{ |
| + rec: h.rec, |
| + text: h.text.WithAttrs(as), |
| + json: h.json.WithAttrs(as), |
| + groups: append([]string{}, h.groups...), |
| + } |
| } |
| -// WithGroup records the name. An earlier version returned h unchanged, |
| -// reasoning that grouping only nests keys while this handler scans |
| -// values. That is true of the values and false of the name: the name is |
| -// caller-supplied, so WithGroup(team.Slug) puts content in the one place |
| -// the scanner was not looking. Keeping it costs a string. |
| func (h *handler) WithGroup(name string) slog.Handler { |
| if name == "" { |
| return h |
| } |
| - n := &handler{rec: h.rec} |
| - n.attrs = append([]slog.Attr{}, h.attrs...) |
| - n.groups = append(append([]string{}, h.groups...), name) |
| - return n |
| -} |
| - |
| -// appendAttr writes one attribute's value, recursing into groups. |
| -// |
| -// Resolve first: a slog.LogValuer can carry content its static type does |
| -// not show, and an unresolved value would be scanned as its wrapper. |
| -// Group attrs arrive as a single attr whose value holds the members, so |
| -// a scanner that does not recurse misses everything inside one. |
| -func appendAttr(b *strings.Builder, a slog.Attr) { |
| - v := a.Value.Resolve() |
| - if v.Kind() == slog.KindGroup { |
| - // Write the group's own key before recursing, for the reason |
| - // WithGroup gives: the name is caller-supplied and can carry |
| - // content on its own. |
| - b.WriteByte(' ') |
| - b.WriteString(a.Key) |
| - for _, g := range v.Group() { |
| - appendAttr(b, g) |
| - } |
| - return |
| - } |
| - b.WriteByte(' ') |
| - b.WriteString(a.Key) |
| - b.WriteByte('=') |
| - b.WriteString(render(v)) |
| -} |
| - |
| -// render returns the union of every form a production handler could |
| -// print, which is not always what slog.Value.String returns. |
| -// |
| -// Three ways a value reads differently in production than through |
| -// Value.String, all failing in the same dangerous direction — readable |
| -// in the log, unreadable to the scanner, so the gate passes on a line |
| -// that leaks: |
| -// |
| -// - A byte slice. slog's TextHandler quotes it as a string, so a queue |
| -// payload logged as []byte is READABLE in production, while |
| -// Value.String goes through fmt.Sprint and yields "[67 65 78 ...]". |
| -// The test is on the KIND, not on the []byte type: json.RawMessage |
| -// is the likeliest type a queue payload actually has, and a type |
| -// assertion to []byte does not match it. slog's own byteSlice check |
| -// is a reflect kind check for precisely this reason, and an earlier |
| -// version of this function asserted the type instead. |
| -// - An encoding.TextMarshaler. TextHandler prefers MarshalText over |
| -// Stringer; Value.String goes through fmt, which prefers Stringer. |
| -// A type whose String() redacts and whose MarshalText() does not |
| -// therefore leaks in production and reads clean here. This is the |
| -// LogValuer bug wearing a different interface. |
| -// - A json.Marshaler, the same trick under JSONHandler, which reaches |
| -// MarshalJSON through json.Marshal. |
| -// |
| -// So take the union rather than choose: any form ANY stock handler could |
| -// emit is a form the scanner has to see. Concatenating them is safe |
| -// because the result is only ever substring-searched, never read. |
| -func render(v slog.Value) string { |
| - if v.Kind() != slog.KindAny { |
| - return v.String() |
| - } |
| - a := v.Any() |
| - var b strings.Builder |
| - b.WriteString(v.String()) |
| - |
| - if rv := reflect.ValueOf(a); rv.IsValid() && |
| - rv.Kind() == reflect.Slice && rv.Type().Elem().Kind() == reflect.Uint8 { |
| - b.WriteByte(' ') |
| - b.Write(rv.Bytes()) |
| - } |
| - // Marshal errors are ignored on purpose: a value that fails to |
| - // marshal prints nothing in production either, so there is nothing |
| - // for the scanner to miss. |
| - if tm, ok := a.(encoding.TextMarshaler); ok { |
| - if t, err := tm.MarshalText(); err == nil { |
| - b.WriteByte(' ') |
| - b.Write(t) |
| - } |
| - } |
| - if jm, ok := a.(json.Marshaler); ok { |
| - if j, err := jm.MarshalJSON(); err == nil { |
| - b.WriteByte(' ') |
| - b.Write(j) |
| - } |
| + return &handler{ |
| + rec: h.rec, |
| + text: h.text.WithGroup(name), |
| + json: h.json.WithGroup(name), |
| + groups: append(append([]string{}, h.groups...), name), |
| } |
| - return b.String() |
| } |
diff --git a/internal/home/logtest/logtest_test.go b/internal/home/logtest/logtest_test.go| index f1fe621..2afa493 100644 |
| --- a/internal/home/logtest/logtest_test.go |
| +++ b/internal/home/logtest/logtest_test.go |
| @@ -4,6 +4,7 @@ import ( |
| "encoding/json" |
| "errors" |
| "fmt" |
| + "io" |
| "log/slog" |
| "net/url" |
| "strings" |
| @@ -251,3 +252,122 @@ func TestFoundCatchesACanaryInAnInlineGroupKey(t *testing.T) { |
| t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| } |
| } |
| + |
| +// The cases below are the ones a hand-written value renderer missed. |
| +// Each is a value that a stock slog handler prints readably while |
| +// slog.Value.String does not, which is the shape that lets a leaking |
| +// line pass a green gate. They exist as regressions against ever |
| +// hand-enumerating interfaces again — see Recorder.Handler. |
| + |
| +// person has an exported field and a redacting String. JSONHandler |
| +// calls json.Marshal on the whole value, which walks exported fields |
| +// and never consults String; fmt consults String and stops there. |
| +type person struct{ Address string } |
| + |
| +func (p person) String() string { return "person#42" } |
| + |
| +func TestFoundCatchesAnExportedFieldUnderARedactingString(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", person{Address: Canaries[0]}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +func TestFoundCatchesASliceOfRedactingValues(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("members", "who", []person{{Address: Canaries[0]}}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +func TestFoundCatchesAMapOfRedactingValues(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("members", "who", map[string]person{"a": {Address: Canaries[0]}}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// A pointer to a string: fmt prints the pointer's hex address, JSON |
| +// prints the string. Not contrived — an optional field is a pointer. |
| +func TestFoundCatchesAStringPointer(t *testing.T) { |
| + r := NewRecorder() |
| + addr := Canaries[0] |
| + slog.New(r.Handler()).Info("signin", "who", &addr) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// TextHandler formats an opaque value with %+v; slog.Value.String uses |
| +// %v. A Formatter can say more under one than the other. |
| +type verboseOnly struct{ address string } |
| + |
| +func (v verboseOnly) Format(f fmt.State, _ rune) { |
| + if f.Flag('+') { |
| + io.WriteString(f, v.address) |
| + return |
| + } |
| + io.WriteString(f, "person#42") |
| +} |
| + |
| +func TestFoundCatchesAFormatterThatSaysMoreUnderPlusV(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", verboseOnly{address: Canaries[0]}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// A marshal FAILURE is not silence: both stock handlers write the error |
| +// text, and an error text routinely quotes the value that failed. |
| +type failingText struct{ address string } |
| + |
| +func (f failingText) String() string { return "person#42" } |
| +func (f failingText) MarshalText() ([]byte, error) { |
| + return nil, errors.New("cannot marshal " + f.address) |
| +} |
| + |
| +func TestFoundCatchesAnAddressInAMarshalError(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", failingText{address: Canaries[0]}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// valText has a VALUE-receiver MarshalText, so a nil *valText panics if |
| +// the method is called. Stock slog recovers and prints <nil>; a |
| +// hand-written renderer took the whole test binary down instead. |
| +type valText struct{ address string } |
| + |
| +func (v valText) MarshalText() ([]byte, error) { return []byte(v.address), nil } |
| + |
| +type panicText struct{} |
| + |
| +func (panicText) MarshalText() ([]byte, error) { panic("boom") } |
| + |
| +func TestRecorderSurvivesValuesThatPanicWhenMarshalled(t *testing.T) { |
| + for _, tc := range []struct { |
| + name string |
| + v any |
| + }{ |
| + {"nil pointer with a value-receiver MarshalText", (*valText)(nil)}, |
| + {"MarshalText that panics", panicText{}}, |
| + } { |
| + t.Run(tc.name, func(t *testing.T) { |
| + defer func() { |
| + if p := recover(); p != nil { |
| + t.Fatalf("recorder panicked on %s: %v — stock slog recovers, so this must too", tc.name, p) |
| + } |
| + }() |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", tc.v) |
| + if got := r.found(); got != "" { |
| + t.Fatalf("found() = %q, want no canary", got) |
| + } |
| + }) |
| + } |
| +} |