diff --git a/TODO.md b/TODO.md index d4ff3d6..dc6fefc 100644 --- a/TODO.md +++ b/TODO.md @@ -23,6 +23,14 @@ latest run passes. # Completed Steps +- 2026-09-28: report ingest correctness (issue #23): a storage failure now + returns 500 instead of a false `ok`; oversize bodies return 413 (distinguished + from malformed JSON, which stays 400); a `MaxBodyBytes` middleware caps every + route, not just the report route; the raw attacker-controlled `geo` blob is no + longer logged (only its length), and `client_id`, `timestamp` and decode error + text are length-bounded before logging; a `decodeJSON` handler helper was + added; and panic recovery now routes the stack through slog instead of chi's + plain-text stderr - 2026-09-21: shutdown lifecycle correctness. The process now shuts down through fx instead of `os.Exit`, so every component's `OnStop` runs and buffered reports are flushed to disk on `SIGTERM` — previously a full flush window of diff --git a/backend/internal/handlers/export_test.go b/backend/internal/handlers/export_test.go new file mode 100644 index 0000000..7de02a5 --- /dev/null +++ b/backend/internal/handlers/export_test.go @@ -0,0 +1,13 @@ +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. +func NewForTest(buf reportAppender, log *slog.Logger) *Handlers { + return &Handlers{buf: buf, log: log} +} diff --git a/backend/internal/handlers/handlers.go b/backend/internal/handlers/handlers.go index a327fcd..db51059 100644 --- a/backend/internal/handlers/handlers.go +++ b/backend/internal/handlers/handlers.go @@ -18,6 +18,13 @@ import ( const jsonContentType = "application/json; charset=utf-8" +// reportAppender is the subset of the report buffer the handlers +// depend on. Defining it here keeps the storage failure path +// exercisable with a stub in tests. +type reportAppender interface { + Append(v any) error +} + // Params defines the dependencies for Handlers. type Params struct { fx.In @@ -30,7 +37,7 @@ type Params struct { // Handlers provides HTTP handler factories for all endpoints. type Handlers struct { - buf *reportbuf.Buffer + buf reportAppender hc *healthcheck.Healthcheck log *slog.Logger params *Params @@ -72,3 +79,15 @@ func (s *Handlers) respondJSON( } } } + +// decodeJSON decodes the request body into v. The body is +// expected to already be bounded by the body-size middleware, so +// a caller can distinguish an over-limit body from malformed +// JSON by testing the returned error for *http.MaxBytesError. +func (s *Handlers) decodeJSON( + _ http.ResponseWriter, + r *http.Request, + v any, +) error { + return json.NewDecoder(r.Body).Decode(v) +} diff --git a/backend/internal/handlers/report.go b/backend/internal/handlers/report.go index d4b54ed..81954a2 100644 --- a/backend/internal/handlers/report.go +++ b/backend/internal/handlers/report.go @@ -2,10 +2,14 @@ package handlers import ( "encoding/json" + "errors" "net/http" ) -const maxReportBodyBytes = 1 << 20 // 1 MiB +// 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"` @@ -35,48 +39,80 @@ func (s *Handlers) HandleReport() http.HandlerFunc { } return func(w http.ResponseWriter, r *http.Request) { - r.Body = http.MaxBytesReader( - w, r.Body, maxReportBodyBytes, - ) - var rpt report - err := json.NewDecoder(r.Body).Decode(&rpt) + err := s.decodeJSON(w, r, &rpt) if err != nil { - s.log.Error("failed to decode report", - "error", err, - ) s.respondJSON(w, r, &response{Status: "error"}, - http.StatusBadRequest, + s.decodeErrorStatus(err), ) return } - totalSamples := 0 - for _, h := range rpt.Hosts { - totalSamples += len(h.History) - } + s.logReportReceived(rpt) - s.log.Info("report received", - "client_id", rpt.ClientID, - "timestamp", rpt.Timestamp, - "host_count", len(rpt.Hosts), - "total_samples", totalSamples, - "geo", string(rpt.Geo), - ) - - bufErr := s.buf.Append(rpt) - if bufErr != nil { - s.log.Error("failed to buffer report", - "error", bufErr, + err = s.buf.Append(rpt) + if err != nil { + s.log.Error("failed to buffer report", "error", err) + s.respondJSON(w, r, + &response{Status: "error"}, + http.StatusInternalServerError, ) + + return } - s.respondJSON(w, r, - &response{Status: "ok"}, - http.StatusOK, - ) + s.respondJSON(w, r, &response{Status: "ok"}, http.StatusOK) } } + +// decodeErrorStatus logs a report decode failure and returns the +// status to send: 413 when the body exceeded the size limit, +// otherwise 400 for malformed JSON. +func (s *Handlers) decodeErrorStatus(err error) int { + var tooLarge *http.MaxBytesError + if errors.As(err, &tooLarge) { + s.log.Warn("report body too large", "limit_bytes", tooLarge.Limit) + + return http.StatusRequestEntityTooLarge + } + + // 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()), + ) + + return http.StatusBadRequest +} + +// logReportReceived logs an accepted report. Untrusted fields are +// bounded (client_id, timestamp) or reduced to a length +// (geo_bytes) so the raw attacker-controlled body never reaches +// the log. +func (s *Handlers) logReportReceived(rpt report) { + totalSamples := 0 + for _, h := range rpt.Hosts { + totalSamples += len(h.History) + } + + s.log.Info("report received", + "client_id", boundedForLog(rpt.ClientID), + "timestamp", 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 new file mode 100644 index 0000000..e28dfb3 --- /dev/null +++ b/backend/internal/handlers/report_test.go @@ -0,0 +1,215 @@ +package handlers_test + +import ( + "bytes" + "encoding/json" + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "sneak.berlin/go/netwatch/internal/handlers" + "sneak.berlin/go/netwatch/internal/middleware" +) + +var errStorageFailed = errors.New("storage failed") + +// stubAppender drives the storage success/failure path without a +// real buffer or disk. +type stubAppender struct { + err error +} + +func (s stubAppender) Append(any) error { return s.err } + +func newTestHandlers(buf stubAppender, out io.Writer) *handlers.Handlers { + return handlers.NewForTest(buf, slog.New(slog.NewJSONHandler(out, nil))) +} + +func decodeStatus(t *testing.T, body []byte) string { + t.Helper() + + var resp struct { + Status string `json:"status"` + } + + err := json.Unmarshal(body, &resp) + if err != nil { + t.Fatalf("response body not JSON: %v (%q)", err, body) + } + + return resp.Status +} + +func TestHandleReportStorageFailureIsNon2xx(t *testing.T) { + t.Parallel() + + h := newTestHandlers(stubAppender{err: errStorageFailed}, io.Discard) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader(`{"clientId":"c1","hosts":[]}`), + ) + + h.HandleReport().ServeHTTP(rec, req) + + if rec.Code < 500 { + t.Fatalf("storage failure status = %d, want a 5xx", rec.Code) + } + + if got := decodeStatus(t, rec.Body.Bytes()); got != "error" { + t.Fatalf("status field = %q, want %q", got, "error") + } +} + +func TestHandleReportMalformedJSONIs400(t *testing.T) { + t.Parallel() + + h := newTestHandlers(stubAppender{}, io.Discard) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader(`{not json`), + ) + + h.HandleReport().ServeHTTP(rec, req) + + if rec.Code != http.StatusBadRequest { + t.Fatalf("malformed status = %d, want %d", + rec.Code, http.StatusBadRequest) + } +} + +func TestHandleReportOversizeIs413(t *testing.T) { + t.Parallel() + + const limit = 32 + + h := newTestHandlers(stubAppender{}, io.Discard) + handler := (&middleware.Middleware{}).MaxBodyBytes(limit)( + h.HandleReport(), + ) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader(`{"clientId":"`+strings.Repeat("x", 200)+`"}`), + ) + // No declared length, so only the middleware's read cap can + // stop this body. + req.ContentLength = -1 + + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusRequestEntityTooLarge { + t.Fatalf("oversize status = %d, want %d", + rec.Code, http.StatusRequestEntityTooLarge) + } +} + +func TestHandleReportDoesNotLogRawGeo(t *testing.T) { + t.Parallel() + + const sentinel = "SENSITIVE-GEO-BLOB" + + var logbuf bytes.Buffer + + h := newTestHandlers(stubAppender{}, &logbuf) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader( + `{"clientId":"c1","geo":{"raw":"`+sentinel+`"},"hosts":[]}`, + ), + ) + + h.HandleReport().ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK) + } + + if strings.Contains(logbuf.String(), sentinel) { + t.Fatal("raw geo bytes were written to the log") + } + + if !strings.Contains(logbuf.String(), "geo_bytes") { + t.Fatal("expected a bounded geo_bytes field in the log") + } +} + +func TestHandleReportLogsClientIDCutToBound(t *testing.T) { + t.Parallel() + + long := strings.Repeat("c", 2*handlers.MaxLoggedFieldBytes) + + var logbuf bytes.Buffer + + h := newTestHandlers(stubAppender{}, &logbuf) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader( + `{"clientId":"`+long+`","timestamp":"`+long+`","hosts":[]}`, + ), + ) + + h.HandleReport().ServeHTTP(rec, req) + + var logged struct { + ClientID string `json:"client_id"` + Timestamp string `json:"timestamp"` + } + + err := json.Unmarshal(logbuf.Bytes(), &logged) + if err != nil { + t.Fatalf("log line not JSON: %v (%q)", err, logbuf.String()) + } + + want := long[:handlers.MaxLoggedFieldBytes] + + if logged.ClientID != want { + t.Fatalf("logged client_id is %d bytes, want %d", + len(logged.ClientID), len(want)) + } + + if logged.Timestamp != want { + t.Fatalf("logged timestamp is %d bytes, want %d", + len(logged.Timestamp), len(want)) + } +} + +func TestHandleReportDecodeErrorLogIsBounded(t *testing.T) { + t.Parallel() + + // 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) + + var logbuf bytes.Buffer + + h := newTestHandlers(stubAppender{}, &logbuf) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader(`{"hosts":[{"history":[{"t":`+huge+`}]}]}`), + ) + + h.HandleReport().ServeHTTP(rec, req) + + if rec.Code != http.StatusBadRequest { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusBadRequest) + } + + if strings.Contains(logbuf.String(), huge) { + t.Fatal("the whole oversized number was written to the log") + } +} diff --git a/backend/internal/middleware/export_test.go b/backend/internal/middleware/export_test.go index d1961c0..03722f4 100644 --- a/backend/internal/middleware/export_test.go +++ b/backend/internal/middleware/export_test.go @@ -1,6 +1,7 @@ package middleware import ( + "log/slog" "net/http" "net/netip" ) @@ -8,6 +9,12 @@ import ( // Test-only wrappers exposing unexported helpers to the // external middleware_test package. +// NewWithLogger builds a Middleware around a logger for tests +// that exercise the logging paths without the fx graph. +func NewWithLogger(log *slog.Logger) *Middleware { + return &Middleware{log: log} +} + func ClientIP( remoteAddr string, header http.Header, diff --git a/backend/internal/middleware/middleware.go b/backend/internal/middleware/middleware.go index 5f5194b..b74092f 100644 --- a/backend/internal/middleware/middleware.go +++ b/backend/internal/middleware/middleware.go @@ -3,11 +3,14 @@ package middleware import ( + "errors" "fmt" + "io" "log/slog" "net" "net/http" "net/netip" + "runtime/debug" "strings" "time" @@ -22,6 +25,14 @@ import ( const corsMaxAgeSec = 300 +// jsonErrorBody is the body written for errors raised inside +// middleware, matching the {"status":"error"} shape the handlers +// return so clients see one error contract across the API. +const ( + jsonContentType = "application/json; charset=utf-8" + jsonErrorBody = "{\"status\":\"error\"}\n" +) + // Security header values. The backend is a JSON API with no // HTML surface, so the CSP forbids every resource type and // framing outright. @@ -236,6 +247,79 @@ func (s *Middleware) SecurityHeaders() func(http.Handler) http.Handler { } } +// writeJSONError writes the shared JSON error body with the +// given status. Used where middleware must reject a request +// before it reaches a handler. +func writeJSONError(w http.ResponseWriter, status int) { + w.Header().Set("Content-Type", jsonContentType) + w.WriteHeader(status) + _, _ = io.WriteString(w, jsonErrorBody) +} + +// MaxBodyBytes returns middleware that caps the request body at +// limit bytes. A declared Content-Length over the limit is +// rejected immediately with 413. Bodies without a declared +// length (or that understate it) are capped as they are read, so +// a handler that reads the body sees a *http.MaxBytesError it can +// map to 413. Mounted again on a route group, it can only lower +// the limit: a cap applied earlier in the chain still holds. +func (s *Middleware) MaxBodyBytes( + limit int64, +) func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + if r.ContentLength > limit { + writeJSONError( + w, + http.StatusRequestEntityTooLarge, + ) + + return + } + + r.Body = http.MaxBytesReader(w, r.Body, limit) + + next.ServeHTTP(w, r) + }, + ) + } +} + +// Recoverer returns middleware that recovers from a panic in a +// downstream handler, logs the panic and stack trace through +// slog, and responds 500 with no body. http.ErrAbortHandler is +// re-panicked so the server can abort the response as intended. +func (s *Middleware) Recoverer() func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + defer func() { + rec := recover() + if rec == nil { + return + } + + err, ok := rec.(error) + if ok && errors.Is(err, http.ErrAbortHandler) { + panic(rec) + } + + s.log.ErrorContext(r.Context(), + "panic recovered", + "panic", fmt.Sprintf("%v", rec), + "stack", string(debug.Stack()), + ) + + w.WriteHeader(http.StatusInternalServerError) + }() + + next.ServeHTTP(w, r) + }, + ) + } +} + // CORS returns middleware that adds permissive CORS headers. func (s *Middleware) CORS() func(http.Handler) http.Handler { return cors.Handler(cors.Options{ diff --git a/backend/internal/middleware/middleware_test.go b/backend/internal/middleware/middleware_test.go index a664ee6..c4580b3 100644 --- a/backend/internal/middleware/middleware_test.go +++ b/backend/internal/middleware/middleware_test.go @@ -1,9 +1,12 @@ package middleware_test import ( + "bytes" + "log/slog" "net/http" "net/http/httptest" "net/netip" + "strings" "testing" "sneak.berlin/go/netwatch/internal/middleware" @@ -146,3 +149,92 @@ func TestSecurityHeaders(t *testing.T) { } } } + +// TestMaxBodyBytesRejectsOversizeOnNonReadingRoute confirms the +// limit is enforced even for a handler that never reads the body +// (for example the health check), via the Content-Length check. +func TestMaxBodyBytesRejectsOversizeOnNonReadingRoute(t *testing.T) { + t.Parallel() + + const limit = 16 + + called := false + handler := (&middleware.Middleware{}).MaxBodyBytes(limit)( + http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) { + called = true + }), + ) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/.well-known/healthcheck", + strings.NewReader(strings.Repeat("x", limit+1)), + ) + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusRequestEntityTooLarge { + t.Fatalf("status = %d, want %d", + rec.Code, http.StatusRequestEntityTooLarge) + } + + if called { + t.Fatal("handler ran despite oversize body") + } +} + +func TestMaxBodyBytesAllowsWithinLimit(t *testing.T) { + t.Parallel() + + const limit = 64 + + handler := (&middleware.Middleware{}).MaxBodyBytes(limit)( + http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }), + ) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodPost, "/api/v1/reports", + strings.NewReader(`{"clientId":"c1"}`), + ) + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK) + } +} + +func TestRecovererReturns500AndLogsThroughSlog(t *testing.T) { + t.Parallel() + + var logbuf bytes.Buffer + + mw := middleware.NewWithLogger( + slog.New(slog.NewJSONHandler(&logbuf, nil)), + ) + + handler := mw.Recoverer()( + http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) { + panic("boom") + }), + ) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody) + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want %d", + rec.Code, http.StatusInternalServerError) + } + + out := logbuf.String() + if !strings.Contains(out, "panic recovered") { + t.Fatalf("panic was not logged through slog: %q", out) + } + + if !strings.Contains(out, `"level":"ERROR"`) { + t.Fatalf("panic log was not structured JSON at error level: %q", out) + } +} diff --git a/backend/internal/server/export_test.go b/backend/internal/server/export_test.go new file mode 100644 index 0000000..7279b22 --- /dev/null +++ b/backend/internal/server/export_test.go @@ -0,0 +1,5 @@ +package server + +// MaxRequestBodyBytes exposes the router-wide body limit to the +// external tests. +const MaxRequestBodyBytes = maxRequestBodyBytes diff --git a/backend/internal/server/routes.go b/backend/internal/server/routes.go index 5f2dd8b..9d4547d 100644 --- a/backend/internal/server/routes.go +++ b/backend/internal/server/routes.go @@ -7,18 +7,26 @@ import ( "github.com/go-chi/chi/v5/middleware" ) -const requestTimeout = 60 * time.Second +const ( + requestTimeout = 60 * time.Second + + // maxRequestBodyBytes caps every request body. A route group + // can mount s.mw.MaxBodyBytes with a smaller value to lower + // its bound, but cannot raise it: this cap runs first. + maxRequestBodyBytes int64 = 1 << 20 // 1 MiB +) // SetupRoutes configures the chi router with middleware and // all application routes. func (s *Server) SetupRoutes() { s.router = chi.NewRouter() - s.router.Use(middleware.Recoverer) + s.router.Use(s.mw.Recoverer()) s.router.Use(middleware.RequestID) s.router.Use(s.mw.Logging()) s.router.Use(s.mw.SecurityHeaders()) s.router.Use(s.mw.CORS()) + s.router.Use(s.mw.MaxBodyBytes(maxRequestBodyBytes)) s.router.Use(middleware.Timeout(requestTimeout)) s.router.Get( diff --git a/backend/internal/server/routes_test.go b/backend/internal/server/routes_test.go new file mode 100644 index 0000000..aaa9813 --- /dev/null +++ b/backend/internal/server/routes_test.go @@ -0,0 +1,67 @@ +package server_test + +import ( + "net/http" + "net/http/httptest" + "strings" + "testing" + + "sneak.berlin/go/netwatch/internal/config" + "sneak.berlin/go/netwatch/internal/globals" + "sneak.berlin/go/netwatch/internal/handlers" + "sneak.berlin/go/netwatch/internal/healthcheck" + "sneak.berlin/go/netwatch/internal/logger" + "sneak.berlin/go/netwatch/internal/middleware" + "sneak.berlin/go/netwatch/internal/reportbuf" + "sneak.berlin/go/netwatch/internal/server" + + "go.uber.org/fx" + "go.uber.org/fx/fxtest" +) + +// TestHealthCheckRejectsOversizeBody sends the health check, which +// never reads its body, a body one byte over the limit. Only the +// router-wide body limit can reject it. +func TestHealthCheckRejectsOversizeBody(t *testing.T) { + t.Parallel() + + var srv *server.Server + + // The same constructors as main, never started: SetupRoutes is + // called directly, so nothing listens. + app := fxtest.New(t, + fx.Provide( + config.New, + globals.New, + handlers.New, + healthcheck.New, + logger.New, + middleware.New, + reportbuf.New, + server.New, + ), + fx.Populate(&srv), + ) + + err := app.Err() + if err != nil { + t.Fatalf("build server: %v", err) + } + + srv.SetupRoutes() + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), + http.MethodGet, "/.well-known/healthcheck", + strings.NewReader( + strings.Repeat("x", int(server.MaxRequestBodyBytes)+1), + ), + ) + + srv.ServeHTTP(rec, req) + + if rec.Code != http.StatusRequestEntityTooLarge { + t.Fatalf("status = %d, want %d", + rec.Code, http.StatusRequestEntityTooLarge) + } +}