diff --git a/README.md b/README.md index d1edf4b..c484bb5 100644 --- a/README.md +++ b/README.md @@ -1152,6 +1152,80 @@ that the rate is not bounded by the limits above on every route: `/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there the multiplier is whatever the deployment will serve. +That figure is now the ceiling on a second writer 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 512-byte +encoded budget (`internal/logfield`). 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`, without the SQL. +Slow statements are kept — at `WARN`, above the same 200 ms threshold +GORM used, with the statement bounded — because that report is the one +thing GORM's logger gave an operator that nothing else here does, and +a statement that both missed and ran slow is still reported as slow. +The adapter orders those cases exactly as GORM's own `Trace` orders +them, so dropping the miss costs an operator no report that GORM's +`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; +`internal/gormlog/gormlog_test.go` asserts each line against +`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic. + +**What the ceiling does not cover.** It is a per-line bound on the +access log and on GORM's statement logging, not a bound on every line +this service writes. The exceptions are named here because a bound +that is true of one writer and silently false of another is worse than +no stated bound at all. + +- Other `slog` calls that reach a client-chosen value — the + `MaxBodySize` rejection, the CSRF failure, the receiver rate-limit + rejection, and the two lookup misses above — still log the request + path or the submitted username untruncated. +- The `log` delivery target (`internal/delivery/target_log.go`) writes + the entire inbound event, headers and body, to the log. That is what + the target is for. Each line is bounded per event by the 1 MB + receiver body cap, and it costs nothing unless an authenticated + operator creates a target of that type. +- 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, measured at 2,772 bytes against the ceiling's 2,560. 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 + https://git.eeqj.de/sneak/webhooker/issues/187. + Every limiter here — receiver, login, and password change — identifies the client the same way, through one shared key function: the connection's own address, unless the peer is listed in @@ -1390,6 +1464,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..c2408c8 --- /dev/null +++ b/internal/gormlog/gormlog_test.go @@ -0,0 +1,425 @@ +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() + + arms := []struct { + name string + slow time.Duration + want string + }{ + {"slow", alwaysSlow, "slow sql statement"}, + {"routine", neverSlow, "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) + 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..97a7bc4 --- /dev/null +++ b/internal/handlers/gormlogbound_test.go @@ -0,0 +1,477 @@ +package handlers_test + +import ( + "bytes" + "context" + "io" + "log" + "net/http" + "net/http/httptest" + "net/url" + "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) + postLogin(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) +} + +// postLogin submits the login form with an unknown username. The +// field is bounded only by the 1 MB body cap, and the lookup behind +// it misses by design. +func postLogin( + t *testing.T, h *handlers.Handlers, username string, +) { + t.Helper() + + form := url.Values{} + form.Set("username", username) + form.Set("password", "not-the-password") + + req := httptest.NewRequestWithContext( + context.Background(), http.MethodPost, "/pages/login", + strings.NewReader(form.Encode()), + ) + req.Header.Set( + "Content-Type", "application/x-www-form-urlencoded", + ) + + w := httptest.NewRecorder() + h.HandleLoginSubmit().ServeHTTP(w, req) + + // 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}, + w.Code, + ) +} + +// 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, deliberately. +// At DEBUG the handlers' own miss lines log the client-chosen +// entrypoint and username untruncated — the first carve-out in the +// README's ceiling section, and https://git.eeqj.de/sneak/webhooker/issues/176's +// to fix, not this one's. +// +// 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.go b/internal/logfield/logfield.go new file mode 100644 index 0000000..5eab11d --- /dev/null +++ b/internal/logfield/logfield.go @@ -0,0 +1,140 @@ +// Package logfield bounds a client-supplied value against what the log +// handler will actually emit for it, so a line's size is set by this +// service rather than by the client that provoked it. +// +// It lives outside internal/middleware because more than one writer +// needs it: the access log, and the GORM adapter in internal/gormlog, +// which logs SQL with the client-chosen parameters interpolated into +// it. One budget, one implementation. +package logfield + +import ( + "strings" + "unicode" + "unicode/utf8" +) + +const ( + // MaxBytes is the default budget for a field whose value the + // client supplies outright. It is spent in ENCODED bytes (see + // Truncate), so 512 still holds a real browser's User-Agent whole + // — those are plain ASCII, which encodes one byte for one — while + // a value built from characters the encoder escapes keeps a + // shorter prefix. That is the intended trade: 500 quotation marks + // are not a debugging asset. + MaxBytes = 512 + + // truncationMarker is appended to any value Truncate cut, so a + // short value and a truncated one cannot be confused. It is + // charged on top of the budget, not inside it. + truncationMarker = "[truncated]" +) + +// EncodedBytes is what r costs on the line once the log handler has +// escaped it, taking the worse of the two handlers internal/logger +// configures. +// +// slog's JSON handler escapes quote, backslash, newline, carriage +// return and tab to two bytes each, and every other C0 control plus +// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it +// passes every other rune through as its own UTF-8. Its text handler +// quotes with strconv.Quote, which spells a non-printable rune below +// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten +// bytes, not six. The text handler is therefore the worse of the two +// for every non-printable rune, and by four bytes apiece for the +// 955,086 unassigned, private-use and format code points on planes 1 +// to 16. +// +// Charging ten there is what makes the stated per-line ceiling hold +// for the tty handler as well: U+1000C encodes as F0 90 80 8C, every +// byte >= 0x80, which httpguts.ValidHeaderFieldValue accepts and +// net/textproto does not strip, so a header can be filled with them. +// +// Both handlers pass printable runes through as their own UTF-8, so +// unicode.IsPrint separates the escaped cases from the plain ones for +// either handler. +func EncodedBytes(r rune) int { + const ( + // A backslash and the character itself. + shortEscapeBytes = 2 + // \uXXXX, which is also the width of \u00XX. + escapedRuneBytes = 6 + // \UXXXXXXXX, strconv.Quote's spelling of a non-printable + // rune outside the basic multilingual plane. + escapedAstralRuneBytes = 10 + // The first code point strconv.Quote spells with \U. + firstAstralRune = 0x10000 + ) + + switch { + case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t': + return shortEscapeBytes + case !unicode.IsPrint(r) && r >= firstAstralRune: + return escapedAstralRuneBytes + case !unicode.IsPrint(r): + return escapedRuneBytes + default: + return utf8.RuneLen(r) + } +} + +// Truncate caps s at maxBytes of ENCODED output, marking the value +// when it cuts. +// +// Budgeting raw bytes would not bound the line. Escaping only ever +// grows a value, so a raw budget spent on characters the encoder +// escapes buys a field several times its nominal size — and the line +// is the thing an operator is told to multiply by their request rate. +// Charging each rune what it will actually cost is what makes the +// stated ceiling true rather than merely larger. The visible +// consequence is that an escape-heavy value keeps a shorter prefix +// than a plain one, which is the correct trade. +// +// The result is always valid UTF-8. A cut on a byte boundary can split +// a multi-byte rune, and a header — or a SQL literal — can carry bytes +// that were never valid UTF-8 to begin with; both are dropped rather +// than kept, since an encoder would otherwise spend six bytes +// replacing each one. +func Truncate(s string, maxBytes int) string { + // No rune encodes to fewer bytes than it occupies, so nothing past + // maxBytes raw can fit the budget. Slicing first bounds the scan + // below to the budget rather than to the size of the value the + // client sent. + window, cut := s, false + if len(window) > maxBytes { + window, cut = window[:maxBytes], true + } + + var ( + kept strings.Builder + spent int + ) + + for i := 0; i < len(window); { + r, size := utf8.DecodeRuneInString(window[i:]) + if r == utf8.RuneError && size == 1 { + i += size + + continue + } + + cost := EncodedBytes(r) + if spent+cost > maxBytes { + cut = true + + break + } + + spent += cost + + kept.WriteString(window[i : i+size]) + + i += size + } + + if !cut { + return kept.String() + } + + return kept.String() + truncationMarker +} diff --git a/internal/logfield/logfield_test.go b/internal/logfield/logfield_test.go new file mode 100644 index 0000000..580fc3a --- /dev/null +++ b/internal/logfield/logfield_test.go @@ -0,0 +1,202 @@ +package logfield_test + +import ( + "bytes" + "log/slog" + "strings" + "testing" + "unicode/utf8" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/logfield" +) + +// 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 the line-length assertions elsewhere. +// +// A line ceiling has slack in it by construction, so a line-level +// assertion only catches a raw-byte budget for the fills with the +// widest multiplier. 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, for every rune, with nothing +// spare. +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": '', + "del": '', + "line_separator": '
', + "astral_nonprintable": '\U0001000C', + "multibyte_printable": 'é', + "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) + + assert.True( + t, strings.HasSuffix(got, "[truncated]"), + "a value past the budget must be marked", + ) + + kept := strings.TrimSuffix(got, "[truncated]") + + 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, + ) + }) + } +} + +// TestEncodedBytes_CoversWhatTheHandlersActuallyEmit measures the +// charge against what slog really writes rather than against a +// reading of its source, over both handlers internal/logger can +// install. An undercharged rune fails here rather than quietly +// falsifying every stated line ceiling. +func TestEncodedBytes_CoversWhatTheHandlersActuallyEmit(t *testing.T) { + t.Parallel() + + emitted := func(h func(*bytes.Buffer) slog.Handler, r rune) int { + var withValue, withoutValue bytes.Buffer + + slog.New(h(&withValue)).Info("m", "v", string(r)) + slog.New(h(&withoutValue)).Info("m", "v", "") + + return withValue.Len() - withoutValue.Len() + } + + jsonHandler := func(b *bytes.Buffer) slog.Handler { + return slog.NewJSONHandler(b, &slog.HandlerOptions{ + ReplaceAttr: dropTime, + }) + } + textHandler := func(b *bytes.Buffer) slog.Handler { + return slog.NewTextHandler(b, &slog.HandlerOptions{ + ReplaceAttr: dropTime, + }) + } + + // Every code point below U+0800 densely — which covers all of C0, + // DEL, C1 and the two-byte range — plus the separators only the + // JSON handler escapes, plus a stratified walk across the rest of + // the assigned space and into the astral planes. + var runes []rune + + for r := rune(1); r < 0x800; r++ { + runes = append(runes, r) + } + + runes = append( + runes, + '
', // LINE SEPARATOR, escaped only by the JSON handler + '
', // PARAGRAPH SEPARATOR, likewise + rune(0xFEFF), // ZERO WIDTH NO-BREAK SPACE + rune(0xFFFD), // REPLACEMENT CHARACTER + ) + + for r := rune(0x800); r <= 0x10FFFF; r += 0x1D1 { + runes = append(runes, r) + } + + for _, r := range runes { + if !utf8.ValidRune(r) { + continue + } + + charged := logfield.EncodedBytes(r) + + require.LessOrEqual( + t, emitted(jsonHandler, r), charged, + "json handler spends more than U+%04X is charged", r, + ) + require.LessOrEqual( + t, emitted(textHandler, r), charged, + "text handler spends more than U+%04X is charged", r, + ) + } +} + +func dropTime(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + + return a +} + +// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a +// value that fits is returned untouched, so a reader can tell a short +// value from a cut one. +func TestTruncate_LeavesShortValuesAlone(t *testing.T) { + t.Parallel() + + const in = "Mozilla/5.0 (X11; Linux x86_64)" + + assert.Equal(t, in, logfield.Truncate(in, logfield.MaxBytes)) +} + +// TestTruncate_DropsInvalidUTF8 covers a value that was never valid +// UTF-8 — a SQL parameter or a header can carry one. Replacing each +// bad byte would cost six encoded bytes apiece, so they are dropped. +func TestTruncate_DropsInvalidUTF8(t *testing.T) { + t.Parallel() + + got := logfield.Truncate("a\xffb\xfec", logfield.MaxBytes) + + assert.Equal(t, "abc", got) + assert.True(t, utf8.ValidString(got)) +} + +// TestTruncate_NeverSplitsARune covers a cut landing inside a +// multi-byte encoding. +func TestTruncate_NeverSplitsARune(t *testing.T) { + t.Parallel() + + // A three-byte printable rune, so a small budget lands inside the + // encoding rather than between two of them. + in := strings.Repeat("€", logfield.MaxBytes) + + for budget := 1; budget <= 16; budget++ { + got := strings.TrimSuffix( + logfield.Truncate(in, budget), "[truncated]", + ) + + assert.True( + t, utf8.ValidString(got), + "budget %d produced invalid UTF-8", budget, + ) + assert.LessOrEqual(t, encodedCost(got), budget) + } +} diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 56af5bc..e9da550 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -6,11 +6,8 @@ import ( "log/slog" "net" "net/http" - "strings" "sync" "time" - "unicode" - "unicode/utf8" basicauth "github.com/99designs/basicauth-go" "github.com/go-chi/chi" @@ -22,6 +19,7 @@ import ( "go.uber.org/fx" "sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/globals" + "sneak.berlin/go/webhooker/internal/logfield" "sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/session" ) @@ -44,16 +42,6 @@ const ( // pick the size of the line it writes. redactedQuery = "?(redacted)" - // maxLogFieldBytes bounds each access log field whose value the - // client supplies outright: the URL, the User-Agent and the - // Referer. The budget is spent in ENCODED bytes (see - // truncateLogField), so 512 still holds a real browser's User-Agent - // whole — those are plain ASCII, which encodes one byte for one — - // while a value built from characters the encoder escapes keeps a - // shorter prefix. That is the intended trade: 500 quotation marks - // are not a debugging asset. - maxLogFieldBytes = 512 - // maxLogRequestIDBytes bounds the request id, which is also // client-supplied: chi's RequestID middleware passes an inbound // X-Request-Id header through verbatim. Its generated form is an @@ -66,15 +54,10 @@ const ( // is half this. maxLogMethodBytes = 32 - // truncationMarker is appended to any field the access log cut, so - // a short value and a truncated one cannot be confused. It is - // charged on top of the budget, not inside it. - truncationMarker = "[truncated]" - // MaxAccessLogLineBytes is the ceiling on one JSON access log line, // and the number an operator multiplies by the request rate to size // log storage. It is not an observation of a sample: it is the sum - // of the budgets above, each of which truncateLogField enforces in + // of the field budgets, each of which logfield.Truncate enforces in // ENCODED bytes, plus the part of the line no client can influence. // // url, useragent, referer 3*(512+11) = 1569 @@ -84,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 @@ -91,13 +77,29 @@ const ( // than sitting on the arithmetic. // // The tty text handler in internal/logger is covered by the same - // figure. encodedLogFieldBytes charges every rune at least what + // figure. logfield.EncodedBytes charges every rune at least what // the wider of the two handlers emits for it — including the ten // bytes strconv.Quote spends on a non-printable rune at or above // U+10000, which is four more than the JSON handler ever spends — // so each budget bounds the encoded field under either handler. // The text handler's fixed portion is 286, the smaller of the two, // which puts its worst case at 2037. + // + // The access log is the widest line this service writes that + // carries client-chosen text, so the figure is also the ceiling on + // the other writer that does: the GORM adapter in + // internal/gormlog, whose widest line spends two logfield.MaxBytes + // budgets (the interpolated SQL and the driver error) against a + // fixed portion smaller than this one's. + // internal/gormlog/gormlog_test.go asserts that against this + // constant directly rather than leaving it as arithmetic. + // + // It is not the widest line the service can write. A handler panic + // arrives through net/http's nil ErrorLog as one record carrying a + // whole goroutine stack, measured at 2,772 bytes. That value is + // the runtime's, not a client's, so it is a carve-out this ceiling + // states rather than covers; see README.md and + // https://git.eeqj.de/sneak/webhooker/issues/187. MaxAccessLogLineBytes = 2560 ) @@ -174,114 +176,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { lrw.ResponseWriter.WriteHeader(code) } -// encodedLogFieldBytes is what r costs on the line once the log -// handler has escaped it, taking the worse of the two handlers -// internal/logger configures. -// -// slog's JSON handler escapes quote, backslash, newline, carriage -// return and tab to two bytes each, and every other C0 control plus -// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it -// passes every other rune through as its own UTF-8. Its text handler -// quotes with strconv.Quote, which spells a non-printable rune below -// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten -// bytes, not six. The text handler is therefore the worse of the two -// for every non-printable rune, and by four bytes apiece for the -// 955,086 unassigned, private-use and format code points on planes 1 -// to 16. -// -// Charging ten there is what makes MaxAccessLogLineBytes hold for the -// tty handler as well: U+1000C encodes as F0 90 80 8C, every byte -// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and -// net/textproto does not strip, so a header can be filled with them. -// -// Both handlers pass printable runes through as their own UTF-8, so -// unicode.IsPrint separates the escaped cases from the plain ones for -// either handler. -func encodedLogFieldBytes(r rune) int { - const ( - // A backslash and the character itself. - shortEscapeBytes = 2 - // \uXXXX, which is also the width of \u00XX. - escapedRuneBytes = 6 - // \UXXXXXXXX, strconv.Quote's spelling of a non-printable - // rune outside the basic multilingual plane. - escapedAstralRuneBytes = 10 - // The first code point strconv.Quote spells with \U. - firstAstralRune = 0x10000 - ) - - switch { - case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t': - return shortEscapeBytes - case !unicode.IsPrint(r) && r >= firstAstralRune: - return escapedAstralRuneBytes - case !unicode.IsPrint(r): - return escapedRuneBytes - default: - return utf8.RuneLen(r) - } -} - -// truncateLogField caps s at maxBytes of ENCODED output, marking the -// value when it cuts. -// -// Budgeting raw bytes would not bound the line. Escaping only ever -// grows a value, so a raw budget spent on characters the encoder -// escapes buys a field several times its nominal size — and the line -// is the thing an operator is told to multiply by their request rate. -// Charging each rune what it will actually cost is what makes -// MaxAccessLogLineBytes true rather than merely larger. The visible -// consequence is that an escape-heavy value keeps a shorter prefix -// than a plain one, which is the correct trade. -// -// The result is always valid UTF-8. A cut on a byte boundary can split -// a multi-byte rune, and a header can carry bytes that were never -// valid UTF-8 to begin with; both are dropped rather than kept, since -// an encoder would otherwise spend six bytes replacing each one. -func truncateLogField(s string, maxBytes int) string { - // No rune encodes to fewer bytes than it occupies, so nothing past - // maxBytes raw can fit the budget. Slicing first bounds the scan - // below to the budget rather than to the size of the header the - // client sent. - window, cut := s, false - if len(window) > maxBytes { - window, cut = window[:maxBytes], true - } - - var ( - kept strings.Builder - spent int - ) - - for i := 0; i < len(window); { - r, size := utf8.DecodeRuneInString(window[i:]) - if r == utf8.RuneError && size == 1 { - i += size - - continue - } - - cost := encodedLogFieldBytes(r) - if spent+cost > maxBytes { - cut = true - - break - } - - spent += cost - - kept.WriteString(window[i : i+size]) - - i += size - } - - if !cut { - return kept.String() - } - - return kept.String() + truncationMarker -} - // concreteLogURL renders the request's own URL for the access log // branches that keep it, with the query string replaced by a fixed // marker. @@ -375,21 +269,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { // line does not track the size of the request. s.log.Info("http request", "request_start", start, - "method", truncateLogField( + "method", logfield.Truncate( r.Method, maxLogMethodBytes, ), - "url", truncateLogField( + "url", logfield.Truncate( accessLogURL(r, lrw.statusCode), - maxLogFieldBytes, + logfield.MaxBytes, ), - "useragent", truncateLogField( - r.UserAgent(), maxLogFieldBytes, + "useragent", logfield.Truncate( + r.UserAgent(), logfield.MaxBytes, ), - "request_id", truncateLogField( + "request_id", logfield.Truncate( requestID, maxLogRequestIDBytes, ), - "referer", truncateLogField( - r.Referer(), maxLogFieldBytes, + "referer", logfield.Truncate( + r.Referer(), logfield.MaxBytes, ), "proto", r.Proto, "remoteIP", ipFromHostPort(r.RemoteAddr),