Log rejected invalid requests as INVALID_REQUEST

Author: thomas-samoht

app/errors/handlers.py

@@ -1,6 +1,7 @@
 import logging
 from typing import no_type_check
 
+import gfmodules.logging as gflog
 from fastapi import FastAPI, Request
 from fastapi.exceptions import RequestValidationError
 from fastapi.responses import JSONResponse
@@ -9,6 +10,8 @@
 
 from app.errors.fhir import FHIRError
 from app.errors.mapping import DEFAULT_SPEC, EXCEPTION_MAP, UNEXPECTED_ERROR_MESSAGE, spec_for
+from app.logging.context import bind_auth_claims
+from app.logging.events import Log
 from app.models.fhir.resources.operation_outcome.resource import (
     OperationOutcome,
     OperationOutcomeDetail,
@@ -41,10 +44,26 @@ def log_rejection(status_code: int, exc: Exception) -> None:
     )
 
 
+def log_invalid_request(status_code: int, reason: str) -> None:
+    gflog.emit(
+        logger,
+        Log.INVALID_REQUEST,
+        "Invalid request rejected",
+        fields={"http_status": status_code, "error_reason": reason},
+    )
+
+
+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))
+
+
 def handle_mapped_exception(request: Request, exc: Exception) -> JSONResponse:
     spec = spec_for(exc)
     status_code = spec.http_status
     log_rejection(status_code, exc)
+    if spec.invalid_input:
+        _log_invalid_request(request, status_code, exc)
 
     if "fhir" in request.url.path:
         fhir_error = FHIRError(severity=spec.severity, code=spec.fhir_code, msg=str(exc))
@@ -61,6 +80,7 @@ def handle_request_validation_exception(req: Request, exc: RequestValidationErro
     path = req.url.path
     status_code = 422
     log_rejection(status_code, exc)
+    _log_invalid_request(req, status_code, exc)
     if "fhir" in path:
         issues = []
 

app/errors/mapping.py

@@ -20,6 +20,7 @@ class ErrorSpec(BaseModel):
     fhir_code: str
     http_status: int
     log: bool = False
+    invalid_input: bool = False
 
 
 # `spec_for` resolves an exception through its MRO, so a subclass picks up its base
@@ -30,11 +31,11 @@ class ErrorSpec(BaseModel):
     ForbiddenError: ErrorSpec(severity="error", fhir_code="forbidden", http_status=403),
     UnauthorizedError: ErrorSpec(severity="error", fhir_code="security", http_status=403),
     InvalidKeyInfoError: ErrorSpec(severity="error", fhir_code="transient", http_status=503),
-    InvalidModelError: ErrorSpec(severity="error", fhir_code="structure", http_status=400),
+    InvalidModelError: ErrorSpec(severity="error", fhir_code="structure", http_status=400, invalid_input=True),
     InvalidHeaderPropertyError: ErrorSpec(severity="error", fhir_code="invalid", http_status=401),
-    PseudonymError: ErrorSpec(severity="error", fhir_code="invalid", http_status=422),
+    PseudonymError: ErrorSpec(severity="error", fhir_code="invalid", http_status=422, invalid_input=True),
     PseudonymExchangeError: ErrorSpec(severity="error", fhir_code="invalid", http_status=400, log=True),
-    ValueError: ErrorSpec(severity="error", fhir_code="invalid", http_status=400, log=True),
+    ValueError: ErrorSpec(severity="error", fhir_code="invalid", http_status=400, invalid_input=True),
 }
 
 # Applied to any exception without a mapped type (rendered as HTTP 500). Unmapped

app/logging/events.py

@@ -42,6 +42,15 @@ class Log(_Base):
             _APP: ("exception_type", "table", "column", "value_length", "column_limit"),
         },
     )
+    INVALID_REQUEST = LogEvent(  # NVI-SYS-007
+        "100607",
+        logging.WARNING,
+        (_APP, _SIEM),
+        {
+            _APP: (*_CALLER, "http_status", "error_reason"),
+            _SIEM: (*_CALLER, "http_status", "error_reason"),
+        },
+    )
 
     REGISTERED_REFERRAL = LogEvent(  # NVI-REF-001
         "900400",

tests/errors/test_handlers.py

@@ -18,6 +18,8 @@
     InvalidKeyInfoError,
     InvalidModelError,
     NotFoundError,
+    PseudonymError,
+    PseudonymExchangeError,
     UnauthorizedScopeError,
     UnauthorizedSourceError,
 )
@@ -181,3 +183,34 @@ def test_logs_the_unhandled_exception_event(self) -> None:
             method="GET",
         )
         assert entry.record.exc_info is not None
