Compare commits
2 Commits
ce36f430fb
...
f9d9a2c8d7
| Author | SHA1 | Date | |
|---|---|---|---|
| f9d9a2c8d7 | |||
| b573959a26 |
179
README.md
179
README.md
@@ -1037,38 +1037,77 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
|
||||
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
|
||||
`X-Request-Id`.
|
||||
|
||||
The body is replaced on every route rather than filtered by route, and
|
||||
that is a choice rather than a limitation: the route is reachable from
|
||||
the hook. `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. There
|
||||
are two reasons to redact unconditionally anyway. Nothing debuggable
|
||||
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 same hook rewrites the request URL. The SDK builds it as
|
||||
`scheme://host/path` from the concrete path, which on the receiver
|
||||
route is `/webhook/<uuid>` in full — and that UUID is a write
|
||||
capability, not an identifier: anyone holding it can post events this
|
||||
service accepts and its targets then deliver. A tracker has its own
|
||||
retention, access control and deletion policy, so the rule the access
|
||||
log follows above does not carry across that boundary. What is sent is
|
||||
the chi route pattern instead: `http://host/webhook/{uuid}`.
|
||||
|
||||
The headers are an allowlist for that second reason: 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,
|
||||
path, 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 already in the retained URL, because the SDK derives that
|
||||
URL's 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. So 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
|
||||
The scheme and the host are kept, and everything else in the URL is
|
||||
discarded rather than edited, so a future SDK version that starts
|
||||
appending a query string cannot widen this. The scheme has to survive
|
||||
for the reason given below. The host is whatever the request's `Host`
|
||||
header carried — this service validates no hostname, so on a directly
|
||||
exposed deployment a client sets it — and that same header is on the
|
||||
allowlist above, so scrubbing the host out of the URL would withhold
|
||||
nothing that is not sent anyway.
|
||||
|
||||
The body, the query string and the URL are all handled on every route
|
||||
rather than filtered by route. For the URL that is also what keeps the
|
||||
event locatable: an error event is grouped by its exception and stack
|
||||
trace, not by its URL, so replacing the path with the pattern costs no
|
||||
grouping and the pattern still names the route in the UI. And an
|
||||
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
|
||||
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
|
||||
the multiplier is whatever the deployment will serve.
|
||||
|
||||
That figure is now the ceiling on a second writer as well. GORM's own
|
||||
default logger printed the fully interpolated SQL — parameters and all
|
||||
— to standard output on every statement that returned an error,
|
||||
including a plain record-not-found, at a level no operator setting
|
||||
reached. Two of this service's lookups miss by design on
|
||||
unauthenticated routes: the entrypoint lookup behind `/webhook/{uuid}`
|
||||
and the user lookup behind the login form, whose path segment and
|
||||
submitted username the client picks outright. Every `gorm.Open` in the
|
||||
service now installs the adapter in `internal/gormlog` instead. It
|
||||
writes through the same `slog` logger as everything else, so its lines
|
||||
take the level the operator set and the handler `internal/logger`
|
||||
selected, and every value it emits is spent through the same 512-byte
|
||||
encoded budget (`internal/logfield`). A record-not-found is not logged
|
||||
as an error: it is the expected outcome on both of those paths, and
|
||||
each handler already records its own miss at `DEBUG`, without the SQL.
|
||||
Slow statements are kept — at `WARN`, above the same 200 ms threshold
|
||||
GORM used, with the statement bounded — because that report is the one
|
||||
thing GORM's logger gave an operator that nothing else here does, and
|
||||
a statement that both missed and ran slow is still reported as slow.
|
||||
The adapter orders those cases exactly as GORM's own `Trace` orders
|
||||
them, so dropping the miss costs an operator no report that GORM's
|
||||
`IgnoreRecordNotFoundError` would have kept. A
|
||||
GORM line spends at most two of those budgets, the statement and the
|
||||
driver error, against a smaller fixed portion than the access log's;
|
||||
`internal/gormlog/gormlog_test.go` asserts each line against
|
||||
`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
|
||||
|
||||
**What the ceiling does not cover.** It is a per-line bound on the
|
||||
access log and on GORM's statement logging, not a bound on every line
|
||||
this service writes. The exceptions are named here because a bound
|
||||
that is true of one writer and silently false of another is worse than
|
||||
no stated bound at all.
|
||||
|
||||
- Other `slog` calls that reach a client-chosen value — the
|
||||
`MaxBodySize` rejection, the CSRF failure, the receiver rate-limit
|
||||
rejection, and the two lookup misses above — still log the request
|
||||
path or the submitted username untruncated.
|
||||
- The `log` delivery target (`internal/delivery/target_log.go`) writes
|
||||
the entire inbound event, headers and body, to the log. That is what
|
||||
the target is for. Each line is bounded per event by the 1 MB
|
||||
receiver body cap, and it costs nothing unless an authenticated
|
||||
operator creates a target of that type.
|
||||
- Two writers that do not go through `internal/logger` at all, both on
|
||||
standard error. `fx` prints the dependency graph and the lifecycle
|
||||
hooks through its default console logger at startup and shutdown —
|
||||
nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
|
||||
`os.Stderr`. The Go runtime writes a panic or a fatal error itself;
|
||||
a panic in a background worker rather than in a request handler is
|
||||
the case that reaches it, since nothing recovers those. Neither
|
||||
carries a client-chosen value at a client-chosen length: the five
|
||||
`panic` calls in this service are invariant guards over constants
|
||||
and over `crypto/rand`.
|
||||
- `net/http`'s own faults, which are **not** a separate writer.
|
||||
`internal/server/http.go` builds its server with a nil `ErrorLog`,
|
||||
so `net/http` falls back to the `log` package's default logger — and
|
||||
`internal/logger` calls `slog.SetDefault`, which redirects that
|
||||
logger into whichever handler it installed. Those lines therefore
|
||||
arrive on standard output, shaped like every other line, at `INFO`.
|
||||
They are not truncated and they are not bounded by the ceiling: a
|
||||
handler panic arrives as one record carrying a whole goroutine
|
||||
stack, measured at 2,772 bytes against the ceiling's 2,560. The
|
||||
value is the runtime's, not a client's.
|
||||
- A handler panic reaches that path rather than the one it looks like
|
||||
it should. `internal/server/routes.go` installs chi's
|
||||
`middleware.Recoverer` in front of every route, which is meant to
|
||||
print the panic and its stack to standard error and answer 500. On
|
||||
the Go version this service builds against it does neither: chi
|
||||
v1.5.5's stack pretty-printer looks for a `panic(0x` frame that the
|
||||
runtime no longer emits, walks past the end of its own slice, and
|
||||
panics before writing a byte. That second panic escapes to
|
||||
`net/http`, which drops the connection and reports it through the
|
||||
nil `ErrorLog` above. Tracked separately in
|
||||
https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||
|
||||
Every limiter here — receiver, login, and password change — identifies
|
||||
the client the same way, through one shared key function: the
|
||||
connection's own address, unless the peer is listed in
|
||||
@@ -1351,6 +1464,10 @@ webhooker/
|
||||
│ │ └── webhook_db_manager.go # Per-webhook DB lifecycle manager
|
||||
│ ├── globals/
|
||||
│ │ └── globals.go # Build-time variables (appname, version, arch)
|
||||
│ ├── gormlog/
|
||||
│ │ └── gormlog.go # GORM's logger.Interface on top of slog, bounded
|
||||
│ ├── logfield/
|
||||
│ │ └── logfield.go # Encoded-byte budget for client-supplied log values
|
||||
│ ├── delivery/
|
||||
│ │ ├── engine.go # Event-driven delivery engine (channel + timer based)
|
||||
│ │ ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries
|
||||
|
||||
@@ -17,6 +17,7 @@ import (
|
||||
"gorm.io/gorm"
|
||||
_ "modernc.org/sqlite" // Pure Go SQLite driver
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
"sneak.berlin/go/webhooker/internal/logger"
|
||||
)
|
||||
|
||||
@@ -155,7 +156,10 @@ func (d *Database) connect() error {
|
||||
// Then use it with GORM
|
||||
db, err := gorm.Open(sqlite.Dialector{
|
||||
Conn: sqlDB,
|
||||
}, &gorm.Config{})
|
||||
}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See internal/gormlog.
|
||||
Logger: gormlog.New(d.log),
|
||||
})
|
||||
if err != nil {
|
||||
d.log.Error(
|
||||
"failed to connect to database",
|
||||
|
||||
@@ -14,6 +14,7 @@ import (
|
||||
"gorm.io/driver/sqlite"
|
||||
"gorm.io/gorm"
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
"sneak.berlin/go/webhooker/internal/logger"
|
||||
)
|
||||
|
||||
@@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB(
|
||||
|
||||
db, err := gorm.Open(sqlite.Dialector{
|
||||
Conn: sqlDB,
|
||||
}, &gorm.Config{})
|
||||
}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See internal/gormlog.
|
||||
Logger: gormlog.New(m.log),
|
||||
})
|
||||
if err != nil {
|
||||
_ = sqlDB.Close()
|
||||
|
||||
|
||||
@@ -12,6 +12,7 @@ import (
|
||||
|
||||
"gorm.io/driver/sqlite"
|
||||
"gorm.io/gorm"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
)
|
||||
|
||||
// archiveExpiryNever is the expiry sentinel (and default) that
|
||||
@@ -282,7 +283,11 @@ func (w *archiveWriter) openMode(
|
||||
}
|
||||
|
||||
gdb, err := gorm.Open(
|
||||
sqlite.Dialector{Conn: sqlDB}, &gorm.Config{},
|
||||
sqlite.Dialector{Conn: sqlDB}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See
|
||||
// internal/gormlog.
|
||||
Logger: gormlog.New(w.log),
|
||||
},
|
||||
)
|
||||
if err != nil {
|
||||
_ = sqlDB.Close()
|
||||
|
||||
155
internal/delivery/target_database_archive_gormlog_test.go
Normal file
155
internal/delivery/target_database_archive_gormlog_test.go
Normal 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)],
|
||||
)
|
||||
}
|
||||
}
|
||||
17
internal/gormlog/export_test.go
Normal file
17
internal/gormlog/export_test.go
Normal 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
168
internal/gormlog/gormlog.go
Normal 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,
|
||||
)
|
||||
}
|
||||
425
internal/gormlog/gormlog_test.go
Normal file
425
internal/gormlog/gormlog_test.go
Normal 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))
|
||||
}
|
||||
477
internal/handlers/gormlogbound_test.go
Normal file
477
internal/handlers/gormlogbound_test.go
Normal 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,
|
||||
)
|
||||
}
|
||||
140
internal/logfield/logfield.go
Normal file
140
internal/logfield/logfield.go
Normal file
@@ -0,0 +1,140 @@
|
||||
// Package logfield bounds a client-supplied value against what the log
|
||||
// handler will actually emit for it, so a line's size is set by this
|
||||
// service rather than by the client that provoked it.
|
||||
//
|
||||
// It lives outside internal/middleware because more than one writer
|
||||
// needs it: the access log, and the GORM adapter in internal/gormlog,
|
||||
// which logs SQL with the client-chosen parameters interpolated into
|
||||
// it. One budget, one implementation.
|
||||
package logfield
|
||||
|
||||
import (
|
||||
"strings"
|
||||
"unicode"
|
||||
"unicode/utf8"
|
||||
)
|
||||
|
||||
const (
|
||||
// MaxBytes is the default budget for a field whose value the
|
||||
// client supplies outright. It is spent in ENCODED bytes (see
|
||||
// Truncate), so 512 still holds a real browser's User-Agent whole
|
||||
// — those are plain ASCII, which encodes one byte for one — while
|
||||
// a value built from characters the encoder escapes keeps a
|
||||
// shorter prefix. That is the intended trade: 500 quotation marks
|
||||
// are not a debugging asset.
|
||||
MaxBytes = 512
|
||||
|
||||
// truncationMarker is appended to any value Truncate cut, so a
|
||||
// short value and a truncated one cannot be confused. It is
|
||||
// charged on top of the budget, not inside it.
|
||||
truncationMarker = "[truncated]"
|
||||
)
|
||||
|
||||
// EncodedBytes is what r costs on the line once the log handler has
|
||||
// escaped it, taking the worse of the two handlers internal/logger
|
||||
// configures.
|
||||
//
|
||||
// slog's JSON handler escapes quote, backslash, newline, carriage
|
||||
// return and tab to two bytes each, and every other C0 control plus
|
||||
// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
|
||||
// passes every other rune through as its own UTF-8. Its text handler
|
||||
// quotes with strconv.Quote, which spells a non-printable rune below
|
||||
// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
|
||||
// bytes, not six. The text handler is therefore the worse of the two
|
||||
// for every non-printable rune, and by four bytes apiece for the
|
||||
// 955,086 unassigned, private-use and format code points on planes 1
|
||||
// to 16.
|
||||
//
|
||||
// Charging ten there is what makes the stated per-line ceiling hold
|
||||
// for the tty handler as well: U+1000C encodes as F0 90 80 8C, every
|
||||
// byte >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
|
||||
// net/textproto does not strip, so a header can be filled with them.
|
||||
//
|
||||
// Both handlers pass printable runes through as their own UTF-8, so
|
||||
// unicode.IsPrint separates the escaped cases from the plain ones for
|
||||
// either handler.
|
||||
func EncodedBytes(r rune) int {
|
||||
const (
|
||||
// A backslash and the character itself.
|
||||
shortEscapeBytes = 2
|
||||
// \uXXXX, which is also the width of \u00XX.
|
||||
escapedRuneBytes = 6
|
||||
// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
|
||||
// rune outside the basic multilingual plane.
|
||||
escapedAstralRuneBytes = 10
|
||||
// The first code point strconv.Quote spells with \U.
|
||||
firstAstralRune = 0x10000
|
||||
)
|
||||
|
||||
switch {
|
||||
case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
|
||||
return shortEscapeBytes
|
||||
case !unicode.IsPrint(r) && r >= firstAstralRune:
|
||||
return escapedAstralRuneBytes
|
||||
case !unicode.IsPrint(r):
|
||||
return escapedRuneBytes
|
||||
default:
|
||||
return utf8.RuneLen(r)
|
||||
}
|
||||
}
|
||||
|
||||
// Truncate caps s at maxBytes of ENCODED output, marking the value
|
||||
// when it cuts.
|
||||
//
|
||||
// Budgeting raw bytes would not bound the line. Escaping only ever
|
||||
// grows a value, so a raw budget spent on characters the encoder
|
||||
// escapes buys a field several times its nominal size — and the line
|
||||
// is the thing an operator is told to multiply by their request rate.
|
||||
// Charging each rune what it will actually cost is what makes the
|
||||
// stated ceiling true rather than merely larger. The visible
|
||||
// consequence is that an escape-heavy value keeps a shorter prefix
|
||||
// than a plain one, which is the correct trade.
|
||||
//
|
||||
// The result is always valid UTF-8. A cut on a byte boundary can split
|
||||
// a multi-byte rune, and a header — or a SQL literal — can carry bytes
|
||||
// that were never valid UTF-8 to begin with; both are dropped rather
|
||||
// than kept, since an encoder would otherwise spend six bytes
|
||||
// replacing each one.
|
||||
func Truncate(s string, maxBytes int) string {
|
||||
// No rune encodes to fewer bytes than it occupies, so nothing past
|
||||
// maxBytes raw can fit the budget. Slicing first bounds the scan
|
||||
// below to the budget rather than to the size of the value the
|
||||
// client sent.
|
||||
window, cut := s, false
|
||||
if len(window) > maxBytes {
|
||||
window, cut = window[:maxBytes], true
|
||||
}
|
||||
|
||||
var (
|
||||
kept strings.Builder
|
||||
spent int
|
||||
)
|
||||
|
||||
for i := 0; i < len(window); {
|
||||
r, size := utf8.DecodeRuneInString(window[i:])
|
||||
if r == utf8.RuneError && size == 1 {
|
||||
i += size
|
||||
|
||||
continue
|
||||
}
|
||||
|
||||
cost := EncodedBytes(r)
|
||||
if spent+cost > maxBytes {
|
||||
cut = true
|
||||
|
||||
break
|
||||
}
|
||||
|
||||
spent += cost
|
||||
|
||||
kept.WriteString(window[i : i+size])
|
||||
|
||||
i += size
|
||||
}
|
||||
|
||||
if !cut {
|
||||
return kept.String()
|
||||
}
|
||||
|
||||
return kept.String() + truncationMarker
|
||||
}
|
||||
202
internal/logfield/logfield_test.go
Normal file
202
internal/logfield/logfield_test.go
Normal file
@@ -0,0 +1,202 @@
|
||||
package logfield_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"log/slog"
|
||||
"strings"
|
||||
"testing"
|
||||
"unicode/utf8"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"sneak.berlin/go/webhooker/internal/logfield"
|
||||
)
|
||||
|
||||
// encodedCost is what a whole string costs on a line, by the same
|
||||
// accounting Truncate spends its budget with.
|
||||
func encodedCost(s string) int {
|
||||
total := 0
|
||||
for _, r := range s {
|
||||
total += logfield.EncodedBytes(r)
|
||||
}
|
||||
|
||||
return total
|
||||
}
|
||||
|
||||
// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
|
||||
// version of the line-length assertions elsewhere.
|
||||
//
|
||||
// A line ceiling has slack in it by construction, so a line-level
|
||||
// assertion only catches a raw-byte budget for the fills with the
|
||||
// widest multiplier. Here the budget is checked against exactly what
|
||||
// it bought: a value built from a single rune must keep exactly
|
||||
// MaxBytes/EncodedBytes(r) of them, for every rune, with nothing
|
||||
// spare.
|
||||
func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for name, r := range map[string]rune{
|
||||
"plain": 'x',
|
||||
"quote": '"',
|
||||
"backslash": '\\',
|
||||
"tab": '\t',
|
||||
"newline": '\n',
|
||||
"carriage_return": '\r',
|
||||
"c0_control": '',
|
||||
"del": '',
|
||||
"line_separator": '
',
|
||||
"astral_nonprintable": '\U0001000C',
|
||||
"multibyte_printable": 'é',
|
||||
"three_byte_printable": '€',
|
||||
"emoji_printable": '\U0001F600',
|
||||
} {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
cost := logfield.EncodedBytes(r)
|
||||
want := logfield.MaxBytes / cost
|
||||
|
||||
// Far past the budget under either accounting.
|
||||
in := strings.Repeat(string(r), logfield.MaxBytes*2)
|
||||
|
||||
got := logfield.Truncate(in, logfield.MaxBytes)
|
||||
|
||||
assert.True(
|
||||
t, strings.HasSuffix(got, "[truncated]"),
|
||||
"a value past the budget must be marked",
|
||||
)
|
||||
|
||||
kept := strings.TrimSuffix(got, "[truncated]")
|
||||
|
||||
assert.Equal(
|
||||
t, want, utf8.RuneCountInString(kept),
|
||||
"budget bought the wrong number of runes at "+
|
||||
"%d encoded bytes each", cost,
|
||||
)
|
||||
assert.LessOrEqual(
|
||||
t, encodedCost(kept), logfield.MaxBytes,
|
||||
)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestEncodedBytes_CoversWhatTheHandlersActuallyEmit measures the
|
||||
// charge against what slog really writes rather than against a
|
||||
// reading of its source, over both handlers internal/logger can
|
||||
// install. An undercharged rune fails here rather than quietly
|
||||
// falsifying every stated line ceiling.
|
||||
func TestEncodedBytes_CoversWhatTheHandlersActuallyEmit(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
emitted := func(h func(*bytes.Buffer) slog.Handler, r rune) int {
|
||||
var withValue, withoutValue bytes.Buffer
|
||||
|
||||
slog.New(h(&withValue)).Info("m", "v", string(r))
|
||||
slog.New(h(&withoutValue)).Info("m", "v", "")
|
||||
|
||||
return withValue.Len() - withoutValue.Len()
|
||||
}
|
||||
|
||||
jsonHandler := func(b *bytes.Buffer) slog.Handler {
|
||||
return slog.NewJSONHandler(b, &slog.HandlerOptions{
|
||||
ReplaceAttr: dropTime,
|
||||
})
|
||||
}
|
||||
textHandler := func(b *bytes.Buffer) slog.Handler {
|
||||
return slog.NewTextHandler(b, &slog.HandlerOptions{
|
||||
ReplaceAttr: dropTime,
|
||||
})
|
||||
}
|
||||
|
||||
// Every code point below U+0800 densely — which covers all of C0,
|
||||
// DEL, C1 and the two-byte range — plus the separators only the
|
||||
// JSON handler escapes, plus a stratified walk across the rest of
|
||||
// the assigned space and into the astral planes.
|
||||
var runes []rune
|
||||
|
||||
for r := rune(1); r < 0x800; r++ {
|
||||
runes = append(runes, r)
|
||||
}
|
||||
|
||||
runes = append(
|
||||
runes,
|
||||
'
', // LINE SEPARATOR, escaped only by the JSON handler
|
||||
'
', // PARAGRAPH SEPARATOR, likewise
|
||||
rune(0xFEFF), // ZERO WIDTH NO-BREAK SPACE
|
||||
rune(0xFFFD), // REPLACEMENT CHARACTER
|
||||
)
|
||||
|
||||
for r := rune(0x800); r <= 0x10FFFF; r += 0x1D1 {
|
||||
runes = append(runes, r)
|
||||
}
|
||||
|
||||
for _, r := range runes {
|
||||
if !utf8.ValidRune(r) {
|
||||
continue
|
||||
}
|
||||
|
||||
charged := logfield.EncodedBytes(r)
|
||||
|
||||
require.LessOrEqual(
|
||||
t, emitted(jsonHandler, r), charged,
|
||||
"json handler spends more than U+%04X is charged", r,
|
||||
)
|
||||
require.LessOrEqual(
|
||||
t, emitted(textHandler, r), charged,
|
||||
"text handler spends more than U+%04X is charged", r,
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
func dropTime(_ []string, a slog.Attr) slog.Attr {
|
||||
if a.Key == slog.TimeKey {
|
||||
return slog.Attr{}
|
||||
}
|
||||
|
||||
return a
|
||||
}
|
||||
|
||||
// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
|
||||
// value that fits is returned untouched, so a reader can tell a short
|
||||
// value from a cut one.
|
||||
func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
const in = "Mozilla/5.0 (X11; Linux x86_64)"
|
||||
|
||||
assert.Equal(t, in, logfield.Truncate(in, logfield.MaxBytes))
|
||||
}
|
||||
|
||||
// TestTruncate_DropsInvalidUTF8 covers a value that was never valid
|
||||
// UTF-8 — a SQL parameter or a header can carry one. Replacing each
|
||||
// bad byte would cost six encoded bytes apiece, so they are dropped.
|
||||
func TestTruncate_DropsInvalidUTF8(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
got := logfield.Truncate("a\xffb\xfec", logfield.MaxBytes)
|
||||
|
||||
assert.Equal(t, "abc", got)
|
||||
assert.True(t, utf8.ValidString(got))
|
||||
}
|
||||
|
||||
// TestTruncate_NeverSplitsARune covers a cut landing inside a
|
||||
// multi-byte encoding.
|
||||
func TestTruncate_NeverSplitsARune(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// A three-byte printable rune, so a small budget lands inside the
|
||||
// encoding rather than between two of them.
|
||||
in := strings.Repeat("€", logfield.MaxBytes)
|
||||
|
||||
for budget := 1; budget <= 16; budget++ {
|
||||
got := strings.TrimSuffix(
|
||||
logfield.Truncate(in, budget), "[truncated]",
|
||||
)
|
||||
|
||||
assert.True(
|
||||
t, utf8.ValidString(got),
|
||||
"budget %d produced invalid UTF-8", budget,
|
||||
)
|
||||
assert.LessOrEqual(t, encodedCost(got), budget)
|
||||
}
|
||||
}
|
||||
@@ -6,11 +6,8 @@ import (
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"strings"
|
||||
"sync"
|
||||
"time"
|
||||
"unicode"
|
||||
"unicode/utf8"
|
||||
|
||||
basicauth "github.com/99designs/basicauth-go"
|
||||
"github.com/go-chi/chi"
|
||||
@@ -22,6 +19,7 @@ import (
|
||||
"go.uber.org/fx"
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/globals"
|
||||
"sneak.berlin/go/webhooker/internal/logfield"
|
||||
"sneak.berlin/go/webhooker/internal/logger"
|
||||
"sneak.berlin/go/webhooker/internal/session"
|
||||
)
|
||||
@@ -44,16 +42,6 @@ const (
|
||||
// pick the size of the line it writes.
|
||||
redactedQuery = "?(redacted)"
|
||||
|
||||
// maxLogFieldBytes bounds each access log field whose value the
|
||||
// client supplies outright: the URL, the User-Agent and the
|
||||
// Referer. The budget is spent in ENCODED bytes (see
|
||||
// truncateLogField), so 512 still holds a real browser's User-Agent
|
||||
// whole — those are plain ASCII, which encodes one byte for one —
|
||||
// while a value built from characters the encoder escapes keeps a
|
||||
// shorter prefix. That is the intended trade: 500 quotation marks
|
||||
// are not a debugging asset.
|
||||
maxLogFieldBytes = 512
|
||||
|
||||
// maxLogRequestIDBytes bounds the request id, which is also
|
||||
// client-supplied: chi's RequestID middleware passes an inbound
|
||||
// X-Request-Id header through verbatim. Its generated form is an
|
||||
@@ -66,15 +54,10 @@ const (
|
||||
// is half this.
|
||||
maxLogMethodBytes = 32
|
||||
|
||||
// truncationMarker is appended to any field the access log cut, so
|
||||
// a short value and a truncated one cannot be confused. It is
|
||||
// charged on top of the budget, not inside it.
|
||||
truncationMarker = "[truncated]"
|
||||
|
||||
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
|
||||
// and the number an operator multiplies by the request rate to size
|
||||
// log storage. It is not an observation of a sample: it is the sum
|
||||
// of the budgets above, each of which truncateLogField enforces in
|
||||
// of the field budgets, each of which logfield.Truncate enforces in
|
||||
// ENCODED bytes, plus the part of the line no client can influence.
|
||||
//
|
||||
// url, useragent, referer 3*(512+11) = 1569
|
||||
@@ -84,6 +67,9 @@ const (
|
||||
// ----
|
||||
// 2087
|
||||
//
|
||||
// The 512 is logfield.MaxBytes; the 11 is the truncation marker,
|
||||
// charged on top of each budget rather than inside it.
|
||||
//
|
||||
// The fixed portion is the JSON punctuation, the field names, the
|
||||
// level and the message, both timestamps at their longest, an IPv6
|
||||
// remoteIP with a zone, a three-digit status and a full-width int64
|
||||
@@ -91,13 +77,29 @@ const (
|
||||
// than sitting on the arithmetic.
|
||||
//
|
||||
// The tty text handler in internal/logger is covered by the same
|
||||
// figure. encodedLogFieldBytes charges every rune at least what
|
||||
// figure. logfield.EncodedBytes charges every rune at least what
|
||||
// the wider of the two handlers emits for it — including the ten
|
||||
// bytes strconv.Quote spends on a non-printable rune at or above
|
||||
// U+10000, which is four more than the JSON handler ever spends —
|
||||
// so each budget bounds the encoded field under either handler.
|
||||
// The text handler's fixed portion is 286, the smaller of the two,
|
||||
// which puts its worst case at 2037.
|
||||
//
|
||||
// The access log is the widest line this service writes that
|
||||
// carries client-chosen text, so the figure is also the ceiling on
|
||||
// the other writer that does: the GORM adapter in
|
||||
// internal/gormlog, whose widest line spends two logfield.MaxBytes
|
||||
// budgets (the interpolated SQL and the driver error) against a
|
||||
// fixed portion smaller than this one's.
|
||||
// internal/gormlog/gormlog_test.go asserts that against this
|
||||
// constant directly rather than leaving it as arithmetic.
|
||||
//
|
||||
// It is not the widest line the service can write. A handler panic
|
||||
// arrives through net/http's nil ErrorLog as one record carrying a
|
||||
// whole goroutine stack, measured at 2,772 bytes. That value is
|
||||
// the runtime's, not a client's, so it is a carve-out this ceiling
|
||||
// states rather than covers; see README.md and
|
||||
// https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
@@ -174,114 +176,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
|
||||
lrw.ResponseWriter.WriteHeader(code)
|
||||
}
|
||||
|
||||
// encodedLogFieldBytes is what r costs on the line once the log
|
||||
// handler has escaped it, taking the worse of the two handlers
|
||||
// internal/logger configures.
|
||||
//
|
||||
// slog's JSON handler escapes quote, backslash, newline, carriage
|
||||
// return and tab to two bytes each, and every other C0 control plus
|
||||
// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
|
||||
// passes every other rune through as its own UTF-8. Its text handler
|
||||
// quotes with strconv.Quote, which spells a non-printable rune below
|
||||
// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
|
||||
// bytes, not six. The text handler is therefore the worse of the two
|
||||
// for every non-printable rune, and by four bytes apiece for the
|
||||
// 955,086 unassigned, private-use and format code points on planes 1
|
||||
// to 16.
|
||||
//
|
||||
// Charging ten there is what makes MaxAccessLogLineBytes hold for the
|
||||
// tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
|
||||
// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
|
||||
// net/textproto does not strip, so a header can be filled with them.
|
||||
//
|
||||
// Both handlers pass printable runes through as their own UTF-8, so
|
||||
// unicode.IsPrint separates the escaped cases from the plain ones for
|
||||
// either handler.
|
||||
func encodedLogFieldBytes(r rune) int {
|
||||
const (
|
||||
// A backslash and the character itself.
|
||||
shortEscapeBytes = 2
|
||||
// \uXXXX, which is also the width of \u00XX.
|
||||
escapedRuneBytes = 6
|
||||
// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
|
||||
// rune outside the basic multilingual plane.
|
||||
escapedAstralRuneBytes = 10
|
||||
// The first code point strconv.Quote spells with \U.
|
||||
firstAstralRune = 0x10000
|
||||
)
|
||||
|
||||
switch {
|
||||
case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
|
||||
return shortEscapeBytes
|
||||
case !unicode.IsPrint(r) && r >= firstAstralRune:
|
||||
return escapedAstralRuneBytes
|
||||
case !unicode.IsPrint(r):
|
||||
return escapedRuneBytes
|
||||
default:
|
||||
return utf8.RuneLen(r)
|
||||
}
|
||||
}
|
||||
|
||||
// truncateLogField caps s at maxBytes of ENCODED output, marking the
|
||||
// value when it cuts.
|
||||
//
|
||||
// Budgeting raw bytes would not bound the line. Escaping only ever
|
||||
// grows a value, so a raw budget spent on characters the encoder
|
||||
// escapes buys a field several times its nominal size — and the line
|
||||
// is the thing an operator is told to multiply by their request rate.
|
||||
// Charging each rune what it will actually cost is what makes
|
||||
// MaxAccessLogLineBytes true rather than merely larger. The visible
|
||||
// consequence is that an escape-heavy value keeps a shorter prefix
|
||||
// than a plain one, which is the correct trade.
|
||||
//
|
||||
// The result is always valid UTF-8. A cut on a byte boundary can split
|
||||
// a multi-byte rune, and a header can carry bytes that were never
|
||||
// valid UTF-8 to begin with; both are dropped rather than kept, since
|
||||
// an encoder would otherwise spend six bytes replacing each one.
|
||||
func truncateLogField(s string, maxBytes int) string {
|
||||
// No rune encodes to fewer bytes than it occupies, so nothing past
|
||||
// maxBytes raw can fit the budget. Slicing first bounds the scan
|
||||
// below to the budget rather than to the size of the header the
|
||||
// client sent.
|
||||
window, cut := s, false
|
||||
if len(window) > maxBytes {
|
||||
window, cut = window[:maxBytes], true
|
||||
}
|
||||
|
||||
var (
|
||||
kept strings.Builder
|
||||
spent int
|
||||
)
|
||||
|
||||
for i := 0; i < len(window); {
|
||||
r, size := utf8.DecodeRuneInString(window[i:])
|
||||
if r == utf8.RuneError && size == 1 {
|
||||
i += size
|
||||
|
||||
continue
|
||||
}
|
||||
|
||||
cost := encodedLogFieldBytes(r)
|
||||
if spent+cost > maxBytes {
|
||||
cut = true
|
||||
|
||||
break
|
||||
}
|
||||
|
||||
spent += cost
|
||||
|
||||
kept.WriteString(window[i : i+size])
|
||||
|
||||
i += size
|
||||
}
|
||||
|
||||
if !cut {
|
||||
return kept.String()
|
||||
}
|
||||
|
||||
return kept.String() + truncationMarker
|
||||
}
|
||||
|
||||
// concreteLogURL renders the request's own URL for the access log
|
||||
// branches that keep it, with the query string replaced by a fixed
|
||||
// marker.
|
||||
@@ -375,21 +269,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
|
||||
// line does not track the size of the request.
|
||||
s.log.Info("http request",
|
||||
"request_start", start,
|
||||
"method", truncateLogField(
|
||||
"method", logfield.Truncate(
|
||||
r.Method, maxLogMethodBytes,
|
||||
),
|
||||
"url", truncateLogField(
|
||||
"url", logfield.Truncate(
|
||||
accessLogURL(r, lrw.statusCode),
|
||||
maxLogFieldBytes,
|
||||
logfield.MaxBytes,
|
||||
),
|
||||
"useragent", truncateLogField(
|
||||
r.UserAgent(), maxLogFieldBytes,
|
||||
"useragent", logfield.Truncate(
|
||||
r.UserAgent(), logfield.MaxBytes,
|
||||
),
|
||||
"request_id", truncateLogField(
|
||||
"request_id", logfield.Truncate(
|
||||
requestID, maxLogRequestIDBytes,
|
||||
),
|
||||
"referer", truncateLogField(
|
||||
r.Referer(), maxLogFieldBytes,
|
||||
"referer", logfield.Truncate(
|
||||
r.Referer(), logfield.MaxBytes,
|
||||
),
|
||||
"proto", r.Proto,
|
||||
"remoteIP", ipFromHostPort(r.RemoteAddr),
|
||||
|
||||
@@ -2,8 +2,11 @@ package server
|
||||
|
||||
import (
|
||||
"net/http"
|
||||
"net/url"
|
||||
"strings"
|
||||
|
||||
"github.com/getsentry/sentry-go"
|
||||
"github.com/go-chi/chi"
|
||||
)
|
||||
|
||||
// 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.
|
||||
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.
|
||||
// It is its own function so a test can stand up a client wired exactly
|
||||
// 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
|
||||
// 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
|
||||
// cleared even if SendDefaultPII is ever turned on.
|
||||
func scrubSentryRequest(
|
||||
event *sentry.Event,
|
||||
_ *sentry.EventHint,
|
||||
hint *sentry.EventHint,
|
||||
) *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
|
||||
}
|
||||
|
||||
req := event.Request
|
||||
|
||||
if req.URL != "" {
|
||||
req.URL = sentryRouteURL(req.URL, pattern)
|
||||
}
|
||||
|
||||
if req.QueryString != "" {
|
||||
req.QueryString = sentryRedacted
|
||||
}
|
||||
@@ -71,6 +105,91 @@ func scrubSentryRequest(
|
||||
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
|
||||
// off-host. Dropping by allowlist rather than by blocklist is what
|
||||
// makes an unrecognised header safe: the SDK's own filter removes four
|
||||
|
||||
@@ -13,12 +13,13 @@ import (
|
||||
|
||||
"github.com/getsentry/sentry-go"
|
||||
sentryhttp "github.com/getsentry/sentry-go/http"
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"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
|
||||
// from the request without a SendDefaultPII guard.
|
||||
const (
|
||||
@@ -33,6 +34,12 @@ const (
|
||||
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
|
||||
// accepts in place of the form field.
|
||||
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
|
||||
@@ -58,19 +65,41 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
|
||||
c.events = append(c.events, event)
|
||||
}
|
||||
|
||||
// captureThroughSentryHTTP panics inside a form handler wrapped in the
|
||||
// real sentryhttp middleware and returns the event the SDK produced.
|
||||
// sentryCase drives one request through the real sentryhttp middleware
|
||||
// inside a real chi router and returns the events the SDK produced.
|
||||
//
|
||||
// This is the only construction path on which Request.Data appears:
|
||||
// sentryhttp calls Scope.SetRequest, which tees r.Body into a 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.
|
||||
// Routing through a chi mux is load-bearing, not decoration. chi puts
|
||||
// its routing context on the request context before the middleware
|
||||
// chain runs and fills it in as it matches, so a hand-built request
|
||||
// carries no route pattern at all and could not distinguish the hook
|
||||
// working from the hook falling back.
|
||||
//
|
||||
// scrub selects whether the production BeforeSend hooks are installed,
|
||||
// so the same path shows both what the SDK collects and what survives.
|
||||
func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
|
||||
// This is also the only construction path on which Request.Data
|
||||
// appears: sentryhttp calls Scope.SetRequest, which tees r.Body into a
|
||||
// 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()
|
||||
|
||||
transport := &captureTransport{}
|
||||
@@ -80,57 +109,107 @@ func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
|
||||
)
|
||||
opts.Transport = transport
|
||||
|
||||
if !scrub {
|
||||
if !c.scrub {
|
||||
opts.BeforeSend = nil
|
||||
opts.BeforeSendTransaction = nil
|
||||
}
|
||||
|
||||
if c.tracing {
|
||||
opts.EnableTracing = true
|
||||
opts.TracesSampleRate = 1.0
|
||||
}
|
||||
|
||||
client, err := sentry.NewClient(opts)
|
||||
require.NoError(t, err)
|
||||
|
||||
handler := sentryhttp.New(sentryhttp.Options{}).Handle(
|
||||
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()
|
||||
c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
|
||||
|
||||
panic("boom")
|
||||
}),
|
||||
)
|
||||
|
||||
handler.ServeHTTP(
|
||||
httptest.NewRecorder(),
|
||||
sentryLoginRequest(client),
|
||||
)
|
||||
|
||||
require.Len(t, transport.events, 1)
|
||||
|
||||
return transport.events[0]
|
||||
return transport.events
|
||||
}
|
||||
|
||||
// sentryLoginRequest builds the password POST the capture above drives,
|
||||
// with a credential planted in the body, the query and a header.
|
||||
// router mirrors setupGlobalMiddleware's ordering over the two route
|
||||
// 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 {
|
||||
form := url.Values{}
|
||||
form.Set("username", "admin")
|
||||
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(
|
||||
sentry.SetHubOnContext(
|
||||
context.Background(),
|
||||
sentry.NewHub(client, sentry.NewScope()),
|
||||
),
|
||||
http.MethodPost,
|
||||
"/pages/login?url=https://hooks.slack.com/services/"+
|
||||
sentryQueryMarker,
|
||||
strings.NewReader(form.Encode()),
|
||||
target,
|
||||
strings.NewReader(body),
|
||||
)
|
||||
|
||||
req.Header.Set(
|
||||
"Content-Type", "application/x-www-form-urlencoded",
|
||||
)
|
||||
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
|
||||
req.Header.Set("User-Agent", sentryKeptUserAgent)
|
||||
|
||||
return req
|
||||
@@ -146,15 +225,27 @@ func marshalEvent(t *testing.T, event *sentry.Event) string {
|
||||
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
|
||||
// hook exists for. Without it the SDK ships the whole POST body, the
|
||||
// raw query and the CSRF header, none of which SendDefaultPII=false
|
||||
// suppresses.
|
||||
// raw query, the CSRF header and the concrete request path, none of
|
||||
// which SendDefaultPII=false suppresses.
|
||||
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
event := captureThroughSentryHTTP(t, false)
|
||||
require.NotNil(t, event.Request)
|
||||
event := onlyEvent(t, sentryCase{
|
||||
panics: true,
|
||||
request: sentryLoginRequest,
|
||||
}.capture(t))
|
||||
|
||||
assert.Contains(
|
||||
t, event.Request.Data, sentryBodyMarker,
|
||||
@@ -165,6 +256,18 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||
assert.Contains(
|
||||
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
|
||||
@@ -173,8 +276,11 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
event := captureThroughSentryHTTP(t, true)
|
||||
require.NotNil(t, event.Request)
|
||||
event := onlyEvent(t, sentryCase{
|
||||
scrub: true,
|
||||
panics: true,
|
||||
request: sentryLoginRequest,
|
||||
}.capture(t))
|
||||
|
||||
encoded := marshalEvent(t, event)
|
||||
|
||||
@@ -189,16 +295,45 @@ func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
||||
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
|
||||
// the debugging signal: the route, the method and the metadata headers
|
||||
// still identify what failed.
|
||||
// the debugging signal: the route, its scheme and host, the method and
|
||||
// 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) {
|
||||
t.Parallel()
|
||||
|
||||
event := captureThroughSentryHTTP(t, true)
|
||||
require.NotNil(t, event.Request)
|
||||
event := onlyEvent(t, sentryCase{
|
||||
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,
|
||||
@@ -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
|
||||
// hook sees outside an HTTP handler, where no request is attached.
|
||||
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
|
||||
@@ -223,5 +479,6 @@ func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
|
||||
|
||||
require.NotNil(t, scrubbed)
|
||||
assert.Nil(t, scrubbed.Request)
|
||||
assert.Empty(t, scrubbed.Transaction)
|
||||
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user