Compare commits
2 Commits
ce36f430fb
...
f9d9a2c8d7
| Author | SHA1 | Date | |
|---|---|---|---|
| f9d9a2c8d7 | |||
| b573959a26 |
156
README.md
156
README.md
@@ -1037,38 +1037,77 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
|
|||||||
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
|
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
|
||||||
`X-Request-Id`.
|
`X-Request-Id`.
|
||||||
|
|
||||||
The body is replaced on every route rather than filtered by route, and
|
The same hook rewrites the request URL. The SDK builds it as
|
||||||
that is a choice rather than a limitation: the route is reachable from
|
`scheme://host/path` from the concrete path, which on the receiver
|
||||||
the hook. `sentryhttp`'s recover path puts the request on the context
|
route is `/webhook/<uuid>` in full — and that UUID is a write
|
||||||
it hands to `RecoverWithContext`, and the SDK carries that context
|
capability, not an identifier: anyone holding it can post events this
|
||||||
through to `BeforeSend` as `hint.Context`, so
|
service accepts and its targets then deliver. A tracker has its own
|
||||||
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
|
retention, access control and deletion policy, so the rule the access
|
||||||
and chi's `RoutePattern()` yields the matched pattern off it. There
|
log follows above does not carry across that boundary. What is sent is
|
||||||
are two reasons to redact unconditionally anyway. Nothing debuggable
|
the chi route pattern instead: `http://host/webhook/{uuid}`.
|
||||||
is lost:
|
|
||||||
every handler reads its fields with `PostFormValue`, so the body is
|
|
||||||
exactly where the credentials are — the target destination URL, the
|
|
||||||
login password, both password-change fields — and the one route whose
|
|
||||||
body is genuine signal is the receiver, whose body is already stored
|
|
||||||
on the event and served from the UI, so a tracker is not where anyone
|
|
||||||
reads it. And an unconditional rule cannot leak on a route somebody
|
|
||||||
forgets to add to it, which a route-conditional one can.
|
|
||||||
|
|
||||||
The headers are an allowlist for that second reason: the SDK's own
|
The scheme and the host are kept, and everything else in the URL is
|
||||||
filter removes four names and passes everything else, which would ship
|
discarded rather than edited, so a future SDK version that starts
|
||||||
`X-CSRF-Token` and the shared secrets senders put on the receiver
|
appending a query string cannot widen this. The scheme has to survive
|
||||||
route. What survives still names the failing route — scheme, host,
|
for the reason given below. The host is whatever the request's `Host`
|
||||||
path, method — and `X-Request-Id` ties the event to the local access
|
header carried — this service validates no hostname, so on a directly
|
||||||
log line that holds the rest. Nothing dropped is needed for the
|
exposed deployment a client sets it — and that same header is on the
|
||||||
likeliest use, debugging a CSRF rejection. Its three inputs are the
|
allowlist above, so scrubbing the host out of the URL would withhold
|
||||||
TLS decision, `Origin` and `Referer`; the latter two are kept, and the
|
nothing that is not sent anyway.
|
||||||
first is already in the retained URL, because the SDK derives that
|
|
||||||
URL's scheme from `r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` —
|
The body, the query string and the URL are all handled on every route
|
||||||
byte for byte the predicate `internal/middleware/csrf.go` uses to
|
rather than filtered by route. For the URL that is also what keeps the
|
||||||
choose between the `csrf.Secure(true)` and `csrf.Secure(false)`
|
event locatable: an error event is grouped by its exception and stack
|
||||||
handlers. So dropping `X-Forwarded-Proto` costs nothing. The dropped
|
trace, not by its URL, so replacing the path with the pattern costs no
|
||||||
provider headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are
|
grouping and the pattern still names the route in the UI. And an
|
||||||
real signal but are recorded locally on the event, and
|
unconditional rule cannot leak on a route somebody forgets to add to
|
||||||
|
it, which a route-conditional one can. For the body there is a second
|
||||||
|
reason: nothing debuggable is lost, because every handler reads its
|
||||||
|
fields with `PostFormValue`, so the body is exactly where the
|
||||||
|
credentials are — the target destination URL, the login password, both
|
||||||
|
password-change fields — and the one route whose body is genuine
|
||||||
|
signal is the receiver, whose body is already stored on the event and
|
||||||
|
served from the UI, so a tracker is not where anyone reads it.
|
||||||
|
|
||||||
|
The route is reachable from the hook only on the error dispatch.
|
||||||
|
`sentryhttp`'s recover path puts the request on the context it hands
|
||||||
|
to `RecoverWithContext`, and the SDK carries that context through to
|
||||||
|
`BeforeSend` as `hint.Context`, so
|
||||||
|
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
|
||||||
|
and chi's `RoutePattern()` yields the matched pattern off it. The
|
||||||
|
transaction dispatch has no such request: a finished span captures
|
||||||
|
with a nil hint, which the client replaces with an empty one, so
|
||||||
|
`BeforeSendTransaction` sees no context at all. Tracing is off in this
|
||||||
|
service, so no transaction event is produced today, but the hook is
|
||||||
|
installed on both dispatches as a floor.
|
||||||
|
|
||||||
|
Where the pattern is out of reach — the transaction dispatch, an event
|
||||||
|
captured outside the router, or a request that matched no route — the
|
||||||
|
fallback is never the concrete path. The path becomes the literal
|
||||||
|
`/(redacted)`, so the URL reads `http://host/(redacted)`; a URL the
|
||||||
|
rewrite cannot parse into a scheme is withheld whole. A transaction
|
||||||
|
event additionally carries the SDK's own `METHOD /path` name, built
|
||||||
|
from the concrete path as well; it is rewritten on the same terms, to
|
||||||
|
`POST /webhook/{uuid}` where the pattern is known and `POST
|
||||||
|
/(redacted)` where it is not.
|
||||||
|
|
||||||
|
The headers are an allowlist for the same reason the rules above are
|
||||||
|
unconditional: the SDK's own filter removes four names and passes
|
||||||
|
everything else, which would ship `X-CSRF-Token` and the shared
|
||||||
|
secrets senders put on the receiver route. What survives still names
|
||||||
|
the failing route — scheme, host, route pattern, method — and
|
||||||
|
`X-Request-Id` ties the event to the local access log line that holds
|
||||||
|
the rest. Nothing dropped is needed for the likeliest use, debugging a
|
||||||
|
CSRF rejection. Its three inputs are the TLS decision, `Origin` and
|
||||||
|
`Referer`; the latter two are kept, and the first is the scheme of the
|
||||||
|
retained URL, because the SDK derives that scheme from
|
||||||
|
`r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` — byte
|
||||||
|
for byte the predicate `internal/middleware/csrf.go` uses to choose
|
||||||
|
between the `csrf.Secure(true)` and `csrf.Secure(false)` handlers.
|
||||||
|
That is what the rewrite above preserves it for, and it is why
|
||||||
|
dropping `X-Forwarded-Proto` costs nothing. The dropped provider
|
||||||
|
headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are real
|
||||||
|
signal but are recorded locally on the event, and
|
||||||
`Sentry-Trace`/`Baggage` are already reflected in the event's trace
|
`Sentry-Trace`/`Baggage` are already reflected in the event's trace
|
||||||
context.
|
context.
|
||||||
|
|
||||||
@@ -1126,11 +1165,15 @@ writes through the same `slog` logger as everything else, so its lines
|
|||||||
take the level the operator set and the handler `internal/logger`
|
take the level the operator set and the handler `internal/logger`
|
||||||
selected, and every value it emits is spent through the same 512-byte
|
selected, and every value it emits is spent through the same 512-byte
|
||||||
encoded budget (`internal/logfield`). A record-not-found is not logged
|
encoded budget (`internal/logfield`). A record-not-found is not logged
|
||||||
at all: it is the expected outcome on both of those paths, and each
|
as an error: it is the expected outcome on both of those paths, and
|
||||||
handler already records its own miss at `DEBUG`, without the SQL. Slow
|
each handler already records its own miss at `DEBUG`, without the SQL.
|
||||||
statements are kept — at `WARN`, above the same 200 ms threshold GORM
|
Slow statements are kept — at `WARN`, above the same 200 ms threshold
|
||||||
used, with the statement bounded — because that report is the one
|
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
|
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
|
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;
|
driver error, against a smaller fixed portion than the access log's;
|
||||||
`internal/gormlog/gormlog_test.go` asserts each line against
|
`internal/gormlog/gormlog_test.go` asserts each line against
|
||||||
@@ -1151,16 +1194,37 @@ no stated bound at all.
|
|||||||
the target is for. Each line is bounded per event by the 1 MB
|
the target is for. Each line is bounded per event by the 1 MB
|
||||||
receiver body cap, and it costs nothing unless an authenticated
|
receiver body cap, and it costs nothing unless an authenticated
|
||||||
operator creates a target of that type.
|
operator creates a target of that type.
|
||||||
- Three writers that do not go through `internal/logger` at all, all
|
- Two writers that do not go through `internal/logger` at all, both on
|
||||||
of them on standard error. `net/http` builds its server with a nil
|
standard error. `fx` prints the dependency graph and the lifecycle
|
||||||
`ErrorLog`, so its own faults — a handler panic and its stack, a
|
hooks through its default console logger at startup and shutdown —
|
||||||
superfluous `WriteHeader` — go to the `log` package's default
|
nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
|
||||||
logger. `fx` prints the dependency graph and the lifecycle hooks
|
`os.Stderr`. The Go runtime writes a panic or a fatal error itself;
|
||||||
through its console logger at startup and shutdown. The Go runtime
|
a panic in a background worker rather than in a request handler is
|
||||||
writes a panic or a fatal error itself. None of the three carries a
|
the case that reaches it, since nothing recovers those. Neither
|
||||||
client-chosen value at a client-chosen length: the three `panic`
|
carries a client-chosen value at a client-chosen length: the five
|
||||||
calls in this service are invariant guards over constants and over
|
`panic` calls in this service are invariant guards over constants
|
||||||
`crypto/rand`.
|
and over `crypto/rand`.
|
||||||
|
- `net/http`'s own faults, which are **not** a separate writer.
|
||||||
|
`internal/server/http.go` builds its server with a nil `ErrorLog`,
|
||||||
|
so `net/http` falls back to the `log` package's default logger — and
|
||||||
|
`internal/logger` calls `slog.SetDefault`, which redirects that
|
||||||
|
logger into whichever handler it installed. Those lines therefore
|
||||||
|
arrive on standard output, shaped like every other line, at `INFO`.
|
||||||
|
They are not truncated and they are not bounded by the ceiling: a
|
||||||
|
handler panic arrives as one record carrying a whole goroutine
|
||||||
|
stack, measured at 2,772 bytes against the ceiling's 2,560. The
|
||||||
|
value is the runtime's, not a client's.
|
||||||
|
- A handler panic reaches that path rather than the one it looks like
|
||||||
|
it should. `internal/server/routes.go` installs chi's
|
||||||
|
`middleware.Recoverer` in front of every route, which is meant to
|
||||||
|
print the panic and its stack to standard error and answer 500. On
|
||||||
|
the Go version this service builds against it does neither: chi
|
||||||
|
v1.5.5's stack pretty-printer looks for a `panic(0x` frame that the
|
||||||
|
runtime no longer emits, walks past the end of its own slice, and
|
||||||
|
panics before writing a byte. That second panic escapes to
|
||||||
|
`net/http`, which drops the connection and reports it through the
|
||||||
|
nil `ErrorLog` above. Tracked separately in
|
||||||
|
https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||||
|
|
||||||
Every limiter here — receiver, login, and password change — identifies
|
Every limiter here — receiver, login, and password change — identifies
|
||||||
the client the same way, through one shared key function: the
|
the client the same way, through one shared key function: the
|
||||||
|
|||||||
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)],
|
||||||
|
)
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -1,9 +1,17 @@
|
|||||||
package gormlog
|
package gormlog
|
||||||
|
|
||||||
import "time"
|
import (
|
||||||
|
"log/slog"
|
||||||
|
"time"
|
||||||
|
)
|
||||||
|
|
||||||
// ExportSetSlowThreshold overrides the slow-statement threshold so a
|
// ExportNewWithSlowThreshold builds a Logger whose slow-statement
|
||||||
// test can drive the slow path without sleeping. Tests only.
|
// threshold is d rather than DefaultSlowThreshold, so a test can pin
|
||||||
func (l *Logger) ExportSetSlowThreshold(d time.Duration) {
|
// which arm of Trace it is exercising instead of racing the clock on a
|
||||||
l.slowThreshold = d
|
// 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}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -96,6 +96,14 @@ func (l *Logger) Error(
|
|||||||
// every statement it runs, so the cheap paths stay cheap: fc()
|
// every statement it runs, so the cheap paths stay cheap: fc()
|
||||||
// renders the interpolated SQL and is called only on a branch that
|
// renders the interpolated SQL and is called only on a branch that
|
||||||
// will actually emit.
|
// 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(
|
func (l *Logger) Trace(
|
||||||
ctx context.Context,
|
ctx context.Context,
|
||||||
begin time.Time,
|
begin time.Time,
|
||||||
@@ -114,17 +122,6 @@ func (l *Logger) Trace(
|
|||||||
"elapsed_ms", elapsed.Milliseconds(),
|
"elapsed_ms", elapsed.Milliseconds(),
|
||||||
)
|
)
|
||||||
|
|
||||||
case err != nil:
|
|
||||||
// gorm.ErrRecordNotFound is not an error on the paths that
|
|
||||||
// produce it here: an invented entrypoint UUID and an unknown
|
|
||||||
// username are the expected outcome of an unauthenticated
|
|
||||||
// request, not a fault. This is the IgnoreRecordNotFoundError
|
|
||||||
// behaviour, and it is unconditional rather than configurable
|
|
||||||
// because no caller in this service wants the other one — the
|
|
||||||
// two handlers that care already record the miss themselves,
|
|
||||||
// at DEBUG, without the SQL.
|
|
||||||
return
|
|
||||||
|
|
||||||
case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
|
case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
|
||||||
sql, rows := fc()
|
sql, rows := fc()
|
||||||
l.log.WarnContext(ctx, "slow sql statement",
|
l.log.WarnContext(ctx, "slow sql statement",
|
||||||
@@ -134,6 +131,18 @@ func (l *Logger) Trace(
|
|||||||
"threshold_ms", l.slowThreshold.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):
|
case l.log.Enabled(ctx, slog.LevelDebug):
|
||||||
sql, rows := fc()
|
sql, rows := fc()
|
||||||
l.log.DebugContext(ctx, "sql statement",
|
l.log.DebugContext(ctx, "sql statement",
|
||||||
|
|||||||
@@ -100,12 +100,23 @@ type thing struct {
|
|||||||
Name string
|
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,
|
// openDB opens a real SQLite database behind the adapter under test,
|
||||||
// so every assertion below is made against SQL that GORM actually
|
// so every assertion below is made against SQL that GORM actually
|
||||||
// rendered rather than against a string a test wrote by hand.
|
// rendered rather than against a string a test wrote by hand. slow is
|
||||||
|
// the adapter's slow-statement threshold.
|
||||||
func openDB(
|
func openDB(
|
||||||
t *testing.T, buf *bytes.Buffer, h slog.Handler,
|
t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration,
|
||||||
) (*gorm.DB, *gormlog.Logger) {
|
) *gorm.DB {
|
||||||
t.Helper()
|
t.Helper()
|
||||||
|
|
||||||
sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
|
sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
|
||||||
@@ -116,7 +127,7 @@ func openDB(
|
|||||||
|
|
||||||
t.Cleanup(func() { _ = sqlDB.Close() })
|
t.Cleanup(func() { _ = sqlDB.Close() })
|
||||||
|
|
||||||
gl := gormlog.New(slog.New(h))
|
gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow)
|
||||||
|
|
||||||
gdb, err := gorm.Open(
|
gdb, err := gorm.Open(
|
||||||
sqlite.Dialector{Conn: sqlDB},
|
sqlite.Dialector{Conn: sqlDB},
|
||||||
@@ -129,7 +140,7 @@ func openDB(
|
|||||||
// Migration chatter is not what any of these cases is about.
|
// Migration chatter is not what any of these cases is about.
|
||||||
buf.Reset()
|
buf.Reset()
|
||||||
|
|
||||||
return gdb, gl
|
return gdb
|
||||||
}
|
}
|
||||||
|
|
||||||
// assertBounded holds every line the adapter wrote to the stated
|
// assertBounded holds every line the adapter wrote to the stated
|
||||||
@@ -172,7 +183,7 @@ func TestRecordNotFound_WritesNothing(t *testing.T) {
|
|||||||
|
|
||||||
var buf bytes.Buffer
|
var buf bytes.Buffer
|
||||||
|
|
||||||
gdb, _ := openDB(t, &buf, h.make(&buf))
|
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||||
|
|
||||||
var got thing
|
var got thing
|
||||||
|
|
||||||
@@ -191,6 +202,46 @@ 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
|
// TestRecordNotFoundFlood_DoesNotGrowWithInput states the definition
|
||||||
// of done directly: a flood of misses at two input sizes 64 times
|
// of done directly: a flood of misses at two input sizes 64 times
|
||||||
// apart must cost the same number of bytes of log.
|
// apart must cost the same number of bytes of log.
|
||||||
@@ -204,11 +255,12 @@ func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
|
|||||||
|
|
||||||
var buf bytes.Buffer
|
var buf bytes.Buffer
|
||||||
|
|
||||||
gdb, _ := openDB(
|
gdb := openDB(
|
||||||
t, &buf,
|
t, &buf,
|
||||||
slog.NewJSONHandler(&buf, &slog.HandlerOptions{
|
slog.NewJSONHandler(&buf, &slog.HandlerOptions{
|
||||||
Level: slog.LevelDebug,
|
Level: slog.LevelDebug,
|
||||||
}),
|
}),
|
||||||
|
neverSlow,
|
||||||
)
|
)
|
||||||
|
|
||||||
value := strings.Repeat("\x01", size)
|
value := strings.Repeat("\x01", size)
|
||||||
@@ -245,7 +297,7 @@ func TestStatementError_LineIsBounded(t *testing.T) {
|
|||||||
|
|
||||||
var buf bytes.Buffer
|
var buf bytes.Buffer
|
||||||
|
|
||||||
gdb, _ := openDB(t, &buf, h.make(&buf))
|
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||||
|
|
||||||
row := thing{ID: clientValue(f.fill), Name: "a"}
|
row := thing{ID: clientValue(f.fill), Name: "a"}
|
||||||
|
|
||||||
@@ -269,65 +321,50 @@ func TestStatementError_LineIsBounded(t *testing.T) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// TestSlowStatement_IsLoggedAndBounded proves the slow-statement
|
// TestSucceedingStatement_LineIsBoundedOnEitherArm covers the two
|
||||||
// report survived the fix. Silencing GORM outright would have been
|
// arms a statement that returns no error can take, over the same
|
||||||
// the cheaper change and would have cost this, which is the one thing
|
// query, so neither can be bounded by accident of the other.
|
||||||
// GORM's logger reports that nothing else in the service does.
|
//
|
||||||
func TestSlowStatement_IsLoggedAndBounded(t *testing.T) {
|
// - 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()
|
t.Parallel()
|
||||||
|
|
||||||
for _, h := range handlers() {
|
arms := []struct {
|
||||||
for _, f := range fills() {
|
name string
|
||||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
slow time.Duration
|
||||||
t.Parallel()
|
want string
|
||||||
|
}{
|
||||||
var buf bytes.Buffer
|
{"slow", alwaysSlow, "slow sql statement"},
|
||||||
|
{"routine", neverSlow, "sql statement"},
|
||||||
gdb, gl := openDB(t, &buf, h.make(&buf))
|
|
||||||
|
|
||||||
// Every statement counts as slow, so the branch is
|
|
||||||
// reached without making the test wait for it.
|
|
||||||
gl.ExportSetSlowThreshold(time.Nanosecond)
|
|
||||||
|
|
||||||
var got []thing
|
|
||||||
|
|
||||||
require.NoError(t, gdb.Where(
|
|
||||||
"name = ?", clientValue(f.fill),
|
|
||||||
).Find(&got).Error)
|
|
||||||
|
|
||||||
assert.Contains(
|
|
||||||
t, buf.String(), "slow sql statement",
|
|
||||||
)
|
|
||||||
assertBounded(t, buf.String())
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
}
|
||||||
}
|
|
||||||
|
|
||||||
// TestDebugStatement_LineIsBounded covers the branch an operator
|
for _, a := range arms {
|
||||||
// reaches by turning the level down: every statement is reported, so
|
for _, h := range handlers() {
|
||||||
// every statement's interpolated parameters have to be bounded too.
|
for _, f := range fills() {
|
||||||
func TestDebugStatement_LineIsBounded(t *testing.T) {
|
name := a.name + "/" + h.name + "/" + f.name
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for _, h := range handlers() {
|
t.Run(name, func(t *testing.T) {
|
||||||
for _, f := range fills() {
|
t.Parallel()
|
||||||
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))
|
gdb := openDB(t, &buf, h.make(&buf), a.slow)
|
||||||
|
|
||||||
var got []thing
|
var got []thing
|
||||||
|
|
||||||
require.NoError(t, gdb.Where(
|
require.NoError(t, gdb.Where(
|
||||||
"name = ?", clientValue(f.fill),
|
"name = ?", clientValue(f.fill),
|
||||||
).Find(&got).Error)
|
).Find(&got).Error)
|
||||||
|
|
||||||
assert.Contains(t, buf.String(), "sql statement")
|
assert.Contains(t, buf.String(), a.want)
|
||||||
assertBounded(t, buf.String())
|
assertBounded(t, buf.String())
|
||||||
})
|
})
|
||||||
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -18,7 +18,9 @@ import (
|
|||||||
"github.com/go-chi/chi"
|
"github.com/go-chi/chi"
|
||||||
"github.com/stretchr/testify/assert"
|
"github.com/stretchr/testify/assert"
|
||||||
"github.com/stretchr/testify/require"
|
"github.com/stretchr/testify/require"
|
||||||
|
"gorm.io/gorm"
|
||||||
gormlogger "gorm.io/gorm/logger"
|
gormlogger "gorm.io/gorm/logger"
|
||||||
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
"sneak.berlin/go/webhooker/internal/handlers"
|
"sneak.berlin/go/webhooker/internal/handlers"
|
||||||
"sneak.berlin/go/webhooker/internal/middleware"
|
"sneak.berlin/go/webhooker/internal/middleware"
|
||||||
)
|
)
|
||||||
@@ -166,15 +168,38 @@ func (c *stdoutCapture) drain(t *testing.T) string {
|
|||||||
return out
|
return out
|
||||||
}
|
}
|
||||||
|
|
||||||
// captureGORMDefault points GORM's package-level default logger at a
|
// teeStdout writes to a buffer and to whatever os.Stdout is at the
|
||||||
// buffer for the duration of the test.
|
// 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
|
// This is the mutation detector. gormlogger.Default is what a bare
|
||||||
// &gorm.Config{} installs, and it holds an *os.File captured at
|
// &gorm.Config{} installs, and its config here is GORM's verbatim —
|
||||||
// package init, so redirecting os.Stdout does not reach it — it has
|
// Warn, IgnoreRecordNotFoundError false — so a reverted call site
|
||||||
// to be replaced. With every gorm.Open in this service naming its own
|
// behaves as it would in production rather than as a test dialed it.
|
||||||
// logger, nothing consults this value and the buffer stays empty;
|
// With every gorm.Open in this service naming its own logger, nothing
|
||||||
// revert any one of them and the interpolated SQL lands here.
|
// 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 {
|
func captureGORMDefault(t *testing.T) *syncBuf {
|
||||||
t.Helper()
|
t.Helper()
|
||||||
|
|
||||||
@@ -182,7 +207,7 @@ func captureGORMDefault(t *testing.T) *syncBuf {
|
|||||||
orig := gormlogger.Default
|
orig := gormlogger.Default
|
||||||
|
|
||||||
gormlogger.Default = gormlogger.New(
|
gormlogger.Default = gormlogger.New(
|
||||||
log.New(buf, "", log.LstdFlags),
|
log.New(teeStdout{buf: buf}, "", log.LstdFlags),
|
||||||
gormlogger.Config{
|
gormlogger.Config{
|
||||||
SlowThreshold: 200 * time.Millisecond,
|
SlowThreshold: 200 * time.Millisecond,
|
||||||
LogLevel: gormlogger.Warn,
|
LogLevel: gormlogger.Warn,
|
||||||
@@ -228,6 +253,51 @@ func floodUnauthenticated(
|
|||||||
return requests
|
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.
|
// postWebhook drives the receiver with an invented entrypoint path.
|
||||||
// The route pattern matches any single segment, so every byte of the
|
// 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.
|
// value is the client's, and the lookup behind it misses by design.
|
||||||
@@ -314,20 +384,41 @@ func assertFloodBounded(t *testing.T, label, out string) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// TestUnauthenticatedFlood_NoWriterGrowsWithTheInput is the
|
// TestFlood_NoWriterGrowsWithTheInput is the definition of done for
|
||||||
// definition of done for the GORM logger defect, stated over both
|
// the GORM logger defect, stated over every writer at once, for two of
|
||||||
// writers at once.
|
// 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.
|
||||||
//
|
//
|
||||||
// It is deliberately not parallel: it redirects os.Stdout and
|
// What each assertion is worth, since two of the three would pass
|
||||||
// replaces gormlogger.Default, both of which are process-global. Go
|
// against a service that had never been fixed if the capture were set
|
||||||
// runs every non-parallel top-level test to completion before it
|
// up differently:
|
||||||
// resumes the parallel ones, so nothing else in this package is
|
//
|
||||||
// running while the capture is installed.
|
// - 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.
|
//nolint:paralleltest // Deliberately sequential; see above.
|
||||||
func TestUnauthenticatedFlood_NoWriterGrowsWithTheInput(
|
func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
|
||||||
t *testing.T,
|
|
||||||
) {
|
|
||||||
const (
|
const (
|
||||||
smallBytes = 128
|
smallBytes = 128
|
||||||
bigBytes = 8 << 10
|
bigBytes = 8 << 10
|
||||||
@@ -337,9 +428,12 @@ func TestUnauthenticatedFlood_NoWriterGrowsWithTheInput(
|
|||||||
gormDefault := captureGORMDefault(t)
|
gormDefault := captureGORMDefault(t)
|
||||||
capture := captureStdout(t)
|
capture := captureStdout(t)
|
||||||
|
|
||||||
var h *handlers.Handlers
|
var (
|
||||||
|
h *handlers.Handlers
|
||||||
|
mgr *database.WebhookDBManager
|
||||||
|
)
|
||||||
|
|
||||||
app := newTestApp(t, &h)
|
app := newTestApp(t, &h, &mgr)
|
||||||
app.RequireStart()
|
app.RequireStart()
|
||||||
|
|
||||||
t.Cleanup(app.RequireStop)
|
t.Cleanup(app.RequireStop)
|
||||||
@@ -348,10 +442,12 @@ func TestUnauthenticatedFlood_NoWriterGrowsWithTheInput(
|
|||||||
capture.drain(t)
|
capture.drain(t)
|
||||||
|
|
||||||
floodUnauthenticated(t, h, smallBytes, reps)
|
floodUnauthenticated(t, h, smallBytes, reps)
|
||||||
|
floodPerWebhook(t, mgr, smallBytes, reps)
|
||||||
|
|
||||||
small := capture.drain(t)
|
small := capture.drain(t)
|
||||||
|
|
||||||
requests := floodUnauthenticated(t, h, bigBytes, reps)
|
requests := floodUnauthenticated(t, h, bigBytes, reps)
|
||||||
|
requests += floodPerWebhook(t, mgr, bigBytes, reps)
|
||||||
big := capture.drain(t)
|
big := capture.drain(t)
|
||||||
|
|
||||||
assertFloodBounded(t, "small flood", small)
|
assertFloodBounded(t, "small flood", small)
|
||||||
|
|||||||
@@ -85,14 +85,21 @@ const (
|
|||||||
// The text handler's fixed portion is 286, the smaller of the two,
|
// The text handler's fixed portion is 286, the smaller of the two,
|
||||||
// which puts its worst case at 2037.
|
// which puts its worst case at 2037.
|
||||||
//
|
//
|
||||||
// The access log is the widest line this service writes, so the
|
// The access log is the widest line this service writes that
|
||||||
// figure is also the ceiling on the other writer that carries
|
// carries client-chosen text, so the figure is also the ceiling on
|
||||||
// client-chosen text: the GORM adapter in internal/gormlog, whose
|
// the other writer that does: the GORM adapter in
|
||||||
// widest line spends two logfield.MaxBytes budgets (the
|
// internal/gormlog, whose widest line spends two logfield.MaxBytes
|
||||||
// interpolated SQL and the driver error) against a fixed portion
|
// budgets (the interpolated SQL and the driver error) against a
|
||||||
// smaller than this one's. internal/gormlog/gormlog_test.go
|
// fixed portion smaller than this one's.
|
||||||
// asserts that against this constant directly rather than leaving
|
// internal/gormlog/gormlog_test.go asserts that against this
|
||||||
// it as arithmetic.
|
// constant directly rather than leaving it as arithmetic.
|
||||||
|
//
|
||||||
|
// It is not the widest line the service can write. A handler panic
|
||||||
|
// arrives through net/http's nil ErrorLog as one record carrying a
|
||||||
|
// whole goroutine stack, measured at 2,772 bytes. That value is
|
||||||
|
// the runtime's, not a client's, so it is a carve-out this ceiling
|
||||||
|
// states rather than covers; see README.md and
|
||||||
|
// https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||||
MaxAccessLogLineBytes = 2560
|
MaxAccessLogLineBytes = 2560
|
||||||
)
|
)
|
||||||
|
|
||||||
|
|||||||
@@ -2,8 +2,11 @@ package server
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"net/http"
|
"net/http"
|
||||||
|
"net/url"
|
||||||
|
"strings"
|
||||||
|
|
||||||
"github.com/getsentry/sentry-go"
|
"github.com/getsentry/sentry-go"
|
||||||
|
"github.com/go-chi/chi"
|
||||||
)
|
)
|
||||||
|
|
||||||
// sentryRedacted stands in for a withheld field on every event shipped
|
// sentryRedacted stands in for a withheld field on every event shipped
|
||||||
@@ -11,6 +14,12 @@ import (
|
|||||||
// can tell a suppressed value from an absent one.
|
// can tell a suppressed value from an absent one.
|
||||||
const sentryRedacted = "(redacted)"
|
const sentryRedacted = "(redacted)"
|
||||||
|
|
||||||
|
// sentryRedactedPath is what stands in for the request path when the
|
||||||
|
// route pattern is not reachable. It is deliberately not the concrete
|
||||||
|
// path: on the receiver route that path carries the entrypoint UUID,
|
||||||
|
// which is a write capability rather than an identifier.
|
||||||
|
const sentryRedactedPath = "/" + sentryRedacted
|
||||||
|
|
||||||
// sentryClientOptions builds the options the SDK is initialised with.
|
// sentryClientOptions builds the options the SDK is initialised with.
|
||||||
// It is its own function so a test can stand up a client wired exactly
|
// It is its own function so a test can stand up a client wired exactly
|
||||||
// as production is, with only the transport swapped.
|
// as production is, with only the transport swapped.
|
||||||
@@ -44,18 +53,43 @@ func sentryClientOptions(dsn, release string) sentry.ClientOptions {
|
|||||||
// login password and both password-change fields. None of that may
|
// login password and both password-change fields. None of that may
|
||||||
// reach a third-party service.
|
// reach a third-party service.
|
||||||
//
|
//
|
||||||
|
// URL is the third such field. NewRequest builds it as
|
||||||
|
// scheme://host/path (interfaces.go:183), and on the receiver route
|
||||||
|
// that path is /webhook/<uuid> in full — a write capability, not an
|
||||||
|
// identifier. It is rebuilt here from the chi route pattern, on every
|
||||||
|
// route, keeping the scheme and the host.
|
||||||
|
//
|
||||||
// This hook is a floor, not a default: the fields it clears stay
|
// This hook is a floor, not a default: the fields it clears stay
|
||||||
// cleared even if SendDefaultPII is ever turned on.
|
// cleared even if SendDefaultPII is ever turned on.
|
||||||
func scrubSentryRequest(
|
func scrubSentryRequest(
|
||||||
event *sentry.Event,
|
event *sentry.Event,
|
||||||
_ *sentry.EventHint,
|
hint *sentry.EventHint,
|
||||||
) *sentry.Event {
|
) *sentry.Event {
|
||||||
if event == nil || event.Request == nil {
|
if event == nil {
|
||||||
|
return event
|
||||||
|
}
|
||||||
|
|
||||||
|
pattern := sentryRoutePattern(hint)
|
||||||
|
|
||||||
|
// Only transaction events carry a Transaction name, and the SDK
|
||||||
|
// builds it from the concrete path too (sentryhttp.go:105 via
|
||||||
|
// tracing.go:553). Rewritten on the same terms.
|
||||||
|
if event.Transaction != "" {
|
||||||
|
event.Transaction = sentryTransactionName(
|
||||||
|
event.Transaction, pattern,
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
|
if event.Request == nil {
|
||||||
return event
|
return event
|
||||||
}
|
}
|
||||||
|
|
||||||
req := event.Request
|
req := event.Request
|
||||||
|
|
||||||
|
if req.URL != "" {
|
||||||
|
req.URL = sentryRouteURL(req.URL, pattern)
|
||||||
|
}
|
||||||
|
|
||||||
if req.QueryString != "" {
|
if req.QueryString != "" {
|
||||||
req.QueryString = sentryRedacted
|
req.QueryString = sentryRedacted
|
||||||
}
|
}
|
||||||
@@ -71,6 +105,91 @@ func scrubSentryRequest(
|
|||||||
return event
|
return event
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// sentryRoutePattern returns the chi route pattern for the request the
|
||||||
|
// hint carries, or "" when it is not reachable.
|
||||||
|
//
|
||||||
|
// The request is reachable on the error dispatch only. sentryhttp's
|
||||||
|
// recover path calls RecoverWithContext with the request on the
|
||||||
|
// context under sentry.RequestContextKey (sentryhttp.go:124-125), and
|
||||||
|
// the client copies that context onto the hint (client.go:484-485)
|
||||||
|
// before handing it to BeforeSend (client.go:631). chi's routing
|
||||||
|
// context is a pointer placed on the request context before the
|
||||||
|
// middleware chain runs (chi mux.go:84) and filled in as the mux
|
||||||
|
// routes, so by the time a handler panics it names the matched route.
|
||||||
|
//
|
||||||
|
// The transaction dispatch has no such request: Span.doFinish calls
|
||||||
|
// hub.CaptureEvent (tracing.go:356), which passes a nil hint that the
|
||||||
|
// client replaces with an empty one (client.go:620-622). The pattern
|
||||||
|
// is therefore always "" there, and the callers fall back.
|
||||||
|
func sentryRoutePattern(hint *sentry.EventHint) string {
|
||||||
|
if hint == nil || hint.Context == nil {
|
||||||
|
return ""
|
||||||
|
}
|
||||||
|
|
||||||
|
req, ok := hint.Context.Value(
|
||||||
|
sentry.RequestContextKey,
|
||||||
|
).(*http.Request)
|
||||||
|
if !ok || req == nil {
|
||||||
|
return ""
|
||||||
|
}
|
||||||
|
|
||||||
|
rctx := chi.RouteContext(req.Context())
|
||||||
|
if rctx == nil {
|
||||||
|
return ""
|
||||||
|
}
|
||||||
|
|
||||||
|
// Empty when no route matched, which is the fallback case too.
|
||||||
|
return rctx.RoutePattern()
|
||||||
|
}
|
||||||
|
|
||||||
|
// sentryRouteURL rebuilds an event's request URL with the route
|
||||||
|
// pattern in place of the concrete path.
|
||||||
|
//
|
||||||
|
// The scheme is load-bearing and is kept: the SDK derives it from
|
||||||
|
// r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
|
||||||
|
// (interfaces.go:180), byte for byte the predicate
|
||||||
|
// internal/middleware/csrf.go uses, so it is the CSRF TLS decision and
|
||||||
|
// the reason dropping X-Forwarded-Proto from the header allowlist
|
||||||
|
// costs nothing. The host is parsed.Host of the SDK's
|
||||||
|
// scheme://r.Host/path, so it is whatever the client's Host header
|
||||||
|
// carried: this service validates no hostname. It is kept because that
|
||||||
|
// same header is on the allowlist, so scrubbing it here would withhold
|
||||||
|
// nothing that is not sent anyway.
|
||||||
|
//
|
||||||
|
// Everything else in the URL is discarded rather than edited, so a
|
||||||
|
// future SDK that starts appending a query string cannot widen this.
|
||||||
|
func sentryRouteURL(rawURL, pattern string) string {
|
||||||
|
parsed, err := url.Parse(rawURL)
|
||||||
|
if err != nil || parsed.Scheme == "" {
|
||||||
|
// Not a shape this can safely take apart.
|
||||||
|
return sentryRedacted
|
||||||
|
}
|
||||||
|
|
||||||
|
if pattern == "" {
|
||||||
|
pattern = sentryRedactedPath
|
||||||
|
}
|
||||||
|
|
||||||
|
return parsed.Scheme + "://" + parsed.Host + pattern
|
||||||
|
}
|
||||||
|
|
||||||
|
// sentryTransactionName rebuilds the SDK's "METHOD /path" transaction
|
||||||
|
// name with the route pattern in place of the concrete path. Method is
|
||||||
|
// kept for the same reason Request.Method is: net/http admits only a
|
||||||
|
// bounded token there. A name in any other shape is withheld whole,
|
||||||
|
// since nothing can be said about which part of it is a path.
|
||||||
|
func sentryTransactionName(name, pattern string) string {
|
||||||
|
method, _, found := strings.Cut(name, " ")
|
||||||
|
if !found {
|
||||||
|
return sentryRedacted
|
||||||
|
}
|
||||||
|
|
||||||
|
if pattern == "" {
|
||||||
|
pattern = sentryRedactedPath
|
||||||
|
}
|
||||||
|
|
||||||
|
return method + " " + pattern
|
||||||
|
}
|
||||||
|
|
||||||
// keptSentryHeaders returns the subset of headers an event may carry
|
// keptSentryHeaders returns the subset of headers an event may carry
|
||||||
// off-host. Dropping by allowlist rather than by blocklist is what
|
// off-host. Dropping by allowlist rather than by blocklist is what
|
||||||
// makes an unrecognised header safe: the SDK's own filter removes four
|
// makes an unrecognised header safe: the SDK's own filter removes four
|
||||||
|
|||||||
@@ -13,12 +13,13 @@ import (
|
|||||||
|
|
||||||
"github.com/getsentry/sentry-go"
|
"github.com/getsentry/sentry-go"
|
||||||
sentryhttp "github.com/getsentry/sentry-go/http"
|
sentryhttp "github.com/getsentry/sentry-go/http"
|
||||||
|
"github.com/go-chi/chi"
|
||||||
"github.com/stretchr/testify/assert"
|
"github.com/stretchr/testify/assert"
|
||||||
"github.com/stretchr/testify/require"
|
"github.com/stretchr/testify/require"
|
||||||
"sneak.berlin/go/webhooker/internal/server"
|
"sneak.berlin/go/webhooker/internal/server"
|
||||||
)
|
)
|
||||||
|
|
||||||
// The three markers below are the credentials a captured event could
|
// The four markers below are the credentials a captured event could
|
||||||
// carry off-host, one per field of sentry.Request that the SDK fills
|
// carry off-host, one per field of sentry.Request that the SDK fills
|
||||||
// from the request without a SendDefaultPII guard.
|
// from the request without a SendDefaultPII guard.
|
||||||
const (
|
const (
|
||||||
@@ -33,6 +34,12 @@ const (
|
|||||||
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
|
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
|
||||||
// accepts in place of the form field.
|
// accepts in place of the form field.
|
||||||
sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ"
|
sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ"
|
||||||
|
|
||||||
|
// sentryReceiverUUID is the entrypoint identifier in the path of
|
||||||
|
// a receiver request. It is a write capability: anyone holding
|
||||||
|
// it can POST events this service accepts and its targets then
|
||||||
|
// deliver, so it may not reach a third-party tracker.
|
||||||
|
sentryReceiverUUID = "6d1f9c2a-3b7e-4f58-9a0d-c0ffeebadc0d"
|
||||||
)
|
)
|
||||||
|
|
||||||
// sentryKeptUserAgent is a non-secret header value planted so the
|
// sentryKeptUserAgent is a non-secret header value planted so the
|
||||||
@@ -58,19 +65,41 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
|
|||||||
c.events = append(c.events, event)
|
c.events = append(c.events, event)
|
||||||
}
|
}
|
||||||
|
|
||||||
// captureThroughSentryHTTP panics inside a form handler wrapped in the
|
// sentryCase drives one request through the real sentryhttp middleware
|
||||||
// real sentryhttp middleware and returns the event the SDK produced.
|
// inside a real chi router and returns the events the SDK produced.
|
||||||
//
|
//
|
||||||
// This is the only construction path on which Request.Data appears:
|
// Routing through a chi mux is load-bearing, not decoration. chi puts
|
||||||
// sentryhttp calls Scope.SetRequest, which tees r.Body into a 10 KiB
|
// its routing context on the request context before the middleware
|
||||||
// buffer, ParseForm drains the tee, and Scope.ApplyToEvent copies the
|
// chain runs and fills it in as it matches, so a hand-built request
|
||||||
// buffer into the event inside prepareEvent — before BeforeSend runs.
|
// carries no route pattern at all and could not distinguish the hook
|
||||||
// A hand-built sentry.NewRequest never reads the body and so cannot
|
// working from the hook falling back.
|
||||||
// regress-test any of it.
|
|
||||||
//
|
//
|
||||||
// scrub selects whether the production BeforeSend hooks are installed,
|
// This is also the only construction path on which Request.Data
|
||||||
// so the same path shows both what the SDK collects and what survives.
|
// appears: sentryhttp calls Scope.SetRequest, which tees r.Body into a
|
||||||
func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
|
// 10 KiB buffer, ParseForm drains the tee, and Scope.ApplyToEvent
|
||||||
|
// copies the buffer into the event inside prepareEvent — before
|
||||||
|
// BeforeSend runs. A hand-built sentry.NewRequest never reads the body
|
||||||
|
// and so cannot regress-test any of it.
|
||||||
|
type sentryCase struct {
|
||||||
|
// scrub selects whether the production BeforeSend hooks are
|
||||||
|
// installed, so the same path shows both what the SDK collects
|
||||||
|
// and what survives.
|
||||||
|
scrub bool
|
||||||
|
|
||||||
|
// tracing enables the transaction dispatch, which the service
|
||||||
|
// leaves off. With it on, a served request produces a
|
||||||
|
// transaction event through BeforeSendTransaction.
|
||||||
|
tracing bool
|
||||||
|
|
||||||
|
// panics selects the error dispatch, via BeforeSend.
|
||||||
|
panics bool
|
||||||
|
|
||||||
|
// request builds the request to serve, given the client whose
|
||||||
|
// hub it must carry.
|
||||||
|
request func(*sentry.Client) *http.Request
|
||||||
|
}
|
||||||
|
|
||||||
|
func (c sentryCase) capture(t *testing.T) []*sentry.Event {
|
||||||
t.Helper()
|
t.Helper()
|
||||||
|
|
||||||
transport := &captureTransport{}
|
transport := &captureTransport{}
|
||||||
@@ -80,57 +109,107 @@ func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
|
|||||||
)
|
)
|
||||||
opts.Transport = transport
|
opts.Transport = transport
|
||||||
|
|
||||||
if !scrub {
|
if !c.scrub {
|
||||||
opts.BeforeSend = nil
|
opts.BeforeSend = nil
|
||||||
opts.BeforeSendTransaction = nil
|
opts.BeforeSendTransaction = nil
|
||||||
}
|
}
|
||||||
|
|
||||||
|
if c.tracing {
|
||||||
|
opts.EnableTracing = true
|
||||||
|
opts.TracesSampleRate = 1.0
|
||||||
|
}
|
||||||
|
|
||||||
client, err := sentry.NewClient(opts)
|
client, err := sentry.NewClient(opts)
|
||||||
require.NoError(t, err)
|
require.NoError(t, err)
|
||||||
|
|
||||||
handler := sentryhttp.New(sentryhttp.Options{}).Handle(
|
c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
|
||||||
http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
|
|
||||||
// This call is what drains the tee and fills the
|
|
||||||
// buffer. Its success is asserted by the unscrubbed
|
|
||||||
// case below, which sees the body in the event.
|
|
||||||
_ = r.ParseForm()
|
|
||||||
|
|
||||||
panic("boom")
|
return transport.events
|
||||||
}),
|
|
||||||
)
|
|
||||||
|
|
||||||
handler.ServeHTTP(
|
|
||||||
httptest.NewRecorder(),
|
|
||||||
sentryLoginRequest(client),
|
|
||||||
)
|
|
||||||
|
|
||||||
require.Len(t, transport.events, 1)
|
|
||||||
|
|
||||||
return transport.events[0]
|
|
||||||
}
|
}
|
||||||
|
|
||||||
// sentryLoginRequest builds the password POST the capture above drives,
|
// router mirrors setupGlobalMiddleware's ordering over the two route
|
||||||
// with a credential planted in the body, the query and a header.
|
// patterns these tests need: a recovering middleware first, then the
|
||||||
|
// sentryhttp handler registered with Use and Repanic set, exactly as
|
||||||
|
// routes.go registers it. The local recover stands in for chi's
|
||||||
|
// middleware.Recoverer, which holds that slot in production; it is
|
||||||
|
// here only to keep panic stacks out of the test output.
|
||||||
|
func (c sentryCase) router() http.Handler {
|
||||||
|
handler := func(_ http.ResponseWriter, r *http.Request) {
|
||||||
|
// This call is what drains the body tee and fills the
|
||||||
|
// buffer. Its success is asserted by the unscrubbed case
|
||||||
|
// below, which sees the body in the event.
|
||||||
|
_ = r.ParseForm()
|
||||||
|
|
||||||
|
if c.panics {
|
||||||
|
panic("boom")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
router := chi.NewRouter()
|
||||||
|
router.Use(recoveringMiddleware)
|
||||||
|
router.Use(
|
||||||
|
sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle,
|
||||||
|
)
|
||||||
|
router.HandleFunc("/pages/login", handler)
|
||||||
|
router.HandleFunc("/webhook/{uuid}", handler)
|
||||||
|
|
||||||
|
return router
|
||||||
|
}
|
||||||
|
|
||||||
|
func recoveringMiddleware(next http.Handler) http.Handler {
|
||||||
|
return http.HandlerFunc(
|
||||||
|
func(w http.ResponseWriter, r *http.Request) {
|
||||||
|
defer func() { _ = recover() }()
|
||||||
|
|
||||||
|
next.ServeHTTP(w, r)
|
||||||
|
},
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
|
// sentryLoginRequest builds the password POST most cases drive, with a
|
||||||
|
// credential planted in the body, the query and a header.
|
||||||
func sentryLoginRequest(client *sentry.Client) *http.Request {
|
func sentryLoginRequest(client *sentry.Client) *http.Request {
|
||||||
form := url.Values{}
|
form := url.Values{}
|
||||||
form.Set("username", "admin")
|
form.Set("username", "admin")
|
||||||
form.Set("password", sentryBodyMarker)
|
form.Set("password", sentryBodyMarker)
|
||||||
|
|
||||||
|
req := sentryRequest(
|
||||||
|
client,
|
||||||
|
"/pages/login?url=https://hooks.slack.com/services/"+
|
||||||
|
sentryQueryMarker,
|
||||||
|
form.Encode(),
|
||||||
|
)
|
||||||
|
|
||||||
|
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
|
||||||
|
|
||||||
|
return req
|
||||||
|
}
|
||||||
|
|
||||||
|
// sentryReceiverRequest builds a POST to the receiver route, whose
|
||||||
|
// concrete path carries the entrypoint capability.
|
||||||
|
func sentryReceiverRequest(client *sentry.Client) *http.Request {
|
||||||
|
return sentryRequest(
|
||||||
|
client, "/webhook/"+sentryReceiverUUID, "payload=hello",
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
|
func sentryRequest(
|
||||||
|
client *sentry.Client,
|
||||||
|
target, body string,
|
||||||
|
) *http.Request {
|
||||||
req := httptest.NewRequestWithContext(
|
req := httptest.NewRequestWithContext(
|
||||||
sentry.SetHubOnContext(
|
sentry.SetHubOnContext(
|
||||||
context.Background(),
|
context.Background(),
|
||||||
sentry.NewHub(client, sentry.NewScope()),
|
sentry.NewHub(client, sentry.NewScope()),
|
||||||
),
|
),
|
||||||
http.MethodPost,
|
http.MethodPost,
|
||||||
"/pages/login?url=https://hooks.slack.com/services/"+
|
target,
|
||||||
sentryQueryMarker,
|
strings.NewReader(body),
|
||||||
strings.NewReader(form.Encode()),
|
|
||||||
)
|
)
|
||||||
|
|
||||||
req.Header.Set(
|
req.Header.Set(
|
||||||
"Content-Type", "application/x-www-form-urlencoded",
|
"Content-Type", "application/x-www-form-urlencoded",
|
||||||
)
|
)
|
||||||
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
|
|
||||||
req.Header.Set("User-Agent", sentryKeptUserAgent)
|
req.Header.Set("User-Agent", sentryKeptUserAgent)
|
||||||
|
|
||||||
return req
|
return req
|
||||||
@@ -146,15 +225,27 @@ func marshalEvent(t *testing.T, event *sentry.Event) string {
|
|||||||
return string(encoded)
|
return string(encoded)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// onlyEvent asserts a single event was captured and returns it.
|
||||||
|
func onlyEvent(t *testing.T, events []*sentry.Event) *sentry.Event {
|
||||||
|
t.Helper()
|
||||||
|
|
||||||
|
require.Len(t, events, 1)
|
||||||
|
require.NotNil(t, events[0].Request)
|
||||||
|
|
||||||
|
return events[0]
|
||||||
|
}
|
||||||
|
|
||||||
// TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the
|
// TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the
|
||||||
// hook exists for. Without it the SDK ships the whole POST body, the
|
// hook exists for. Without it the SDK ships the whole POST body, the
|
||||||
// raw query and the CSRF header, none of which SendDefaultPII=false
|
// raw query, the CSRF header and the concrete request path, none of
|
||||||
// suppresses.
|
// which SendDefaultPII=false suppresses.
|
||||||
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
event := captureThroughSentryHTTP(t, false)
|
event := onlyEvent(t, sentryCase{
|
||||||
require.NotNil(t, event.Request)
|
panics: true,
|
||||||
|
request: sentryLoginRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
assert.Contains(
|
assert.Contains(
|
||||||
t, event.Request.Data, sentryBodyMarker,
|
t, event.Request.Data, sentryBodyMarker,
|
||||||
@@ -165,6 +256,18 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
|||||||
assert.Contains(
|
assert.Contains(
|
||||||
t, marshalEvent(t, event), sentryHeaderMarker,
|
t, marshalEvent(t, event), sentryHeaderMarker,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
receiver := onlyEvent(t, sentryCase{
|
||||||
|
panics: true,
|
||||||
|
request: sentryReceiverRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
|
assert.Contains(
|
||||||
|
t, receiver.Request.URL, sentryReceiverUUID,
|
||||||
|
"the SDK is expected to build Request.URL from the "+
|
||||||
|
"concrete path; if it no longer does, the route "+
|
||||||
|
"pattern rewrite's premise changed",
|
||||||
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
// TestSentryScrub_RedactsTheCapturedRequest is the regression test: no
|
// TestSentryScrub_RedactsTheCapturedRequest is the regression test: no
|
||||||
@@ -173,8 +276,11 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
|
|||||||
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
event := captureThroughSentryHTTP(t, true)
|
event := onlyEvent(t, sentryCase{
|
||||||
require.NotNil(t, event.Request)
|
scrub: true,
|
||||||
|
panics: true,
|
||||||
|
request: sentryLoginRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
encoded := marshalEvent(t, event)
|
encoded := marshalEvent(t, event)
|
||||||
|
|
||||||
@@ -189,16 +295,45 @@ func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
|
|||||||
assert.Empty(t, event.Request.Env)
|
assert.Empty(t, event.Request.Env)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern is the
|
||||||
|
// regression test for the receiver URL: the entrypoint UUID is a write
|
||||||
|
// capability and may not reach the tracker, while the route it names
|
||||||
|
// must still be readable there.
|
||||||
|
func TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern(
|
||||||
|
t *testing.T,
|
||||||
|
) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
event := onlyEvent(t, sentryCase{
|
||||||
|
scrub: true,
|
||||||
|
panics: true,
|
||||||
|
request: sentryReceiverRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
|
assert.NotContains(
|
||||||
|
t, marshalEvent(t, event), sentryReceiverUUID,
|
||||||
|
)
|
||||||
|
assert.Equal(
|
||||||
|
t, "http://example.com/webhook/{uuid}", event.Request.URL,
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
// TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost
|
// TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost
|
||||||
// the debugging signal: the route, the method and the metadata headers
|
// the debugging signal: the route, its scheme and host, the method and
|
||||||
// still identify what failed.
|
// the metadata headers still identify what failed. On a static route
|
||||||
|
// the pattern is the path, so the URL is unchanged there.
|
||||||
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
|
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
event := captureThroughSentryHTTP(t, true)
|
event := onlyEvent(t, sentryCase{
|
||||||
require.NotNil(t, event.Request)
|
scrub: true,
|
||||||
|
panics: true,
|
||||||
|
request: sentryLoginRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
assert.Contains(t, event.Request.URL, "/pages/login")
|
assert.Equal(
|
||||||
|
t, "http://example.com/pages/login", event.Request.URL,
|
||||||
|
)
|
||||||
assert.Equal(t, http.MethodPost, event.Request.Method)
|
assert.Equal(t, http.MethodPost, event.Request.Method)
|
||||||
assert.Equal(
|
assert.Equal(
|
||||||
t,
|
t,
|
||||||
@@ -212,6 +347,127 @@ func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
|
|||||||
)
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// TestSentryScrub_RedactsTheTransactionDispatch covers the other hook.
|
||||||
|
// Span.doFinish captures with a nil hint, so BeforeSendTransaction
|
||||||
|
// gets one with no context and no request: the route pattern is out of
|
||||||
|
// reach and both the URL and the SDK-built transaction name have to
|
||||||
|
// fall back. Tracing is off in this service, so no transaction event
|
||||||
|
// is produced today; the hook is a floor against that changing.
|
||||||
|
func TestSentryScrub_RedactsTheTransactionDispatch(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
events := sentryCase{
|
||||||
|
scrub: true,
|
||||||
|
tracing: true,
|
||||||
|
request: sentryReceiverRequest,
|
||||||
|
}.capture(t)
|
||||||
|
|
||||||
|
event := onlyEvent(t, events)
|
||||||
|
require.Equal(t, "transaction", event.Type)
|
||||||
|
|
||||||
|
assert.NotContains(
|
||||||
|
t, marshalEvent(t, event), sentryReceiverUUID,
|
||||||
|
)
|
||||||
|
assert.Equal(
|
||||||
|
t, "http://example.com/(redacted)", event.Request.URL,
|
||||||
|
)
|
||||||
|
assert.Equal(t, "POST /(redacted)", event.Transaction)
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook pins
|
||||||
|
// that dispatch's premise the same way, since it is the one the
|
||||||
|
// service does not exercise today.
|
||||||
|
func TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook(
|
||||||
|
t *testing.T,
|
||||||
|
) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
event := onlyEvent(t, sentryCase{
|
||||||
|
tracing: true,
|
||||||
|
request: sentryReceiverRequest,
|
||||||
|
}.capture(t))
|
||||||
|
|
||||||
|
require.Equal(t, "transaction", event.Type)
|
||||||
|
assert.Contains(t, event.Request.URL, sentryReceiverUUID)
|
||||||
|
assert.Contains(t, event.Transaction, sentryReceiverUUID)
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestSentryScrub_FallsBackWithoutARoutePattern covers every way the
|
||||||
|
// pattern can be missing. None of them may fall back to the concrete
|
||||||
|
// path, and all of them keep the scheme, which is the CSRF TLS
|
||||||
|
// decision.
|
||||||
|
func TestSentryScrub_FallsBackWithoutARoutePattern(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
concrete := "https://example.com/webhook/" + sentryReceiverUUID
|
||||||
|
|
||||||
|
// A request with no chi routing context on it at all, which is
|
||||||
|
// what an event captured outside the router would carry.
|
||||||
|
unrouted := httptest.NewRequestWithContext(
|
||||||
|
context.Background(), http.MethodPost, concrete, nil,
|
||||||
|
)
|
||||||
|
|
||||||
|
for name, hint := range map[string]*sentry.EventHint{
|
||||||
|
"no hint": nil,
|
||||||
|
"no context": {},
|
||||||
|
"no request": {Context: context.Background()},
|
||||||
|
"unrouted request": {
|
||||||
|
Context: context.WithValue(
|
||||||
|
context.Background(),
|
||||||
|
sentry.RequestContextKey,
|
||||||
|
unrouted,
|
||||||
|
),
|
||||||
|
},
|
||||||
|
} {
|
||||||
|
t.Run(name, func(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
event := sentry.NewEvent()
|
||||||
|
event.Request = &sentry.Request{URL: concrete}
|
||||||
|
event.Transaction = "POST /webhook/" +
|
||||||
|
sentryReceiverUUID
|
||||||
|
|
||||||
|
scrubbed := server.ScrubSentryRequestForTest(
|
||||||
|
event, hint,
|
||||||
|
)
|
||||||
|
require.NotNil(t, scrubbed)
|
||||||
|
|
||||||
|
assert.Equal(
|
||||||
|
t,
|
||||||
|
"https://example.com/(redacted)",
|
||||||
|
scrubbed.Request.URL,
|
||||||
|
)
|
||||||
|
assert.Equal(
|
||||||
|
t, "POST /(redacted)", scrubbed.Transaction,
|
||||||
|
)
|
||||||
|
assert.NotContains(
|
||||||
|
t,
|
||||||
|
marshalEvent(t, scrubbed),
|
||||||
|
sentryReceiverUUID,
|
||||||
|
)
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestSentryScrub_WithholdsUnparseableValues covers the shapes the
|
||||||
|
// rewrite cannot take apart. Withholding them whole is the safe
|
||||||
|
// answer, since nothing can be said about which part is a path.
|
||||||
|
func TestSentryScrub_WithholdsUnparseableValues(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
event := sentry.NewEvent()
|
||||||
|
event.Request = &sentry.Request{
|
||||||
|
URL: "/webhook/" + sentryReceiverUUID,
|
||||||
|
}
|
||||||
|
event.Transaction = "/webhook/" + sentryReceiverUUID
|
||||||
|
|
||||||
|
scrubbed := server.ScrubSentryRequestForTest(event, nil)
|
||||||
|
require.NotNil(t, scrubbed)
|
||||||
|
|
||||||
|
assert.Equal(t, "(redacted)", scrubbed.Request.URL)
|
||||||
|
assert.Equal(t, "(redacted)", scrubbed.Transaction)
|
||||||
|
}
|
||||||
|
|
||||||
// TestSentryScrub_ToleratesEventsWithoutARequest covers the events the
|
// TestSentryScrub_ToleratesEventsWithoutARequest covers the events the
|
||||||
// hook sees outside an HTTP handler, where no request is attached.
|
// hook sees outside an HTTP handler, where no request is attached.
|
||||||
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
|
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
|
||||||
@@ -223,5 +479,6 @@ func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
|
|||||||
|
|
||||||
require.NotNil(t, scrubbed)
|
require.NotNil(t, scrubbed)
|
||||||
assert.Nil(t, scrubbed.Request)
|
assert.Nil(t, scrubbed.Request)
|
||||||
|
assert.Empty(t, scrubbed.Transaction)
|
||||||
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
|
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user