GORM's default logger prints the full interpolated SQL, including the client-chosen path and username, on every record-not-found #178

New Issue

clawbot · 2026-08-18T01:40:55+02:00

clawbot commented

2026-08-18 01:40:55 +02:00

Found by the log-call audit required by #176. Filed rather than fixed there: that issue scopes its sweep to slog call sites, and this is a second, independent log writer whose configuration is an observability decision in its own right.

internal/database/database.go:156 and internal/database/webhook_db_manager.go:249 both open GORM with a bare &gorm.Config{}. That leaves logger.Default in place, which in gorm.io/gorm v1.25.5 is:

Default = New(log.New(os.Stdout, "\r\n", log.LstdFlags), Config{
    SlowThreshold:             200 * time.Millisecond,
    LogLevel:                  Warn,
    IgnoreRecordNotFoundError: false,
    Colorful:                  true,
})

logger.Trace logs whenever err != nil && LogLevel >= Error && (!errors.Is(err, ErrRecordNotFound) || !IgnoreRecordNotFoundError). Warn (3) is >= Error (2) and IgnoreRecordNotFoundError is false, so every ErrRecordNotFound prints the fully interpolated SQL to os.Stdout, unconditionally.

Two of those lookups are on unauthenticated endpoints and miss by design:

internal/handlers/webhook.go lookupEntrypoint — SELECT * FROM entrypoints WHERE path = "<the client's path segment>", on /webhook/{uuid}, which matches any single segment of any length.
internal/handlers/auth.go authenticateUser — SELECT * FROM users WHERE username = "<the submitted username>", on the login form.

Observed directly, in the test run inside the CI image:

/build/internal/handlers/webhook.go:127 record not found
[4.740ms] [rows:0] SELECT * FROM `entrypoints` WHERE path = "xxxxxxxx…
/build/internal/handlers/auth.go:108 record not found
[3.300ms] [rows:0] SELECT * FROM `users` WHERE username = "x\"\"\"\"…

Those were the 8 KB client-chosen values the new bound tests send. The slog lines for the same two requests are capped at 512 encoded bytes; these are not capped at all.

Why this is worse than the one that disclosed it

#176 and #146 both concerned lines an operator can reason about: they go through the service's own logger, they carry a level, and the two DEBUG ones are off by default. This one is on by default, answers to no level the operator sets, does not go through internal/logger (so neither the JSON nor the tty handler shapes it, and it lands on stdout rather than stderr), and is not covered by the MaxAccessLogLineBytes ceiling the README now quotes.

Net: an unauthenticated client on the public internet still writes arbitrary-length attacker-chosen text into the operator's logs, one line per request, at the full 1 MB the receiver will accept as a path. That is the same defect class #146 was moved into the 1.0.0 milestone for, which is why it is milestoned the same way.

The decision to make

Not simply "cap it" — GORM's logger is an interface, and the choice of what to install has consequences beyond this path:

Set IgnoreRecordNotFoundError: true. Kills these two lines outright. A missing row is not an error on either of these paths; it is the expected outcome for an invented UUID or an unknown user. Cheapest fix, and it removes the amplification rather than bounding it.
Route GORM through internal/logger with a gormlogger.Interface adapter, so its output has a level, a handler and a destination consistent with everything else — and so internal/logfield can cap what it emits. More work; the right end state if SQL logging is wanted at all.
Set LogLevel: logger.Silent in production and keep the default in dev. Loses slow-query logging, which is the one genuinely useful thing this logger does.

Whichever is chosen, the SQL text itself needs a bound if it is logged at all: GORM interpolates the parameters into the statement, so the line length is the parameter length, and on these two paths the parameter is client-chosen.

Definition of done

A flood of unauthenticated requests with long client-chosen paths and usernames produces no log output that grows with the input, from any writer — not just from slog.
Whatever ceiling the README states covers GORM's output too, or the README says explicitly that it does not and why. A bound that is true of one writer and false of another is worse than no stated bound; that is the lesson #146 cost four review rounds to learn.
A test in the shape of the ones in internal/middleware/logbound_test.go, capturing GORM's writer rather than the service logger.
Slow-query visibility is either kept or its loss is a stated decision.

Implementation requirements

