diff --git a/README.md b/README.md index 00de84b..876f261 100644 --- a/README.md +++ b/README.md @@ -456,6 +456,19 @@ Your proxy must therefore **append** the peer address to `option forwardfor`, Caddy and AWS ALB by default), and must append a bare address with no port. +Every log line that names a client carries two addresses: `remoteIP`, +the connecting peer, which behind a proxy is the proxy; and `clientIP`, +the client the rate limiters identify by the rules above, which is the +field to read when tracing who sent what. Those lines are the +`http request` access log line, the rate-limit rejection lines +(`login failure limit exceeded` among them), the +`csrf: token validation failed` warning and the receiver's +`webhook request received` line. `clientIP` is only as trustworthy as +`TRUSTED_PROXIES`: for a request from a peer inside the list, it is +read out of the `X-Forwarded-For` that peer sent, so a peer that does +not belong in the list can make it name any address it likes. For a +request from any other peer, both fields name the peer. + #### Sessions Sessions are bounded by two independent clocks, and end at whichever @@ -840,9 +853,9 @@ reports. was given, so on any port other than 443 `$host` makes every form POST — including login — fail with `403 origin invalid`, with nothing in the error naming the cause. -5. **Keep the proxy's access log.** webhooker's own access log records - the peer address, which behind a proxy is always the proxy. The - proxy's log is the only record of which client sent what. nginx's +5. **Keep the proxy's access log.** webhooker's own access log names + the client in its `clientIP` field only while `TRUSTED_PROXIES` + covers the proxy; the 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. @@ -871,9 +884,8 @@ server { # webhooker's message. client_max_body_size 1m; - # $remote_addr is the client. webhooker's own log records this - # proxy and nothing else, so this file is the only place the - # client's address is written down. + # $remote_addr is the client. webhooker's own log names it, as + # clientIP, only while TRUSTED_PROXIES covers this proxy. access_log /var/log/nginx/webhooker.access.log combined; location / { @@ -2448,20 +2460,20 @@ trade. Net: **one `INFO` line per request, of at most 2,560 bytes.** That ceiling is arithmetic, not an observation: 3 × (512 + 11) for `url`, `useragent` and `referer`, plus 128 + 11 for `request_id`, plus 32 + 11 -for `method`, plus a 336-byte fixed portion (the field names, the -punctuation, both timestamps at their longest, an IPv6 `remoteIP` with -a zone, the status and the latency) — 2,087 bytes, stated at 2,560 so -the figure has headroom. `internal/middleware/accesslog_test.go` -asserts it against 8 KB of client-chosen text in the path, in the -query, and in each of `User-Agent`, `Referer` and `X-Request-Id`, +for `method`, plus a 405-byte fixed portion (the field names, the +punctuation, both timestamps at their longest, `remoteIP` and +`clientIP` each charged as an IPv6 address with a zone, the status and +the latency) — 2,156 bytes, stated at 2,560 so the figure has headroom. +`internal/middleware/accesslog_test.go` asserts it against 8 KB of +client-chosen text in the path, in the query, and in each of +`User-Agent`, `Referer` and `X-Request-Id`, including cases built from the characters the handlers escape, and against the widest access log line the service can be made to write: a 5xx that keeps its concrete path while all three header fields are also at their budget. Every case runs through both handlers `internal/logger` can select — the JSON one and the text one it installs on a tty — since the two do not escape alike and the ceiling is quoted -unqualified. Measured over a real connection, the widest access log line -is 1,972 bytes. +unqualified. Multiply that ceiling by the request rate to size log storage. Note that the rate is not bounded by the limits above on every route: @@ -2799,9 +2811,9 @@ remedies are to block the source at the reverse proxy, or to rate-limit `POST /pages/login` there — the one place a limit can be applied without reintroducing the lockout, because the proxy sees the real client address. `TRUSTED_PROXIES` does not stop the saturation. -The flood's source is in the proxy's access log: webhooker's own logs -record the proxy's address, not the client's (see -[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)). +The flood's source is in the `clientIP` field of webhooker's access +log while `TRUSTED_PROXIES` covers the proxy, and in the proxy's own +access log either way (see [Trusted proxies](#trusted-proxies)). Finer-grained per-webhook rate limits (configured in the web UI and enforced in the webhook handler) can layer on top of this env-level @@ -3038,7 +3050,7 @@ Applied to all routes in this order: (HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy, Permissions-Policy) 3. **Logging** — Structured request logging (method, URL, status, - latency, remote IP, user agent, request ID) + latency, remote IP, client IP, user agent, request ID) 4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` and `METRICS_PASSWORD` are both set) 5. **CORS** — Cross-origin resource sharing headers diff --git a/internal/handlers/webhook.go b/internal/handlers/webhook.go index 7bf7660..e913057 100644 --- a/internal/handlers/webhook.go +++ b/internal/handlers/webhook.go @@ -11,6 +11,7 @@ import ( "sneak.berlin/go/webhooker/internal/database" "sneak.berlin/go/webhooker/internal/delivery" "sneak.berlin/go/webhooker/internal/logfield" + "sneak.berlin/go/webhooker/internal/middleware" ) const ( @@ -57,7 +58,8 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc { h.log.Info("webhook request received", "entrypoint_uuid", entrypointUUID, "method", r.Method, - "remote_addr", r.RemoteAddr, + "remoteIP", middleware.RemoteIP(r), + "clientIP", middleware.ClientIP(r), ) if !entrypoint.Active { diff --git a/internal/handlers/webhook_test.go b/internal/handlers/webhook_test.go new file mode 100644 index 0000000..bd91e4e --- /dev/null +++ b/internal/handlers/webhook_test.go @@ -0,0 +1,124 @@ +package handlers_test + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "net/netip" + "strings" + "testing" + + "github.com/go-chi/chi" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/database" + "sneak.berlin/go/webhooker/internal/handlers" + "sneak.berlin/go/webhooker/internal/middleware" +) + +// TestHandleWebhook_LogsClientNextToThePeer checks that the +// receiver's "webhook request received" line carries both addresses: +// remoteIP, the connecting peer, and clientIP, the client the access +// log attributes the request to. +func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) { + t.Parallel() + + // untrustedPeer is outside the trusted 10.0.0.0/8, so its + // X-Forwarded-For is ignored and it is the client. + const untrustedPeer = "192.0.2.10" + + cases := map[string]struct { + peer string + wantRemote string + wantClient string + }{ + "trusted proxy with a forwarded chain": { + peer: "10.0.0.1:44444", + wantRemote: "10.0.0.1", + wantClient: "198.51.100.7", + }, + "untrusted peer": { + peer: untrustedPeer + ":5555", + wantRemote: untrustedPeer, + wantClient: untrustedPeer, + }, + } + + for name, tc := range cases { + t.Run(name, func(t *testing.T) { + t.Parallel() + + var ( + h *handlers.Handlers + mw *middleware.Middleware + db *database.Database + ) + + app := newTestAppWithConfig(t, &config.Config{ + DataDir: t.TempDir(), + TrustedProxies: []netip.Prefix{ + netip.MustParsePrefix("10.0.0.0/8"), + }, + }, &h, &mw, &db) + app.RequireStart() + + t.Cleanup(app.RequireStop) + + buf := new(bytes.Buffer) + h.SetLogForTest(slog.New(slog.NewJSONHandler(buf, nil))) + + webhook := seedWebhook(t, db) + seedEntrypoint(t, db, webhook.ID) + + // Logging is what works the client address out, so the + // request goes through it as it does in production. + router := chi.NewRouter() + router.Use(mw.Logging()) + router.Post("/h/{uuid}", h.HandleWebhook()) + + req := httptest.NewRequestWithContext( + context.Background(), http.MethodPost, + "/h/ep-"+webhook.ID, strings.NewReader("{}"), + ) + req.RemoteAddr = tc.peer + req.Header.Set("X-Forwarded-For", "198.51.100.7, 10.0.0.2") + + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + + require.Equal(t, http.StatusOK, w.Code) + + line := receivedLine(t, buf) + assert.Equal(t, tc.wantRemote, line["remoteIP"]) + assert.Equal(t, tc.wantClient, line["clientIP"]) + }) + } +} + +// receivedLine returns the one "webhook request received" line in the +// captured JSON log. +func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + + var found []map[string]any + + for line := range strings.SplitSeq( + strings.TrimSpace(buf.String()), "\n", + ) { + var entry map[string]any + + require.NoError(t, json.Unmarshal([]byte(line), &entry)) + + if entry["msg"] == "webhook request received" { + found = append(found, entry) + } + } + + require.Len(t, found, 1) + + return found[0] +} diff --git a/internal/middleware/accesslog_test.go b/internal/middleware/accesslog_test.go index 10ae894..046c0ad 100644 --- a/internal/middleware/accesslog_test.go +++ b/internal/middleware/accesslog_test.go @@ -648,7 +648,8 @@ func TestAccessLog_RetainsEveryOtherField(t *testing.T) { for _, key := range []string{ "request_start", "method", "url", "useragent", "request_id", - "referer", "proto", "remoteIP", "status", "latency_ms", + "referer", "proto", "remoteIP", "clientIP", "status", + "latency_ms", } { assert.Contains(t, entries[0], key) } diff --git a/internal/middleware/clientip_test.go b/internal/middleware/clientip_test.go new file mode 100644 index 0000000..809357a --- /dev/null +++ b/internal/middleware/clientip_test.go @@ -0,0 +1,176 @@ +package middleware_test + +import ( + "bytes" + "context" + "log/slog" + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/middleware" +) + +const ( + // forwardedChain is the X-Forwarded-For a request arrives with: + // the client, then a second proxy inside trustedProxyCIDR that the + // request passed through before reaching trustedPeer. + forwardedChain = clientIPv4 + ", 10.0.0.2" + + // untrustedPeer is a peer outside trustedProxyCIDR, so its + // X-Forwarded-For is ignored and the peer is the client. + untrustedPeer = "192.0.2.10:5555" + + // oneRequestPerMinute is the receiver limit these tests install: + // the second request on a path is rejected, and the aggregate + // limit is ReceiverAggregateMultiplierConst. + oneRequestPerMinute = 1 +) + +// clientLogSite is one log line that names the client. build wraps the +// middleware that writes it around a handler, and requests is how many +// identical requests it takes before the line is written. +type clientLogSite struct { + build func(m *middleware.Middleware) http.Handler + requests int +} + +// clientLogSites maps the message of each line that names the client +// to the way to make it be written. +func clientLogSites() map[string]clientLogSite { + served := func(*middleware.Middleware) http.Handler { + return okHandler() + } + + receiver := func(m *middleware.Middleware) http.Handler { + return m.ReceiverRateLimit()(okHandler()) + } + + login := func(m *middleware.Middleware) http.Handler { + return http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + m.RecordLoginFailure(r, "someone") + w.WriteHeader(http.StatusUnauthorized) + }, + ) + } + + csrf := func(m *middleware.Middleware) http.Handler { + return m.CSRF(http.HandlerFunc(forbidden))(okHandler()) + } + + return map[string]clientLogSite{ + "http request": { + build: served, + requests: 1, + }, + "webhook receiver rate limit exceeded": { + build: receiver, + requests: oneRequestPerMinute + 1, + }, + // The aggregate limit sits in front of the per-entrypoint + // one, so the requests that one rejects count towards it. + "webhook receiver aggregate rate limit exceeded": { + build: receiver, + requests: middleware.ReceiverAggregateMultiplierConst* + oneRequestPerMinute + 1, + }, + "login failure limit exceeded": { + build: login, + requests: middleware.LoginRateLimitConst + 1, + }, + "csrf: token validation failed": { + build: csrf, + requests: 1, + }, + } +} + +// clientLogLines sends the site's requests from peer, each carrying +// forwardedChain, through Logging and then the site, as production +// does, and returns the logged lines whose message is msg. +func clientLogLines( + t *testing.T, site clientLogSite, msg, peer string, +) []map[string]any { + t.Helper() + + buf := new(bytes.Buffer) + log := slog.New(slog.NewJSONHandler( + buf, + &slog.HandlerOptions{Level: slog.LevelDebug}, + )) + + cfg := &config.Config{ + Environment: config.EnvironmentDev, + ReceiverRateLimit: oneRequestPerMinute, + TrustedProxies: trustedProxies(trustedProxyCIDR), + } + + m := middleware.NewForTest( + log, cfg, newTestSessionManager(cfg, log, nil), + ) + handler := m.Logging()(site.build(m)) + + for range site.requests { + req := httptest.NewRequestWithContext( + context.Background(), http.MethodPost, "/h/x", nil, + ) + req.RemoteAddr = peer + req.Header.Set(headerXFF, forwardedChain) + + handler.ServeHTTP(httptest.NewRecorder(), req) + } + + var lines []map[string]any + + for _, entry := range accessLogEntries(t, buf) { + if entry["msg"] == msg { + lines = append(lines, entry) + } + } + + return lines +} + +// TestClientIP_LoggedNextToThePeer checks that every line that names +// the client carries both addresses: remoteIP, the connecting peer, +// and clientIP, the client the rate limiters key on. +func TestClientIP_LoggedNextToThePeer(t *testing.T) { + t.Parallel() + + cases := map[string]struct { + peer string + wantRemote string + wantClient string + }{ + "trusted proxy with a forwarded chain": { + peer: trustedPeer, + wantRemote: "10.0.0.1", + wantClient: clientIPv4, + }, + "untrusted peer": { + peer: untrustedPeer, + wantRemote: "192.0.2.10", + wantClient: "192.0.2.10", + }, + } + + for msg, site := range clientLogSites() { + for name, tc := range cases { + t.Run(msg+"/"+name, func(t *testing.T) { + t.Parallel() + + lines := clientLogLines(t, site, msg, tc.peer) + require.NotEmpty(t, lines, "%q was never logged", msg) + + for _, line := range lines { + assert.Equal(t, tc.wantRemote, line["remoteIP"]) + assert.Equal(t, tc.wantClient, line["clientIP"]) + } + }) + } + } +} diff --git a/internal/middleware/csrf.go b/internal/middleware/csrf.go index 2ad5846..92ada3f 100644 --- a/internal/middleware/csrf.go +++ b/internal/middleware/csrf.go @@ -45,10 +45,10 @@ func (m *Middleware) CSRF( // unauthenticated client: a POST with no token to // /hook//edit lands here. The // method and path are capped against the same budgets as - // the access log. remote_addr is set by net/http from the - // accepted connection rather than by the client, and + // the access log. remoteIP and clientIP are the same + // addresses the access log carries, and // csrf.FailureReason returns one of gorilla/csrf's own - // fixed error values, so neither is client-sized. + // fixed error values, so none of them is client-sized. m.log.Warn("csrf: token validation failed", "method", logfield.Truncate( r.Method, maxLogMethodBytes, @@ -56,7 +56,8 @@ func (m *Middleware) CSRF( "path", logfield.Truncate( r.URL.Path, logfield.MaxBytes, ), - "remote_addr", r.RemoteAddr, + "remoteIP", RemoteIP(r), + "clientIP", ClientIP(r), "reason", csrf.FailureReason(r), ) forbidden.ServeHTTP(w, r) diff --git a/internal/middleware/loginguard.go b/internal/middleware/loginguard.go index 2d8c385..e0d5ee4 100644 --- a/internal/middleware/loginguard.go +++ b/internal/middleware/loginguard.go @@ -385,6 +385,8 @@ func (m *Middleware) RecordLoginFailure( "path", logfield.Truncate( r.URL.Path, logfield.MaxBytes, ), + "remoteIP", RemoteIP(r), + "clientIP", ClientIP(r), ) } diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 7552a4a..51c8bbd 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -3,6 +3,7 @@ package middleware import ( + "context" "log/slog" "net" "net/http" @@ -69,18 +70,19 @@ const ( // url, useragent, referer 3*(512+11) = 1569 // request_id 128+11 = 139 // method 32+11 = 43 - // fixed portion = 336 + // fixed portion = 405 // ---- - // 2087 + // 2156 // // The 512 is logfield.MaxBytes; the 11 is the truncation marker, // charged on top of each budget rather than inside it. // // The fixed portion is the JSON punctuation, the field names, the - // level and the message, both timestamps at their longest, an IPv6 - // remoteIP with a zone, a three-digit status and a full-width int64 - // latency. Stated at 2560 so the figure carries headroom rather - // than sitting on the arithmetic. + // level and the message, both timestamps at their longest, remoteIP + // and clientIP each charged as an IPv6 address with a zone, a + // three-digit status and a full-width int64 latency. Stated at 2560 + // so the figure carries headroom rather than sitting on the + // arithmetic. // // The tty text handler in internal/logger is covered by the same // figure. logfield.EncodedBytes charges every rune at least what @@ -88,8 +90,8 @@ const ( // bytes strconv.Quote spends on a non-printable rune at or above // U+10000, which is four more than the JSON handler ever spends — // so each budget bounds the encoded field under either handler. - // The text handler's fixed portion is 286, the smaller of the two, - // which puts its worst case at 2037. + // The text handler's fixed portion is 351, the smaller of the two, + // which puts its worst case at 2102. // // It is also the ceiling on every OTHER line this service writes // THROUGH SLOG that carries text an UNAUTHENTICATED client @@ -215,6 +217,28 @@ func ipFromHostPort(hp string) string { return h } +// RemoteIP returns the address of the connecting peer, without its +// port. Behind a reverse proxy it is the proxy. Every log line that +// names the client logs it as remoteIP, next to clientIP. +func RemoteIP(r *http.Request) string { + return ipFromHostPort(r.RemoteAddr) +} + +// clientIPKey is the request context key under which Logging stores +// the value ClientIP returns. +type clientIPKey struct{} + +// ClientIP returns the address the request is attributed to, which +// Logging works out once per request with clientAddr in ratelimit.go +// and logs as clientIP. The other lines that name the client read it +// from here, so all of them agree. It is empty for a request Logging +// has not seen. +func ClientIP(r *http.Request) string { + ip, _ := r.Context().Value(clientIPKey{}).(string) + + return ip +} + type loggingResponseWriter struct { http.ResponseWriter @@ -316,6 +340,13 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { lrw := newLoggingResponseWriter(w) ctx := r.Context() + // When RemoteAddr is not an address, the peer's own + // text is all the request can be attributed to. + clientIP := RemoteIP(r) + if addr, ok := s.clientAddr(r); ok { + clientIP = addr.String() + } + defer func() { latency := time.Since(start) requestID := "" @@ -350,13 +381,16 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { r.Referer(), logfield.MaxBytes, ), "proto", r.Proto, - "remoteIP", ipFromHostPort(r.RemoteAddr), + "remoteIP", RemoteIP(r), + "clientIP", clientIP, "status", lrw.statusCode, "latency_ms", latency.Milliseconds(), ) }() - next.ServeHTTP(lrw, r) + next.ServeHTTP(lrw, r.WithContext( + context.WithValue(ctx, clientIPKey{}, clientIP), + )) }) } } diff --git a/internal/middleware/ratelimit.go b/internal/middleware/ratelimit.go index 8249b6b..a3ebe85 100644 --- a/internal/middleware/ratelimit.go +++ b/internal/middleware/ratelimit.go @@ -202,24 +202,17 @@ func (m *Middleware) forwardedClientAddr( } // rateLimitKey is the client identity every rate limiter in this -// package buckets on. Forwarded headers are honoured only when the -// direct peer (RemoteAddr) is inside the configured trusted-proxy -// set; otherwise the peer address itself is the key. Without that -// gate any client could mint a fresh bucket per request, or starve -// another client's bucket, by picking an X-Forwarded-For value — -// which makes every limit here decorative against a deliberate -// attacker. -// -// The address that identifies the client is then reduced to a bucket -// by bucketKey: full address for IPv4, /64 prefix for IPv6. +// package buckets on: the address clientAddr attributes the request +// to, reduced to a bucket by bucketKey — full address for IPv4, /64 +// prefix for IPv6. func (m *Middleware) rateLimitKey(r *http.Request) (string, error) { return m.clientKey(r), nil } // clientKey computes the bucket key described on rateLimitKey. func (m *Middleware) clientKey(r *http.Request) string { - peer, err := netip.ParseAddr(ipFromHostPort(r.RemoteAddr)) - if err != nil { + addr, ok := m.clientAddr(r) + if !ok { // Not an address we can reason about; key on the raw // value, the most specific identity left. Distinct // RemoteAddr values stay in distinct buckets, so this @@ -230,16 +223,36 @@ func (m *Middleware) clientKey(r *http.Request) string { return r.RemoteAddr } + return bucketKey(addr) +} + +// clientAddr is the address a request is attributed to. The rate +// limiters key on it and the logs name it as clientIP. +// +// Forwarded headers are honoured only when the direct peer +// (RemoteAddr) is inside the configured trusted-proxy set; otherwise +// the peer address itself is the client. Without that gate any client +// could mint a fresh bucket per request, or starve another client's +// bucket, by picking an X-Forwarded-For value — which makes every +// limit here decorative against a deliberate attacker. +// +// ok is false when RemoteAddr is not an address at all. +func (m *Middleware) clientAddr(r *http.Request) (netip.Addr, bool) { + peer, err := netip.ParseAddr(ipFromHostPort(r.RemoteAddr)) + if err != nil { + return netip.Addr{}, false + } + peer = normalizeAddr(peer) if !m.isTrustedProxy(peer) { - return bucketKey(peer) + return peer, true } if addr, ok := m.forwardedClientAddr(r); ok { - return bucketKey(addr) + return addr, true } - return bucketKey(peer) + return peer, true } // tooManyRequests returns the 429 handler used by the @@ -262,6 +275,8 @@ func (m *Middleware) tooManyRequests( "path", logfield.Truncate( r.URL.Path, logfield.MaxBytes, ), + "remoteIP", RemoteIP(r), + "clientIP", ClientIP(r), ) http.Error(w, responseMessage, http.StatusTooManyRequests) } @@ -286,8 +301,12 @@ func (m *Middleware) tooManyRequests( func (m *Middleware) floodTooManyRequests( logMessage, responseMessage string, ) http.HandlerFunc { - return func(w http.ResponseWriter, _ *http.Request) { - m.log.Debug(logMessage) + return func(w http.ResponseWriter, r *http.Request) { + m.log.Debug( + logMessage, + "remoteIP", RemoteIP(r), + "clientIP", ClientIP(r), + ) http.Error(w, responseMessage, http.StatusTooManyRequests) } }