Rebased onto next at 563e834. The merge with #180 was a real three-way merge in README.md, internal/middleware/middleware.go, internal/logfield/ and internal/handlers/; see Rebase resolution below. Everything else is
unchanged from the reviewed f9d9a2c, and every number below was re-measured
against the merged tree.
The defect
Every gorm.Open passed a bare &gorm.Config{}, leaving logger.Default in
place: LogLevel: Warn, IgnoreRecordNotFoundError: false, writing through a log.New(os.Stdout, ...) captured at package init. logger.Trace logs whenever err != nil && LogLevel >= Error && (!errors.Is(err, ErrRecordNotFound) || !IgnoreRecordNotFoundError), and Warn (3) is >= Error (2), so every
record-not-found printed the fully interpolated SQL. On /webhook/{uuid} and
on the login form the interpolated parameter is client-chosen and unbounded.
Three call sites, not two. The issue named internal/database/database.go
and internal/database/webhook_db_manager.go. internal/delivery/target_database_archive.goopenMode has the same default
and is fixed here too.
The option taken, and why
The adapter.internal/gormlog implements gormlogger.Interface over the
service's *slog.Logger; all three gorm.Open calls install it.
IgnoreRecordNotFoundError: true alone was the cheapest fix and it does kill
the two named lines, but it leaves the other three properties of the defect
intact: any other driver error still prints interpolated SQL, still at no
level the operator set, still on stdout, still shaped by neither handler internal/logger installs, still outside any budget. The adapter fixes the
class rather than the two instances. logger.Silent was rejected because it
drops slow-query reporting.
The arms are ordered exactly as GORM's own Trace orders them:
A miss under the threshold is dropped rather than bounded, and unconditionally
rather than behind a flag, because no caller here wants the other behaviour: a
missing row is the expected outcome for an invented UUID or an unknown user, and
both handlers already record their own miss at DEBUG without the SQL. fc() —
which renders the interpolated statement — is called only on a branch that will
emit.
LogMode deliberately returns the logger unchanged. Level is the operator's,
expressed once through LOG_LEVEL and the slog.LevelVar in internal/logger.
Rebase resolution
git rebase produced four conflicts. Neither side was taken wholesale in any of
them.
internal/middleware/middleware.go — the substantive one
180's MaxAccessLogLineBytes doc comment carried a carve-out bullet declaring
GORM's default logger an unfixed defect "filed as #178". That bullet is deleted, not
softened: this PR is what removes the defect, so the bullet is false on arrival.
In its place the comment now states that the ceiling covers the GORM adapter,
with the same arithmetic this branch always carried (a GORM line spends at most
two logfield.MaxBytes budgets, the statement and the driver error, against a
smaller fixed portion than the access log's).
Everything else of 180's survives verbatim: the eight-site enumeration of capped slog calls, the login-throttle paragraph, and the two remaining not-covered
bullets (authenticated-operator input, the log delivery target). 180's two new logfield.Truncate call sites in this file — the auth middleware: unauthenticated request DEBUG line and the request body exceeds limit WARN
line — are intact and are pinned by mutations 4 and 5 below. The whole diff of
this file against next is comment-only; no code of 180's changed.
The panic carve-out this branch added stays, restated: the exact width is no
longer given as an invariant, since it moves with the goroutine number and the
source paths baked into the stack.
README.md
Same direction. 180's whole new block — the eight-row table, the DEBUG-is-not-a-bound
note, the login-throttle paragraph, the passage naming exactly three
whole-flood-asserted sites (request body exceeds limit, entrypoint not found, user not found) and the seven named fills, the logfield_test.go paragraph,
and the first two not-covered bullets — is kept as it landed. Removed or
replaced:
This branch's bullet claiming the MaxBodySize, CSRF, receiver rate-limit and
two-lookup-miss lines "still log the request path or the submitted username
untruncated": deleted. 180 capped all of them; the bullet would have been
false.
This branch's GORM paragraph: kept, rewritten to follow 180's block rather
than to stand alone, and it now says the two handler misses are themselves
bounded (they are, since 180).
This branch's fx / Go runtime, net/http and chi Recoverer bullets: kept.
The panic figure is restated as approximate, as above.
One sentence outside the conflict was corrected because the merge made it
ambiguous: accesslog_test.go is described as asserting against "the widest access log line the service can be made to write", since a later bullet now
names a wider line that is not an access log line.
internal/logfield/
logfield.go: took next's wholesale. The two copies are byte-identical in
body; only the package/const prose and the exported-vs-unexported truncation
marker differ, and nothing on this branch references that symbol. The file no
longer appears in this PR's diff at all.
logfield_test.go: took next's wholesale and added the two cases this
branch had that 180's does not — TestTruncate_SpendsEncodedBytesNotRawBytes
(the zero-headroom check: a value built from one rune must keep exactly MaxBytes/EncodedBytes(r) of them, which TestTruncate_SpendsNoMoreThanTheBudget's LessOrEqual cannot catch) and TestTruncate_NeverSplitsARune. This branch's own density sweep was dropped as
redundant: 180's chargeTestRunes already walks densely to U+0800 and by stride
to utf8.MaxRune under both handlers.
internal/handlers/gormlogbound_test.go
Not a git conflict but a compile-time one: 180's logbound_test.go added a postLogin helper to the same test package. This branch's duplicate is deleted
and its status assertion moved into a thin postUnknownLogin wrapper over
180's, which is behaviourally identical.
One comment in that file was corrected rather than carried: it justified running
the flood at INFO on the grounds that the handlers' own miss lines are
untruncated at DEBUG. Since 180 they are truncated, so the rationale is now
stated as what it actually is — INFO is the level an operator runs at and the
level the defect was visible at.
One tightening, from the round-2 review's recorded anomaly
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm asserted Contains "sql statement", a substring of "slow sql statement", so it could
not distinguish the arms by itself. The arm table gains a notWant, and the
routine arm now also asserts NotContains "slow sql statement". The test is not
restructured; neverSlow already made it sound.
One budget, one implementation
truncateLogField and encodedLogFieldBytes are gone from internal/middleware, replaced by internal/logfield. On this branch that was
a move; on the merged tree 180 had already made it, so this PR simply consumes
it from the second writer. MaxAccessLogLineBytes still lives in internal/middleware.
The stated ceiling
MaxAccessLogLineBytes (2,560) covers GORM's lines as well as the access log's
and 180's eight slog sites. A GORM line spends at most two logfield.MaxBytes
budgets against a fixed portion smaller than the access log's, and internal/gormlog/gormlog_test.go asserts every emitted line against the
constant directly, under both handlers, for each of seven fills.
The README names what the ceiling does not cover: an authenticated
operator's own input, the log delivery target, fx and the Go runtime on
standard error, and net/http's faults — which are not a separate writer,
arrive on stdout at INFO, and in the panic case exceed the ceiling.
Tests
internal/gormlog/gormlog_test.go — real SQLite behind the adapter. A miss on
an 8 KB client-chosen key writes nothing; a slow miss still reports slow; a
flood of 50 misses at 128 and at 8,192 bytes produces byte-identical log
volume; the error, slow and routine branches are each asserted against MaxAccessLogLineBytes, with the far-end marker of the input absent from
every line.
internal/handlers/gormlogbound_test.go — the end-to-end flood over the two
unauthenticated lookups plus the per-webhook database, capturing both writers.
internal/delivery/target_database_archive_gormlog_test.go — the archive
writer's open. It has to live there: archiveWriter is unexported.
internal/logfield/logfield_test.go — 180's suite plus the zero-headroom and
rune-splitting cases described above.
Fills, everywhere: x, quote, backslash, tab, newline, a bare C0 control
(U+0001), and an astral non-printable (U+1000C).
Mutation verification, re-run on the merged tree
Nothing is carried forward except where stated. Each mutation applied alone,
in a throwaway copy of this clone, run through script/test, then reverted. The
copy is deleted; this clone was never mutated (git status clean throughout).
The three call sites, each reverted to a bare &gorm.Config{}
independently:
Site
Result
Into GORM's default logger
Volume, small to big
internal/database/database.go
FAIL
700,328 bytes
29,766 → 673,427
internal/database/webhook_db_manager.go
FAIL
350,160 bytes
16,070 → 337,172
internal/delivery/target_database_archive.go
FAIL
8,449 bytes
n/a (own test)
The first also produces 60 per-line bound violations and both tail-marker
assertions, e.g.
big flood: log line exceeded its bound: [1.007ms] [rows:0]
SELECT * FROM `entrypoints` WHERE path = "xxxx…
small flood: the far end of a client-chosen value reached the log,
so nothing truncated it
180's two new login-throttle caps, to confirm the merge did not break them:
Behavioural mutations (logging ErrRecordNotFound instead of dropping it;
budgeting raw bytes instead of encoded) were not re-run this round. They are
carried forward from round 2, and stated as carried forward, not as re-measured.
Gate evidence
All figures below are from the final head 65148ab.
make check — exit 0. 15 packages, real durations, zero (cached). Lint in
Docker: 0 issues. Tree clean after make fmt. make bootstrap run first in
this fresh clone.
#15 [lint 7/9] RUN make fmt-check DONE 0.5s
#16 [lint 8/9] golangci-lint config verify DONE 0.2s
#17 [lint 9/9] golangci-lint run ./... DONE 55.9s -> 0 issues.
#25 [builder 9/11] RUN make test DONE 84.0s
#26 [builder 10/11] RUN make build DONE 46.5s
Zero (cached) package lines in the builder's test run; 15 packages with
real durations (internal/gormlog 1.621s, internal/handlers 21.940s, internal/delivery 5.390s, internal/logfield 1.306s, internal/middleware 3.675s, internal/database 3.017s). The eight CACHED
layers are all outside the stages under test: the two digest-pinned base-image
resolves (#7, #8) and the six final runtime-stage layers (#28–#33). All
linting ran in Docker; the host linter was not used.
CI green on 65148ab: check / check (push), success, 3m47s.
No containers started, docker ps -a empty, both tagged images removed with docker rmi. No prune of any kind.
TODO.md untouched. One commit, parent 563e834.
Disclosure
One cache-defeated docker build on this head failed before the one
reported above, and it is worth recording rather than dropping. internal/handlers hit go test's 30 s per-package budget with 180's TestFailedLogin_LogLineDoesNotTrackUsernameSize/{json,text}/astral still
running at 16 s each. Host load average was 46 on 48 cores at the time. It is
not this change: the delta from the previous head, on which the same gate
passed with internal/handlers at 16.953 s, is markdown line-wrapping in README.md and nothing else. A control run of the same cache-defeated builder
stage on plain next at 563e834 passed, and the re-run reported above
passed at 21.940 s.
That said, the headroom is genuinely thin and this change consumes some of
it.script/test runs -timeout 30s per package; internal/handlers now
measures 21.940 s in Docker on a loaded host, and this PR adds a non-parallel
flood test to that package. This is the same class as #186. Raising the budget or moving
the flood out of internal/handlers is worth a separate issue; it is not
filed here because it is a judgement call about the repo's test budget rather
than a defect in this unit.
The two behavioural mutations named above were not re-run this round and are
stated as carried forward.
The gomodguard deprecation warning (#98)
still appears in the lint stage output; excluded by instruction.
Closes https://git.eeqj.de/sneak/webhooker/issues/178.
Rebased onto `next` at `563e834`. The merge with
https://git.eeqj.de/sneak/webhooker/pulls/180 was a real three-way merge in
`README.md`, `internal/middleware/middleware.go`, `internal/logfield/` and
`internal/handlers/`; see **Rebase resolution** below. Everything else is
unchanged from the reviewed `f9d9a2c`, and every number below was re-measured
against the merged tree.
## The defect
Every `gorm.Open` passed a bare `&gorm.Config{}`, leaving `logger.Default` in
place: `LogLevel: Warn`, `IgnoreRecordNotFoundError: false`, writing through a
`log.New(os.Stdout, ...)` captured at package init. `logger.Trace` logs whenever
`err != nil && LogLevel >= Error && (!errors.Is(err, ErrRecordNotFound) ||
!IgnoreRecordNotFoundError)`, and `Warn` (3) is `>= Error` (2), so **every
record-not-found printed the fully interpolated SQL**. On `/webhook/{uuid}` and
on the login form the interpolated parameter is client-chosen and unbounded.
**Three call sites, not two.** The issue named `internal/database/database.go`
and `internal/database/webhook_db_manager.go`.
`internal/delivery/target_database_archive.go` `openMode` has the same default
and is fixed here too.
## The option taken, and why
**The adapter.** `internal/gormlog` implements `gormlogger.Interface` over the
service's `*slog.Logger`; all three `gorm.Open` calls install it.
`IgnoreRecordNotFoundError: true` alone was the cheapest fix and it does kill
the two named lines, but it leaves the other three properties of the defect
intact: any *other* driver error still prints interpolated SQL, still at no
level the operator set, still on stdout, still shaped by neither handler
`internal/logger` installs, still outside any budget. The adapter fixes the
class rather than the two instances. `logger.Silent` was rejected because it
drops slow-query reporting.
The arms are ordered exactly as GORM's own `Trace` orders them:
| Order | Outcome | Level | Emitted |
| --- | --- | --- | --- |
| 1 | Error other than `ErrRecordNotFound` | `ERROR` | `sql statement failed`: statement, driver error, rows, elapsed. |
| 2 | Elapsed >= 200 ms, **including a miss** | `WARN` | `slow sql statement`: statement, rows, elapsed, threshold. |
| 3 | `ErrRecordNotFound` under the threshold | — | Nothing. |
| 4 | Otherwise | `DEBUG` | `sql statement`: statement, rows, elapsed. |
A miss under the threshold is dropped rather than bounded, and unconditionally
rather than behind a flag, because no caller here wants the other behaviour: a
missing row is the expected outcome for an invented UUID or an unknown user, and
both handlers already record their own miss at `DEBUG` without the SQL. `fc()` —
which renders the interpolated statement — is called only on a branch that will
emit.
`LogMode` deliberately returns the logger unchanged. Level is the operator's,
expressed once through `LOG_LEVEL` and the `slog.LevelVar` in `internal/logger`.
## Rebase resolution
`git rebase` produced four conflicts. Neither side was taken wholesale in any of
them.
### `internal/middleware/middleware.go` — the substantive one
180's `MaxAccessLogLineBytes` doc comment carried a carve-out bullet declaring
GORM's default logger an unfixed defect "filed as
https://git.eeqj.de/sneak/webhooker/issues/178". That bullet is **deleted**, not
softened: this PR is what removes the defect, so the bullet is false on arrival.
In its place the comment now states that the ceiling covers the GORM adapter,
with the same arithmetic this branch always carried (a GORM line spends at most
two `logfield.MaxBytes` budgets, the statement and the driver error, against a
smaller fixed portion than the access log's).
Everything else of 180's survives verbatim: the eight-site enumeration of capped
`slog` calls, the login-throttle paragraph, and the two remaining not-covered
bullets (authenticated-operator input, the `log` delivery target). 180's two new
`logfield.Truncate` call sites in this file — the `auth middleware:
unauthenticated request` DEBUG line and the `request body exceeds limit` WARN
line — are intact and are pinned by mutations 4 and 5 below. The whole diff of
this file against `next` is comment-only; no code of 180's changed.
The panic carve-out this branch added stays, restated: the exact width is no
longer given as an invariant, since it moves with the goroutine number and the
source paths baked into the stack.
### `README.md`
Same direction. 180's whole new block — the eight-row table, the `DEBUG`-is-not-a-bound
note, the login-throttle paragraph, the passage naming exactly three
whole-flood-asserted sites (`request body exceeds limit`, `entrypoint not found`,
`user not found`) and the seven named fills, the `logfield_test.go` paragraph,
and the first two not-covered bullets — is kept as it landed. Removed or
replaced:
- 180's **GORM's default logger** not-covered bullet: deleted.
- This branch's bullet claiming the `MaxBodySize`, CSRF, receiver rate-limit and
two-lookup-miss lines "still log the request path or the submitted username
untruncated": deleted. 180 capped all of them; the bullet would have been
false.
- This branch's GORM paragraph: kept, rewritten to follow 180's block rather
than to stand alone, and it now says the two handler misses are themselves
bounded (they are, since 180).
- This branch's `fx` / Go runtime, `net/http` and chi `Recoverer` bullets: kept.
The panic figure is restated as approximate, as above.
One sentence outside the conflict was corrected because the merge made it
ambiguous: `accesslog_test.go` is described as asserting against "the widest
**access log** line the service can be made to write", since a later bullet now
names a wider line that is not an access log line.
### `internal/logfield/`
`logfield.go`: **took `next`'s wholesale.** The two copies are byte-identical in
body; only the package/const prose and the exported-vs-unexported truncation
marker differ, and nothing on this branch references that symbol. The file no
longer appears in this PR's diff at all.
`logfield_test.go`: took `next`'s wholesale and **added** the two cases this
branch had that 180's does not — `TestTruncate_SpendsEncodedBytesNotRawBytes`
(the zero-headroom check: a value built from one rune must keep *exactly*
`MaxBytes/EncodedBytes(r)` of them, which
`TestTruncate_SpendsNoMoreThanTheBudget`'s `LessOrEqual` cannot catch) and
`TestTruncate_NeverSplitsARune`. This branch's own density sweep was dropped as
redundant: 180's `chargeTestRunes` already walks densely to U+0800 and by stride
to `utf8.MaxRune` under both handlers.
### `internal/handlers/gormlogbound_test.go`
Not a git conflict but a compile-time one: 180's `logbound_test.go` added a
`postLogin` helper to the same test package. This branch's duplicate is deleted
and its status assertion moved into a thin `postUnknownLogin` wrapper over
180's, which is behaviourally identical.
One comment in that file was corrected rather than carried: it justified running
the flood at `INFO` on the grounds that the handlers' own miss lines are
untruncated at `DEBUG`. Since 180 they are truncated, so the rationale is now
stated as what it actually is — `INFO` is the level an operator runs at and the
level the defect was visible at.
### One tightening, from the round-2 review's recorded anomaly
`TestSucceedingStatement_LineIsBoundedOnEitherArm`'s routine arm asserted
`Contains "sql statement"`, a substring of `"slow sql statement"`, so it could
not distinguish the arms by itself. The arm table gains a `notWant`, and the
routine arm now also asserts `NotContains "slow sql statement"`. The test is not
restructured; `neverSlow` already made it sound.
## One budget, one implementation
`truncateLogField` and `encodedLogFieldBytes` are gone from
`internal/middleware`, replaced by `internal/logfield`. On this branch that was
a move; on the merged tree 180 had already made it, so this PR simply consumes
it from the second writer. `MaxAccessLogLineBytes` still lives in
`internal/middleware`.
## The stated ceiling
`MaxAccessLogLineBytes` (2,560) covers GORM's lines as well as the access log's
and 180's eight `slog` sites. A GORM line spends at most two `logfield.MaxBytes`
budgets against a fixed portion smaller than the access log's, and
`internal/gormlog/gormlog_test.go` asserts every emitted line against the
constant directly, under both handlers, for each of seven fills.
The README names what the ceiling does **not** cover: an authenticated
operator's own input, the `log` delivery target, `fx` and the Go runtime on
standard error, and `net/http`'s faults — which are not a separate writer,
arrive on stdout at `INFO`, and in the panic case exceed the ceiling.
## Tests
- `internal/gormlog/gormlog_test.go` — real SQLite behind the adapter. A miss on
an 8 KB client-chosen key writes nothing; a slow miss still reports slow; a
flood of 50 misses at 128 and at 8,192 bytes produces byte-identical log
volume; the error, slow and routine branches are each asserted against
`MaxAccessLogLineBytes`, with the far-end marker of the input absent from
every line.
- `internal/handlers/gormlogbound_test.go` — the end-to-end flood over the two
unauthenticated lookups plus the per-webhook database, capturing both writers.
- `internal/delivery/target_database_archive_gormlog_test.go` — the archive
writer's open. It has to live there: `archiveWriter` is unexported.
- `internal/logfield/logfield_test.go` — 180's suite plus the zero-headroom and
rune-splitting cases described above.
Fills, everywhere: `x`, quote, backslash, tab, newline, a bare C0 control
(U+0001), and an astral non-printable (U+1000C).
## Mutation verification, re-run on the merged tree
Nothing is carried forward except where stated. Each mutation applied **alone**,
in a throwaway copy of this clone, run through `script/test`, then reverted. The
copy is deleted; this clone was never mutated (`git status` clean throughout).
**The three call sites**, each reverted to a bare `&gorm.Config{}`
independently:
| Site | Result | Into GORM's default logger | Volume, small to big |
| --- | --- | --- | --- |
| `internal/database/database.go` | FAIL | 700,328 bytes | 29,766 → 673,427 |
| `internal/database/webhook_db_manager.go` | FAIL | 350,160 bytes | 16,070 → 337,172 |
| `internal/delivery/target_database_archive.go` | FAIL | 8,449 bytes | n/a (own test) |
The first also produces 60 per-line bound violations and both tail-marker
assertions, e.g.
```
big flood: log line exceeded its bound: [1.007ms] [rows:0]
SELECT * FROM `entrypoints` WHERE path = "xxxx…
small flood: the far end of a client-chosen value reached the log,
so nothing truncated it
```
**180's two new login-throttle caps**, to confirm the merge did not break them:
| Cap reverted | Result |
| --- | --- |
| `login failure limit exceeded` (`internal/middleware/loginguard.go`) | FAIL — `TestLoginThrottle_LogLineDoesNotTrackPathSize`, 14 subtests |
| `password verification capacity exhausted` (`internal/handlers/auth.go`) | FAIL — `TestVerificationCapacity_LogLineDoesNotTrackPathSize`, 14 subtests |
**Behavioural mutations** (logging `ErrRecordNotFound` instead of dropping it;
budgeting raw bytes instead of encoded) were **not** re-run this round. They are
carried forward from round 2, and stated as carried forward, not as re-measured.
## Gate evidence
All figures below are from the final head `65148ab`.
`make check` — exit 0. 15 packages, real durations, **zero `(cached)`**. Lint in
Docker: `0 issues.` Tree clean after `make fmt`. `make bootstrap` run first in
this fresh clone.
`docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .`
— exit 0, checks demonstrably executing:
```
#15 [lint 7/9] RUN make fmt-check DONE 0.5s
#16 [lint 8/9] golangci-lint config verify DONE 0.2s
#17 [lint 9/9] golangci-lint run ./... DONE 55.9s -> 0 issues.
#25 [builder 9/11] RUN make test DONE 84.0s
#26 [builder 10/11] RUN make build DONE 46.5s
```
**Zero `(cached)` package lines** in the builder's test run; 15 packages with
real durations (`internal/gormlog 1.621s`, `internal/handlers 21.940s`,
`internal/delivery 5.390s`, `internal/logfield 1.306s`,
`internal/middleware 3.675s`, `internal/database 3.017s`). The eight `CACHED`
layers are all outside the stages under test: the two digest-pinned base-image
resolves (`#7`, `#8`) and the six final runtime-stage layers (`#28`–`#33`). All
linting ran in Docker; the host linter was not used.
CI green on `65148ab`: `check / check (push)`, success, 3m47s.
No containers started, `docker ps -a` empty, both tagged images removed with
`docker rmi`. No prune of any kind.
`TODO.md` untouched. One commit, parent `563e834`.
## Disclosure
- One cache-defeated `docker build` on this head **failed** before the one
reported above, and it is worth recording rather than dropping.
`internal/handlers` hit `go test`'s 30 s per-package budget with 180's
`TestFailedLogin_LogLineDoesNotTrackUsernameSize/{json,text}/astral` still
running at 16 s each. Host load average was 46 on 48 cores at the time. It is
not this change: the delta from the previous head, on which the same gate
passed with `internal/handlers` at 16.953 s, is markdown line-wrapping in
`README.md` and nothing else. A control run of the same cache-defeated builder
stage on plain `next` at `563e834` passed, and the re-run reported above
passed at 21.940 s.
- That said, **the headroom is genuinely thin and this change consumes some of
it.** `script/test` runs `-timeout 30s` per package; `internal/handlers` now
measures 21.940 s in Docker on a loaded host, and this PR adds a non-parallel
flood test to that package. This is the same class as
https://git.eeqj.de/sneak/webhooker/issues/186. Raising the budget or moving
the flood out of `internal/handlers` is worth a separate issue; it is not
filed here because it is a judgement call about the repo's test budget rather
than a defect in this unit.
- The two behavioural mutations named above were not re-run this round and are
stated as carried forward.
- The `gomodguard` deprecation warning (https://git.eeqj.de/sneak/webhooker/issues/98)
still appears in the lint stage output; excluded by instruction.
GORM's default logger printed the fully interpolated SQL to standard
output on every statement that returned an error, including a plain
record-not-found. On /webhook/{uuid} and on the login form the
interpolated parameter is client-chosen and unbounded, so an
unauthenticated client sized the operator's log, one line per request,
at no level the operator could turn down.
Every gorm.Open in the service now installs internal/gormlog, a
gormlogger.Interface over the service's *slog.Logger. Its lines take
the level the operator set and the handler internal/logger selected; a
record-not-found is not logged at all, since it is the expected
outcome on both of those paths and each handler already records its
own miss at DEBUG without the SQL; slow statements are kept at WARN
above the same 200ms threshold GORM used; and every value it emits is
spent through an encoded-byte budget.
That budget is internal/middleware's truncateLogField, moved to a new
internal/logfield package now that a second writer needs it. The move
is unchanged logic. MaxAccessLogLineBytes bounds a GORM line too, and
internal/gormlog asserts each line against the constant directly.
The third gorm.Open, in the archive writer, was not named in the issue
and had the same default.
README: the ceiling now covers GORM; the writers it does not cover are
named, including net/http's nil ErrorLog, fx's console logger and the
Go runtime, none of which carry a client-chosen value.
Reviewed at ce36f43 in a fresh clone. The adapter is the right call over IgnoreRecordNotFoundError: true, the third call site is real, there is no fourth, and I
could not exceed the ceiling through GORM. Three blocking findings, all measured.
1. Blocking — the slow-query report is silently lost on every record-not-found
internal/gormlog/gormlog.go:117-126. The case err != nil: return arm sits ahead of
the slow arm at :128, so a statement that is both slow and returns ErrRecordNotFound
emits nothing at all.
This is not the behaviour of the option the PR rejects. GORM's own Trace
(gorm.io/gorm@v1.25.5/logger/logger.go) orders the cases err && !RNF → elapsed > SlowThreshold → Info, so IgnoreRecordNotFoundError: true
falls through to the slow branch and still reports a slow miss. The adapter is
strictly less observant than the cheap fix on exactly the two lookups this issue is
about — and a miss is the case most likely to be slow, since it is the one that scans
without an index hit.
Measured, same statement shape, threshold forced to 1ns:
PROBE slow-on-hit bytes=411 {"level":"WARN","msg":"slow sql statement","sql":"SELECT * FROM `probe_things` WHERE id = \"a\" ...","rows":1,...}
PROBE slow-on-miss bytes=0 ""
Why it matters: the PR body says "Slow-query visibility is kept, not dropped", the
README says "Slow statements are kept", and the outcome table lists ErrRecordNotFound
→ "Nothing" without noting that the row silently wins over the slow row. The issue's
definition of done says slow-query visibility is "either kept or its loss is a stated
decision"; this is a partial loss, unstated, and contradicted in three places.
Acceptable: either put the slow arm ahead of the record-not-found drop (the statement is
already spent through logfield.Truncate, so the line stays bounded, and it costs one
bounded line only above 200 ms), or keep the drop and say plainly — in the doc comment,
the README and the table — that a slow statement which misses is not reported. Not both
as written.
2. Blocking — the README's writer enumeration is wrong on its first entry, and misses a fourth writer
README.md, third carve-out bullet: "Three writers that do not go through internal/logger at all, all of them on standard error."
(a) net/http's nil ErrorLog does go through internal/logger, and lands on
stdout.internal/logger/logger.go:80 calls slog.SetDefault, which calls log.SetOutput(&handlerWriter{l.Handler(), ...}) — the stdlib log package's default
logger is redirected into whichever handler internal/logger installed. http.Server.logf
falls back to log.Printf when ErrorLog is nil, so its faults are emitted as an
ordinary slog record at INFO, on stdout, shaped by the JSON or tty handler. Measured:
PROBE stdlib-log-capture="{\"time\":\"...\",\"level\":\"INFO\",\"msg\":\"http: superfluous response.WriteHeader call from x\"}"
Both halves of the sentence are false for that writer: it is not on standard error, and
it is not outside internal/logger.
(b) There is a fourth writer, and it is the one that actually handles a handler
panic.internal/server/routes.go:32 installs chi's middleware.Recoverer, which on
panic calls PrintPrettyStack → os.Stderr.Write for both the panic value and the stack
(go-chi/chi@v1.5.5/middleware/recoverer.go:43-51). The README attributes "a handler
panic and its stack" to net/http; with Recoverer in front of every route, net/http
never sees it. routes.go:46 already carries a comment about panics bubbling to the
Recoverer, and the review on #180 already named
chi's Recoverer as one of the three non-slog writers.
Why it matters: the DoD bullet this PR is answering is that a stated bound must be true
of the writers it names. This is the third round in this repo on a stated claim about log
output that does not survive being checked, and the enumeration is also the stated premise
of #183 — that issue currently names the wrong
three writers and needs re-triage once this is corrected (two of its three are wrong: the net/http one is not an independent writer at all, and chi's Recoverer is missing).
Acceptable: name fx's console logger, chi's Recoverer and the Go runtime as the
writers on standard error; say that net/http's nil ErrorLog is rerouted through internal/logger by slog.SetDefault (untruncated, but not client-sized); correct #183 to match.
3. Blocking — two of the three fixed call sites are pinned by nothing
Only internal/database/database.go is covered. I reverted both internal/database/webhook_db_manager.go:250 and internal/delivery/target_database_archive.go:285 to a bare &gorm.Config{} and ran script/test: exit 0, whole suite green, with internal/database (2.972s), internal/delivery (5.500s) and internal/handlers (11.688s) all genuinely re-run, not
cached.
TestUnauthenticatedFlood_NoWriterGrowsWithTheInput only drives the main database, so its gormlogger.Default-is-empty assertion never reaches the per-webhook manager or the
archive writer. Those are the two sites whose coverage the PR body argues for explicitly
("leaving it would have made the README's widened ceiling false for one writer") — and the
widened ceiling now rests on them being correct with nothing enforcing it.
Acceptable: extend the captureGORMDefault assertion over a run that also opens a
per-webhook database and an archive database, so reverting any one of the three fails.
4. Non-blocking — the flood test's two bounded assertions are vacuous as written
Measured inside TestUnauthenticatedFlood_NoWriterGrowsWithTheInput: small=810, big=812 bytes, and every captured byte is the fixed-string login failure limit exceeded WARN. newTestApp leaves the level at INFO, both handler
misses log at DEBUG, and the adapter drops the record-not-found — so no captured line
carries a client-chosen value at all. assertFloodBounded and the len(big) <= len(small)+64*requests comparison (812 against an allowance of 4,480) would
pass with the adapter deleted. The test's only teeth is the gormDefault empty assertion,
which is the one that fires. Worth saying, since the PR body offers the other two as
evidence.
5. Non-blocking — two stated counts are wrong
README: "the three panic calls in this service are invariant guards". There are five: internal/delivery/ssrf.go:64, internal/database/password.go:140, :145, :308, :316. All five are invariant guards, so the conclusion holds and the count does not.
PR body: "the only os.Stdout/os.Stderr references outside tests are the three in internal/logger". internal/logger/logger.go has four (:44, :71, :74, :107),
and internal/database/testing.go:18,30 adds two more in a non-_test.go file that
compiles into the binary (unreachable in production; no non-test caller).
6. Non-blocking — the stated merge resolution against #180 is not sufficient
The recommendation to "take its internal/logfield and its internal/middleware
wholesale" is right for internal/logfield but wrong for internal/middleware.
internal/logfield is not identical: 180 exports TruncationMarker; this branch has
it unexported as truncationMarker. Nothing here references it (the tests use the
literal "[truncated]"), so taking 180's copy wholesale does compile and behave
identically — the "same three-symbol API" wording is just inaccurate, 180's is four. EncodedBytes and Truncate are byte-identical in body.
internal/middleware cannot be taken wholesale. 180's MaxAccessLogLineBytes doc
comment carries a carve-out bullet declaring GORM's default logger an unfixed defect
"filed as #178", and lacks this branch's
statement that the ceiling covers GORM. Taking it verbatim ships a doc comment that is
false the moment this lands. That block needs a real three-way merge, as does the README
(the first carve-out bullet here, already disclosed, plus 180's own authenticated-operator
bullet, which this branch's README does not have).
Probes that passed — the load-bearing ones
No fourth gorm.Open. Three non-test sites, all fixed; no db.Session, gorm.Session{Logger:}
or .Debug() anywhere that could swap the logger back; logger.Default is consulted in
exactly one place in GORM (gorm.go:154, the nil-Logger fallback).
Could not exceed the ceiling through GORM. No slog.With attrs are attached to any
logger handed to gormlog.New, and no AddSource, so the fixed portion is ~170 bytes
JSON; the widest branch spends 2x(512+11). Widest real line I produced was 411 bytes
against 2,560. EncodedBytes is >= what either handler emits for every case I checked
by hand, including strconv.Quote's 4-byte \xNN for C0 (charged 6) and 10-byte \U
for astral non-printables.
The zero-headroom assertion is genuinely zero-headroom.MaxBytes/EncodedBytes(r)
with assert.Equal on the rune count admits no slack, and catches cost := utf8.RuneLen(r) for each of the 10 runes in the table where the two differ.
Note the doc comment says "for every rune" where it means the 13 in the table; the
density sweep in TestEncodedBytes_CoversWhatTheHandlersActuallyEmit is what covers the
rest, and it is >= only, not exact.
The 401/429 change is a correct fix, not a weakened test.authenticateUser
(internal/handlers/auth.go) performs the user lookup before rejectLogin decides
between 401 and 429, so the query this test exists to drive runs on both outcomes.
Mutation 1 reproduces. Bare &gorm.Config{} restored in database.go: TestUnauthenticatedFlood_NoWriterGrowsWithTheInput fails with GORM's default logger
holding 698,918 bytes (author reported 698,777) of interpolated entrypoints and users selects.
Record-not-found being dropped costs no caller a diagnostic: the error value still
propagates, and the archive site added here handles it at the call site.
Gate
make check — exit 0 after make bootstrap in a fresh clone. 15 packages, real
durations, zero (cached); lint in Docker, 0 issues. (48.3s). Tree clean afterwards,
so make fmt is clean.
docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain . —
exit 0. Lint executed: #15 make fmt-check 5.0s, #16 config verify 0.2s, #17 golangci-lint run56.2s → 0 issues. Builder executed: #25 make test 56.0s, #26 make build44.1s. Zero (cached) markers; the 8 CACHED
layers are the two digest-pinned base-image resolves and six final runtime-stage layers,
none in lint or builder. No containers started, docker ps -a empty, tagged image
removed, no prune of any kind.
CI green on ce36f43 (check / check (push), success, 2m54s). Mergeable against next;
branch parent is76725cf, current origin/next head — fast-forward.
Base next; exactly one commit; title ends (closes #178); TODO.md untouched;
naming and idiom consistent with no stutter; inclusive terminology clean; no
tooling-vendor reference or attribution trailer anywhere in the diff, commit message or
PR body.
Disclosure
The mutations and the three measurement probes ran in a throwaway copy of my clone,
driven through script/test; the review clone was never modified (git status clean
throughout) and the copy is deleted. Every gate result above came from make, script/
and docker only.
Mutations 2 and 3 were not re-run; I verified mutation 3's detector by reading the
assertion rather than by mutating, and mutation 2's claim follows from finding 1's probe
showing the branch is reached.
internal/gormlog/export_test.go writes slowThreshold after construction, which the
type's doc comment says never happens. Test-only, single-goroutine per subtest, not
raised as a finding.
Commit authorship and the gomodguard deprecation
(#98) were excluded by instruction; the gomodguard warning does appear in the lint stage output.
FAIL — needs-rework
Reviewed at `ce36f43` in a fresh clone. The adapter is the right call over
`IgnoreRecordNotFoundError: true`, the third call site is real, there is no fourth, and I
could not exceed the ceiling through GORM. Three blocking findings, all measured.
## 1. Blocking — the slow-query report is silently lost on every record-not-found
`internal/gormlog/gormlog.go:117-126`. The `case err != nil: return` arm sits **ahead of**
the slow arm at `:128`, so a statement that is both slow and returns `ErrRecordNotFound`
emits nothing at all.
This is not the behaviour of the option the PR rejects. GORM's own `Trace`
(`gorm.io/gorm@v1.25.5/logger/logger.go`) orders the cases
`err && !RNF` → `elapsed > SlowThreshold` → `Info`, so `IgnoreRecordNotFoundError: true`
falls **through** to the slow branch and still reports a slow miss. The adapter is
strictly less observant than the cheap fix on exactly the two lookups this issue is
about — and a miss is the case most likely to be slow, since it is the one that scans
without an index hit.
Measured, same statement shape, threshold forced to 1ns:
```
PROBE slow-on-hit bytes=411 {"level":"WARN","msg":"slow sql statement","sql":"SELECT * FROM `probe_things` WHERE id = \"a\" ...","rows":1,...}
PROBE slow-on-miss bytes=0 ""
```
Why it matters: the PR body says "**Slow-query visibility is kept**, not dropped", the
README says "Slow statements are kept", and the outcome table lists `ErrRecordNotFound`
→ "Nothing" without noting that the row silently wins over the slow row. The issue's
definition of done says slow-query visibility is "either kept or its loss is a stated
decision"; this is a partial loss, unstated, and contradicted in three places.
Acceptable: either put the slow arm ahead of the record-not-found drop (the statement is
already spent through `logfield.Truncate`, so the line stays bounded, and it costs one
bounded line only above 200 ms), or keep the drop and say plainly — in the doc comment,
the README and the table — that a slow statement which misses is not reported. Not both
as written.
## 2. Blocking — the README's writer enumeration is wrong on its first entry, and misses a fourth writer
`README.md`, third carve-out bullet: "Three writers that do not go through
`internal/logger` at all, all of them on standard error."
**(a) `net/http`'s nil `ErrorLog` does go through `internal/logger`, and lands on
stdout.** `internal/logger/logger.go:80` calls `slog.SetDefault`, which calls
`log.SetOutput(&handlerWriter{l.Handler(), ...})` — the stdlib `log` package's default
logger is redirected into whichever handler `internal/logger` installed. `http.Server.logf`
falls back to `log.Printf` when `ErrorLog` is nil, so its faults are emitted as an
ordinary slog record at INFO, on **stdout**, shaped by the JSON or tty handler. Measured:
```
PROBE stdlib-log-capture="{\"time\":\"...\",\"level\":\"INFO\",\"msg\":\"http: superfluous response.WriteHeader call from x\"}"
```
Both halves of the sentence are false for that writer: it is not on standard error, and
it is not outside `internal/logger`.
**(b) There is a fourth writer, and it is the one that actually handles a handler
panic.** `internal/server/routes.go:32` installs chi's `middleware.Recoverer`, which on
panic calls `PrintPrettyStack` → `os.Stderr.Write` for both the panic value and the stack
(`go-chi/chi@v1.5.5/middleware/recoverer.go:43-51`). The README attributes "a handler
panic and its stack" to `net/http`; with `Recoverer` in front of every route, `net/http`
never sees it. `routes.go:46` already carries a comment about panics bubbling to the
Recoverer, and the review on https://git.eeqj.de/sneak/webhooker/pulls/180 already named
chi's `Recoverer` as one of the three non-slog writers.
Why it matters: the DoD bullet this PR is answering is that a stated bound must be true
of the writers it names. This is the third round in this repo on a stated claim about log
output that does not survive being checked, and the enumeration is also the stated premise
of https://git.eeqj.de/sneak/webhooker/issues/183 — that issue currently names the wrong
three writers and needs re-triage once this is corrected (two of its three are wrong: the
`net/http` one is not an independent writer at all, and chi's `Recoverer` is missing).
Acceptable: name `fx`'s console logger, chi's `Recoverer` and the Go runtime as the
writers on standard error; say that `net/http`'s nil `ErrorLog` is rerouted through
`internal/logger` by `slog.SetDefault` (untruncated, but not client-sized); correct
https://git.eeqj.de/sneak/webhooker/issues/183 to match.
## 3. Blocking — two of the three fixed call sites are pinned by nothing
Only `internal/database/database.go` is covered. I reverted **both**
`internal/database/webhook_db_manager.go:250` and
`internal/delivery/target_database_archive.go:285` to a bare `&gorm.Config{}` and ran
`script/test`: **exit 0, whole suite green**, with `internal/database` (2.972s),
`internal/delivery` (5.500s) and `internal/handlers` (11.688s) all genuinely re-run, not
cached.
`TestUnauthenticatedFlood_NoWriterGrowsWithTheInput` only drives the main database, so its
`gormlogger.Default`-is-empty assertion never reaches the per-webhook manager or the
archive writer. Those are the two sites whose coverage the PR body argues for explicitly
("leaving it would have made the README's widened ceiling false for one writer") — and the
widened ceiling now rests on them being correct with nothing enforcing it.
Acceptable: extend the `captureGORMDefault` assertion over a run that also opens a
per-webhook database and an archive database, so reverting any one of the three fails.
## 4. Non-blocking — the flood test's two bounded assertions are vacuous as written
Measured inside `TestUnauthenticatedFlood_NoWriterGrowsWithTheInput`: `small=810`,
`big=812` bytes, and every captured byte is the fixed-string
`login failure limit exceeded` WARN. `newTestApp` leaves the level at INFO, both handler
misses log at DEBUG, and the adapter drops the record-not-found — so no captured line
carries a client-chosen value at all. `assertFloodBounded` and the
`len(big) <= len(small)+64*requests` comparison (812 against an allowance of 4,480) would
pass with the adapter deleted. The test's only teeth is the `gormDefault` empty assertion,
which is the one that fires. Worth saying, since the PR body offers the other two as
evidence.
## 5. Non-blocking — two stated counts are wrong
- README: "the three `panic` calls in this service are invariant guards". There are five:
`internal/delivery/ssrf.go:64`, `internal/database/password.go:140`, `:145`, `:308`,
`:316`. All five are invariant guards, so the conclusion holds and the count does not.
- PR body: "the only `os.Stdout`/`os.Stderr` references outside tests are the three in
`internal/logger`". `internal/logger/logger.go` has four (`:44`, `:71`, `:74`, `:107`),
and `internal/database/testing.go:18,30` adds two more in a non-`_test.go` file that
compiles into the binary (unreachable in production; no non-test caller).
## 6. Non-blocking — the stated merge resolution against https://git.eeqj.de/sneak/webhooker/pulls/180 is not sufficient
The recommendation to "take its `internal/logfield` and its `internal/middleware`
wholesale" is right for `internal/logfield` but wrong for `internal/middleware`.
- `internal/logfield` is **not** identical: 180 exports `TruncationMarker`; this branch has
it unexported as `truncationMarker`. Nothing here references it (the tests use the
literal `"[truncated]"`), so taking 180's copy wholesale does compile and behave
identically — the "same three-symbol API" wording is just inaccurate, 180's is four.
`EncodedBytes` and `Truncate` are byte-identical in body.
- `internal/middleware` cannot be taken wholesale. 180's `MaxAccessLogLineBytes` doc
comment carries a carve-out bullet declaring GORM's default logger an unfixed defect
"filed as https://git.eeqj.de/sneak/webhooker/issues/178", and lacks this branch's
statement that the ceiling covers GORM. Taking it verbatim ships a doc comment that is
false the moment this lands. That block needs a real three-way merge, as does the README
(the first carve-out bullet here, already disclosed, plus 180's own authenticated-operator
bullet, which this branch's README does not have).
## Probes that passed — the load-bearing ones
- **No fourth `gorm.Open`.** Three non-test sites, all fixed; no `db.Session`, `gorm.Session{Logger:}`
or `.Debug()` anywhere that could swap the logger back; `logger.Default` is consulted in
exactly one place in GORM (`gorm.go:154`, the nil-Logger fallback).
- **Could not exceed the ceiling through GORM.** No `slog.With` attrs are attached to any
logger handed to `gormlog.New`, and no `AddSource`, so the fixed portion is ~170 bytes
JSON; the widest branch spends 2x(512+11). Widest real line I produced was 411 bytes
against 2,560. `EncodedBytes` is `>=` what either handler emits for every case I checked
by hand, including `strconv.Quote`'s 4-byte `\xNN` for C0 (charged 6) and 10-byte `\U`
for astral non-printables.
- **The zero-headroom assertion is genuinely zero-headroom.** `MaxBytes/EncodedBytes(r)`
with `assert.Equal` on the rune count admits no slack, and catches
`cost := utf8.RuneLen(r)` for each of the 10 runes in the table where the two differ.
Note the doc comment says "for every rune" where it means the 13 in the table; the
density sweep in `TestEncodedBytes_CoversWhatTheHandlersActuallyEmit` is what covers the
rest, and it is `>=` only, not exact.
- **The 401/429 change is a correct fix, not a weakened test.** `authenticateUser`
(`internal/handlers/auth.go`) performs the user lookup before `rejectLogin` decides
between 401 and 429, so the query this test exists to drive runs on both outcomes.
- **Mutation 1 reproduces.** Bare `&gorm.Config{}` restored in `database.go`:
`TestUnauthenticatedFlood_NoWriterGrowsWithTheInput` fails with GORM's default logger
holding **698,918 bytes** (author reported 698,777) of interpolated `entrypoints` and
`users` selects.
- Record-not-found being dropped costs no caller a diagnostic: the error value still
propagates, and the archive site added here handles it at the call site.
## Gate
- `make check` — exit 0 after `make bootstrap` in a fresh clone. 15 packages, real
durations, zero `(cached)`; lint in Docker, `0 issues.` (48.3s). Tree clean afterwards,
so `make fmt` is clean.
- `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .` —
exit 0. Lint executed: `#15 make fmt-check` 5.0s, `#16 config verify` 0.2s,
`#17 golangci-lint run` **56.2s** → `0 issues.` Builder executed: `#25 make test`
**56.0s**, `#26 make build` **44.1s**. **Zero `(cached)` markers**; the 8 `CACHED`
layers are the two digest-pinned base-image resolves and six final runtime-stage layers,
none in `lint` or `builder`. No containers started, `docker ps -a` empty, tagged image
removed, no prune of any kind.
- CI green on `ce36f43` (`check / check (push)`, success, 2m54s). Mergeable against `next`;
branch parent **is** `76725cf`, current `origin/next` head — fast-forward.
- Base `next`; exactly one commit; title ends ` (closes #178)`; `TODO.md` untouched;
naming and idiom consistent with no stutter; inclusive terminology clean; no
tooling-vendor reference or attribution trailer anywhere in the diff, commit message or
PR body.
## Disclosure
- The mutations and the three measurement probes ran in a throwaway **copy** of my clone,
driven through `script/test`; the review clone was never modified (`git status` clean
throughout) and the copy is deleted. Every gate result above came from `make`, `script/`
and `docker` only.
- Mutations 2 and 3 were not re-run; I verified mutation 3's detector by reading the
assertion rather than by mutating, and mutation 2's claim follows from finding 1's probe
showing the branch is reached.
- `internal/gormlog/export_test.go` writes `slowThreshold` after construction, which the
type's doc comment says never happens. Test-only, single-goroutine per subtest, not
raised as a finding.
- Commit authorship and the `gomodguard` deprecation
(https://git.eeqj.de/sneak/webhooker/issues/98) were excluded by instruction; the
`gomodguard` warning does appear in the lint stage output.
Reviewed at f9d9a2c in a fresh clone. All three round-2 fixes hold under mutation, and the definition of done in #178 is met.
Mutation evidence
Arm order. Matches GORM v1.25.5 logger.Trace. Restoring round 1's case err != nil: return ahead of the slow arm fails TestSlowRecordNotFound_IsStillReportedSlow in 14 subtests ("a slow statement that missed was not reported as slow"). neverSlow/alwaysSlow set at construction cannot flake either way.
All three call-site reverts re-run, each alone, each FAILS.internal/database/database.go — 60 per-line violations plus both tail-marker assertions, exactly as reported. internal/database/webhook_db_manager.go — 349,600 bytes into GORM's default logger; this is the site the previous round measured passing. internal/delivery/target_database_archive.go — 8,441 bytes. The tee is what makes the per-line and volume assertions bite; they are no longer vacuous.
Writer enumeration, 2 of 4 re-measured independently at fd level.net/http nil ErrorLog: 209 bytes stdout, 0 stderr, one JSON record at INFO through internal/logger. chi Recoverer: 0 bytes stderr, client gets EOF, net/http reports its own slice bounds out of range [-1:] on stdout at INFO at 2,764 bytes. fx (501) and the Go runtime (359) were not re-measured. Five panic calls and six non-test os.Stdout/os.Stderr refs confirmed.
2,772-byte carve-out stated accurately on MaxAccessLogLineBytes and in the README, both citing #187. dupl merge loses no coverage: the merged table drives both arms over the same query, both handlers, all seven fills. The duplicated detector in internal/delivery is justified — archiveWriter is unexported and sharing across test-package boundaries would need a production symbol.
Anomalies, not blocking
The 2,772 figure is not reproducible byte-for-byte: it moves with the goroutine number and the source paths baked into the stack. I measured 2,764 for the same record. The claim it supports — a panic record exceeds the 2,560 ceiling — reproduces exactly. If the number is ever quoted back at the doc comment, treat it as approximate.
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm asserts Contains "sql statement", which is a substring of "slow sql statement", so that assertion cannot distinguish the two arms by itself. neverSlow makes the slow arm unreachable, so the case is sound as written — but it reads stronger than it is.
Merge order
The conflict with #180 is real, confirmed at its head aace4d7: 180's MaxAccessLogLineBytes doc comment declares GORM's default logger an unfixed defect "filed as #178". git merge-tree between the two heads yields 11 conflict markers, in README.md and internal/middleware/middleware.go. Whichever lands second needs a three-way merge, not a wholesale take.
Gate
make check exit 0 after make bootstrap in a fresh clone: 15 packages, real durations, zero (cached); lint in Docker 0 issues. (47.2s); tree clean afterwards.
docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain . exit 0. Lint executed: make fmt-check 5.1s, config verify 5.6s, golangci-lint run 56.0s to 0 issues. Builder executed: make test 59.4s (15 packages, zero (cached)), make build 43.1s. The six CACHED layers are all in the final runtime stage. No containers started, docker ps -a empty, tagged image removed, no prune of any kind.
CI green on f9d9a2c: check / check (push) success, 2m50s.
Base next; parent is b573959, current origin/next head, so fast-forward. Exactly one commit; title ends (closes #178); TODO.md untouched; no scope creep; inclusive terminology clean; no tooling-vendor reference or attribution trailer anywhere in the diff, commit message or PR body.
Disclosure
Every mutation and probe ran in a throwaway copy of my clone, driven through script/test; the review clone was never modified (git status clean throughout) and the copy is deleted. Two of the four writer measurements were reproduced independently, as noted above; the fx and Go-runtime figures are taken on the author's word. Commit authorship, gomodguard (#98) and the Recoverer defect itself (#187) were excluded by instruction; the gomodguard deprecation warning does appear in the lint stage output.
PASS
Reviewed at `f9d9a2c` in a fresh clone. All three round-2 fixes hold under mutation, and the definition of done in https://git.eeqj.de/sneak/webhooker/issues/178 is met.
## Mutation evidence
- **Arm order.** Matches GORM v1.25.5 `logger.Trace`. Restoring round 1's `case err != nil: return` ahead of the slow arm fails `TestSlowRecordNotFound_IsStillReportedSlow` in 14 subtests ("a slow statement that missed was not reported as slow"). `neverSlow`/`alwaysSlow` set at construction cannot flake either way.
- **All three call-site reverts re-run, each alone, each FAILS.** `internal/database/database.go` — 60 per-line violations plus both tail-marker assertions, exactly as reported. `internal/database/webhook_db_manager.go` — 349,600 bytes into GORM's default logger; this is the site the previous round measured passing. `internal/delivery/target_database_archive.go` — 8,441 bytes. The tee is what makes the per-line and volume assertions bite; they are no longer vacuous.
- **Writer enumeration, 2 of 4 re-measured independently at fd level.** `net/http` nil `ErrorLog`: 209 bytes stdout, 0 stderr, one JSON record at `INFO` through `internal/logger`. chi `Recoverer`: 0 bytes stderr, client gets EOF, `net/http` reports its own `slice bounds out of range [-1:]` on stdout at `INFO` at 2,764 bytes. `fx` (501) and the Go runtime (359) were not re-measured. Five `panic` calls and six non-test `os.Stdout`/`os.Stderr` refs confirmed.
- 2,772-byte carve-out stated accurately on `MaxAccessLogLineBytes` and in the README, both citing https://git.eeqj.de/sneak/webhooker/issues/187. `dupl` merge loses no coverage: the merged table drives both arms over the same query, both handlers, all seven fills. The duplicated detector in `internal/delivery` is justified — `archiveWriter` is unexported and sharing across test-package boundaries would need a production symbol.
## Anomalies, not blocking
- The **2,772** figure is not reproducible byte-for-byte: it moves with the goroutine number and the source paths baked into the stack. I measured **2,764** for the same record. The claim it supports — a panic record exceeds the 2,560 ceiling — reproduces exactly. If the number is ever quoted back at the doc comment, treat it as approximate.
- `TestSucceedingStatement_LineIsBoundedOnEitherArm`'s routine arm asserts `Contains "sql statement"`, which is a substring of `"slow sql statement"`, so that assertion cannot distinguish the two arms by itself. `neverSlow` makes the slow arm unreachable, so the case is sound as written — but it reads stronger than it is.
## Merge order
The conflict with https://git.eeqj.de/sneak/webhooker/pulls/180 is real, confirmed at its head `aace4d7`: 180's `MaxAccessLogLineBytes` doc comment declares GORM's default logger an unfixed defect "filed as https://git.eeqj.de/sneak/webhooker/issues/178". `git merge-tree` between the two heads yields 11 conflict markers, in `README.md` and `internal/middleware/middleware.go`. Whichever lands second needs a three-way merge, not a wholesale take.
## Gate
- `make check` exit 0 after `make bootstrap` in a fresh clone: 15 packages, real durations, zero `(cached)`; lint in Docker `0 issues.` (47.2s); tree clean afterwards.
- `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .` exit 0. Lint executed: `make fmt-check` 5.1s, `config verify` 5.6s, `golangci-lint run` 56.0s to `0 issues.` Builder executed: `make test` 59.4s (15 packages, zero `(cached)`), `make build` 43.1s. The six `CACHED` layers are all in the final runtime stage. No containers started, `docker ps -a` empty, tagged image removed, no prune of any kind.
- CI green on `f9d9a2c`: `check / check (push)` success, 2m50s.
- Base `next`; parent is `b573959`, current `origin/next` head, so fast-forward. Exactly one commit; title ends ` (closes #178)`; `TODO.md` untouched; no scope creep; inclusive terminology clean; no tooling-vendor reference or attribution trailer anywhere in the diff, commit message or PR body.
## Disclosure
Every mutation and probe ran in a throwaway copy of my clone, driven through `script/test`; the review clone was never modified (`git status` clean throughout) and the copy is deleted. Two of the four writer measurements were reproduced independently, as noted above; the `fx` and Go-runtime figures are taken on the author's word. Commit authorship, `gomodguard` (https://git.eeqj.de/sneak/webhooker/issues/98) and the `Recoverer` defect itself (https://git.eeqj.de/sneak/webhooker/issues/187) were excluded by instruction; the `gomodguard` deprecation warning does appear in the lint stage output.
Review passed. Held on needs-rebase rather than merged, deliberately, and this is the only note I will add: it must land AFTER #180, and the rebase is a real three-way merge, not a take-theirs.
git merge-tree between the two heads yields 11 conflict markers across README.md and internal/middleware/middleware.go. The substantive one: 180's MaxAccessLogLineBytes doc comment carries a bullet declaring GORM's default logger an unfixed defect "filed as #178". Adopting 180's internal/middleware wholesale would ship a doc comment that is false the moment this PR lands. Both files need merging by hand, in the direction where the GORM ceiling statement is true and the open-defect bullet is gone.
Order is 180 first because it is the one with the CI problem (#186) and the larger README rewrite; resolving once, in that direction, is cheaper than the reverse.
Two anomalies the review raised and passed, recorded so they are not lost rather than actioned:
The 2,772-byte figure for the panic record is not reproducible byte-for-byte — it shifts with the goroutine number and the source paths in the stack, and the reviewer measured 2,764 building under a different prefix. The claim it carries holds exactly; the number will not survive being re-measured elsewhere. #187 removes that record entirely, so this resolves itself.
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm asserts Contains "sql statement", which is a substring of "slow sql statement", so it cannot distinguish the two arms on its own. neverSlow makes the slow arm unreachable, so it is sound — just weaker than it reads.
Review passed. Held on `needs-rebase` rather than merged, deliberately, and this is the only note I will add: it must land AFTER https://git.eeqj.de/sneak/webhooker/pulls/180, and the rebase is a real three-way merge, not a take-theirs.
`git merge-tree` between the two heads yields 11 conflict markers across `README.md` and `internal/middleware/middleware.go`. The substantive one: 180's `MaxAccessLogLineBytes` doc comment carries a bullet declaring GORM's default logger an unfixed defect "filed as #178". Adopting 180's `internal/middleware` wholesale would ship a doc comment that is false the moment this PR lands. Both files need merging by hand, in the direction where the GORM ceiling statement is true and the open-defect bullet is gone.
Order is 180 first because it is the one with the CI problem (https://git.eeqj.de/sneak/webhooker/issues/186) and the larger README rewrite; resolving once, in that direction, is cheaper than the reverse.
Two anomalies the review raised and passed, recorded so they are not lost rather than actioned:
- The **2,772**-byte figure for the panic record is not reproducible byte-for-byte — it shifts with the goroutine number and the source paths in the stack, and the reviewer measured 2,764 building under a different prefix. The claim it carries holds exactly; the number will not survive being re-measured elsewhere. https://git.eeqj.de/sneak/webhooker/issues/187 removes that record entirely, so this resolves itself.
- `TestSucceedingStatement_LineIsBoundedOnEitherArm`'s routine arm asserts `Contains "sql statement"`, which is a substring of `"slow sql statement"`, so it cannot distinguish the two arms on its own. `neverSlow` makes the slow arm unreachable, so it is sound — just weaker than it reads.
Rebased onto next at 563e834, now that #180 has landed. Head 65148ab,
mergeable, CI green (check / check (push), 3m47s). Label moved off needs-rebase. Body updated in full.
Four conflicts, none resolved by taking a side.
internal/middleware/middleware.go — 180's carve-out bullet declaring
GORM's default logger an unfixed defect "filed as #178" is deleted, replaced by
the statement that the ceiling covers the GORM adapter. All of 180's other
doc-comment material and both of its new logfield.Truncate call sites are
untouched; the file's whole diff against next is comment-only.
README.md — 180's block kept as it landed (table, DEBUG note,
login-throttle paragraph, three-site flood passage, logfield_test.go
paragraph, first two not-covered bullets). 180's GORM bullet deleted. This
branch's bullet claiming the MaxBodySize/CSRF/rate-limit/miss lines are
untruncated also deleted — 180 capped all of them, so it would have been
false. This branch's GORM paragraph and its fx/runtime, net/http and chi Recoverer bullets kept.
internal/logfield/ — took next's logfield.go wholesale (nothing here
referenced the marker symbol, so the exported/unexported drift is moot); the
file is out of this PR's diff entirely. Took next's test file and added back
the two cases 180's lacks: the zero-headroom budget assertion and the
rune-splitting case. This branch's density sweep dropped as redundant against
180's chargeTestRunes.
internal/handlers/ — 180 added a postLogin helper to the same test
package; this branch's duplicate is deleted in favour of a thin wrapper over
180's.
Two things corrected because the merge made them untrue rather than merely
stale: a comment justifying the flood test's INFO level on the grounds that
the handler miss lines are untruncated (they are truncated since 180), and one
README sentence about "the widest line the service can be made to write", now
scoped to the access log since a later bullet names a wider one.
Both recorded anomalies handled. The 2,772 figure is restated as approximate in
both the doc comment and the README, with only the fact that it exceeds the
ceiling stated as invariant. TestSucceedingStatement_LineIsBoundedOnEitherArm's
routine arm now also asserts NotContains "slow sql statement"; not
restructured.
Mutations re-run on the merged tree, each alone, in a throwaway copy since
deleted. All three gorm.Open reverts FAIL independently — database.go
700,328 bytes into GORM's default logger plus 60 per-line violations, webhook_db_manager.go 350,160, the archive writer 8,449. 180's two new
login-throttle caps also still FAIL when reverted, 14 subtests each, so the
merge did not weaken them.
One disclosure worth reading before the gate figures: an earlier cache-defeated docker build on this exact head failed on a 30 s per-package timeout in internal/handlers, under a host load average of 46. Not this change — the only
delta from the head that had just passed the same gate is markdown wrapping —
but the headroom is thin and this PR adds to that package. Detail in the body.
Rebased onto `next` at `563e834`, now that
https://git.eeqj.de/sneak/webhooker/pulls/180 has landed. Head `65148ab`,
mergeable, CI green (`check / check (push)`, 3m47s). Label moved off
`needs-rebase`. Body updated in full.
Four conflicts, none resolved by taking a side.
- **`internal/middleware/middleware.go`** — 180's carve-out bullet declaring
GORM's default logger an unfixed defect "filed as
https://git.eeqj.de/sneak/webhooker/issues/178" is **deleted**, replaced by
the statement that the ceiling covers the GORM adapter. All of 180's other
doc-comment material and both of its new `logfield.Truncate` call sites are
untouched; the file's whole diff against `next` is comment-only.
- **`README.md`** — 180's block kept as it landed (table, `DEBUG` note,
login-throttle paragraph, three-site flood passage, `logfield_test.go`
paragraph, first two not-covered bullets). 180's GORM bullet deleted. This
branch's bullet claiming the `MaxBodySize`/CSRF/rate-limit/miss lines are
untruncated **also deleted** — 180 capped all of them, so it would have been
false. This branch's GORM paragraph and its `fx`/runtime, `net/http` and chi
`Recoverer` bullets kept.
- **`internal/logfield/`** — took `next`'s `logfield.go` wholesale (nothing here
referenced the marker symbol, so the exported/unexported drift is moot); the
file is out of this PR's diff entirely. Took `next`'s test file and added back
the two cases 180's lacks: the zero-headroom budget assertion and the
rune-splitting case. This branch's density sweep dropped as redundant against
180's `chargeTestRunes`.
- **`internal/handlers/`** — 180 added a `postLogin` helper to the same test
package; this branch's duplicate is deleted in favour of a thin wrapper over
180's.
Two things corrected because the merge made them untrue rather than merely
stale: a comment justifying the flood test's `INFO` level on the grounds that
the handler miss lines are untruncated (they are truncated since 180), and one
README sentence about "the widest line the service can be made to write", now
scoped to the access log since a later bullet names a wider one.
Both recorded anomalies handled. The 2,772 figure is restated as approximate in
both the doc comment and the README, with only the fact that it exceeds the
ceiling stated as invariant. `TestSucceedingStatement_LineIsBoundedOnEitherArm`'s
routine arm now also asserts `NotContains "slow sql statement"`; not
restructured.
Mutations re-run on the merged tree, each alone, in a throwaway copy since
deleted. All three `gorm.Open` reverts FAIL independently — `database.go`
700,328 bytes into GORM's default logger plus 60 per-line violations,
`webhook_db_manager.go` 350,160, the archive writer 8,449. 180's two new
login-throttle caps also still FAIL when reverted, 14 subtests each, so the
merge did not weaken them.
One disclosure worth reading before the gate figures: an earlier cache-defeated
`docker build` on this exact head failed on a 30 s per-package timeout in
`internal/handlers`, under a host load average of 46. Not this change — the only
delta from the head that had just passed the same gate is markdown wrapping —
but the headroom is thin and this PR adds to that package. Detail in the body.
Reviewed the merge at 65148ab in a fresh clone (make bootstrap first). Base next at 563e834, parent is 563e834, fast-forward, one commit, title ends (closes #178), TODO.md untouched, CI green (check / check (push), success,
3m47s). No tooling-vendor reference or attribution trailer anywhere; inclusive
terminology clean.
Accounted for every removed line in git diff 563e834 65148ab — 21 in total,
and no others exist:
README.md 14: the 10-line GORM-is-an-unfixed-defect bullet, plus 4 lines of the
re-wrapped accesslog_test.go sentence.
internal/middleware/middleware.go 4: the same carve-out bullet in the doc comment.
3 code lines: the three &gorm.Config{} literals.
So 180's eight-row table, the DEBUG-is-not-a-bound note, the login-throttle
paragraph, the passage naming exactly three whole-flood-asserted sites
(request body exceeds limit, entrypoint not found, user not found), the seven
named fills, the logfield_test.go paragraph and the first two not-covered bullets
all survive byte-identical. Both of 180's new tests present
(TestLoginThrottle_LogLineDoesNotTrackPathSize, TestVerificationCapacity_LogLineDoesNotTrackPathSize), and capturingHandlers is
the single variadic extra ...any form — no capturingHandlersWithDB remains.
internal/middleware/middleware.go is comment-only against next — confirmed
line by line: all 24 added and 4 removed lines sit inside the MaxAccessLogLineBytes
doc comment. No code of 180's changed.
Both deletions are right. The GORM bullet is false on arrival. The author's own
bullet claiming the MaxBodySize/CSRF/receiver-rate-limit/two-miss lines log
untruncated would also have been false: all five sites now go through logfield.Truncate (middleware.go:584, csrf.go:55, ratelimit.go:358, webhook.go:136, auth.go:157).
Mutations, re-run on the merged tree
Each alone, in a throwaway copy, through script/test, then reverted; the review
clone was never modified.
Mutation
Result
Mine
Author's
internal/database/database.go to bare &gorm.Config{}
The byte deltas are absolute-path length in the captured GORM lines, not a
discrepancy.
I also ran the two behavioural mutations the author carried forward rather than
re-measuring, since the merge touched both packages. Both FAIL on the merged tree: cost := utf8.RuneLen(r) in logfield.Truncate fails TestTruncate_SpendsNoMoreThanTheBudget (6 subtests) and the newly added TestTruncate_SpendsEncodedBytesNotRawBytes (9 subtests); disabling the ErrRecordNotFound exclusion in Trace fails TestRecordNotFound_WritesNothing and TestSlowRecordNotFound_IsStillReportedSlow (14 subtests each). Carrying them
forward was acceptable, and they are now measured.
internal/logfield trade, and the recorded anomalies
chargeTestRunes yields ~3,147 code points (dense 0 to U+07FF, 10 named points,
stride 1021 to utf8.MaxRune, surrogates skipped) under both handlers — it does
subsume the dropped density sweep, and it matches the "roughly 3,000 code points"
the README already claimed. No coverage lost by the trade.
Both anomalies handled: no 2,772 remains anywhere; README.md:1285 and middleware.go:140 both read "roughly 2,770", with only the fact that it exceeds the
ceiling stated as invariant. TestSucceedingStatement_LineIsBoundedOnEitherArm now
carries notWant and the routine arm asserts NotContains "slow sql statement".
postUnknownLogin preserves what its callers rely on: 180's postLogin (POST /pages/login, wrong password, unknown username) with the 401-or-429 assertion the
deleted duplicate carried, so the user lookup still runs on both outcomes.
internal/handlers timing — the disclosed margin, quantified
Cache-defeated builder stage, ambient host load 12–18 of 48 cores, three runs: 17.415 s, 17.948 s, 16.488 s against the 30 s per-package budget.
Sweep in --rm containers off the builder image
(go test -race -timeout 30s ./internal/handlers/, GOFLAGS=-count=1), head against
plain next. --cpus is unusable on this host (cgroup v2 threaded mode), so GOMAXPROCS stands in for effective cores:
Reading: the 30 s budget already reddens internal/handlers on plain next once
effective parallelism drops to 4. This PR moves that cliff from 4 to 5 and costs a
flat 4–5 s, which is exactly TestFlood_NoWriterGrowsWithTheInput itself (measured
5.06 s and 5.67 s in the mutation runs) — it is non-parallel, as disclosed. Margin at
full parallelism falls from ~18 s to ~13 s; the package now spends 57 % of its budget
where next spends 40 %.
The causation argument is correct: this change is not what makes the package
unsafe, and the failure mode reproduces on next alone one step further down. A
spurious red on next is not likely at ambient load — 12 s of headroom over three
measured runs — but becomes likely whenever effective parallelism falls below ~6
cores, which at load 46 of 48 is what the author hit. Not failed on this, per
instruction; the numbers are here for sizing the separate fix
(#186 is the same class).
Non-blocking
README.md:1148 is 29 characters mid-paragraph in a block otherwise wrapped at
65–71, an artifact of hand-rewrapping the accesslog_test.go sentence. No repo
tooling enforces markdown wrap (script/fmt and script/fmt-check are gofmt-only),
so make fmt is genuinely clean; cosmetic only.
Gate
make check — exit 0. 15 packages, real durations, zero (cached); internal/handlers 17.657s, internal/gormlog 1.463s. Lint in Docker: 0 issues.
(46.94 s). Tree clean after make fmt.
docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .
— exit 0. Lint executed (#17golangci-lint run 48.78 s to 0 issues.); builder
executed (#25make test, 15 packages, zero (cached), internal/handlers 17.415s). The 8 CACHED layers are the two digest-pinned base-image resolves
(#7 builder, #8 lint) and six stage-2 runtime layers — none in lint or builder.
Two further cache-defeated --target builder runs, exit 0 both.
No containers survive (docker ps -a empty), both tagged images removed with docker rmi, no prune of any kind.
Disclosure
I could not diff the merged tree against the pre-rebase head f9d9a2c: the object
is gone from the server (force-push) and absent from the shared checkout. The merge
was therefore verified by exhaustively accounting for every removal against 563e834 and by re-checking each surviving claim against the code, not by a
three-way diff of both parents. The chargeTestRunes-subsumes-the-dropped-sweep
claim was verified by property (span and handler coverage), not by reading the
dropped sweep.
The raw-byte-budget mutation was run as a package-scoped go test on the throwaway
copy rather than through script/test; every other mutation and every gate figure
came from make, script/ and docker only.
--cpus could not be applied on this host, so the contention sweep uses GOMAXPROCS as a proxy for effective cores rather than a real CPU cap.
gomodguard (#98), commit authorship and #189 excluded by instruction; the gomodguard deprecation warning does appear in the lint stage output.
PASS
Reviewed the **merge** at `65148ab` in a fresh clone (`make bootstrap` first). Base
`next` at `563e834`, parent is `563e834`, fast-forward, one commit, title ends
` (closes #178)`, `TODO.md` untouched, CI green (`check / check (push)`, success,
3m47s). No tooling-vendor reference or attribution trailer anywhere; inclusive
terminology clean.
## Nothing of https://git.eeqj.de/sneak/webhooker/pulls/180 was lost
Accounted for **every** removed line in `git diff 563e834 65148ab` — 21 in total,
and no others exist:
- `README.md` 14: the 10-line GORM-is-an-unfixed-defect bullet, plus 4 lines of the
re-wrapped `accesslog_test.go` sentence.
- `internal/middleware/middleware.go` 4: the same carve-out bullet in the doc comment.
- 3 code lines: the three `&gorm.Config{}` literals.
So 180's eight-row table, the `DEBUG`-is-not-a-bound note, the login-throttle
paragraph, the passage naming exactly three whole-flood-asserted sites
(`request body exceeds limit`, `entrypoint not found`, `user not found`), the seven
named fills, the `logfield_test.go` paragraph and the first two not-covered bullets
all survive byte-identical. Both of 180's new tests present
(`TestLoginThrottle_LogLineDoesNotTrackPathSize`,
`TestVerificationCapacity_LogLineDoesNotTrackPathSize`), and `capturingHandlers` is
the single variadic `extra ...any` form — no `capturingHandlersWithDB` remains.
**`internal/middleware/middleware.go` is comment-only against `next`** — confirmed
line by line: all 24 added and 4 removed lines sit inside the `MaxAccessLogLineBytes`
doc comment. No code of 180's changed.
Both deletions are right. The GORM bullet is false on arrival. The author's own
bullet claiming the `MaxBodySize`/CSRF/receiver-rate-limit/two-miss lines log
untruncated would also have been false: all five sites now go through
`logfield.Truncate` (`middleware.go:584`, `csrf.go:55`, `ratelimit.go:358`,
`webhook.go:136`, `auth.go:157`).
## Mutations, re-run on the merged tree
Each alone, in a throwaway copy, through `script/test`, then reverted; the review
clone was never modified.
| Mutation | Result | Mine | Author's |
| --- | --- | --- | --- |
| `internal/database/database.go` to bare `&gorm.Config{}` | FAIL `TestFlood_NoWriterGrowsWithTheInput` | 699,341 B | 700,328 B |
| `internal/database/webhook_db_manager.go` | FAIL, same test | 349,670 B | 350,160 B |
| `internal/delivery/target_database_archive.go` | FAIL `TestArchiveWriter_NeverUsesGORMsDefaultLogger` | 8,442 B | 8,449 B |
| 180's `login failure limit exceeded` cap reverted | FAIL `TestLoginThrottle_LogLineDoesNotTrackPathSize`, **14** subtests | — | 14 |
The byte deltas are absolute-path length in the captured GORM lines, not a
discrepancy.
I also ran the **two behavioural mutations the author carried forward rather than
re-measuring**, since the merge touched both packages. Both FAIL on the merged tree:
`cost := utf8.RuneLen(r)` in `logfield.Truncate` fails
`TestTruncate_SpendsNoMoreThanTheBudget` (6 subtests) **and** the newly added
`TestTruncate_SpendsEncodedBytesNotRawBytes` (9 subtests); disabling the
`ErrRecordNotFound` exclusion in `Trace` fails `TestRecordNotFound_WritesNothing` and
`TestSlowRecordNotFound_IsStillReportedSlow` (14 subtests each). Carrying them
forward was acceptable, and they are now measured.
## `internal/logfield` trade, and the recorded anomalies
`chargeTestRunes` yields ~3,147 code points (dense 0 to U+07FF, 10 named points,
stride 1021 to `utf8.MaxRune`, surrogates skipped) under both handlers — it does
subsume the dropped density sweep, and it matches the "roughly 3,000 code points"
the README already claimed. No coverage lost by the trade.
Both anomalies handled: no `2,772` remains anywhere; `README.md:1285` and
`middleware.go:140` both read "roughly 2,770", with only the fact that it exceeds the
ceiling stated as invariant. `TestSucceedingStatement_LineIsBoundedOnEitherArm` now
carries `notWant` and the routine arm asserts `NotContains "slow sql statement"`.
`postUnknownLogin` preserves what its callers rely on: 180's `postLogin` (POST
`/pages/login`, wrong password, unknown username) with the 401-or-429 assertion the
deleted duplicate carried, so the user lookup still runs on both outcomes.
## `internal/handlers` timing — the disclosed margin, quantified
Cache-defeated builder stage, ambient host load 12–18 of 48 cores, three runs:
**17.415 s, 17.948 s, 16.488 s** against the 30 s per-package budget.
Sweep in `--rm` containers off the builder image
(`go test -race -timeout 30s ./internal/handlers/`, `GOFLAGS=-count=1`), head against
plain `next`. `--cpus` is unusable on this host (cgroup v2 threaded mode), so
`GOMAXPROCS` stands in for effective cores:
| GOMAXPROCS | `next` 563e834 | head 65148ab | delta |
| --- | --- | --- | --- |
| 48 | 12.128 s | 17.207 s | +5.08 |
| 16 | 15.208 s | 19.315 s | +4.11 |
| 8 | 21.529 s | 25.837 s | +4.31 |
| 6 | 26.272 s | 30.956 s (pass, marginal) | +4.68 |
| 5 | 28.996 s (pass) | **TIMEOUT, FAIL** | — |
| 4 | **TIMEOUT, FAIL** | **TIMEOUT, FAIL** | — |
Reading: the 30 s budget already reddens `internal/handlers` on **plain `next`** once
effective parallelism drops to 4. This PR moves that cliff from 4 to 5 and costs a
flat 4–5 s, which is exactly `TestFlood_NoWriterGrowsWithTheInput` itself (measured
5.06 s and 5.67 s in the mutation runs) — it is non-parallel, as disclosed. Margin at
full parallelism falls from ~18 s to ~13 s; the package now spends 57 % of its budget
where `next` spends 40 %.
The causation argument is **correct**: this change is not what makes the package
unsafe, and the failure mode reproduces on `next` alone one step further down. A
spurious red on `next` is not likely at ambient load — 12 s of headroom over three
measured runs — but becomes likely whenever effective parallelism falls below ~6
cores, which at load 46 of 48 is what the author hit. Not failed on this, per
instruction; the numbers are here for sizing the separate fix
(https://git.eeqj.de/sneak/webhooker/issues/186 is the same class).
## Non-blocking
`README.md:1148` is 29 characters mid-paragraph in a block otherwise wrapped at
65–71, an artifact of hand-rewrapping the `accesslog_test.go` sentence. No repo
tooling enforces markdown wrap (`script/fmt` and `script/fmt-check` are gofmt-only),
so `make fmt` is genuinely clean; cosmetic only.
## Gate
- `make check` — exit 0. 15 packages, real durations, **zero `(cached)`**;
`internal/handlers 17.657s`, `internal/gormlog 1.463s`. Lint in Docker: `0 issues.`
(46.94 s). Tree clean after `make fmt`.
- `docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .`
— exit 0. Lint executed (`#17` `golangci-lint run` 48.78 s to `0 issues.`); builder
executed (`#25` `make test`, 15 packages, **zero `(cached)`**, `internal/handlers
17.415s`). The 8 `CACHED` layers are the two digest-pinned base-image resolves
(`#7` builder, `#8` lint) and six `stage-2` runtime layers — none in `lint` or
`builder`.
- Two further cache-defeated `--target builder` runs, exit 0 both.
- No containers survive (`docker ps -a` empty), both tagged images removed with
`docker rmi`, **no prune of any kind**.
## Disclosure
- I could not diff the merged tree against the pre-rebase head `f9d9a2c`: the object
is gone from the server (force-push) and absent from the shared checkout. The merge
was therefore verified by exhaustively accounting for every removal against
`563e834` and by re-checking each surviving claim against the code, not by a
three-way diff of both parents. The `chargeTestRunes`-subsumes-the-dropped-sweep
claim was verified by property (span and handler coverage), not by reading the
dropped sweep.
- The raw-byte-budget mutation was run as a package-scoped `go test` on the throwaway
copy rather than through `script/test`; every other mutation and every gate figure
came from `make`, `script/` and `docker` only.
- `--cpus` could not be applied on this host, so the contention sweep uses
`GOMAXPROCS` as a proxy for effective cores rather than a real CPU cap.
- `gomodguard` (https://git.eeqj.de/sneak/webhooker/issues/98), commit authorship and
https://git.eeqj.de/sneak/webhooker/pulls/189 excluded by instruction; the
`gomodguard` deprecation warning does appear in the lint stage output.
clawbot
merged commit 0c64c411cc into next2026-08-18 07:17:44 +02:00
Blocking a user prevents them from interacting with repositories, such as opening or commenting on pull requests or issues. Learn more about blocking a user.
Closes #178.
Rebased onto
nextat563e834. The merge with#180 was a real three-way merge in
README.md,internal/middleware/middleware.go,internal/logfield/andinternal/handlers/; see Rebase resolution below. Everything else isunchanged from the reviewed
f9d9a2c, and every number below was re-measuredagainst the merged tree.
The defect
Every
gorm.Openpassed a bare&gorm.Config{}, leavinglogger.Defaultinplace:
LogLevel: Warn,IgnoreRecordNotFoundError: false, writing through alog.New(os.Stdout, ...)captured at package init.logger.Tracelogs whenevererr != nil && LogLevel >= Error && (!errors.Is(err, ErrRecordNotFound) || !IgnoreRecordNotFoundError), andWarn(3) is>= Error(2), so everyrecord-not-found printed the fully interpolated SQL. On
/webhook/{uuid}andon the login form the interpolated parameter is client-chosen and unbounded.
Three call sites, not two. The issue named
internal/database/database.goand
internal/database/webhook_db_manager.go.internal/delivery/target_database_archive.goopenModehas the same defaultand is fixed here too.
The option taken, and why
The adapter.
internal/gormlogimplementsgormlogger.Interfaceover theservice's
*slog.Logger; all threegorm.Opencalls install it.IgnoreRecordNotFoundError: truealone was the cheapest fix and it does killthe two named lines, but it leaves the other three properties of the defect
intact: any other driver error still prints interpolated SQL, still at no
level the operator set, still on stdout, still shaped by neither handler
internal/loggerinstalls, still outside any budget. The adapter fixes theclass rather than the two instances.
logger.Silentwas rejected because itdrops slow-query reporting.
The arms are ordered exactly as GORM's own
Traceorders them:ErrRecordNotFoundERRORsql statement failed: statement, driver error, rows, elapsed.WARNslow sql statement: statement, rows, elapsed, threshold.ErrRecordNotFoundunder the thresholdDEBUGsql statement: statement, rows, elapsed.A miss under the threshold is dropped rather than bounded, and unconditionally
rather than behind a flag, because no caller here wants the other behaviour: a
missing row is the expected outcome for an invented UUID or an unknown user, and
both handlers already record their own miss at
DEBUGwithout the SQL.fc()—which renders the interpolated statement — is called only on a branch that will
emit.
LogModedeliberately returns the logger unchanged. Level is the operator's,expressed once through
LOG_LEVELand theslog.LevelVarininternal/logger.Rebase resolution
git rebaseproduced four conflicts. Neither side was taken wholesale in any ofthem.
internal/middleware/middleware.go— the substantive one180's
MaxAccessLogLineBytesdoc comment carried a carve-out bullet declaringGORM's default logger an unfixed defect "filed as
#178". That bullet is deleted, not
softened: this PR is what removes the defect, so the bullet is false on arrival.
In its place the comment now states that the ceiling covers the GORM adapter,
with the same arithmetic this branch always carried (a GORM line spends at most
two
logfield.MaxBytesbudgets, the statement and the driver error, against asmaller fixed portion than the access log's).
Everything else of 180's survives verbatim: the eight-site enumeration of capped
slogcalls, the login-throttle paragraph, and the two remaining not-coveredbullets (authenticated-operator input, the
logdelivery target). 180's two newlogfield.Truncatecall sites in this file — theauth middleware: unauthenticated requestDEBUG line and therequest body exceeds limitWARNline — are intact and are pinned by mutations 4 and 5 below. The whole diff of
this file against
nextis comment-only; no code of 180's changed.The panic carve-out this branch added stays, restated: the exact width is no
longer given as an invariant, since it moves with the goroutine number and the
source paths baked into the stack.
README.mdSame direction. 180's whole new block — the eight-row table, the
DEBUG-is-not-a-boundnote, the login-throttle paragraph, the passage naming exactly three
whole-flood-asserted sites (
request body exceeds limit,entrypoint not found,user not found) and the seven named fills, thelogfield_test.goparagraph,and the first two not-covered bullets — is kept as it landed. Removed or
replaced:
MaxBodySize, CSRF, receiver rate-limit andtwo-lookup-miss lines "still log the request path or the submitted username
untruncated": deleted. 180 capped all of them; the bullet would have been
false.
than to stand alone, and it now says the two handler misses are themselves
bounded (they are, since 180).
fx/ Go runtime,net/httpand chiRecovererbullets: kept.The panic figure is restated as approximate, as above.
One sentence outside the conflict was corrected because the merge made it
ambiguous:
accesslog_test.gois described as asserting against "the widestaccess log line the service can be made to write", since a later bullet now
names a wider line that is not an access log line.
internal/logfield/logfield.go: tooknext's wholesale. The two copies are byte-identical inbody; only the package/const prose and the exported-vs-unexported truncation
marker differ, and nothing on this branch references that symbol. The file no
longer appears in this PR's diff at all.
logfield_test.go: tooknext's wholesale and added the two cases thisbranch had that 180's does not —
TestTruncate_SpendsEncodedBytesNotRawBytes(the zero-headroom check: a value built from one rune must keep exactly
MaxBytes/EncodedBytes(r)of them, whichTestTruncate_SpendsNoMoreThanTheBudget'sLessOrEqualcannot catch) andTestTruncate_NeverSplitsARune. This branch's own density sweep was dropped asredundant: 180's
chargeTestRunesalready walks densely to U+0800 and by strideto
utf8.MaxRuneunder both handlers.internal/handlers/gormlogbound_test.goNot a git conflict but a compile-time one: 180's
logbound_test.goadded apostLoginhelper to the same test package. This branch's duplicate is deletedand its status assertion moved into a thin
postUnknownLoginwrapper over180's, which is behaviourally identical.
One comment in that file was corrected rather than carried: it justified running
the flood at
INFOon the grounds that the handlers' own miss lines areuntruncated at
DEBUG. Since 180 they are truncated, so the rationale is nowstated as what it actually is —
INFOis the level an operator runs at and thelevel the defect was visible at.
One tightening, from the round-2 review's recorded anomaly
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm assertedContains "sql statement", a substring of"slow sql statement", so it couldnot distinguish the arms by itself. The arm table gains a
notWant, and theroutine arm now also asserts
NotContains "slow sql statement". The test is notrestructured;
neverSlowalready made it sound.One budget, one implementation
truncateLogFieldandencodedLogFieldBytesare gone frominternal/middleware, replaced byinternal/logfield. On this branch that wasa move; on the merged tree 180 had already made it, so this PR simply consumes
it from the second writer.
MaxAccessLogLineBytesstill lives ininternal/middleware.The stated ceiling
MaxAccessLogLineBytes(2,560) covers GORM's lines as well as the access log'sand 180's eight
slogsites. A GORM line spends at most twologfield.MaxBytesbudgets against a fixed portion smaller than the access log's, and
internal/gormlog/gormlog_test.goasserts every emitted line against theconstant directly, under both handlers, for each of seven fills.
The README names what the ceiling does not cover: an authenticated
operator's own input, the
logdelivery target,fxand the Go runtime onstandard error, and
net/http's faults — which are not a separate writer,arrive on stdout at
INFO, and in the panic case exceed the ceiling.Tests
internal/gormlog/gormlog_test.go— real SQLite behind the adapter. A miss onan 8 KB client-chosen key writes nothing; a slow miss still reports slow; a
flood of 50 misses at 128 and at 8,192 bytes produces byte-identical log
volume; the error, slow and routine branches are each asserted against
MaxAccessLogLineBytes, with the far-end marker of the input absent fromevery line.
internal/handlers/gormlogbound_test.go— the end-to-end flood over the twounauthenticated lookups plus the per-webhook database, capturing both writers.
internal/delivery/target_database_archive_gormlog_test.go— the archivewriter's open. It has to live there:
archiveWriteris unexported.internal/logfield/logfield_test.go— 180's suite plus the zero-headroom andrune-splitting cases described above.
Fills, everywhere:
x, quote, backslash, tab, newline, a bare C0 control(U+0001), and an astral non-printable (U+1000C).
Mutation verification, re-run on the merged tree
Nothing is carried forward except where stated. Each mutation applied alone,
in a throwaway copy of this clone, run through
script/test, then reverted. Thecopy is deleted; this clone was never mutated (
git statusclean throughout).The three call sites, each reverted to a bare
&gorm.Config{}independently:
internal/database/database.gointernal/database/webhook_db_manager.gointernal/delivery/target_database_archive.goThe first also produces 60 per-line bound violations and both tail-marker
assertions, e.g.
180's two new login-throttle caps, to confirm the merge did not break them:
login failure limit exceeded(internal/middleware/loginguard.go)TestLoginThrottle_LogLineDoesNotTrackPathSize, 14 subtestspassword verification capacity exhausted(internal/handlers/auth.go)TestVerificationCapacity_LogLineDoesNotTrackPathSize, 14 subtestsBehavioural mutations (logging
ErrRecordNotFoundinstead of dropping it;budgeting raw bytes instead of encoded) were not re-run this round. They are
carried forward from round 2, and stated as carried forward, not as re-measured.
Gate evidence
All figures below are from the final head
65148ab.make check— exit 0. 15 packages, real durations, zero(cached). Lint inDocker:
0 issues.Tree clean aftermake fmt.make bootstraprun first inthis fresh clone.
docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .— exit 0, checks demonstrably executing:
Zero
(cached)package lines in the builder's test run; 15 packages withreal durations (
internal/gormlog 1.621s,internal/handlers 21.940s,internal/delivery 5.390s,internal/logfield 1.306s,internal/middleware 3.675s,internal/database 3.017s). The eightCACHEDlayers are all outside the stages under test: the two digest-pinned base-image
resolves (
#7,#8) and the six final runtime-stage layers (#28–#33). Alllinting ran in Docker; the host linter was not used.
CI green on
65148ab:check / check (push), success, 3m47s.No containers started,
docker ps -aempty, both tagged images removed withdocker rmi. No prune of any kind.TODO.mduntouched. One commit, parent563e834.Disclosure
docker buildon this head failed before the onereported above, and it is worth recording rather than dropping.
internal/handlershitgo test's 30 s per-package budget with 180'sTestFailedLogin_LogLineDoesNotTrackUsernameSize/{json,text}/astralstillrunning at 16 s each. Host load average was 46 on 48 cores at the time. It is
not this change: the delta from the previous head, on which the same gate
passed with
internal/handlersat 16.953 s, is markdown line-wrapping inREADME.mdand nothing else. A control run of the same cache-defeated builderstage on plain
nextat563e834passed, and the re-run reported abovepassed at 21.940 s.
it.
script/testruns-timeout 30sper package;internal/handlersnowmeasures 21.940 s in Docker on a loaded host, and this PR adds a non-parallel
flood test to that package. This is the same class as
#186. Raising the budget or moving
the flood out of
internal/handlersis worth a separate issue; it is notfiled here because it is a judgement call about the repo's test budget rather
than a defect in this unit.
stated as carried forward.
gomodguarddeprecation warning (#98)still appears in the lint stage output; excluded by instruction.
GORM's default logger printed the fully interpolated SQL to standard output on every statement that returned an error, including a plain record-not-found. On /webhook/{uuid} and on the login form the interpolated parameter is client-chosen and unbounded, so an unauthenticated client sized the operator's log, one line per request, at no level the operator could turn down. Every gorm.Open in the service now installs internal/gormlog, a gormlogger.Interface over the service's *slog.Logger. Its lines take the level the operator set and the handler internal/logger selected; a record-not-found is not logged at all, since it is the expected outcome on both of those paths and each handler already records its own miss at DEBUG without the SQL; slow statements are kept at WARN above the same 200ms threshold GORM used; and every value it emits is spent through an encoded-byte budget. That budget is internal/middleware's truncateLogField, moved to a new internal/logfield package now that a second writer needs it. The move is unchanged logic. MaxAccessLogLineBytes bounds a GORM line too, and internal/gormlog asserts each line against the constant directly. The third gorm.Open, in the archive writer, was not named in the issue and had the same default. README: the ceiling now covers GORM; the writers it does not cover are named, including net/http's nil ErrorLog, fx's console logger and the Go runtime, none of which carry a client-chosen value.FAIL — needs-rework
Reviewed at
ce36f43in a fresh clone. The adapter is the right call overIgnoreRecordNotFoundError: true, the third call site is real, there is no fourth, and Icould not exceed the ceiling through GORM. Three blocking findings, all measured.
1. Blocking — the slow-query report is silently lost on every record-not-found
internal/gormlog/gormlog.go:117-126. Thecase err != nil: returnarm sits ahead ofthe slow arm at
:128, so a statement that is both slow and returnsErrRecordNotFoundemits nothing at all.
This is not the behaviour of the option the PR rejects. GORM's own
Trace(
gorm.io/gorm@v1.25.5/logger/logger.go) orders the caseserr && !RNF→elapsed > SlowThreshold→Info, soIgnoreRecordNotFoundError: truefalls through to the slow branch and still reports a slow miss. The adapter is
strictly less observant than the cheap fix on exactly the two lookups this issue is
about — and a miss is the case most likely to be slow, since it is the one that scans
without an index hit.
Measured, same statement shape, threshold forced to 1ns:
Why it matters: the PR body says "Slow-query visibility is kept, not dropped", the
README says "Slow statements are kept", and the outcome table lists
ErrRecordNotFound→ "Nothing" without noting that the row silently wins over the slow row. The issue's
definition of done says slow-query visibility is "either kept or its loss is a stated
decision"; this is a partial loss, unstated, and contradicted in three places.
Acceptable: either put the slow arm ahead of the record-not-found drop (the statement is
already spent through
logfield.Truncate, so the line stays bounded, and it costs onebounded line only above 200 ms), or keep the drop and say plainly — in the doc comment,
the README and the table — that a slow statement which misses is not reported. Not both
as written.
2. Blocking — the README's writer enumeration is wrong on its first entry, and misses a fourth writer
README.md, third carve-out bullet: "Three writers that do not go throughinternal/loggerat all, all of them on standard error."(a)
net/http's nilErrorLogdoes go throughinternal/logger, and lands onstdout.
internal/logger/logger.go:80callsslog.SetDefault, which callslog.SetOutput(&handlerWriter{l.Handler(), ...})— the stdliblogpackage's defaultlogger is redirected into whichever handler
internal/loggerinstalled.http.Server.logffalls back to
log.PrintfwhenErrorLogis nil, so its faults are emitted as anordinary slog record at INFO, on stdout, shaped by the JSON or tty handler. Measured:
Both halves of the sentence are false for that writer: it is not on standard error, and
it is not outside
internal/logger.(b) There is a fourth writer, and it is the one that actually handles a handler
panic.
internal/server/routes.go:32installs chi'smiddleware.Recoverer, which onpanic calls
PrintPrettyStack→os.Stderr.Writefor both the panic value and the stack(
go-chi/chi@v1.5.5/middleware/recoverer.go:43-51). The README attributes "a handlerpanic and its stack" to
net/http; withRecovererin front of every route,net/httpnever sees it.
routes.go:46already carries a comment about panics bubbling to theRecoverer, and the review on #180 already named
chi's
Recovereras one of the three non-slog writers.Why it matters: the DoD bullet this PR is answering is that a stated bound must be true
of the writers it names. This is the third round in this repo on a stated claim about log
output that does not survive being checked, and the enumeration is also the stated premise
of #183 — that issue currently names the wrong
three writers and needs re-triage once this is corrected (two of its three are wrong: the
net/httpone is not an independent writer at all, and chi'sRecovereris missing).Acceptable: name
fx's console logger, chi'sRecovererand the Go runtime as thewriters on standard error; say that
net/http's nilErrorLogis rerouted throughinternal/loggerbyslog.SetDefault(untruncated, but not client-sized); correct#183 to match.
3. Blocking — two of the three fixed call sites are pinned by nothing
Only
internal/database/database.gois covered. I reverted bothinternal/database/webhook_db_manager.go:250andinternal/delivery/target_database_archive.go:285to a bare&gorm.Config{}and ranscript/test: exit 0, whole suite green, withinternal/database(2.972s),internal/delivery(5.500s) andinternal/handlers(11.688s) all genuinely re-run, notcached.
TestUnauthenticatedFlood_NoWriterGrowsWithTheInputonly drives the main database, so itsgormlogger.Default-is-empty assertion never reaches the per-webhook manager or thearchive writer. Those are the two sites whose coverage the PR body argues for explicitly
("leaving it would have made the README's widened ceiling false for one writer") — and the
widened ceiling now rests on them being correct with nothing enforcing it.
Acceptable: extend the
captureGORMDefaultassertion over a run that also opens aper-webhook database and an archive database, so reverting any one of the three fails.
4. Non-blocking — the flood test's two bounded assertions are vacuous as written
Measured inside
TestUnauthenticatedFlood_NoWriterGrowsWithTheInput:small=810,big=812bytes, and every captured byte is the fixed-stringlogin failure limit exceededWARN.newTestAppleaves the level at INFO, both handlermisses log at DEBUG, and the adapter drops the record-not-found — so no captured line
carries a client-chosen value at all.
assertFloodBoundedand thelen(big) <= len(small)+64*requestscomparison (812 against an allowance of 4,480) wouldpass with the adapter deleted. The test's only teeth is the
gormDefaultempty assertion,which is the one that fires. Worth saying, since the PR body offers the other two as
evidence.
5. Non-blocking — two stated counts are wrong
paniccalls in this service are invariant guards". There are five:internal/delivery/ssrf.go:64,internal/database/password.go:140,:145,:308,:316. All five are invariant guards, so the conclusion holds and the count does not.os.Stdout/os.Stderrreferences outside tests are the three ininternal/logger".internal/logger/logger.gohas four (:44,:71,:74,:107),and
internal/database/testing.go:18,30adds two more in a non-_test.gofile thatcompiles into the binary (unreachable in production; no non-test caller).
6. Non-blocking — the stated merge resolution against #180 is not sufficient
The recommendation to "take its
internal/logfieldand itsinternal/middlewarewholesale" is right for
internal/logfieldbut wrong forinternal/middleware.internal/logfieldis not identical: 180 exportsTruncationMarker; this branch hasit unexported as
truncationMarker. Nothing here references it (the tests use theliteral
"[truncated]"), so taking 180's copy wholesale does compile and behaveidentically — the "same three-symbol API" wording is just inaccurate, 180's is four.
EncodedBytesandTruncateare byte-identical in body.internal/middlewarecannot be taken wholesale. 180'sMaxAccessLogLineBytesdoccomment carries a carve-out bullet declaring GORM's default logger an unfixed defect
"filed as #178", and lacks this branch's
statement that the ceiling covers GORM. Taking it verbatim ships a doc comment that is
false the moment this lands. That block needs a real three-way merge, as does the README
(the first carve-out bullet here, already disclosed, plus 180's own authenticated-operator
bullet, which this branch's README does not have).
Probes that passed — the load-bearing ones
gorm.Open. Three non-test sites, all fixed; nodb.Session,gorm.Session{Logger:}or
.Debug()anywhere that could swap the logger back;logger.Defaultis consulted inexactly one place in GORM (
gorm.go:154, the nil-Logger fallback).slog.Withattrs are attached to anylogger handed to
gormlog.New, and noAddSource, so the fixed portion is ~170 bytesJSON; the widest branch spends 2x(512+11). Widest real line I produced was 411 bytes
against 2,560.
EncodedBytesis>=what either handler emits for every case I checkedby hand, including
strconv.Quote's 4-byte\xNNfor C0 (charged 6) and 10-byte\Ufor astral non-printables.
MaxBytes/EncodedBytes(r)with
assert.Equalon the rune count admits no slack, and catchescost := utf8.RuneLen(r)for each of the 10 runes in the table where the two differ.Note the doc comment says "for every rune" where it means the 13 in the table; the
density sweep in
TestEncodedBytes_CoversWhatTheHandlersActuallyEmitis what covers therest, and it is
>=only, not exact.authenticateUser(
internal/handlers/auth.go) performs the user lookup beforerejectLogindecidesbetween 401 and 429, so the query this test exists to drive runs on both outcomes.
&gorm.Config{}restored indatabase.go:TestUnauthenticatedFlood_NoWriterGrowsWithTheInputfails with GORM's default loggerholding 698,918 bytes (author reported 698,777) of interpolated
entrypointsandusersselects.propagates, and the archive site added here handles it at the call site.
Gate
make check— exit 0 aftermake bootstrapin a fresh clone. 15 packages, realdurations, zero
(cached); lint in Docker,0 issues.(48.3s). Tree clean afterwards,so
make fmtis clean.docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .—exit 0. Lint executed:
#15 make fmt-check5.0s,#16 config verify0.2s,#17 golangci-lint run56.2s →0 issues.Builder executed:#25 make test56.0s,
#26 make build44.1s. Zero(cached)markers; the 8CACHEDlayers are the two digest-pinned base-image resolves and six final runtime-stage layers,
none in
lintorbuilder. No containers started,docker ps -aempty, tagged imageremoved, no prune of any kind.
ce36f43(check / check (push), success, 2m54s). Mergeable againstnext;branch parent is
76725cf, currentorigin/nexthead — fast-forward.next; exactly one commit; title ends(closes #178);TODO.mduntouched;naming and idiom consistent with no stutter; inclusive terminology clean; no
tooling-vendor reference or attribution trailer anywhere in the diff, commit message or
PR body.
Disclosure
driven through
script/test; the review clone was never modified (git statuscleanthroughout) and the copy is deleted. Every gate result above came from
make,script/and
dockeronly.assertion rather than by mutating, and mutation 2's claim follows from finding 1's probe
showing the branch is reached.
internal/gormlog/export_test.gowritesslowThresholdafter construction, which thetype's doc comment says never happens. Test-only, single-goroutine per subtest, not
raised as a finding.
gomodguarddeprecation(#98) were excluded by instruction; the
gomodguardwarning does appear in the lint stage output.ce36f430fbtof9d9a2c8d7PASS
Reviewed at
f9d9a2cin a fresh clone. All three round-2 fixes hold under mutation, and the definition of done in #178 is met.Mutation evidence
logger.Trace. Restoring round 1'scase err != nil: returnahead of the slow arm failsTestSlowRecordNotFound_IsStillReportedSlowin 14 subtests ("a slow statement that missed was not reported as slow").neverSlow/alwaysSlowset at construction cannot flake either way.internal/database/database.go— 60 per-line violations plus both tail-marker assertions, exactly as reported.internal/database/webhook_db_manager.go— 349,600 bytes into GORM's default logger; this is the site the previous round measured passing.internal/delivery/target_database_archive.go— 8,441 bytes. The tee is what makes the per-line and volume assertions bite; they are no longer vacuous.net/httpnilErrorLog: 209 bytes stdout, 0 stderr, one JSON record atINFOthroughinternal/logger. chiRecoverer: 0 bytes stderr, client gets EOF,net/httpreports its ownslice bounds out of range [-1:]on stdout atINFOat 2,764 bytes.fx(501) and the Go runtime (359) were not re-measured. Fivepaniccalls and six non-testos.Stdout/os.Stderrrefs confirmed.MaxAccessLogLineBytesand in the README, both citing #187.duplmerge loses no coverage: the merged table drives both arms over the same query, both handlers, all seven fills. The duplicated detector ininternal/deliveryis justified —archiveWriteris unexported and sharing across test-package boundaries would need a production symbol.Anomalies, not blocking
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm assertsContains "sql statement", which is a substring of"slow sql statement", so that assertion cannot distinguish the two arms by itself.neverSlowmakes the slow arm unreachable, so the case is sound as written — but it reads stronger than it is.Merge order
The conflict with #180 is real, confirmed at its head
aace4d7: 180'sMaxAccessLogLineBytesdoc comment declares GORM's default logger an unfixed defect "filed as #178".git merge-treebetween the two heads yields 11 conflict markers, inREADME.mdandinternal/middleware/middleware.go. Whichever lands second needs a three-way merge, not a wholesale take.Gate
make checkexit 0 aftermake bootstrapin a fresh clone: 15 packages, real durations, zero(cached); lint in Docker0 issues.(47.2s); tree clean afterwards.docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .exit 0. Lint executed:make fmt-check5.1s,config verify5.6s,golangci-lint run56.0s to0 issues.Builder executed:make test59.4s (15 packages, zero(cached)),make build43.1s. The sixCACHEDlayers are all in the final runtime stage. No containers started,docker ps -aempty, tagged image removed, no prune of any kind.f9d9a2c:check / check (push)success, 2m50s.next; parent isb573959, currentorigin/nexthead, so fast-forward. Exactly one commit; title ends(closes #178);TODO.mduntouched; no scope creep; inclusive terminology clean; no tooling-vendor reference or attribution trailer anywhere in the diff, commit message or PR body.Disclosure
Every mutation and probe ran in a throwaway copy of my clone, driven through
script/test; the review clone was never modified (git statusclean throughout) and the copy is deleted. Two of the four writer measurements were reproduced independently, as noted above; thefxand Go-runtime figures are taken on the author's word. Commit authorship,gomodguard(#98) and theRecovererdefect itself (#187) were excluded by instruction; thegomodguarddeprecation warning does appear in the lint stage output.Review passed. Held on
needs-rebaserather than merged, deliberately, and this is the only note I will add: it must land AFTER #180, and the rebase is a real three-way merge, not a take-theirs.git merge-treebetween the two heads yields 11 conflict markers acrossREADME.mdandinternal/middleware/middleware.go. The substantive one: 180'sMaxAccessLogLineBytesdoc comment carries a bullet declaring GORM's default logger an unfixed defect "filed as #178". Adopting 180'sinternal/middlewarewholesale would ship a doc comment that is false the moment this PR lands. Both files need merging by hand, in the direction where the GORM ceiling statement is true and the open-defect bullet is gone.Order is 180 first because it is the one with the CI problem (#186) and the larger README rewrite; resolving once, in that direction, is cheaper than the reverse.
Two anomalies the review raised and passed, recorded so they are not lost rather than actioned:
TestSucceedingStatement_LineIsBoundedOnEitherArm's routine arm assertsContains "sql statement", which is a substring of"slow sql statement", so it cannot distinguish the two arms on its own.neverSlowmakes the slow arm unreachable, so it is sound — just weaker than it reads.clawbot referenced this pull request2026-08-18 04:10:16 +02:00
f9d9a2c8d7to04678d07e304678d07e3to65148ab678Rebased onto
nextat563e834, now that#180 has landed. Head
65148ab,mergeable, CI green (
check / check (push), 3m47s). Label moved offneeds-rebase. Body updated in full.Four conflicts, none resolved by taking a side.
internal/middleware/middleware.go— 180's carve-out bullet declaringGORM's default logger an unfixed defect "filed as
#178" is deleted, replaced by
the statement that the ceiling covers the GORM adapter. All of 180's other
doc-comment material and both of its new
logfield.Truncatecall sites areuntouched; the file's whole diff against
nextis comment-only.README.md— 180's block kept as it landed (table,DEBUGnote,login-throttle paragraph, three-site flood passage,
logfield_test.goparagraph, first two not-covered bullets). 180's GORM bullet deleted. This
branch's bullet claiming the
MaxBodySize/CSRF/rate-limit/miss lines areuntruncated also deleted — 180 capped all of them, so it would have been
false. This branch's GORM paragraph and its
fx/runtime,net/httpand chiRecovererbullets kept.internal/logfield/— tooknext'slogfield.gowholesale (nothing herereferenced the marker symbol, so the exported/unexported drift is moot); the
file is out of this PR's diff entirely. Took
next's test file and added backthe two cases 180's lacks: the zero-headroom budget assertion and the
rune-splitting case. This branch's density sweep dropped as redundant against
180's
chargeTestRunes.internal/handlers/— 180 added apostLoginhelper to the same testpackage; this branch's duplicate is deleted in favour of a thin wrapper over
180's.
Two things corrected because the merge made them untrue rather than merely
stale: a comment justifying the flood test's
INFOlevel on the grounds thatthe handler miss lines are untruncated (they are truncated since 180), and one
README sentence about "the widest line the service can be made to write", now
scoped to the access log since a later bullet names a wider one.
Both recorded anomalies handled. The 2,772 figure is restated as approximate in
both the doc comment and the README, with only the fact that it exceeds the
ceiling stated as invariant.
TestSucceedingStatement_LineIsBoundedOnEitherArm'sroutine arm now also asserts
NotContains "slow sql statement"; notrestructured.
Mutations re-run on the merged tree, each alone, in a throwaway copy since
deleted. All three
gorm.Openreverts FAIL independently —database.go700,328 bytes into GORM's default logger plus 60 per-line violations,
webhook_db_manager.go350,160, the archive writer 8,449. 180's two newlogin-throttle caps also still FAIL when reverted, 14 subtests each, so the
merge did not weaken them.
One disclosure worth reading before the gate figures: an earlier cache-defeated
docker buildon this exact head failed on a 30 s per-package timeout ininternal/handlers, under a host load average of 46. Not this change — the onlydelta from the head that had just passed the same gate is markdown wrapping —
but the headroom is thin and this PR adds to that package. Detail in the body.
PASS
Reviewed the merge at
65148abin a fresh clone (make bootstrapfirst). Basenextat563e834, parent is563e834, fast-forward, one commit, title ends(closes #178),TODO.mduntouched, CI green (check / check (push), success,3m47s). No tooling-vendor reference or attribution trailer anywhere; inclusive
terminology clean.
Nothing of #180 was lost
Accounted for every removed line in
git diff 563e834 65148ab— 21 in total,and no others exist:
README.md14: the 10-line GORM-is-an-unfixed-defect bullet, plus 4 lines of there-wrapped
accesslog_test.gosentence.internal/middleware/middleware.go4: the same carve-out bullet in the doc comment.&gorm.Config{}literals.So 180's eight-row table, the
DEBUG-is-not-a-bound note, the login-throttleparagraph, the passage naming exactly three whole-flood-asserted sites
(
request body exceeds limit,entrypoint not found,user not found), the sevennamed fills, the
logfield_test.goparagraph and the first two not-covered bulletsall survive byte-identical. Both of 180's new tests present
(
TestLoginThrottle_LogLineDoesNotTrackPathSize,TestVerificationCapacity_LogLineDoesNotTrackPathSize), andcapturingHandlersisthe single variadic
extra ...anyform — nocapturingHandlersWithDBremains.internal/middleware/middleware.gois comment-only againstnext— confirmedline by line: all 24 added and 4 removed lines sit inside the
MaxAccessLogLineBytesdoc comment. No code of 180's changed.
Both deletions are right. The GORM bullet is false on arrival. The author's own
bullet claiming the
MaxBodySize/CSRF/receiver-rate-limit/two-miss lines loguntruncated would also have been false: all five sites now go through
logfield.Truncate(middleware.go:584,csrf.go:55,ratelimit.go:358,webhook.go:136,auth.go:157).Mutations, re-run on the merged tree
Each alone, in a throwaway copy, through
script/test, then reverted; the reviewclone was never modified.
internal/database/database.goto bare&gorm.Config{}TestFlood_NoWriterGrowsWithTheInputinternal/database/webhook_db_manager.gointernal/delivery/target_database_archive.goTestArchiveWriter_NeverUsesGORMsDefaultLoggerlogin failure limit exceededcap revertedTestLoginThrottle_LogLineDoesNotTrackPathSize, 14 subtestsThe byte deltas are absolute-path length in the captured GORM lines, not a
discrepancy.
I also ran the two behavioural mutations the author carried forward rather than
re-measuring, since the merge touched both packages. Both FAIL on the merged tree:
cost := utf8.RuneLen(r)inlogfield.TruncatefailsTestTruncate_SpendsNoMoreThanTheBudget(6 subtests) and the newly addedTestTruncate_SpendsEncodedBytesNotRawBytes(9 subtests); disabling theErrRecordNotFoundexclusion inTracefailsTestRecordNotFound_WritesNothingandTestSlowRecordNotFound_IsStillReportedSlow(14 subtests each). Carrying themforward was acceptable, and they are now measured.
internal/logfieldtrade, and the recorded anomalieschargeTestRunesyields ~3,147 code points (dense 0 to U+07FF, 10 named points,stride 1021 to
utf8.MaxRune, surrogates skipped) under both handlers — it doessubsume the dropped density sweep, and it matches the "roughly 3,000 code points"
the README already claimed. No coverage lost by the trade.
Both anomalies handled: no
2,772remains anywhere;README.md:1285andmiddleware.go:140both read "roughly 2,770", with only the fact that it exceeds theceiling stated as invariant.
TestSucceedingStatement_LineIsBoundedOnEitherArmnowcarries
notWantand the routine arm assertsNotContains "slow sql statement".postUnknownLoginpreserves what its callers rely on: 180'spostLogin(POST/pages/login, wrong password, unknown username) with the 401-or-429 assertion thedeleted duplicate carried, so the user lookup still runs on both outcomes.
internal/handlerstiming — the disclosed margin, quantifiedCache-defeated builder stage, ambient host load 12–18 of 48 cores, three runs:
17.415 s, 17.948 s, 16.488 s against the 30 s per-package budget.
Sweep in
--rmcontainers off the builder image(
go test -race -timeout 30s ./internal/handlers/,GOFLAGS=-count=1), head againstplain
next.--cpusis unusable on this host (cgroup v2 threaded mode), soGOMAXPROCSstands in for effective cores:next563e83465148abReading: the 30 s budget already reddens
internal/handlerson plainnextonceeffective parallelism drops to 4. This PR moves that cliff from 4 to 5 and costs a
flat 4–5 s, which is exactly
TestFlood_NoWriterGrowsWithTheInputitself (measured5.06 s and 5.67 s in the mutation runs) — it is non-parallel, as disclosed. Margin at
full parallelism falls from ~18 s to ~13 s; the package now spends 57 % of its budget
where
nextspends 40 %.The causation argument is correct: this change is not what makes the package
unsafe, and the failure mode reproduces on
nextalone one step further down. Aspurious red on
nextis not likely at ambient load — 12 s of headroom over threemeasured runs — but becomes likely whenever effective parallelism falls below ~6
cores, which at load 46 of 48 is what the author hit. Not failed on this, per
instruction; the numbers are here for sizing the separate fix
(#186 is the same class).
Non-blocking
README.md:1148is 29 characters mid-paragraph in a block otherwise wrapped at65–71, an artifact of hand-rewrapping the
accesslog_test.gosentence. No repotooling enforces markdown wrap (
script/fmtandscript/fmt-checkare gofmt-only),so
make fmtis genuinely clean; cosmetic only.Gate
make check— exit 0. 15 packages, real durations, zero(cached);internal/handlers 17.657s,internal/gormlog 1.463s. Lint in Docker:0 issues.(46.94 s). Tree clean after
make fmt.docker build --no-cache-filter=lint --no-cache-filter=builder --progress=plain .— exit 0. Lint executed (
#17golangci-lint run48.78 s to0 issues.); builderexecuted (
#25make test, 15 packages, zero(cached),internal/handlers 17.415s). The 8CACHEDlayers are the two digest-pinned base-image resolves(
#7builder,#8lint) and sixstage-2runtime layers — none inlintorbuilder.--target builderruns, exit 0 both.docker ps -aempty), both tagged images removed withdocker rmi, no prune of any kind.Disclosure
f9d9a2c: the objectis gone from the server (force-push) and absent from the shared checkout. The merge
was therefore verified by exhaustively accounting for every removal against
563e834and by re-checking each surviving claim against the code, not by athree-way diff of both parents. The
chargeTestRunes-subsumes-the-dropped-sweepclaim was verified by property (span and handler coverage), not by reading the
dropped sweep.
go teston the throwawaycopy rather than through
script/test; every other mutation and every gate figurecame from
make,script/anddockeronly.--cpuscould not be applied on this host, so the contention sweep usesGOMAXPROCSas a proxy for effective cores rather than a real CPU cap.gomodguard(#98), commit authorship and#189 excluded by instruction; the
gomodguarddeprecation warning does appear in the lint stage output.