Compare commits

3 Commits

Author SHA1 Message Date
31228608d1 Log SQL with placeholders, never bound values (closes #207)
All checks were successful
check / check (push) Successful in 3m39s
With DEBUG=true the GORM adapter logged fully interpolated statements.
On a first boot that put two secrets in the log: the INSERT into
settings carrying the base64 session encryption key -- which is the
whole of the session security model, since anyone holding it can forge
an authenticated session cookie -- and the INSERT into users carrying
the admin account's Argon2id password hash. Debug logs get pasted into
issues and chats.

internal/gormlog.Logger now implements gorm.ParamsFilter and discards
the bound values, so GORM renders the statement with its placeholders
intact instead of substituting them in. This is unconditional rather
than a denylist of tables known to hold a secret: a table added later
is covered without anyone remembering to add it, and the cost of
missing one is a credential in a log. It applies at every level,
including the routine arm an operator reaches at DEBUG, which is the
only level at which a successful INSERT is written at all.

Truncation was never a fix for this. The session key is 44 base64
characters and an Argon2id hash under 100, so both fit inside every
budget the adapter applies; a truncated secret is still a secret.

internal/gormlog/firstboot_test.go boots the real graph -- config.New
reading DEBUG from the environment, internal/logger building its
production handler, database.New migrating and creating the admin
user, session.New taking the session key -- against an empty DATA_DIR,
captures stdout, and asserts that neither the session key nor the
password hash appears in it. It reads both secrets back out of the
SQLite file afterwards, so the assertions are made against the values
that boot actually generated. Three requires guard against vacuity:
the capture has to contain a DEBUG line and both INSERTs, or the
absence of the secrets proves nothing. values_test.go pins the same
property per arm of Trace, and that an INSERT keeps one placeholder
per value it bound.

Removing the filter fails all three new tests.

README documents what DEBUG=true does and does not expose, including
the one secret still logged in the clear on purpose: the initial admin
password, at INFO, once, because that line is the only place an
operator ever sees it.
2026-08-20 05:04:43 +00:00
a13e5b7ded Shut down the app when the listener fails (closes #200) (#218)
All checks were successful
check / check (push) Successful in 3m48s
2026-08-20 06:42:36 +02:00
bb30b3ad64 Fail loudly on half-set metrics auth credentials (closes #205) (#216)
Some checks failed
check / check (push) Superseded by a newer commit; never tested
2026-08-20 06:30:23 +02:00
13 changed files with 1342 additions and 49 deletions

View File

@@ -107,14 +107,26 @@ TTY detection, and security headers are always applied.
| `DATA_DIR` | Directory for all SQLite databases | `/var/lib/webhooker` |
| `DEBUG` | Enable debug logging | `false` |
| `MAINTENANCE_MODE` | Report `maintenanceMode: true` in the healthcheck JSON. It does not change how any request is served — no maintenance page exists | `false` |
| `METRICS_USERNAME` | Basic auth username for `/metrics` | `""` |
| `METRICS_PASSWORD` | Basic auth password for `/metrics` | `""` |
| `METRICS_USERNAME` | Basic auth username for `/metrics`. Must be set together with `METRICS_PASSWORD`; one without the other fails startup | `""` |
| `METRICS_PASSWORD` | Basic auth password for `/metrics`. Must be set together with `METRICS_USERNAME`; one without the other fails startup | `""` |
| `SENTRY_DSN` | Sentry error reporting DSN | `""` |
| `RETENTION_SWEEP_INTERVAL` | How often the retention reaper and archive sweeper run (Go duration, must be positive) | `1h` |
| `SESSION_IDLE_TIMEOUT` | Idle session timeout (Go duration) | `24h` |
| `RECEIVER_RATE_LIMIT` | Receiver requests/minute per IP per entrypoint (10x that per IP across the route) | `120` |
| `TRUSTED_PROXIES` | CIDRs whose forwarded headers are trusted (unset: all clients behind a proxy share one rate-limit bucket; a correct login password is never throttled either way) | `""` (none) |
#### Metrics credentials
`METRICS_USERNAME` and `METRICS_PASSWORD` are set together or not at
all. With both set, `/metrics` is served behind basic auth. With
neither set, the route is not registered and returns 404. With one set
and the other empty or unset, the process refuses to start and exits
non-zero with an error naming both variables — mounting the endpoint
on the username alone would publish it behind a password that is the
empty string, and quietly withholding it would deny an endpoint that
was asked for. The `hasMetricsAuth` field in the startup log and the
existence of the route are the same value, so they cannot disagree.
#### Trusted proxies
`TRUSTED_PROXIES` is a comma-separated list of CIDR blocks (a bare
@@ -244,6 +256,51 @@ On first startup, webhooker creates an `admin` user
with a randomly generated password and logs it to stdout. This password
is only displayed once.
#### What `DEBUG=true` exposes
`DEBUG=true` lowers the log level to `DEBUG`, which turns on every
statement GORM runs, the two by-design lookup misses on the
unauthenticated routes, and the rate limiter's own rejections. It is
meant to be safe to turn on while diagnosing a live service and safe to
paste the output of into a bug report.
What it does **not** put in the log:
- **Values bound to a SQL statement.** Statements are logged with their
placeholders, never with the values substituted into them, at every
level. That is what keeps the session encryption key out of the first
boot's `INSERT INTO settings` and the `admin` account's Argon2id
password hash out of its `INSERT INTO users` — the two statements
that made a debug log worth stealing. It applies to every table and
every statement rather than to a list of tables known to hold a
secret, so a table added later is covered without anyone remembering
to add it. The cost is that a failing statement can no longer be
replayed from the log alone: the statement, the table, the driver
error and the row count are all still there, but its values have to
come from the database.
`internal/gormlog/firstboot_test.go` boots the real graph with
`DEBUG=true` against an empty `DATA_DIR` and asserts that neither
secret appears in what that boot wrote to stdout.
The one exception is `(*gorm.DB).Scan`, which GORM logs through its
own trace recorder rather than through this filter. No production
code path calls it, and `internal/gormlog/scan_guard_test.go` fails
if a non-test file adds one.
- **Session cookies, API keys or target credentials.** None of these is
logged at any level.
What is in the log regardless of `DEBUG`, and is not a debug-logging
decision:
- **The initial `admin` password**, in the clear, once, at `INFO`, on
the first boot that creates the account. That line is the only place
it is ever shown; the database stores the hash. A first boot's output
is not safe to paste anywhere until that account's password has been
changed.
- **An authenticated operator's own configuration**, echoed back
untruncated — webhook names, target hostnames. See the logging
section under Security for the full list and for the per-line size
bound that covers unauthenticated traffic.
### Running with Docker
```bash
@@ -1406,6 +1463,24 @@ and the driver error — against a smaller fixed portion than the access
log's, and `internal/gormlog/gormlog_test.go` asserts each line against
`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
The adapter also logs no bound value at all: it implements
`gorm.ParamsFilter` and discards the parameters, so GORM renders the
statement with its placeholders intact instead of substituting the
values into it. That is a separate property from the size bound and it
is what a bound is no substitute for — the session encryption key is 44
base64 characters and an Argon2id hash under 100, so both fit inside
every budget above and a truncated secret is still a secret. It holds
on all three arms of `Trace`, including the routine one an operator
reaches at `DEBUG`, which is the only level at which a successful
`INSERT` is written at all. One GORM path does not consult the filter —
`(*gorm.DB).Scan`, which records the statement through GORM's own trace
recorder. No production code path calls it; its one caller is
`internal/database/database_test.go:91`, whose `SELECT 1` binds
nothing, and `internal/gormlog/scan_guard_test.go` fails if a non-test
file calls it. `Pluck`, `Row` and `Raw` all run through the normal
callback processor and are filtered.
See `#### What DEBUG=true exposes` under Configuration.
What that ceiling does **not** cover, stated here so the figure is not
read as more than it is:
@@ -1682,7 +1757,7 @@ abuse limit later; they are tracked as future work.
| Method | Path | Description |
| ------ | ---------- | ----------- |
| `GET` | `/metrics` | Prometheus metrics, behind basic auth. The route is registered only when `METRICS_USERNAME` is set; otherwise it does not exist and returns 404 |
| `GET` | `/metrics` | Prometheus metrics, behind basic auth. The route is registered only when `METRICS_USERNAME` and `METRICS_PASSWORD` are both set; with neither set it does not exist and returns 404, and with only one set the process refuses to start |
#### API (Planned)
@@ -1837,7 +1912,8 @@ Applied to all routes in this order:
Permissions-Policy)
3. **Logging** — Structured request logging (method, URL, status,
latency, remote IP, user agent, request ID)
4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` and
`METRICS_PASSWORD` are both set)
5. **CORS** — Cross-origin resource sharing headers
6. **Timeout** — 60-second request timeout
7. **Recoverer** — Panic recovery: one `ERROR` record through
@@ -1869,8 +1945,9 @@ being read and without reaching CSRF, the route group's remaining
middleware, or the handler. It is not rejected before *any* other
middleware, though: the global entries listed above all run first, so
such a request is still logged and given the security headers — and
counted in the metrics, on a deployment where `METRICS_USERNAME` is
set and the Metrics middleware is therefore registered at all. The
counted in the metrics, on a deployment where the `/metrics`
credentials are set and the Metrics middleware is therefore registered
at all. The
rejection itself is logged at `WARN` with the method, path and
declared length. A chunked request, or
one that lies about its length, is hard-capped by

View File

@@ -71,6 +71,16 @@ var ErrInvalidPort = errors.New("invalid port")
// nor a bare IP address.
var ErrInvalidCIDR = errors.New("invalid CIDR")
// ErrIncompleteMetricsAuth is returned when exactly one of
// METRICS_USERNAME and METRICS_PASSWORD carries a value. Neither
// fallback is acceptable: serving /metrics on the username alone
// publishes an endpoint whose password is the empty string, and
// silently leaving it unmounted withholds an endpoint the operator
// asked for. Half-set is a configuration error, so startup fails.
var ErrIncompleteMetricsAuth = errors.New(
"incomplete metrics credentials",
)
//nolint:revive // ConfigParams is a standard fx naming convention.
type ConfigParams struct {
fx.In
@@ -128,6 +138,21 @@ func (c *Config) IsProd() bool {
return c.Environment == EnvironmentProd
}
// MetricsAuthEnabled reports whether /metrics is served behind basic
// auth. It is the only answer to that question in the codebase: the
// route mount, the Prometheus recording middleware and the startup
// log's hasMetricsAuth field all read this one method, so the log
// cannot report auth as off while the route is mounted.
//
// It requires both credentials rather than the username alone.
// loadFromEnv already rejects a half-set pair, but a Config built in
// code bypasses that, and the failure mode this guards is an endpoint
// mounted with a credential map whose only password is the empty
// string.
func (c *Config) MetricsAuthEnabled() bool {
return c.MetricsUsername != "" && c.MetricsPassword != ""
}
// envString returns the value of the named environment variable,
// or an empty string if not set.
func envString(key string) string {
@@ -329,6 +354,30 @@ func envPrefixList(key string) ([]netip.Prefix, error) {
return prefixes, nil
}
// resolveMetricsAuth reads the /metrics basic-auth credentials and
// rejects a half-set pair, naming both variables either way. The
// error carries neither value: the password is a secret.
func resolveMetricsAuth() (string, string, error) {
username := envString("METRICS_USERNAME")
password := envString("METRICS_PASSWORD")
if (username == "") == (password == "") {
return username, password, nil
}
set, empty := "METRICS_USERNAME", "METRICS_PASSWORD"
if username == "" {
set, empty = empty, set
}
return "", "", fmt.Errorf(
"%w: %s is set but %s is empty; METRICS_USERNAME and "+
"METRICS_PASSWORD must both be set to serve /metrics, "+
"or both be empty to leave it unmounted",
ErrIncompleteMetricsAuth, set, empty,
)
}
// resolveEnvironment reads WEBHOOKER_ENVIRONMENT, defaulting to
// dev, and rejects unrecognised values.
func resolveEnvironment() (string, error) {
@@ -406,13 +455,18 @@ func loadFromEnv() (*Config, error) {
return nil, err
}
metricsUsername, metricsPassword, err := resolveMetricsAuth()
if err != nil {
return nil, err
}
return &Config{
DataDir: envString("DATA_DIR"),
Debug: debug,
MaintenanceMode: maintenanceMode,
Environment: environment,
MetricsUsername: envString("METRICS_USERNAME"),
MetricsPassword: envString("METRICS_PASSWORD"),
MetricsUsername: metricsUsername,
MetricsPassword: metricsPassword,
Port: port,
SentryDSN: envString("SENTRY_DSN"),
RetentionSweepInterval: retentionSweepInterval,
@@ -512,8 +566,7 @@ func New(lc fx.Lifecycle, params ConfigParams) (*Config, error) {
"receiverRateLimit", s.ReceiverRateLimit,
"trustedProxies", len(s.TrustedProxies),
"hasSentryDSN", s.SentryDSN != "",
"hasMetricsAuth",
s.MetricsUsername != "" && s.MetricsPassword != "",
"hasMetricsAuth", s.MetricsAuthEnabled(),
)
s.warnSharedRateLimitBucket(log)

View File

@@ -26,6 +26,12 @@ const (
// cidrPrivateV4 is the sample trusted-proxy block the
// TRUSTED_PROXIES cases are built from.
cidrPrivateV4 = "10.0.0.0/8"
// metricsAuthValue is the sample METRICS_PASSWORD the metrics
// credential cases are built from. It is asserted absent from
// the startup error, so it must not be a substring of either
// variable name that error prints.
metricsAuthValue = "s3cret"
)
func TestEnvironmentConfig(t *testing.T) {
@@ -726,3 +732,168 @@ func TestSharedRateLimitBucketWarning(t *testing.T) {
})
}
}
// metricsEnv describes what one subtest below puts in the
// environment for a single METRICS_ variable. A variable that is
// set to the empty string and one that is not set at all are
// distinct inputs here, because the reported bug arrived through
// the first of them.
type metricsEnv struct {
set bool
value string
}
// unset leaves the variable out of the environment entirely.
func unset() metricsEnv {
return metricsEnv{set: false, value: ""}
}
// setTo sets the variable, including to the empty string.
func setTo(value string) metricsEnv {
return metricsEnv{set: true, value: value}
}
// metricsAuthCase is one row of the table in TestMetricsAuthConfig,
// named so the table can live in its own function and keep the test
// itself short.
type metricsAuthCase struct {
name string
username metricsEnv
password metricsEnv
expectError bool
expectAuth bool
}
// metricsAuthCases enumerates every combination of the two
// credentials, counting "set to the empty string" and "not set at
// all" as separate inputs on each side.
func metricsAuthCases() []metricsAuthCase {
return []metricsAuthCase{
{
name: "both unset leaves metrics unmounted",
username: unset(),
password: unset(),
},
{
name: "both empty leaves metrics unmounted",
username: setTo(""),
password: setTo(""),
},
{
name: "both set enables metrics auth",
username: setTo("metrics"),
password: setTo(metricsAuthValue),
expectAuth: true,
},
{
name: "username with unset password fails",
username: setTo("metrics"),
password: unset(),
expectError: true,
},
{
name: "username with empty password fails",
username: setTo("metrics"),
password: setTo(""),
expectError: true,
},
{
name: "password with unset username fails",
username: unset(),
password: setTo(metricsAuthValue),
expectError: true,
},
{
name: "password with empty username fails",
username: setTo(""),
password: setTo(metricsAuthValue),
expectError: true,
},
}
}
// TestMetricsAuthConfig covers every combination of METRICS_USERNAME
// and METRICS_PASSWORD. Either both carry a value, in which case
// /metrics is served behind basic auth, or neither does, in which
// case the route is never mounted. One without the other is a
// startup error rather than a fallback: mounting on the username
// alone published /metrics behind a credential map that accepted an
// empty password, which is the defect this test exists to pin. See
// https://git.eeqj.de/sneak/webhooker/issues/205.
func TestMetricsAuthConfig(t *testing.T) {
for _, tt := range metricsAuthCases() {
t.Run(tt.name, func(t *testing.T) {
// Cannot use t.Parallel() here because t.Setenv
// is incompatible with parallel subtests.
if tt.username.set {
t.Setenv("METRICS_USERNAME", tt.username.value)
} else {
require.NoError(
t, os.Unsetenv("METRICS_USERNAME"),
)
}
if tt.password.set {
t.Setenv("METRICS_PASSWORD", tt.password.value)
} else {
require.NoError(
t, os.Unsetenv("METRICS_PASSWORD"),
)
}
if tt.expectError {
assertMetricsAuthRejected(t)
return
}
assertMetricsAuthAccepted(t, tt.expectAuth)
})
}
}
// assertMetricsAuthRejected requires that fx refused to build the
// graph, that the failure is ErrIncompleteMetricsAuth, and that the
// operator is told both variable names — the point of failing here
// rather than degrading is that the message says what to fix.
func assertMetricsAuthRejected(t *testing.T) {
t.Helper()
var cfg *config.Config
app := fx.New(
fx.NopLogger,
fx.Provide(globals.New, logger.New, config.New),
fx.Populate(&cfg),
)
err := app.Err()
require.Error(t, err)
require.ErrorIs(t, err, config.ErrIncompleteMetricsAuth)
assert.Contains(t, err.Error(), "METRICS_USERNAME")
assert.Contains(t, err.Error(), "METRICS_PASSWORD")
// The password is a secret and must not reach a startup error.
assert.NotContains(t, err.Error(), metricsAuthValue)
}
// assertMetricsAuthAccepted requires that startup succeeded and that
// MetricsAuthEnabled — the single value the /metrics mount and the
// startup log both read — reports what the environment asked for.
func assertMetricsAuthAccepted(t *testing.T, expectAuth bool) {
t.Helper()
var cfg *config.Config
app := fxtest.New(
t,
fx.Provide(globals.New, logger.New, config.New),
fx.Populate(&cfg),
)
require.NoError(t, app.Err())
app.RequireStart()
defer app.RequireStop()
assert.Equal(t, expectAuth, cfg.MetricsAuthEnabled())
}

View File

@@ -0,0 +1,229 @@
package gormlog_test
import (
"context"
"database/sql"
"os"
"path/filepath"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.uber.org/fx"
"go.uber.org/fx/fxtest"
_ "modernc.org/sqlite" // Pure Go SQLite driver.
"sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/globals"
"sneak.berlin/go/webhooker/internal/logger"
"sneak.berlin/go/webhooker/internal/session"
)
// argon2Prefix opens every encoded Argon2id hash this service
// produces. It is asserted on separately from the hash itself, so that
// a change to the password encoding cannot quietly turn the hash
// assertion into a comparison against a string the log never held.
const argon2Prefix = "$argon2id$"
// settingsInsert and usersInsert are the two statements a first boot
// runs that carry a secret. The sqlite dialector quotes identifiers
// with backticks.
const (
settingsInsert = "INSERT INTO `settings`"
usersInsert = "INSERT INTO `users`"
)
// captureStdoutToFile redirects os.Stdout into a file for the rest of
// the test and returns a function that reads back everything written
// to it.
//
// A file rather than a pipe: internal/logger writes synchronously to
// whatever os.Stdout is when it builds its handler, so once fx's start
// returns, every byte the boot produced is already in the file and no
// draining goroutine is needed to prove it. Redirecting the variable
// before the application is built is what puts the service logger —
// and therefore the GORM adapter, which writes through it — into the
// capture.
//
// The redirect also decides the handler: a regular file is not a
// character device, so internal/logger installs its JSON handler, the
// one it installs in production under a log collector.
func captureStdoutToFile(t *testing.T) func() string {
t.Helper()
path := filepath.Join(t.TempDir(), "stdout.log")
//nolint:gosec // The path is this test's own t.TempDir().
f, err := os.Create(path)
require.NoError(t, err)
orig := os.Stdout
os.Stdout = f
t.Cleanup(func() {
os.Stdout = orig
_ = f.Close()
})
return func() string {
require.NoError(t, f.Sync())
//nolint:gosec // As above.
b, readErr := os.ReadFile(path)
require.NoError(t, readErr)
return string(b)
}
}
// firstBootSecrets are the two values a first boot generates and
// stores, read back out of the database.
type firstBootSecrets struct {
sessionKey string
passwordHash string
}
// readFirstBootSecrets reads those two secrets straight out of the
// SQLite file with database/sql rather than through GORM, so that
// reading them cannot itself add a line to the log under test.
func readFirstBootSecrets(
t *testing.T, dataDir string,
) firstBootSecrets {
t.Helper()
db, err := sql.Open("sqlite", filepath.Join(
dataDir, "webhooker.db",
))
require.NoError(t, err)
defer func() { require.NoError(t, db.Close()) }()
ctx := context.Background()
var got firstBootSecrets
require.NoError(t, db.QueryRowContext(
ctx, `SELECT value FROM settings WHERE key = 'session_key'`,
).Scan(&got.sessionKey))
require.NoError(t, db.QueryRowContext(
ctx, `SELECT password FROM users WHERE username = 'admin'`,
).Scan(&got.passwordHash))
require.NotEmpty(t, got.sessionKey)
require.Contains(t, got.passwordHash, argon2Prefix)
return got
}
// bootAtDebug starts and stops the real application graph against
// dataDir with DEBUG=true, and returns everything it wrote to standard
// output.
//
// config.New reads DEBUG from the environment exactly as the binary
// does, internal/logger builds the handler it builds in production,
// database.New runs the migrations and creates the admin user, and
// session.New takes the session key. Those four are the whole of the
// path that writes either secret.
func bootAtDebug(t *testing.T, dataDir string) string {
t.Helper()
t.Setenv("DEBUG", "true")
t.Setenv("DATA_DIR", dataDir)
read := captureStdoutToFile(t)
var sess *session.Session
app := fxtest.New(
t,
fx.Provide(
globals.New,
logger.New,
config.New,
database.New,
session.New,
),
fx.Populate(&sess),
)
app.RequireStart()
app.RequireStop()
return read()
}
// requireFirstBootWasLogged is the non-vacuity half of the test below.
// Without it a build that logged no SQL at all, or that never reached
// DEBUG, would satisfy every absence assertion.
func requireFirstBootWasLogged(t *testing.T, out string) {
t.Helper()
require.Contains(
t, out, `"level":"DEBUG"`,
"DEBUG=true did not reach the logger",
)
require.Contains(
t, out, settingsInsert,
"the session key INSERT was not logged, so its absence "+
"proves nothing",
)
require.Contains(
t, out, usersInsert,
"the admin user INSERT was not logged, so its absence "+
"proves nothing",
)
}
// TestFirstBootAtDebug_LogsNeitherSecret is the definition of done.
//
// A first boot is the only boot that writes either secret. The
// settings INSERT carries the base64 session encryption key, which is
// the whole of the session security model: anyone holding it can forge
// an authenticated session cookie. The users INSERT carries the admin
// account's Argon2id hash. Under interpolated statement logging both
// landed in the log an operator diagnosing a startup problem pastes
// into an issue.
//
// The secrets are read back out of the database file afterwards, so
// the assertions are made against the values this boot actually
// generated rather than against a pattern that might not match them.
//
// What this test does not cover: the initial admin password itself,
// which internal/database logs once in the clear, on purpose, because
// that line is the only place an operator ever sees it. That is a
// separate decision from the SQL log, and it is documented in the
// README rather than asserted here.
//
// Not parallel: it redirects os.Stdout and sets environment variables,
// both process-global.
//
//nolint:paralleltest // Deliberately sequential; see above.
func TestFirstBootAtDebug_LogsNeitherSecret(t *testing.T) {
dataDir := t.TempDir()
// An empty DATA_DIR is what makes this a first boot: with a
// database already in place neither INSERT runs.
entries, err := os.ReadDir(dataDir)
require.NoError(t, err)
require.Empty(t, entries, "DATA_DIR was not empty")
out := bootAtDebug(t, dataDir)
requireFirstBootWasLogged(t, out)
secrets := readFirstBootSecrets(t, dataDir)
assert.NotContains(
t, out, secrets.sessionKey,
"the session encryption key reached the debug log",
)
assert.NotContains(
t, out, secrets.passwordHash,
"the admin password hash reached the debug log",
)
assert.NotContains(
t, out, argon2Prefix,
"an encoded Argon2id hash reached the debug log",
)
}

View File

@@ -17,6 +17,10 @@
// level the operator controls, they are shaped by whichever handler
// internal/logger selected, and every value a client can influence is
// spent through logfield.Truncate.
//
// It also logs no bound value at all. See ParamsFilter: the statement
// is written with its placeholders intact, at every level, so the
// values a statement carries never reach the log in the first place.
package gormlog
import (
@@ -26,6 +30,7 @@ import (
"log/slog"
"time"
"gorm.io/gorm"
gormlogger "gorm.io/gorm/logger"
"sneak.berlin/go/webhooker/internal/logfield"
)
@@ -47,8 +52,14 @@ type Logger struct {
}
// Interface compliance is asserted here rather than discovered at the
// gorm.Open call sites.
var _ gormlogger.Interface = (*Logger)(nil)
// gorm.Open call sites. gorm.ParamsFilter is the optional half: GORM
// type-asserts for it and silently keeps interpolating if it is
// missing, so losing it would cost no build error and no test that
// does not look at the emitted SQL.
var (
_ gormlogger.Interface = (*Logger)(nil)
_ gorm.ParamsFilter = (*Logger)(nil)
)
// New returns a GORM logger that writes through log.
func New(log *slog.Logger) *Logger {
@@ -71,6 +82,46 @@ func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface {
return l
}
// ParamsFilter drops every bound value before GORM renders a statement
// for the log, so what is logged is the statement's shape — its
// placeholders — and never the values in it.
//
// GORM builds the string it hands to Trace by calling
// Dialector.Explain(sql, vars...), which substitutes each value into
// the statement. Discarding vars here leaves the '?' placeholders in
// place, because ExplainSQL only substitutes while it still has a
// value for the next one. That happens before Trace is reached, so it
// holds on all three of its arms: the failed statement, the slow one,
// and the routine one an operator sees at DEBUG.
//
// This is the whole of the fix, and it is deliberately unconditional
// rather than a list of tables to redact. At first boot the two
// statements that carry a secret are the INSERT into settings holding
// the base64 session key — which is the entire session security model,
// since anyone with it can mint a valid cookie — and the INSERT into
// users holding the Argon2id hash. A denylist would have had to be
// extended by hand for every table added afterwards, and the cost of
// missing one is a credential in a log that gets pasted into issues.
//
// What is given up is the ability to read a value out of the log. The
// statement, the table, the error and the row count are all still
// there, which is what identifies a failing statement; reproducing it
// needs the values, and those an operator now gets from the database
// rather than from the log.
//
// One GORM path does not consult this: (*gorm.DB).Scan records the
// statement through gorm's own traceRecorder, which does not implement
// this interface. No production code path calls it; its one caller is
// internal/database/database_test.go:91, whose SELECT 1 binds nothing.
// scan_guard_test.go fails if a non-test file calls it.
// (*gorm.DB).Pluck, Row and Raw all run through the normal callback
// processor and are filtered.
func (l *Logger) ParamsFilter(
_ context.Context, sql string, _ ...any,
) (string, []any) {
return sql, nil
}
// Info logs one of GORM's own informational messages.
func (l *Logger) Info(
ctx context.Context, msg string, data ...any,
@@ -93,9 +144,9 @@ func (l *Logger) Error(
}
// Trace reports the outcome of a single statement. GORM calls it for
// every statement it runs, so the cheap paths stay cheap: fc()
// renders the interpolated SQL and is called only on a branch that
// will actually emit.
// every statement it runs, so the cheap paths stay cheap: fc() renders
// the statement — with placeholders, per ParamsFilter — 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

View File

@@ -232,7 +232,7 @@ func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) {
require.ErrorIs(t, err, gorm.ErrRecordNotFound)
assert.Contains(
t, buf.String(), "slow sql statement",
t, buf.String(), slowLine,
"a slow statement that missed was not "+
"reported as slow",
)
@@ -284,9 +284,11 @@ func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
}
// TestStatementError_LineIsBounded covers the branch that does log.
// A driver error is not ErrRecordNotFound, so the interpolated
// statement is written and on an insert the interpolated value is
// still whatever the client supplied.
// A driver error is not ErrRecordNotFound, so the statement is
// written, and the driver's own error text can quote what the client
// supplied. The statement's parameters are no longer part of that —
// see TestBoundValues_NeverReachTheLog — but the budget is what holds
// the line when the statement itself, or the error, is the long part.
func TestStatementError_LineIsBounded(t *testing.T) {
t.Parallel()
@@ -313,7 +315,7 @@ func TestStatementError_LineIsBounded(t *testing.T) {
require.Error(t, err)
assert.Contains(
t, buf.String(), "sql statement failed",
t, buf.String(), errorLine,
)
assertBounded(t, buf.String())
})
@@ -329,22 +331,22 @@ func TestStatementError_LineIsBounded(t *testing.T) {
// 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.
// down to DEBUG: every statement is reported, so every statement
// has to be bounded too.
func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
t.Parallel()
// "sql statement" is a substring of "slow sql statement", so the
// routine arm carries notWant as well: Contains alone cannot tell
// the two arms apart in that direction.
// routineLine is a substring of slowLine, so the routine arm
// carries notWant as well: Contains alone cannot tell the two arms
// apart in that direction.
arms := []struct {
name string
slow time.Duration
want string
notWant string
}{
{"slow", alwaysSlow, "slow sql statement", ""},
{"routine", neverSlow, "sql statement", "slow sql statement"},
{"slow", alwaysSlow, slowLine, ""},
{"routine", neverSlow, routineLine, slowLine},
}
for _, a := range arms {

View File

@@ -0,0 +1,260 @@
package gormlog_test
import (
"fmt"
"go/ast"
"go/parser"
"go/token"
"io/fs"
"os"
"path/filepath"
"strings"
"testing"
"github.com/stretchr/testify/require"
)
// minNonTestFiles guards the walk below against passing because it
// found nothing to look at. The tree held 60 non-test .go files when
// this was written.
const minNonTestFiles = 40
// isRowProducer reports whether name is a method that returns a
// database/sql row handle. GORM's Row and Rows return *sql.Row and
// *sql.Rows, so Scan on the result of one of them is database/sql's
// Scan and never (*gorm.DB).Scan.
func isRowProducer(name string) bool {
switch name {
case "Row", "Rows", "QueryRow", "QueryRowContext":
return true
default:
return false
}
}
// receiverIsRowHandle reports whether x is syntactically a call to a
// row producer, which is the only receiver form this check accepts for
// a Scan.
func receiverIsRowHandle(x ast.Expr) bool {
call, ok := x.(*ast.CallExpr)
if !ok {
return false
}
sel, ok := call.Fun.(*ast.SelectorExpr)
if !ok {
return false
}
return isRowProducer(sel.Sel.Name)
}
// unguardedScans returns the position of every Scan call in file whose
// receiver is not a row handle. It fails closed: a receiver it cannot
// resolve syntactically — a local variable, a struct field — is
// reported rather than assumed safe.
func unguardedScans(
fset *token.FileSet, file *ast.File,
) []token.Position {
var found []token.Position
ast.Inspect(file, func(n ast.Node) bool {
call, ok := n.(*ast.CallExpr)
if !ok {
return true
}
sel, ok := call.Fun.(*ast.SelectorExpr)
if !ok || sel.Sel.Name != "Scan" {
return true
}
if !receiverIsRowHandle(sel.X) {
found = append(found, fset.Position(sel.Sel.Pos()))
}
return true
})
return found
}
// moduleRoot walks up from the working directory to the directory
// holding go.mod.
func moduleRoot(t *testing.T) string {
t.Helper()
dir, err := os.Getwd()
require.NoError(t, err)
for {
_, statErr := os.Stat(filepath.Join(dir, "go.mod"))
if statErr == nil {
return dir
}
parent := filepath.Dir(dir)
require.NotEqual(t, parent, dir, "no go.mod above %s", dir)
dir = parent
}
}
// skipDir reports whether a directory holds no source this check
// governs.
func skipDir(name string) bool {
switch name {
case ".git", "bin", "node_modules", "testdata":
return true
default:
return false
}
}
// walkNonTestGo parses every non-test .go file under root and returns
// how many it parsed along with every unguarded Scan it found.
func walkNonTestGo(t *testing.T, root string) (int, []string) {
t.Helper()
var (
parsed int
hits []string
)
fset := token.NewFileSet()
require.NoError(t, filepath.WalkDir(
root,
func(path string, d fs.DirEntry, err error) error {
if err != nil {
return err
}
if d.IsDir() {
if skipDir(d.Name()) {
return fs.SkipDir
}
return nil
}
if !isNonTestGo(d.Name()) {
return nil
}
file, err := parser.ParseFile(fset, path, nil, 0)
if err != nil {
return err
}
parsed++
for _, pos := range unguardedScans(fset, file) {
hits = append(hits, relPosition(root, pos))
}
return nil
},
))
return parsed, hits
}
// isNonTestGo reports whether a file name is Go source this check
// governs.
func isNonTestGo(name string) bool {
return strings.HasSuffix(name, ".go") &&
!strings.HasSuffix(name, "_test.go")
}
// relPosition renders pos with its path relative to root, so a failure
// names the file the way the repository does.
func relPosition(root string, pos token.Position) string {
name := pos.Filename
rel, err := filepath.Rel(root, name)
if err == nil {
name = rel
}
return fmt.Sprintf("%s:%d:%d", name, pos.Line, pos.Column)
}
// TestGormScanIsNeverCalledOutsideTests keeps (*gorm.DB).Scan out of
// non-test code.
//
// It is the one statement path (*Logger).ParamsFilter does not reach:
// Scan swaps GORM's own trace recorder in for the adapter, and that
// recorder does not implement gorm.ParamsFilter, so the statement is
// logged with its values interpolated. The package comment states the
// limit; this fails when someone adds a call site anyway.
//
// The current tree has one caller, internal/database/database_test.go,
// which this check does not govern: it is test-only and its SELECT 1
// binds nothing.
func TestGormScanIsNeverCalledOutsideTests(t *testing.T) {
t.Parallel()
parsed, offenders := walkNonTestGo(t, moduleRoot(t))
require.GreaterOrEqual(
t, parsed, minNonTestFiles,
"parsed %d non-test .go files, so this check found "+
"nothing to look at", parsed,
)
require.Empty(
t, offenders,
"Scan called on a receiver this check cannot show is a "+
"database/sql row handle. (*gorm.DB).Scan logs the "+
"statement with its bound values interpolated — use "+
"Find, Pluck, or Raw(...).Row().Scan instead. A "+
"database/sql Scan reached through a variable is "+
"reported too; write it as <producer>().Scan rather "+
"than widening this check.",
)
}
// scanGuardCase is one planted snippet and whether the check above
// should report it.
type scanGuardCase struct {
name string
body string
want int
}
func scanGuardCases() []scanGuardCase {
return []scanGuardCase{
{"gorm chain", `db.DB().Raw("SELECT 1").Scan(&v)`, 1},
{"gorm receiver", `gdb.Scan(&v)`, 1},
{"gorm via variable", "q := gdb.Raw(\"x\")\nq.Scan(&v)", 1},
{"gorm model chain", `gdb.Model(&x).Scan(&v)`, 1},
{"sql row", `gdb.Raw("SELECT 1").Row().Scan(&v)`, 0},
{"sql rows", `gdb.Raw("SELECT 1").Rows().Scan(&v)`, 0},
{"unrelated call", `gdb.Find(&v)`, 0},
}
}
// TestScanGuard_ReportsPlantedCalls proves the check fires. Without it
// a detector that matched nothing would satisfy the walk above no
// matter what the tree contained.
func TestScanGuard_ReportsPlantedCalls(t *testing.T) {
t.Parallel()
for _, tc := range scanGuardCases() {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
fset := token.NewFileSet()
src := fmt.Sprintf(
"package p\n\nfunc f() {\n\t%s\n}\n", tc.body,
)
file, err := parser.ParseFile(
fset, tc.name+".go", src, 0,
)
require.NoError(t, err)
require.Len(t, unguardedScans(fset, file), tc.want)
})
}
}

View File

@@ -0,0 +1,185 @@
package gormlog_test
import (
"bytes"
"strings"
"testing"
"time"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"gorm.io/gorm"
)
// secretValue is bound as a parameter by every case below. Nothing
// else in this package writes it, so finding it in captured output
// means a bound value was rendered into the log.
const secretValue = "QQBOUNDVALUEMARKERQQ"
// The three messages Trace emits under, one per arm.
//
// routineLine is a substring of slowLine, so a case that wants the
// routine arm has to rule the slow one out as well rather than rely on
// Contains alone.
const (
routineLine = "sql statement"
slowLine = "slow sql statement"
errorLine = "sql statement failed"
)
// boundValueCase is one arm of Trace, driven by a statement that binds
// secretValue.
type boundValueCase struct {
name string
slow time.Duration
want string
drive func(t *testing.T, gdb *gorm.DB)
}
// insertSecret returns a driver that inserts one row whose Name is the
// secret.
func insertSecret(id string) func(*testing.T, *gorm.DB) {
return func(t *testing.T, gdb *gorm.DB) {
t.Helper()
require.NoError(t, gdb.Create(&thing{
ID: id, Name: secretValue,
}).Error)
}
}
// insertSecretTwice drives the error arm: the same primary key a
// second time is a UNIQUE constraint failure, which is an error GORM
// logs with the statement.
func insertSecretTwice(t *testing.T, gdb *gorm.DB) {
t.Helper()
require.NoError(t, gdb.Create(&thing{
ID: secretValue, Name: secretValue,
}).Error)
require.Error(t, gdb.Create(&thing{
ID: secretValue, Name: "other",
}).Error)
}
// selectSecret drives a query whose WHERE clause binds the secret,
// covering the read side as well as the write side.
func selectSecret(t *testing.T, gdb *gorm.DB) {
t.Helper()
var got []thing
require.NoError(
t, gdb.Where("name = ?", secretValue).Find(&got).Error,
)
}
func boundValueCases() []boundValueCase {
return []boundValueCase{
{
name: "routine", slow: neverSlow,
want: routineLine, drive: insertSecret("routine"),
},
{
name: "slow", slow: alwaysSlow,
want: slowLine, drive: insertSecret("slow"),
},
{
name: "error", slow: neverSlow,
want: errorLine, drive: insertSecretTwice,
},
{
name: "select", slow: neverSlow,
want: routineLine, drive: selectSecret,
},
}
}
// TestBoundValues_NeverReachTheLog states the values-off property
// directly, on each arm of Trace that emits.
//
// Truncation is not what is being asserted. A bounded secret is still
// a secret: the session key is 44 base64 characters and an Argon2id
// hash under 100, so both fit inside every budget this package
// applies. What keeps them out is that the adapter logs the
// statement's shape and discards its parameters — see
// (*Logger).ParamsFilter — and that has to hold at DEBUG as much as on
// an error, because DEBUG is the level at which a successful INSERT is
// written at all.
//
// Each case also requires a placeholder in the logged statement.
// Without that, the absence of the value would be satisfied by a
// logger that wrote nothing useful.
func TestBoundValues_NeverReachTheLog(t *testing.T) {
t.Parallel()
for _, tc := range boundValueCases() {
for _, h := range handlers() {
t.Run(tc.name+"/"+h.name, func(t *testing.T) {
t.Parallel()
var buf bytes.Buffer
gdb := openDB(t, &buf, h.make(&buf), tc.slow)
tc.drive(t, gdb)
assertNoBoundValue(t, buf.String(), tc.want)
})
}
}
}
// assertNoBoundValue holds one captured arm to the property: it wrote
// the line it was supposed to write, that line kept its placeholders,
// and it carried no bound value.
func assertNoBoundValue(t *testing.T, out, want string) {
t.Helper()
require.Contains(
t, out, want,
"the arm under test wrote nothing, so the assertions "+
"below are vacuous",
)
assert.NotContains(
t, out, secretValue,
"a bound parameter was rendered into the log",
)
assert.Contains(
t, out, "?",
"the statement was logged without its placeholders",
)
}
// TestInsert_KeepsOnePlaceholderPerBoundValue pins the shape of the
// INSERT specifically, since that is the statement that carries both
// first-boot secrets. A statement that dropped one value and kept the
// other would satisfy the assertions above.
func TestInsert_KeepsOnePlaceholderPerBoundValue(t *testing.T) {
t.Parallel()
var buf bytes.Buffer
gdb := openDB(t, &buf, handlers()[0].make(&buf), neverSlow)
require.NoError(t, gdb.Create(&thing{
ID: "m", Name: secretValue,
}).Error)
out := buf.String()
require.Contains(t, out, "INSERT INTO")
assert.NotContains(t, out, secretValue)
for line := range strings.SplitSeq(out, "\n") {
if !strings.Contains(line, "INSERT INTO") {
continue
}
assert.GreaterOrEqual(
t, strings.Count(line, "?"), 2,
"insert logged fewer placeholders than it bound "+
"values: %s", line,
)
}
}

View File

@@ -43,10 +43,7 @@ func (s *Server) serveUntilShutdown() {
err := s.httpServer.ListenAndServe()
if err != nil && !errors.Is(err, http.ErrServerClosed) {
s.log.Error("listen error", "error", err)
if s.cancelFunc != nil {
s.cancelFunc()
}
s.shutdownOnListenFailure()
}
}

View File

@@ -0,0 +1,95 @@
package server_test
import (
"context"
"net"
"testing"
"time"
"github.com/stretchr/testify/require"
"go.uber.org/fx"
"sneak.berlin/go/webhooker/internal/globals"
"sneak.berlin/go/webhooker/internal/server"
)
// listenFailureDeadline is how long the app gets to give up after a
// listen it cannot satisfy. The defect this pins left the process
// reporting RUNNING for 183 seconds with nothing bound; a bind error
// is known instantly, so anything past a moment here is that defect
// back.
const listenFailureDeadline = 2 * time.Second
// lifecycleTimeout bounds the app's start and stop sequences so a
// wedged hook fails the test instead of hanging it.
const lifecycleTimeout = 15 * time.Second
// TestListenFailure_ShutsDownTheApp pins that a listener the server
// cannot bind terminates the application with a non-zero status.
//
// The fx OnStart hook returns as soon as the serving goroutine is
// spawned, so a bind failure is discovered after fx has already
// reported RUNNING. Nothing else in the graph observes it, and the
// process used to stay alive with no listener: down, but indis-
// tinguishable from healthy to systemd's Restart=on-failure and to
// Docker's restart policies, which is the state this test exists to
// keep from returning.
//
// The port is occupied by a listener this test holds open, on a
// kernel-chosen port, so the failure is the real EADDRINUSE the
// operator hits when a second instance starts. Loopback is enough to
// collide with the server's wildcard bind: a listening socket on a
// specific address blocks the wildcard from claiming the same port.
func TestListenFailure_ShutsDownTheApp(t *testing.T) {
t.Parallel()
var listenCfg net.ListenConfig
occupied, err := listenCfg.Listen(
t.Context(), "tcp", "127.0.0.1:0",
)
require.NoError(t, err)
t.Cleanup(func() { _ = occupied.Close() })
addr, ok := occupied.Addr().(*net.TCPAddr)
require.True(t, ok, "listener is not TCP")
// The collaborators come from the wired graph rather than stubs,
// so the Server under test is the one that ships. Only the port
// is test-specific.
env := newTestEnv(t)
env.cfg.Port = addr.Port
app := fx.New(
fx.NopLogger,
fx.Supply(env.log, env.cfg, env.mw, env.hnd),
fx.Provide(globals.New, server.New),
fx.Invoke(func(*server.Server) {}),
)
startCtx, cancelStart := context.WithTimeout(
context.Background(), lifecycleTimeout,
)
defer cancelStart()
require.NoError(t, app.Start(startCtx))
select {
case sig := <-app.Wait():
require.Equal(
t, server.ListenFailureExitCode, sig.ExitCode,
"listen failure must exit non-zero",
)
case <-time.After(listenFailureDeadline):
t.Fatal("listen failure left the app running")
}
// The stop sequence still has to complete: the fix must reach
// shutdown through fx rather than around it.
stopCtx, cancelStop := context.WithTimeout(
context.Background(), lifecycleTimeout,
)
defer cancelStop()
require.NoError(t, app.Stop(stopCtx))
}

View File

@@ -55,8 +55,11 @@ func (s *Server) setupGlobalMiddleware() {
s.router.Use(s.mw.SecurityHeaders())
s.router.Use(s.mw.Logging())
// Metrics middleware (only if credentials are configured)
if s.params.Config.MetricsUsername != "" {
// Metrics recording middleware, registered only when the
// endpoint that exposes what it records is served. The
// condition is the same MetricsAuthEnabled the /metrics mount
// in setupRoutes reads.
if s.params.Config.MetricsAuthEnabled() {
s.router.Use(s.mw.Metrics())
}
@@ -103,8 +106,14 @@ func (s *Server) setupRoutes() {
s.h.HandleHealthCheck(),
)
// set up authenticated /metrics route:
if s.params.Config.MetricsUsername != "" {
// Authenticated /metrics route. The condition is
// Config.MetricsAuthEnabled and never the username alone: a
// username with an empty password would otherwise mount the
// endpoint behind a credential map that accepts an empty
// password. Config rejects that combination at startup, and
// this reads the same value the startup log reports, so the
// two cannot disagree about whether the route exists.
if s.params.Config.MetricsAuthEnabled() {
s.router.Group(func(r chi.Router) {
r.Use(s.mw.MetricsAuth())
r.Get(

View File

@@ -34,6 +34,13 @@ import (
// the CSRF middleware executed.
const csrfCookieName = "_gorilla_csrf"
const (
// metricsUser and metricsAuthValue are the /metrics basic-auth
// credentials the metrics routing tests below configure.
metricsUser = "metrics"
metricsAuthValue = "s3cret"
)
type noopNotifier struct{}
func (n *noopNotifier) Notify([]delivery.Task) {}
@@ -69,9 +76,23 @@ type testEnv struct {
func newTestEnv(t *testing.T) *testEnv {
t.Helper()
return newTestEnvWithConfig(t, &config.Config{
DataDir: t.TempDir(),
Environment: config.EnvironmentDev,
})
}
// newTestEnvWithConfig is newTestEnv over a caller-supplied Config,
// for the routes whose existence the configuration decides. The same
// pointer reaches the router and every middleware, so a test cannot
// accidentally configure one and not the other.
func newTestEnvWithConfig(
t *testing.T, cfg *config.Config,
) *testEnv {
t.Helper()
var (
log *logger.Logger
cfg *config.Config
mw *middleware.Middleware
hnd *handlers.Handlers
sess *session.Session
@@ -84,12 +105,7 @@ func newTestEnv(t *testing.T) *testEnv {
fx.Provide(
globals.New,
logger.New,
func() *config.Config {
return &config.Config{
DataDir: t.TempDir(),
Environment: config.EnvironmentDev,
}
},
func() *config.Config { return cfg },
database.New,
database.NewWebhookDBManager,
healthcheck.New,
@@ -99,7 +115,7 @@ func newTestEnv(t *testing.T) *testEnv {
middleware.New,
handlers.New,
),
fx.Populate(&log, &cfg, &mw, &hnd, &sess, &db, &dbMgr),
fx.Populate(&log, &mw, &hnd, &sess, &db, &dbMgr),
)
app.RequireStart()
t.Cleanup(app.RequireStop)
@@ -657,3 +673,119 @@ func TestSourceLogsBody_OtherUser404s(t *testing.T) {
assert.Equal(t, http.StatusSeeOther, anon.Code)
assert.Equal(t, "/pages/login", anon.Header().Get("Location"))
}
// metricsConfig is a Config differing from the routing default only
// in the two /metrics credentials.
func metricsConfig(
t *testing.T, username, password string,
) *config.Config {
t.Helper()
return &config.Config{
DataDir: t.TempDir(),
Environment: config.EnvironmentDev,
MetricsUsername: username,
MetricsPassword: password,
}
}
// metricsRequest asks the real router for /metrics with the given
// basic-auth credentials, or with no Authorization header when
// username is empty.
func (e *testEnv) metricsRequest(
username, password string,
) *httptest.ResponseRecorder {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/metrics", nil,
)
if username != "" {
req.SetBasicAuth(username, password)
}
w := httptest.NewRecorder()
e.router.ServeHTTP(w, req)
return w
}
// TestMetricsRouteUnmountedWithoutCredentials pins that with neither
// credential configured the route does not exist, which is the
// documented behaviour and the only valid way for /metrics to be
// absent.
func TestMetricsRouteUnmountedWithoutCredentials(t *testing.T) {
t.Parallel()
env := newTestEnvWithConfig(t, metricsConfig(t, "", ""))
assert.Equal(
t, http.StatusNotFound,
env.metricsRequest("", "").Code,
)
}
// TestMetricsRouteRequiresCredentials pins that with both credentials
// configured the route exists and every request that does not carry
// the configured pair is refused — including the empty password that
// a half-set configuration used to make sufficient.
func TestMetricsRouteRequiresCredentials(t *testing.T) {
t.Parallel()
env := newTestEnvWithConfig(
t, metricsConfig(t, metricsUser, metricsAuthValue),
)
assert.Equal(
t, http.StatusUnauthorized,
env.metricsRequest("", "").Code,
"no credentials must not reach the metrics handler",
)
assert.Equal(
t, http.StatusUnauthorized,
env.metricsRequest(metricsUser, "").Code,
"an empty password must not reach the metrics handler",
)
assert.Equal(
t, http.StatusUnauthorized,
env.metricsRequest(metricsUser, "wrong").Code,
)
ok := env.metricsRequest(metricsUser, metricsAuthValue)
assert.Equal(t, http.StatusOK, ok.Code)
assert.Contains(t, ok.Body.String(), "go_goroutines")
}
// TestMetricsRouteUnmountedOnHalfSetConfig pins the defect from
// https://git.eeqj.de/sneak/webhooker/issues/205 at the routing
// layer. Config rejects a half-set pair at startup, so this Config
// cannot be reached from the environment; the assertion is that the
// route tree does not publish an endpoint accepting an empty
// password even when handed one anyway, because the mount and the
// startup log's hasMetricsAuth read the same value.
func TestMetricsRouteUnmountedOnHalfSetConfig(t *testing.T) {
t.Parallel()
for _, tc := range []struct {
name string
username string
password string
}{
{name: "username only", username: metricsUser},
{name: "password only", password: metricsAuthValue},
} {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
cfg := metricsConfig(t, tc.username, tc.password)
env := newTestEnvWithConfig(t, cfg)
assert.False(t, cfg.MetricsAuthEnabled())
assert.Equal(
t, http.StatusNotFound,
env.metricsRequest(
tc.username, tc.password,
).Code,
)
})
}
}

View File

@@ -50,6 +50,13 @@ const (
minSentryFlush = 250 * time.Millisecond
)
// ListenFailureExitCode is the status the process exits with when the
// HTTP listener cannot be established, or dies for a reason other
// than a requested shutdown. It must stay non-zero: systemd
// `Restart=on-failure` and Docker's restart policies key off it, and a
// zero exit would read as a deliberate stop.
const ListenFailureExitCode = 1
// SentryFlushBudget reports how long the Sentry flush may run when
// remaining is the time left on the fx stop context after the HTTP
// drain. sentry.Flush takes a bare duration and honours no context,
@@ -75,13 +82,13 @@ type ServerParams struct {
Config *config.Config
Middleware *middleware.Middleware
Handlers *handlers.Handlers
Shutdowner fx.Shutdowner
}
// Server is the main HTTP server that wires up routes and manages
// graceful shutdown.
type Server struct {
startupTime time.Time
exitCode int
sentryEnabled bool
log *slog.Logger
cancelFunc context.CancelFunc
@@ -159,7 +166,12 @@ func (s *Server) enableSentry() {
s.sentryEnabled = true
}
func (s *Server) serve() int {
// serve installs the signal watcher, starts the listener and blocks
// until the server's context is cancelled. The process exit status is
// fx's to decide — from a signal, or from the code
// shutdownOnListenFailure hands the Shutdowner — so this reports
// nothing back to its caller.
func (s *Server) serve() {
ctx, cancelFunc := context.WithCancel(context.Background())
s.cancelFunc = cancelFunc
@@ -185,7 +197,30 @@ func (s *Server) serve() int {
<-ctx.Done()
// Shutdown is handled by the fx OnStop hook (cleanShutdown).
// Do not call cleanShutdown() here to avoid double invocation.
return s.exitCode
}
// shutdownOnListenFailure ends the application after the HTTP
// listener failed. The fx OnStart hook returns as soon as the serving
// goroutine is spawned, so nothing downstream of it ever learns that
// the listen failed: fx reports RUNNING and the process sits alive
// with nothing bound, which is invisible to systemd and Docker
// restart policies. Asking the Shutdowner to stop the app with a
// non-zero code is what turns that into a visible failure.
//
// The context cancel that follows only unwinds serve()'s own wait.
// The shutdown itself runs through fx's normal stop sequence, so the
// clean-shutdown drain in cleanShutdown is reached unchanged.
func (s *Server) shutdownOnListenFailure() {
err := s.params.Shutdowner.Shutdown(
fx.ExitCode(ListenFailureExitCode),
)
if err != nil {
s.log.Error("shutdown request failed", "error", err)
}
if s.cancelFunc != nil {
s.cancelFunc()
}
}
func (s *Server) cleanupForExit() {
@@ -193,9 +228,6 @@ func (s *Server) cleanupForExit() {
}
func (s *Server) cleanShutdown(ctx context.Context) {
// initiate clean shutdown
s.exitCode = 0
ctxShutdown, shutdownCancel := context.WithTimeout(
ctx, ShutdownTimeout,
)