oficina / home Public

Review pass: the gate had three ways to pass a line that leaks

Fable returned REQUEST CHANGES on 0c00cd9. Every finding was re-verified
against the Go and chi sources before applying; all held.

The []byte case fails in the dangerous direction. slog's text handler
quotes a byte slice as a string, so a queue payload logged as []byte is
READABLE in production, while slog.Value.String goes through fmt.Sprint
and renders "[67 65 78 ...]". The scanner found nothing on a line that
leaks. Queue payloads are the sink most likely to arrive as a byte
slice. Confirmed by running both handlers side by side; render() now
special-cases it.

The address canary could not be found by the test that sends it. The
guard built its query string with url.QueryEscape, turning "@" into
"%40", so any request logger printing r.URL or RawQuery — the usual
first thing anyone adds — would log an address the scanner missed.
found() now also checks the QueryEscape and PathEscape forms, and scans
case-folded, because an address is routinely lowercased before hashing.

The most likely first request logger bypassed the gate entirely. chi's
middleware.Logger builds log.New(os.Stdout, ...) at package init and
writes the request line straight to stdout, touching neither slog nor
the log default; middleware.Recoverer writes panics to os.Stderr the
same way. Nothing forbade either import. internal/guardstest gains
TestNoLogSinkOutsideSlog, which forbids that import and, by AST walk
rather than text scan, os.Stdout, os.Stderr and the log package's own
printers in non-test code. Verified both ways: it fails on a planted
middleware.Logger and on a planted os.Stderr write, and os.Exit does not
trip it.

The claim that JSONHandler drops error text was false. json_handler.go
type-asserts error and appends err.Error(); a run confirms the text
survives. The comment now gives the real, narrower reason for a custom
handler. This was my own invention and it had been asserted in the
previous commit message too.

slog.SetDefault also calls log.SetOutput and log.SetFlags(0), and
restoring a default-handler logger does not undo that — the branch is
skipped. Every later test in the package would have had its log output
swallowed into a dead recorder. The cleanup now restores log.Writer and
log.Flags as well.

Routes are enumerated with chi.Walk instead of hand-listed, and each is
driven with both GET and POST carrying a form body, since sign-in will
put the address in a POST body. A route added in step 2 is now covered
without anyone remembering to add it. The two things still owed by step
2's author — resolve slog.Default() at call time, and add a guardstest
rule for any new sink — are stated in the test rather than left implied.

The containment guard's rationale was also wrong: test flags are
registered by testing.Init since Go 1.13, not by importing testing. The
comment now makes the narrower true claim, and the rule matches the
package tree so a future logtest subpackage cannot escape it.

The gap paragraph now names all four of §3.4's sinks and what is
uncovered for each, including job status messages and rastrillo's own
machinery — which resolves slog.Default() at construction, so swapping
the default afterwards does not reach it. The four-sink wording is
attributed to §3.4, not AGENTS.md: AGENTS.md on this branch still names
three and gains the fourth only when fix/agents-md-matches-spec lands.

go test -race passes. All four .amadan/ci.d gates green.

🤖 Generated with Claude Opus 5, at the direction of Paul Campbell.
Reviewed-By: Fable 5.1 (REQUEST CHANGES on 0c00cd9)
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01SfmrCe9McDH9dnqkuEMrjF
Paul Campbell pushed by paul@keymail.dev 1caabab1fb0d180218b9e8521bf0a78afea071f9 parent 0c00cd9
5 files changed, +279 −63
  • internal/guardstest/logsinks_test.go +82 −0
  • internal/guardstest/logtest_containment_test.go +10 −6
  • internal/home/logs_test.go +73 −34
  • internal/home/logtest/logtest.go +78 −23
  • internal/home/logtest/logtest_test.go +36 −0

CI passed — run details

Intent

Attributed to this commit: 17.9 g CO₂e (1168416 tokens). This is an attribution, not a measurement — usage counted from this commit's own marker forward to the next one on feat/gate-9-no-content-in-logs, never backward from it. A turn that produced more than one commit books all of its tokens to the last one, and a concurrent session on this branch can add to the same figure. Some of it was priced using the shared default rate, because no model-specific factor row exists yet for at least one model involved. The Carbon view has the repo total, which is never derived from this attribution.

