amadan
The route check judged the wrong thing, and a nested []byte still hid
Two findings from the third review, both narrow.
The route assertion read the status code and concluded from a 404 that
the handler never ran. A handler that answers 404 ITSELF runs perfectly
well — and that is not a corner case: a directory route returning 404
for an unknown team slug is the first real route step 2 adds. Planted
one that logs the team param and then calls http.NotFound: the gate
caught the leak correctly and the assertion simultaneously reported
that the handler had not run and pointed at fillParams. Loud and
wrong. It now asks chi whether it dispatched — an attached
RouteContext whose RoutePattern is empty only when nothing matched —
which is the question that was always meant.
encodings missed the queue-payload canary in the form it will actually
take. The bare []byte was covered; a []byte NESTED in something was
not. TextHandler renders a struct field as "[67 65 78 …]" and
JSONHandler base64-encodes it, and neither resembles the canary. A job
struct with a Payload []byte logged whole via slog.Any is more likely
than logging the bare slice, and this package had already singled out
the queue payload as the sink most likely to arrive as bytes — so this
was the one encoding its own rule ("a transformed leak is still a
leak") most needed. Base64 in three alphabets and the decimal-byte
form are now scanned. Three new tests, all failing against the
previous encodings.
Also corrected: the package doc said "the production sinks are these
two handlers", which is loose — production is slog's own default
handler, since main.go configures none. It renders values as
TextHandler does, so scanning both is a superset rather than a
different set, and the doc now says so. The strconv.Quote comment
claimed more about JSON escaping than is true; the two handlers differ
only on control characters, which no canary carries. And a comment
promising two things listed three.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
3 files changed,
+84
−16
internal/home/logs_test.go+22 −14internal/home/logtest/logtest.go+30 −2internal/home/logtest/logtest_test.go+32 −0
CI passed — run details
diff --git a/internal/home/logs_test.go b/internal/home/logs_test.go| index 0f20db5..d2d0309 100644 |
| --- a/internal/home/logs_test.go |
| +++ b/internal/home/logs_test.go |
| @@ -1,6 +1,7 @@ |
| package home |
| import ( |
| + "context" |
| "log" |
| "log/slog" |
| "net/http" |
| @@ -29,7 +30,7 @@ import ( |
| // |
| // 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 |
| +// 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, |
| @@ -129,22 +130,29 @@ func TestNoContentInLogs(t *testing.T) { |
| 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 answers 404 or 405 never ran its |
| - // handler, so anything it logs went unscanned and the gate |
| - // passed by not looking — the failure mode the zero-routes |
| - // check above already guards against, one level down. The |
| - // likeliest cause is a regex-constrained parameter |
| - // ({id:[0-9]+}) that the canary does not satisfy, including |
| - // the nested-brace shape {id:[0-9]{2}}, which fillParams |
| - // mangles rather than fills. Both are silent today; this makes |
| - // them loud on the day someone adds one. |
| - if declared[tg] && (w.Code == http.StatusNotFound || w.Code == http.StatusMethodNotAllowed) { |
| - t.Errorf("%s %s answered %d: the route is declared but its handler never ran, "+ |
| - "so gate 9 did not scan it. If it has a constrained parameter, fillParams "+ |
| - "needs a value that satisfies it.", tg.method, tg.path, w.Code) |
| + // 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) |
| } |
| } |
diff --git a/internal/home/logtest/logtest.go b/internal/home/logtest/logtest.go| index 8037675..9ea52a7 100644 |
| --- a/internal/home/logtest/logtest.go |
| +++ b/internal/home/logtest/logtest.go |
| @@ -54,6 +54,8 @@ package logtest |
| import ( |
| "context" |
| + "encoding/base64" |
| + "fmt" |
| "log/slog" |
| "math" |
| "net/url" |
| @@ -113,6 +115,12 @@ func NewRecorder() *Recorder { return &Recorder{} } |
| // 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 |
| @@ -182,10 +190,30 @@ func (r *Recorder) found() string { |
| // copy is the one likeliest to reach an error string. |
| // |
| // strconv.Quote covers what TextHandler does to a value that needs |
| -// quoting, and what JSONHandler does to one carrying an escape. |
| +// 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) |
| - return []string{c, url.QueryEscape(c), url.PathEscape(c), q[1 : len(q)-1]} |
| + 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 |
diff --git a/internal/home/logtest/logtest_test.go b/internal/home/logtest/logtest_test.go| index 2afa493..1a903d8 100644 |
| --- a/internal/home/logtest/logtest_test.go |
| +++ b/internal/home/logtest/logtest_test.go |
| @@ -371,3 +371,35 @@ func TestRecorderSurvivesValuesThatPanicWhenMarshalled(t *testing.T) { |
| }) |
| } |
| } |
| + |
| +// 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]) |
| + } |
| + }) |
| + } |
| +} |