+
+
+class TestInvalidRequestLogging:
+    def test_logs_a_request_validation_error(self) -> None:
+        with capture_records() as records:
+            _client().get("/rest/validated")
+
+        assert_event_emitted(
+            records, Log.INVALID_REQUEST, http_status=422, error_reason="query.required: Field required"
+        )
+
+    @pytest.mark.parametrize(
+        ("exc", "status"),
+        [(ValueError("bad"), 400), (PseudonymError("bad"), 422), (InvalidModelError("bad"), 400)],
+    )
+    def test_logs_invalid_input(self, exc: Exception, status: int) -> None:
+        _pending["exc"] = exc
+        with capture_records() as records:
+            _client().get("/rest/boom")
+
+        assert_event_emitted(records, Log.INVALID_REQUEST, http_status=status)
+
+    @pytest.mark.parametrize(
+        "exc", [NotFoundError(), PseudonymExchangeError("rejected"), UnauthorizedSourceError(), RuntimeError("boom")]
+    )
+    def test_does_not_log_other_failures_as_invalid_requests(self, exc: Exception) -> None:
+        _pending["exc"] = exc
+        with capture_records() as records:
+            _client().get("/rest/boom")
+
+        assert records.for_event(Log.INVALID_REQUEST) == []

tests/errors/test_mapping.py

@@ -1,6 +1,6 @@
 import pytest
 
-from app.errors.mapping import ErrorSpec, should_log, spec_for
+from app.errors.mapping import DEFAULT_SPEC, EXCEPTION_MAP, ErrorSpec, should_log, spec_for
 from app.models.auth.data import AuthorizationScope
 from app.services.exceptions import (
     ConflictError,
@@ -17,8 +17,10 @@
 )
 
 
-def _spec(fhir_code: str, http_status: int, *, log: bool = False) -> ErrorSpec:
-    return ErrorSpec(severity="error", fhir_code=fhir_code, http_status=http_status, log=log)
+def _spec(fhir_code: str, http_status: int, *, log: bool = False, invalid_input: bool = False) -> ErrorSpec:
+    return ErrorSpec(
+        severity="error", fhir_code=fhir_code, http_status=http_status, log=log, invalid_input=invalid_input
+    )
 
 
 def _scope_error() -> UnauthorizedScopeError:
@@ -33,10 +35,14 @@ def _scope_error() -> UnauthorizedScopeError:
         pytest.param(ForbiddenError(), _spec("forbidden", 403), id="forbidden"),
         pytest.param(InvalidKeyInfoError(), _spec("transient", 503), id="invalid-key-info"),
         pytest.param(InvalidHeaderPropertyError("aud", "x"), _spec("invalid", 401), id="invalid-header-property"),
-        pytest.param(PseudonymError(), _spec("invalid", 422), id="pseudonym"),
-        pytest.param(ValueError("boom"), _spec("invalid", 400, log=True), id="value-error"),
+        pytest.param(PseudonymError(), _spec("invalid", 422, invalid_input=True), id="pseudonym"),
+        pytest.param(ValueError("boom"), _spec("invalid", 400, invalid_input=True), id="value-error"),
         pytest.param(PseudonymExchangeError("rejected"), _spec("invalid", 400, log=True), id="pseudonym-exchange"),
-        pytest.param(InvalidModelError("bad"), _spec("structure", 400), id="invalid-model-outranks-value-error"),
+        pytest.param(
+            InvalidModelError("bad"),
+            _spec("structure", 400, invalid_input=True),
+            id="invalid-model-outranks-value-error",
+        ),
         pytest.param(_scope_error(), _spec("security", 403), id="unauthorized-scope-via-mro"),
         pytest.param(UnauthorizedManagingRequestError(), _spec("security", 403), id="unauthorized-managing-via-mro"),
         pytest.param(UnauthorizedUraError(), _spec("security", 403), id="unauthorized-ura-via-mro"),
