| 1 | // Package logtest is §12 gate 9, "no-content-in-logs": it proves, by |
| 2 | // capturing what the app actually logs, that no address, team name or |
| 3 | // queue payload reaches a log line. |
| 4 | // |
| 5 | // The rule is the design spec's §3.4: "no address, team name, or queue |
| 6 | // payload in any log line, error string, job status message or metric |
| 7 | // label. Errors carry person refs and codes. Test-enforced (§12 gate |
| 8 | // 9)." The reasoning is that logs are storage, and storage we do not |
| 9 | // control is storage we cannot redact — AGENTS.md's own phrasing is |
| 10 | // "Platform-held logs are storage we cannot grep." |
| 11 | // |
| 12 | // Cite §3.4 rather than AGENTS.md for the four-sink list: AGENTS.md on |
| 13 | // this branch still names three, and gains the fourth only when |
| 14 | // fix/agents-md-matches-spec lands. |
| 15 | // |
| 16 | // # What it does not cover |
| 17 | // |
| 18 | // Named in full, because "gate 9 is done" would otherwise be believed. |
| 19 | // §3.4 lists four sinks — log line, error string, job status message, |
| 20 | // metric label — and this covers one and a half of them. |
| 21 | // |
| 22 | // - Log lines: only those routed through slog. A sink that writes to |
| 23 | // os.Stdout or os.Stderr directly is invisible here. chi's own |
| 24 | // middleware.Logger is exactly such a sink (it builds |
| 25 | // log.New(os.Stdout, ...) at init), which is why |
| 26 | // internal/guardstest forbids importing it. |
| 27 | // - Error strings: only transitively, when an error is logged. An |
| 28 | // error string rendered into an HTTP response is not scanned. |
| 29 | // - Job status messages: not covered. There is no queue yet; when |
| 30 | // there is, rastrillo's jobs package turns err.Error() into a |
| 31 | // status message the owner sees, and that needs its own assertion. |
| 32 | // - Metric labels: not covered. This app exports no metrics. |
| 33 | // |
| 34 | // Also uncovered: cmd/home/main.go's two logger.Error calls, which run |
| 35 | // outside any handler with no seam to drive from a test; and anything |
| 36 | // logged by rastrillo's own machinery, since this drives the app router |
| 37 | // directly rather than rastrillo's handler chain. Rastrillo resolves |
| 38 | // slog.Default() at CONSTRUCTION, so swapping the default afterwards |
| 39 | // does not capture a logger it already holds. |
| 40 | // |
| 41 | // # Why it passes trivially today |
| 42 | // |
| 43 | // The skeleton holds no content and takes no user input, so there is |
| 44 | // nothing yet to leak. Its value is as a tripwire for §13 step 2: the |
| 45 | // day sign-in logs an address, this fails. §13 step 1 lists gate 9 |
| 46 | // alongside the skeleton for exactly that reason — a guard written |
| 47 | // after the code it guards is a guard written to pass. |
| 48 | // |
| 49 | // AssertNoContent takes a *testing.T, so this package must never be |
| 50 | // imported from non-test code: doing so would drag the testing package |
| 51 | // into the production binary. internal/sheets/sealtest carries the same |
| 52 | // warning for the same reason. |
| 53 | package logtest |
| 54 | |
| 55 | import ( |
| 56 | "context" |
| 57 | "encoding/base64" |
| 58 | "fmt" |
| 59 | "log/slog" |
| 60 | "math" |
| 61 | "net/url" |
| 62 | "strconv" |
| 63 | "strings" |
| 64 | "sync" |
| 65 | "testing" |
| 66 | ) |
| 67 | |
| 68 | // Canaries are the strings a test seeds into the app before asserting. |
| 69 | // Any of them reaching a log record — as the message, as an attribute |
| 70 | // value, or nested inside a group — is a content leak. |
| 71 | // |
| 72 | // One per sink named in §3.4. They are deliberately unlike anything the |
| 73 | // app would otherwise log, so a match is a leak and never a coincidence. |
| 74 | var Canaries = []string{ |
| 75 | "CANARY-ADDRESS-a41f@example.invalid", |
| 76 | "CANARY-TEAM-NAME-7c2e", |
| 77 | "CANARY-QUEUE-PAYLOAD-93bd", |
| 78 | } |
| 79 | |
| 80 | // Recorder collects everything logged through the handler it hands out. |
| 81 | // The zero value is not usable; call NewRecorder. |
| 82 | type Recorder struct { |
| 83 | mu sync.Mutex |
| 84 | buf strings.Builder |
| 85 | } |
| 86 | |
| 87 | // NewRecorder returns a Recorder ready to hand out handlers. |
| 88 | func NewRecorder() *Recorder { return &Recorder{} } |
| 89 | |
| 90 | // Handler returns a slog.Handler that records into r. Install it with |
| 91 | // slog.New(r.Handler()). |
| 92 | // |
| 93 | // It fans every record out through a real slog.TextHandler AND a real |
| 94 | // slog.JSONHandler, and scans what they produce. |
| 95 | // |
| 96 | // This is the third shape of this function and the first that is not a |
| 97 | // guess. The first two hand-wrote a value renderer and tried to |
| 98 | // enumerate the ways a value prints differently in production than |
| 99 | // through slog.Value.String — first the []byte type, then a reflect |
| 100 | // kind check plus encoding.TextMarshaler plus json.Marshaler. Both |
| 101 | // were incomplete, and the second was incomplete in ten ways: any |
| 102 | // struct with an exported field and a redacting String(), a slice or |
| 103 | // map of such values, a *string (fmt prints the pointer, JSON prints |
| 104 | // the string), a value whose MarshalText FAILS (both stock handlers |
| 105 | // print the error text, which contains the value), a fmt.Formatter |
| 106 | // that says more under %+v than %v, and so on. JSONHandler does not |
| 107 | // call MarshalJSON — it calls json.Marshal on the whole value, which |
| 108 | // walks exported fields, elements and map values to any depth and |
| 109 | // honours MarshalText at every one of them. That is not a list anyone |
| 110 | // can finish by hand. |
| 111 | // |
| 112 | // So do not try. The production sinks are these two handlers; run the |
| 113 | // record through them and scan their bytes. It cannot drift from the |
| 114 | // standard library, it needs no maintenance when a new interface is |
| 115 | // honoured, and it inherits slog's own panic recovery — a MarshalText |
| 116 | // that panics prints "!PANIC: …" here exactly as it would in |
| 117 | // production, rather than taking the test binary down. |
| 118 | // |
| 119 | // One precision: production is slog's own default handler, since |
| 120 | // cmd/home/main.go never configures one and rastrillo falls back to |
| 121 | // slog.Default(). That handler renders values the way TextHandler does, |
| 122 | // so scanning both handlers is a superset of what production emits, not |
| 123 | // a different set. |
| 124 | func (r *Recorder) Handler() slog.Handler { |
| 125 | // Level is set below every real level so nothing is filtered. A |
| 126 | // handler that filtered by level would let a canary logged at Debug |
| 127 | // pass the gate by never being formatted — the gate would succeed |
| 128 | // by not looking. |
| 129 | opts := &slog.HandlerOptions{Level: slog.Level(math.MinInt32)} |
| 130 | w := recorderWriter{rec: r} |
| 131 | return &handler{ |
| 132 | rec: r, |
| 133 | text: slog.NewTextHandler(w, opts), |
| 134 | json: slog.NewJSONHandler(w, opts), |
| 135 | } |
| 136 | } |
| 137 | |
| 138 | // recorderWriter serialises both stock handlers into one buffer. Each |
| 139 | // handler holds its own mutex, so they do not exclude each other. |
| 140 | type recorderWriter struct{ rec *Recorder } |
| 141 | |
| 142 | func (w recorderWriter) Write(p []byte) (int, error) { |
| 143 | w.rec.mu.Lock() |
| 144 | defer w.rec.mu.Unlock() |
| 145 | return w.rec.buf.Write(p) |
| 146 | } |
| 147 | |
| 148 | // Text returns every record captured so far. |
| 149 | func (r *Recorder) Text() string { |
| 150 | r.mu.Lock() |
| 151 | defer r.mu.Unlock() |
| 152 | return r.buf.String() |
| 153 | } |
| 154 | |
| 155 | func (r *Recorder) write(line string) { |
| 156 | r.mu.Lock() |
| 157 | defer r.mu.Unlock() |
| 158 | r.buf.WriteString(line) |
| 159 | r.buf.WriteByte('\n') |
| 160 | } |
| 161 | |
| 162 | // found returns the first canary present in what was captured, or "". |
| 163 | // |
| 164 | // It is the detection primitive, kept separate from AssertNoContent so |
| 165 | // this package's own tests can drive a deliberate leak: a failing |
| 166 | // subtest always fails its parent, so a scanner exercised only through |
| 167 | // a live *testing.T could never be proven to detect anything while |
| 168 | // leaving the suite green. |
| 169 | func (r *Recorder) found() string { |
| 170 | text := r.Text() |
| 171 | lower := strings.ToLower(text) |
| 172 | for _, c := range Canaries { |
| 173 | for _, v := range encodings(c) { |
| 174 | if strings.Contains(text, v) || strings.Contains(lower, strings.ToLower(v)) { |
| 175 | return c |
| 176 | } |
| 177 | } |
| 178 | } |
| 179 | return "" |
| 180 | } |
| 181 | |
| 182 | // encodings returns the forms a canary can legitimately take on its way |
| 183 | // into a log line. A transformed leak is still a leak. |
| 184 | // |
| 185 | // Percent-encoding is not hypothetical: a request logger that prints |
| 186 | // r.URL, r.RequestURI or RawQuery — the usual first thing anyone adds — |
| 187 | // logs an address from a query string as CANARY%40example.invalid, and |
| 188 | // a scan for the raw form misses it. Case-folding matters because an |
| 189 | // address is routinely lowercased before it is hashed, so the lowercased |
| 190 | // copy is the one likeliest to reach an error string. |
| 191 | // |
| 192 | // strconv.Quote covers what TextHandler does to a value that needs |
| 193 | // quoting. (JSONHandler escapes the same characters for the forms these |
| 194 | // canaries take; the two differ only on control characters, which none |
| 195 | // of them carry.) |
| 196 | // |
| 197 | // The base64 and decimal-byte forms are there because a []byte NESTED in |
| 198 | // something — a struct field, a slice element, a map value — is printed |
| 199 | // by JSONHandler as base64 and by TextHandler as "[67 65 78 …]", and |
| 200 | // neither resembles the canary. A job struct carrying a Payload []byte |
| 201 | // and logged whole with slog.Any is more likely than logging the bare |
| 202 | // slice, and the queue payload is the sink this package singled out as |
| 203 | // most likely to arrive as bytes. |
| 204 | func encodings(c string) []string { |
| 205 | q := strconv.Quote(c) |
| 206 | b := []byte(c) |
| 207 | return []string{ |
| 208 | c, |
| 209 | url.QueryEscape(c), |
| 210 | url.PathEscape(c), |
| 211 | q[1 : len(q)-1], |
| 212 | base64.StdEncoding.EncodeToString(b), |
| 213 | base64.RawStdEncoding.EncodeToString(b), |
| 214 | base64.URLEncoding.EncodeToString(b), |
| 215 | fmt.Sprint(b), |
| 216 | } |
| 217 | } |
| 218 | |
| 219 | // AssertNoContent fails t if any canary reached a log record, naming |
| 220 | // the canary and dumping everything captured so the offending line is |
| 221 | // visible without a second run. |
| 222 | func (r *Recorder) AssertNoContent(t *testing.T) { |
| 223 | t.Helper() |
| 224 | if c := r.found(); c != "" { |
| 225 | t.Fatalf("gate 9: %q reached a log line.\ncaptured:\n%s", c, r.Text()) |
| 226 | } |
| 227 | } |
| 228 | |
| 229 | // handler fans one record out to both stock handlers, and records open |
| 230 | // group names alongside. |
| 231 | type handler struct { |
| 232 | rec *Recorder |
| 233 | text slog.Handler |
| 234 | json slog.Handler |
| 235 | groups []string |
| 236 | } |
| 237 | |
| 238 | // Enabled answers true at every level, for the reason Handler gives. |
| 239 | func (h *handler) Enabled(context.Context, slog.Level) bool { return true } |
| 240 | |
| 241 | func (h *handler) Handle(ctx context.Context, r slog.Record) error { |
| 242 | // Open group names are written explicitly. Both stock handlers |
| 243 | // prefix keys with them — "acme.rows=3" — so they are usually |
| 244 | // captured anyway, but slog drops a group with no attributes under |
| 245 | // it, and a group name is caller-supplied: WithGroup(team.Slug) is |
| 246 | // a plausible line to write. Writing it costs a string. |
| 247 | for _, g := range h.groups { |
| 248 | h.rec.write(g) |
| 249 | } |
| 250 | if err := h.text.Handle(ctx, r); err != nil { |
| 251 | return err |
| 252 | } |
| 253 | // A slog.Record is re-iterable, so handing the same one to a second |
| 254 | // handler is sound. |
| 255 | return h.json.Handle(ctx, r) |
| 256 | } |
| 257 | |
| 258 | func (h *handler) WithAttrs(as []slog.Attr) slog.Handler { |
| 259 | return &handler{ |
| 260 | rec: h.rec, |
| 261 | text: h.text.WithAttrs(as), |
| 262 | json: h.json.WithAttrs(as), |
| 263 | groups: append([]string{}, h.groups...), |
| 264 | } |
| 265 | } |
| 266 | |
| 267 | func (h *handler) WithGroup(name string) slog.Handler { |
| 268 | if name == "" { |
| 269 | return h |
| 270 | } |
| 271 | return &handler{ |
| 272 | rec: h.rec, |
| 273 | text: h.text.WithGroup(name), |
| 274 | json: h.json.WithGroup(name), |
| 275 | groups: append(append([]string{}, h.groups...), name), |
| 276 | } |
| 277 | } |
| 278 | |
amadan