Log rejected bundle entries as invalid requests

Author: thomas-samoht

app/errors/handlers.py

@@ -7,6 +7,7 @@
 from fastapi.responses import JSONResponse
 from gfmodules.logging.exceptions import log_unhandled_exception
 from gfmodules.logging.middleware import restore_request_context
+from pydantic import ValidationError
 
 from app.errors.fhir import FHIRError
 from app.errors.mapping import DEFAULT_SPEC, EXCEPTION_MAP, UNEXPECTED_ERROR_MESSAGE, spec_for
@@ -23,8 +24,8 @@
 _DENIAL_STATUSES = frozenset({401, 403})
 
 
-def _summarize_reason(exc: Exception) -> str:
-    if isinstance(exc, RequestValidationError):
+def summarize_reason(exc: Exception) -> str:
+    if isinstance(exc, (RequestValidationError, ValidationError)):
         reasons = [
             f"{'.'.join(str(loc) for loc in err.get('loc', ()))}: {err.get('msg', '')}".strip(" :")
             for err in exc.errors()
@@ -40,7 +41,7 @@ def log_rejection(status_code: int, exc: Exception) -> None:
         "Request rejected with %s (%s): %s",
         status_code,
         type(exc).__name__,
-        _summarize_reason(exc),
+        summarize_reason(exc),
     )
 
 
@@ -55,7 +56,7 @@ def log_invalid_request(status_code: int, reason: str) -> None:
 
 def _log_invalid_request(request: Request, status_code: int, exc: Exception) -> None:
     with bind_auth_claims(getattr(request.state, "auth", None)):
-        log_invalid_request(status_code, _summarize_reason(exc))
+        log_invalid_request(status_code, summarize_reason(exc))
 
 
 def handle_mapped_exception(request: Request, exc: Exception) -> JSONResponse:

app/services/fhir/bundle.py

@@ -5,7 +5,7 @@
 
 import gfmodules.logging as gflog
 
-from app.errors.handlers import log_rejection
+from app.errors.handlers import log_invalid_request, log_rejection, summarize_reason
 from app.errors.mapping import DEFAULT_SPEC, UNEXPECTED_ERROR_MESSAGE, spec_for
 from app.logging.events import Log
 from app.models.auth.context import AuthContext
@@ -28,6 +28,11 @@
 logger = logging.getLogger(__name__)
 
 