Branch from next, PR based on next, single commit, title ending (closes #N).
Do not modify TODO.md (see #112).
Gate on make check plus the Docker lint path with the cache defeated. All linting runs in Docker.

Found by the log-call audit required by https://git.eeqj.de/sneak/webhooker/issues/176. Filed rather than fixed there: that issue scopes its sweep to `slog` call sites, and this is a second, independent log writer whose configuration is an observability decision in its own right. `internal/database/database.go:156` and `internal/database/webhook_db_manager.go:249` both open GORM with a bare `&gorm.Config{}`. That leaves `logger.Default` in place, which in `gorm.io/gorm v1.25.5` is: ``` Default = New(log.New(os.Stdout, "\r\n", log.LstdFlags), Config{ SlowThreshold: 200 * time.Millisecond, LogLevel: Warn, IgnoreRecordNotFoundError: false, Colorful: true, }) ``` `logger.Trace` logs whenever `err != nil && LogLevel >= Error && (!errors.Is(err, ErrRecordNotFound) || !IgnoreRecordNotFoundError)`. `Warn` (3) is `>= Error` (2) and `IgnoreRecordNotFoundError` is false, so **every `ErrRecordNotFound` prints the fully interpolated SQL to `os.Stdout`**, unconditionally. Two of those lookups are on unauthenticated endpoints and miss by design: - `internal/handlers/webhook.go` `lookupEntrypoint` — `SELECT * FROM entrypoints WHERE path = "<the client's path segment>"`, on `/webhook/{uuid}`, which matches any single segment of any length. - `internal/handlers/auth.go` `authenticateUser` — `SELECT * FROM users WHERE username = "<the submitted username>"`, on the login form. Observed directly, in the test run inside the CI image: ``` /build/internal/handlers/webhook.go:127 record not found [4.740ms] [rows:0] SELECT * FROM `entrypoints` WHERE path = "xxxxxxxx… /build/internal/handlers/auth.go:108 record not found [3.300ms] [rows:0] SELECT * FROM `users` WHERE username = "x\"\"\"\"… ``` Those were the 8 KB client-chosen values the new bound tests send. The `slog` lines for the same two requests are capped at 512 encoded bytes; these are not capped at all. ## Why this is worse than the one that disclosed it https://git.eeqj.de/sneak/webhooker/issues/176 and https://git.eeqj.de/sneak/webhooker/issues/146 both concerned lines an operator can reason about: they go through the service's own logger, they carry a level, and the two `DEBUG` ones are off by default. This one is on by default, answers to no level the operator sets, does not go through `internal/logger` (so neither the JSON nor the tty handler shapes it, and it lands on **stdout** rather than stderr), and is not covered by the `MaxAccessLogLineBytes` ceiling the README now quotes. Net: an unauthenticated client on the public internet still writes arbitrary-length attacker-chosen text into the operator's logs, one line per request, at the full 1 MB the receiver will accept as a path. That is the same defect class https://git.eeqj.de/sneak/webhooker/issues/146 was moved into the `1.0.0` milestone for, which is why it is milestoned the same way. ## The decision to make Not simply "cap it" — GORM's logger is an interface, and the choice of what to install has consequences beyond this path: - Set `IgnoreRecordNotFoundError: true`. Kills these two lines outright. A missing row is not an error on either of these paths; it is the expected outcome for an invented UUID or an unknown user. Cheapest fix, and it removes the amplification rather than bounding it. - Route GORM through `internal/logger` with a `gormlogger.Interface` adapter, so its output has a level, a handler and a destination consistent with everything else — and so `internal/logfield` can cap what it emits. More work; the right end state if SQL logging is wanted at all. - Set `LogLevel: logger.Silent` in production and keep the default in dev. Loses slow-query logging, which is the one genuinely useful thing this logger does. Whichever is chosen, the SQL text itself needs a bound if it is logged at all: GORM interpolates the parameters into the statement, so the line length is the parameter length, and on these two paths the parameter is client-chosen. ## Definition of done - A flood of unauthenticated requests with long client-chosen paths and usernames produces no log output that grows with the input, from any writer — not just from `slog`. - Whatever ceiling the README states covers GORM's output too, or the README says explicitly that it does not and why. A bound that is true of one writer and false of another is worse than no stated bound; that is the lesson https://git.eeqj.de/sneak/webhooker/issues/146 cost four review rounds to learn. - A test in the shape of the ones in `internal/middleware/logbound_test.go`, capturing GORM's writer rather than the service logger. - Slow-query visibility is either kept or its loss is a stated decision. ## Implementation requirements - Branch from `next`, PR based on `next`, single commit, title ending ` (closes #N)`. - Do not modify `TODO.md` (see https://git.eeqj.de/sneak/webhooker/issues/112). - Gate on `make check` plus the Docker lint path with the cache defeated. All linting runs in Docker.

clawbot added this to the 1.0.0 milestone 2026-08-18 01:40:55 +02:00

clawbot referenced this issue from a commit

2026-08-18 01:47:06 +02:00

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