diff --git a/backend/app/core/middleware.py b/backend/app/core/middleware.py index bc8664259..6a1c9be77 100644 --- a/backend/app/core/middleware.py +++ b/backend/app/core/middleware.py @@ -58,16 +58,29 @@ async def http_request_logger(request: Request, call_next) -> Response: return await _log_http_request(request, call_next) +def _resolve_request_body_size(request: Request) -> int: + """ + Read the request payload size from Content-Length. + Returns 0 when the header is absent or malformed (e.g. chunked transfer). + """ + try: + return int(request.headers.get("content-length") or 0) + except ValueError: + return 0 + + async def _log_http_request(request: Request, call_next) -> Response: start_time = time.time() method = request.method raw_path = request.url.path + request_body_size = _resolve_request_body_size(request) span = trace.get_current_span() if span.is_recording(): span.set_attribute("http.request.method", method) span.set_attribute("http.request_method", method) span.set_attribute("http.method", method) + span.set_attribute("http.request.body.size", request_body_size) if sentry_sdk.get_client().is_active(): sentry_sdk.set_tag("http.method", method) @@ -102,7 +115,11 @@ async def _log_http_request(request: Request, call_next) -> Response: span.set_attribute("http.request.duration_ms", round(duration_ms, 2)) if raw_path not in SILENT_LOG_PATHS: - logger.info(f"{method} {raw_path} - {status} [{duration_ms:.2f}ms]") + logger.info( + f"[_log_http_request] {method} {raw_path} - {status} [{duration_ms:.2f}ms] " + f"| request_body_size: {request_body_size}B " + f"| correlation_id: {correlation_id.get()}" + ) try: if sentry_sdk.get_client().is_active(): @@ -116,6 +133,12 @@ async def _log_http_request(request: Request, call_next) -> Response: "http.status_code": str(status), } sentry_sdk.metrics.count("http.server.request.count", 1, attributes=attrs) + sentry_sdk.metrics.distribution( + "http.server.request.body.size", + request_body_size, + unit="byte", + attributes=attrs, + ) sentry_sdk.metrics.distribution( "http.server.request.duration", duration_ms, diff --git a/backend/app/tests/core/test_middleware.py b/backend/app/tests/core/test_middleware.py new file mode 100644 index 000000000..e32d9d3b1 --- /dev/null +++ b/backend/app/tests/core/test_middleware.py @@ -0,0 +1,174 @@ +import logging +import re + +import pytest +from fastapi import Response +from fastapi.testclient import TestClient +from starlette.requests import Request + +from app.core.middleware import _resolve_request_body_size + + +def _build_request(headers: dict[str, str] | None = None) -> Request: + raw_headers = [ + (key.lower().encode(), value.encode()) for key, value in (headers or {}).items() + ] + return Request( + { + "type": "http", + "http_version": "1.1", + "method": "POST", + "scheme": "http", + "server": ("testserver", 80), + "path": "/api/v1/probe", + "raw_path": b"/api/v1/probe", + "query_string": b"", + "root_path": "", + "headers": raw_headers, + } + ) + + +class TestResolveRequestBodySize: + def test_reads_content_length_header(self) -> None: + request = _build_request({"content-length": "512"}) + assert _resolve_request_body_size(request) == 512 + + def test_missing_header_is_zero(self) -> None: + assert _resolve_request_body_size(_build_request()) == 0 + + def test_empty_header_is_zero(self) -> None: + request = _build_request({"content-length": ""}) + assert _resolve_request_body_size(request) == 0 + + @pytest.mark.parametrize("value", ["chunked", "12.5", "-"]) + def test_malformed_header_is_zero(self, value: str) -> None: + request = _build_request({"content-length": value}) + assert _resolve_request_body_size(request) == 0 + + +class TestAccessLogLine: + def test_logs_body_size_and_correlation_id( + self, client: TestClient, caplog: pytest.LogCaptureFixture + ) -> None: + payload = b"0123456789abcdef" + + with caplog.at_level(logging.INFO, logger="http_request_logger"): + response = client.post("/api/v1/no-such-route", content=payload) + + assert response.status_code == 404 + line = next( + record.getMessage() + for record in caplog.records + if record.name == "http_request_logger" + ) + assert "POST /api/v1/no-such-route - 404" in line + assert "| request_body_size: 16B |" in line + assert re.search(r"correlation_id: [0-9a-f]{32}$", line) + + def test_logs_zero_for_bodyless_request( + self, client: TestClient, caplog: pytest.LogCaptureFixture + ) -> None: + with caplog.at_level(logging.INFO, logger="http_request_logger"): + client.get("/api/v1/no-such-route") + + line = next( + record.getMessage() + for record in caplog.records + if record.name == "http_request_logger" + ) + assert "| request_body_size: 0B |" in line + + +class TestBodySizeSpanAttribute: + @pytest.mark.asyncio + async def test_recording_span_records_body_size(self) -> None: + from opentelemetry import trace + from opentelemetry.sdk.trace import TracerProvider + from opentelemetry.sdk.trace.export import SimpleSpanProcessor + from opentelemetry.sdk.trace.export.in_memory_span_exporter import ( + InMemorySpanExporter, + ) + + from app.core.middleware import _log_http_request + + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = provider.get_tracer(__name__) + + async def call_next(_: Request) -> Response: + return Response(status_code=200) + + request = _build_request({"content-length": "2048"}) + with trace.use_span(tracer.start_span("test-request"), end_on_exit=True): + await _log_http_request(request, call_next) + + (span,) = exporter.get_finished_spans() + assert span.attributes is not None + assert span.attributes["http.request.body.size"] == 2048 + + +class TestSentryBodySizeMetric: + @pytest.mark.asyncio + async def test_emits_body_size_distribution( + self, monkeypatch: pytest.MonkeyPatch + ) -> None: + import sentry_sdk + + from app.core.middleware import _log_http_request + + distributions: list[tuple[str, float, str | None]] = [] + + class ActiveClient: + def is_active(self) -> bool: + return True + + monkeypatch.setattr(sentry_sdk, "get_client", lambda: ActiveClient()) + monkeypatch.setattr( + sentry_sdk.metrics, + "distribution", + lambda name, value, unit=None, attributes=None: distributions.append( + (name, value, unit) + ), + ) + monkeypatch.setattr( + sentry_sdk.metrics, "count", lambda name, value, attributes=None: None + ) + + async def call_next(_: Request) -> Response: + return Response(status_code=200) + + request = _build_request({"content-length": "4096"}) + await _log_http_request(request, call_next) + + body_size_metrics = [m for m in distributions if m[0].endswith("body.size")] + assert body_size_metrics == [("http.server.request.body.size", 4096, "byte")] + + @pytest.mark.asyncio + async def test_no_metrics_when_sentry_inactive( + self, monkeypatch: pytest.MonkeyPatch + ) -> None: + import sentry_sdk + + from app.core.middleware import _log_http_request + + emitted: list[str] = [] + + class InactiveClient: + def is_active(self) -> bool: + return False + + monkeypatch.setattr(sentry_sdk, "get_client", lambda: InactiveClient()) + monkeypatch.setattr( + sentry_sdk.metrics, + "distribution", + lambda name, *a, **kw: emitted.append(name), + ) + + async def call_next(_: Request) -> Response: + return Response(status_code=200) + + await _log_http_request(_build_request({"content-length": "77"}), call_next) + + assert emitted == []