@@ -51,7 +57,7 @@ def test_spec_for_resolves_the_expected_spec(exc: Exception, expected: ErrorSpec
     ("exc", "expected"),
     [
         pytest.param(PseudonymError(), False, id="pseudonym"),
-        pytest.param(ValueError("boom"), True, id="value-error"),
+        pytest.param(ValueError("boom"), False, id="value-error"),
         pytest.param(PseudonymExchangeError("rejected"), True, id="pseudonym-exchange"),
         pytest.param(RuntimeError("unexpected"), True, id="unmapped"),
         pytest.param(NotFoundError(), False, id="not-found"),
@@ -61,3 +67,8 @@ def test_spec_for_resolves_the_expected_spec(exc: Exception, expected: ErrorSpec
 )
 def test_should_log(exc: Exception, expected: bool) -> None:
     assert should_log(exc) is expected
+
+
+def test_no_spec_is_both_a_failure_and_invalid_input() -> None:
+    for spec in [*EXCEPTION_MAP.values(), DEFAULT_SPEC]:
+        assert not (spec.log and spec.invalid_input)

tests/logging/test_events.py

@@ -28,6 +28,7 @@ def test_defines_every_required_event(self) -> None:
             ("SYS_UNHANDLED_EXCEPTION", "100604"),
             ("DB_SCHEMA_ERROR", "100605"),
             ("SYS_MISSING_CORRELATION_ID", "100606"),
+            ("INVALID_REQUEST", "100607"),
             ("REGISTERED_REFERRAL", "900400"),
             ("IDEMPOTENT_REGISTRATION", "900401"),
             ("REFERRAL_SEARCHED_ON_ID", "900402"),

tests/routers/test_localization_list.py

@@ -2,8 +2,10 @@
 
 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.models.auth.data import AuthorizationScope
 from app.models.pseudonym import EncryptedPseudonym
 from app.models.ura import UraNumber
@@ -84,6 +86,29 @@ def test_rejects_source_that_differs_from_claims(self, client: TestClient) -> No
 
         assert response.status_code == 403
 
+    @pytest.mark.parametrize(
+        "path",
+        [
+            ("extension", 0, "valueReference", "identifier", "system"),
+            ("source", "identifier", "system"),
+        ],
+        ids=["ura-system", "device-system"],
+    )
+    def test_logs_a_list_with_a_wrong_naming_system_as_an_invalid_request(
+        self, client: TestClient, path: tuple[str | int, ...]
+    ) -> None:
+        body = _body()
+        node: Any = body
+        for key in path[:-1]:
+            node = node[key]
+        node[path[-1]] = "urn:wrong"
+
+        with capture_records() as records:
+            response = client.post("/fhir/List", json=body, headers=FHIR_JSON)
+
+        assert response.status_code == 400
+        assert_event_emitted(records, Log.INVALID_REQUEST, organization_identifier=TEST_URA, http_status=400)
+
     def test_requires_create_scope(
         self,
         referral_service: ReferralService,
@@ -169,6 +194,14 @@ def test_localize_query_needs_no_source_match(self, localize_client: TestClient)
         assert response.status_code == 200
         assert response.json()["resourceType"] == "Bundle"
 
+    def test_keeps_the_subject_token_out_of_an_invalid_localization_log(self, localize_client: TestClient) -> None:
+        with capture_records() as records:
+            response = localize_client.get("/fhir/List", params={"subject:identifier": "leaky-token-value"})
+
+        assert response.status_code == 422
+        entry = assert_event_emitted(records, Log.INVALID_REQUEST, http_status=422)
+        assert "leaky-token-value" not in entry.message["error_reason"]
+
     def test_localize_query_requires_localize_scope(self, client: TestClient) -> None:
         response = client.get("/fhir/List", params={"subject:identifier": TEST_PSEUDONYM_TOKEN})
 

tests/routers/test_localize.py

@@ -131,6 +131,14 @@ def test_logs_a_failed_localization_with_the_callers_claims(
             http_status=400,
         )
 
+    def test_logs_an_invalid_body_as_an_invalid_request(self, localize_client: TestClient) -> None:
+        with capture_records() as records:
+            response = localize_client.post("/localize", json={})
+
+        assert response.status_code == 422
+        assert_event_emitted(records, Log.INVALID_REQUEST, organization_identifier=TEST_URA, http_status=422)
+        assert records.for_event(Log.LOCALIZATION_FAILED) == []
+
     def test_requires_localize_scope(
         self,
         referral_service: ReferralService,

tests/routers/test_registrations.py

@@ -116,6 +116,38 @@ def test_invalid_request_body_is_not_a_failed_registration(self, source_client:
         assert response.status_code == 422
         assert records.for_event(Log.REFERRAL_REGISTRATION_FAILED) == []
 
+    def test_logs_an_invalid_body_as_an_invalid_request(self, source_client: TestClient) -> None:
+        with capture_records() as records:
+            response = source_client.post("/registrations", json={})
+
+        assert response.status_code == 422
+        assert_event_emitted(records, Log.INVALID_REQUEST, organization_identifier=TEST_URA, http_status=422)
+
+    def test_logs_malformed_json_as_an_invalid_request(self, source_client: TestClient) -> None:
+        with capture_records() as records:
+            response = source_client.post("/registrations", content=b"{", headers={"Content-Type": "application/json"})
+
+        assert response.status_code == 422
+        assert_event_emitted(records, Log.INVALID_REQUEST, http_status=422)
+
+    def test_logs_a_rejected_exchange_only_as_a_failed_registration(
+        self,
+        source_client: TestClient,
+        crypto_client: CryptoServiceApiClientMock,
+        key_info_service: KeyInfoService,
+        monkeypatch: pytest.MonkeyPatch,
+    ) -> None:
+        key_info_service.add_one("nvi-label", mechanism="AES_CBC")
+        rejected = PseudonymExchangeError("Invalid pseudonym or oprf_key")
+        monkeypatch.setattr(crypto_client, "exchange", Mock(side_effect=rejected))
+
+        with capture_records() as records:
+            response = source_client.post("/registrations", json={"pseudonym": "pseu", "oprf_key": "key1"})
+
+        assert response.status_code == 400
+        assert len(records.for_event(Log.REFERRAL_REGISTRATION_FAILED)) == 1
+        assert records.for_event(Log.INVALID_REQUEST) == []
+
     def test_requires_create_scope(
         self,
         referral_service: ReferralService,