Gate 9: prove no address, team name or queue payload reaches a log line
§12 gate 9, the third of the three §13 step 1 owes. It scans what the
app actually logs, driving every route the router declares with
canary-laden input, and fails if an address, team name or queue payload
reaches a log record.
It passes trivially today, and that is the point: the skeleton holds no
content, so the value is as a tripwire for step 2. The day sign-in logs
an address, this goes red. §13 step 1 puts gate 9 beside the skeleton
because a guard written after the code it guards is a guard written to
pass.
The scanner went through three shapes across four review passes, and
the first two were wrong in the same way. Both 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 TextMarshaler plus json.Marshaler. Review
found ten more forms the second still missed, which settled it: the
list cannot be finished by hand, because JSONHandler does not call
MarshalJSON, it calls json.Marshal on the whole value, walking exported
fields, slice elements and map values to any depth and honouring
MarshalText at every one. A struct with an exported Address and a
redacting String() leaks there and reads clean to any hand-written
renderer. So does a plain *string: fmt prints the pointer, JSON prints
the string.
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, needs no maintenance when a new interface is
honoured, and inherits slog's panic recovery — a MarshalText that
panics prints "!PANIC:" here exactly as in production instead of taking
the test binary down.
The route sweep enumerates from the router rather than a hand-list, so
a route added in step 2 is covered without anyone remembering. Route
parameters are filled with a canary, because requesting the pattern
literally meant chi.URLParam returned "{team}" and a handler logging a
team slug passed. Each route is driven with the method it was declared
with, since a DELETE-only route answered 405 to GET and POST and never
ran. And a declared route chi never dispatched is an error, not a
comment — judged by asking chi whether it matched, not by reading the
status, because a handler that answers 404 itself ran perfectly well.
The sink guard resolves identifiers through the file's imports and keys
on the import path, so `import goos "os"; goos.Stderr` no longer walks
past it, and a dot-import of a forbidden package is refused outright
since it leaves no selector to match.
The package doc names what this does NOT cover — metric labels, job
status messages, non-slog sinks, main.go's two logger.Error calls —
because "gate 9 is done" would otherwise be believed.
Every test was checked against the unfixed code first. Reviewed by
Fable across four passes; the first three returned CHANGES NEEDED and
found real bypasses each time, the fourth approved. Two non-blocking
gaps recorded for follow-up: a regex-constrained route inside a Mount
is not detected as undispatched, and a canary embedded in a larger
nested []byte is missed by the base64 phase alignment.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
6 files changed,
+1146
−0
internal/guardstest/logsinks_test.go+121 −0internal/guardstest/logtest_containment_test.go+38 −0internal/guardstest/repo_test.go+132 −0internal/home/logs_test.go+173 −0internal/home/logtest/logtest.go+277 −0internal/home/logtest/logtest_test.go+405 −0
CI passed — run details
Intent
diff --git a/internal/guardstest/logsinks_test.go b/internal/guardstest/logsinks_test.go| new file mode 100644 |
| index 0000000..b55dafc |
| --- /dev/null |
| +++ b/internal/guardstest/logsinks_test.go |
| @@ -0,0 +1,121 @@ |
| +package guards |
| + |
| +import ( |
| + "go/ast" |
| + "go/parser" |
| + "go/token" |
| + "strconv" |
| + "strings" |
| + "testing" |
| +) |
| + |
| +// Gate 9 (§12) scans what this app logs through slog. Anything that |
| +// writes somewhere else is not scanned and cannot be — so the rule is |
| +// that nothing else may write. |
| +// |
| +// This is not theoretical. chi's own middleware.Logger builds |
| +// log.New(os.Stdout, "", log.LstdFlags) at package init and writes the |
| +// request line — URL included — straight to stdout, touching neither |
| +// slog nor the log package default. middleware.Recoverer writes the |
| +// panic and stack to os.Stderr the same way. Either one is the most |
| +// natural thing for someone to reach for when adding request logging in |
| +// step 2, and either one would carry an address past a green gate. |
| +const chiMiddleware = "github.com/go-chi/chi/v5/middleware" |
| + |
| +// forbiddenSelectors are names that write outside slog, keyed by IMPORT |
| +// PATH rather than by the identifier they happen to be spelled with. |
| +// os.Stdout/os.Stderr are the raw sinks; the log package's own printers |
| +// go to its default writer, which is not the recorder either. |
| +// |
| +// Keying on the path is what makes `import goos "os"; goos.Stderr` fail |
| +// too. An earlier version compared the identifier to the literal "os", |
| +// which an alias walks straight past — and which also fired on a local |
| +// variable that happened to be named log. |
| +var forbiddenSelectors = map[string]map[string]string{ |
| + "os": { |
| + "Stdout": "writes outside slog, so gate 9 cannot see it", |
| + "Stderr": "writes outside slog, so gate 9 cannot see it", |
| + }, |
| + "log": { |
| + "New": "builds a logger gate 9 cannot capture; use slog", |
| + "Print": "writes to the log default, not slog", |
| + "Printf": "writes to the log default, not slog", |
| + "Println": "writes to the log default, not slog", |
| + "Fatal": "writes to the log default, not slog", |
| + "Fatalf": "writes to the log default, not slog", |
| + }, |
| +} |
| + |
| +// TestNoLogSinkOutsideSlog fails on any non-test file that imports chi's |
| +// middleware package or names a writer gate 9 cannot observe. |
| +// |
| +// cmd/home/main.go is in scope: it is where a stray fmt.Fprintln(os.Stderr) |
| +// would most plausibly land. os.Exit and os.Getenv are untouched by this |
| +// rule — only the two stream variables are named. |
| +func TestNoLogSinkOutsideSlog(t *testing.T) { |
| + root := repoRoot(t) |
| + for _, path := range goFiles(t, root) { |
| + if strings.HasSuffix(path, "_test.go") { |
| + continue |
| + } |
| + rel := relPath(t, root, path) |
| + |
| + for _, imp := range fileImports(t, path) { |
| + if imp == chiMiddleware { |
| + t.Errorf("%s: imports %q, whose Logger writes to os.Stdout and Recoverer to os.Stderr — neither is visible to gate 9", rel, chiMiddleware) |
| + } |
| + } |
| + |
| + fset := token.NewFileSet() |
| + f, err := parser.ParseFile(fset, path, nil, 0) |
| + if err != nil { |
| + t.Fatalf("guards: parse %s: %v", rel, err) |
| + } |
| + |
| + // Local identifier -> import path, so an alias resolves to the |
| + // package it actually names. |
| + local := map[string]string{} |
| + for _, imp := range f.Imports { |
| + ipath, err := strconv.Unquote(imp.Path.Value) |
| + if err != nil { |
| + t.Fatalf("guards: unquote import in %s: %v", rel, err) |
| + } |
| + name := ipath[strings.LastIndex(ipath, "/")+1:] |
| + if imp.Name != nil { |
| + name = imp.Name.Name |
| + } |
| + // A dot-import puts the package's names in file scope |
| + // unqualified, so os.Stderr becomes a bare Stderr with no |
| + // selector to match. Refuse the import rather than try to |
| + // resolve it. |
| + if name == "." { |
| + if _, forbidden := forbiddenSelectors[ipath]; forbidden { |
| + t.Errorf("%s:%d: dot-imports %q, which hides its sinks from this guard", |
| + rel, fset.Position(imp.Pos()).Line, ipath) |
| + } |
| + continue |
| + } |
| + local[name] = ipath |
| + } |
| + |
| + ast.Inspect(f, func(n ast.Node) bool { |
| + sel, ok := n.(*ast.SelectorExpr) |
| + if !ok { |
| + return true |
| + } |
| + ident, ok := sel.X.(*ast.Ident) |
| + if !ok { |
| + return true |
| + } |
| + ipath, isPackage := local[ident.Name] |
| + if !isPackage { |
| + return true |
| + } |
| + if why, bad := forbiddenSelectors[ipath][sel.Sel.Name]; bad { |
| + t.Errorf("%s:%d: %s.%s (%s) — %s", |
| + rel, fset.Position(sel.Pos()).Line, ident.Name, sel.Sel.Name, ipath, why) |
| + } |
| + return true |
| + }) |
| + } |
| +} |
diff --git a/internal/guardstest/logtest_containment_test.go b/internal/guardstest/logtest_containment_test.go| new file mode 100644 |
| index 0000000..3c12ac6 |
| --- /dev/null |
| +++ b/internal/guardstest/logtest_containment_test.go |
| @@ -0,0 +1,38 @@ |
| +package guards |
| + |
| +import ( |
| + "strings" |
| + "testing" |
| +) |
| + |
| +// logtestImport is gate 9's test helper package. Its own doc comment |
| +// already says this — "this package must never be imported from |
| +// non-test code: doing so would drag the testing package into the |
| +// production binary" — but a comment is not a guard. |
| +const logtestImport = "amadan.net/oficina/home/internal/home/logtest" |
| + |
| +// TestLogtestOnlyImportedByTests fails on any non-_test.go file that |
| +// imports logtest, or anything under it: a future logtest subpackage |
| +// must inherit the rule rather than fall outside it on an exact match. |
| +// |
| +// An earlier version of this comment said the import registers test |
| +// flags on the default flag set. It does not: since Go 1.13 those are |
| +// registered by testing.Init, which only the generated test main calls. |
| +// The true claim is narrower and is the one Sheets' original makes — |
| +// linking testing into a deployed binary is binary hygiene we do not |
| +// want to argue about per-release, and nothing announces it at build |
| +// time. |
| +func TestLogtestOnlyImportedByTests(t *testing.T) { |
| + root := repoRoot(t) |
| + for _, path := range goFiles(t, root) { |
| + if strings.HasSuffix(path, "_test.go") { |
| + continue |
| + } |
| + rel := relPath(t, root, path) |
| + for _, imp := range fileImports(t, path) { |
| + if imp == logtestImport || strings.HasPrefix(imp, logtestImport+"/") { |
| + t.Errorf("%s: imports %q from non-test code (logtest imports testing, so it must stay test-only)", rel, logtestImport) |
| + } |
| + } |
| + } |
| +} |
diff --git a/internal/guardstest/repo_test.go b/internal/guardstest/repo_test.go| new file mode 100644 |
| index 0000000..7e400c6 |
| --- /dev/null |
| +++ b/internal/guardstest/repo_test.go |
| @@ -0,0 +1,132 @@ |
| +// Package guards turns rules that live as prose in AGENTS.md into |
| +// tests. CARLOS's own rule for this: "A guard a shell step can satisfy |
| +// is a guard a shell step can be wrong about — put guards inside the |
| +// test binary." So these run as part of `go test ./...`, not as |
| +// separate shell greps that a CI step could get subtly wrong (or that a |
| +// shell rewrite could quietly stop running). |
| +// |
| +// This file holds the shared plumbing (repo-root discovery, file |
| +// walking, import parsing) that every rule's test file uses. It carries |
| +// no Test functions of its own. The shape is ported from Sheets' |
| +// internal/guardstest/repo_test.go deliberately: two apps disagreeing |
| +// about how to find their own repo root is a bug waiting to differ. |
| +package guards |
| + |
| +import ( |
| + "go/parser" |
| + "go/token" |
| + "os" |
| + "path/filepath" |
| + "runtime" |
| + "strconv" |
| + "strings" |
| + "testing" |
| +) |
| + |
| +// module is the module path declared in this repo's go.mod. Used to |
| +// confirm repoRoot found the right go.mod, not some unrelated one on a |
| +// parent path (e.g. if the worktree lives under another Go module). |
| +const module = "amadan.net/oficina/home" |
| + |
| +// repoRoot locates the module root by walking up from this source |
| +// file's own location (via runtime.Caller), not from the working |
| +// directory. `go test ./...` runs every package's tests with that |
| +// package's own directory as cwd, so cwd is not a reliable anchor — |
| +// runtime.Caller(0) always points back to this file, wherever it was |
| +// invoked from. |
| +func repoRoot(t *testing.T) string { |
| + t.Helper() |
| + _, thisFile, _, ok := runtime.Caller(0) |
| + if !ok { |
| + t.Fatal("guards: runtime.Caller(0) failed") |
| + } |
| + dir := filepath.Dir(thisFile) |
| + for { |
| + if b, err := os.ReadFile(filepath.Join(dir, "go.mod")); err == nil { |
| + if strings.Contains(string(b), "module "+module+"\n") { |
| + return dir |
| + } |
| + } |
| + parent := filepath.Dir(dir) |
| + if parent == dir { |
| + t.Fatalf("guards: no go.mod for module %q found above %s", module, filepath.Dir(thisFile)) |
| + } |
| + dir = parent |
| + } |
| +} |
| + |
| +// skipDir names directories goFiles never descends into: version |
| +// control, dependency/vendor trees, and dotfiles-style tooling |
| +// directories that hold no Go source of ours. Skipping dot-directories |
| +// also keeps .claude/worktrees — which holds full checkouts of this |
| +// same repo — out of the walk, so a guard never reports another |
| +// branch's files as this one's. |
| +func skipDir(name string) bool { |
| + if strings.HasPrefix(name, ".") { |
| + return true |
| + } |
| + switch name { |
| + case "vendor", "node_modules", "testdata": |
| + return true |
| + } |
| + return false |
| +} |
| + |
| +// goFiles returns the path of every *.go file under root. |
| +func goFiles(t *testing.T, root string) []string { |
| + t.Helper() |
| + var files []string |
| + err := filepath.WalkDir(root, func(path string, d os.DirEntry, err error) error { |
| + if err != nil { |
| + return err |
| + } |
| + if d.IsDir() { |
| + if path != root && skipDir(d.Name()) { |
| + return filepath.SkipDir |
| + } |
| + return nil |
| + } |
| + if strings.HasSuffix(path, ".go") { |
| + files = append(files, path) |
| + } |
| + return nil |
| + }) |
| + if err != nil { |
| + t.Fatalf("guards: walk %s: %v", root, err) |
| + } |
| + return files |
| +} |
| + |
| +// relPath is filepath.Rel with the guards-package error-handling |
| +// boilerplate folded in, since every rule needs a repo-relative path |
| +// for its failure messages. |
| +func relPath(t *testing.T, root, path string) string { |
| + t.Helper() |
| + rel, err := filepath.Rel(root, path) |
| + if err != nil { |
| + t.Fatalf("guards: rel %s: %v", path, err) |
| + } |
| + return filepath.ToSlash(rel) |
| +} |
| + |
| +// fileImports returns the import paths a Go source file declares. It |
| +// parses in ImportsOnly mode — the cheapest mode that still sees the |
| +// import block — so walking every file in the tree on every test run |
| +// stays fast. |
| +func fileImports(t *testing.T, path string) []string { |
| + t.Helper() |
| + fset := token.NewFileSet() |
| + f, err := parser.ParseFile(fset, path, nil, parser.ImportsOnly) |
| + if err != nil { |
| + t.Fatalf("guards: parse %s: %v", path, err) |
| + } |
| + imports := make([]string, 0, len(f.Imports)) |
| + for _, imp := range f.Imports { |
| + p, err := strconv.Unquote(imp.Path.Value) |
| + if err != nil { |
| + t.Fatalf("guards: unquote import in %s: %v", path, err) |
| + } |
| + imports = append(imports, p) |
| + } |
| + return imports |
| +} |
diff --git a/internal/home/logs_test.go b/internal/home/logs_test.go| new file mode 100644 |
| index 0000000..d2d0309 |
| --- /dev/null |
| +++ b/internal/home/logs_test.go |
| @@ -0,0 +1,173 @@ |
| +package home |
| + |
| +import ( |
| + "context" |
| + "log" |
| + "log/slog" |
| + "net/http" |
| + "net/http/httptest" |
| + "net/url" |
| + "regexp" |
| + "strings" |
| + "testing" |
| + |
| + "github.com/go-chi/chi/v5" |
| + |
| + "amadan.net/oficina/home/internal/home/logtest" |
| +) |
| + |
| +// TestNoContentInLogs is §12 gate 9 against the app's own surface: it |
| +// drives every route the router declares, with canary-laden input, and |
| +// asserts none of it reaches a log line. Spec §3.4: "no address, team |
| +// name, or queue payload in any log line, error string, job status |
| +// message or metric label." |
| +// |
| +// It passes trivially today — this skeleton logs nothing per request — |
| +// and that is the point. §13 step 1 lists gate 9 beside the skeleton so |
| +// the guard exists before the code it guards. |
| +// |
| +// # What has to stay true for this to keep biting |
| +// |
| +// Routes are enumerated from the router with chi.Walk rather than |
| +// hand-listed, so a route added in step 2 is driven by this test without |
| +// anyone remembering to add it. Three things are still on the author of |
| +// step 2: |
| +// |
| +// - A handler must log through slog.Default() resolved AT CALL TIME, |
| +// or be handed a logger the test can substitute. A logger captured |
| +// into a struct at construction is not reached by SetDefault here. |
| +// Rastrillo resolves slog.Default() at construction, which is why |
| +// its own machinery is outside this gate. |
| +// - A sink that is not slog is invisible. internal/guardstest forbids |
| +// the ones that exist today; a new one needs a new rule there. |
| +// - A route parameter constrained by a regex — {id:[0-9]+} — will not |
| +// match the canary substituted into it, so its route 404s and its |
| +// handler is never driven. There are none today. The day there is |
| +// one, fillParams is where a satisfying value goes. |
| +func TestNoContentInLogs(t *testing.T) { |
| + rec := logtest.NewRecorder() |
| + |
| + // slog.SetDefault also calls log.SetOutput and log.SetFlags(0), and |
| + // restoring a default-handler logger does NOT undo that — the branch |
| + // is skipped. Left alone, every later test in this package would have |
| + // its log output swallowed into a dead recorder. |
| + prevLogger, prevWriter, prevFlags := slog.Default(), log.Writer(), log.Flags() |
| + slog.SetDefault(slog.New(rec.Handler())) |
| + t.Cleanup(func() { |
| + slog.SetDefault(prevLogger) |
| + log.SetOutput(prevWriter) |
| + log.SetFlags(prevFlags) |
| + }) |
| + |
| + app := New() |
| + router := app.Router() |
| + |
| + routes, ok := router.(chi.Routes) |
| + if !ok { |
| + t.Fatalf("Router() is %T, which does not implement chi.Routes: "+ |
| + "this test enumerates routes so new ones are covered automatically", router) |
| + } |
| + |
| + // Each route is driven with the method it was DECLARED with, not |
| + // just GET and POST. A route registered only as DELETE or PATCH |
| + // answers 405 to both, so its handler never runs and whatever it |
| + // logs is never seen. |
| + type target struct{ method, path string } |
| + var targets []target |
| + seen := map[target]bool{} |
| + // 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) |
| + } |
| + } |
| + |
| + err := chi.Walk(routes, func(method string, route string, _ http.Handler, _ ...func(http.Handler) http.Handler) error { |
| + // chi route patterns can carry wildcards; make them fetchable. |
| + // Parameters are filled with a canary so a handler that logs |
| + // 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, true) |
| + add(http.MethodGet, path, false) |
| + add(http.MethodPost, path, false) |
| + return nil |
| + }) |
| + if err != nil { |
| + t.Fatalf("walk routes: %v", err) |
| + } |
| + if len(targets) == 0 { |
| + t.Fatal("walked zero routes: the gate would pass by not looking") |
| + } |
| + // 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, false) |
| + add(http.MethodPost, p, false) |
| + } |
| + |
| + for _, tg := range targets { |
| + // Sign-in will be a POST with the address in the form body, so |
| + // the body is driven, not just the URL. |
| + body := strings.NewReader(url.Values{ |
| + "address": {logtest.Canaries[0]}, |
| + "team": {logtest.Canaries[1]}, |
| + }.Encode()) |
| + |
| + req := httptest.NewRequest(tg.method, tg.path+"?q="+url.QueryEscape(logtest.Canaries[0]), body) |
| + req.Header.Set("Content-Type", "application/x-www-form-urlencoded") |
| + // The headers most likely to be logged wholesale by a future |
| + // request logger, each carrying content that must never appear. |
| + req.Header.Set("Referer", "https://"+logtest.Canaries[1]+".example.invalid") |
| + req.Header.Set("User-Agent", logtest.Canaries[0]) |
| + req.Header.Set("X-Forwarded-For", logtest.Canaries[0]) |
| + req.AddCookie(&http.Cookie{Name: "team", Value: logtest.Canaries[2]}) |
| + |
| + // Ask chi whether it DISPATCHED, rather than reading the status |
| + // the handler chose. A handler that answers 404 itself — which |
| + // is what a directory route does for an unknown team slug, and |
| + // so the first real route step 2 adds — ran perfectly well and |
| + // was scanned. Judging by status code would fail it with a |
| + // diagnosis pointing at fillParams, which is the opposite of |
| + // what happened. RoutePattern is empty only when nothing matched. |
| + rctx := chi.NewRouteContext() |
| + req = req.WithContext(context.WithValue(req.Context(), chi.RouteCtxKey, rctx)) |
| + w := httptest.NewRecorder() |
| + router.ServeHTTP(w, req) |
| + |
| + // A declared route that chi never dispatched ran no handler, so |
| + // anything it logs went unscanned and the gate passed by not |
| + // looking — the failure mode the zero-routes check above guards, |
| + // one level down. The cause will be a regex-constrained |
| + // parameter ({id:[0-9]+}) the canary does not satisfy, or the |
| + // nested-brace shape {id:[0-9]{2}}, which fillParams mangles |
| + // rather than fills. Both are silent today; this makes them loud. |
| + if declared[tg] && rctx.RoutePattern() == "" { |
| + t.Errorf("%s %s was declared but chi matched no route, so its handler never ran "+ |
| + "and gate 9 did not scan it. If it has a constrained parameter, fillParams "+ |
| + "needs a value that satisfies it.", tg.method, tg.path) |
| + } |
| + } |
| + |
| + rec.AssertNoContent(t) |
| +} |
| + |
| +// chiParam matches one chi route parameter, {team} or {id:[0-9]+}. |
| +var chiParam = regexp.MustCompile(`\{[^{}]*\}`) |
| + |
| +// fillParams substitutes a canary for every route parameter. |
| +// |
| +// Without it the test requests the pattern literally, so chi.URLParam |
| +// returns "{team}" and a handler that logs the team slug from the path |
| +// passes the gate — while in production it logs a real team name. A team |
| +// slug in a path is the likeliest shape for the directory's own routes. |
| +func fillParams(pattern string) string { |
| + return chiParam.ReplaceAllLiteralString(pattern, url.PathEscape(logtest.Canaries[1])) |
| +} |
diff --git a/internal/home/logtest/logtest.go b/internal/home/logtest/logtest.go| new file mode 100644 |
| index 0000000..9ea52a7 |
| --- /dev/null |
| +++ b/internal/home/logtest/logtest.go |
| @@ -0,0 +1,277 @@ |
| +// Package logtest is §12 gate 9, "no-content-in-logs": it proves, by |
| +// capturing what the app actually logs, that no address, team name or |
| +// queue payload reaches a log line. |
| +// |
| +// The rule is the design spec's §3.4: "no address, team name, or queue |
| +// payload in any log line, error string, job status message or metric |
| +// label. Errors carry person refs and codes. Test-enforced (§12 gate |
| +// 9)." The reasoning is that logs are storage, and storage we do not |
| +// control is storage we cannot redact — AGENTS.md's own phrasing is |
| +// "Platform-held logs are storage we cannot grep." |
| +// |
| +// Cite §3.4 rather than AGENTS.md for the four-sink list: AGENTS.md on |
| +// this branch still names three, and gains the fourth only when |
| +// fix/agents-md-matches-spec lands. |
| +// |
| +// # What it does not cover |
| +// |
| +// Named in full, because "gate 9 is done" would otherwise be believed. |
| +// §3.4 lists four sinks — log line, error string, job status message, |
| +// metric label — and this covers one and a half of them. |
| +// |
| +// - Log lines: only those routed through slog. A sink that writes to |
| +// os.Stdout or os.Stderr directly is invisible here. chi's own |
| +// middleware.Logger is exactly such a sink (it builds |
| +// log.New(os.Stdout, ...) at init), which is why |
| +// internal/guardstest forbids importing it. |
| +// - Error strings: only transitively, when an error is logged. An |
| +// error string rendered into an HTTP response is not scanned. |
| +// - Job status messages: not covered. There is no queue yet; when |
| +// there is, rastrillo's jobs package turns err.Error() into a |
| +// status message the owner sees, and that needs its own assertion. |
| +// - Metric labels: not covered. This app exports no metrics. |
| +// |
| +// Also uncovered: cmd/home/main.go's two logger.Error calls, which run |
| +// outside any handler with no seam to drive from a test; and anything |
| +// logged by rastrillo's own machinery, since this drives the app router |
| +// directly rather than rastrillo's handler chain. Rastrillo resolves |
| +// slog.Default() at CONSTRUCTION, so swapping the default afterwards |
| +// does not capture a logger it already holds. |
| +// |
| +// # Why it passes trivially today |
| +// |
| +// The skeleton holds no content and takes no user input, so there is |
| +// nothing yet to leak. Its value is as a tripwire for §13 step 2: the |
| +// day sign-in logs an address, this fails. §13 step 1 lists gate 9 |
| +// alongside the skeleton for exactly that reason — a guard written |
| +// after the code it guards is a guard written to pass. |
| +// |
| +// AssertNoContent takes a *testing.T, so this package must never be |
| +// imported from non-test code: doing so would drag the testing package |
| +// into the production binary. internal/sheets/sealtest carries the same |
| +// warning for the same reason. |
| +package logtest |
| + |
| +import ( |
| + "context" |
| + "encoding/base64" |
| + "fmt" |
| + "log/slog" |
| + "math" |
| + "net/url" |
| + "strconv" |
| + "strings" |
| + "sync" |
| + "testing" |
| +) |
| + |
| +// Canaries are the strings a test seeds into the app before asserting. |
| +// Any of them reaching a log record — as the message, as an attribute |
| +// value, or nested inside a group — is a content leak. |
| +// |
| +// One per sink named in §3.4. They are deliberately unlike anything the |
| +// app would otherwise log, so a match is a leak and never a coincidence. |
| +var Canaries = []string{ |
| + "CANARY-ADDRESS-a41f@example.invalid", |
| + "CANARY-TEAM-NAME-7c2e", |
| + "CANARY-QUEUE-PAYLOAD-93bd", |
| +} |
| + |
| +// Recorder collects everything logged through the handler it hands out. |
| +// The zero value is not usable; call NewRecorder. |
| +type Recorder struct { |
| + mu sync.Mutex |
| + buf strings.Builder |
| +} |
| + |
| +// NewRecorder returns a Recorder ready to hand out handlers. |
| +func NewRecorder() *Recorder { return &Recorder{} } |
| + |
| +// Handler returns a slog.Handler that records into r. Install it with |
| +// slog.New(r.Handler()). |
| +// |
| +// 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. |
| +// |
| +// One precision: production is slog's own default handler, since |
| +// cmd/home/main.go never configures one and rastrillo falls back to |
| +// slog.Default(). That handler renders values the way TextHandler does, |
| +// so scanning both handlers is a superset of what production emits, not |
| +// a different set. |
| +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 } |
| + |
| +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() |
| + return r.buf.String() |
| +} |
| + |
| +func (r *Recorder) write(line string) { |
| + r.mu.Lock() |
| + defer r.mu.Unlock() |
| + r.buf.WriteString(line) |
| + r.buf.WriteByte('\n') |
| +} |
| + |
| +// found returns the first canary present in what was captured, or "". |
| +// |
| +// It is the detection primitive, kept separate from AssertNoContent so |
| +// this package's own tests can drive a deliberate leak: a failing |
| +// subtest always fails its parent, so a scanner exercised only through |
| +// a live *testing.T could never be proven to detect anything while |
| +// leaving the suite green. |
| +func (r *Recorder) found() string { |
| + text := r.Text() |
| + lower := strings.ToLower(text) |
| + for _, c := range Canaries { |
| + for _, v := range encodings(c) { |
| + if strings.Contains(text, v) || strings.Contains(lower, strings.ToLower(v)) { |
| + return c |
| + } |
| + } |
| + } |
| + return "" |
| +} |
| + |
| +// encodings returns the forms a canary can legitimately take on its way |
| +// into a log line. A transformed leak is still a leak. |
| +// |
| +// Percent-encoding is not hypothetical: a request logger that prints |
| +// r.URL, r.RequestURI or RawQuery — the usual first thing anyone adds — |
| +// logs an address from a query string as CANARY%40example.invalid, and |
| +// 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. (JSONHandler escapes the same characters for the forms these |
| +// canaries take; the two differ only on control characters, which none |
| +// of them carry.) |
| +// |
| +// The base64 and decimal-byte forms are there because a []byte NESTED in |
| +// something — a struct field, a slice element, a map value — is printed |
| +// by JSONHandler as base64 and by TextHandler as "[67 65 78 …]", and |
| +// neither resembles the canary. A job struct carrying a Payload []byte |
| +// and logged whole with slog.Any is more likely than logging the bare |
| +// slice, and the queue payload is the sink this package singled out as |
| +// most likely to arrive as bytes. |
| +func encodings(c string) []string { |
| + q := strconv.Quote(c) |
| + b := []byte(c) |
| + return []string{ |
| + c, |
| + url.QueryEscape(c), |
| + url.PathEscape(c), |
| + q[1 : len(q)-1], |
| + base64.StdEncoding.EncodeToString(b), |
| + base64.RawStdEncoding.EncodeToString(b), |
| + base64.URLEncoding.EncodeToString(b), |
| + fmt.Sprint(b), |
| + } |
| +} |
| + |
| +// AssertNoContent fails t if any canary reached a log record, naming |
| +// the canary and dumping everything captured so the offending line is |
| +// visible without a second run. |
| +func (r *Recorder) AssertNoContent(t *testing.T) { |
| + t.Helper() |
| + if c := r.found(); c != "" { |
| + t.Fatalf("gate 9: %q reached a log line.\ncaptured:\n%s", c, r.Text()) |
| + } |
| +} |
| + |
| +// handler fans one record out to both stock handlers, and records open |
| +// group names alongside. |
| +type handler struct { |
| + rec *Recorder |
| + text slog.Handler |
| + json slog.Handler |
| + groups []string |
| +} |
| + |
| +// 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(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 { |
| + h.rec.write(g) |
| + } |
| + if err := h.text.Handle(ctx, r); err != nil { |
| + return err |
| + } |
| + // A slog.Record is re-iterable, so handing the same one to a second |
| + // handler is sound. |
| + return h.json.Handle(ctx, r) |
| +} |
| + |
| +func (h *handler) WithAttrs(as []slog.Attr) slog.Handler { |
| + return &handler{ |
| + rec: h.rec, |
| + text: h.text.WithAttrs(as), |
| + json: h.json.WithAttrs(as), |
| + groups: append([]string{}, h.groups...), |
| + } |
| +} |
| + |
| +func (h *handler) WithGroup(name string) slog.Handler { |
| + if name == "" { |
| + return h |
| + } |
| + return &handler{ |
| + rec: h.rec, |
| + text: h.text.WithGroup(name), |
| + json: h.json.WithGroup(name), |
| + groups: append(append([]string{}, h.groups...), name), |
| + } |
| +} |
diff --git a/internal/home/logtest/logtest_test.go b/internal/home/logtest/logtest_test.go| new file mode 100644 |
| index 0000000..1a903d8 |
| --- /dev/null |
| +++ b/internal/home/logtest/logtest_test.go |
| @@ -0,0 +1,405 @@ |
| +package logtest |
| + |
| +import ( |
| + "encoding/json" |
| + "errors" |
| + "fmt" |
| + "io" |
| + "log/slog" |
| + "net/url" |
| + "strings" |
| + "testing" |
| +) |
| + |
| +// found is the detection primitive every test here drives. It is |
| +// exercised directly rather than through AssertNoContent because a |
| +// failing subtest always fails its parent: routing a deliberate leak |
| +// through a live *testing.T would leave this package unable to go |
| +// green. internal/sheets/sealtest splits leaked/findLeak from its |
| +// assertion for the same reason. |
| + |
| +func TestFoundCatchesACanaryInTheMessage(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("sending to " + Canaries[0]) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +func TestFoundCatchesACanaryInATopLevelAttr(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("upsert", "team", Canaries[1]) |
| + if got := r.found(); got != Canaries[1] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| + } |
| +} |
| + |
| +// A leak inside a group is the one a naive scanner misses: slog.Record's |
| +// Attrs walk yields the group as a single attr, and its members are only |
| +// reachable by recursing into Value.Group(). |
| +func TestFoundCatchesACanaryNestedInAGroup(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("enqueue", |
| + slog.Group("job", slog.String("payload", Canaries[2]))) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| +} |
| + |
| +// The skeleton's only real logging is logger.Error("resolve", "err", err), |
| +// so an address reaching a log line will most likely arrive wrapped in an |
| +// error. A JSON handler would hide this: json.Marshal of a plain error |
| +// yields {} and drops the text entirely. |
| +func TestFoundCatchesACanaryInsideAWrappedError(t *testing.T) { |
| + r := NewRecorder() |
| + err := fmt.Errorf("resolve: %w", errors.New("no mailbox for "+Canaries[0])) |
| + slog.New(r.Handler()).Error("resolve", "err", err) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// Attrs bound by With() are preformatted by the handler and never appear |
| +// in the Record, so a scanner that only walks the Record misses them. |
| +func TestFoundCatchesACanaryBoundByWith(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).With("addr", Canaries[0]).Info("start") |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +func TestFoundCatchesACanaryUnderWithGroup(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).WithGroup("mail").Info("queued", "to", Canaries[0]) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// A LogValuer can carry content that formatting the value plainly does |
| +// not show, so values must be resolved before they are scanned. |
| +// |
| +// The String method is what makes this test bite. Without it, fmt.Sprint |
| +// of the struct renders its field and an unresolved scan finds the |
| +// canary by accident — the test would pass even with Resolve removed, |
| +// proving nothing. With it, the unresolved form is "REDACTED" and only a |
| +// scanner that resolves sees the canary, which is exactly what slog's |
| +// real handlers do before printing. |
| +type valuer struct{ s string } |
| + |
| +func (v valuer) String() string { return "REDACTED" } |
| + |
| +func (v valuer) LogValue() slog.Value { return slog.StringValue(v.s) } |
| + |
| +func TestFoundResolvesLogValuers(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("person", "who", valuer{Canaries[1]}) |
| + if got := r.found(); got != Canaries[1] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| + } |
| +} |
| + |
| +func TestFoundReportsNothingForCleanLogs(t *testing.T) { |
| + r := NewRecorder() |
| + l := slog.New(r.Handler()) |
| + l.Info("serve", "port", 8080) |
| + l.Error("resolve", "err", errors.New("socket path missing")) |
| + l.With("app", "home").WithGroup("db").Info("open", "path", "/var/lib/home.db") |
| + if got := r.found(); got != "" { |
| + t.Fatalf("found() = %q, want no leak", got) |
| + } |
| +} |
| + |
| +// Enabled must answer true at every level, or a canary logged at Debug |
| +// would never reach Handle and the gate would pass by not looking. |
| +func TestRecorderIsEnabledAtEveryLevel(t *testing.T) { |
| + r := NewRecorder() |
| + l := slog.New(r.Handler()) |
| + l.Debug("debug " + Canaries[0]) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q at Debug, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +func TestCanariesAreDistinctAndNonEmpty(t *testing.T) { |
| + seen := map[string]bool{} |
| + for _, c := range Canaries { |
| + if c == "" { |
| + t.Fatal("a canary is empty: it would match every log line") |
| + } |
| + if seen[c] { |
| + t.Fatalf("duplicate canary %q", c) |
| + } |
| + seen[c] = true |
| + } |
| + if len(Canaries) < 3 { |
| + t.Fatalf("got %d canaries, want one each for address, team name and queue payload", len(Canaries)) |
| + } |
| +} |
| + |
| +// A queue payload is the sink most likely to arrive as a byte slice, and |
| +// it fails in the dangerous direction: slog's text handler quotes []byte |
| +// as a string, so it is READABLE in production, while fmt.Sprint renders |
| +// it as "[67 65 78 ...]". A scanner using Value.String finds nothing on a |
| +// line that leaks. |
| +func TestFoundCatchesAByteSlicePayload(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("enqueue", "payload", []byte(Canaries[2])) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| +} |
| + |
| +// The first request logger anyone adds prints r.URL or RawQuery, so an |
| +// address arriving in a query string reaches the log percent-encoded. |
| +// An encoded address is an address. |
| +func TestFoundCatchesAPercentEncodedAddress(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("req", "url", "/?q="+url.QueryEscape(Canaries[0])) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// An address is routinely lowercased before it is hashed, so the |
| +// lowercased copy is the one likeliest to reach an error string. |
| +func TestFoundCatchesALowercasedCanary(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Error("hash", "err", "failed to hash "+strings.ToLower(Canaries[1])) |
| + if got := r.found(); got != Canaries[1] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| + } |
| +} |
| + |
| +// payloadBytes is a NAMED byte slice with no marshaller of its own — |
| +// the plain form of the type a queue payload has in practice. It exists |
| +// because v.Any().([]byte) does not match it while slog's own |
| +// reflect-kind check does, so an assertion-based render read it as |
| +// "[67 65 78 ...]" and the gate passed on a readable line. |
| +type payloadBytes []byte |
| + |
| +func TestFoundCatchesANamedByteSlicePayload(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("enqueue", "payload", payloadBytes(Canaries[2])) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| +} |
| + |
| +// json.RawMessage is the single likeliest type for a queue payload, and |
| +// it is a named byte slice, so it failed the same way. |
| +func TestFoundCatchesAJSONRawMessagePayload(t *testing.T) { |
| + r := NewRecorder() |
| + raw := json.RawMessage(`"` + Canaries[2] + `"`) |
| + slog.New(r.Handler()).Info("enqueue", "payload", raw) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| +} |
| + |
| +// redactingID redacts through String and leaks through MarshalText. |
| +// slog's TextHandler prefers MarshalText; fmt — and so slog.Value.String |
| +// — prefers Stringer. A type shaped like this is not contrived: giving a |
| +// person type a redacting String is the obvious defensive move, and |
| +// MarshalText is then the method someone adds later for serialisation. |
| +type redactingID struct{ address string } |
| + |
| +func (r redactingID) String() string { return "person#42" } |
| +func (r redactingID) MarshalText() ([]byte, error) { return []byte(r.address), nil } |
| + |
| +func TestFoundCatchesATextMarshalerThatOutlivesItsString(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", redactingID{address: Canaries[0]}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// The same trick under JSONHandler, which reaches MarshalJSON through |
| +// json.Marshal. |
| +type redactingJSONID struct{ address string } |
| + |
| +func (r redactingJSONID) String() string { return "person#42" } |
| +func (r redactingJSONID) MarshalJSON() ([]byte, error) { |
| + return json.Marshal(r.address) |
| +} |
| + |
| +func TestFoundCatchesAJSONMarshalerThatOutlivesItsString(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("signin", "who", redactingJSONID{address: Canaries[0]}) |
| + if got := r.found(); got != Canaries[0] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| + } |
| +} |
| + |
| +// A group NAME is caller-supplied, so it can carry a team slug just as a |
| +// value can. WithGroup previously discarded it. |
| +func TestFoundCatchesACanaryInAGroupName(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).WithGroup(Canaries[1]).Info("saved", "rows", 3) |
| + if got := r.found(); got != Canaries[1] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| + } |
| +} |
| + |
| +// And an inline group's key, which arrives as an attr rather than |
| +// through WithGroup. |
| +func TestFoundCatchesACanaryInAnInlineGroupKey(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("saved", slog.Group(Canaries[1], "rows", 3)) |
| + if got := r.found(); got != Canaries[1] { |
| + 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) |
| + } |
| + }) |
| + } |
| +} |
| + |
| +// jobRecord carries a payload the way a queue job actually would: as a |
| +// field, not as the bare value. TextHandler prints the field as |
| +// "[67 65 78 …]" and JSONHandler base64-encodes it, so neither resembles |
| +// the canary and the scanner needs both forms. |
| +type jobRecord struct { |
| + ID int |
| + Payload []byte |
| +} |
| + |
| +func TestFoundCatchesAByteSliceNestedInAStruct(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("enqueue", "job", jobRecord{ID: 7, Payload: []byte(Canaries[2])}) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| +} |
| + |
| +func TestFoundCatchesAByteSliceInASliceAndAMap(t *testing.T) { |
| + for name, v := range map[string]any{ |
| + "slice of any": []any{[]byte(Canaries[2])}, |
| + "map value": map[string][]byte{"p": []byte(Canaries[2])}, |
| + } { |
| + t.Run(name, func(t *testing.T) { |
| + r := NewRecorder() |
| + slog.New(r.Handler()).Info("enqueue", "job", v) |
| + if got := r.found(); got != Canaries[2] { |
| + t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| + } |
| + }) |
| + } |
| +} |