Keep the entrypoint UUID out of webhooker's own logs #534
@@ -802,7 +802,12 @@ comes up, serves pages, and is broken in a way nothing reports.
|
||||
proxy's log names it regardless. nginx's default `combined` format already
|
||||
logs `$remote_addr`; do not replace it with one that drops the client
|
||||
address, and retain those logs as long as you would want to answer a question
|
||||
about traffic.
|
||||
about traffic. That log also records the full request path, so it holds the
|
||||
entrypoint UUID of every event a sender posts. webhooker's own log does not,
|
||||
apart from the line a `log` target writes. Protect the proxy's log as you
|
||||
would the entrypoint URLs themselves: anyone who can read it can post events
|
||||
to every entrypoint in it (see
|
||||
[The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)).
|
||||
|
||||
### nginx
|
||||
|
||||
@@ -828,7 +833,9 @@ server {
|
||||
client_max_body_size 1m;
|
||||
|
||||
# $remote_addr is the client. webhooker's own log names it, as
|
||||
# clientIP, only while TRUSTED_PROXIES covers this proxy.
|
||||
# clientIP, only while TRUSTED_PROXIES covers this proxy. The
|
||||
# request path in this log holds the entrypoint UUID, so protect
|
||||
# the file like the entrypoint URL itself.
|
||||
access_log /var/log/nginx/webhooker.access.log combined;
|
||||
|
||||
location / {
|
||||
@@ -1160,7 +1167,16 @@ What that means for an operator:
|
||||
|
||||
- **The URL is a capability, so treat it as a secret.** Keep it out of logs,
|
||||
ticket bodies, chat messages and screenshots. Anyone who reads it anywhere can
|
||||
post events as that sender.
|
||||
post events as that sender. Apart from a `log` target's line, webhooker's own
|
||||
log lines never carry the UUID: they name a request to the receiver by the
|
||||
route pattern `/h/{uuid}`, the `webhook request received` line names the
|
||||
entrypoint by its `entrypoint_id`, and the access log keeps only the scheme
|
||||
and host of a `Referer`. A `log` target writes the request's headers as
|
||||
received, so a `Referer` naming the entrypoint URL appears in its line, as it
|
||||
does when a sender has followed a redirect from `http://` to `https://`. The
|
||||
reverse proxy's access log does carry the UUID, in the request path, so it
|
||||
must be protected like the URL itself (see
|
||||
[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)).
|
||||
- **Rotating means minting a new entrypoint, not changing a key.** There is no
|
||||
way to rotate the UUID in place. To retire one, delete the entrypoint (or
|
||||
deactivate it, which answers `410`) and create a new one, then point the
|
||||
@@ -2422,27 +2438,32 @@ log volume it caps rather than eliminates. A path that names no entrypoint is
|
||||
recorded by the handler at `DEBUG`, and the aggregate limiter logs its own
|
||||
rejections at `DEBUG` and without the path, so neither appears at all under the
|
||||
default level. The per-entrypoint limiter is the loud one: it logs every
|
||||
rejection at `WARN` with the request path, which on this route is
|
||||
attacker-controlled text. A client hammering a single invented path is served
|
||||
rejection at `WARN`, naming the route pattern `/h/{uuid}` rather than the
|
||||
request path. A client hammering a single invented path is served
|
||||
`RECEIVER_RATE_LIMIT` requests and has the rest of its aggregate budget rejected
|
||||
there, so the aggregate limit is what bounds the _number_ of those `WARN` lines
|
||||
— to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
|
||||
defaults, where before it there was no bound at all. Their _width_ is bounded by
|
||||
the field budgets below, the same ones the access log spends. The access log is
|
||||
bounded by neither limit: every request is recorded once at `INFO`, served or
|
||||
rejected alike.
|
||||
defaults, where before it there was no bound at all. The access log is bounded
|
||||
by neither limit: every request is recorded once at `INFO`, served or rejected
|
||||
alike.
|
||||
|
||||
What the access log does bound is the _content_ of those lines. A 3xx or 4xx
|
||||
response logs the chi route pattern — `/h/{uuid}`, `/user/{username}//`, or the
|
||||
literal `(unmatched)` when the request hit no route at all — in place of the
|
||||
concrete URL. Those are the outcomes an unauthenticated client can drive for
|
||||
free: 404 and 429 on any invented receiver path, a login redirect on any
|
||||
invented profile path. Logging the URL there would let a flood write text of its
|
||||
own choosing, at a length of its own choosing, into the log. 2xx and 5xx
|
||||
responses keep the concrete path — a success resolved against a static route or
|
||||
against the operator's own data (on the receiver, against a stored entrypoint
|
||||
UUID), and a 5xx is a bug in this service, where the exact path is the evidence
|
||||
and no client can provoke one at will.
|
||||
What the access log does bound is the _content_ of those lines. On the receiver
|
||||
route it logs the route pattern `/h/{uuid}` whatever the status, because the
|
||||
concrete path carries the entrypoint UUID, which is the entrypoint's credential
|
||||
(see
|
||||
[The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)).
|
||||
A request chi never routed, because it matched no route or because a middleware
|
||||
answered it first, logs the literal `(unmatched)` whatever the status. In the
|
||||
`dev` environment the CORS middleware answers a preflight that way, so a
|
||||
preflight to the receiver does not log its UUID either. On every other route, a
|
||||
3xx or 4xx response logs the chi route pattern, such as `/user/{username}//`, in
|
||||
place of the concrete URL. Those are the outcomes an unauthenticated client can
|
||||
drive for free: a 404 on any invented path, a login redirect on any invented
|
||||
profile path. Logging the URL there would let a flood write text of its own
|
||||
choosing, at a length of its own choosing, into the log. 2xx and 5xx responses
|
||||
keep the concrete path — a success resolved against a static route or against
|
||||
the operator's own data, and a 5xx is a bug in this service, where the exact
|
||||
path is the evidence and no client can provoke one at will.
|
||||
|
||||
The query string is never logged; it is replaced by the fixed marker
|
||||
`?(redacted)`. It is client-chosen on every route, and
|
||||
@@ -2454,6 +2475,11 @@ to, `notice`, which names the line a page shows after an action, and the event
|
||||
log's `show`, which picks the events it lists. A query string sent to an
|
||||
entrypoint is not lost either: the event stores it, and the event log shows it.
|
||||
|
||||
The `referer` field keeps only the scheme and host of the request's `Referer`,
|
||||
and logs `(redacted)` for one without them, because its path can be an
|
||||
entrypoint URL: a sender that follows the `http://` to `https://` redirect in
|
||||
the nginx example sends the URL it was redirected from.
|
||||
|
||||
Client-supplied request content does not leave the host by the other route
|
||||
either. The Sentry SDK attaches the request to every event it captures,
|
||||
independently of the access log, and `SendDefaultPII=false` does not cover all
|
||||
@@ -2468,9 +2494,10 @@ The same hook rewrites the request URL. The SDK builds it as
|
||||
`scheme://host/path` from the concrete path, which on the receiver route is
|
||||
`/h/<uuid>` in full — and that UUID is a write capability, not an identifier:
|
||||
anyone holding it can post events this service accepts and its targets then
|
||||
deliver. A tracker has its own retention, access control and deletion policy, so
|
||||
the rule the access log follows above does not carry across that boundary. What
|
||||
is sent is the chi route pattern instead: `http://host/h/{uuid}`.
|
||||
deliver. What is sent is the chi route pattern instead: `http://host/h/{uuid}`.
|
||||
A tracker has its own retention, access control and deletion policy, so the
|
||||
pattern is sent on every route, including the 2xx and 5xx responses outside the
|
||||
receiver for which the access log keeps the concrete path.
|
||||
|
||||
The scheme and the host are kept, and everything else in the URL is discarded
|
||||
rather than edited, so a future SDK version that starts appending a query string
|
||||
@@ -2599,9 +2626,7 @@ than it:
|
||||
| ------------------------------------------ | ------- | ------------------- | ------------------------------------------ |
|
||||
| `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` precedes `RequireAuth` |
|
||||
| `csrf: token validation failed` (403) | `WARN` | path, method | yes — `CSRF` precedes `RequireAuth` |
|
||||
| `... rate limit exceeded` (429) | `WARN` | path | yes, on the receiver |
|
||||
| `auth middleware: unauthenticated request` | `DEBUG` | path, method | yes, by definition |
|
||||
| `entrypoint not found` | `DEBUG` | entrypoint UUID | yes, on the receiver |
|
||||
| `user not found` / `invalid password` | `DEBUG` | username | yes, on the sign-in form |
|
||||
| `login failure limit exceeded` (429) | `WARN` | path | yes, on the sign-in form |
|
||||
| `password verification capacity exhausted` | `WARN` | path | yes, on the sign-in form |
|
||||
@@ -2629,13 +2654,12 @@ wider of the two handlers spends more on than the client spent sending them.
|
||||
Every case holds each line to the 2,560-byte ceiling. That per-line ceiling is
|
||||
what the figure above states, and every row establishes it.
|
||||
|
||||
Three of the sites go further and bound the whole flood's output — the total
|
||||
bytes a run of distinct invented values wrote, which is the shape an operator
|
||||
sizing storage cares about. They are `request body exceeds limit`
|
||||
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`),
|
||||
`entrypoint not found` and `user not found` (the last two through
|
||||
`assertBoundedFlood`). The other rows carry no aggregate assertion; the per-line
|
||||
ceiling is what they establish.
|
||||
Two of the sites go further and bound the whole flood's output — the total bytes
|
||||
a run of distinct invented values wrote, which is the shape an operator sizing
|
||||
storage cares about. They are `request body exceeds limit`
|
||||
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`) and `user not found`
|
||||
(through `assertBoundedFlood`). The other rows carry no aggregate assertion; the
|
||||
per-line ceiling is what they establish.
|
||||
|
||||
`internal/logfield/logfield_test.go` measures the per-rune charge against what
|
||||
the handlers really emit, over roughly 3,000 code points on each, so an
|
||||
@@ -2653,7 +2677,7 @@ everything else, so its lines take the level the operator set and the handler
|
||||
`internal/logger` selected, and every value it emits is spent through the same
|
||||
`internal/logfield` budget. A record-not-found is not logged as an error: it is
|
||||
the expected outcome on both of those paths, and each handler already records
|
||||
its own miss at `DEBUG` — bounded, per the table above — without the SQL. Slow
|
||||
its own miss at `DEBUG`, without the SQL and within the ceiling above. Slow
|
||||
statements are kept, at `WARN`, above the same 200 ms threshold GORM used and
|
||||
with the statement bounded, because that report is the one thing GORM's logger
|
||||
gave an operator that nothing else here does. The adapter orders its cases
|
||||
|
||||
@@ -1,19 +1,15 @@
|
||||
package handlers_test
|
||||
|
||||
// The handler-side half of the log-field audit. Two slog calls in
|
||||
// this package reach a value an UNAUTHENTICATED client picks outright
|
||||
// and of a length it picks outright:
|
||||
// The handler-side half of the log-field audit. The slog calls in
|
||||
// this package that reach a value an UNAUTHENTICATED client picks
|
||||
// outright, and of a length it picks outright, are the failed-login
|
||||
// DEBUG lines, whose username is a form field.
|
||||
//
|
||||
// - the unknown-entrypoint DEBUG line on /h/{uuid}, whose
|
||||
// path segment matched no stored entrypoint and so is bounded by
|
||||
// nothing;
|
||||
// - the failed-login DEBUG lines, whose username is a form field.
|
||||
//
|
||||
// Both are at DEBUG, which is off in production by default. That is
|
||||
// They are at DEBUG, which is off in production by default. That is
|
||||
// not a bound: an operator turning DEBUG on to diagnose a flood must
|
||||
// not thereby hand the flood an unbounded write. Both spend the same
|
||||
// internal/logfield budget as the access log, and both are held here
|
||||
// to middleware.MaxAccessLogLineBytes.
|
||||
// not thereby hand the flood an unbounded write. They spend the same
|
||||
// internal/logfield budget as the access log, and are held here to
|
||||
// middleware.MaxAccessLogLineBytes.
|
||||
//
|
||||
// The two login lines past the username lookup — "invalid password"
|
||||
// and "user logged in" — carry the same cap without needing it, since
|
||||
@@ -260,43 +256,6 @@ func postLoginWithPassword(
|
||||
return w.Code
|
||||
}
|
||||
|
||||
// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
|
||||
// client-chosen path at the unauthenticated receiver's
|
||||
// unknown-entrypoint DEBUG line and holds it to the same ceiling the
|
||||
// access log states.
|
||||
func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for handlerName, newHandler := range logHandlers() {
|
||||
for fillName, fill := range escapeFills() {
|
||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
h, buf := capturingHandlers(t, newHandler)
|
||||
router := receiverRouter(h)
|
||||
|
||||
for i := range floodRequests {
|
||||
assert.Equal(
|
||||
t,
|
||||
http.StatusNotFound,
|
||||
postReceiver(
|
||||
t, router,
|
||||
oversizedFill(fill)+
|
||||
strings.Repeat("y", i),
|
||||
),
|
||||
)
|
||||
}
|
||||
|
||||
lines := logLines(t, buf)
|
||||
require.Len(t, lines, floodRequests)
|
||||
assertNoClientText(t, buf)
|
||||
|
||||
assertBoundedFlood(t, buf.Len())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
|
||||
// client-chosen username at the unauthenticated login endpoint's
|
||||
// DEBUG line and holds it to the same ceiling.
|
||||
|
||||
@@ -10,7 +10,6 @@ import (
|
||||
"gorm.io/gorm"
|
||||
"sneak.berlin/go/webhooker/internal/database"
|
||||
"sneak.berlin/go/webhooker/internal/delivery"
|
||||
"sneak.berlin/go/webhooker/internal/logfield"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
)
|
||||
|
||||
@@ -49,14 +48,13 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
|
||||
return
|
||||
}
|
||||
|
||||
// Logged only once the UUID is known to name a real
|
||||
// entrypoint. The UUID comes straight out of the path on
|
||||
// the one unauthenticated endpoint, so logging it before
|
||||
// the lookup let a client write an INFO line per invented
|
||||
// path; the request itself is already in the access log
|
||||
// and a miss is already logged at DEBUG.
|
||||
// Logged only once the lookup has found the entrypoint, so
|
||||
// an invented path writes no INFO line; a miss is logged at
|
||||
// DEBUG. The entrypoint is named by its ID: the UUID is its
|
||||
// credential and is never logged.
|
||||
h.log.Info("webhook request received",
|
||||
"entrypoint_uuid", entrypointUUID,
|
||||
"entrypoint_id", entrypoint.ID,
|
||||
"webhook_id", entrypoint.WebhookID,
|
||||
"method", r.Method,
|
||||
"remoteIP", middleware.RemoteIP(r),
|
||||
"clientIP", middleware.ClientIP(r),
|
||||
@@ -133,17 +131,10 @@ func (h *Handlers) lookupEntrypoint(
|
||||
"path = ?", entrypointUUID,
|
||||
).First(&entrypoint)
|
||||
if result.Error != nil {
|
||||
// The receiver is unauthenticated and /h/{uuid}
|
||||
// matches any single segment, so this value is entirely
|
||||
// client-chosen on exactly the branch where the lookup
|
||||
// failed. DEBUG is off by default; the cap is what keeps
|
||||
// turning it on from restoring an unbounded write.
|
||||
h.log.Debug(
|
||||
"entrypoint not found",
|
||||
"path", logfield.Truncate(
|
||||
entrypointUUID, logfield.MaxBytes,
|
||||
),
|
||||
)
|
||||
// Not even an unknown UUID is logged. The receiver's log
|
||||
// lines never carry the path segment, which is a credential
|
||||
// whenever it names an entrypoint.
|
||||
h.log.Debug("entrypoint not found")
|
||||
http.NotFound(w, r)
|
||||
|
||||
return entrypoint, false
|
||||
|
||||
@@ -12,12 +12,15 @@ import (
|
||||
"testing"
|
||||
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/google/uuid"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"gorm.io/gorm/clause"
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/database"
|
||||
"sneak.berlin/go/webhooker/internal/handlers"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
"sneak.berlin/go/webhooker/internal/middleware/middlewaretest"
|
||||
)
|
||||
|
||||
// TestHandleWebhook_LogsClientNextToThePeer checks that the
|
||||
@@ -99,6 +102,87 @@ func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// TestHandleWebhook_LogsNoEntrypointUUID sends an accepted event, a
|
||||
// request over the receiver rate limit and a request for an unknown
|
||||
// UUID through the receiver as routes.go mounts it, and checks that
|
||||
// nothing logged, at any level, carries either UUID.
|
||||
func TestHandleWebhook_LogsNoEntrypointUUID(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var (
|
||||
h *handlers.Handlers
|
||||
db *database.Database
|
||||
)
|
||||
|
||||
cfg := &config.Config{DataDir: t.TempDir(), ReceiverRateLimit: 1}
|
||||
|
||||
app := newTestAppWithConfig(t, cfg, &h, &db)
|
||||
app.RequireStart()
|
||||
|
||||
t.Cleanup(app.RequireStop)
|
||||
|
||||
buf := new(bytes.Buffer)
|
||||
log := slog.New(slog.NewJSONHandler(
|
||||
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
|
||||
))
|
||||
h.SetLogForTest(log)
|
||||
mw := middlewaretest.New(t, log, cfg, nil)
|
||||
|
||||
webhook := seedWebhook(t, db)
|
||||
entrypoint := &database.Entrypoint{
|
||||
WebhookID: webhook.ID,
|
||||
Path: uuid.New().String(),
|
||||
Active: true,
|
||||
}
|
||||
require.NoError(t, db.DB().Omit(clause.Associations).
|
||||
Create(entrypoint).Error)
|
||||
|
||||
unknownUUID := uuid.New().String()
|
||||
|
||||
router := chi.NewRouter()
|
||||
router.Use(mw.Logging())
|
||||
router.With(mw.ReceiverRateLimit()).HandleFunc(
|
||||
middleware.ReceiverRoute, h.HandleWebhook(),
|
||||
)
|
||||
|
||||
// In order: the limit is one request per minute per path, so the
|
||||
// second request for the known UUID is the rejected one.
|
||||
for _, step := range []struct {
|
||||
entrypointUUID string
|
||||
wantStatus int
|
||||
}{
|
||||
{entrypoint.Path, http.StatusOK},
|
||||
{entrypoint.Path, http.StatusTooManyRequests},
|
||||
{unknownUUID, http.StatusNotFound},
|
||||
} {
|
||||
req := httptest.NewRequestWithContext(
|
||||
context.Background(), http.MethodPost,
|
||||
"/h/"+step.entrypointUUID, strings.NewReader("{}"),
|
||||
)
|
||||
w := httptest.NewRecorder()
|
||||
router.ServeHTTP(w, req)
|
||||
|
||||
require.Equal(t, step.wantStatus, w.Code)
|
||||
}
|
||||
|
||||
// The lines this test is about were all written, so the checks
|
||||
// below are not passing on an empty log.
|
||||
for _, msg := range []string{
|
||||
"webhook request received",
|
||||
"webhook receiver rate limit exceeded",
|
||||
"entrypoint not found",
|
||||
} {
|
||||
assert.Contains(t, buf.String(), `"msg":"`+msg+`"`)
|
||||
}
|
||||
|
||||
assert.NotContains(t, buf.String(), entrypoint.Path)
|
||||
assert.NotContains(t, buf.String(), unknownUUID)
|
||||
|
||||
line := receivedLine(t, buf)
|
||||
assert.Equal(t, entrypoint.ID, line["entrypoint_id"])
|
||||
assert.Equal(t, webhook.ID, line["webhook_id"])
|
||||
}
|
||||
|
||||
// receivedLine returns the one "webhook request received" line in the
|
||||
// captured JSON log.
|
||||
func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any {
|
||||
|
||||
@@ -7,6 +7,7 @@ import (
|
||||
"log/slog"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"strconv"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
@@ -27,6 +28,13 @@ const floodRequests = 64
|
||||
// line for a redirected or rejected request may contain it.
|
||||
const attackerMarker = "QQATTACKERTEXTQQ"
|
||||
|
||||
// knownEntrypointUUID and failingEntrypointUUID are the UUIDs the
|
||||
// stand-in receiver in accessLogRouter answers 200 and 500 to.
|
||||
const (
|
||||
knownEntrypointUUID = "6f1e2a9c-4b7d-4e3a-9c2f-1d8b5a7e3c60"
|
||||
failingEntrypointUUID = "0b7c3e5a-2d9f-4a61-8e4b-7c1d6f2a9e35"
|
||||
)
|
||||
|
||||
// maxLineBytes bounds a single access log line whose client-supplied
|
||||
// fields are of ordinary size. Well above what the fixed fields need,
|
||||
// well below the length of the oversized input the amplification tests
|
||||
@@ -132,17 +140,21 @@ func accessLogRouter(m *middleware.Middleware) *chi.Mux {
|
||||
)
|
||||
|
||||
router.HandleFunc(
|
||||
"/h/{uuid}",
|
||||
middleware.ReceiverRoute,
|
||||
func(w http.ResponseWriter, r *http.Request) {
|
||||
// Stands in for the real handler: an unknown entrypoint
|
||||
// UUID 404s, a known one succeeds.
|
||||
if chi.URLParam(r, "uuid") != "known" {
|
||||
// Stands in for the real handler: a known entrypoint
|
||||
// UUID succeeds, a failing one is a server error, and
|
||||
// any other 404s.
|
||||
switch chi.URLParam(r, "uuid") {
|
||||
case knownEntrypointUUID:
|
||||
w.WriteHeader(http.StatusOK)
|
||||
case failingEntrypointUUID:
|
||||
http.Error(
|
||||
w, "boom", http.StatusInternalServerError,
|
||||
)
|
||||
default:
|
||||
http.Error(w, "not found", http.StatusNotFound)
|
||||
|
||||
return
|
||||
}
|
||||
|
||||
w.WriteHeader(http.StatusOK)
|
||||
},
|
||||
)
|
||||
|
||||
@@ -335,11 +347,13 @@ func oversizedValue(ch string) string {
|
||||
}
|
||||
|
||||
// oversizedHeaders fills every client-supplied header the access log
|
||||
// reads with the same value.
|
||||
// reads with the same value. The Referer carries it as the host of an
|
||||
// absolute URL, because the access log keeps only a Referer's scheme
|
||||
// and host.
|
||||
func oversizedHeaders(value string) map[string]string {
|
||||
return map[string]string{
|
||||
"User-Agent": value,
|
||||
"Referer": value,
|
||||
"Referer": "http://" + value,
|
||||
"X-Request-Id": value,
|
||||
}
|
||||
}
|
||||
@@ -649,17 +663,111 @@ func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t, http.StatusOK, get(t, router, "/h/known?src=ci"),
|
||||
t, http.StatusOK,
|
||||
get(t, router, "/.well-known/healthcheck?src=ci"),
|
||||
)
|
||||
|
||||
// The path resolved against a stored entrypoint, so it stays. The
|
||||
// query never does: see TestAccessLog_UnauthenticatedSuccess...
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, "/h/known?(redacted)", entries[0]["url"])
|
||||
assert.Equal(
|
||||
t, "/.well-known/healthcheck?(redacted)", entries[0]["url"],
|
||||
)
|
||||
assert.NotContains(t, buf.String(), "src=ci")
|
||||
}
|
||||
|
||||
// TestAccessLog_ReceiverNeverLogsTheUUID covers the two statuses that
|
||||
// keep the concrete path on every other route. On the receiver that
|
||||
// path carries the entrypoint UUID, so the line names the route
|
||||
// pattern instead.
|
||||
func TestAccessLog_ReceiverNeverLogsTheUUID(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for entrypointUUID, wantStatus := range map[string]int{
|
||||
knownEntrypointUUID: http.StatusOK,
|
||||
failingEntrypointUUID: http.StatusInternalServerError,
|
||||
} {
|
||||
t.Run(strconv.Itoa(wantStatus), func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t, wantStatus,
|
||||
get(t, router, "/h/"+entrypointUUID+"?src=ci"),
|
||||
)
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, middleware.ReceiverRoute, entries[0]["url"])
|
||||
assert.NotContains(t, buf.String(), entrypointUUID)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestAccessLog_ReceiverPreflightNeverLogsTheUUID sends a CORS
|
||||
// preflight to the receiver in dev, in the production middleware
|
||||
// order. CORS answers it with 200 before chi routes it, so the line
|
||||
// names no route and carries no UUID.
|
||||
func TestAccessLog_ReceiverPreflightNeverLogsTheUUID(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
|
||||
router := chi.NewRouter()
|
||||
router.Use(m.Logging())
|
||||
router.Use(m.CORS())
|
||||
router.HandleFunc(
|
||||
middleware.ReceiverRoute,
|
||||
func(w http.ResponseWriter, _ *http.Request) {
|
||||
w.WriteHeader(http.StatusOK)
|
||||
},
|
||||
)
|
||||
|
||||
req := httptest.NewRequestWithContext(
|
||||
context.Background(), http.MethodOptions,
|
||||
"/h/"+knownEntrypointUUID, nil,
|
||||
)
|
||||
req.Header.Set("Origin", "https://sender.example")
|
||||
req.Header.Set("Access-Control-Request-Method", http.MethodPost)
|
||||
|
||||
w := httptest.NewRecorder()
|
||||
router.ServeHTTP(w, req)
|
||||
assert.Equal(t, http.StatusOK, w.Code)
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, unmatchedRouteLiteral, entries[0]["url"])
|
||||
assert.NotContains(t, buf.String(), knownEntrypointUUID)
|
||||
}
|
||||
|
||||
// TestAccessLog_RefererNeverLogsTheUUID sends receiver requests whose
|
||||
// Referer is the entrypoint URL, as a sender's is after it follows a
|
||||
// redirect from http:// to https://. The referer field keeps only the
|
||||
// scheme and host, and a Referer without them is logged as a marker.
|
||||
func TestAccessLog_RefererNeverLogsTheUUID(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
for _, referer := range []string{
|
||||
"http://webhooker.example/h/" + knownEntrypointUUID + "?src=ci",
|
||||
"/h/" + knownEntrypointUUID,
|
||||
} {
|
||||
assert.Equal(t, http.StatusOK, getWithHeaders(
|
||||
t, router, "/h/"+knownEntrypointUUID,
|
||||
map[string]string{"Referer": referer},
|
||||
))
|
||||
}
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 2)
|
||||
assert.Equal(t, "http://webhooker.example", entries[0]["referer"])
|
||||
assert.Equal(t, "(redacted)", entries[1]["referer"])
|
||||
assert.NotContains(t, buf.String(), knownEntrypointUUID)
|
||||
}
|
||||
|
||||
func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
|
||||
@@ -10,8 +10,10 @@ package middleware_test
|
||||
// the client's choosing.
|
||||
// - CSRF's 403 rejection, at WARN, also registered ahead of
|
||||
// RequireAuth.
|
||||
// - The rate limiters' 429 rejection, at WARN, on the
|
||||
// unauthenticated receiver among others.
|
||||
// - The rate limiters' 429 rejection, at WARN. On the receiver
|
||||
// route it names the route pattern rather than the path, and
|
||||
// the limiters that log a path sit behind RequireAuth, so its cap
|
||||
// is defensive.
|
||||
// - RequireAuth's own unauthenticated-request line, at DEBUG.
|
||||
// - RecordLoginFailure's throttle rejection, at WARN. Its cap is
|
||||
// defensive rather than load-bearing today: chi pins the one
|
||||
@@ -268,10 +270,14 @@ func logSites() map[string]logSite {
|
||||
send: postNoToken,
|
||||
wantStatus: http.StatusForbidden,
|
||||
},
|
||||
// The per-entrypoint receiver limiter, unauthenticated. Its
|
||||
// bucket is keyed on the path, so the first request through a
|
||||
// fresh path is served and only the ones after it are
|
||||
// rejected; sendUntilLimited absorbs that.
|
||||
// The 429 line every limiter but the aggregate one shares.
|
||||
// Mounted outside any route, as here, it logs the path, as
|
||||
// it does for the limiters behind RequireAuth; on
|
||||
// ReceiverRoute it names the pattern instead. The
|
||||
// per-entrypoint receiver limiter's bucket is keyed on the
|
||||
// path, so the first request through a fresh path is served
|
||||
// and only the ones after it are rejected; sendUntilLimited
|
||||
// absorbs that.
|
||||
"receiver rate limit 429": {
|
||||
build: func(
|
||||
t *testing.T, m *middleware.Middleware,
|
||||
|
||||
@@ -41,7 +41,8 @@ const unmatchedMethod = unmatchedRoute
|
||||
// after /h/ is client-chosen, so labelling by path lets any
|
||||
// unauthenticated client mint permanent series at will, and publishes
|
||||
// the entrypoint UUID (the receiver's only credential) in the scrape
|
||||
// while doing it.
|
||||
// while doing it. The access log and the 429 line read it for the
|
||||
// same reason: see ReceiverRoute.
|
||||
//
|
||||
// chi populates the route context during routeHTTP, so this is only
|
||||
// valid once routing has run. Every caller below is on the recording
|
||||
|
||||
@@ -13,7 +13,6 @@ import (
|
||||
"time"
|
||||
|
||||
basicauth "github.com/99designs/basicauth-go"
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/go-chi/chi/middleware"
|
||||
"github.com/go-chi/cors"
|
||||
"github.com/prometheus/client_golang/prometheus"
|
||||
@@ -49,6 +48,10 @@ const (
|
||||
// pick the size of the line it writes.
|
||||
redactedQuery = "?(redacted)"
|
||||
|
||||
// redactedReferer stands in for a Referer the access log cannot
|
||||
// reduce to its scheme and host; see accessLogReferer.
|
||||
redactedReferer = "(redacted)"
|
||||
|
||||
// maxLogRequestIDBytes bounds the request id, which is also
|
||||
// client-supplied: chi's RequestID middleware passes an inbound
|
||||
// X-Request-Id header through verbatim. Its generated form is an
|
||||
@@ -96,14 +99,14 @@ const (
|
||||
// It is also the ceiling on every OTHER line this service writes
|
||||
// THROUGH SLOG that carries text an UNAUTHENTICATED client
|
||||
// supplies. Those lines — the MaxBodySize rejection, the CSRF
|
||||
// rejection, the rate-limit rejection, the unauthenticated-request
|
||||
// and unknown-entrypoint DEBUG lines, the failed-login DEBUG
|
||||
// lines, and the two login-throttle WARN lines ("login failure
|
||||
// limit exceeded" in loginguard.go and "password verification
|
||||
// capacity exhausted" in internal/handlers/auth.go) — spend the
|
||||
// same per-field budgets, and each carries strictly fewer
|
||||
// client-supplied fields than the access log does,
|
||||
// so none of them can reach a width the access log cannot. That is
|
||||
// rejection, the unauthenticated-request DEBUG line, the
|
||||
// failed-login DEBUG lines, and the two login-throttle WARN
|
||||
// lines ("login failure limit exceeded" in loginguard.go and
|
||||
// "password verification capacity exhausted" in
|
||||
// internal/handlers/auth.go) — spend the same per-field budgets,
|
||||
// and each carries strictly fewer client-supplied fields than the
|
||||
// access log does, so none of them can reach a width the access
|
||||
// log cannot. That is
|
||||
// asserted directly, per line and under both handlers, rather than
|
||||
// left to the reasoning: see logbound_test.go in this package and
|
||||
// in internal/handlers.
|
||||
@@ -151,6 +154,12 @@ const (
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
// ReceiverRoute is the route pattern the webhook receiver is served
|
||||
// at. Its path carries the entrypoint UUID, which is the receiver's
|
||||
// only credential, so the log lines this package writes name a
|
||||
// request on this route by the pattern, never by its path.
|
||||
const ReceiverRoute = "/h/{uuid}"
|
||||
|
||||
//nolint:revive // MiddlewareParams is a standard fx naming convention.
|
||||
type MiddlewareParams struct {
|
||||
fx.In
|
||||
@@ -268,14 +277,14 @@ func (lrw *loggingResponseWriter) Unwrap() http.ResponseWriter {
|
||||
// marker.
|
||||
//
|
||||
// The path on those branches is bounded by the service's routes or by
|
||||
// the operator's data — a 2xx on the receiver means the UUID named a
|
||||
// stored entrypoint, a 2xx under /s means the file is in the embedded
|
||||
// tree. The query is not bounded by anything: /.well-known/healthcheck
|
||||
// and /s/* take no authentication and sit behind no rate limiter, and
|
||||
// /pages/login behind only the login limiter, so any of them will
|
||||
// answer 200 to a URL carrying an arbitrary number of arbitrary bytes
|
||||
// after the '?'. Keeping the path and dropping the query is what makes
|
||||
// this branch as bounded as the pattern branches below.
|
||||
// the operator's data — a 2xx under /s means the file is in the
|
||||
// embedded tree. The query is not bounded by anything:
|
||||
// /.well-known/healthcheck and /s/* take no authentication and sit
|
||||
// behind no rate limiter, and /pages/login behind only the login
|
||||
// limiter, so any of them will answer 200 to a URL carrying an
|
||||
// arbitrary number of arbitrary bytes after the '?'. Keeping the path
|
||||
// and dropping the query is what makes this branch as bounded as the
|
||||
// pattern branches below.
|
||||
//
|
||||
// Nothing debuggable is lost. The only query parameters the service
|
||||
// reads are the login page's `next`, the page to return to,
|
||||
@@ -297,36 +306,61 @@ func concreteLogURL(r *http.Request) string {
|
||||
|
||||
// accessLogURL returns the value for the access log's url field.
|
||||
//
|
||||
// 2xx and 5xx responses get the concrete path (see concreteLogURL). A
|
||||
// success resolved against a static route or against the operator's
|
||||
// own data — on the receiver, a 2xx means the UUID named a stored
|
||||
// entrypoint — and a server error is our own bug, where the exact URL
|
||||
// is the primary evidence and which no client can provoke at will.
|
||||
// On ReceiverRoute it is the route pattern whatever the status, so
|
||||
// the entrypoint UUID in the path is never logged. A request chi never
|
||||
// routed gets unmatchedRoute whatever the status, for the same reason:
|
||||
// in dev, CORS answers a preflight to the receiver before routing.
|
||||
//
|
||||
// On every other route, 2xx and 5xx responses get the concrete path
|
||||
// (see concreteLogURL). A success resolved against a static route or
|
||||
// against the operator's own data, and a server error is our own bug,
|
||||
// where the exact URL is the primary evidence and which no client can
|
||||
// provoke at will.
|
||||
//
|
||||
// 3xx and 4xx responses get the chi route pattern instead. Those are
|
||||
// the outcomes an unauthenticated client drives for free: 404 or 429
|
||||
// on any invented /h/ path, 303 to the login page on any
|
||||
// invented /user/ path. Logging the concrete URL there lets a flood
|
||||
// write attacker-chosen text, of attacker-chosen length, into the
|
||||
// operator's log at one line per request. The pattern comes from the
|
||||
// router's own table, so it is bounded by the service's routes while
|
||||
// still naming which class of request was rejected.
|
||||
// the outcomes an unauthenticated client drives for free, such as a
|
||||
// 303 to the login page on any invented /user/ path. Logging the
|
||||
// concrete URL there lets a flood write attacker-chosen text, of
|
||||
// attacker-chosen length, into the operator's log at one line per
|
||||
// request. The pattern comes from the router's own table, so it is
|
||||
// bounded by the service's routes while still naming which class of
|
||||
// request was rejected.
|
||||
//
|
||||
// The pattern is only populated once routing has run, so this must be
|
||||
// called after the handler returns, not before.
|
||||
func accessLogURL(r *http.Request, status int) string {
|
||||
pattern := routePatternID(r.Context())
|
||||
if pattern == ReceiverRoute || pattern == unmatchedRoute {
|
||||
return pattern
|
||||
}
|
||||
|
||||
if status < http.StatusMultipleChoices ||
|
||||
status >= http.StatusInternalServerError {
|
||||
return concreteLogURL(r)
|
||||
}
|
||||
|
||||
if rc := chi.RouteContext(r.Context()); rc != nil {
|
||||
if pattern := rc.RoutePattern(); pattern != "" {
|
||||
return pattern
|
||||
}
|
||||
return pattern
|
||||
}
|
||||
|
||||
// accessLogReferer returns the value for the access log's referer
|
||||
// field: the Referer's scheme and host, never its path or query. The
|
||||
// path can be an entrypoint URL, which carries the UUID: a sender that
|
||||
// follows a redirect from http:// to https:// sends the URL it was
|
||||
// redirected from, and a browser sends the 404 page's URL under /h/
|
||||
// when it fetches that page's stylesheet. A Referer without both a
|
||||
// scheme and a host is logged as redactedReferer.
|
||||
func accessLogReferer(r *http.Request) string {
|
||||
referer := r.Referer()
|
||||
if referer == "" {
|
||||
return ""
|
||||
}
|
||||
|
||||
return unmatchedRoute
|
||||
parsed, err := url.Parse(referer)
|
||||
if err != nil || parsed.Scheme == "" || parsed.Host == "" {
|
||||
return redactedReferer
|
||||
}
|
||||
|
||||
return parsed.Scheme + "://" + parsed.Host
|
||||
}
|
||||
|
||||
// Logging returns middleware that logs each HTTP request with
|
||||
@@ -379,7 +413,7 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
|
||||
requestID, maxLogRequestIDBytes,
|
||||
),
|
||||
"referer", logfield.Truncate(
|
||||
r.Referer(), logfield.MaxBytes,
|
||||
accessLogReferer(r), logfield.MaxBytes,
|
||||
),
|
||||
"proto", r.Proto,
|
||||
"remoteIP", RemoteIP(r),
|
||||
|
||||
@@ -259,26 +259,28 @@ func (m *Middleware) clientAddr(r *http.Request) (netip.Addr, bool) {
|
||||
return peer, true
|
||||
}
|
||||
|
||||
// tooManyRequests returns the 429 handler used by the
|
||||
// password-change and per-entrypoint receiver limiters: it logs the
|
||||
// tooManyRequests returns the 429 handler used by the postRateLimit
|
||||
// limiters and the per-entrypoint receiver limiter: it logs the
|
||||
// rejection with logMessage and answers with responseMessage.
|
||||
// httprate adds the Retry-After header (RFC 6585). The aggregate
|
||||
// receiver limiter uses floodTooManyRequests instead.
|
||||
//
|
||||
// The path is capped against the same budget as the access log's url
|
||||
// field. The per-entrypoint receiver limiter is unauthenticated and
|
||||
// its path is a client-chosen segment of client-chosen length, so at
|
||||
// WARN an uncapped path would let a sender pick the size of the line
|
||||
// it writes — the same defect the access log capping closed.
|
||||
// On ReceiverRoute the line names the route pattern, so the
|
||||
// entrypoint UUID in the path is never logged. Elsewhere it names the
|
||||
// path, capped against the same budget as the access log's url field;
|
||||
// the limiters there sit behind RequireAuth, so the cap is defensive.
|
||||
func (m *Middleware) tooManyRequests(
|
||||
logMessage, responseMessage string,
|
||||
) http.HandlerFunc {
|
||||
return func(w http.ResponseWriter, r *http.Request) {
|
||||
path := r.URL.Path
|
||||
if routePatternID(r.Context()) == ReceiverRoute {
|
||||
path = ReceiverRoute
|
||||
}
|
||||
|
||||
m.log.Warn(
|
||||
logMessage,
|
||||
"path", logfield.Truncate(
|
||||
r.URL.Path, logfield.MaxBytes,
|
||||
),
|
||||
"path", logfield.Truncate(path, logfield.MaxBytes),
|
||||
"remoteIP", RemoteIP(r),
|
||||
"clientIP", ClientIP(r),
|
||||
)
|
||||
|
||||
@@ -6,7 +6,8 @@ import (
|
||||
|
||||
sentryhttp "github.com/getsentry/sentry-go/http"
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/go-chi/chi/middleware"
|
||||
chimw "github.com/go-chi/chi/middleware"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
"sneak.berlin/go/webhooker/static"
|
||||
)
|
||||
|
||||
@@ -60,7 +61,7 @@ func (s *Server) SetupRoutes() {
|
||||
}
|
||||
|
||||
func (s *Server) setupGlobalMiddleware() {
|
||||
s.router.Use(middleware.RequestID)
|
||||
s.router.Use(chimw.RequestID)
|
||||
s.router.Use(s.mw.SecurityHeaders())
|
||||
s.router.Use(s.mw.Logging())
|
||||
|
||||
@@ -345,7 +346,7 @@ func (s *Server) setupWebhookRoutes() {
|
||||
// unauthenticated endpoint's body; TestReceiver_OversizeBodyRefused
|
||||
// pins it.
|
||||
s.router.With(s.mw.ReceiverRateLimit()).HandleFunc(
|
||||
"/h/{uuid}",
|
||||
middleware.ReceiverRoute,
|
||||
s.h.HandleWebhook(),
|
||||
)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user