Log failed referral queries and bulk deletes

Author: thomas-samoht

app/logging/events.py

@@ -102,6 +102,15 @@ class Log(_Base):
             _SIEM: (*_CALLER, "resource_ura"),
         },
     )
+    REFERRAL_QUERY_FAILED = LogEvent(  # NVI-REF-007
+        "900406",
+        logging.WARNING,
+        (_APP, _SIEM),
+        {
+            _APP: (*_CALLER, "http_status", "error_reason"),
+            _SIEM: (*_CALLER, "http_status", "error_reason"),
+        },
+    )
 
     REFERRAL_DELETED = LogEvent(  # NVI-DEL-001
         "900500",
@@ -132,6 +141,15 @@ class Log(_Base):
             _SIEM: (*_CALLER, "deleted_count"),
         },
     )
+    REFERRALS_DELETE_FAILED = LogEvent(  # NVI-DEL-005
+        "900504",
+        logging.WARNING,
+        (_APP, _SIEM),
+        {
+            _APP: (*_CALLER, "http_status", "error_reason"),
+            _SIEM: (*_CALLER, "http_status", "error_reason"),
+        },
+    )
 
     LOCALIZATION_SUCCESS = LogEvent(  # NVI-LOC-001
         "900600",

app/services/pseudonym_referral_service.py

@@ -66,19 +66,27 @@ def query(
         limit: int | None = None,
         offset: int = 0,
     ) -> tuple[int, Sequence[ReferralEntity]]:
-        encrypted = self._resolve_encrypted(pseudonym) if pseudonym else None
-        return self._referral_service.query(
-            ura_number, encrypted_pseudonym=encrypted, source=source, limit=limit, offset=offset
-        )
+        try:
+            encrypted = self._resolve_encrypted(pseudonym) if pseudonym else None
+            return self._referral_service.query(
+                ura_number, encrypted_pseudonym=encrypted, source=source, limit=limit, offset=offset
+            )
+        except Exception as exc:
+            _log_failure(Log.REFERRAL_QUERY_FAILED, "Referral query failed", exc)
+            raise
 
     def delete_many(
         self,
         ura_number: UraNumber,
         pseudonym: OprfPseudonym | None = None,
         source: str | None = None,
     ) -> int:
-        encrypted = self._resolve_encrypted(pseudonym) if pseudonym else None
-        return self._referral_service.delete_many(ura_number, encrypted_pseudonym=encrypted, source=source)
+        try:
+            encrypted = self._resolve_encrypted(pseudonym) if pseudonym else None
+            return self._referral_service.delete_many(ura_number, encrypted_pseudonym=encrypted, source=source)
+        except Exception as exc:
+            _log_failure(Log.REFERRALS_DELETE_FAILED, "Referral deletion failed", exc)
+            raise
 
     def _resolve_encrypted(self, pseudonym: OprfPseudonym) -> EncryptedPseudonym:
         return self._pseudonym_resolver.resolve(pseudonym).encrypted

tests/logging/test_events.py

@@ -35,9 +35,11 @@ def test_defines_every_required_event(self) -> None:
             ("REFERRALS_QUERIED", "900403"),
             ("REFERRAL_REGISTRATION_FAILED", "900404"),
             ("REFERRAL_ACCESS_DENIED", "900405"),
+            ("REFERRAL_QUERY_FAILED", "900406"),
             ("REFERRAL_DELETED", "900500"),
             ("ALL_PATIENT_REFERRALS_DELETED", "900501"),
             ("ALL_URA_REFERRALS_DELETED", "900503"),
+            ("REFERRALS_DELETE_FAILED", "900504"),
             ("LOCALIZATION_SUCCESS", "900600"),
             ("LOCALIZATION_FAILED", "900601"),
             ("LOCALIZATION_ERROR", "900601"),

tests/routers/test_localization_list.py

@@ -1,4 +1,5 @@
 from typing import Any
+from unittest.mock import Mock
 
 import pytest
 from fastapi.testclient import TestClient
@@ -9,6 +10,7 @@
 from app.models.auth.data import AuthorizationScope
 from app.models.pseudonym import EncryptedPseudonym
 from app.models.ura import UraNumber
+from app.services.exceptions import PseudonymExchangeError
 from app.services.key_info import KeyInfoService
 from app.services.referral_service import ReferralService
 from tests.conftest import TEST_PSEUDONYM_TOKEN, make_list_resource
@@ -367,3 +369,29 @@ def test_delete_by_query_reports_not_found_when_nothing_matched(self, client: Te
 
         assert response.status_code == 404
         assert response.json()["issue"][0]["code"] == "not-found"
+
+
+@pytest.fixture()
+def rejecting_exchange(crypto_client: CryptoServiceApiClientMock, monkeypatch: pytest.MonkeyPatch) -> None:
+    rejected = PseudonymExchangeError("Invalid pseudonym or oprf_key")
+    monkeypatch.setattr(crypto_client, "exchange", Mock(side_effect=rejected))
+
+
+@pytest.mark.usefixtures("rejecting_exchange")
+def test_logs_a_failed_search_as_a_failed_query(client: TestClient) -> None:
+    params = {"subject:identifier": TEST_PSEUDONYM_TOKEN, "source:identifier": TEST_SOURCE_ID}
+    with capture_records() as records:
+        response = client.get("/fhir/List", params=params)
+
+    assert response.status_code == 400
+    assert_event_emitted(records, Log.REFERRAL_QUERY_FAILED, organization_identifier=TEST_URA, http_status=400)
+    assert records.for_event(Log.LOCALIZATION_FAILED) == []
+
+
+@pytest.mark.usefixtures("rejecting_exchange")
+def test_logs_a_failed_bulk_delete(client: TestClient) -> None:
+    with capture_records() as records:
+        response = client.delete("/fhir/List", params={"subject:identifier": TEST_PSEUDONYM_TOKEN})
+
+    assert response.status_code == 400
+    assert_event_emitted(records, Log.REFERRALS_DELETE_FAILED, organization_identifier=TEST_URA, http_status=400)

tests/services/test_pseudonym_referral_service.py

@@ -192,3 +192,46 @@ def test_delete_many_without_pseudonym_removes_referrals_of_the_source(
 
     assert pseudonym_referral_service.delete_many(ura_number, source=SOURCE) == 2
     assert pseudonym_referral_service.query(ura_number)[0] == 1
+
+
+def test_query_logs_a_failure_when_the_pseudonym_is_rejected(
+    rejecting_service: PseudonymReferralService, ura_number: UraNumber, caplog: pytest.LogCaptureFixture
+) -> None:
+    with caplog.at_level(logging.INFO), pytest.raises(PseudonymExchangeError):
+        rejecting_service.query(ura_number, pseudonym=PSEUDONYM)
+
+    (fields,) = logged_fields(caplog, Log.REFERRAL_QUERY_FAILED)
+    assert fields["http_status"] == 400
+
+
+def test_query_without_a_pseudonym_logs_no_failure(
+    pseudonym_referral_service: PseudonymReferralService, ura_number: UraNumber, caplog: pytest.LogCaptureFixture
+) -> None:
+    with caplog.at_level(logging.INFO):
+        pseudonym_referral_service.query(ura_number)
+
+    assert logged_fields(caplog, Log.REFERRAL_QUERY_FAILED) == []
+
+
+def test_delete_many_logs_a_failure_when_it_breaks(
+    failing_service: PseudonymReferralService, ura_number: UraNumber, caplog: pytest.LogCaptureFixture
+) -> None:
+    with caplog.at_level(logging.INFO), pytest.raises(RuntimeError):
+        failing_service.delete_many(ura_number, pseudonym=PSEUDONYM, source=SOURCE)
+
+    (fields,) = logged_fields(caplog, Log.REFERRALS_DELETE_FAILED)
+    assert fields["http_status"] == 500
+    assert fields["error_reason"] == "boom"
+
+
+def test_delete_many_logs_no_failure_when_nothing_matches(
+    pseudonym_referral_service: PseudonymReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    key_info_service.add_one("nvi-label", "AES_CBC")
+    with caplog.at_level(logging.INFO):
+        assert pseudonym_referral_service.delete_many(ura_number, pseudonym=PSEUDONYM, source=SOURCE) == 0
+
+    assert logged_fields(caplog, Log.REFERRALS_DELETE_FAILED) == []