diff --git a/internal/guardstest/logsinks_test.go b/internal/guardstest/logsinks_test.go
new file mode 100644
index 0000000..cf69df5
--- /dev/null
+++ b/internal/guardstest/logsinks_test.go
@@ -0,0 +1,82 @@
+package guards
+
+import (
+ "go/ast"
+ "go/parser"
+ "go/token"
+ "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 package-qualified names that write outside
+// slog. 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.
+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)
+ }
+ ast.Inspect(f, func(n ast.Node) bool {
+ sel, ok := n.(*ast.SelectorExpr)
+ if !ok {
+ return true
+ }
+ pkg, ok := sel.X.(*ast.Ident)
+ if !ok {
+ return true
+ }
+ if why, bad := forbiddenSelectors[pkg.Name][sel.Sel.Name]; bad {
+ t.Errorf("%s:%d: %s.%s — %s", rel, fset.Position(sel.Pos()).Line, pkg.Name, sel.Sel.Name, why)
+ }
+ return true
+ })
+ }
+}
diff --git a/internal/guardstest/logtest_containment_test.go b/internal/guardstest/logtest_containment_test.go
index b3f8bbb..3c12ac6 100644
--- a/internal/guardstest/logtest_containment_test.go
+++ b/internal/guardstest/logtest_containment_test.go
@@ -12,12 +12,16 @@ import (
const logtestImport = "amadan.net/oficina/home/internal/home/logtest"
// TestLogtestOnlyImportedByTests fails on any non-_test.go file that
-// imports logtest.
+// imports logtest, or anything under it: a future logtest subpackage
+// must inherit the rule rather than fall outside it on an exact match.
//
-// The failure this prevents is quiet: importing logtest from production
-// code links testing into the binary, which registers test flags on the
-// default flag set and changes what the deployed binary accepts on its
-// command line. Nothing about that announces itself at build time.
+// 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) {
@@ -26,7 +30,7 @@ func TestLogtestOnlyImportedByTests(t *testing.T) {
}
rel := relPath(t, root, path)
for _, imp := range fileImports(t, path) {
- if imp == logtestImport {
+ 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/home/logs_test.go b/internal/home/logs_test.go
index 5cdd45f..e3eb564 100644
--- a/internal/home/logs_test.go
+++ b/internal/home/logs_test.go
@@ -1,65 +1,104 @@
package home
import (
+ "log"
"log/slog"
"net/http"
"net/http/httptest"
"net/url"
+ "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 with canary-laden input and asserts none of it
-// reaches a log line. AGENTS.md: "No address, team name, or queue
-// payload in any log line, error string, job status message or metric
-// label. Platform-held logs are storage we cannot grep."
+// 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: the day a request logger,
-// a sign-in handler or an error path prints a URL, a header or an
-// address, this fails. A guard written afterwards is a guard written to
-// pass.
+// the guard exists before the code it guards.
+//
+// # What has to stay true for this to keep biting
//
-// Scope: this covers internal/home's router. It does NOT cover
-// cmd/home/main.go's own logger.Error("resolve", …) and
-// logger.Error("serve", …) calls, which run outside any handler and
-// have no seam to drive from a test. They log a rastrillo error and no
-// app value today; if main ever logs something derived from config or a
-// request, that needs its own guard.
+// 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. Two 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.
func TestNoContentInLogs(t *testing.T) {
rec := logtest.NewRecorder()
- // The app and rastrillo both log through slog.Default(), so swapping
- // the default is what actually captures them. Restored on cleanup;
- // this test must not run in parallel with anything that logs.
- prev := slog.Default()
+ // 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(prev) })
+ 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)
+ }
- targets := []string{
- "/",
- "/healthz",
- "/?q=" + url.QueryEscape(logtest.Canaries[0]),
- "/" + url.PathEscape(logtest.Canaries[1]),
- "/no-such-route",
+ var targets []string
+ err := chi.Walk(routes, func(_ string, route string, _ http.Handler, _ ...func(http.Handler) http.Handler) error {
+ targets = append(targets, route)
+ 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.
+ targets = append(targets, "/no-such-route", "/"+url.PathEscape(logtest.Canaries[1]))
for _, target := range targets {
- req := httptest.NewRequest(http.MethodGet, target, nil)
- // 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]})
+ // chi route patterns can carry wildcards; make them fetchable.
+ target = strings.ReplaceAll(target, "/*", "/x")
+
+ for _, method := range []string{http.MethodGet, http.MethodPost} {
+ // 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(method, target+"?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]})
- w := httptest.NewRecorder()
- app.Router().ServeHTTP(w, req)
+ router.ServeHTTP(httptest.NewRecorder(), req)
+ }
}
rec.AssertNoContent(t)
diff --git a/internal/home/logtest/logtest.go b/internal/home/logtest/logtest.go
index 3858360..3d2d255 100644
--- a/internal/home/logtest/logtest.go
+++ b/internal/home/logtest/logtest.go
@@ -2,21 +2,41 @@
// capturing what the app actually logs, that no address, team name or
// queue payload reaches a log line.
//
-// AGENTS.md states the rule this enforces — "No address, team name, or
-// queue payload in any log line, error string, job status message or
-// metric label. Platform-held logs are storage we cannot grep." The
-// design spec's §3.4 is the reasoning: logs are storage, and storage we
-// do not control is storage we cannot redact.
+// 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."
//
-// # What it does not cover yet
+// 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.
//
-// Gate 9 names three sinks. This package covers log lines, and error
-// strings transitively wherever an error is logged. It does NOT cover
-// metric labels: this app emits no metrics, so there is nothing to
-// scan. The day rastrillo or this app exports a metric with a label
-// built from a value, this package needs a second assertion and this
-// paragraph is wrong. Named here rather than left as a silent gap,
-// because "gate 9 is done" would otherwise be believed.
+// # 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
//
@@ -35,6 +55,7 @@ package logtest
import (
"context"
"log/slog"
+ "net/url"
"strings"
"sync"
"testing"
@@ -89,14 +110,30 @@ func (r *Recorder) write(line string) {
// leaving the suite green.
func (r *Recorder) found() string {
text := r.Text()
+ lower := strings.ToLower(text)
for _, c := range Canaries {
- if strings.Contains(text, c) {
- return c
+ 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.
+func encodings(c string) []string {
+ return []string{c, url.QueryEscape(c), url.PathEscape(c)}
+}
+
// 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.
@@ -109,13 +146,12 @@ func (r *Recorder) AssertNoContent(t *testing.T) {
// handler flattens each record into one scannable line.
//
-// It does not reuse slog's own handlers on purpose. JSONHandler marshals
-// an attribute of type error with json.Marshal, which yields {} for a
-// plain error and drops its text — so an address wrapped in an error,
-// the most likely way one reaches a log line here, would be invisible to
-// a scanner reading JSON while still being printed in production.
-// Formatting each value with slog.Value.String (fmt.Sprint semantics)
-// keeps what production would show.
+// 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).
type handler struct {
rec *Recorder
attrs []slog.Attr
@@ -172,5 +208,24 @@ func appendAttr(b *strings.Builder, a slog.Attr) {
b.WriteByte(' ')
b.WriteString(a.Key)
b.WriteByte('=')
- b.WriteString(v.String())
+ b.WriteString(render(v))
+}
+
+// render returns the value as production would show it, which is not
+// always what slog.Value.String returns.
+//
+// A []byte is the case that matters and it fails in the dangerous
+// direction: slog's text handler 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 ...]".
+// Scanning the numeric form finds nothing, so the gate would pass on a
+// line that leaks. Queue payloads are exactly the sink most likely to
+// arrive as a byte slice.
+func render(v slog.Value) string {
+ if v.Kind() == slog.KindAny {
+ if bs, ok := v.Any().([]byte); ok {
+ return string(bs)
+ }
+ }
+ return v.String()
}
diff --git a/internal/home/logtest/logtest_test.go b/internal/home/logtest/logtest_test.go
index d20fd4e..a63fcca 100644
--- a/internal/home/logtest/logtest_test.go
+++ b/internal/home/logtest/logtest_test.go
@@ -4,6 +4,8 @@ import (
"errors"
"fmt"
"log/slog"
+ "net/url"
+ "strings"
"testing"
)
@@ -133,3 +135,37 @@ func TestCanariesAreDistinctAndNonEmpty(t *testing.T) {
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])
+ }
+}