+def _invalid_entry(msg: str, status: int = 422, code: str = "required", reason: str | None = None) -> BundleEntry[Any]:
+    log_invalid_request(status, reason or msg)
+    return BundleEntry(response=EntryResponse.make_error_response(msg, str(status), code))
+
+
 class BundleService:
     def __init__(
         self,
@@ -37,14 +42,10 @@ def __init__(
 
     def process_entry(self, ctx: AuthContext, entry: BundleEntry[Any], index: int) -> BundleEntry[Any]:
         if entry.request is None:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(f"Bundle.entry.{index}.request is required")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request is required")
 
         if entry.request.method is None:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(f"Bundle.entry.{index}.request.method is required")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request.method is required")
 
         method = entry.request.method
         resolved_url = self.resolve_request_url(entry.request.url, index)
@@ -151,6 +152,9 @@ def _entry_result(self, index: int, action: Callable[[], BundleEntry[Any]]) -> B
             else:
                 log_rejection(spec.http_status, exc)
 
+            if spec.invalid_input:
+                return _invalid_entry(f"Bundle.entry.{index}: {exc}", spec.http_status, spec.fhir_code)
+
             return BundleEntry(
                 response=EntryResponse.make_error_response(
                     msg=f"Bundle.entry.{index}: {UNEXPECTED_ERROR_MESSAGE if unexpected else exc}",
@@ -184,11 +188,8 @@ def _parse_params(
         try:
             return model.model_validate(resolved_url.params)
         except ValueError as e:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(
-                    f"Bundle.entry.{index}.request: invalid url parameter: {e}"
-                )
-            )
+            prefix = f"Bundle.entry.{index}.request: invalid url parameter"
+            return _invalid_entry(f"{prefix}: {e}", reason=f"{prefix}: {summarize_reason(e)}")
 
     def _deny_mismatched_source(
         self,
@@ -208,13 +209,7 @@ def _deny_mismatched_source(
             # A source built on the wrong naming system, which the standalone route rejects
             # before it reaches the service too.
             spec = spec_for(e)
-            return BundleEntry(
-                response=EntryResponse.make_error_response(
-                    msg=f"Bundle.entry.{index}: {e}",
-                    status=str(spec.http_status),
-                    code=spec.fhir_code,
-                )
-            )
+            return _invalid_entry(f"Bundle.entry.{index}: {e}", spec.http_status, spec.fhir_code)
 
         try:
             AuthContextService.assert_source_matches(ctx, entry_source)
@@ -231,14 +226,10 @@ def _deny_mismatched_source(
     def _validate_post_resource(self, entry: BundleEntry[Any], index: int) -> LocalizationList | BundleEntry[Any]:
         """Return the validated ``LocalizationList`` or an error ``BundleEntry``."""
         if entry.resource is None:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(msg=f"Bundle.entry.{index}: resource cannot be empty")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}: resource cannot be empty")
 
         if not isinstance(entry.resource, LocalizationList):
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(f"Bundle.entry.{index}: invalid List resource")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}: invalid List resource")
 
         return entry.resource
 
@@ -276,27 +267,15 @@ def resolve_request_url(self, url: str, index: int) -> EntryRequestDto | BundleE
         try:
             request_dto = EntryRequestDto.from_url(url)
         except ValueError:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(f"Bundle.entry.{index}.request.url is malformed")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request.url is malformed")
 
         if request_dto.resource is None:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(f"Bundle.entry.{index}.request.url: resource not found")
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request.url: resource not found")
 
         if request_dto.resource != "List":
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(
-                    f"Bundle.entry.{index}.request.url unsupported {request_dto.resource} resource"
-                )
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request.url unsupported {request_dto.resource} resource")
 
         if request_dto.id is not None and request_dto.params is not None:
-            return BundleEntry(
-                response=EntryResponse.make_validation_response(
-                    f"Bundle.entry.{index}.request.url:  unsupported url for requested transaction"
-                )
-            )
+            return _invalid_entry(f"Bundle.entry.{index}.request.url:  unsupported url for requested transaction")
 
         return request_dto

tests/routers/test_fhir_base.py

@@ -1,9 +1,13 @@
 from typing import Any
+from unittest.mock import Mock
 
 import pytest
 from fastapi.testclient import TestClient
+from gfmodules.logging.testing import assert_event_emitted, capture_records
 
 from app.debug.crypto_service_api_client_mock import CryptoServiceApiClientMock
+from app.logging.events import Log
+from app.services.exceptions import PseudonymExchangeError
 from app.services.key_info import KeyInfoService
 from app.services.referral_service import ReferralService
 from tests.conftest import make_list_resource
@@ -95,3 +99,61 @@ def test_processes_a_get_query_entry(self, client: TestClient) -> None:
         entry = response.json()["entry"][0]
         assert entry["response"]["status"] == "200"
         assert entry["resource"]["resourceType"] == "Bundle"
+
+
+_NO_RESOURCE = {"request": {"method": "POST", "url": "List"}}
+
+
+def _wrong_ura_entry() -> dict[str, Any]:
+    entry = _post_entry()
+    entry["resource"]["extension"][0]["valueReference"]["identifier"]["system"] = "urn:wrong"
+    return entry
+
+
+class TestInvalidEntryLogging:
+    @pytest.mark.parametrize(
+        ("entry", "status"),
+        [
+            (_NO_RESOURCE, 422),
+            (_wrong_ura_entry(), 400),
+            ({"request": {"method": "GET", "url": "Patient"}}, 422),
+        ],
+        ids=["missing-resource", "wrong-ura-system", "unsupported-resource"],
+    )
+    def test_logs_a_rejected_entry(self, client: TestClient, entry: dict[str, Any], status: int) -> None:
+        with capture_records() as records:
+            response = client.post("/fhir", json=_bundle(entry), headers=FHIR_JSON)
+
+        assert response.json()["entry"][0]["response"]["status"] == str(status)
+        assert_event_emitted(records, Log.INVALID_REQUEST, organization_identifier=TEST_URA, http_status=status)
+
+    def test_logs_only_the_invalid_entries_of_a_mixed_bundle(self, client: TestClient) -> None:
+        with capture_records() as records:
+            response = client.post(
+                "/fhir", json=_bundle(_post_entry(), _NO_RESOURCE, _wrong_ura_entry()), headers=FHIR_JSON
+            )
+
+        assert [e["response"]["status"] for e in response.json()["entry"]] == ["201", "422", "400"]
+        assert len(records.for_event(Log.INVALID_REQUEST)) == 2
+
+    def test_keeps_the_subject_token_out_of_a_rejected_entry_log(self, client: TestClient) -> None:
+        entry = {"request": {"method": "DELETE", "url": "List?subject:identifier=urn:wrong|leaky-token-value"}}
+        with capture_records() as records:
+            response = client.post("/fhir", json=_bundle(entry), headers=FHIR_JSON)
+
+        assert response.json()["entry"][0]["response"]["status"] == "422"
+        logged = assert_event_emitted(records, Log.INVALID_REQUEST, http_status=422)
+        assert "leaky-token-value" not in logged.message["error_reason"]
+
+    def test_logs_a_rejected_exchange_in_an_entry_only_as_a_failed_registration(
+        self, client: TestClient, crypto_client: CryptoServiceApiClientMock, monkeypatch: pytest.MonkeyPatch
+    ) -> None:
+        rejected = PseudonymExchangeError("Invalid pseudonym or oprf_key")
+        monkeypatch.setattr(crypto_client, "exchange", Mock(side_effect=rejected))
+
+        with capture_records() as records:
+            response = client.post("/fhir", json=_bundle(_post_entry()), headers=FHIR_JSON)
+
+        assert response.json()["entry"][0]["response"]["status"] == "400"
+        assert len(records.for_event(Log.REFERRAL_REGISTRATION_FAILED)) == 1
+        assert records.for_event(Log.INVALID_REQUEST) == []

tests/services/fhir/test_bundle_service.py

@@ -4,6 +4,7 @@
 
 import pytest
 
+from app.logging.events import Log
 from app.models.auth.context import AuthContext, AuthenticationClaims
 from app.models.auth.data import AuthorizationScope
 from app.models.fhir.bundle import BundleEntry, EntryRequest
@@ -510,7 +511,7 @@ def test_failed_own_query_is_not_a_localization_failure(
         with caplog.at_level(logging.INFO):
             process(bundle_service, make_entry("GET", own_query_url), [AuthorizationScope.READ])
 
-        assert _event_ids(caplog) == []
+        assert _event_ids(caplog) == [Log.INVALID_REQUEST.event_id]
 
     def test_failed_delete_by_query_is_not_a_localization_failure(
         self,
@@ -523,7 +524,7 @@ def test_failed_delete_by_query_is_not_a_localization_failure(
         with caplog.at_level(logging.INFO):
             process(bundle_service, make_entry("DELETE", QUERY_URL), [AuthorizationScope.DELETE])
 
-        assert _event_ids(caplog) == []
+        assert _event_ids(caplog) == [Log.INVALID_REQUEST.event_id]
 
 
 class TestSourceMatch: