Compare commits
1 Commits
next
...
ce36f430fb
| Author | SHA1 | Date | |
|---|---|---|---|
| ce36f430fb |
53
README.md
53
README.md
@@ -1113,6 +1113,55 @@ 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
|
||||
at all: 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. 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.
|
||||
- Three writers that do not go through `internal/logger` at all, all
|
||||
of them on standard error. `net/http` builds its server with a nil
|
||||
`ErrorLog`, so its own faults — a handler panic and its stack, a
|
||||
superfluous `WriteHeader` — go to the `log` package's default
|
||||
logger. `fx` prints the dependency graph and the lifecycle hooks
|
||||
through its console logger at startup and shutdown. The Go runtime
|
||||
writes a panic or a fatal error itself. None of the three carries a
|
||||
client-chosen value at a client-chosen length: the three `panic`
|
||||
calls in this service are invariant guards over constants and over
|
||||
`crypto/rand`.
|
||||
|
||||
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
|
||||
@@ -1351,6 +1400,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
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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()
|
||||
|
||||
|
||||
@@ -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()
|
||||
|
||||
9
internal/gormlog/export_test.go
Normal file
9
internal/gormlog/export_test.go
Normal file
@@ -0,0 +1,9 @@
|
||||
package gormlog
|
||||
|
||||
import "time"
|
||||
|
||||
// ExportSetSlowThreshold overrides the slow-statement threshold so a
|
||||
// test can drive the slow path without sleeping. Tests only.
|
||||
func (l *Logger) ExportSetSlowThreshold(d time.Duration) {
|
||||
l.slowThreshold = d
|
||||
}
|
||||
159
internal/gormlog/gormlog.go
Normal file
159
internal/gormlog/gormlog.go
Normal file
@@ -0,0 +1,159 @@
|
||||
// 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.
|
||||
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 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.
|
||||
return
|
||||
|
||||
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 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,
|
||||
)
|
||||
}
|
||||
388
internal/gormlog/gormlog_test.go
Normal file
388
internal/gormlog/gormlog_test.go
Normal file
@@ -0,0 +1,388 @@
|
||||
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
|
||||
}
|
||||
|
||||
// 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.
|
||||
func openDB(
|
||||
t *testing.T, buf *bytes.Buffer, h slog.Handler,
|
||||
) (*gorm.DB, *gormlog.Logger) {
|
||||
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.New(slog.New(h))
|
||||
|
||||
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, gl
|
||||
}
|
||||
|
||||
// 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))
|
||||
|
||||
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",
|
||||
)
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// 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,
|
||||
}),
|
||||
)
|
||||
|
||||
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))
|
||||
|
||||
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())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestSlowStatement_IsLoggedAndBounded proves the slow-statement
|
||||
// report survived the fix. Silencing GORM outright would have been
|
||||
// the cheaper change and would have cost this, which is the one thing
|
||||
// GORM's logger reports that nothing else in the service does.
|
||||
func TestSlowStatement_IsLoggedAndBounded(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, gl := openDB(t, &buf, h.make(&buf))
|
||||
|
||||
// Every statement counts as slow, so the branch is
|
||||
// reached without making the test wait for it.
|
||||
gl.ExportSetSlowThreshold(time.Nanosecond)
|
||||
|
||||
var got []thing
|
||||
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
|
||||
assert.Contains(
|
||||
t, buf.String(), "slow sql statement",
|
||||
)
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestDebugStatement_LineIsBounded covers the branch an operator
|
||||
// reaches by turning the level down: every statement is reported, so
|
||||
// every statement's interpolated parameters have to be bounded too.
|
||||
func TestDebugStatement_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))
|
||||
|
||||
var got []thing
|
||||
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
|
||||
assert.Contains(t, buf.String(), "sql statement")
|
||||
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))
|
||||
}
|
||||
381
internal/handlers/gormlogbound_test.go
Normal file
381
internal/handlers/gormlogbound_test.go
Normal file
@@ -0,0 +1,381 @@
|
||||
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"
|
||||
gormlogger "gorm.io/gorm/logger"
|
||||
"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<<drain-" + strconv.Itoa(c.seq) + ">>\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
|
||||
}
|
||||
|
||||
// captureGORMDefault points GORM's package-level default logger at a
|
||||
// buffer for the duration of the test.
|
||||
//
|
||||
// This is the mutation detector. gormlogger.Default is what a bare
|
||||
// &gorm.Config{} installs, and it holds an *os.File captured at
|
||||
// package init, so redirecting os.Stdout does not reach it — it has
|
||||
// to be replaced. With every gorm.Open in this service naming its own
|
||||
// logger, nothing consults this value and the buffer stays empty;
|
||||
// revert any one of them 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(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
|
||||
}
|
||||
|
||||
// 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)],
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
// TestUnauthenticatedFlood_NoWriterGrowsWithTheInput is the
|
||||
// definition of done for the GORM logger defect, stated over both
|
||||
// writers at once.
|
||||
//
|
||||
// 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 TestUnauthenticatedFlood_NoWriterGrowsWithTheInput(
|
||||
t *testing.T,
|
||||
) {
|
||||
const (
|
||||
smallBytes = 128
|
||||
bigBytes = 8 << 10
|
||||
reps = 5
|
||||
)
|
||||
|
||||
gormDefault := captureGORMDefault(t)
|
||||
capture := captureStdout(t)
|
||||
|
||||
var h *handlers.Handlers
|
||||
|
||||
app := newTestApp(t, &h)
|
||||
app.RequireStart()
|
||||
|
||||
t.Cleanup(app.RequireStop)
|
||||
|
||||
// Startup chatter is not what this test measures.
|
||||
capture.drain(t)
|
||||
|
||||
floodUnauthenticated(t, h, smallBytes, reps)
|
||||
|
||||
small := capture.drain(t)
|
||||
|
||||
requests := floodUnauthenticated(t, h, 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,
|
||||
)
|
||||
}
|
||||
140
internal/logfield/logfield.go
Normal file
140
internal/logfield/logfield.go
Normal file
@@ -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
|
||||
}
|
||||
202
internal/logfield/logfield_test.go
Normal file
202
internal/logfield/logfield_test.go
Normal file
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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,22 @@ 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, so the
|
||||
// figure is also the ceiling on the other writer that carries
|
||||
// client-chosen text: 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.
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
@@ -174,114 +169,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 +262,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),
|
||||
|
||||
Reference in New Issue
Block a user