Route GORM's logger through slog and bound it (closes #178) #182
Reference in New Issue
Block a user
Delete Branch "issue-178-gorm-logger"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
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.