From 0c64c411cc4377016a4b05d7f5e3f900aa6efecd Mon Sep 17 00:00:00 2001 From: clawbot Date: Tue, 18 Aug 2026 07:17:43 +0200 Subject: [PATCH] Route GORM's logger through slog and bound it (closes #178) --- README.md | 83 +++- internal/database/database.go | 6 +- internal/database/webhook_db_manager.go | 6 +- internal/delivery/target_database_archive.go | 7 +- .../target_database_archive_gormlog_test.go | 155 ++++++ internal/gormlog/export_test.go | 17 + internal/gormlog/gormlog.go | 168 +++++++ internal/gormlog/gormlog_test.go | 436 +++++++++++++++++ internal/handlers/gormlogbound_test.go | 462 ++++++++++++++++++ internal/logfield/logfield_test.go | 100 ++++ internal/middleware/middleware.go | 28 +- 11 files changed, 1447 insertions(+), 21 deletions(-) create mode 100644 internal/delivery/target_database_archive_gormlog_test.go create mode 100644 internal/gormlog/export_test.go create mode 100644 internal/gormlog/gormlog.go create mode 100644 internal/gormlog/gormlog_test.go create mode 100644 internal/handlers/gormlogbound_test.go diff --git a/README.md b/README.md index 93b198b..4e8e972 100644 --- a/README.md +++ b/README.md @@ -1141,10 +1141,11 @@ the figure has headroom. `internal/middleware/accesslog_test.go` asserts it against 8 KB of client-chosen text in the path, in the query, and in each of `User-Agent`, `Referer` and `X-Request-Id`, including cases built from the characters the handlers escape, and -against the widest line the service can be made to write: a 5xx that -keeps its concrete path while all three header fields are also at their -budget. Every case runs through both handlers `internal/logger` can -select — the JSON one and the text one it installs on a tty — since the +against the widest access log line the service can be made to write: a +5xx that keeps its concrete path while all three header fields are also +at their budget. Every case runs through both handlers +`internal/logger` can select — the JSON one and the text one it +installs on a tty — since the two do not escape alike and the ceiling is quoted unqualified. Measured over a real connection, the widest line is 1,972 bytes. @@ -1213,6 +1214,33 @@ against what the handlers really emit, over roughly 3,000 code points on each, so an undercharged rune fails a test rather than quietly falsifying the ceiling. +**It covers GORM's statement logging as well.** GORM's own default +logger printed the fully interpolated SQL — parameters and all — to +standard output on every statement that returned an error, including a +plain record-not-found, at a level no operator setting reached. Two of +this service's lookups miss by design on unauthenticated routes: the +entrypoint lookup behind `/webhook/{uuid}` and the user lookup behind +the login form, whose path segment and submitted username the client +picks outright. Every +`gorm.Open` in the service now installs the adapter in +`internal/gormlog` instead. It writes through the same `slog` logger as +everything else, so its lines take the level the operator set and the +handler `internal/logger` selected, and every value it emits is spent +through the same `internal/logfield` budget. A record-not-found is not +logged as an error: it is the expected outcome on both of those paths, +and each handler already records its own miss at `DEBUG` — bounded, per +the table above — without the SQL. Slow statements are kept, at `WARN`, +above the same 200 ms threshold GORM used and with the statement +bounded, because that report is the one thing GORM's logger gave an +operator that nothing else here does. The adapter orders its cases +exactly as GORM's own `Trace` orders them, so a statement that both +missed and ran slow is still reported as slow, and dropping the miss +costs an operator no report `IgnoreRecordNotFoundError` would have +kept. A GORM line spends at most two of those budgets — the statement +and the driver error — against a smaller fixed portion than the access +log's, and `internal/gormlog/gormlog_test.go` asserts each line against +`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic. + What that ceiling does **not** cover, stated here so the figure is not read as more than it is: @@ -1236,16 +1264,39 @@ read as more than it is: that type on a specific webhook, and each line it writes is bounded per event by the 1 MB receiver body cap. Adding one is a decision to spend log volume on that webhook's payloads. -- **GORM's default logger**, which prints the fully interpolated SQL to - stdout on every record-not-found — including the client-chosen path - on `/webhook/{uuid}` and the submitted username on the login form. - This one is not deliberate and not yet fixed; it does not go through - `internal/logger` at all, so no level the operator sets and no budget - above applies to it. Tracked at - . Until it is fixed, - an unauthenticated flood can still write text of its own choosing and - its own length to the operator's stdout, and the ceiling above - describes only the `slog` half of the picture. +- **Two writers that do not go through `internal/logger` at all**, both + on standard error. `fx` prints the dependency graph and the lifecycle + hooks through its default console logger at startup and shutdown — + nothing calls `fx.WithLogger`, and `fx.New` builds that logger over + `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a + panic in a background worker rather than in a request handler is the + case that reaches it, since nothing recovers those. Neither carries a + client-chosen value at a client-chosen length: the five `panic` calls + in this service are invariant guards over constants and over + `crypto/rand`. +- **`net/http`'s own faults**, which are _not_ a separate writer. + `internal/server/http.go` builds its server with a nil `ErrorLog`, so + `net/http` falls back to the `log` package's default logger — and + `internal/logger` calls `slog.SetDefault`, which redirects that logger + into whichever handler it installed. Those lines therefore arrive on + standard output, shaped like every other line, at `INFO`. They are not + truncated and they are not bounded by the ceiling: a handler panic + arrives as one record carrying a whole goroutine stack, above the + ceiling's 2,560 bytes — measured at roughly 2,770 in one checkout. The + exact width is not an invariant, since it moves with the goroutine + number and with the source paths baked into the stack; that it exceeds + the ceiling does not move. The value is the runtime's, not a client's. +- **A handler panic reaches that path** rather than the one it looks + like it should. `internal/server/routes.go` installs chi's + `middleware.Recoverer` in front of every route, which is meant to + print the panic and its stack to standard error and answer 500. On the + Go version this service builds against it does neither: chi v1.5.5's + stack pretty-printer looks for a `panic(0x` frame that the runtime no + longer emits, walks past the end of its own slice, and panics before + writing a byte. That second panic escapes to `net/http`, which drops + the connection and reports it through the nil `ErrorLog` above. + Tracked separately in + . Every limiter here — receiver, login, and password change — identifies the client the same way, through one shared key function: the @@ -1485,6 +1536,10 @@ webhooker/ │ │ └── webhook_db_manager.go # Per-webhook DB lifecycle manager │ ├── globals/ │ │ └── globals.go # Build-time variables (appname, version, arch) +│ ├── gormlog/ +│ │ └── gormlog.go # GORM's logger.Interface on top of slog, bounded +│ ├── logfield/ +│ │ └── logfield.go # Encoded-byte budget for client-supplied log values │ ├── delivery/ │ │ ├── engine.go # Event-driven delivery engine (channel + timer based) │ │ ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries diff --git a/internal/database/database.go b/internal/database/database.go index bbee40c..b6a1494 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -17,6 +17,7 @@ import ( "gorm.io/gorm" _ "modernc.org/sqlite" // Pure Go SQLite driver "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/gormlog" "sneak.berlin/go/webhooker/internal/logger" ) @@ -155,7 +156,10 @@ func (d *Database) connect() error { // Then use it with GORM db, err := gorm.Open(sqlite.Dialector{ Conn: sqlDB, - }, &gorm.Config{}) + }, &gorm.Config{ + // Never leave this at GORM's default. See internal/gormlog. + Logger: gormlog.New(d.log), + }) if err != nil { d.log.Error( "failed to connect to database", diff --git a/internal/database/webhook_db_manager.go b/internal/database/webhook_db_manager.go index a1f694d..0e89be1 100644 --- a/internal/database/webhook_db_manager.go +++ b/internal/database/webhook_db_manager.go @@ -14,6 +14,7 @@ import ( "gorm.io/driver/sqlite" "gorm.io/gorm" "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/gormlog" "sneak.berlin/go/webhooker/internal/logger" ) @@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB( db, err := gorm.Open(sqlite.Dialector{ Conn: sqlDB, - }, &gorm.Config{}) + }, &gorm.Config{ + // Never leave this at GORM's default. See internal/gormlog. + Logger: gormlog.New(m.log), + }) if err != nil { _ = sqlDB.Close() diff --git a/internal/delivery/target_database_archive.go b/internal/delivery/target_database_archive.go index f2ca64b..d179e07 100644 --- a/internal/delivery/target_database_archive.go +++ b/internal/delivery/target_database_archive.go @@ -12,6 +12,7 @@ import ( "gorm.io/driver/sqlite" "gorm.io/gorm" + "sneak.berlin/go/webhooker/internal/gormlog" ) // archiveExpiryNever is the expiry sentinel (and default) that @@ -282,7 +283,11 @@ func (w *archiveWriter) openMode( } gdb, err := gorm.Open( - sqlite.Dialector{Conn: sqlDB}, &gorm.Config{}, + sqlite.Dialector{Conn: sqlDB}, &gorm.Config{ + // Never leave this at GORM's default. See + // internal/gormlog. + Logger: gormlog.New(w.log), + }, ) if err != nil { _ = sqlDB.Close() diff --git a/internal/delivery/target_database_archive_gormlog_test.go b/internal/delivery/target_database_archive_gormlog_test.go new file mode 100644 index 0000000..1644f8c --- /dev/null +++ b/internal/delivery/target_database_archive_gormlog_test.go @@ -0,0 +1,155 @@ +package delivery_test + +import ( + "bytes" + "log" + "log/slog" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gorm.io/gorm" + gormlogger "gorm.io/gorm/logger" + "sneak.berlin/go/webhooker/internal/delivery" + "sneak.berlin/go/webhooker/internal/middleware" +) + +// archiveGORMTailMarker sits at the far end of the value this file +// drives into an archive lookup. Its presence in a log line means the +// whole value reached the log, so nothing truncated it. +const archiveGORMTailMarker = "ENDOFCLIENTVALUE" + +// archiveGORMFillBytes is how much text the lookup carries. It is far +// past every budget in play. +const archiveGORMFillBytes = 8 << 10 + +// gormDefaultBuf collects what GORM's package-level default logger +// writes, if anything reaches it. +type gormDefaultBuf struct { + mu sync.Mutex + b bytes.Buffer +} + +func (g *gormDefaultBuf) Write(p []byte) (int, error) { + g.mu.Lock() + defer g.mu.Unlock() + + return g.b.Write(p) +} + +func (g *gormDefaultBuf) String() string { + g.mu.Lock() + defer g.mu.Unlock() + + return g.b.String() +} + +// captureArchiveGORMDefault replaces GORM's package-level default +// logger with one configured exactly as GORM configures its own, +// writing to a buffer. +// +// This duplicates the detector in internal/handlers rather than +// sharing it: a test helper cannot cross a package's test boundary +// without exporting production code to carry it, and a logging +// detector is not worth a production symbol. What it detects is the +// third gorm.Open in this service, at +// internal/delivery/target_database_archive.go — the archive writer, +// whose type is unexported, so nothing outside this package can drive +// it. +func captureArchiveGORMDefault(t *testing.T) *gormDefaultBuf { + t.Helper() + + buf := &gormDefaultBuf{} + orig := gormlogger.Default + + gormlogger.Default = gormlogger.New( + log.New(buf, "", log.LstdFlags), + gormlogger.Config{ + SlowThreshold: 200 * time.Millisecond, + LogLevel: gormlogger.Warn, + IgnoreRecordNotFoundError: false, + Colorful: false, + }, + ) + + t.Cleanup(func() { gormlogger.Default = orig }) + + return buf +} + +// TestArchiveWriter_NeverUsesGORMsDefaultLogger pins the archive +// writer's gorm.Open to the adapter. +// +// Restore a bare &gorm.Config{} at +// internal/delivery/target_database_archive.go and this fails: the +// default logger prints the fully interpolated SELECT on every +// ErrRecordNotFound, so the client-chosen event id below arrives whole +// and unbounded on stdout, answering to no level the operator set. +// +// Not parallel: gormlogger.Default is process-global. Go runs every +// non-parallel top-level test to completion before it resumes the +// parallel ones. +// +//nolint:paralleltest // Deliberately sequential; see above. +func TestArchiveWriter_NeverUsesGORMsDefaultLogger(t *testing.T) { + var captured bytes.Buffer + + gormDefault := captureArchiveGORMDefault(t) + + w := delivery.NewExportArchiveWriter( + filepath.Join(t.TempDir(), "archive.db"), + slog.New(slog.NewTextHandler( + &captured, &slog.HandlerOptions{Level: slog.LevelDebug}, + )), + 0, + ) + + require.NoError(t, w.Open(0)) + + t.Cleanup(w.Evict) + + // A lookup that misses, carrying a value the size of an inbound + // event id. Under the default logger this is the line that gets + // interpolated and printed. + value := strings.Repeat("\x01", archiveGORMFillBytes) + + archiveGORMTailMarker + + var row delivery.ExportArchivedEvent + + err := w.DB().Where("event_id = ?", value).First(&row).Error + require.ErrorIs(t, err, gorm.ErrRecordNotFound) + + got := gormDefault.String() + assert.Empty( + t, got, + "GORM's default logger wrote %d bytes, so the archive "+ + "writer's gorm.Open is back on a bare &gorm.Config{}; "+ + "the first of them: %s", + len(got), got[:min(len(got), 300)], + ) + + // The adapter drops a miss, so this should be silent too — and + // whatever it does write stays inside the stated ceiling. + out := captured.String() + + assert.NotContains( + t, out, archiveGORMTailMarker, + "the far end of the client-chosen value reached the log", + ) + + for line := range strings.SplitSeq(strings.TrimRight(out, "\n"), "\n") { + if line == "" { + continue + } + + assert.LessOrEqual( + t, len(line), middleware.MaxAccessLogLineBytes, + "log line exceeded its bound: %s", + line[:min(len(line), 300)], + ) + } +} diff --git a/internal/gormlog/export_test.go b/internal/gormlog/export_test.go new file mode 100644 index 0000000..3d249b7 --- /dev/null +++ b/internal/gormlog/export_test.go @@ -0,0 +1,17 @@ +package gormlog + +import ( + "log/slog" + "time" +) + +// ExportNewWithSlowThreshold builds a Logger whose slow-statement +// threshold is d rather than DefaultSlowThreshold, so a test can pin +// which arm of Trace it is exercising instead of racing the clock on a +// loaded machine. The threshold is set at construction, like every +// other field, so the type's concurrency guarantee still holds. +func ExportNewWithSlowThreshold( + log *slog.Logger, d time.Duration, +) *Logger { + return &Logger{log: log, slowThreshold: d} +} diff --git a/internal/gormlog/gormlog.go b/internal/gormlog/gormlog.go new file mode 100644 index 0000000..38ff5ec --- /dev/null +++ b/internal/gormlog/gormlog.go @@ -0,0 +1,168 @@ +// Package gormlog adapts GORM's logger onto the service's slog +// logger. +// +// GORM's own default logger is not usable here. It is built at package +// init with log.New(os.Stdout, ...) at LogLevel Warn with +// IgnoreRecordNotFoundError false, so it writes the fully interpolated +// SQL — parameters and all — for every statement that returns an +// error, including gorm.ErrRecordNotFound. Two of this service's +// lookups miss by design on unauthenticated routes: the entrypoint +// lookup on /webhook/{uuid}, whose path segment the client picks +// outright, and the user lookup behind the login form, whose username +// the client picks outright. Under the default logger each of those +// misses printed an unbounded, attacker-chosen string, at no level the +// operator can turn down, past every handler internal/logger installs. +// +// This adapter fixes all three properties at once: the lines get a +// level the operator controls, they are shaped by whichever handler +// internal/logger selected, and every value a client can influence is +// spent through logfield.Truncate. +package gormlog + +import ( + "context" + "errors" + "fmt" + "log/slog" + "time" + + gormlogger "gorm.io/gorm/logger" + "sneak.berlin/go/webhooker/internal/logfield" +) + +// DefaultSlowThreshold is the duration at or above which a statement +// is logged as slow. It is GORM's own default, kept deliberately: slow +// SQL is the one thing GORM's logger reports that nothing else in this +// service does, so silencing the logger outright would have cost real +// observability to fix a log-volume defect. +const DefaultSlowThreshold = 200 * time.Millisecond + +// Logger implements gormlogger.Interface on top of an *slog.Logger. +// +// It is safe for concurrent use: every field is set at construction +// and never written again. +type Logger struct { + log *slog.Logger + slowThreshold time.Duration +} + +// Interface compliance is asserted here rather than discovered at the +// gorm.Open call sites. +var _ gormlogger.Interface = (*Logger)(nil) + +// New returns a GORM logger that writes through log. +func New(log *slog.Logger) *Logger { + return &Logger{ + log: log, + slowThreshold: DefaultSlowThreshold, + } +} + +// LogMode returns the logger unchanged. +// +// GORM's LogLevel is deliberately not honoured. Level is the operator's +// decision and it is expressed once, through LOG_LEVEL and the +// slog.LevelVar internal/logger holds; a second level knob inside the +// database layer could only disagree with it. The mapping from GORM's +// four categories onto slog levels is fixed in Trace below. +// +//nolint:ireturn // The interface return is GORM's signature, not a choice. +func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface { + return l +} + +// Info logs one of GORM's own informational messages. +func (l *Logger) Info( + ctx context.Context, msg string, data ...any, +) { + l.log.InfoContext(ctx, "gorm", "message", format(msg, data...)) +} + +// Warn logs one of GORM's own warnings. +func (l *Logger) Warn( + ctx context.Context, msg string, data ...any, +) { + l.log.WarnContext(ctx, "gorm", "message", format(msg, data...)) +} + +// Error logs one of GORM's own errors. +func (l *Logger) Error( + ctx context.Context, msg string, data ...any, +) { + l.log.ErrorContext(ctx, "gorm", "message", format(msg, data...)) +} + +// Trace reports the outcome of a single statement. GORM calls it for +// every statement it runs, so the cheap paths stay cheap: fc() +// renders the interpolated SQL and is called only on a branch that +// will actually emit. +// +// The arms are ordered exactly as GORM's own Trace orders them — +// non-record-not-found error, then slow, then the routine case — so +// that a statement which both misses and runs slow is still reported +// as slow. A miss is the likeliest statement to be slow, since it is +// the one that scans without finding a row, and ordering the drop +// ahead of the slow arm would have made this adapter less observant +// than the IgnoreRecordNotFoundError option it was chosen over. +func (l *Logger) Trace( + ctx context.Context, + begin time.Time, + fc func() (string, int64), + err error, +) { + elapsed := time.Since(begin) + + switch { + case err != nil && !errors.Is(err, gormlogger.ErrRecordNotFound): + sql, rows := fc() + l.log.ErrorContext(ctx, "sql statement failed", + "error", logfield.Truncate(err.Error(), logfield.MaxBytes), + "sql", logfield.Truncate(sql, logfield.MaxBytes), + "rows", rows, + "elapsed_ms", elapsed.Milliseconds(), + ) + + case l.slowThreshold > 0 && elapsed >= l.slowThreshold: + sql, rows := fc() + l.log.WarnContext(ctx, "slow sql statement", + "sql", logfield.Truncate(sql, logfield.MaxBytes), + "rows", rows, + "elapsed_ms", elapsed.Milliseconds(), + "threshold_ms", l.slowThreshold.Milliseconds(), + ) + + case err != nil: + // gorm.ErrRecordNotFound is not an error on the paths that + // produce it here: an invented entrypoint UUID and an unknown + // username are the expected outcome of an unauthenticated + // request, not a fault. This is the IgnoreRecordNotFoundError + // behaviour, and it is unconditional rather than configurable + // because no caller in this service wants the other one — the + // two handlers that care already record the miss themselves, + // at DEBUG, without the SQL. A miss that ran slow has already + // been reported by the arm above. + return + + case l.log.Enabled(ctx, slog.LevelDebug): + sql, rows := fc() + l.log.DebugContext(ctx, "sql statement", + "sql", logfield.Truncate(sql, logfield.MaxBytes), + "rows", rows, + "elapsed_ms", elapsed.Milliseconds(), + ) + } +} + +// format renders one of GORM's printf-style internal messages and +// bounds it. GORM builds these itself, but they can quote a value the +// statement carried, so they are spent through the same budget as +// everything else rather than trusted. +func format(msg string, data ...any) string { + if len(data) == 0 { + return logfield.Truncate(msg, logfield.MaxBytes) + } + + return logfield.Truncate( + fmt.Sprintf(msg, data...), logfield.MaxBytes, + ) +} diff --git a/internal/gormlog/gormlog_test.go b/internal/gormlog/gormlog_test.go new file mode 100644 index 0000000..d8e53cc --- /dev/null +++ b/internal/gormlog/gormlog_test.go @@ -0,0 +1,436 @@ +package gormlog_test + +import ( + "bytes" + "context" + "database/sql" + "fmt" + "log/slog" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gorm.io/driver/sqlite" + "gorm.io/gorm" + _ "modernc.org/sqlite" // Pure Go SQLite driver. + "sneak.berlin/go/webhooker/internal/gormlog" + "sneak.berlin/go/webhooker/internal/middleware" +) + +// fillBytes is how much client-chosen text each case drives into the +// statement. It is well past every budget in play, so a value that +// arrives short arrived short because something cut it. +const fillBytes = 8 << 10 + +// tailMarker sits at the far end of every generated value. A line that +// contains it carried the whole value, which means nothing cut it — so +// a value that merely happened to be short cannot pass for a truncated +// one. +const tailMarker = "ENDOFCLIENTVALUE" + +// fills are the characters a client can drive into a SQL parameter, +// chosen for what the log handlers charge for them rather than for +// looking dangerous. +// +// The C0 control is the one that matters. Both handlers spell U+0001 +// as a six-byte escape for the single byte it costs a client to send, +// which is the widest multiplier available in the basic multilingual +// plane and the case a raw-byte budget breaks on first. The astral +// non-printable costs ten under the text handler, four more than the +// JSON handler ever spends. +func fills() []struct { + name string + fill string +} { + return []struct { + name string + fill string + }{ + {"plain", "x"}, + {"quote", `"`}, + {"backslash", `\`}, + {"tab", "\t"}, + {"newline", "\n"}, + {"c0_control", "\x01"}, + {"astral_nonprintable", "\U0001000C"}, + } +} + +// clientValue builds a value of at least fillBytes raw bytes out of +// fill, ending in tailMarker. +func clientValue(fill string) string { + var b strings.Builder + + for b.Len() < fillBytes { + b.WriteString(fill) + } + + b.WriteString(tailMarker) + + return b.String() +} + +// handlers are the two slog handlers internal/logger can install. The +// ceiling is quoted to operators unqualified, so every case is +// asserted under both. +func handlers() []struct { + name string + make func(*bytes.Buffer) slog.Handler +} { + opts := &slog.HandlerOptions{Level: slog.LevelDebug} + + return []struct { + name string + make func(*bytes.Buffer) slog.Handler + }{ + {"json", func(b *bytes.Buffer) slog.Handler { + return slog.NewJSONHandler(b, opts) + }}, + {"text", func(b *bytes.Buffer) slog.Handler { + return slog.NewTextHandler(b, opts) + }}, + } +} + +type thing struct { + ID string `gorm:"primaryKey"` + Name string +} + +// neverSlow is a slow-statement threshold no statement in this file +// can reach. Cases that are about a non-slow arm of Trace set it, so +// that a machine under load cannot turn a miss into a slow report and +// decide the outcome for them. +const neverSlow = time.Hour + +// alwaysSlow makes every statement count as slow, so the slow arm is +// reached without the test waiting for it. +const alwaysSlow = time.Nanosecond + +// openDB opens a real SQLite database behind the adapter under test, +// so every assertion below is made against SQL that GORM actually +// rendered rather than against a string a test wrote by hand. slow is +// the adapter's slow-statement threshold. +func openDB( + t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration, +) *gorm.DB { + t.Helper() + + sqlDB, err := sql.Open("sqlite", fmt.Sprintf( + "file:%s?mode=rwc", + filepath.Join(t.TempDir(), "gormlog.db"), + )) + require.NoError(t, err) + + t.Cleanup(func() { _ = sqlDB.Close() }) + + gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow) + + gdb, err := gorm.Open( + sqlite.Dialector{Conn: sqlDB}, + &gorm.Config{Logger: gl}, + ) + require.NoError(t, err) + + require.NoError(t, gdb.AutoMigrate(&thing{})) + + // Migration chatter is not what any of these cases is about. + buf.Reset() + + return gdb +} + +// assertBounded holds every line the adapter wrote to the stated +// ceiling and proves each was cut rather than merely short. +func assertBounded(t *testing.T, out string) { + t.Helper() + + assert.NotContains( + t, out, tailMarker, + "the far end of the client value reached the log, so "+ + "nothing truncated it", + ) + + for line := range strings.SplitSeq( + strings.TrimRight(out, "\n"), "\n", + ) { + if line == "" { + continue + } + + assert.LessOrEqual( + t, len(line), middleware.MaxAccessLogLineBytes, + "log line exceeded its bound: %s", + line[:min(len(line), 300)], + ) + } +} + +// TestRecordNotFound_WritesNothing is the defect itself. GORM's own +// default logger prints the fully interpolated SELECT on every +// ErrRecordNotFound, and on this service's two unauthenticated +// lookups the interpolated parameter is whatever the client sent. +func TestRecordNotFound_WritesNothing(t *testing.T) { + t.Parallel() + + for _, h := range handlers() { + for _, f := range fills() { + t.Run(h.name+"/"+f.name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, h.make(&buf), neverSlow) + + var got thing + + err := gdb.Where( + "id = ?", clientValue(f.fill), + ).First(&got).Error + require.ErrorIs(t, err, gorm.ErrRecordNotFound) + + assert.Empty( + t, buf.String(), + "a miss on a client-chosen key must not "+ + "write a log line", + ) + }) + } + } +} + +// TestSlowRecordNotFound_IsStillReportedSlow pins the arm ordering in +// Trace against the drop above. +// +// GORM's own Trace orders its cases error-that-is-not-a-miss, then +// slow, then routine, so IgnoreRecordNotFoundError: true — the cheap +// option this adapter was chosen over — still reports a miss that ran +// slow. An adapter that dropped the miss first would be strictly less +// observant than the option it replaced, on exactly the two lookups +// this package exists for. A miss is also the statement most likely to +// be slow, since it is the one that scans without finding a row. +func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) { + t.Parallel() + + for _, h := range handlers() { + for _, f := range fills() { + t.Run(h.name+"/"+f.name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, h.make(&buf), alwaysSlow) + + var got thing + + err := gdb.Where( + "id = ?", clientValue(f.fill), + ).First(&got).Error + require.ErrorIs(t, err, gorm.ErrRecordNotFound) + + assert.Contains( + t, buf.String(), "slow sql statement", + "a slow statement that missed was not "+ + "reported as slow", + ) + assertBounded(t, buf.String()) + }) + } + } +} + +// TestRecordNotFoundFlood_DoesNotGrowWithInput states the definition +// of done directly: a flood of misses at two input sizes 64 times +// apart must cost the same number of bytes of log. +func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) { + t.Parallel() + + const requests = 50 + + flood := func(t *testing.T, size int) int { + t.Helper() + + var buf bytes.Buffer + + gdb := openDB( + t, &buf, + slog.NewJSONHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + }), + neverSlow, + ) + + value := strings.Repeat("\x01", size) + + for range requests { + var got thing + + _ = gdb.Where("id = ?", value).First(&got).Error + } + + return buf.Len() + } + + small := flood(t, 128) + big := flood(t, 128*64) + + assert.Equal( + t, small, big, + "log volume tracked the size of the client's input", + ) +} + +// TestStatementError_LineIsBounded covers the branch that does log. +// A driver error is not ErrRecordNotFound, so the interpolated +// statement is written — and on an insert the interpolated value is +// still whatever the client supplied. +func TestStatementError_LineIsBounded(t *testing.T) { + t.Parallel() + + for _, h := range handlers() { + for _, f := range fills() { + t.Run(h.name+"/"+f.name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, h.make(&buf), neverSlow) + + row := thing{ID: clientValue(f.fill), Name: "a"} + + require.NoError(t, gdb.Create(&row).Error) + + buf.Reset() + + // The same primary key a second time: a UNIQUE + // constraint failure, which is an error GORM logs. + err := gdb.Create(&thing{ + ID: row.ID, Name: "b", + }).Error + require.Error(t, err) + + assert.Contains( + t, buf.String(), "sql statement failed", + ) + assertBounded(t, buf.String()) + }) + } + } +} + +// TestSucceedingStatement_LineIsBoundedOnEitherArm covers the two +// arms a statement that returns no error can take, over the same +// query, so neither can be bounded by accident of the other. +// +// - slow. Silencing GORM outright would have been the cheaper fix +// and would have cost this report, which is the one thing GORM's +// logger gave an operator that nothing else in this service does. +// - routine. The branch an operator reaches by turning the level +// down to DEBUG: every statement is reported, so every +// statement's interpolated parameters have to be bounded too. +func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) { + t.Parallel() + + // "sql statement" is a substring of "slow sql statement", so the + // routine arm carries notWant as well: Contains alone cannot tell + // the two arms apart in that direction. + arms := []struct { + name string + slow time.Duration + want string + notWant string + }{ + {"slow", alwaysSlow, "slow sql statement", ""}, + {"routine", neverSlow, "sql statement", "slow sql statement"}, + } + + for _, a := range arms { + for _, h := range handlers() { + for _, f := range fills() { + name := a.name + "/" + h.name + "/" + f.name + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, h.make(&buf), a.slow) + + var got []thing + + require.NoError(t, gdb.Where( + "name = ?", clientValue(f.fill), + ).Find(&got).Error) + + assert.Contains(t, buf.String(), a.want) + + if a.notWant != "" { + assert.NotContains( + t, buf.String(), a.notWant, + ) + } + + assertBounded(t, buf.String()) + }) + } + } + } +} + +// TestGORMOwnMessages_AreBounded covers the three printf-style +// entry points. GORM builds these itself, but nothing stops one of +// them quoting a value the statement carried. +func TestGORMOwnMessages_AreBounded(t *testing.T) { + t.Parallel() + + for _, h := range handlers() { + for _, f := range fills() { + t.Run(h.name+"/"+f.name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gl := gormlog.New(slog.New(h.make(&buf))) + ctx := context.Background() + value := clientValue(f.fill) + + gl.Info(ctx, "%s", value) + gl.Warn(ctx, "%s", value) + gl.Error(ctx, "%s", value) + + // The no-argument form, which is how GORM reports + // most of its own conditions. Reached through a + // function value so the vet printf check does not + // read the message as a format string — which is + // also why the adapter does not. + noArgs := func( + f func(context.Context, string, ...any), + msg string, + ) { + f(ctx, msg) + } + noArgs(gl.Info, value) + + assertBounded(t, buf.String()) + }) + } + } +} + +// TestLogMode_KeepsTheOperatorsLevel records that GORM's own level +// knob is deliberately inert: level belongs to LOG_LEVEL, and a +// second one inside the database layer could only disagree with it. +func TestLogMode_KeepsTheOperatorsLevel(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gl := gormlog.New(slog.New(slog.NewJSONHandler( + &buf, &slog.HandlerOptions{Level: slog.LevelDebug}, + ))) + + assert.Same(t, gl, gl.LogMode(0)) +} diff --git a/internal/handlers/gormlogbound_test.go b/internal/handlers/gormlogbound_test.go new file mode 100644 index 0000000..123eb4d --- /dev/null +++ b/internal/handlers/gormlogbound_test.go @@ -0,0 +1,462 @@ +package handlers_test + +import ( + "bytes" + "context" + "io" + "log" + "net/http" + "net/http/httptest" + "os" + "strconv" + "strings" + "sync" + "testing" + "time" + + "github.com/go-chi/chi" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gorm.io/gorm" + gormlogger "gorm.io/gorm/logger" + "sneak.berlin/go/webhooker/internal/database" + "sneak.berlin/go/webhooker/internal/handlers" + "sneak.berlin/go/webhooker/internal/middleware" +) + +// gormBoundTailMarker sits at the far end of every client-chosen value +// this file sends. Its presence in the log means the whole value +// reached the log, so a value that merely happened to be short cannot +// pass for a truncated one. +const gormBoundTailMarker = "ENDOFCLIENTVALUE" + +// gormBoundFills are the characters a client can drive through the +// receiver path segment and the login username, chosen for what a log +// handler charges for them. +// +// The bare C0 control is the one that matters: both handlers spell +// U+0001 as a six-byte escape for the one byte it costs to send, the +// widest multiplier available below U+10000 and the case a raw-byte +// budget breaks on first. GORM's default logger applies no budget at +// all, so under the mutation every one of these arrives whole. +func gormBoundFills() []struct { + name string + fill string +} { + return []struct { + name string + fill string + }{ + {"plain", "x"}, + {"quote", `"`}, + {"backslash", `\`}, + {"tab", "\t"}, + {"newline", "\n"}, + {"c0_control", "\x01"}, + {"astral_nonprintable", "\U0001000C"}, + } +} + +// syncBuf collects captured output from the goroutine draining the +// pipe. +type syncBuf struct { + mu sync.Mutex + b bytes.Buffer +} + +func (s *syncBuf) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + + return s.b.Write(p) +} + +func (s *syncBuf) String() string { + s.mu.Lock() + defer s.mu.Unlock() + + return s.b.String() +} + +func (s *syncBuf) reset() { + s.mu.Lock() + defer s.mu.Unlock() + + s.b.Reset() +} + +// stdoutCapture redirects os.Stdout for the duration of a test. +// +// internal/logger builds its handler over os.Stdout at construction +// time, so redirecting the variable before the application is built +// captures everything the service logger — and therefore the GORM +// adapter, which writes through it — emits. +type stdoutCapture struct { + buf *syncBuf + r *os.File + w *os.File + orig *os.File + done chan struct{} + seq int +} + +func captureStdout(t *testing.T) *stdoutCapture { + t.Helper() + + r, w, err := os.Pipe() + require.NoError(t, err) + + c := &stdoutCapture{ + buf: &syncBuf{}, + r: r, + w: w, + orig: os.Stdout, + done: make(chan struct{}), + } + + os.Stdout = w + + go func() { + defer close(c.done) + + _, _ = io.Copy(c.buf, r) + }() + + t.Cleanup(func() { + os.Stdout = c.orig + _ = w.Close() + + <-c.done + + _ = r.Close() + }) + + return c +} + +// drain returns everything written since the previous drain and +// clears the buffer. +// +// A sentinel is pushed through the same pipe and waited for, so the +// draining goroutine is known to have caught up before the buffer is +// read. Without it the comparison below would race the reader rather +// than measure the writers. +func (c *stdoutCapture) drain(t *testing.T) string { + t.Helper() + + c.seq++ + + sentinel := "\n<>\n" + + _, err := c.w.WriteString(sentinel) + require.NoError(t, err) + + deadline := time.Now().Add(10 * time.Second) + for !strings.Contains(c.buf.String(), sentinel) { + require.False( + t, time.Now().After(deadline), + "timed out waiting for captured output", + ) + time.Sleep(time.Millisecond) + } + + out := strings.Replace(c.buf.String(), sentinel, "", 1) + + c.buf.reset() + + return out +} + +// teeStdout writes to a buffer and to whatever os.Stdout is at the +// moment of the write. +// +// The second half is the point. GORM's package-level default logger +// resolves os.Stdout once, at package init, so a logger built over the +// variable would keep writing to the real terminal no matter what a +// test redirects. Resolving it per write puts the bytes a defaulted +// gorm.Config would cost in production into the same capture as +// everything else internal/logger emits, which is what lets the volume +// assertions below measure the whole writer set rather than one member +// of it. +type teeStdout struct { + buf *syncBuf +} + +func (w teeStdout) Write(p []byte) (int, error) { + _, _ = os.Stdout.Write(p) + + return w.buf.Write(p) +} + +// captureGORMDefault replaces GORM's package-level default logger with +// one configured exactly as GORM configures its own, writing to a +// buffer and to os.Stdout. +// +// This is the mutation detector. gormlogger.Default is what a bare +// &gorm.Config{} installs, and its config here is GORM's verbatim — +// Warn, IgnoreRecordNotFoundError false — so a reverted call site +// behaves as it would in production rather than as a test dialed it. +// With every gorm.Open in this service naming its own logger, nothing +// consults this value and the buffer stays empty; revert any one of +// the three and the interpolated SQL lands here. +func captureGORMDefault(t *testing.T) *syncBuf { + t.Helper() + + buf := &syncBuf{} + orig := gormlogger.Default + + gormlogger.Default = gormlogger.New( + log.New(teeStdout{buf: buf}, "", log.LstdFlags), + gormlogger.Config{ + SlowThreshold: 200 * time.Millisecond, + LogLevel: gormlogger.Warn, + IgnoreRecordNotFoundError: false, + Colorful: false, + }, + ) + + t.Cleanup(func() { gormlogger.Default = orig }) + + return buf +} + +// floodUnauthenticated drives reps requests at each of the two +// unauthenticated lookups that miss by design, for every fill, with a +// client-chosen value of size raw bytes. +func floodUnauthenticated( + t *testing.T, h *handlers.Handlers, size, reps int, +) int { + t.Helper() + + requests := 0 + + for _, f := range gormBoundFills() { + var b strings.Builder + + for b.Len() < size { + b.WriteString(f.fill) + } + + b.WriteString(gormBoundTailMarker) + + value := b.String() + + for range reps { + postWebhook(t, h, value) + postUnknownLogin(t, h, value) + + requests += 2 + } + } + + return requests +} + +// floodPerWebhook drives the same client-chosen values at the second +// gorm.Open site, the per-webhook database internal/database's +// WebhookDBManager opens. +// +// That site is behind authentication in production, so this is not +// part of the unauthenticated flood above and is counted separately. +// It is here because the ceiling the README states covers every +// writer, and the manager is one of them: with nothing driving it, a +// bare &gorm.Config{} could be restored at +// internal/database/webhook_db_manager.go and the whole suite would +// stay green. +func floodPerWebhook( + t *testing.T, mgr *database.WebhookDBManager, size, reps int, +) int { + t.Helper() + + requests := 0 + + for _, f := range gormBoundFills() { + var b strings.Builder + + for b.Len() < size { + b.WriteString(f.fill) + } + + b.WriteString(gormBoundTailMarker) + + value := b.String() + + db, err := mgr.GetDB("pin-" + f.name) + require.NoError(t, err) + + for range reps { + var got database.Event + + err = db.Where("id = ?", value).First(&got).Error + require.ErrorIs(t, err, gorm.ErrRecordNotFound) + + requests++ + } + } + + return requests +} + +// postWebhook drives the receiver with an invented entrypoint path. +// The route pattern matches any single segment, so every byte of the +// value is the client's, and the lookup behind it misses by design. +func postWebhook( + t *testing.T, h *handlers.Handlers, entrypoint string, +) { + t.Helper() + + req := httptest.NewRequestWithContext( + context.Background(), http.MethodPost, "/webhook/x", + strings.NewReader("{}"), + ) + + rctx := chi.NewRouteContext() + rctx.URLParams.Add("uuid", entrypoint) + + req = req.WithContext(context.WithValue( + req.Context(), chi.RouteCtxKey, rctx, + )) + + w := httptest.NewRecorder() + h.HandleWebhook().ServeHTTP(w, req) + + require.Equal(t, http.StatusNotFound, w.Code) +} + +// postUnknownLogin submits the login form with an unknown username, +// through the postLogin helper in logbound_test.go. The field is +// bounded only by the 1 MB body cap, and the lookup behind it misses +// by design. +func postUnknownLogin( + t *testing.T, h *handlers.Handlers, username string, +) { + t.Helper() + + // 401 while the client still has failure budget against this + // username, 429 once the login guard has taken it away. Both + // outcomes sit behind the user lookup, which is the query this + // test is here to drive. + require.Contains( + t, + []int{http.StatusUnauthorized, http.StatusTooManyRequests}, + postLogin(t, h, username), + ) +} + +// assertFloodBounded holds every captured line to the stated ceiling +// and proves nothing carried a whole client value. +func assertFloodBounded(t *testing.T, label, out string) { + t.Helper() + + assert.NotContains( + t, out, gormBoundTailMarker, + "%s: the far end of a client-chosen value reached the "+ + "log, so nothing truncated it", label, + ) + + for line := range strings.SplitSeq( + strings.TrimRight(out, "\n"), "\n", + ) { + if line == "" { + continue + } + + assert.LessOrEqual( + t, len(line), middleware.MaxAccessLogLineBytes, + "%s: log line exceeded its bound: %s", + label, line[:min(len(line), 300)], + ) + } +} + +// TestFlood_NoWriterGrowsWithTheInput is the definition of done for +// the GORM logger defect, stated over every writer at once, for two of +// this service's three gorm.Open sites: the main database behind the +// two unauthenticated lookups, and the per-webhook database the +// WebhookDBManager opens. The third, the archive writer, is pinned in +// internal/delivery, where its type lives. +// +// What each assertion is worth, since two of the three would pass +// against a service that had never been fixed if the capture were set +// up differently: +// +// - The gormDefault check is the sharp one. It fires the moment any +// gorm.Open in this service goes back to a bare &gorm.Config{}. +// - The volume and per-line checks bite only because the replaced +// default logger tees into os.Stdout, so a reverted call site +// shows up in the same capture as everything internal/logger +// writes — the way it would in production. Without that tee both +// were vacuous: at INFO the two handler misses log at DEBUG and +// the adapter drops the record-not-found, so the capture holds +// nothing but fixed-string warnings. +// +// The level is left where newTestApp leaves it, at INFO: the level an +// operator runs at by default, and the one the defect was visible at. +// The handlers' own miss lines sit at DEBUG and spend the same +// logfield budget as everything else, so they are not what makes +// either assertion above bite at any level. +// +// It is deliberately not parallel: it redirects os.Stdout and replaces +// gormlogger.Default, both of which are process-global. Go runs every +// non-parallel top-level test to completion before it resumes the +// parallel ones, so nothing else in this package is running while the +// capture is installed. +// +//nolint:paralleltest // Deliberately sequential; see above. +func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) { + const ( + smallBytes = 128 + bigBytes = 8 << 10 + reps = 5 + ) + + gormDefault := captureGORMDefault(t) + capture := captureStdout(t) + + var ( + h *handlers.Handlers + mgr *database.WebhookDBManager + ) + + app := newTestApp(t, &h, &mgr) + app.RequireStart() + + t.Cleanup(app.RequireStop) + + // Startup chatter is not what this test measures. + capture.drain(t) + + floodUnauthenticated(t, h, smallBytes, reps) + floodPerWebhook(t, mgr, smallBytes, reps) + + small := capture.drain(t) + + requests := floodUnauthenticated(t, h, bigBytes, reps) + requests += floodPerWebhook(t, mgr, bigBytes, reps) + big := capture.drain(t) + + assertFloodBounded(t, "small flood", small) + assertFloodBounded(t, "big flood", big) + + // GORM's default logger is what the defect was. Nothing in this + // service may reach it. + got := gormDefault.String() + assert.Empty( + t, got, + "GORM's default logger wrote %d bytes; the first of them: %s", + len(got), got[:min(len(got), 300)], + ) + + // The same flood, with 64 times the client-chosen input, must not + // buy 64 times the log. A few bytes of slack covers a latency + // field changing width; the input grew by roughly half a megabyte. + const slackPerRequest = 64 + + assert.LessOrEqual( + t, len(big), len(small)+slackPerRequest*requests, + "log volume tracked the size of the client's input: "+ + "%d bytes at %d bytes of input per request, %d bytes "+ + "at %d", + len(small), smallBytes, len(big), bigBytes, + ) +} diff --git a/internal/logfield/logfield_test.go b/internal/logfield/logfield_test.go index a75e475..8372f00 100644 --- a/internal/logfield/logfield_test.go +++ b/internal/logfield/logfield_test.go @@ -219,3 +219,103 @@ func TestTruncate_DropsInvalidUTF8(t *testing.T) { assert.Equal(t, "abc", got) assert.True(t, utf8.ValidString(got)) } + +// encodedCost is what a whole string costs on a line, by the same +// accounting Truncate spends its budget with. +func encodedCost(s string) int { + total := 0 + for _, r := range s { + total += logfield.EncodedBytes(r) + } + + return total +} + +// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom +// version of TestTruncate_SpendsNoMoreThanTheBudget above, and of the +// line-length assertions elsewhere. +// +// A line ceiling has slack in it by construction, and a LessOrEqual +// against the budget cannot tell a budget spent exactly from one +// spent under. Here the budget is checked against exactly what it +// bought: a value built from a single rune must keep exactly +// MaxBytes/EncodedBytes(r) of them, with nothing spare. A raw-byte +// budget — cost := utf8.RuneLen(r) — fails this for every rune the +// handlers escape. +func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) { + t.Parallel() + + for name, r := range map[string]rune{ + "plain": 'x', + "quote": '"', + "backslash": '\\', + "tab": '\t', + "newline": '\n', + "carriage_return": '\r', + "c0_control": '\x01', + "del": '\x7f', + // U+2028 LINE SEPARATOR, which only the JSON handler + // escapes. + "line_separator": '
', + "astral_nonprintable": '\U0001000C', + "multibyte_printable": 'é', + // U+20AC, a three-byte printable rune, charged its own + // UTF-8 bytes rather than an escape. + "three_byte_printable": '€', + "emoji_printable": '\U0001F600', + } { + t.Run(name, func(t *testing.T) { + t.Parallel() + + cost := logfield.EncodedBytes(r) + want := logfield.MaxBytes / cost + + // Far past the budget under either accounting. + in := strings.Repeat(string(r), logfield.MaxBytes*2) + + got := logfield.Truncate(in, logfield.MaxBytes) + + require.True( + t, strings.HasSuffix( + got, logfield.TruncationMarker, + ), + "a value past the budget must be marked", + ) + + kept := strings.TrimSuffix( + got, logfield.TruncationMarker, + ) + + assert.Equal( + t, want, utf8.RuneCountInString(kept), + "budget bought the wrong number of runes at "+ + "%d encoded bytes each", cost, + ) + assert.LessOrEqual( + t, encodedCost(kept), logfield.MaxBytes, + ) + }) + } +} + +// TestTruncate_NeverSplitsARune covers a cut landing inside a +// multi-byte encoding rather than between two of them. +func TestTruncate_NeverSplitsARune(t *testing.T) { + t.Parallel() + + // U+20AC, three bytes and printable, so a small budget lands + // inside an encoding rather than on a boundary. + in := strings.Repeat("€", logfield.MaxBytes) + + for b := 1; b <= 16; b++ { + got := strings.TrimSuffix( + logfield.Truncate(in, b), logfield.TruncationMarker, + ) + + assert.True( + t, utf8.ValidString(got), + "budget %d produced invalid UTF-8", b, + ) + assert.LessOrEqual(t, encodedCost(got), b) + } +} diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index eef3340..dcc944e 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -67,6 +67,9 @@ const ( // ---- // 2087 // + // The 512 is logfield.MaxBytes; the 11 is the truncation marker, + // charged on top of each budget rather than inside it. + // // The fixed portion is the JSON punctuation, the field names, the // level and the message, both timestamps at their longest, an IPv6 // remoteIP with a zone, a three-digit status and a full-width int64 @@ -104,6 +107,17 @@ const ( // a caller on a parameterised route would supply, which is the // only way those caps can be pinned at all. // + // One writer in that set is not a handler's own slog call. The + // GORM adapter in internal/gormlog logs the statement with the + // client-chosen parameter already interpolated into it, which on + // the receiver and login lookups is exactly the value the budgets + // above exist for. Its widest line spends two logfield.MaxBytes + // budgets — the statement and the driver error — against a fixed + // portion smaller than this one's, and + // internal/gormlog/gormlog_test.go asserts every line it emits + // against this constant directly rather than leaving it as + // arithmetic. + // // What it does NOT cover, so that the figure above is not read as // more than it is: // @@ -119,10 +133,16 @@ const ( // - The "log" delivery target, which exists to write the whole // inbound event to the log. Deliberate; see // internal/delivery/target_log.go. - // - GORM's default logger, which prints the interpolated SQL to - // stdout on a record-not-found and so is unbounded on the - // receiver and login lookups. NOT deliberate; filed as - // https://git.eeqj.de/sneak/webhooker/issues/178. + // - The widest line the service can write, which is neither an + // access log line nor client-chosen. A handler panic arrives + // through net/http's nil ErrorLog as one record carrying a + // whole goroutine stack, above this figure — measured at + // roughly 2,770 bytes. The exact width is not an invariant: it + // moves with the goroutine number and with the source paths + // baked into the stack. That it exceeds this ceiling does not + // move. The value is the runtime's, not a client's; see + // README.md and + // https://git.eeqj.de/sneak/webhooker/issues/187. MaxAccessLogLineBytes = 2560 )