| 1 | package logtest |
| 2 | |
| 3 | import ( |
| 4 | "encoding/json" |
| 5 | "errors" |
| 6 | "fmt" |
| 7 | "io" |
| 8 | "log/slog" |
| 9 | "net/url" |
| 10 | "strings" |
| 11 | "testing" |
| 12 | ) |
| 13 | |
| 14 | // found is the detection primitive every test here drives. It is |
| 15 | // exercised directly rather than through AssertNoContent because a |
| 16 | // failing subtest always fails its parent: routing a deliberate leak |
| 17 | // through a live *testing.T would leave this package unable to go |
| 18 | // green. internal/sheets/sealtest splits leaked/findLeak from its |
| 19 | // assertion for the same reason. |
| 20 | |
| 21 | func TestFoundCatchesACanaryInTheMessage(t *testing.T) { |
| 22 | r := NewRecorder() |
| 23 | slog.New(r.Handler()).Info("sending to " + Canaries[0]) |
| 24 | if got := r.found(); got != Canaries[0] { |
| 25 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 26 | } |
| 27 | } |
| 28 | |
| 29 | func TestFoundCatchesACanaryInATopLevelAttr(t *testing.T) { |
| 30 | r := NewRecorder() |
| 31 | slog.New(r.Handler()).Info("upsert", "team", Canaries[1]) |
| 32 | if got := r.found(); got != Canaries[1] { |
| 33 | t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| 34 | } |
| 35 | } |
| 36 | |
| 37 | // A leak inside a group is the one a naive scanner misses: slog.Record's |
| 38 | // Attrs walk yields the group as a single attr, and its members are only |
| 39 | // reachable by recursing into Value.Group(). |
| 40 | func TestFoundCatchesACanaryNestedInAGroup(t *testing.T) { |
| 41 | r := NewRecorder() |
| 42 | slog.New(r.Handler()).Info("enqueue", |
| 43 | slog.Group("job", slog.String("payload", Canaries[2]))) |
| 44 | if got := r.found(); got != Canaries[2] { |
| 45 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 46 | } |
| 47 | } |
| 48 | |
| 49 | // The skeleton's only real logging is logger.Error("resolve", "err", err), |
| 50 | // so an address reaching a log line will most likely arrive wrapped in an |
| 51 | // error. A JSON handler would hide this: json.Marshal of a plain error |
| 52 | // yields {} and drops the text entirely. |
| 53 | func TestFoundCatchesACanaryInsideAWrappedError(t *testing.T) { |
| 54 | r := NewRecorder() |
| 55 | err := fmt.Errorf("resolve: %w", errors.New("no mailbox for "+Canaries[0])) |
| 56 | slog.New(r.Handler()).Error("resolve", "err", err) |
| 57 | if got := r.found(); got != Canaries[0] { |
| 58 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 59 | } |
| 60 | } |
| 61 | |
| 62 | // Attrs bound by With() are preformatted by the handler and never appear |
| 63 | // in the Record, so a scanner that only walks the Record misses them. |
| 64 | func TestFoundCatchesACanaryBoundByWith(t *testing.T) { |
| 65 | r := NewRecorder() |
| 66 | slog.New(r.Handler()).With("addr", Canaries[0]).Info("start") |
| 67 | if got := r.found(); got != Canaries[0] { |
| 68 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 69 | } |
| 70 | } |
| 71 | |
| 72 | func TestFoundCatchesACanaryUnderWithGroup(t *testing.T) { |
| 73 | r := NewRecorder() |
| 74 | slog.New(r.Handler()).WithGroup("mail").Info("queued", "to", Canaries[0]) |
| 75 | if got := r.found(); got != Canaries[0] { |
| 76 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 77 | } |
| 78 | } |
| 79 | |
| 80 | // A LogValuer can carry content that formatting the value plainly does |
| 81 | // not show, so values must be resolved before they are scanned. |
| 82 | // |
| 83 | // The String method is what makes this test bite. Without it, fmt.Sprint |
| 84 | // of the struct renders its field and an unresolved scan finds the |
| 85 | // canary by accident — the test would pass even with Resolve removed, |
| 86 | // proving nothing. With it, the unresolved form is "REDACTED" and only a |
| 87 | // scanner that resolves sees the canary, which is exactly what slog's |
| 88 | // real handlers do before printing. |
| 89 | type valuer struct{ s string } |
| 90 | |
| 91 | func (v valuer) String() string { return "REDACTED" } |
| 92 | |
| 93 | func (v valuer) LogValue() slog.Value { return slog.StringValue(v.s) } |
| 94 | |
| 95 | func TestFoundResolvesLogValuers(t *testing.T) { |
| 96 | r := NewRecorder() |
| 97 | slog.New(r.Handler()).Info("person", "who", valuer{Canaries[1]}) |
| 98 | if got := r.found(); got != Canaries[1] { |
| 99 | t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| 100 | } |
| 101 | } |
| 102 | |
| 103 | func TestFoundReportsNothingForCleanLogs(t *testing.T) { |
| 104 | r := NewRecorder() |
| 105 | l := slog.New(r.Handler()) |
| 106 | l.Info("serve", "port", 8080) |
| 107 | l.Error("resolve", "err", errors.New("socket path missing")) |
| 108 | l.With("app", "home").WithGroup("db").Info("open", "path", "/var/lib/home.db") |
| 109 | if got := r.found(); got != "" { |
| 110 | t.Fatalf("found() = %q, want no leak", got) |
| 111 | } |
| 112 | } |
| 113 | |
| 114 | // Enabled must answer true at every level, or a canary logged at Debug |
| 115 | // would never reach Handle and the gate would pass by not looking. |
| 116 | func TestRecorderIsEnabledAtEveryLevel(t *testing.T) { |
| 117 | r := NewRecorder() |
| 118 | l := slog.New(r.Handler()) |
| 119 | l.Debug("debug " + Canaries[0]) |
| 120 | if got := r.found(); got != Canaries[0] { |
| 121 | t.Fatalf("found() = %q at Debug, want %q", got, Canaries[0]) |
| 122 | } |
| 123 | } |
| 124 | |
| 125 | func TestCanariesAreDistinctAndNonEmpty(t *testing.T) { |
| 126 | seen := map[string]bool{} |
| 127 | for _, c := range Canaries { |
| 128 | if c == "" { |
| 129 | t.Fatal("a canary is empty: it would match every log line") |
| 130 | } |
| 131 | if seen[c] { |
| 132 | t.Fatalf("duplicate canary %q", c) |
| 133 | } |
| 134 | seen[c] = true |
| 135 | } |
| 136 | if len(Canaries) < 3 { |
| 137 | t.Fatalf("got %d canaries, want one each for address, team name and queue payload", len(Canaries)) |
| 138 | } |
| 139 | } |
| 140 | |
| 141 | // A queue payload is the sink most likely to arrive as a byte slice, and |
| 142 | // it fails in the dangerous direction: slog's text handler quotes []byte |
| 143 | // as a string, so it is READABLE in production, while fmt.Sprint renders |
| 144 | // it as "[67 65 78 ...]". A scanner using Value.String finds nothing on a |
| 145 | // line that leaks. |
| 146 | func TestFoundCatchesAByteSlicePayload(t *testing.T) { |
| 147 | r := NewRecorder() |
| 148 | slog.New(r.Handler()).Info("enqueue", "payload", []byte(Canaries[2])) |
| 149 | if got := r.found(); got != Canaries[2] { |
| 150 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 151 | } |
| 152 | } |
| 153 | |
| 154 | // The first request logger anyone adds prints r.URL or RawQuery, so an |
| 155 | // address arriving in a query string reaches the log percent-encoded. |
| 156 | // An encoded address is an address. |
| 157 | func TestFoundCatchesAPercentEncodedAddress(t *testing.T) { |
| 158 | r := NewRecorder() |
| 159 | slog.New(r.Handler()).Info("req", "url", "/?q="+url.QueryEscape(Canaries[0])) |
| 160 | if got := r.found(); got != Canaries[0] { |
| 161 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 162 | } |
| 163 | } |
| 164 | |
| 165 | // An address is routinely lowercased before it is hashed, so the |
| 166 | // lowercased copy is the one likeliest to reach an error string. |
| 167 | func TestFoundCatchesALowercasedCanary(t *testing.T) { |
| 168 | r := NewRecorder() |
| 169 | slog.New(r.Handler()).Error("hash", "err", "failed to hash "+strings.ToLower(Canaries[1])) |
| 170 | if got := r.found(); got != Canaries[1] { |
| 171 | t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| 172 | } |
| 173 | } |
| 174 | |
| 175 | // payloadBytes is a NAMED byte slice with no marshaller of its own — |
| 176 | // the plain form of the type a queue payload has in practice. It exists |
| 177 | // because v.Any().([]byte) does not match it while slog's own |
| 178 | // reflect-kind check does, so an assertion-based render read it as |
| 179 | // "[67 65 78 ...]" and the gate passed on a readable line. |
| 180 | type payloadBytes []byte |
| 181 | |
| 182 | func TestFoundCatchesANamedByteSlicePayload(t *testing.T) { |
| 183 | r := NewRecorder() |
| 184 | slog.New(r.Handler()).Info("enqueue", "payload", payloadBytes(Canaries[2])) |
| 185 | if got := r.found(); got != Canaries[2] { |
| 186 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 187 | } |
| 188 | } |
| 189 | |
| 190 | // json.RawMessage is the single likeliest type for a queue payload, and |
| 191 | // it is a named byte slice, so it failed the same way. |
| 192 | func TestFoundCatchesAJSONRawMessagePayload(t *testing.T) { |
| 193 | r := NewRecorder() |
| 194 | raw := json.RawMessage(`"` + Canaries[2] + `"`) |
| 195 | slog.New(r.Handler()).Info("enqueue", "payload", raw) |
| 196 | if got := r.found(); got != Canaries[2] { |
| 197 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 198 | } |
| 199 | } |
| 200 | |
| 201 | // redactingID redacts through String and leaks through MarshalText. |
| 202 | // slog's TextHandler prefers MarshalText; fmt — and so slog.Value.String |
| 203 | // — prefers Stringer. A type shaped like this is not contrived: giving a |
| 204 | // person type a redacting String is the obvious defensive move, and |
| 205 | // MarshalText is then the method someone adds later for serialisation. |
| 206 | type redactingID struct{ address string } |
| 207 | |
| 208 | func (r redactingID) String() string { return "person#42" } |
| 209 | func (r redactingID) MarshalText() ([]byte, error) { return []byte(r.address), nil } |
| 210 | |
| 211 | func TestFoundCatchesATextMarshalerThatOutlivesItsString(t *testing.T) { |
| 212 | r := NewRecorder() |
| 213 | slog.New(r.Handler()).Info("signin", "who", redactingID{address: Canaries[0]}) |
| 214 | if got := r.found(); got != Canaries[0] { |
| 215 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 216 | } |
| 217 | } |
| 218 | |
| 219 | // The same trick under JSONHandler, which reaches MarshalJSON through |
| 220 | // json.Marshal. |
| 221 | type redactingJSONID struct{ address string } |
| 222 | |
| 223 | func (r redactingJSONID) String() string { return "person#42" } |
| 224 | func (r redactingJSONID) MarshalJSON() ([]byte, error) { |
| 225 | return json.Marshal(r.address) |
| 226 | } |
| 227 | |
| 228 | func TestFoundCatchesAJSONMarshalerThatOutlivesItsString(t *testing.T) { |
| 229 | r := NewRecorder() |
| 230 | slog.New(r.Handler()).Info("signin", "who", redactingJSONID{address: Canaries[0]}) |
| 231 | if got := r.found(); got != Canaries[0] { |
| 232 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 233 | } |
| 234 | } |
| 235 | |
| 236 | // A group NAME is caller-supplied, so it can carry a team slug just as a |
| 237 | // value can. WithGroup previously discarded it. |
| 238 | func TestFoundCatchesACanaryInAGroupName(t *testing.T) { |
| 239 | r := NewRecorder() |
| 240 | slog.New(r.Handler()).WithGroup(Canaries[1]).Info("saved", "rows", 3) |
| 241 | if got := r.found(); got != Canaries[1] { |
| 242 | t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| 243 | } |
| 244 | } |
| 245 | |
| 246 | // And an inline group's key, which arrives as an attr rather than |
| 247 | // through WithGroup. |
| 248 | func TestFoundCatchesACanaryInAnInlineGroupKey(t *testing.T) { |
| 249 | r := NewRecorder() |
| 250 | slog.New(r.Handler()).Info("saved", slog.Group(Canaries[1], "rows", 3)) |
| 251 | if got := r.found(); got != Canaries[1] { |
| 252 | t.Fatalf("found() = %q, want %q", got, Canaries[1]) |
| 253 | } |
| 254 | } |
| 255 | |
| 256 | // The cases below are the ones a hand-written value renderer missed. |
| 257 | // Each is a value that a stock slog handler prints readably while |
| 258 | // slog.Value.String does not, which is the shape that lets a leaking |
| 259 | // line pass a green gate. They exist as regressions against ever |
| 260 | // hand-enumerating interfaces again — see Recorder.Handler. |
| 261 | |
| 262 | // person has an exported field and a redacting String. JSONHandler |
| 263 | // calls json.Marshal on the whole value, which walks exported fields |
| 264 | // and never consults String; fmt consults String and stops there. |
| 265 | type person struct{ Address string } |
| 266 | |
| 267 | func (p person) String() string { return "person#42" } |
| 268 | |
| 269 | func TestFoundCatchesAnExportedFieldUnderARedactingString(t *testing.T) { |
| 270 | r := NewRecorder() |
| 271 | slog.New(r.Handler()).Info("signin", "who", person{Address: Canaries[0]}) |
| 272 | if got := r.found(); got != Canaries[0] { |
| 273 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 274 | } |
| 275 | } |
| 276 | |
| 277 | func TestFoundCatchesASliceOfRedactingValues(t *testing.T) { |
| 278 | r := NewRecorder() |
| 279 | slog.New(r.Handler()).Info("members", "who", []person{{Address: Canaries[0]}}) |
| 280 | if got := r.found(); got != Canaries[0] { |
| 281 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 282 | } |
| 283 | } |
| 284 | |
| 285 | func TestFoundCatchesAMapOfRedactingValues(t *testing.T) { |
| 286 | r := NewRecorder() |
| 287 | slog.New(r.Handler()).Info("members", "who", map[string]person{"a": {Address: Canaries[0]}}) |
| 288 | if got := r.found(); got != Canaries[0] { |
| 289 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 290 | } |
| 291 | } |
| 292 | |
| 293 | // A pointer to a string: fmt prints the pointer's hex address, JSON |
| 294 | // prints the string. Not contrived — an optional field is a pointer. |
| 295 | func TestFoundCatchesAStringPointer(t *testing.T) { |
| 296 | r := NewRecorder() |
| 297 | addr := Canaries[0] |
| 298 | slog.New(r.Handler()).Info("signin", "who", &addr) |
| 299 | if got := r.found(); got != Canaries[0] { |
| 300 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 301 | } |
| 302 | } |
| 303 | |
| 304 | // TextHandler formats an opaque value with %+v; slog.Value.String uses |
| 305 | // %v. A Formatter can say more under one than the other. |
| 306 | type verboseOnly struct{ address string } |
| 307 | |
| 308 | func (v verboseOnly) Format(f fmt.State, _ rune) { |
| 309 | if f.Flag('+') { |
| 310 | io.WriteString(f, v.address) |
| 311 | return |
| 312 | } |
| 313 | io.WriteString(f, "person#42") |
| 314 | } |
| 315 | |
| 316 | func TestFoundCatchesAFormatterThatSaysMoreUnderPlusV(t *testing.T) { |
| 317 | r := NewRecorder() |
| 318 | slog.New(r.Handler()).Info("signin", "who", verboseOnly{address: Canaries[0]}) |
| 319 | if got := r.found(); got != Canaries[0] { |
| 320 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 321 | } |
| 322 | } |
| 323 | |
| 324 | // A marshal FAILURE is not silence: both stock handlers write the error |
| 325 | // text, and an error text routinely quotes the value that failed. |
| 326 | type failingText struct{ address string } |
| 327 | |
| 328 | func (f failingText) String() string { return "person#42" } |
| 329 | func (f failingText) MarshalText() ([]byte, error) { |
| 330 | return nil, errors.New("cannot marshal " + f.address) |
| 331 | } |
| 332 | |
| 333 | func TestFoundCatchesAnAddressInAMarshalError(t *testing.T) { |
| 334 | r := NewRecorder() |
| 335 | slog.New(r.Handler()).Info("signin", "who", failingText{address: Canaries[0]}) |
| 336 | if got := r.found(); got != Canaries[0] { |
| 337 | t.Fatalf("found() = %q, want %q", got, Canaries[0]) |
| 338 | } |
| 339 | } |
| 340 | |
| 341 | // valText has a VALUE-receiver MarshalText, so a nil *valText panics if |
| 342 | // the method is called. Stock slog recovers and prints <nil>; a |
| 343 | // hand-written renderer took the whole test binary down instead. |
| 344 | type valText struct{ address string } |
| 345 | |
| 346 | func (v valText) MarshalText() ([]byte, error) { return []byte(v.address), nil } |
| 347 | |
| 348 | type panicText struct{} |
| 349 | |
| 350 | func (panicText) MarshalText() ([]byte, error) { panic("boom") } |
| 351 | |
| 352 | func TestRecorderSurvivesValuesThatPanicWhenMarshalled(t *testing.T) { |
| 353 | for _, tc := range []struct { |
| 354 | name string |
| 355 | v any |
| 356 | }{ |
| 357 | {"nil pointer with a value-receiver MarshalText", (*valText)(nil)}, |
| 358 | {"MarshalText that panics", panicText{}}, |
| 359 | } { |
| 360 | t.Run(tc.name, func(t *testing.T) { |
| 361 | defer func() { |
| 362 | if p := recover(); p != nil { |
| 363 | t.Fatalf("recorder panicked on %s: %v — stock slog recovers, so this must too", tc.name, p) |
| 364 | } |
| 365 | }() |
| 366 | r := NewRecorder() |
| 367 | slog.New(r.Handler()).Info("signin", "who", tc.v) |
| 368 | if got := r.found(); got != "" { |
| 369 | t.Fatalf("found() = %q, want no canary", got) |
| 370 | } |
| 371 | }) |
| 372 | } |
| 373 | } |
| 374 | |
| 375 | // jobRecord carries a payload the way a queue job actually would: as a |
| 376 | // field, not as the bare value. TextHandler prints the field as |
| 377 | // "[67 65 78 …]" and JSONHandler base64-encodes it, so neither resembles |
| 378 | // the canary and the scanner needs both forms. |
| 379 | type jobRecord struct { |
| 380 | ID int |
| 381 | Payload []byte |
| 382 | } |
| 383 | |
| 384 | func TestFoundCatchesAByteSliceNestedInAStruct(t *testing.T) { |
| 385 | r := NewRecorder() |
| 386 | slog.New(r.Handler()).Info("enqueue", "job", jobRecord{ID: 7, Payload: []byte(Canaries[2])}) |
| 387 | if got := r.found(); got != Canaries[2] { |
| 388 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 389 | } |
| 390 | } |
| 391 | |
| 392 | func TestFoundCatchesAByteSliceInASliceAndAMap(t *testing.T) { |
| 393 | for name, v := range map[string]any{ |
| 394 | "slice of any": []any{[]byte(Canaries[2])}, |
| 395 | "map value": map[string][]byte{"p": []byte(Canaries[2])}, |
| 396 | } { |
| 397 | t.Run(name, func(t *testing.T) { |
| 398 | r := NewRecorder() |
| 399 | slog.New(r.Handler()).Info("enqueue", "job", v) |
| 400 | if got := r.found(); got != Canaries[2] { |
| 401 | t.Fatalf("found() = %q, want %q", got, Canaries[2]) |
| 402 | } |
| 403 | }) |
| 404 | } |
| 405 | } |
| 406 | |
amadan