diff --git a/TODO.md b/TODO.md index da6fdcd..c3b0c9c 100644 --- a/TODO.md +++ b/TODO.md @@ -23,6 +23,12 @@ latest run passes. # 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 `reports--.jsonl.zst`, where the number goes up by one for each file the server starts to write, so two flushes in the same millisecond, diff --git a/backend/internal/handlers/export_test.go b/backend/internal/handlers/export_test.go index 7de02a5..220da99 100644 --- a/backend/internal/handlers/export_test.go +++ b/backend/internal/handlers/export_test.go @@ -2,9 +2,6 @@ package handlers 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, // bypassing the fx graph so handler behaviour (including the // storage failure path) is exercisable in unit tests. diff --git a/backend/internal/handlers/report.go b/backend/internal/handlers/report.go index 859a3a7..e7dd4e4 100644 --- a/backend/internal/handlers/report.go +++ b/backend/internal/handlers/report.go @@ -5,14 +5,10 @@ import ( "errors" "net/http" + "sneak.berlin/go/netwatch/internal/logger" "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 { T int64 `json:"t"` 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 // oversized number, for example), so it is bounded too. s.log.Error("failed to decode report", - "error", boundedForLog(err.Error()), + "error", logger.BoundedForLog(err.Error()), ) return http.StatusBadRequest @@ -115,20 +111,10 @@ func (s *Handlers) logReportReceived(rpt report) { } s.log.Info("report received", - "client_id", boundedForLog(rpt.ClientID), - "timestamp", boundedForLog(rpt.Timestamp), + "client_id", logger.BoundedForLog(rpt.ClientID), + "timestamp", logger.BoundedForLog(rpt.Timestamp), "host_count", len(rpt.Hosts), "total_samples", totalSamples, "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 -} diff --git a/backend/internal/handlers/report_test.go b/backend/internal/handlers/report_test.go index 996ce5c..cd94b5c 100644 --- a/backend/internal/handlers/report_test.go +++ b/backend/internal/handlers/report_test.go @@ -12,6 +12,7 @@ import ( "testing" "sneak.berlin/go/netwatch/internal/handlers" + "sneak.berlin/go/netwatch/internal/logger" "sneak.berlin/go/netwatch/internal/middleware" "sneak.berlin/go/netwatch/internal/reportbuf" ) @@ -174,7 +175,7 @@ func TestHandleReportDoesNotLogRawGeo(t *testing.T) { func TestHandleReportLogsClientIDCutToBound(t *testing.T) { t.Parallel() - long := strings.Repeat("c", 2*handlers.MaxLoggedFieldBytes) + long := strings.Repeat("c", 2*logger.MaxLoggedFieldBytes) var logbuf bytes.Buffer @@ -197,16 +198,16 @@ func TestHandleReportLogsClientIDCutToBound(t *testing.T) { t.Fatalf("log line not JSON: %v (%q)", err, logbuf.String()) } - want := long[:handlers.MaxLoggedFieldBytes] + want := long[:logger.MaxLoggedFieldBytes] if logged["client_id"] != want { 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 { 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 // error text quote the whole number. - huge := strings.Repeat("9", 2*handlers.MaxLoggedFieldBytes) + huge := strings.Repeat("9", 2*logger.MaxLoggedFieldBytes) var logbuf bytes.Buffer diff --git a/backend/internal/logger/logger.go b/backend/internal/logger/logger.go index 9f30c1a..de6c884 100644 --- a/backend/internal/logger/logger.go +++ b/backend/internal/logger/logger.go @@ -11,6 +11,21 @@ import ( "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. type Params struct { fx.In diff --git a/backend/internal/middleware/middleware.go b/backend/internal/middleware/middleware.go index d59ecdf..87ae3a9 100644 --- a/backend/internal/middleware/middleware.go +++ b/backend/internal/middleware/middleware.go @@ -187,7 +187,10 @@ func addrInAny(s string, trusted []netip.Prefix) bool { } // 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 { return func(next http.Handler) http.Handler { return http.HandlerFunc( @@ -200,21 +203,19 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { latency := time.Since(start) s.log.InfoContext(ctx, "request", "request_start", start, - "method", r.Method, - "url", r.URL.String(), - "useragent", r.UserAgent(), + "method", logger.BoundedForLog(r.Method), + "url", logger.BoundedForLog(r.URL.String()), + "useragent", logger.BoundedForLog(r.UserAgent()), "request_id", - ctx.Value( - middleware.RequestIDKey, - ), - "referer", r.Referer(), - "proto", r.Proto, + logger.BoundedForLog(middleware.GetReqID(ctx)), + "referer", logger.BoundedForLog(r.Referer()), + "proto", logger.BoundedForLog(r.Proto), "remote_ip", - clientIP( + logger.BoundedForLog(clientIP( r.RemoteAddr, r.Header, s.trustedProxies, - ), + )), "status", lrw.statusCode, "latency_ms", latency.Milliseconds(), diff --git a/backend/internal/middleware/middleware_test.go b/backend/internal/middleware/middleware_test.go index 559c308..d08c973 100644 --- a/backend/internal/middleware/middleware_test.go +++ b/backend/internal/middleware/middleware_test.go @@ -13,7 +13,10 @@ import ( "testing/synctest" "time" + "sneak.berlin/go/netwatch/internal/logger" "sneak.berlin/go/netwatch/internal/middleware" + + chimiddleware "github.com/go-chi/chi/v5/middleware" ) 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. func okHandler() http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {