Compare commits

2 Commits

Author SHA1 Message Date
f9d9a2c8d7 Route GORM's logger through slog and bound it (closes #178)
All checks were successful
check / check (push) Successful in 2m50s
GORM's default logger printed the fully interpolated SQL to standard
output on every statement that returned an error, including a plain
record-not-found. On /webhook/{uuid} and on the login form the
interpolated parameter is client-chosen and unbounded, so an
unauthenticated client sized the operator's log, one line per request,
at no level the operator could turn down.

Every gorm.Open in the service now installs internal/gormlog, a
gormlogger.Interface over the service's *slog.Logger. Its lines take
the level the operator set and the handler internal/logger selected; a
record-not-found is not logged as an error, since it is the expected
outcome on both of those paths and each handler already records its
own miss at DEBUG without the SQL; slow statements are kept at WARN
above the same 200ms threshold GORM used; and every value it emits is
spent through an encoded-byte budget.

Trace orders its cases exactly as GORM's own Trace orders them --
error-that-is-not-a-miss, then slow, then routine -- so a statement
that both missed and ran slow is still reported as slow. Ordering the
drop first would have made this adapter strictly less observant than
the IgnoreRecordNotFoundError option it was chosen over, on the two
lookups the issue is about, and a miss is the statement most likely to
be slow.

That budget is internal/middleware's truncateLogField, moved to a new
internal/logfield package now that a second writer needs it. The move
is unchanged logic. MaxAccessLogLineBytes bounds a GORM line too, and
internal/gormlog asserts each line against the constant directly.

The third gorm.Open, in the archive writer, was not named in the issue
and had the same default. All three sites are pinned independently:
internal/handlers covers the main and per-webhook databases,
internal/delivery covers the archive writer, whose type is unexported.
Reverting any one of the three to a bare &gorm.Config{} fails the
suite.

The flood test's per-line and volume assertions were vacuous, because
the replaced default logger wrote only to a buffer while everything
else went to the captured stdout. It now tees to stdout as GORM's real
default does, so a reverted call site lands in the same capture and
those assertions measure the whole writer set.

