fix(backend): cut request log fields to the log bound (closes #60)
check / check (push) Successful in 50s

The request log wrote the URL, User-Agent, Referer and other
request-supplied strings with no length limit, and the server accepts
headers up to 1 MiB, so one request could put about 1 MiB per field
into a log line. Every string the request log takes from the request,
including the request ID chi copies from X-Request-Id, is now cut to
the 128-byte bound the report handler already used. That bound and
its helper moved from the handlers package to the logger package so
both use the one copy.

Model: opus-5-5
This commit is contained in:
2026-09-29 06:28:21 +00:00
parent 6022cc8b02
commit f6d2d98824
7 changed files with 92 additions and 37 deletions
+6
View File
@@ -23,6 +23,12 @@ latest run passes.
# Completed Steps # Completed Steps
- 2026-09-29: the request log is bounded (issue #60): the method, URL, protocol,
`User-Agent`, `Referer`, request ID (which chi takes from the client's
`X-Request-Id` header) and client address it writes are each cut to 128 bytes,
the bound the report handler already used, so one request can no longer put
about 1 MiB per field into a log line. That bound and its helper now live in
the `logger` package, shared by both
- 2026-09-29: report file names can no longer collide (issue #61): each is - 2026-09-29: report file names can no longer collide (issue #61): each is
`reports-<timestamp>-<number>.jsonl.zst`, where the number goes up by one for `reports-<timestamp>-<number>.jsonl.zst`, where the number goes up by one for
each file the server starts to write, so two flushes in the same millisecond, each file the server starts to write, so two flushes in the same millisecond,
-3
View File
@@ -2,9 +2,6 @@ package handlers
import "log/slog" import "log/slog"
// MaxLoggedFieldBytes exposes the log bound to the external tests.
const MaxLoggedFieldBytes = maxLoggedFieldBytes
// NewForTest builds a Handlers around a report sink and logger, // NewForTest builds a Handlers around a report sink and logger,
// bypassing the fx graph so handler behaviour (including the // bypassing the fx graph so handler behaviour (including the
// storage failure path) is exercisable in unit tests. // storage failure path) is exercisable in unit tests.
+4 -18
View File
@@ -5,14 +5,10 @@ import (
"errors" "errors"
"net/http" "net/http"
"sneak.berlin/go/netwatch/internal/logger"
"sneak.berlin/go/netwatch/internal/reportbuf" "sneak.berlin/go/netwatch/internal/reportbuf"
) )
// maxLoggedFieldBytes bounds untrusted text (string fields,
// decode error text) before it is logged, so a caller cannot
// inflate log volume with an oversized value.
const maxLoggedFieldBytes = 128
type reportSample struct { type reportSample struct {
T int64 `json:"t"` T int64 `json:"t"`
Latency *int `json:"latency"` Latency *int `json:"latency"`
@@ -83,7 +79,7 @@ func (s *Handlers) decodeErrorStatus(err error) int {
// The decoder's error text can quote request bytes (a whole // The decoder's error text can quote request bytes (a whole
// oversized number, for example), so it is bounded too. // oversized number, for example), so it is bounded too.
s.log.Error("failed to decode report", s.log.Error("failed to decode report",
"error", boundedForLog(err.Error()), "error", logger.BoundedForLog(err.Error()),
) )
return http.StatusBadRequest return http.StatusBadRequest
@@ -115,20 +111,10 @@ func (s *Handlers) logReportReceived(rpt report) {
} }
s.log.Info("report received", s.log.Info("report received",
"client_id", boundedForLog(rpt.ClientID), "client_id", logger.BoundedForLog(rpt.ClientID),
"timestamp", boundedForLog(rpt.Timestamp), "timestamp", logger.BoundedForLog(rpt.Timestamp),
"host_count", len(rpt.Hosts), "host_count", len(rpt.Hosts),
"total_samples", totalSamples, "total_samples", totalSamples,
"geo_bytes", len(rpt.Geo), "geo_bytes", len(rpt.Geo),
) )
} }
// boundedForLog truncates an untrusted string to a fixed byte
// bound so an attacker-controlled field cannot dominate the log.
func boundedForLog(s string) string {
if len(s) > maxLoggedFieldBytes {
return s[:maxLoggedFieldBytes]
}
return s
}
+6 -5
View File
@@ -12,6 +12,7 @@ import (
"testing" "testing"
"sneak.berlin/go/netwatch/internal/handlers" "sneak.berlin/go/netwatch/internal/handlers"
"sneak.berlin/go/netwatch/internal/logger"
"sneak.berlin/go/netwatch/internal/middleware" "sneak.berlin/go/netwatch/internal/middleware"
"sneak.berlin/go/netwatch/internal/reportbuf" "sneak.berlin/go/netwatch/internal/reportbuf"
) )
@@ -174,7 +175,7 @@ func TestHandleReportDoesNotLogRawGeo(t *testing.T) {
func TestHandleReportLogsClientIDCutToBound(t *testing.T) { func TestHandleReportLogsClientIDCutToBound(t *testing.T) {
t.Parallel() t.Parallel()
long := strings.Repeat("c", 2*handlers.MaxLoggedFieldBytes) long := strings.Repeat("c", 2*logger.MaxLoggedFieldBytes)
var logbuf bytes.Buffer var logbuf bytes.Buffer
@@ -197,16 +198,16 @@ func TestHandleReportLogsClientIDCutToBound(t *testing.T) {
t.Fatalf("log line not JSON: %v (%q)", err, logbuf.String()) t.Fatalf("log line not JSON: %v (%q)", err, logbuf.String())
} }
want := long[:handlers.MaxLoggedFieldBytes] want := long[:logger.MaxLoggedFieldBytes]
if logged["client_id"] != want { if logged["client_id"] != want {
t.Fatalf("logged client_id not cut to %d bytes: %q", t.Fatalf("logged client_id not cut to %d bytes: %q",
handlers.MaxLoggedFieldBytes, logged["client_id"]) logger.MaxLoggedFieldBytes, logged["client_id"])
} }
if logged["timestamp"] != want { if logged["timestamp"] != want {
t.Fatalf("logged timestamp not cut to %d bytes: %q", t.Fatalf("logged timestamp not cut to %d bytes: %q",
handlers.MaxLoggedFieldBytes, logged["timestamp"]) logger.MaxLoggedFieldBytes, logged["timestamp"])
} }
} }
@@ -215,7 +216,7 @@ func TestHandleReportDecodeErrorLogIsBounded(t *testing.T) {
// A number too large for its int64 field makes the decoder's // A number too large for its int64 field makes the decoder's
// error text quote the whole number. // error text quote the whole number.
huge := strings.Repeat("9", 2*handlers.MaxLoggedFieldBytes) huge := strings.Repeat("9", 2*logger.MaxLoggedFieldBytes)
var logbuf bytes.Buffer var logbuf bytes.Buffer
+15
View File
@@ -11,6 +11,21 @@ import (
"go.uber.org/fx" "go.uber.org/fx"
) )
// MaxLoggedFieldBytes bounds untrusted text (request fields,
// header values, decode error text) before it is logged, so a
// caller cannot inflate log volume with an oversized value.
const MaxLoggedFieldBytes = 128
// BoundedForLog truncates an untrusted string to a fixed byte
// bound so an attacker-controlled field cannot dominate the log.
func BoundedForLog(s string) string {
if len(s) > MaxLoggedFieldBytes {
return s[:MaxLoggedFieldBytes]
}
return s
}
// Params defines the dependencies for Logger. // Params defines the dependencies for Logger.
type Params struct { type Params struct {
fx.In fx.In
+12 -11
View File
@@ -187,7 +187,10 @@ func addrInAny(s string, trusted []netip.Prefix) bool {
} }
// Logging returns middleware that logs each request with // Logging returns middleware that logs each request with
// timing, status code, and client information. // timing, status code, and client information. Every string
// taken from the request is cut to logger.MaxLoggedFieldBytes,
// including the request ID, which chi takes from the client's
// X-Request-Id header when one is sent.
func (s *Middleware) Logging() func(http.Handler) http.Handler { func (s *Middleware) Logging() func(http.Handler) http.Handler {
return func(next http.Handler) http.Handler { return func(next http.Handler) http.Handler {
return http.HandlerFunc( return http.HandlerFunc(
@@ -200,21 +203,19 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
latency := time.Since(start) latency := time.Since(start)
s.log.InfoContext(ctx, "request", s.log.InfoContext(ctx, "request",
"request_start", start, "request_start", start,
"method", r.Method, "method", logger.BoundedForLog(r.Method),
"url", r.URL.String(), "url", logger.BoundedForLog(r.URL.String()),
"useragent", r.UserAgent(), "useragent", logger.BoundedForLog(r.UserAgent()),
"request_id", "request_id",
ctx.Value( logger.BoundedForLog(middleware.GetReqID(ctx)),
middleware.RequestIDKey, "referer", logger.BoundedForLog(r.Referer()),
), "proto", logger.BoundedForLog(r.Proto),
"referer", r.Referer(),
"proto", r.Proto,
"remote_ip", "remote_ip",
clientIP( logger.BoundedForLog(clientIP(
r.RemoteAddr, r.RemoteAddr,
r.Header, r.Header,
s.trustedProxies, s.trustedProxies,
), )),
"status", lrw.statusCode, "status", lrw.statusCode,
"latency_ms", "latency_ms",
latency.Milliseconds(), latency.Milliseconds(),
@@ -13,7 +13,10 @@ import (
"testing/synctest" "testing/synctest"
"time" "time"
"sneak.berlin/go/netwatch/internal/logger"
"sneak.berlin/go/netwatch/internal/middleware" "sneak.berlin/go/netwatch/internal/middleware"
chimiddleware "github.com/go-chi/chi/v5/middleware"
) )
const ( const (
@@ -303,6 +306,52 @@ func TestRecovererRepanicsOnAbortHandler(t *testing.T) {
} }
} }
// TestLoggingCutsRequestStringsToBound sends an over-long URL and
// over-long header values, and checks the request log writes each
// one cut to logger.MaxLoggedFieldBytes.
func TestLoggingCutsRequestStringsToBound(t *testing.T) {
t.Parallel()
long := strings.Repeat("a", 2*logger.MaxLoggedFieldBytes)
var logbuf bytes.Buffer
mw := middleware.NewWithLogger(
slog.New(slog.NewJSONHandler(&logbuf, nil)),
)
handler := chimiddleware.RequestID(mw.Logging()(okHandler()))
req := httptest.NewRequestWithContext(t.Context(),
http.MethodGet, "/"+long, http.NoBody)
req.Header.Set("User-Agent", long)
req.Header.Set("Referer", long)
req.Header.Set("X-Request-Id", long)
handler.ServeHTTP(httptest.NewRecorder(), req)
var logged map[string]any
err := json.Unmarshal(logbuf.Bytes(), &logged)
if err != nil {
t.Fatalf("log line not JSON: %v (%q)", err, logbuf.String())
}
want := map[string]string{
"url": ("/" + long)[:logger.MaxLoggedFieldBytes],
"useragent": long[:logger.MaxLoggedFieldBytes],
"referer": long[:logger.MaxLoggedFieldBytes],
"request_id": long[:logger.MaxLoggedFieldBytes],
}
for field, value := range want {
if logged[field] != value {
t.Errorf("logged %s = %q, want it cut to %d bytes",
field, logged[field], logger.MaxLoggedFieldBytes)
}
}
}
// okHandler stands in for the route a middleware guards. // okHandler stands in for the route a middleware guards.
func okHandler() http.Handler { func okHandler() http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {