Compare commits
1 Commits
f9d9a2c8d7
...
ce36f430fb
| Author | SHA1 | Date | |
|---|---|---|---|
| ce36f430fb |
154
README.md
154
README.md
@@ -1037,77 +1037,38 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
|
||||
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
|
||||
`X-Request-Id`.
|
||||
|
||||
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 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
|
||||
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. 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.
|
||||
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.
|
||||
|
||||
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
|
||||
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
|
||||
`Sentry-Trace`/`Baggage` are already reflected in the event's trace
|
||||
context.
|
||||
|
||||
@@ -1165,15 +1126,11 @@ 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
|
||||
at all: it is the expected outcome on both of those paths, and each
|
||||
handler already records its own miss at `DEBUG`, without the SQL. Slow
|
||||
statements are kept — at `WARN`, above the same 200 ms threshold GORM
|
||||
used, with the statement bounded — because that report is the one
|
||||
thing GORM's logger gave an operator that nothing else here does. A
|
||||
GORM line spends at most two of those budgets, the statement and the
|
||||
driver error, against a smaller fixed portion than the access log's;
|
||||
`internal/gormlog/gormlog_test.go` asserts each line against
|
||||
@@ -1194,37 +1151,16 @@ no stated bound at all.
|
||||
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.
|
||||
- Three writers that do not go through `internal/logger` at all, all
|
||||
of them on standard error. `net/http` builds its server with a nil
|
||||
`ErrorLog`, so its own faults — a handler panic and its stack, a
|
||||
superfluous `WriteHeader` — go to the `log` package's default
|
||||
logger. `fx` prints the dependency graph and the lifecycle hooks
|
||||
through its console logger at startup and shutdown. The Go runtime
|
||||
writes a panic or a fatal error itself. None of the three carries a
|
||||
client-chosen value at a client-chosen length: the three `panic`
|
||||
calls in this service are invariant guards over constants and over
|
||||
`crypto/rand`.
|
||||
|
||||
Every limiter here — receiver, login, and password change — identifies
|
||||
the client the same way, through one shared key function: the
|
||||
|
||||
@@ -1,155 +0,0 @@
|
||||
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)],
|
||||
)
|
||||
}
|
||||
}
|
||||
@@ -1,17 +1,9 @@
|
||||
package gormlog
|
||||
|
||||
import (
|
||||
"log/slog"
|
||||
"time"
|
||||
)
|
||||
import "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}
|
||||
// ExportSetSlowThreshold overrides the slow-statement threshold so a
|
||||
// test can drive the slow path without sleeping. Tests only.
|
||||
func (l *Logger) ExportSetSlowThreshold(d time.Duration) {
|
||||
l.slowThreshold = d
|
||||
}
|
||||
|
||||
@@ -96,14 +96,6 @@ func (l *Logger) Error(
|
||||
// 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,
|
||||
@@ -122,15 +114,6 @@ func (l *Logger) Trace(
|
||||
"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
|
||||
@@ -139,10 +122,18 @@ func (l *Logger) Trace(
|
||||
// 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.
|
||||
// at DEBUG, without the SQL.
|
||||
return
|
||||
|
||||
case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
|
||||
sql, rows := fc()
|
||||
l.log.WarnContext(ctx, "slow sql statement",
|
||||
"sql", logfield.Truncate(sql, logfield.MaxBytes),
|
||||
"rows", rows,
|
||||
"elapsed_ms", elapsed.Milliseconds(),
|
||||
"threshold_ms", l.slowThreshold.Milliseconds(),
|
||||
)
|
||||
|
||||
case l.log.Enabled(ctx, slog.LevelDebug):
|
||||
sql, rows := fc()
|
||||
l.log.DebugContext(ctx, "sql statement",
|
||||
|
||||
@@ -100,23 +100,12 @@ type thing struct {
|
||||
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.
|
||||
// rendered rather than against a string a test wrote by hand.
|
||||
func openDB(
|
||||
t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration,
|
||||
) *gorm.DB {
|
||||
t *testing.T, buf *bytes.Buffer, h slog.Handler,
|
||||
) (*gorm.DB, *gormlog.Logger) {
|
||||
t.Helper()
|
||||
|
||||
sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
|
||||
@@ -127,7 +116,7 @@ func openDB(
|
||||
|
||||
t.Cleanup(func() { _ = sqlDB.Close() })
|
||||
|
||||
gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow)
|
||||
gl := gormlog.New(slog.New(h))
|
||||
|
||||
gdb, err := gorm.Open(
|
||||
sqlite.Dialector{Conn: sqlDB},
|
||||
@@ -140,7 +129,7 @@ func openDB(
|
||||
// Migration chatter is not what any of these cases is about.
|
||||
buf.Reset()
|
||||
|
||||
return gdb
|
||||
return gdb, gl
|
||||
}
|
||||
|
||||
// assertBounded holds every line the adapter wrote to the stated
|
||||
@@ -183,7 +172,7 @@ func TestRecordNotFound_WritesNothing(t *testing.T) {
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||
gdb, _ := openDB(t, &buf, h.make(&buf))
|
||||
|
||||
var got thing
|
||||
|
||||
@@ -202,46 +191,6 @@ func TestRecordNotFound_WritesNothing(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// 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.
|
||||
@@ -255,12 +204,11 @@ func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(
|
||||
gdb, _ := openDB(
|
||||
t, &buf,
|
||||
slog.NewJSONHandler(&buf, &slog.HandlerOptions{
|
||||
Level: slog.LevelDebug,
|
||||
}),
|
||||
neverSlow,
|
||||
)
|
||||
|
||||
value := strings.Repeat("\x01", size)
|
||||
@@ -297,7 +245,7 @@ func TestStatementError_LineIsBounded(t *testing.T) {
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||
gdb, _ := openDB(t, &buf, h.make(&buf))
|
||||
|
||||
row := thing{ID: clientValue(f.fill), Name: "a"}
|
||||
|
||||
@@ -321,50 +269,65 @@ func TestStatementError_LineIsBounded(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// 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) {
|
||||
// TestSlowStatement_IsLoggedAndBounded proves the slow-statement
|
||||
// report survived the fix. Silencing GORM outright would have been
|
||||
// the cheaper change and would have cost this, which is the one thing
|
||||
// GORM's logger reports that nothing else in the service does.
|
||||
func TestSlowStatement_IsLoggedAndBounded(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
arms := []struct {
|
||||
name string
|
||||
slow time.Duration
|
||||
want string
|
||||
}{
|
||||
{"slow", alwaysSlow, "slow sql statement"},
|
||||
{"routine", neverSlow, "sql statement"},
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb, gl := openDB(t, &buf, h.make(&buf))
|
||||
|
||||
// Every statement counts as slow, so the branch is
|
||||
// reached without making the test wait for it.
|
||||
gl.ExportSetSlowThreshold(time.Nanosecond)
|
||||
|
||||
var got []thing
|
||||
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
|
||||
assert.Contains(
|
||||
t, buf.String(), "slow sql statement",
|
||||
)
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
for _, a := range arms {
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
name := a.name + "/" + h.name + "/" + f.name
|
||||
// TestDebugStatement_LineIsBounded covers the branch an operator
|
||||
// reaches by turning the level down: every statement is reported, so
|
||||
// every statement's interpolated parameters have to be bounded too.
|
||||
func TestDebugStatement_LineIsBounded(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
t.Run(name, func(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
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), a.slow)
|
||||
gdb, _ := openDB(t, &buf, h.make(&buf))
|
||||
|
||||
var got []thing
|
||||
var got []thing
|
||||
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
|
||||
assert.Contains(t, buf.String(), a.want)
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
assert.Contains(t, buf.String(), "sql statement")
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -18,9 +18,7 @@ import (
|
||||
"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"
|
||||
)
|
||||
@@ -168,38 +166,15 @@ func (c *stdoutCapture) drain(t *testing.T) string {
|
||||
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.
|
||||
// captureGORMDefault points GORM's package-level default logger at a
|
||||
// buffer for the duration of the test.
|
||||
//
|
||||
// This is the mutation detector. gormlogger.Default is what a bare
|
||||
// &gorm.Config{} installs, and 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.
|
||||
// &gorm.Config{} installs, and it holds an *os.File captured at
|
||||
// package init, so redirecting os.Stdout does not reach it — it has
|
||||
// to be replaced. With every gorm.Open in this service naming its own
|
||||
// logger, nothing consults this value and the buffer stays empty;
|
||||
// revert any one of them and the interpolated SQL lands here.
|
||||
func captureGORMDefault(t *testing.T) *syncBuf {
|
||||
t.Helper()
|
||||
|
||||
@@ -207,7 +182,7 @@ func captureGORMDefault(t *testing.T) *syncBuf {
|
||||
orig := gormlogger.Default
|
||||
|
||||
gormlogger.Default = gormlogger.New(
|
||||
log.New(teeStdout{buf: buf}, "", log.LstdFlags),
|
||||
log.New(buf, "", log.LstdFlags),
|
||||
gormlogger.Config{
|
||||
SlowThreshold: 200 * time.Millisecond,
|
||||
LogLevel: gormlogger.Warn,
|
||||
@@ -253,51 +228,6 @@ func floodUnauthenticated(
|
||||
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.
|
||||
@@ -384,41 +314,20 @@ func assertFloodBounded(t *testing.T, label, out string) {
|
||||
}
|
||||
}
|
||||
|
||||
// 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.
|
||||
// TestUnauthenticatedFlood_NoWriterGrowsWithTheInput is the
|
||||
// definition of done for the GORM logger defect, stated over both
|
||||
// writers at once.
|
||||
//
|
||||
// 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.
|
||||
// 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) {
|
||||
func TestUnauthenticatedFlood_NoWriterGrowsWithTheInput(
|
||||
t *testing.T,
|
||||
) {
|
||||
const (
|
||||
smallBytes = 128
|
||||
bigBytes = 8 << 10
|
||||
@@ -428,12 +337,9 @@ func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
|
||||
gormDefault := captureGORMDefault(t)
|
||||
capture := captureStdout(t)
|
||||
|
||||
var (
|
||||
h *handlers.Handlers
|
||||
mgr *database.WebhookDBManager
|
||||
)
|
||||
var h *handlers.Handlers
|
||||
|
||||
app := newTestApp(t, &h, &mgr)
|
||||
app := newTestApp(t, &h)
|
||||
app.RequireStart()
|
||||
|
||||
t.Cleanup(app.RequireStop)
|
||||
@@ -442,12 +348,10 @@ func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
|
||||
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)
|
||||
|
||||
@@ -85,21 +85,14 @@ const (
|
||||
// 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.
|
||||
// The access log is the widest line this service writes, so the
|
||||
// figure is also the ceiling on the other writer that carries
|
||||
// client-chosen text: the GORM adapter in internal/gormlog, whose
|
||||
// widest line spends two logfield.MaxBytes budgets (the
|
||||
// interpolated SQL and the driver error) against a fixed portion
|
||||
// smaller than this one's. internal/gormlog/gormlog_test.go
|
||||
// asserts that against this constant directly rather than leaving
|
||||
// it as arithmetic.
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
|
||||
@@ -2,11 +2,8 @@ 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
|
||||
@@ -14,12 +11,6 @@ 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.
|
||||
@@ -53,43 +44,18 @@ 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,
|
||||
hint *sentry.EventHint,
|
||||
_ *sentry.EventHint,
|
||||
) *sentry.Event {
|
||||
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 {
|
||||
if event == nil || event.Request == nil {
|
||||
return event
|
||||
}
|
||||
|
||||
req := event.Request
|
||||
|
||||
if req.URL != "" {
|
||||
req.URL = sentryRouteURL(req.URL, pattern)
|
||||
}
|
||||
|
||||
if req.QueryString != "" {
|
||||
req.QueryString = sentryRedacted
|
||||
}
|
||||
@@ -105,91 +71,6 @@ 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,13 +13,12 @@ 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 four markers below are the credentials a captured event could
|
||||
// The three 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 (
|
||||
@@ -34,12 +33,6 @@ 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
|
||||
@@ -65,41 +58,19 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
|
||||
c.events = append(c.events, event)
|
||||
}
|
||||
|
||||
// sentryCase drives one request through the real sentryhttp middleware
|
||||
// inside a real chi router and returns the events the SDK produced.
|
||||
// captureThroughSentryHTTP panics inside a form handler wrapped in the
|
||||
// real sentryhttp middleware and returns the event the SDK produced.
|
||||
//
|
||||
// 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.
|
||||
// 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.
|
||||
//
|
||||
// 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 {
|
||||
// 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 {
|
||||
t.Helper()
|
||||
|
||||
transport := &captureTransport{}
|
||||
@@ -109,107 +80,57 @@ func (c sentryCase) capture(t *testing.T) []*sentry.Event {
|
||||
)
|
||||
opts.Transport = transport
|
||||
|
||||
if !c.scrub {
|
||||
if !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)
|
||||
|
||||
c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
|
||||
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()
|
||||
|
||||
return transport.events
|
||||
}
|
||||
|
||||
// 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
|
||||
handler.ServeHTTP(
|
||||
httptest.NewRecorder(),
|
||||
sentryLoginRequest(client),
|
||||
)
|
||||
|
||||
require.Len(t, transport.events, 1)
|
||||
|
||||
return transport.events[0]
|
||||
}
|
||||
|
||||
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.
|
||||
// sentryLoginRequest builds the password POST the capture above drives,
|
||||
// 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,
|
||||
target,
|
||||
strings.NewReader(body),
|
||||
"/pages/login?url=https://hooks.slack.com/services/"+
|
||||
sentryQueryMarker,
|
||||
strings.NewReader(form.Encode()),
|
||||
)
|
||||
|
||||
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
|
||||
@@ -225,27 +146,15 @@ 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, the CSRF header and the concrete request path, none of
|
||||
// which SendDefaultPII=false suppresses.
|
||||
// raw query and the CSRF header, none of which SendDefaultPII=false
|
||||
// suppresses.
|
||||
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
event := onlyEvent(t, sentryCase{
|
||||
panics: true,
|
||||
request: sentryLoginRequest,
|
||||
}.capture(t))
|
||||
event := captureThroughSentryHTTP(t, false)
|
||||
require.NotNil(t, event.Request)
|
||||
|
||||
assert.Contains(
|
||||
t, event.Request.Data, sentryBodyMarker,
|
||||
@@ -256,18 +165,6 @@ 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
|
||||
@@ -276,11 +173,8 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
event := onlyEvent(t, sentryCase{
|
||||
scrub: true,
|
||||
panics: true,
|
||||
request: sentryLoginRequest,
|
||||
}.capture(t))
|
||||
event := captureThroughSentryHTTP(t, true)
|
||||
require.NotNil(t, event.Request)
|
||||
|
||||
encoded := marshalEvent(t, event)
|
||||
|
||||
@@ -295,45 +189,16 @@ 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, 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.
|
||||
// the debugging signal: the route, the method and the metadata headers
|
||||
// still identify what failed.
|
||||
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
event := onlyEvent(t, sentryCase{
|
||||
scrub: true,
|
||||
panics: true,
|
||||
request: sentryLoginRequest,
|
||||
}.capture(t))
|
||||
event := captureThroughSentryHTTP(t, true)
|
||||
require.NotNil(t, event.Request)
|
||||
|
||||
assert.Equal(
|
||||
t, "http://example.com/pages/login", event.Request.URL,
|
||||
)
|
||||
assert.Contains(t, event.Request.URL, "/pages/login")
|
||||
assert.Equal(t, http.MethodPost, event.Request.Method)
|
||||
assert.Equal(
|
||||
t,
|
||||
@@ -347,127 +212,6 @@ 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) {
|
||||
@@ -479,6 +223,5 @@ 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