README: the ceiling now covers GORM, and the writers it does not cover
are re-derived by measuring rather than by reading. fx's console
logger and the Go runtime write to standard error. net/http's nil
ErrorLog is not a separate writer at all -- slog.SetDefault redirects
the log package's default logger into internal/logger's handler, so
those lines arrive on standard output at INFO. A handler panic reaches
that same path because chi's Recoverer crashes before writing, which
is filed as #187 and is also the widest line the service can write, at
2,772 bytes against the stated 2,560.
2026-08-18 01:20:36 +00:00
b573959a26 Send the chi route pattern to Sentry, not the concrete path (closes #179)
All checks were successful
check / check (push) Successful in 2m51s
#160 scrubbed the Sentry body, query, cookies, env and headers but kept
Request.URL, which the SDK builds from the concrete path. On the
receiver that path is /webhook/<uuid> in full — a write capability, not
an identifier: anyone holding it can inject events the operator's
targets then deliver. #146's "2xx and 5xx keep the concrete path" ruling
was reasoned about a log the operator owns and does not transfer to a
tracker with its own retention and access control.

The chi route pattern now replaces the path on every route, reached via
the request the SDK carries on hint.Context. Unconditional, because a
route-conditional rule leaks on any route someone forgets to add, and on
a static route the pattern is the path anyway. The fallback is never the
concrete path.

Also rewrites event.Transaction, which carries the same UUID on the
sibling dispatch and which the issue did not name. Tracing is off today,
so that half is a floor rather than a live fix — and it is why enabling
tracing later needs #185 first, or every transaction collapses into one
bucket.

Independently reviewed. The reviewer ran fourteen adversarial probes —
404 and 405 panics, panics in middleware before and after routing,
direct CaptureException, mounted subrouters, wildcards, tracing on and
off — and found no path where the concrete URL survives, and no third
field carrying it.

Merge note: the final round was a two-comment documentation fix on an
already-passed review, correcting a rationale that called the host
operator configuration when it is the client's Host header. I verified
that amend is comment-only myself rather than spending a fifth review
round on it.
2026-08-18 02:42:58 +02:00
14 changed files with 2204 additions and 220 deletions

179
README.md
View File

@@ -1037,38 +1037,77 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and `Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
`X-Request-Id`. `X-Request-Id`.
The body is replaced on every route rather than filtered by route, and The same hook rewrites the request URL. The SDK builds it as
that is a choice rather than a limitation: the route is reachable from `scheme://host/path` from the concrete path, which on the receiver
the hook. `sentryhttp`'s recover path puts the request on the context route is `/webhook/<uuid>` in full — and that UUID is a write
it hands to `RecoverWithContext`, and the SDK carries that context capability, not an identifier: anyone holding it can post events this
through to `BeforeSend` as `hint.Context`, so service accepts and its targets then deliver. A tracker has its own
`hint.Context.Value(sentry.RequestContextKey)` yields the live request retention, access control and deletion policy, so the rule the access
and chi's `RoutePattern()` yields the matched pattern off it. There log follows above does not carry across that boundary. What is sent is
are two reasons to redact unconditionally anyway. Nothing debuggable the chi route pattern instead: `http://host/webhook/{uuid}`.
is lost:
every handler reads its fields with `PostFormValue`, so the body is
exactly where the credentials are — the target destination URL, the
login password, both password-change fields — and the one route whose
body is genuine signal is the receiver, whose body is already stored
on the event and served from the UI, so a tracker is not where anyone
reads it. And an unconditional rule cannot leak on a route somebody
forgets to add to it, which a route-conditional one can.
The headers are an allowlist for that second reason: the SDK's own The scheme and the host are kept, and everything else in the URL is
filter removes four names and passes everything else, which would ship discarded rather than edited, so a future SDK version that starts
`X-CSRF-Token` and the shared secrets senders put on the receiver appending a query string cannot widen this. The scheme has to survive
route. What survives still names the failing route — scheme, host, for the reason given below. The host is whatever the request's `Host`
path, method — and `X-Request-Id` ties the event to the local access header carried — this service validates no hostname, so on a directly
log line that holds the rest. Nothing dropped is needed for the exposed deployment a client sets it — and that same header is on the
likeliest use, debugging a CSRF rejection. Its three inputs are the allowlist above, so scrubbing the host out of the URL would withhold
TLS decision, `Origin` and `Referer`; the latter two are kept, and the nothing that is not sent anyway.
first is already in the retained URL, because the SDK derives that
URL's scheme from `r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` The body, the query string and the URL are all handled on every route
byte for byte the predicate `internal/middleware/csrf.go` uses to rather than filtered by route. For the URL that is also what keeps the
choose between the `csrf.Secure(true)` and `csrf.Secure(false)` event locatable: an error event is grouped by its exception and stack
handlers. So dropping `X-Forwarded-Proto` costs nothing. The dropped trace, not by its URL, so replacing the path with the pattern costs no
provider headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are grouping and the pattern still names the route in the UI. And an
real signal but are recorded locally on the event, and unconditional rule cannot leak on a route somebody forgets to add to
it, which a route-conditional one can. For the body there is a second
reason: nothing debuggable is lost, because every handler reads its
fields with `PostFormValue`, so the body is exactly where the
credentials are — the target destination URL, the login password, both
password-change fields — and the one route whose body is genuine
signal is the receiver, whose body is already stored on the event and
served from the UI, so a tracker is not where anyone reads it.
The route is reachable from the hook only on the error dispatch.
`sentryhttp`'s recover path puts the request on the context it hands
to `RecoverWithContext`, and the SDK carries that context through to
`BeforeSend` as `hint.Context`, so
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
and chi's `RoutePattern()` yields the matched pattern off it. The
transaction dispatch has no such request: a finished span captures
with a nil hint, which the client replaces with an empty one, so
`BeforeSendTransaction` sees no context at all. Tracing is off in this
service, so no transaction event is produced today, but the hook is
installed on both dispatches as a floor.
Where the pattern is out of reach — the transaction dispatch, an event
captured outside the router, or a request that matched no route — the
fallback is never the concrete path. The path becomes the literal
`/(redacted)`, so the URL reads `http://host/(redacted)`; a URL the
rewrite cannot parse into a scheme is withheld whole. A transaction
event additionally carries the SDK's own `METHOD /path` name, built
from the concrete path as well; it is rewritten on the same terms, to
`POST /webhook/{uuid}` where the pattern is known and `POST
/(redacted)` where it is not.
The headers are an allowlist for the same reason the rules above are
unconditional: the SDK's own filter removes four names and passes
everything else, which would ship `X-CSRF-Token` and the shared
secrets senders put on the receiver route. What survives still names
the failing route — scheme, host, route pattern, method — and
`X-Request-Id` ties the event to the local access log line that holds
the rest. Nothing dropped is needed for the likeliest use, debugging a
CSRF rejection. Its three inputs are the TLS decision, `Origin` and
`Referer`; the latter two are kept, and the first is the scheme of the
retained URL, because the SDK derives that scheme from
`r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` — byte
for byte the predicate `internal/middleware/csrf.go` uses to choose
between the `csrf.Secure(true)` and `csrf.Secure(false)` handlers.
That is what the rewrite above preserves it for, and it is why
dropping `X-Forwarded-Proto` costs nothing. The dropped provider
headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are real
signal but are recorded locally on the event, and
`Sentry-Trace`/`Baggage` are already reflected in the event's trace `Sentry-Trace`/`Baggage` are already reflected in the event's trace
context. context.
@@ -1113,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 `/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
the multiplier is whatever the deployment will serve. 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 Every limiter here — receiver, login, and password change — identifies
the client the same way, through one shared key function: the the client the same way, through one shared key function: the
connection's own address, unless the peer is listed in connection's own address, unless the peer is listed in
@@ -1351,6 +1464,10 @@ webhooker/
│ │ └── webhook_db_manager.go # Per-webhook DB lifecycle manager │ │ └── webhook_db_manager.go # Per-webhook DB lifecycle manager
│ ├── globals/ │ ├── globals/
│ │ └── globals.go # Build-time variables (appname, version, arch) │ │ └── 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/ │ ├── delivery/
│ │ ├── engine.go # Event-driven delivery engine (channel + timer based) │ │ ├── engine.go # Event-driven delivery engine (channel + timer based)
│ │ ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries │ │ ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries

View File

@@ -17,6 +17,7 @@ import (
"gorm.io/gorm" "gorm.io/gorm"
_ "modernc.org/sqlite" // Pure Go SQLite driver _ "modernc.org/sqlite" // Pure Go SQLite driver
"sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/gormlog"
"sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/logger"
) )
@@ -155,7 +156,10 @@ func (d *Database) connect() error {
// Then use it with GORM // Then use it with GORM
db, err := gorm.Open(sqlite.Dialector{ db, err := gorm.Open(sqlite.Dialector{
Conn: sqlDB, Conn: sqlDB,
}, &gorm.Config{}) }, &gorm.Config{
// Never leave this at GORM's default. See internal/gormlog.
Logger: gormlog.New(d.log),
})
if err != nil { if err != nil {
d.log.Error( d.log.Error(
"failed to connect to database", "failed to connect to database",

View File

@@ -14,6 +14,7 @@ import (
"gorm.io/driver/sqlite" "gorm.io/driver/sqlite"
"gorm.io/gorm" "gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/gormlog"
"sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/logger"
) )
@@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB(
db, err := gorm.Open(sqlite.Dialector{ db, err := gorm.Open(sqlite.Dialector{
Conn: sqlDB, Conn: sqlDB,
}, &gorm.Config{}) }, &gorm.Config{
// Never leave this at GORM's default. See internal/gormlog.
Logger: gormlog.New(m.log),
})
if err != nil { if err != nil {
_ = sqlDB.Close() _ = sqlDB.Close()

View File

@@ -12,6 +12,7 @@ import (
"gorm.io/driver/sqlite" "gorm.io/driver/sqlite"
"gorm.io/gorm" "gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/gormlog"
) )
// archiveExpiryNever is the expiry sentinel (and default) that // archiveExpiryNever is the expiry sentinel (and default) that
@@ -282,7 +283,11 @@ func (w *archiveWriter) openMode(
} }
gdb, err := gorm.Open( 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 { if err != nil {
_ = sqlDB.Close() _ = sqlDB.Close()

View File

@@ -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)],
)
}
}

View File

@@ -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}
}

168
internal/gormlog/gormlog.go Normal file
View File

@@ -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,
)
}

View File

@@ -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))
}

View File

@@ -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<<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
}
// 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,
)
}

View 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
}

View 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)
}
}

View File

@@ -6,11 +6,8 @@ import (
"log/slog" "log/slog"
"net" "net"
"net/http" "net/http"
"strings"
"sync" "sync"
"time" "time"
"unicode"
"unicode/utf8"
basicauth "github.com/99designs/basicauth-go" basicauth "github.com/99designs/basicauth-go"
"github.com/go-chi/chi" "github.com/go-chi/chi"
@@ -22,6 +19,7 @@ import (
"go.uber.org/fx" "go.uber.org/fx"
"sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/globals" "sneak.berlin/go/webhooker/internal/globals"
"sneak.berlin/go/webhooker/internal/logfield"
"sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/logger"
"sneak.berlin/go/webhooker/internal/session" "sneak.berlin/go/webhooker/internal/session"
) )
@@ -44,16 +42,6 @@ const (
// pick the size of the line it writes. // pick the size of the line it writes.
redactedQuery = "?(redacted)" 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 // maxLogRequestIDBytes bounds the request id, which is also
// client-supplied: chi's RequestID middleware passes an inbound // client-supplied: chi's RequestID middleware passes an inbound
// X-Request-Id header through verbatim. Its generated form is an // X-Request-Id header through verbatim. Its generated form is an
@@ -66,15 +54,10 @@ const (
// is half this. // is half this.
maxLogMethodBytes = 32 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, // MaxAccessLogLineBytes is the ceiling on one JSON access log line,
// and the number an operator multiplies by the request rate to size // 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 // 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. // ENCODED bytes, plus the part of the line no client can influence.
// //
// url, useragent, referer 3*(512+11) = 1569 // url, useragent, referer 3*(512+11) = 1569
@@ -84,6 +67,9 @@ const (
// ---- // ----
// 2087 // 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 // The fixed portion is the JSON punctuation, the field names, the
// level and the message, both timestamps at their longest, an IPv6 // level and the message, both timestamps at their longest, an IPv6
// remoteIP with a zone, a three-digit status and a full-width int64 // remoteIP with a zone, a three-digit status and a full-width int64
@@ -91,13 +77,29 @@ const (
// than sitting on the arithmetic. // than sitting on the arithmetic.
// //
// The tty text handler in internal/logger is covered by the same // 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 // the wider of the two handlers emits for it — including the ten
// bytes strconv.Quote spends on a non-printable rune at or above // bytes strconv.Quote spends on a non-printable rune at or above
// U+10000, which is four more than the JSON handler ever spends — // U+10000, which is four more than the JSON handler ever spends —
// so each budget bounds the encoded field under either handler. // so each budget bounds the encoded field under either handler.
// The text handler's fixed portion is 286, the smaller of the two, // The text handler's fixed portion is 286, the smaller of the two,
// which puts its worst case at 2037. // 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 MaxAccessLogLineBytes = 2560
) )
@@ -174,114 +176,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
lrw.ResponseWriter.WriteHeader(code) 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 // concreteLogURL renders the request's own URL for the access log
// branches that keep it, with the query string replaced by a fixed // branches that keep it, with the query string replaced by a fixed
// marker. // marker.
@@ -375,21 +269,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
// line does not track the size of the request. // line does not track the size of the request.
s.log.Info("http request", s.log.Info("http request",
"request_start", start, "request_start", start,
"method", truncateLogField( "method", logfield.Truncate(
r.Method, maxLogMethodBytes, r.Method, maxLogMethodBytes,
), ),
"url", truncateLogField( "url", logfield.Truncate(
accessLogURL(r, lrw.statusCode), accessLogURL(r, lrw.statusCode),
maxLogFieldBytes, logfield.MaxBytes,
), ),
"useragent", truncateLogField( "useragent", logfield.Truncate(
r.UserAgent(), maxLogFieldBytes, r.UserAgent(), logfield.MaxBytes,
), ),
"request_id", truncateLogField( "request_id", logfield.Truncate(
requestID, maxLogRequestIDBytes, requestID, maxLogRequestIDBytes,
), ),
"referer", truncateLogField( "referer", logfield.Truncate(
r.Referer(), maxLogFieldBytes, r.Referer(), logfield.MaxBytes,
), ),
"proto", r.Proto, "proto", r.Proto,
"remoteIP", ipFromHostPort(r.RemoteAddr), "remoteIP", ipFromHostPort(r.RemoteAddr),

View File

@@ -2,8 +2,11 @@ package server
import ( import (
"net/http" "net/http"
"net/url"
"strings"
"github.com/getsentry/sentry-go" "github.com/getsentry/sentry-go"
"github.com/go-chi/chi"
) )
// sentryRedacted stands in for a withheld field on every event shipped // sentryRedacted stands in for a withheld field on every event shipped
@@ -11,6 +14,12 @@ import (
// can tell a suppressed value from an absent one. // can tell a suppressed value from an absent one.
const sentryRedacted = "(redacted)" const sentryRedacted = "(redacted)"
// sentryRedactedPath is what stands in for the request path when the
// route pattern is not reachable. It is deliberately not the concrete
// path: on the receiver route that path carries the entrypoint UUID,
// which is a write capability rather than an identifier.
const sentryRedactedPath = "/" + sentryRedacted
// sentryClientOptions builds the options the SDK is initialised with. // sentryClientOptions builds the options the SDK is initialised with.
// It is its own function so a test can stand up a client wired exactly // It is its own function so a test can stand up a client wired exactly
// as production is, with only the transport swapped. // as production is, with only the transport swapped.
@@ -44,18 +53,43 @@ func sentryClientOptions(dsn, release string) sentry.ClientOptions {
// login password and both password-change fields. None of that may // login password and both password-change fields. None of that may
// reach a third-party service. // reach a third-party service.
// //
// URL is the third such field. NewRequest builds it as
// scheme://host/path (interfaces.go:183), and on the receiver route
// that path is /webhook/<uuid> in full — a write capability, not an
// identifier. It is rebuilt here from the chi route pattern, on every
// route, keeping the scheme and the host.
//
// This hook is a floor, not a default: the fields it clears stay // This hook is a floor, not a default: the fields it clears stay
// cleared even if SendDefaultPII is ever turned on. // cleared even if SendDefaultPII is ever turned on.
func scrubSentryRequest( func scrubSentryRequest(
event *sentry.Event, event *sentry.Event,
_ *sentry.EventHint, hint *sentry.EventHint,
) *sentry.Event { ) *sentry.Event {
if event == nil || event.Request == nil { if event == nil {
return event
}
pattern := sentryRoutePattern(hint)
// Only transaction events carry a Transaction name, and the SDK
// builds it from the concrete path too (sentryhttp.go:105 via
// tracing.go:553). Rewritten on the same terms.
if event.Transaction != "" {
event.Transaction = sentryTransactionName(
event.Transaction, pattern,
)
}
if event.Request == nil {
return event return event
} }
req := event.Request req := event.Request
if req.URL != "" {
req.URL = sentryRouteURL(req.URL, pattern)
}
if req.QueryString != "" { if req.QueryString != "" {
req.QueryString = sentryRedacted req.QueryString = sentryRedacted
} }
@@ -71,6 +105,91 @@ func scrubSentryRequest(
return event return event
} }
// sentryRoutePattern returns the chi route pattern for the request the
// hint carries, or "" when it is not reachable.
//
// The request is reachable on the error dispatch only. sentryhttp's
// recover path calls RecoverWithContext with the request on the
// context under sentry.RequestContextKey (sentryhttp.go:124-125), and
// the client copies that context onto the hint (client.go:484-485)
// before handing it to BeforeSend (client.go:631). chi's routing
// context is a pointer placed on the request context before the
// middleware chain runs (chi mux.go:84) and filled in as the mux
// routes, so by the time a handler panics it names the matched route.
//
// The transaction dispatch has no such request: Span.doFinish calls
// hub.CaptureEvent (tracing.go:356), which passes a nil hint that the
// client replaces with an empty one (client.go:620-622). The pattern
// is therefore always "" there, and the callers fall back.
func sentryRoutePattern(hint *sentry.EventHint) string {
if hint == nil || hint.Context == nil {
return ""
}
req, ok := hint.Context.Value(
sentry.RequestContextKey,
).(*http.Request)
if !ok || req == nil {
return ""
}
rctx := chi.RouteContext(req.Context())
if rctx == nil {
return ""
}
// Empty when no route matched, which is the fallback case too.
return rctx.RoutePattern()
}
// sentryRouteURL rebuilds an event's request URL with the route
// pattern in place of the concrete path.
//
// The scheme is load-bearing and is kept: the SDK derives it from
// r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
// (interfaces.go:180), byte for byte the predicate
// internal/middleware/csrf.go uses, so it is the CSRF TLS decision and
// the reason dropping X-Forwarded-Proto from the header allowlist
// costs nothing. The host is parsed.Host of the SDK's
// scheme://r.Host/path, so it is whatever the client's Host header
// carried: this service validates no hostname. It is kept because that
// same header is on the allowlist, so scrubbing it here would withhold
// nothing that is not sent anyway.
//
// Everything else in the URL is discarded rather than edited, so a
// future SDK that starts appending a query string cannot widen this.
func sentryRouteURL(rawURL, pattern string) string {
parsed, err := url.Parse(rawURL)
if err != nil || parsed.Scheme == "" {
// Not a shape this can safely take apart.
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return parsed.Scheme + "://" + parsed.Host + pattern
}
// sentryTransactionName rebuilds the SDK's "METHOD /path" transaction
// name with the route pattern in place of the concrete path. Method is
// kept for the same reason Request.Method is: net/http admits only a
// bounded token there. A name in any other shape is withheld whole,
// since nothing can be said about which part of it is a path.
func sentryTransactionName(name, pattern string) string {
method, _, found := strings.Cut(name, " ")
if !found {
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return method + " " + pattern
}
// keptSentryHeaders returns the subset of headers an event may carry // keptSentryHeaders returns the subset of headers an event may carry
// off-host. Dropping by allowlist rather than by blocklist is what // off-host. Dropping by allowlist rather than by blocklist is what
// makes an unrecognised header safe: the SDK's own filter removes four // makes an unrecognised header safe: the SDK's own filter removes four

View File

@@ -13,12 +13,13 @@ import (
"github.com/getsentry/sentry-go" "github.com/getsentry/sentry-go"
sentryhttp "github.com/getsentry/sentry-go/http" sentryhttp "github.com/getsentry/sentry-go/http"
"github.com/go-chi/chi"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/server" "sneak.berlin/go/webhooker/internal/server"
) )
// The three markers below are the credentials a captured event could // The four markers below are the credentials a captured event could
// carry off-host, one per field of sentry.Request that the SDK fills // carry off-host, one per field of sentry.Request that the SDK fills
// from the request without a SendDefaultPII guard. // from the request without a SendDefaultPII guard.
const ( const (
@@ -33,6 +34,12 @@ const (
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf // sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
// accepts in place of the form field. // accepts in place of the form field.
sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ" sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ"
// sentryReceiverUUID is the entrypoint identifier in the path of
// a receiver request. It is a write capability: anyone holding
// it can POST events this service accepts and its targets then
// deliver, so it may not reach a third-party tracker.
sentryReceiverUUID = "6d1f9c2a-3b7e-4f58-9a0d-c0ffeebadc0d"
) )
// sentryKeptUserAgent is a non-secret header value planted so the // sentryKeptUserAgent is a non-secret header value planted so the
@@ -58,19 +65,41 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
c.events = append(c.events, event) c.events = append(c.events, event)
} }
// captureThroughSentryHTTP panics inside a form handler wrapped in the // sentryCase drives one request through the real sentryhttp middleware
// real sentryhttp middleware and returns the event the SDK produced. // inside a real chi router and returns the events the SDK produced.
// //
// This is the only construction path on which Request.Data appears: // Routing through a chi mux is load-bearing, not decoration. chi puts
// sentryhttp calls Scope.SetRequest, which tees r.Body into a 10 KiB // its routing context on the request context before the middleware
// buffer, ParseForm drains the tee, and Scope.ApplyToEvent copies the // chain runs and fills it in as it matches, so a hand-built request
// buffer into the event inside prepareEvent — before BeforeSend runs. // carries no route pattern at all and could not distinguish the hook
// A hand-built sentry.NewRequest never reads the body and so cannot // working from the hook falling back.
// regress-test any of it.
// //
// scrub selects whether the production BeforeSend hooks are installed, // This is also the only construction path on which Request.Data
// so the same path shows both what the SDK collects and what survives. // appears: sentryhttp calls Scope.SetRequest, which tees r.Body into a
func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event { // 10 KiB buffer, ParseForm drains the tee, and Scope.ApplyToEvent
// copies the buffer into the event inside prepareEvent — before
// BeforeSend runs. A hand-built sentry.NewRequest never reads the body
// and so cannot regress-test any of it.
type sentryCase struct {
// scrub selects whether the production BeforeSend hooks are
// installed, so the same path shows both what the SDK collects
// and what survives.
scrub bool
// tracing enables the transaction dispatch, which the service
// leaves off. With it on, a served request produces a
// transaction event through BeforeSendTransaction.
tracing bool
// panics selects the error dispatch, via BeforeSend.
panics bool
// request builds the request to serve, given the client whose
// hub it must carry.
request func(*sentry.Client) *http.Request
}
func (c sentryCase) capture(t *testing.T) []*sentry.Event {
t.Helper() t.Helper()
transport := &captureTransport{} transport := &captureTransport{}
@@ -80,57 +109,107 @@ func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
) )
opts.Transport = transport opts.Transport = transport
if !scrub { if !c.scrub {
opts.BeforeSend = nil opts.BeforeSend = nil
opts.BeforeSendTransaction = nil opts.BeforeSendTransaction = nil
} }
if c.tracing {
opts.EnableTracing = true
opts.TracesSampleRate = 1.0
}
client, err := sentry.NewClient(opts) client, err := sentry.NewClient(opts)
require.NoError(t, err) require.NoError(t, err)
handler := sentryhttp.New(sentryhttp.Options{}).Handle( c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the tee and fills the
// buffer. Its success is asserted by the unscrubbed
// case below, which sees the body in the event.
_ = r.ParseForm()
panic("boom") return transport.events
}),
)
handler.ServeHTTP(
httptest.NewRecorder(),
sentryLoginRequest(client),
)
require.Len(t, transport.events, 1)
return transport.events[0]
} }
// sentryLoginRequest builds the password POST the capture above drives, // router mirrors setupGlobalMiddleware's ordering over the two route
// with a credential planted in the body, the query and a header. // patterns these tests need: a recovering middleware first, then the
// sentryhttp handler registered with Use and Repanic set, exactly as
// routes.go registers it. The local recover stands in for chi's
// middleware.Recoverer, which holds that slot in production; it is
// here only to keep panic stacks out of the test output.
func (c sentryCase) router() http.Handler {
handler := func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the body tee and fills the
// buffer. Its success is asserted by the unscrubbed case
// below, which sees the body in the event.
_ = r.ParseForm()
if c.panics {
panic("boom")
}
}
router := chi.NewRouter()
router.Use(recoveringMiddleware)
router.Use(
sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle,
)
router.HandleFunc("/pages/login", handler)
router.HandleFunc("/webhook/{uuid}", handler)
return router
}
func recoveringMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(
func(w http.ResponseWriter, r *http.Request) {
defer func() { _ = recover() }()
next.ServeHTTP(w, r)
},
)
}
// sentryLoginRequest builds the password POST most cases drive, with a
// credential planted in the body, the query and a header.
func sentryLoginRequest(client *sentry.Client) *http.Request { func sentryLoginRequest(client *sentry.Client) *http.Request {
form := url.Values{} form := url.Values{}
form.Set("username", "admin") form.Set("username", "admin")
form.Set("password", sentryBodyMarker) form.Set("password", sentryBodyMarker)
req := sentryRequest(
client,
"/pages/login?url=https://hooks.slack.com/services/"+
sentryQueryMarker,
form.Encode(),
)
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
return req
}
// sentryReceiverRequest builds a POST to the receiver route, whose
// concrete path carries the entrypoint capability.
func sentryReceiverRequest(client *sentry.Client) *http.Request {
return sentryRequest(
client, "/webhook/"+sentryReceiverUUID, "payload=hello",
)
}
func sentryRequest(
client *sentry.Client,
target, body string,
) *http.Request {
req := httptest.NewRequestWithContext( req := httptest.NewRequestWithContext(
sentry.SetHubOnContext( sentry.SetHubOnContext(
context.Background(), context.Background(),
sentry.NewHub(client, sentry.NewScope()), sentry.NewHub(client, sentry.NewScope()),
), ),
http.MethodPost, http.MethodPost,
"/pages/login?url=https://hooks.slack.com/services/"+ target,
sentryQueryMarker, strings.NewReader(body),
strings.NewReader(form.Encode()),
) )
req.Header.Set( req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded", "Content-Type", "application/x-www-form-urlencoded",
) )
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
req.Header.Set("User-Agent", sentryKeptUserAgent) req.Header.Set("User-Agent", sentryKeptUserAgent)
return req return req
@@ -146,15 +225,27 @@ func marshalEvent(t *testing.T, event *sentry.Event) string {
return string(encoded) return string(encoded)
} }
// onlyEvent asserts a single event was captured and returns it.
func onlyEvent(t *testing.T, events []*sentry.Event) *sentry.Event {
t.Helper()
require.Len(t, events, 1)
require.NotNil(t, events[0].Request)
return events[0]
}
// TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the // TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the
// hook exists for. Without it the SDK ships the whole POST body, the // hook exists for. Without it the SDK ships the whole POST body, the
// raw query and the CSRF header, none of which SendDefaultPII=false // raw query, the CSRF header and the concrete request path, none of
// suppresses. // which SendDefaultPII=false suppresses.
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) { func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
t.Parallel() t.Parallel()
event := captureThroughSentryHTTP(t, false) event := onlyEvent(t, sentryCase{
require.NotNil(t, event.Request) panics: true,
request: sentryLoginRequest,
}.capture(t))
assert.Contains( assert.Contains(
t, event.Request.Data, sentryBodyMarker, t, event.Request.Data, sentryBodyMarker,
@@ -165,6 +256,18 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
assert.Contains( assert.Contains(
t, marshalEvent(t, event), sentryHeaderMarker, t, marshalEvent(t, event), sentryHeaderMarker,
) )
receiver := onlyEvent(t, sentryCase{
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.Contains(
t, receiver.Request.URL, sentryReceiverUUID,
"the SDK is expected to build Request.URL from the "+
"concrete path; if it no longer does, the route "+
"pattern rewrite's premise changed",
)
} }
// TestSentryScrub_RedactsTheCapturedRequest is the regression test: no // TestSentryScrub_RedactsTheCapturedRequest is the regression test: no
@@ -173,8 +276,11 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) { func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
t.Parallel() t.Parallel()
event := captureThroughSentryHTTP(t, true) event := onlyEvent(t, sentryCase{
require.NotNil(t, event.Request) scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
encoded := marshalEvent(t, event) encoded := marshalEvent(t, event)
@@ -189,16 +295,45 @@ func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
assert.Empty(t, event.Request.Env) assert.Empty(t, event.Request.Env)
} }
// TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern is the
// regression test for the receiver URL: the entrypoint UUID is a write
// capability and may not reach the tracker, while the route it names
// must still be readable there.
func TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/webhook/{uuid}", event.Request.URL,
)
}
// TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost // TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost
// the debugging signal: the route, the method and the metadata headers // the debugging signal: the route, its scheme and host, the method and
// still identify what failed. // the metadata headers still identify what failed. On a static route
// the pattern is the path, so the URL is unchanged there.
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) { func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
t.Parallel() t.Parallel()
event := captureThroughSentryHTTP(t, true) event := onlyEvent(t, sentryCase{
require.NotNil(t, event.Request) scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
assert.Contains(t, event.Request.URL, "/pages/login") assert.Equal(
t, "http://example.com/pages/login", event.Request.URL,
)
assert.Equal(t, http.MethodPost, event.Request.Method) assert.Equal(t, http.MethodPost, event.Request.Method)
assert.Equal( assert.Equal(
t, t,
@@ -212,6 +347,127 @@ func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
) )
} }
// TestSentryScrub_RedactsTheTransactionDispatch covers the other hook.
// Span.doFinish captures with a nil hint, so BeforeSendTransaction
// gets one with no context and no request: the route pattern is out of
// reach and both the URL and the SDK-built transaction name have to
// fall back. Tracing is off in this service, so no transaction event
// is produced today; the hook is a floor against that changing.
func TestSentryScrub_RedactsTheTransactionDispatch(t *testing.T) {
t.Parallel()
events := sentryCase{
scrub: true,
tracing: true,
request: sentryReceiverRequest,
}.capture(t)
event := onlyEvent(t, events)
require.Equal(t, "transaction", event.Type)
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/(redacted)", event.Request.URL,
)
assert.Equal(t, "POST /(redacted)", event.Transaction)
}
// TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook pins
// that dispatch's premise the same way, since it is the one the
// service does not exercise today.
func TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
tracing: true,
request: sentryReceiverRequest,
}.capture(t))
require.Equal(t, "transaction", event.Type)
assert.Contains(t, event.Request.URL, sentryReceiverUUID)
assert.Contains(t, event.Transaction, sentryReceiverUUID)
}
// TestSentryScrub_FallsBackWithoutARoutePattern covers every way the
// pattern can be missing. None of them may fall back to the concrete
// path, and all of them keep the scheme, which is the CSRF TLS
// decision.
func TestSentryScrub_FallsBackWithoutARoutePattern(t *testing.T) {
t.Parallel()
concrete := "https://example.com/webhook/" + sentryReceiverUUID
// A request with no chi routing context on it at all, which is
// what an event captured outside the router would carry.
unrouted := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, concrete, nil,
)
for name, hint := range map[string]*sentry.EventHint{
"no hint": nil,
"no context": {},
"no request": {Context: context.Background()},
"unrouted request": {
Context: context.WithValue(
context.Background(),
sentry.RequestContextKey,
unrouted,
),
},
} {
t.Run(name, func(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{URL: concrete}
event.Transaction = "POST /webhook/" +
sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(
event, hint,
)
require.NotNil(t, scrubbed)
assert.Equal(
t,
"https://example.com/(redacted)",
scrubbed.Request.URL,
)
assert.Equal(
t, "POST /(redacted)", scrubbed.Transaction,
)
assert.NotContains(
t,
marshalEvent(t, scrubbed),
sentryReceiverUUID,
)
})
}
}
// TestSentryScrub_WithholdsUnparseableValues covers the shapes the
// rewrite cannot take apart. Withholding them whole is the safe
// answer, since nothing can be said about which part is a path.
func TestSentryScrub_WithholdsUnparseableValues(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{
URL: "/webhook/" + sentryReceiverUUID,
}
event.Transaction = "/webhook/" + sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(event, nil)
require.NotNil(t, scrubbed)
assert.Equal(t, "(redacted)", scrubbed.Request.URL)
assert.Equal(t, "(redacted)", scrubbed.Transaction)
}
// TestSentryScrub_ToleratesEventsWithoutARequest covers the events the // TestSentryScrub_ToleratesEventsWithoutARequest covers the events the
// hook sees outside an HTTP handler, where no request is attached. // hook sees outside an HTTP handler, where no request is attached.
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) { func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
@@ -223,5 +479,6 @@ func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
require.NotNil(t, scrubbed) require.NotNil(t, scrubbed)
assert.Nil(t, scrubbed.Request) assert.Nil(t, scrubbed.Request)
assert.Empty(t, scrubbed.Transaction)
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil)) assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
} }