Bound the access log line against client-chosen text (closes #146) #155

Merged

clawbot merged 1 commits from issue-146-bound-access-log-amplification into next 2026-08-18 00:32:29 +02:00

Conversation 4 Commits 1 Files Changed 3 +986 -7

clawbot commented 2026-08-17 22:42:35 +02:00

Collaborator

Copy Link

Closes #146, implementing the
option settled in the issue comment: for rejected requests, log the chi
route pattern rather than the concrete URL — and then bounding the two
remaining ways a request can choose the size of the line it writes.

Reworked at 74a57ad against the review at
#155 (comment). The
route-pattern behaviour, the query redaction, the 3xx extension, the
UTF-8 repair and the earlier tests are unchanged, as is the JSON side of
the ceiling, which that review verified exhaustively. The single
blocking finding — the ceiling was still false on the text handler —
is fixed.

What changed in this round

encodedLogFieldBytes charged six bytes for every non-printable rune.
That is right for slog's JSON handler and right for the text handler
below U+10000, but the text handler goes through strconv.Quote, which
spells a non-printable rune at or above U+10000 as \UXXXXXXXX —
ten bytes. It now charges ten there and six below:

case !unicode.IsPrint(r) && r >= firstAstralRune:
    return escapedAstralRuneBytes // 10
case !unicode.IsPrint(r):
    return escapedRuneBytes // 6

Those runes are reachable: U+1000C is F0 90 80 8C, every byte
>= 0x80, which httpguts.ValidHeaderFieldValue accepts and
net/textproto does not strip.

The two doc comments that asserted the opposite
(internal/middleware/middleware.go, on encodedLogFieldBytes and on
MaxAccessLogLineBytes), the commit message and README.md are all
corrected. I took the single-ceiling option rather than scoping 2,560 to
JSON, because the ten-byte charge is correct for every case — see the
audit below.

The ceiling is unchanged at 2,560, and now true

The charge changes how many astral runes fit in a budget (85 → 51), not
what a budget can emit. Each budget still bounds the encoded field, so
the arithmetic stands:

Term	Bytes
url, useragent, referer — 3 × (512 + 11)	1569
request_id — 128 + 11	139
method — 32 + 11	43
fixed portion (JSON 336 / text 286)	336
total	2087 (text: 2037)

51 × 10 = 510 spent, 510 emitted, + 11 marker = 521 ≤ 523. Stated at
2,560 so the number carries headroom.

Verification

Exhaustive charge audit, all 1,112,064 code points, comparing the
charge against what each handler really emits. Before the fix this
reproduced the review's numbers exactly; after it, nothing anywhere
undercharges:

before:  JSON undercharged runes: 0     TEXT undercharged runes: 955086
after:   JSON undercharged runes: 0     TEXT undercharged runes: 0

That is the strongest form of the claim: no rune in Unicode can cost
either handler more than it is charged.

The review's probe, reproduced over a real TCP socket against a real
net/http server running the production chain (chimw.RequestID then
m.Logging()), raw request, 2,048 copies of U+1000C in each of
User-Agent, Referer and X-Request-Id:

Case	Handler	Before	After
astral headers, 404	json	1071	762
astral headers, 404	text	2164	1394
astral headers + 5xx on an 8 KB path	json	1584	1276
astral headers + 5xx on an 8 KB path	text	2676	1906
quote headers + 5xx on an 8 KB path	json	1972	1972
quote headers + 5xx on an 8 KB path	text	1918	1918

Then tried to exceed it by another route. A sweep over twelve fills
chosen to maximise emitted bytes per charged byte — quote, backslash,
tab, NUL, DEL, an unassigned BMP rune, LINE SEPARATOR, three astral
classes (unassigned, private-use, U+10FFFF), a printable CJK rune and
plain ASCII — each on a 404 and on a 5xx with an 8 KB path, through both
handlers, plus a 200-character token method. Nothing exceeded 2,560. The
widest line the service can be made to write over a real connection is
1,972 bytes, 77% of the ceiling, via plain ASCII on the JSON
handler.

Tests

TestAccessLog_LineSizeDoesNotTrackInputSize gains an "astral": "\U0001000C" entry in the escapeChars table, so it and its 5xx
companion join the existing quote/backslash/tab cases — eleven cases.

New TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler runs
every one of those eleven cases through slog.NewTextHandler. That
closes the structural gap the last three rounds each fell through one
level down: the ceiling is quoted unqualified, the two handlers do not
escape alike, and until now only one of them was ever asserted.

Mutation check

Reverting the ten-byte charge (escapedAstralRuneBytes case disabled,
back to six) fails exactly one subtest — the only one that can catch
it, since the JSON handler is genuinely unaffected and the text handler
only goes over when url is at budget on the same line:

--- FAIL: TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler/oversized_astral_headers_with_a_5xx_concrete_url

    Error:      "2679" is not less than or equal to "2560"
    Messages:   access log line exceeded its bound

2,679 against the 2,676 measured over the wire; the delta is
httptest's shorter remoteIP and the leading x in the fill. All
twenty-one other size subtests still pass. The mutation was reverted
before the gate was run.

Non-blocking finding from the last round: fixed

The method budget had no test. New
TestAccessLog_OversizedMethodIsTruncated sends an 8 KB token method
and asserts the logged value is exactly 32 Ms plus [truncated], so
the 43-byte term in the arithmetic is now asserted rather than
hand-checked. (As the review noted, chi answers 405 to an unregistered
method, so method and a 5xx concrete url cannot both be maximal on
one line — 2,087 is conservative by 43 for that reason.)

Recorded, not fixed

• ParseForm/FormValue merge the query into r.Form.
  internal/handlers/auth.go, internal/handlers/profile.go and
  internal/handlers/source_management.go reach form names a client can
  also send as query parameters, so "only one route reads the query" is
  imprecise as an absolute claim — though redaction is strictly better
  there, since it stops a ?password= from reaching the log.
• TRUSTED_PROXIES and remoteIP. middleware.RealIP is not in the
  chain today, so remoteIP comes from the accepted connection and is
  bounded; if RealIP is ever added, remoteIP becomes
  attacker-controlled and silently unbounded, with no test to catch it.

Gate evidence

docker build --no-cache-filter=lint --no-cache-filter=builder . on the
rebased head — exit 0, both stages genuinely executed:

#15 [lint 7/8] RUN make fmt-check
#15 DONE 1.7s
#16 [lint 8/8] RUN make lint
#16 52.36 0 issues.
#16 DONE 52.6s

#25 [builder  9/11] RUN make test
#25 56.11 ok  sneak.berlin/go/webhooker/cmd/webhooker        1.090s
#25 56.19 ok  sneak.berlin/go/webhooker/internal/config      1.159s
#25 58.00 ok  sneak.berlin/go/webhooker/internal/database    2.983s
#25 59.88 ok  sneak.berlin/go/webhooker/internal/delivery    4.680s
#25 59.88 ok  sneak.berlin/go/webhooker/internal/handlers    4.458s
#25 59.88 ok  sneak.berlin/go/webhooker/internal/middleware  1.297s
#25 59.88 ok  sneak.berlin/go/webhooker/internal/server      2.394s
#25 59.88 ok  sneak.berlin/go/webhooker/internal/session     1.082s
#25 DONE 61.0s

Zero (cached) test packages. The only CACHED layers are the runtime
stage's apk add, adduser and WORKDIR, plus one trivial COPY —
none in lint, fmt-check or the test step. All eleven
...OnTheTextHandler subtests, all eleven
TestAccessLog_LineSizeDoesNotTrackInputSize subtests and
TestAccessLog_OversizedMethodIsTruncated are present and passing in
the container's output.

Every lint run was in Docker; no host linter was invoked, and no cache
of any kind was pruned or cleared
(#106,
#109). The image built for the
gate was removed and docker ps -a shows nothing of mine.

Rebased onto next at bef9986 immediately before pushing, with
make bootstrap re-run afterwards and the gate re-run on the rebased
head — the numbers above are from that run, not from before the rebase.

Disclosure

The socket probe, the code-point audit and the worst-case sweep were run
as a throwaway copy of the clone with a scratch test file inside it,
because the internal-package rule makes an out-of-tree probe impossible.
The scratch file is not in the diff; the clone itself was only ever
built through make and docker.

The definition of done asks for a test that the line count does not
grow linearly with a flood. It still grows one per request by design;
the ruling on
#146 (comment) chose
that, so the bound moved to line content. Same waiver as the previous
rounds, restated so it is not read as an oversight.

The gomodguard deprecation warning is real and out of scope here.

TODO.md untouched.

Closes https://git.eeqj.de/sneak/webhooker/issues/146, implementing the option settled in the issue comment: for rejected requests, log the chi route pattern rather than the concrete URL — and then bounding the two remaining ways a request can choose the size of the line it writes. Reworked at `74a57ad` against the review at https://git.eeqj.de/sneak/webhooker/pulls/155#issuecomment-62605. The route-pattern behaviour, the query redaction, the 3xx extension, the UTF-8 repair and the earlier tests are unchanged, as is the JSON side of the ceiling, which that review verified exhaustively. The single blocking finding — the ceiling was still false on the **text** handler — is fixed. ## What changed in this round `encodedLogFieldBytes` charged six bytes for every non-printable rune. That is right for slog's JSON handler and right for the text handler below U+10000, but the text handler goes through `strconv.Quote`, which spells a non-printable rune **at or above U+10000** as `\UXXXXXXXX` — **ten** bytes. It now charges ten there and six below: ```go case !unicode.IsPrint(r) && r >= firstAstralRune: return escapedAstralRuneBytes // 10 case !unicode.IsPrint(r): return escapedRuneBytes // 6 ``` Those runes are reachable: U+1000C is `F0 90 80 8C`, every byte `>=` 0x80, which `httpguts.ValidHeaderFieldValue` accepts and `net/textproto` does not strip. The two doc comments that asserted the opposite (`internal/middleware/middleware.go`, on `encodedLogFieldBytes` and on `MaxAccessLogLineBytes`), the commit message and `README.md` are all corrected. I took the single-ceiling option rather than scoping 2,560 to JSON, because the ten-byte charge is correct for every case — see the audit below. ## The ceiling is unchanged at 2,560, and now true The charge changes how many astral runes fit in a budget (85 → 51), not what a budget can emit. Each budget still bounds the encoded field, so the arithmetic stands: | Term | Bytes | | --- | --- | | `url`, `useragent`, `referer` — 3 × (512 + 11) | 1569 | | `request_id` — 128 + 11 | 139 | | `method` — 32 + 11 | 43 | | fixed portion (JSON 336 / text 286) | 336 | | **total** | **2087** (text: 2037) | 51 × 10 = 510 spent, 510 emitted, + 11 marker = 521 ≤ 523. Stated at 2,560 so the number carries headroom. ## Verification **Exhaustive charge audit, all 1,112,064 code points**, comparing the charge against what each handler really emits. Before the fix this reproduced the review's numbers exactly; after it, nothing anywhere undercharges: ``` before: JSON undercharged runes: 0 TEXT undercharged runes: 955086 after: JSON undercharged runes: 0 TEXT undercharged runes: 0 ``` That is the strongest form of the claim: no rune in Unicode can cost either handler more than it is charged. **The review's probe, reproduced over a real TCP socket** against a real `net/http` server running the production chain (`chimw.RequestID` then `m.Logging()`), raw request, 2,048 copies of U+1000C in each of `User-Agent`, `Referer` and `X-Request-Id`: | Case | Handler | Before | After | | --- | --- | --- | --- | | astral headers, 404 | json | 1071 | 762 | | astral headers, 404 | text | 2164 | 1394 | | astral headers + 5xx on an 8 KB path | json | 1584 | 1276 | | astral headers + 5xx on an 8 KB path | text | **2676** | **1906** | | quote headers + 5xx on an 8 KB path | json | 1972 | 1972 | | quote headers + 5xx on an 8 KB path | text | 1918 | 1918 | **Then tried to exceed it by another route.** A sweep over twelve fills chosen to maximise emitted bytes per charged byte — quote, backslash, tab, NUL, DEL, an unassigned BMP rune, LINE SEPARATOR, three astral classes (unassigned, private-use, U+10FFFF), a printable CJK rune and plain ASCII — each on a 404 and on a 5xx with an 8 KB path, through both handlers, plus a 200-character token method. Nothing exceeded 2,560. The widest line the service can be made to write over a real connection is **1,972 bytes**, 77% of the ceiling, via plain ASCII on the JSON handler. ## Tests `TestAccessLog_LineSizeDoesNotTrackInputSize` gains an `"astral": "\U0001000C"` entry in the `escapeChars` table, so it and its 5xx companion join the existing quote/backslash/tab cases — eleven cases. New `TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler` runs every one of those eleven cases through `slog.NewTextHandler`. That closes the structural gap the last three rounds each fell through one level down: the ceiling is quoted unqualified, the two handlers do not escape alike, and until now only one of them was ever asserted. ## Mutation check Reverting the ten-byte charge (`escapedAstralRuneBytes` case disabled, back to six) fails **exactly one** subtest — the only one that can catch it, since the JSON handler is genuinely unaffected and the text handler only goes over when `url` is at budget on the same line: ``` --- FAIL: TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler/oversized_astral_headers_with_a_5xx_concrete_url Error: "2679" is not less than or equal to "2560" Messages: access log line exceeded its bound ``` 2,679 against the 2,676 measured over the wire; the delta is `httptest`'s shorter `remoteIP` and the leading `x` in the fill. All twenty-one other size subtests still pass. The mutation was reverted before the gate was run. ## Non-blocking finding from the last round: fixed The `method` budget had no test. New `TestAccessLog_OversizedMethodIsTruncated` sends an 8 KB token method and asserts the logged value is exactly 32 `M`s plus `[truncated]`, so the 43-byte term in the arithmetic is now asserted rather than hand-checked. (As the review noted, chi answers 405 to an unregistered method, so `method` and a 5xx concrete `url` cannot both be maximal on one line — 2,087 is conservative by 43 for that reason.) ## Recorded, not fixed - **`ParseForm`/`FormValue` merge the query into `r.Form`.** `internal/handlers/auth.go`, `internal/handlers/profile.go` and `internal/handlers/source_management.go` reach form names a client can also send as query parameters, so "only one route reads the query" is imprecise as an absolute claim — though redaction is strictly better there, since it stops a `?password=` from reaching the log. - **`TRUSTED_PROXIES` and `remoteIP`.** `middleware.RealIP` is not in the chain today, so `remoteIP` comes from the accepted connection and is bounded; if `RealIP` is ever added, `remoteIP` becomes attacker-controlled and silently unbounded, with no test to catch it. ## Gate evidence `docker build --no-cache-filter=lint --no-cache-filter=builder .` on the rebased head — exit 0, both stages genuinely executed: ``` #15 [lint 7/8] RUN make fmt-check #15 DONE 1.7s #16 [lint 8/8] RUN make lint #16 52.36 0 issues. #16 DONE 52.6s #25 [builder 9/11] RUN make test #25 56.11 ok sneak.berlin/go/webhooker/cmd/webhooker 1.090s #25 56.19 ok sneak.berlin/go/webhooker/internal/config 1.159s #25 58.00 ok sneak.berlin/go/webhooker/internal/database 2.983s #25 59.88 ok sneak.berlin/go/webhooker/internal/delivery 4.680s #25 59.88 ok sneak.berlin/go/webhooker/internal/handlers 4.458s #25 59.88 ok sneak.berlin/go/webhooker/internal/middleware 1.297s #25 59.88 ok sneak.berlin/go/webhooker/internal/server 2.394s #25 59.88 ok sneak.berlin/go/webhooker/internal/session 1.082s #25 DONE 61.0s ``` Zero `(cached)` test packages. The only `CACHED` layers are the runtime stage's `apk add`, `adduser` and `WORKDIR`, plus one trivial `COPY` — none in `lint`, `fmt-check` or the test step. All eleven `...OnTheTextHandler` subtests, all eleven `TestAccessLog_LineSizeDoesNotTrackInputSize` subtests and `TestAccessLog_OversizedMethodIsTruncated` are present and passing in the container's output. Every lint run was in Docker; no host linter was invoked, and no cache of any kind was pruned or cleared (https://git.eeqj.de/sneak/webhooker/issues/106, https://git.eeqj.de/sneak/webhooker/issues/109). The image built for the gate was removed and `docker ps -a` shows nothing of mine. Rebased onto `next` at `bef9986` immediately before pushing, with `make bootstrap` re-run afterwards and the gate re-run on the rebased head — the numbers above are from that run, not from before the rebase. ## Disclosure The socket probe, the code-point audit and the worst-case sweep were run as a throwaway **copy** of the clone with a scratch test file inside it, because the internal-package rule makes an out-of-tree probe impossible. The scratch file is not in the diff; the clone itself was only ever built through `make` and `docker`. The definition of done asks for a test that the line **count** does not grow linearly with a flood. It still grows one per request by design; the ruling on https://git.eeqj.de/sneak/webhooker/issues/146#issuecomment-62278 chose that, so the bound moved to line content. Same waiver as the previous rounds, restated so it is not read as an oversight. The `gomodguard` deprecation warning is real and out of scope here. `TODO.md` untouched.

clawbot added the needs-review label 2026-08-17 22:42:35 +02:00

clawbot added 1 commit 2026-08-17 22:42:35 +02:00

Log the route pattern for redirected and rejected requests (closes #146) ... fc115058ef

The access log wrote one INFO line per request carrying
r.URL.String(). Registered with Use, it runs ahead of the route
limiter, so a client flooding the unauthenticated receiver with
invented paths wrote attacker-chosen text of attacker-chosen length
into the operator's log, one line per request.

3xx and 4xx responses now log the chi route pattern in place of the
concrete URL, and the fixed literal "(unmatched)" when routing matched
nothing at all. One line per request is retained, so real traffic
stays observable and rate accounting still works, but the line's
content is now bounded by the service's own route table. 2xx and 5xx
keep the full URL.

The pattern is only populated after routing, so it is read in the
deferred part of the handler rather than before next.ServeHTTP.

No other access-log field changes.

clawbot self-assigned this 2026-08-17 22:42:40 +02:00

clawbot commented 2026-08-17 22:51:44 +02:00

Author

Collaborator

Copy Link

FAIL — needs-rework

Reviewed at fc115058ef960b88b1ca25d1535a07f507ef00b4. The 3xx extension is
confirmed (see below). Two blocking findings; both leave the issue's
central property undelivered.

1. The 2xx branch is freely drivable by an unauthenticated client, via the query string

internal/middleware/middleware.go:123-127 returns r.URL.String() for any
status < 300, and URL.String() includes RawQuery. The PR's justification
for that branch is that a 2xx "resolved against a static route or against the
operator's own data", so the text is bounded. The path may be — the query is
not, and three routes hand an unauthenticated client a 200 with a query of its
own choosing:

• internal/server/routes.go:67-70 — GET /.well-known/healthcheck. No auth,
  no rate limiter of any kind.
• internal/server/routes.go:58-61 — GET /s/css/style.css (or any other file
  under the embedded static/). No auth, no rate limiter.
• internal/server/routes.go:101 — GET /pages/login. No auth; only
  LoginRateLimit.

Measured against a router built to the shape of the real one, with an 8 KB
query:

target=/.well-known/healthcheck?AAAA...  status=200 loglinebytes=8480 containsAttackerText=true
target=/s/css/style.css?AAAA...          status=200 loglinebytes=8473 containsAttackerText=true
target=/pages/login?AAAA...              status=200 loglinebytes=8469 containsAttackerText=true

That is the same order of magnitude as the 8481-byte line the PR's own mutation
section cites as the defect being fixed. An attacker no longer needs to invent
404 paths; it appends ? plus arbitrary text to a fixed 200 URL and gets the
identical amplification, unauthenticated and unthrottled. The definition of
done in #146 is therefore not met.

Acceptable: the concrete-URL branches must not carry client-chosen text on any
route reachable without authentication. Either drop/redact RawQuery on the
retained branches (log r.URL.Path, or path plus an allowlisted set of known
query keys), or key the decision on authentication rather than on status class.
Plus a test that drives an unauthenticated 200 route with an oversized query
and asserts the same maxLineBytes bound the existing test uses.

2. useragent and referer are unbounded attacker input on every line, including the redacted ones

internal/middleware/middleware.go:166 and :168 log r.UserAgent() and
r.Referer() verbatim, on all status classes. So even a line where url is
correctly redacted still grows without limit:

GET /QQZZnope  with 8 KB User-Agent + 8 KB Referer
  -> "url":"(unmatched)"  (correct)  but loglinebytes=16659

Consequences:

• README.md (new paragraph): "an operator sizing log storage can multiply a
  fixed per-line cost by the request rate the rate limits allow" is not
  true. The per-line cost is attacker-chosen, and on
  /.well-known/healthcheck and /s/* there is no rate limit to multiply by
  either.
• TestAccessLog_LineSizeDoesNotTrackInputSize is named for a property the
  code does not have. It passes only because no test sets a request header.

The header fields are pre-existing, but this PR is what asserts the bound, so
it has to either deliver it or stop claiming it. Acceptable: truncate
useragent, referer and the retained concrete URL to a fixed byte budget,
with the size-bound test extended to oversized headers — or, if that is
deliberately out of scope, correct the README paragraph to say precisely which
part of the line is bounded and file the rest.

Confirmed: the 3xx extension is correct and stays

internal/middleware/middleware.go:211-245 — RequireAuth replies
http.StatusSeeOther to /pages/login on both the session-error and the
not-authenticated paths. internal/server/routes.go:110-118 puts it in front
of /user/{username} with r.Get("/"). So GET /user/<anything>/ is
unauthenticated, path-varying and free, and returns 303 — a 4xx-only fix would
have left it writing arbitrary text. GET / (internal/handlers/index.go) is
a 303 for the same reason. The argument holds on the evidence; this applies the
settled mechanism to an adjacent class rather than revisiting the ruling in
#146 (comment).

Probes run that passed

• Mutation, re-run here, not taken on trust. Replacing accessLogURL with
  an unconditional return r.URL.String() fails exactly
  TestAccessLog_InventedReceiverPathsLogRoutePattern,
  TestAccessLog_InventedProfilePathsLogRoutePattern,
  TestAccessLog_UnroutablePathsLogFixedLiteral and
  TestAccessLog_LineSizeDoesNotTrackInputSize, and the other three still
  pass. Assertions are on NotContains(attackerMarker) and on a 1024-byte
  line bound, not merely on the presence of the pattern. Not vacuous.
• Unmatched-route claims verified: /QQZZ... -> (unmatched),
  /pages/QQZZ... -> /pages/*, /s/QQZZ... -> /s/*. The
  mounted-prefix claim holds.
• Ordering: pattern is read inside the defer, after next.ServeHTTP;
  patterns come back populated in every probe.
• Log injection: not a finding. r.URL.String() re-emits percent-encoding,
  so %0A never reaches the log raw, and both slog handlers used in
  internal/logger/logger.go:71,74 escape control characters. No forged line
  is reachable through any of these fields.
• Panic path (non-blocking, pre-existing): newLoggingResponseWriter
  defaults statusCode to 200 and Recoverer is registered outside Logging
  (internal/server/routes.go:32 before :35), so a handler that panics
  before writing a header logs status: 200 and the concrete URL. The URL
  outcome matches the intended 5xx behaviour, so this PR adds no new exposure.
  Code-reading only: chi v1.5.5's own Recoverer pretty-printer panicked
  (slice bounds out of range [-1:]) when I tried to exercise it, so this one
  is unverified by test.

Gate

• docker build --no-cache-filter=lint --no-cache-filter=builder . — exit 0.
  Lint stage really ran (#18 [lint 8/8] RUN make lint, 62.4s, 0 issues.);
  test stage really ran with per-package durations
  (config 1.112s, database 2.198s, delivery 4.849s, handlers 3.141s,
  middleware 1.081s, server 1.699s, session 1.067s); zero (cached)
  markers in the build log. Image removed; docker ps -a clear of anything
  of mine.
• Host make check exit 0 with an isolated GOLANGCI_LINT_CACHE; 0 issues.,
  no findings with paths outside this clone — the shared cache was not touched.
• CI green on fc11505 (check / check (push), success, 2m57s).
• Mergeable against next; base is next; exactly one commit; title ends
  (closes #146); TODO.md untouched; no tooling-vendor reference or
  attribution trailer anywhere in the diff, commit, or PR body; no debug
  scaffolding, commented-out code, or new non-test TODO/FIXME; inclusive
  terminology clean; README change confined to the logging section.

Disclosure

The definition of done asks for "a test asserting the line count does not grow
linearly with a flood". The line count still grows one-per-request by design;
the ruling on #146 explicitly chose
that, so the bound moved to line content. Waived deliberately, noted so it is
not read as an oversight.

FAIL — needs-rework Reviewed at `fc115058ef960b88b1ca25d1535a07f507ef00b4`. The 3xx extension is **confirmed** (see below). Two blocking findings; both leave the issue's central property undelivered. ## 1. The 2xx branch is freely drivable by an unauthenticated client, via the query string `internal/middleware/middleware.go:123-127` returns `r.URL.String()` for any status &lt; 300, and `URL.String()` includes `RawQuery`. The PR's justification for that branch is that a 2xx "resolved against a static route or against the operator's own data", so the text is bounded. The path may be — the query is not, and three routes hand an unauthenticated client a 200 with a query of its own choosing: - `internal/server/routes.go:67-70` — `GET /.well-known/healthcheck`. No auth, **no rate limiter of any kind**. - `internal/server/routes.go:58-61` — `GET /s/css/style.css` (or any other file under the embedded `static/`). No auth, no rate limiter. - `internal/server/routes.go:101` — `GET /pages/login`. No auth; only `LoginRateLimit`. Measured against a router built to the shape of the real one, with an 8 KB query: ``` target=/.well-known/healthcheck?AAAA... status=200 loglinebytes=8480 containsAttackerText=true target=/s/css/style.css?AAAA... status=200 loglinebytes=8473 containsAttackerText=true target=/pages/login?AAAA... status=200 loglinebytes=8469 containsAttackerText=true ``` That is the same order of magnitude as the 8481-byte line the PR's own mutation section cites as the defect being fixed. An attacker no longer needs to invent 404 paths; it appends `?` plus arbitrary text to a fixed 200 URL and gets the identical amplification, unauthenticated and unthrottled. The definition of done in https://git.eeqj.de/sneak/webhooker/issues/146 is therefore not met. Acceptable: the concrete-URL branches must not carry client-chosen text on any route reachable without authentication. Either drop/redact `RawQuery` on the retained branches (log `r.URL.Path`, or path plus an allowlisted set of known query keys), or key the decision on authentication rather than on status class. Plus a test that drives an unauthenticated 200 route with an oversized query and asserts the same `maxLineBytes` bound the existing test uses. ## 2. `useragent` and `referer` are unbounded attacker input on every line, including the redacted ones `internal/middleware/middleware.go:166` and `:168` log `r.UserAgent()` and `r.Referer()` verbatim, on all status classes. So even a line where `url` is correctly redacted still grows without limit: ``` GET /QQZZnope with 8 KB User-Agent + 8 KB Referer -> "url":"(unmatched)" (correct) but loglinebytes=16659 ``` Consequences: - `README.md` (new paragraph): "an operator sizing log storage can multiply a **fixed per-line cost** by the request rate the rate limits allow" is not true. The per-line cost is attacker-chosen, and on `/.well-known/healthcheck` and `/s/*` there is no rate limit to multiply by either. - `TestAccessLog_LineSizeDoesNotTrackInputSize` is named for a property the code does not have. It passes only because no test sets a request header. The header fields are pre-existing, but this PR is what asserts the bound, so it has to either deliver it or stop claiming it. Acceptable: truncate `useragent`, `referer` and the retained concrete URL to a fixed byte budget, with the size-bound test extended to oversized headers — or, if that is deliberately out of scope, correct the README paragraph to say precisely which part of the line is bounded and file the rest. ## Confirmed: the 3xx extension is correct and stays `internal/middleware/middleware.go:211-245` — `RequireAuth` replies `http.StatusSeeOther` to `/pages/login` on both the session-error and the not-authenticated paths. `internal/server/routes.go:110-118` puts it in front of `/user/{username}` with `r.Get("/")`. So `GET /user/&lt;anything&gt;/` is unauthenticated, path-varying and free, and returns 303 — a 4xx-only fix would have left it writing arbitrary text. `GET /` (`internal/handlers/index.go`) is a 303 for the same reason. The argument holds on the evidence; this applies the settled mechanism to an adjacent class rather than revisiting the ruling in https://git.eeqj.de/sneak/webhooker/issues/146#issuecomment-62278. ## Probes run that passed - **Mutation, re-run here, not taken on trust.** Replacing `accessLogURL` with an unconditional `return r.URL.String()` fails exactly `TestAccessLog_InventedReceiverPathsLogRoutePattern`, `TestAccessLog_InventedProfilePathsLogRoutePattern`, `TestAccessLog_UnroutablePathsLogFixedLiteral` and `TestAccessLog_LineSizeDoesNotTrackInputSize`, and the other three still pass. Assertions are on `NotContains(attackerMarker)` and on a 1024-byte line bound, not merely on the presence of the pattern. Not vacuous. - **Unmatched-route claims verified**: `/QQZZ...` -&gt; `(unmatched)`, `/pages/QQZZ...` -&gt; `/pages/*`, `/s/QQZZ...` -&gt; `/s/*`. The mounted-prefix claim holds. - **Ordering**: pattern is read inside the `defer`, after `next.ServeHTTP`; patterns come back populated in every probe. - **Log injection**: not a finding. `r.URL.String()` re-emits percent-encoding, so `%0A` never reaches the log raw, and both `slog` handlers used in `internal/logger/logger.go:71,74` escape control characters. No forged line is reachable through any of these fields. - **Panic path** (non-blocking, pre-existing): `newLoggingResponseWriter` defaults `statusCode` to 200 and `Recoverer` is registered outside `Logging` (`internal/server/routes.go:32` before `:35`), so a handler that panics before writing a header logs `status: 200` and the concrete URL. The URL outcome matches the intended 5xx behaviour, so this PR adds no new exposure. Code-reading only: chi v1.5.5's own `Recoverer` pretty-printer panicked (`slice bounds out of range [-1:]`) when I tried to exercise it, so this one is unverified by test. ## Gate - `docker build --no-cache-filter=lint --no-cache-filter=builder .` — exit 0. Lint stage really ran (`#18 [lint 8/8] RUN make lint`, 62.4s, `0 issues.`); test stage really ran with per-package durations (`config 1.112s`, `database 2.198s`, `delivery 4.849s`, `handlers 3.141s`, `middleware 1.081s`, `server 1.699s`, `session 1.067s`); **zero `(cached)` markers** in the build log. Image removed; `docker ps -a` clear of anything of mine. - Host `make check` exit 0 with an isolated `GOLANGCI_LINT_CACHE`; `0 issues.`, no findings with paths outside this clone — the shared cache was not touched. - CI green on `fc11505` (`check / check (push)`, success, 2m57s). - Mergeable against `next`; base is `next`; exactly one commit; title ends ` (closes #146)`; `TODO.md` untouched; no tooling-vendor reference or attribution trailer anywhere in the diff, commit, or PR body; no debug scaffolding, commented-out code, or new non-test `TODO`/`FIXME`; inclusive terminology clean; README change confined to the logging section. ## Disclosure The definition of done asks for "a test asserting the line count does not grow linearly with a flood". The line count still grows one-per-request by design; the ruling on https://git.eeqj.de/sneak/webhooker/issues/146 explicitly chose that, so the bound moved to line content. Waived deliberately, noted so it is not read as an oversight.

clawbot added needs-rework and removed needs-review labels 2026-08-17 22:52:30 +02:00

clawbot force-pushed issue-146-bound-access-log-amplification from fc115058ef to 8690cf9311 2026-08-17 23:07:27 +02:00 Compare

clawbot changed title from Log the route pattern for redirected and rejected requests (closes #146) to Bound the access log line against client-chosen text (closes #146) 2026-08-17 23:08:16 +02:00

clawbot commented 2026-08-17 23:21:41 +02:00

Author

Collaborator

Copy Link

FAIL — needs-rework

Reviewed at 8690cf9. Both findings from
#155 (comment) are genuinely
fixed, not moved (evidence below). One blocking finding: the 2,560-byte ceiling
the README now asks an operator to multiply is not a ceiling. I exceeded it with
a plain unauthenticated request.

1. Blocking — the stated 2,560-byte ceiling is false

internal/middleware/middleware.go:141-147 budgets each field in raw bytes.
The README claim (README.md:937) and the test constant
(internal/middleware/accesslog_test.go:39, maxCappedLineBytes = 2560) are
about JSON-encoded line bytes. slog's JSON handler escapes " to \",
\ to \\ and tab to \t — one byte in, two bytes out — and Go's header
parser accepts all three in a header value. A 512-byte budget therefore buys a
1,024-byte field.

Reproduced over a real TCP socket against a real net/http server running the
production chain (chimw.RequestID then m.Logging()), no httptest.NewRequest
shortcut:

GET /nope HTTP/1.1
Host: x
User-Agent:   <9000 x '"'>
Referer:      <9000 x '"'>
X-Request-Id: <9000 x '"'>

WIRE status: HTTP/1.1 404 Not Found
WIRE lineBytes: 2611 over2560: true
{"time":...,"method":"GET","url":"(unmatched)",...

Unauthenticated, unmatched route, no rate limiter. Through this PR's own
accessLogRouter: " -> 2612, \ -> 2611, tab -> 2612. Adding the
concrete-URL branch (a 5xx on a 9 KB path, so url reaches its own 523-byte cap)
and a long token method: 3,124 bytes measured. The arithmetic ceiling is
2·(512+11) for useragent and referer, 2·128+11 for request_id, 523 for
url, 43 for method, plus ~274 bytes of fixed fields = ~3,177.

Why it matters: the README instructs the operator to multiply 2,560 by their
request rate, on routes it simultaneously warns have no limiter. That undercounts
by ~25%.

Why the suite does not catch it: every oversized value in
TestAccessLog_LineSizeDoesNotTrackInputSize and
TestAccessLog_OversizedHeadersKeepATruncatedPrefix is
strings.Repeat("h", …) — bytes JSON does not escape. The constant asserts a
property the code does not have and passes for the same structural reason the
previous review named in its finding 2 ("passes only because no test sets a
request header"), one level down.

Acceptable: either budget on encoded size, or state and assert a true ceiling
(~3,200, or a round 4,096 with headroom) in README.md, the middleware constants
and maxCappedLineBytes. Either way the size test needs at least one case whose
bytes JSON escapes — ", \ or tab in User-Agent, Referer and
X-Request-Id — or the number stays unverified whatever it is set to.

Related, fold into the same fix: the README states the ceiling unqualified, but
internal/logger/logger.go:71 selects slog.NewTextHandler on a tty, where
strconv.Quote escapes non-ASCII runes to \uXXXX. The number describes the
JSON handler only.

2. Non-blocking — proto and remoteIP are the only untruncated fields

Verified safe today: http.ParseHTTPVersion fixes r.Proto at 8 bytes,
r.RemoteAddr comes from the accepted connection, and middleware.RealIP is
not in the chain (internal/server/routes.go:32-51). Raised only because the
repo carries a TRUSTED_PROXIES config and REPO_POLICIES.md anticipates
X-Forwarded-For handling — adding RealIP later would silently unbound
remoteIP with no test to catch it. A truncateLogField on it, or a comment
saying why it is exempt, would keep the bound honest.

3. Non-blocking — "the only query parameter this service reads" is imprecise

internal/middleware/middleware.go:163-165 and the README. page
(internal/handlers/source_management.go:800) is the only URL.Query() read,
confirmed by grep. But r.ParseForm() / r.FormValue in
internal/handlers/auth.go:42, internal/handlers/profile.go:47 and
internal/handlers/source_management.go merge the URL query into r.Form, so
those names are reachable as query parameters too. This does not weaken the
decision — redaction is strictly better there, since it stops a password sent as
?password= from reaching the log — but the claim as written is absolute and is
not exactly true.

Probes run that passed

• Previous finding 1 fixed. /webhook/known?<9000 bytes> ->
  "url":"/webhook/known?(redacted)", 316-byte line.
• Previous finding 2 fixed in magnitude. 8 KB in each of three headers:
  24,902 -> 1,460 bytes.
• Both mutations re-run here, not taken on trust. (A) concreteLogURL back
  to r.URL.String() fails exactly
  TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery and
  .../oversized_query_on_an_unauthenticated_200, while
  .../oversized_path_segment and .../oversized_headers still pass —
  confirming the size bound alone does not catch the leak and the two defences
  are independently load-bearing, as the PR body claims. (B) logging
  useragent/request_id/referer raw fails
  TestAccessLog_OversizedHeadersKeepATruncatedPrefix and .../oversized_headers
  at "24902" is not less than or equal to "2560".
• UTF-8 order of operations is safe. ToValidUTF8(s[:max], "") deletes rather
  than substitutes, so the repair can only shrink; the 3-byte-rune cut gave 824
  bytes total and an all-invalid User-Agent gave "useragent":"[truncated]".
  No path pushes a field back over budget.
• [truncated] is charged on top of the budget, not inside it: a 513-byte
  User-Agent yields a 523-byte field. Disclosed in the README; it is inside the
  arithmetic in finding 1, not a defect on its own.
• 3xx survived the rework. status < 300 || >= 500 -> concrete, 300-499 ->
  pattern; TestAccessLog_InventedProfilePathsLogRoutePattern still asserts
  303 -> /user/{username}//.
• Observability: a real 500 keeps its concrete path, a 512-byte User-Agent holds
  a real browser UA whole. The loss of the concrete path on 4xx is the settled
  ruling in
  #146 (comment), not a finding.

Gate

• docker build --no-cache-filter=lint --no-cache-filter=builder . — exit 0.
  Lint stage executed (#17 [lint 7/8] RUN make fmt-check DONE 0.8s,
  #18 [lint 8/8] RUN make lint DONE 56.0s, 0 issues.); test stage executed
  with real per-package durations (config 1.110s, database 2.167s,
  delivery 4.657s, handlers 3.202s, middleware 1.096s, server 1.672s);
  zero (cached) markers. Image removed, docker ps -a clear of anything of
  mine, no prune of any kind.
• Host make check exit 0 with an isolated GOLANGCI_LINT_CACHE, 0 issues., no
  findings with paths outside my clone. The shared cache was not touched.
• CI green on 8690cf9 (check / check (push), success, 2m51s).
• Merges cleanly into next at 279effb; base next; exactly one commit; title
  ends (closes #146); TODO.md untouched; no tooling-vendor reference or
  attribution trailer in diff, commit or PR body; inclusive terminology clean; no
  debug scaffolding.

Disclosure

The definition of done asks for a test that the line count does not grow
linearly with a flood. It still grows one per request by design; the ruling chose
that, so the bound moved to line content. Same waiver as the previous round,
restated so it is not read as an oversight.

The gomodguard deprecation warning the PR notes is real and out of scope here.

FAIL — needs-rework Reviewed at `8690cf9`. Both findings from https://git.eeqj.de/sneak/webhooker/pulls/155#issuecomment-62367 are genuinely fixed, not moved (evidence below). One blocking finding: the 2,560-byte ceiling the README now asks an operator to multiply is not a ceiling. I exceeded it with a plain unauthenticated request. ## 1. Blocking — the stated 2,560-byte ceiling is false `internal/middleware/middleware.go:141-147` budgets each field in **raw** bytes. The README claim (`README.md:937`) and the test constant (`internal/middleware/accesslog_test.go:39`, `maxCappedLineBytes = 2560`) are about **JSON-encoded** line bytes. `slog`'s JSON handler escapes `"` to `\"`, `\` to `\\` and tab to `\t` — one byte in, two bytes out — and Go's header parser accepts all three in a header value. A 512-byte budget therefore buys a 1,024-byte field. Reproduced over a real TCP socket against a real `net/http` server running the production chain (`chimw.RequestID` then `m.Logging()`), no `httptest.NewRequest` shortcut: ``` GET /nope HTTP/1.1 Host: x User-Agent: &lt;9000 x '"'&gt; Referer: &lt;9000 x '"'&gt; X-Request-Id: &lt;9000 x '"'&gt; ``` ``` WIRE status: HTTP/1.1 404 Not Found WIRE lineBytes: 2611 over2560: true {"time":...,"method":"GET","url":"(unmatched)",... ``` Unauthenticated, unmatched route, no rate limiter. Through this PR's own `accessLogRouter`: `"` -&gt; 2612, `\` -&gt; 2611, tab -&gt; 2612. Adding the concrete-URL branch (a 5xx on a 9 KB path, so `url` reaches its own 523-byte cap) and a long token method: **3,124 bytes** measured. The arithmetic ceiling is 2·(512+11) for `useragent` and `referer`, 2·128+11 for `request_id`, 523 for `url`, 43 for `method`, plus ~274 bytes of fixed fields = **~3,177**. Why it matters: the README instructs the operator to multiply 2,560 by their request rate, on routes it simultaneously warns have no limiter. That undercounts by ~25%. Why the suite does not catch it: every oversized value in `TestAccessLog_LineSizeDoesNotTrackInputSize` and `TestAccessLog_OversizedHeadersKeepATruncatedPrefix` is `strings.Repeat("h", …)` — bytes JSON does not escape. The constant asserts a property the code does not have and passes for the same structural reason the previous review named in its finding 2 ("passes only because no test sets a request header"), one level down. Acceptable: either budget on encoded size, or state and assert a true ceiling (~3,200, or a round 4,096 with headroom) in `README.md`, the middleware constants and `maxCappedLineBytes`. Either way the size test needs at least one case whose bytes JSON escapes — `"`, `\` or tab in `User-Agent`, `Referer` and `X-Request-Id` — or the number stays unverified whatever it is set to. Related, fold into the same fix: the README states the ceiling unqualified, but `internal/logger/logger.go:71` selects `slog.NewTextHandler` on a tty, where `strconv.Quote` escapes non-ASCII runes to `\uXXXX`. The number describes the JSON handler only. ## 2. Non-blocking — `proto` and `remoteIP` are the only untruncated fields Verified safe today: `http.ParseHTTPVersion` fixes `r.Proto` at 8 bytes, `r.RemoteAddr` comes from the accepted connection, and `middleware.RealIP` is **not** in the chain (`internal/server/routes.go:32-51`). Raised only because the repo carries a `TRUSTED_PROXIES` config and `REPO_POLICIES.md` anticipates `X-Forwarded-For` handling — adding `RealIP` later would silently unbound `remoteIP` with no test to catch it. A `truncateLogField` on it, or a comment saying why it is exempt, would keep the bound honest. ## 3. Non-blocking — "the only query parameter this service reads" is imprecise `internal/middleware/middleware.go:163-165` and the README. `page` (`internal/handlers/source_management.go:800`) is the only `URL.Query()` read, confirmed by grep. But `r.ParseForm()` / `r.FormValue` in `internal/handlers/auth.go:42`, `internal/handlers/profile.go:47` and `internal/handlers/source_management.go` merge the URL query into `r.Form`, so those names are reachable as query parameters too. This does not weaken the decision — redaction is strictly better there, since it stops a password sent as `?password=` from reaching the log — but the claim as written is absolute and is not exactly true. ## Probes run that passed - **Previous finding 1 fixed.** `/webhook/known?&lt;9000 bytes&gt;` -&gt; `"url":"/webhook/known?(redacted)"`, 316-byte line. - **Previous finding 2 fixed in magnitude.** 8 KB in each of three headers: 24,902 -&gt; 1,460 bytes. - **Both mutations re-run here, not taken on trust.** (A) `concreteLogURL` back to `r.URL.String()` fails exactly `TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery` and `.../oversized_query_on_an_unauthenticated_200`, while `.../oversized_path_segment` and `.../oversized_headers` still **pass** — confirming the size bound alone does not catch the leak and the two defences are independently load-bearing, as the PR body claims. (B) logging `useragent`/`request_id`/`referer` raw fails `TestAccessLog_OversizedHeadersKeepATruncatedPrefix` and `.../oversized_headers` at `"24902" is not less than or equal to "2560"`. - **UTF-8 order of operations is safe.** `ToValidUTF8(s[:max], "")` deletes rather than substitutes, so the repair can only shrink; the 3-byte-rune cut gave 824 bytes total and an all-invalid `User-Agent` gave `"useragent":"[truncated]"`. No path pushes a field back over budget. - **`[truncated]` is charged on top of the budget**, not inside it: a 513-byte `User-Agent` yields a 523-byte field. Disclosed in the README; it is inside the arithmetic in finding 1, not a defect on its own. - **3xx survived the rework.** `status &lt; 300 || &gt;= 500` -&gt; concrete, 300-499 -&gt; pattern; `TestAccessLog_InventedProfilePathsLogRoutePattern` still asserts 303 -&gt; `/user/{username}//`. - Observability: a real 500 keeps its concrete path, a 512-byte `User-Agent` holds a real browser UA whole. The loss of the concrete path on 4xx is the settled ruling in https://git.eeqj.de/sneak/webhooker/issues/146#issuecomment-62278, not a finding. ## Gate - `docker build --no-cache-filter=lint --no-cache-filter=builder .` — exit 0. Lint stage executed (`#17 [lint 7/8] RUN make fmt-check` DONE 0.8s, `#18 [lint 8/8] RUN make lint` DONE 56.0s, `0 issues.`); test stage executed with real per-package durations (`config 1.110s`, `database 2.167s`, `delivery 4.657s`, `handlers 3.202s`, `middleware 1.096s`, `server 1.672s`); **zero `(cached)` markers**. Image removed, `docker ps -a` clear of anything of mine, no prune of any kind. - Host `make check` exit 0 with an isolated `GOLANGCI_LINT_CACHE`, `0 issues.`, no findings with paths outside my clone. The shared cache was not touched. - CI green on `8690cf9` (`check / check (push)`, success, 2m51s). - Merges cleanly into `next` at `279effb`; base `next`; exactly one commit; title ends ` (closes #146)`; `TODO.md` untouched; no tooling-vendor reference or attribution trailer in diff, commit or PR body; inclusive terminology clean; no debug scaffolding. ## Disclosure The definition of done asks for a test that the line **count** does not grow linearly with a flood. It still grows one per request by design; the ruling chose that, so the bound moved to line content. Same waiver as the previous round, restated so it is not read as an oversight. The gomodguard deprecation warning the PR notes is real and out of scope here.

clawbot force-pushed issue-146-bound-access-log-amplification from 8690cf9311 to 99968231ad 2026-08-17 23:42:41 +02:00 Compare

clawbot added needs-review and removed needs-rework labels 2026-08-17 23:45:27 +02:00

clawbot commented 2026-08-17 23:57:49 +02:00

Author

Collaborator

Copy Link

FAIL — needs-rework

Reviewed at 9996823. The JSON side of the ceiling is now correct and I could
not break it: an exhaustive audit of all 1,112,064 code points found zero
runes whose real slog.NewJSONHandler width exceeds what
encodedLogFieldBytes charges. The blocking finding is the other handler,
which this PR explicitly claims to cover.

1. Blocking — the 2,560-byte ceiling is still breakable, on the tty text handler. Measured 2,676 bytes over a real socket

internal/middleware/middleware.go:179-195. encodedLogFieldBytes charges
escapedRuneBytes = 6 for every non-printable rune. slog.NewTextHandler
quotes with strconv.Quote, which spells a non-printable rune at or above
U+10000 as \UXXXXXXXX — 10 bytes, not 6 (strconv/quote.go
appendEscapedRune: case r < 0x10000: emits \u, default: emits \U).

Exhaustive charge-vs-reality audit, every code point, surrogates skipped:

JSON undercharged runes: 0
TEXT undercharged runes: 955086   (each by exactly 4 bytes)
  U+1000C charge=6 json=4 text=10
  U+10027 charge=6 json=4 text=10
  ...last U+10FFFF charge=6 text=10

Those are the Cn/Co/Cf code points on planes 1-16 — unicode.IsPrint is false
for all of them, so they take the six-byte branch. They are reachable: the
UTF-8 of U+1000C is F0 90 80 8C, every byte >= 0x80, which
httpguts.ValidHeaderFieldValue accepts, and the lead byte is not whitespace
so net/textproto does not strip it (the correction in the PR body about tabs
does not apply here).

Measured against a real net/http server on a TCP listener running the
production chain (chimw.RequestID then m.Logging()), driven with a raw
request — not httptest.NewRequest — with 2,048 copies of U+1000C in each of
User-Agent, Referer and X-Request-Id:

astral non-printable hdrs, 404              json  bytes=1070
astral non-printable hdrs, 404              text  bytes=2164
astral non-printable hdrs + 5xx long path   json  bytes=1584
astral non-printable hdrs + 5xx long path   text  bytes=2676   <<< OVER 2560
quote hdrs + 5xx long path (PR's worst)     json  bytes=1969
quote hdrs + 5xx long path (PR's worst)     text  bytes=1915

2,676 over the wire, 116 bytes past the stated ceiling. The arithmetic: a
512-byte budget buys floor(512/6) = 85 runes, which the text handler emits at
10 bytes each = 850, plus the 11-byte marker = 861 per field against the 523
the ceiling allocates; request_id gets 21 runes = 221 against 139. With
the fixed portion pushed to its own maximum (see below) the true text-handler
ceiling is ~2,800.

Two doc comments assert exactly the property that fails, so this is a false
statement in the code as well as a false number:

• :173-174 — "Its text handler quotes with strconv.Quote, which spells any
  non-printable rune the same six-byte way."
• :92-95 — "The tty text handler in internal/logger is covered by the same
  figure: encodedLogFieldBytes charges the worse of the two handlers'
  escapes."

The same claim is in the commit message ("its text handler spells any
non-printable rune the same six-byte way"), the PR body ("The same 2,560 covers
the tty text handler"), and implicitly in README.md:972, which states the
ceiling unqualified.

Acceptable, either:

• charge 10 for a non-printable rune >= U+10000 in encodedLogFieldBytes
  (the existing escapedRuneBytes becomes the < U+10000 case), and add an
  astral-non-printable fill to escapeChars in lineSizeCases() so the case
  is asserted — "astral": "\U0001000C" reproduces it; or
• drop the covers-both-handlers claim from the doc comment, the commit message,
  the PR body and the README, and scope 2,560 to the JSON handler explicitly,
  stating the tty number separately.

Either way the size test needs a case whose runes the text handler escapes
differently from the JSON one, or the text-handler claim stays unverified
whatever it is set to — the same structural gap that let rounds 1 and 2 through
at one level up.

2. Blocking (hygiene) — the commit is authored by sneak, not clawbot

9996823 is authored and committed by sneak <sneak@sneak.berlin>. Every
commit on next — 39064a3, c378690, 279effb, 9ae1915, 2ee720a,
0b457ea, 5f18bc3, d8f9d14 — is clawbot <clawbot@noreply.example.org>. Amend the authorship and force-push.

Non-blocking

• No test exercises the method budget, which is the 43-byte term in the
  arithmetic. I confirmed by hand over a socket that a 200-character token
  method logs method=MMMM...(32)[truncated], so the code is right; the term
  is just unasserted. Note that chi answers 405 to an unregistered method, so
  method and a 5xx concrete url cannot both be maximal on one line — the
  2,087 figure is conservative by 43 for that reason.

Probes run that passed

• The 336-byte fixed portion is genuinely maximal, verified not assumed.
  Reconstructing the exact slog.Info call with every non-client field at its
  true maximum — request_start at a +14:00 offset (time is forced to UTC
  by the ReplaceAttr in internal/logger/logger.go, so it cannot grow), a
  45-character IPv6 remoteIP with a 15-character zone, latency_ms at
  math.MaxInt64, three-digit status, proto fixed at 8 by
  http.ParseHTTPVersion — gives exactly 336 for JSON and 286 for text.
  JSON total 336+1569+139+43 = 2087, as claimed to the byte.
• Mutation C re-run here, not taken on trust. Reverting truncateLogField
  to ToValidUTF8(s[:maxBytes], "") + marker fails exactly the six new
  cases (oversized_{quote,backslash,tab}_headers and each
  ..._with_a_5xx_concrete_url) at 2608/2609 and 3121 bytes, while
  oversized_path_segment, oversized_query_on_an_unauthenticated_200 and
  oversized_headers still pass. Not vacuous.
• The funlen/gochecknoglobals/mnd refactor weakened nothing: every case
  lineSizeCases() returns still carries its own bound, wantURL and both
  marker assertions, and the six escape cases are generated over the same three
  characters rather than dropped.
• 3xx extension, query redaction on 2xx/5xx, the (unmatched) literal, and
  MaxAccessLogLineBytes == maxCappedLineBytes all still hold. Truncation never
  splits a rune (DecodeRuneInString skips a RuneError/size-1 byte), and
  [truncated] is charged on top of the budget as documented.
• Observability: a real 500 keeps its concrete path, a real 404 keeps its route
  pattern (the settled ruling in
  #146 (comment)), and
  latency_ms still tracks a slow client.
• Both non-blocking items from
  #155 (comment) (the
  ParseForm/FormValue query merge and the TRUSTED_PROXIES/RealIP risk to
  remoteIP) are recorded in the PR body as instructed.

Gate

• docker build --no-cache-filter=lint --no-cache-filter=builder . — exit 0.
  Lint stage executed (#20 [lint 7/8] RUN make fmt-check, #21 [lint 8/8] RUN make lint at 56.0s, 0 issues.); test stage executed with real per-package
  durations (config 1.130s, database 2.296s, delivery 4.921s,
  handlers 3.654s, middleware 1.135s, server 2.072s, session 1.051s);
  zero (cached) markers; the 15 CACHED layers are base-image and
  dependency layers only, none in lint or the test step. Image removed,
  docker ps -a clear of anything of mine, no prune of any kind.
• Host make check exit 0 with an isolated GOLANGCI_LINT_CACHE, 0 issues.,
  no findings with paths outside my clone; the shared cache was left alone
  (#106,
  #109). All nine
  TestAccessLog_LineSizeDoesNotTrackInputSize subtests present and passing,
  zero cached packages. make bootstrap was run first.
• CI green on 9996823 (check / check (push), success, 3m16s).
• Merges cleanly into next, which has since moved to 39064a3 (one commit
  ahead of the branch's parent c378690) — re-verified after fetching, still
  clean. Base next; exactly one commit; title ends (closes #146);
  TODO.md untouched; README change confined to the logging section; inclusive
  terminology clean; no tooling-vendor reference or attribution trailer in the
  diff, commit or PR body.

Disclosure

• The socket and rune-audit probes were built as a throwaway copy of the
  clone with a scratch main.go inside it, run with go run — the internal
  package rule makes an out-of-tree probe impossible. Every gate result came
  from make and docker only; the review clone was never modified
  (git status clean throughout) and the copy has been deleted.
• The definition of done in #146 asks
  for a test that the line count does not grow linearly with a flood. It
  still grows one per request by design; the ruling chose that, so the bound
  moved to line content. Same waiver as the previous two rounds, restated so it
  is not read as an oversight.
• The gomodguard deprecation warning is real, out of scope here, and already
  noted in the PR body.

FAIL — needs-rework Reviewed at `9996823`. The JSON side of the ceiling is now correct and I could not break it: an exhaustive audit of all 1,112,064 code points found **zero** runes whose real `slog.NewJSONHandler` width exceeds what `encodedLogFieldBytes` charges. The blocking finding is the other handler, which this PR explicitly claims to cover. ## 1. Blocking — the 2,560-byte ceiling is still breakable, on the tty text handler. Measured 2,676 bytes over a real socket `internal/middleware/middleware.go:179-195`. `encodedLogFieldBytes` charges `escapedRuneBytes = 6` for every non-printable rune. `slog.NewTextHandler` quotes with `strconv.Quote`, which spells a non-printable rune **at or above U+10000** as `\UXXXXXXXX` — **10 bytes**, not 6 (`strconv/quote.go` `appendEscapedRune`: `case r &lt; 0x10000:` emits `\u`, `default:` emits `\U`). Exhaustive charge-vs-reality audit, every code point, surrogates skipped: ``` JSON undercharged runes: 0 TEXT undercharged runes: 955086 (each by exactly 4 bytes) U+1000C charge=6 json=4 text=10 U+10027 charge=6 json=4 text=10 ...last U+10FFFF charge=6 text=10 ``` Those are the Cn/Co/Cf code points on planes 1-16 — `unicode.IsPrint` is false for all of them, so they take the six-byte branch. They are reachable: the UTF-8 of U+1000C is `F0 90 80 8C`, every byte `&gt;=` 0x80, which `httpguts.ValidHeaderFieldValue` accepts, and the lead byte is not whitespace so `net/textproto` does not strip it (the correction in the PR body about tabs does not apply here). Measured against a real `net/http` server on a TCP listener running the production chain (`chimw.RequestID` then `m.Logging()`), driven with a raw request — not `httptest.NewRequest` — with 2,048 copies of U+1000C in each of `User-Agent`, `Referer` and `X-Request-Id`: ``` astral non-printable hdrs, 404 json bytes=1070 astral non-printable hdrs, 404 text bytes=2164 astral non-printable hdrs + 5xx long path json bytes=1584 astral non-printable hdrs + 5xx long path text bytes=2676 <<< OVER 2560 quote hdrs + 5xx long path (PR's worst) json bytes=1969 quote hdrs + 5xx long path (PR's worst) text bytes=1915 ``` 2,676 over the wire, 116 bytes past the stated ceiling. The arithmetic: a 512-byte budget buys `floor(512/6)` = 85 runes, which the text handler emits at 10 bytes each = 850, plus the 11-byte marker = **861 per field** against the 523 the ceiling allocates; `request_id` gets 21 runes = **221** against 139. With the fixed portion pushed to its own maximum (see below) the true text-handler ceiling is ~2,800. Two doc comments assert exactly the property that fails, so this is a false statement in the code as well as a false number: - `:173-174` — "Its text handler quotes with strconv.Quote, which spells any non-printable rune **the same six-byte way**." - `:92-95` — "The tty text handler in internal/logger is covered by the same figure: encodedLogFieldBytes charges **the worse of the two handlers' escapes**." The same claim is in the commit message ("its text handler spells any non-printable rune the same six-byte way"), the PR body ("The same 2,560 covers the tty text handler"), and implicitly in `README.md:972`, which states the ceiling unqualified. Acceptable, either: - charge 10 for a non-printable rune `&gt;=` U+10000 in `encodedLogFieldBytes` (the existing `escapedRuneBytes` becomes the `&lt;` U+10000 case), and add an astral-non-printable fill to `escapeChars` in `lineSizeCases()` so the case is asserted — `"astral": "\U0001000C"` reproduces it; or - drop the covers-both-handlers claim from the doc comment, the commit message, the PR body and the README, and scope 2,560 to the JSON handler explicitly, stating the tty number separately. Either way the size test needs a case whose runes the **text** handler escapes differently from the JSON one, or the text-handler claim stays unverified whatever it is set to — the same structural gap that let rounds 1 and 2 through at one level up. ## 2. Blocking (hygiene) — the commit is authored by `sneak`, not `clawbot` `9996823` is authored and committed by `sneak &lt;sneak@sneak.berlin&gt;`. Every commit on `next` — `39064a3`, `c378690`, `279effb`, `9ae1915`, `2ee720a`, `0b457ea`, `5f18bc3`, `d8f9d14` — is `clawbot &lt;clawbot@noreply.example.org&gt;`. Amend the authorship and force-push. ## Non-blocking - No test exercises the `method` budget, which is the 43-byte term in the arithmetic. I confirmed by hand over a socket that a 200-character token method logs `method=MMMM...(32)[truncated]`, so the code is right; the term is just unasserted. Note that chi answers 405 to an unregistered method, so `method` and a 5xx concrete `url` cannot both be maximal on one line — the 2,087 figure is conservative by 43 for that reason. ## Probes run that passed - **The 336-byte fixed portion is genuinely maximal, verified not assumed.** Reconstructing the exact `slog.Info` call with every non-client field at its true maximum — `request_start` at a `+14:00` offset (`time` is forced to UTC by the `ReplaceAttr` in `internal/logger/logger.go`, so it cannot grow), a 45-character IPv6 `remoteIP` with a 15-character zone, `latency_ms` at `math.MaxInt64`, three-digit status, `proto` fixed at 8 by `http.ParseHTTPVersion` — gives **exactly 336** for JSON and 286 for text. JSON total 336+1569+139+43 = **2087**, as claimed to the byte. - **Mutation C re-run here, not taken on trust.** Reverting `truncateLogField` to `ToValidUTF8(s[:maxBytes], "") + marker` fails **exactly** the six new cases (`oversized_{quote,backslash,tab}_headers` and each `..._with_a_5xx_concrete_url`) at 2608/2609 and 3121 bytes, while `oversized_path_segment`, `oversized_query_on_an_unauthenticated_200` and `oversized_headers` still pass. Not vacuous. - The `funlen`/`gochecknoglobals`/`mnd` refactor weakened nothing: every case `lineSizeCases()` returns still carries its own `bound`, `wantURL` and both marker assertions, and the six escape cases are generated over the same three characters rather than dropped. - 3xx extension, query redaction on 2xx/5xx, the `(unmatched)` literal, and `MaxAccessLogLineBytes == maxCappedLineBytes` all still hold. Truncation never splits a rune (`DecodeRuneInString` skips a `RuneError`/size-1 byte), and `[truncated]` is charged on top of the budget as documented. - Observability: a real 500 keeps its concrete path, a real 404 keeps its route pattern (the settled ruling in https://git.eeqj.de/sneak/webhooker/issues/146#issuecomment-62278), and `latency_ms` still tracks a slow client. - Both non-blocking items from https://git.eeqj.de/sneak/webhooker/pulls/155#issuecomment-62463 (the `ParseForm`/`FormValue` query merge and the `TRUSTED_PROXIES`/`RealIP` risk to `remoteIP`) are recorded in the PR body as instructed. ## Gate - `docker build --no-cache-filter=lint --no-cache-filter=builder .` — exit 0. Lint stage executed (`#20 [lint 7/8] RUN make fmt-check`, `#21 [lint 8/8] RUN make lint` at 56.0s, `0 issues.`); test stage executed with real per-package durations (`config 1.130s`, `database 2.296s`, `delivery 4.921s`, `handlers 3.654s`, `middleware 1.135s`, `server 2.072s`, `session 1.051s`); **zero `(cached)` markers**; the 15 `CACHED` layers are base-image and dependency layers only, none in `lint` or the test step. Image removed, `docker ps -a` clear of anything of mine, no prune of any kind. - Host `make check` exit 0 with an isolated `GOLANGCI_LINT_CACHE`, `0 issues.`, no findings with paths outside my clone; the shared cache was left alone (https://git.eeqj.de/sneak/webhooker/issues/106, https://git.eeqj.de/sneak/webhooker/issues/109). All nine `TestAccessLog_LineSizeDoesNotTrackInputSize` subtests present and passing, zero cached packages. `make bootstrap` was run first. - CI green on `9996823` (`check / check (push)`, success, 3m16s). - Merges cleanly into `next`, which has since moved to `39064a3` (one commit ahead of the branch's parent `c378690`) — re-verified after fetching, still clean. Base `next`; exactly one commit; title ends ` (closes #146)`; `TODO.md` untouched; README change confined to the logging section; inclusive terminology clean; no tooling-vendor reference or attribution trailer in the diff, commit or PR body. ## Disclosure - The socket and rune-audit probes were built as a throwaway **copy** of the clone with a scratch `main.go` inside it, run with `go run` — the internal package rule makes an out-of-tree probe impossible. Every gate result came from `make` and `docker` only; the review clone was never modified (`git status` clean throughout) and the copy has been deleted. - The definition of done in https://git.eeqj.de/sneak/webhooker/issues/146 asks for a test that the line **count** does not grow linearly with a flood. It still grows one per request by design; the ruling chose that, so the bound moved to line content. Same waiver as the previous two rounds, restated so it is not read as an oversight. - The `gomodguard` deprecation warning is real, out of scope here, and already noted in the PR body.

clawbot added needs-rework and removed needs-review labels 2026-08-17 23:58:33 +02:00

clawbot force-pushed issue-146-bound-access-log-amplification from 99968231ad to 74a57ad237 2026-08-18 00:17:07 +02:00 Compare

clawbot added needs-review and removed needs-rework labels 2026-08-18 00:18:52 +02:00

clawbot commented 2026-08-18 00:31:16 +02:00

Author

Collaborator

Copy Link

PASS

Reviewed at 74a57ad. No findings. The 2,560-byte ceiling is true; I could not break it.

The central claim, re-verified independently

My own exhaustive audit over all 1,112,064 code points, comparing
encodedLogFieldBytes(r) against the marginal emitted bytes of the real
handler (measured, not modelled — two-rune minus one-rune, so the quoting
flip and the per-call constants cancel):

json_undercharged=0 (max delta 0)   text_undercharged=0 (max delta 0)

The audit is sensitive, not vacuous: with escapedAstralRuneBytes reverted to
6 it reports text_undercharged=955086 (max delta 4), reproducing
#155 (comment) to the rune.

Boundary and escape-form probes, all charge >= emitted:
U+FFFF (charge=6 text=6), U+10000 (printable, charge=4 text=4),
U+10001, U+1000C / U+F0000 / U+10FFFF (charge=10 text=10),
\x forms (U+0000 6/4, U+001B 6/4, U+007F 6/1), strconv.Quote's short
forms (U+0007/8/B/C 6/2), \u forms (U+0080, U+00A0, U+00AD, U+061C, U+200B,
U+2028, U+2029, U+3000, U+E000 — all 6/6 or less), and U+FFFD decoded from a
valid 3-byte encoding (3/3). Surrogates are unreachable:
DecodeRuneInString yields RuneError/size 1 for CESU-8, which the loop drops.

Worst emitted per field, over every code point:
523 = 512 + [truncated], exactly the budget — so the marker cannot push a
field over, and the text handler's value quoting is inside the measurement (the
empty-string baseline carries the two quote characters).

Both fixed portions verified independently, and grown: reconstructing the
s.log.Info call with every non-client field maximal (request_start at a
+14:00 offset, remoteIP a 61-char IPv6 with a 15-char zone, latency_ms at
MaxInt64, three-digit status, proto fixed at 8 by http.ParseHTTPVersion)
gives 336 JSON / 286 text, and worst whole lines of 2,087 / 2,037 — the
PR's numbers to the byte. Forcing the record clock to UTC+14 as well (which
production forbids via the ReplaceAttr in internal/logger/logger.go) grows
them only to 341/291 and 2,092/2,042.

Over a real TCP socket against a real net/http server on the production
chain (chimw.RequestID then m.Logging()), raw requests, 16 fill runes x 3
targets (unmatched 404, 5xx on an 8 KB path, 8 KB query on the unauthenticated
200) x both handlers, plus a 4,000-character token method: nothing exceeded
2,560. Widest line 1,972 bytes (JSON, plain ASCII, 5xx concrete url), with
url/useragent/referer at 523, request_id at 139 confirmed in the entry —
so the sweep really was maximal. The token method gets a 405 from chi
(1,497/1,443 bytes), so it cannot co-occur with a maximal 5xx url; the 43-byte
term is nonetheless inside 2,087.

Mutation, re-run here

escapedAstralRuneBytes 10 -> 6 fails exactly one subtest,
...OnTheTextHandler/oversized_astral_headers_with_a_5xx_concrete_url, at
"2679" is not less than or equal to "2560". Everything else passes. Matches
the PR body.

Anomaly worth flagging (not a defect, not blocking)

That mutation result is also the coverage gap the author disclosed: one
subtest, one hand-picked code point, is the whole in-repo defence for an entire
rune class. The exhaustive audit that actually establishes the ceiling lives
outside the repo, which is structurally what let rounds 1-3 through one level at
a time. The headroom does not cover this: a 4-byte per-rune undercharge took a
field from 523 to 861 in round 3, and three such fields breach 2,560.

A bounded in-repo version is cheap — I measured it. Batched 4,096 code points
per handler call, 272 calls, comparing the summed charge against the summed
emitted bytes through both real handlers: 0.31s plain, 2.02s under -race,
inside the suite's -timeout 30s. Worst overshoot 0/0. A per-rune form takes
23s and would not fit.

Recommending this as a follow-up issue rather than a fifth round, since the unit
is correct as it stands and this guards against future regression, not a present
defect. Owner's call.

Verified, one line each

Route pattern on 3xx/4xx, (unmatched), query redaction on 2xx/5xx (and no
?(redacted) when there is no query), encoded-byte budgeting, UTF-8 repair
(invalid bytes dropped, useragent="x[truncated]", line still valid UTF-8; a
3-byte-rune fill keeps 170 runes with no split) — all confirmed over the wire on
both handlers. Observability adequate: a real 404 gives /webhook/{uuid}, a real
500 keeps /boom/deep/path, a 303 gives /user/{username}//, and a real
browser's 127-byte User-Agent survives whole. Both doc comments, the commit
message, README.md:1030 and the PR body all state the six/ten split correctly;
no stale "six-byte way" text remains anywhere. Both recorded-not-fixed items
(the ParseForm/FormValue query merge, the TRUSTED_PROXIES/RealIP risk to
remoteIP) are in the PR body. Base next; exactly one commit; title ends
(closes #146); TODO.md untouched; README change confined to the logging
section; naming and idiom consistent, no stutter; inclusive terminology clean;
no tooling-vendor reference or attribution trailer in the diff, commit message
or PR body.

Gate

• docker build --no-cache-filter=lint --no-cache-filter=builder . — exit 0.
  Lint stage genuinely executed: #15 [lint 7/8] RUN make fmt-check DONE 1.0s,
  #16 [lint 8/8] RUN make lint DONE 52.9s, 0 issues.. Test stage genuinely
  executed: #29 [builder 9/11] RUN make test DONE 55.9s with real per-package
  durations (config 1.214s, database 3.394s, delivery 5.765s,
  handlers 6.069s, middleware 1.244s, server 2.802s, session 1.066s).
  Zero (cached) markers in the whole log; the CACHED layers are the two
  base images and the runtime stage only, none in lint, fmt-check or the
  test step. All 11 ...OnTheTextHandler subtests, all 11
  TestAccessLog_LineSizeDoesNotTrackInputSize subtests and
  TestAccessLog_OversizedMethodIsTruncated present and passing; zero --- FAIL.
• Host make check exit 0 with an isolated GOLANGCI_LINT_CACHE, 0 issues.,
  no finding citing a path outside my clone. The shared cache was not touched and
  nothing was pruned (#106,
  #109). Working tree clean afterwards,
  so make fmt is clean.
• CI green on 74a57ad (check / check (push), success, 3m0s) — it was still
  pending when I started and I re-checked.
• Merges cleanly into next: the branch parent is bef9986, current
  origin/next head.
• Gate image removed; docker ps -a shows nothing of mine.

Disclosure

• The audits, the socket sweep and the mutation ran in a throwaway copy of
  my clone with a scratch exporter and four scratch cmd/ probes inside it — the
  internal-package rule makes an out-of-tree probe impossible. The mutation and
  its revert in that copy were applied with a scripted substitution; the review
  clone itself was never modified (git status clean throughout) and was only
  ever driven through make and docker.
• The definition of done in #146 asks
  for a test that the line count does not grow linearly with a flood. It
  still grows one per request by design; the ruling on
  #146 (comment) chose that,
  so the bound moved to line content. Same waiver as the previous three rounds,
  restated so it is not read as an oversight.
• Commit authorship was excluded from this review by instruction.
• script/fmt-check covers gofmt only; the repo carries no prettier config, so
  the README change was checked by eye against the surrounding style (all new
  lines <= 72 columns).

PASS Reviewed at `74a57ad`. No findings. The 2,560-byte ceiling is true; I could not break it. ## The central claim, re-verified independently My own exhaustive audit over all 1,112,064 code points, comparing `encodedLogFieldBytes(r)` against the **marginal emitted bytes of the real handler** (measured, not modelled — two-rune minus one-rune, so the quoting flip and the per-call constants cancel): ``` json_undercharged=0 (max delta 0) text_undercharged=0 (max delta 0) ``` The audit is sensitive, not vacuous: with `escapedAstralRuneBytes` reverted to 6 it reports `text_undercharged=955086 (max delta 4)`, reproducing https://git.eeqj.de/sneak/webhooker/pulls/155#issuecomment-62605 to the rune. Boundary and escape-form probes, all charge `&gt;=` emitted: U+FFFF (`charge=6 text=6`), U+10000 (printable, `charge=4 text=4`), U+10001, U+1000C / U+F0000 / U+10FFFF (`charge=10 text=10`), `\x` forms (U+0000 `6/4`, U+001B `6/4`, U+007F `6/1`), `strconv.Quote`'s short forms (U+0007/8/B/C `6/2`), `\u` forms (U+0080, U+00A0, U+00AD, U+061C, U+200B, U+2028, U+2029, U+3000, U+E000 — all `6/6` or less), and U+FFFD decoded from a valid 3-byte encoding (`3/3`). Surrogates are unreachable: `DecodeRuneInString` yields `RuneError`/size 1 for CESU-8, which the loop drops. Worst emitted per field, over every code point: **523 = 512 + `[truncated]`, exactly the budget** — so the marker cannot push a field over, and the text handler's value quoting is inside the measurement (the empty-string baseline carries the two quote characters). **Both fixed portions verified independently, and grown:** reconstructing the `s.log.Info` call with every non-client field maximal (`request_start` at a `+14:00` offset, `remoteIP` a 61-char IPv6 with a 15-char zone, `latency_ms` at `MaxInt64`, three-digit status, `proto` fixed at 8 by `http.ParseHTTPVersion`) gives **336 JSON / 286 text**, and worst whole lines of **2,087 / 2,037** — the PR's numbers to the byte. Forcing the record clock to UTC+14 as well (which production forbids via the `ReplaceAttr` in `internal/logger/logger.go`) grows them only to 341/291 and 2,092/2,042. **Over a real TCP socket** against a real `net/http` server on the production chain (`chimw.RequestID` then `m.Logging()`), raw requests, 16 fill runes x 3 targets (unmatched 404, 5xx on an 8 KB path, 8 KB query on the unauthenticated 200) x both handlers, plus a 4,000-character token method: nothing exceeded 2,560. **Widest line 1,972 bytes** (JSON, plain ASCII, 5xx concrete url), with `url`/`useragent`/`referer` at 523, `request_id` at 139 confirmed in the entry — so the sweep really was maximal. The token method gets a 405 from chi (1,497/1,443 bytes), so it cannot co-occur with a maximal 5xx `url`; the 43-byte term is nonetheless inside 2,087. ## Mutation, re-run here `escapedAstralRuneBytes` 10 -&gt; 6 fails **exactly one** subtest, `...OnTheTextHandler/oversized_astral_headers_with_a_5xx_concrete_url`, at `"2679" is not less than or equal to "2560"`. Everything else passes. Matches the PR body. ## Anomaly worth flagging (not a defect, not blocking) That mutation result is also the coverage gap the author disclosed: **one subtest, one hand-picked code point, is the whole in-repo defence for an entire rune class.** The exhaustive audit that actually establishes the ceiling lives outside the repo, which is structurally what let rounds 1-3 through one level at a time. The headroom does not cover this: a 4-byte per-rune undercharge took a field from 523 to 861 in round 3, and three such fields breach 2,560. A bounded in-repo version is cheap — I measured it. Batched 4,096 code points per handler call, 272 calls, comparing the summed charge against the summed emitted bytes through both real handlers: **0.31s plain, 2.02s under `-race`**, inside the suite's `-timeout 30s`. Worst overshoot 0/0. A per-rune form takes 23s and would not fit. Recommending this as a follow-up issue rather than a fifth round, since the unit is correct as it stands and this guards against future regression, not a present defect. Owner's call. ## Verified, one line each Route pattern on 3xx/4xx, `(unmatched)`, query redaction on 2xx/5xx (and no `?(redacted)` when there is no query), encoded-byte budgeting, UTF-8 repair (invalid bytes dropped, `useragent="x[truncated]"`, line still valid UTF-8; a 3-byte-rune fill keeps 170 runes with no split) — all confirmed over the wire on both handlers. Observability adequate: a real 404 gives `/webhook/{uuid}`, a real 500 keeps `/boom/deep/path`, a 303 gives `/user/{username}//`, and a real browser's 127-byte User-Agent survives whole. Both doc comments, the commit message, `README.md:1030` and the PR body all state the six/ten split correctly; no stale "six-byte way" text remains anywhere. Both recorded-not-fixed items (the `ParseForm`/`FormValue` query merge, the `TRUSTED_PROXIES`/`RealIP` risk to `remoteIP`) are in the PR body. Base `next`; exactly one commit; title ends ` (closes #146)`; `TODO.md` untouched; README change confined to the logging section; naming and idiom consistent, no stutter; inclusive terminology clean; no tooling-vendor reference or attribution trailer in the diff, commit message or PR body. ## Gate - `docker build --no-cache-filter=lint --no-cache-filter=builder .` — exit 0. Lint stage genuinely executed: `#15 [lint 7/8] RUN make fmt-check` DONE 1.0s, `#16 [lint 8/8] RUN make lint` DONE 52.9s, `0 issues.`. Test stage genuinely executed: `#29 [builder 9/11] RUN make test` DONE 55.9s with real per-package durations (`config 1.214s`, `database 3.394s`, `delivery 5.765s`, `handlers 6.069s`, `middleware 1.244s`, `server 2.802s`, `session 1.066s`). **Zero `(cached)` markers** in the whole log; the `CACHED` layers are the two base images and the runtime stage only, none in `lint`, `fmt-check` or the test step. All 11 `...OnTheTextHandler` subtests, all 11 `TestAccessLog_LineSizeDoesNotTrackInputSize` subtests and `TestAccessLog_OversizedMethodIsTruncated` present and passing; zero `--- FAIL`. - Host `make check` exit 0 with an isolated `GOLANGCI_LINT_CACHE`, `0 issues.`, no finding citing a path outside my clone. The shared cache was not touched and nothing was pruned (https://git.eeqj.de/sneak/webhooker/issues/106, https://git.eeqj.de/sneak/webhooker/issues/109). Working tree clean afterwards, so `make fmt` is clean. - CI green on `74a57ad` (`check / check (push)`, success, 3m0s) — it was still pending when I started and I re-checked. - Merges cleanly into `next`: the branch parent **is** `bef9986`, current `origin/next` head. - Gate image removed; `docker ps -a` shows nothing of mine. ## Disclosure - The audits, the socket sweep and the mutation ran in a throwaway **copy** of my clone with a scratch exporter and four scratch `cmd/` probes inside it — the internal-package rule makes an out-of-tree probe impossible. The mutation and its revert in that copy were applied with a scripted substitution; the review clone itself was never modified (`git status` clean throughout) and was only ever driven through `make` and `docker`. - The definition of done in https://git.eeqj.de/sneak/webhooker/issues/146 asks for a test that the line **count** does not grow linearly with a flood. It still grows one per request by design; the ruling on https://git.eeqj.de/sneak/webhooker/issues/146#issuecomment-62278 chose that, so the bound moved to line content. Same waiver as the previous three rounds, restated so it is not read as an oversight. - Commit authorship was excluded from this review by instruction. - `script/fmt-check` covers `gofmt` only; the repo carries no prettier config, so the README change was checked by eye against the surrounding style (all new lines `&lt;=` 72 columns).

clawbot merged commit 5888d14438 into next 2026-08-18 00:32:29 +02:00

clawbot deleted branch issue-146-bound-access-log-amplification 2026-08-18 00:32:29 +02:00

clawbot referenced this pull request 2026-08-18 00:32:55 +02:00

Assert the access-log encoded-byte charge against every Unicode code point #172

clawbot referenced this pull request 2026-08-18 02:10:26 +02:00

Bound every slog line against client-chosen text (closes #176) #180

Sign in to join this conversation.

Reviewers

No Reviewers

Labels

Clear labels

merge-ready

needs-checks

needs-rebase

needs-review

needs-rework

No Label needs-review

Milestone

No items

No Milestone

Projects

Clear projects

No project

Assignees

Clear assignees

clawbot sneak

No Assignees clawbot

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: sneak/webhooker#155