Log referral queries and bulk deletes in ReferralService (#608)

Author: thomas-samoht

app/routers/registrations.py

@@ -1,14 +1,11 @@
-import logging
 from typing import Annotated, Any
 
-import gfmodules.logging as gflog
 from fastapi import APIRouter, Body, Depends, Query, Response
 
 from app.dependencies import (
     get_pseudonym_resolver,
     get_referral_service,
 )
-from app.logging.events import Log
 from app.models.auth.context import AuthContext
 from app.models.auth.data import AuthorizationScope
 from app.models.registrations import (
@@ -21,7 +18,6 @@
 from app.services.pseudonym_resolver import PseudonymResolver
 from app.services.referral_service import ReferralService
 
-logger = logging.getLogger(__name__)
 router = APIRouter(tags=["Registrations"], prefix="/registrations")
 
 
@@ -36,14 +32,7 @@ def get_registration(
 ) -> Any:
     resolved = pseudonym_resolver.resolve(params.oprf_pseudonym())
 
-    results = referral_service.get_many(ura_number=ctx.claims.ura_number, encrypted_pseudonym=resolved.encrypted)
-
-    gflog.emit(
-        logger,
-        Log.REFERRALS_QUERIED,
-        "Referrals queried",
-        fields={"result_count": len(results)},
-    )
+    _, results = referral_service.query(ctx.claims.ura_number, encrypted_pseudonym=resolved.encrypted)
 
     return RegistrationList.from_entities(results)
 
@@ -83,20 +72,11 @@ def delete_registration(
     source: Annotated[str, Depends(require_managing_source)],
 ) -> Any:
     resolved = pseudonym_resolver.resolve(params.oprf_pseudonym())
-    encrypted_pseudonym = resolved.encrypted
 
-    deleted_count = referral_service.delete_many(
+    referral_service.delete_many(
         ura_number=ctx.claims.ura_number,
-        encrypted_pseudonym=encrypted_pseudonym,
+        encrypted_pseudonym=resolved.encrypted,
         source=source,
     )
 
-    if deleted_count > 0:
-        gflog.emit(
-            logger,
-            Log.ALL_PATIENT_REFERRALS_DELETED,
-            "All patient referrals deleted",
-            fields={"pseudonym_hash": str(encrypted_pseudonym), "deleted_count": deleted_count},
-        )
-
     return Response(status_code=204)

app/services/fhir/localization_list.py

@@ -90,25 +90,13 @@ def query(
                 resolved.encrypted, authenticated_ura, limit=page_size, offset=params.offset
             )
         else:
-            encrypted_pseudonym = resolved.encrypted if resolved else None
-            total = self.referral_service.count(
-                encrypted_pseudonym=encrypted_pseudonym,
+            total, referrals = self.referral_service.query(
+                authenticated_ura,
+                encrypted_pseudonym=(resolved.encrypted if resolved else None),
                 source=params.source,
-                ura_number=authenticated_ura,
-            )
-            referrals = self.referral_service.get_many(
-                encrypted_pseudonym=encrypted_pseudonym,
-                source=params.source,
-                ura_number=authenticated_ura,
                 limit=page_size,
                 offset=params.offset,
             )
-            gflog.emit(
-                logger,
-                Log.REFERRALS_QUERIED,
-                "Referrals queried",
-                fields={"result_count": total},
-            )
 
         bundle = Bundle(
             type="searchset",
@@ -158,37 +146,21 @@ def delete_by_query(
         authenticated_ura: UraNumber,
         source: str,
     ) -> tuple[OperationOutcome, int]:
-        ura_number = authenticated_ura
-
         resolved: ResolvedPseudonym | None = None
         if params.subject:
             resolved = self._pseudonym_resolver.resolve(PseudonymToken(params.subject))
 
         deleted_count = self.referral_service.delete_many(
             encrypted_pseudonym=(resolved.encrypted if resolved else None),
             source=source,
-            ura_number=ura_number,
+            ura_number=authenticated_ura,
         )
 
         if deleted_count < 1:
             return (
                 OperationOutcome.make_error_outcome(code="not-found", msg="No resources matched the given criteria"),
                 404,
             )
-        if resolved is not None:
-            gflog.emit(
-                logger,
-                Log.ALL_PATIENT_REFERRALS_DELETED,
-                "All patient referrals deleted",
-                fields={"pseudonym_hash": str(resolved.response), "deleted_count": deleted_count},
-            )
-        else:
-            gflog.emit(
-                logger,
-                Log.ALL_URA_REFERRALS_DELETED,
-                "All URA referrals deleted",
-                fields={"deleted_count": deleted_count},
-            )
         return (
             OperationOutcome.make_good_outcome(f"{deleted_count} resources have been deleted successfully"),
             200,

app/services/referral_service.py

@@ -131,6 +131,26 @@ def count(
                 source=source,
             )
 
+    def query(
+        self,
+        ura_number: UraNumber,
+        encrypted_pseudonym: EncryptedPseudonym | None = None,
+        source: str | None = None,
+        limit: int | None = None,
+        offset: int = 0,
+    ) -> tuple[int, Sequence[ReferralEntity]]:
+        total = self.count(ura_number=ura_number, encrypted_pseudonym=encrypted_pseudonym, source=source)
+        referrals = self.get_many(
+            ura_number=ura_number, encrypted_pseudonym=encrypted_pseudonym, source=source, limit=limit, offset=offset
+        )
+        gflog.emit(
+            logger,
+            Log.REFERRALS_QUERIED,
+            "Referrals queried",
+            fields={"result_count": total},
+        )
+        return total, referrals
+
     def localize(
         self,
         encrypted_pseudonym: EncryptedPseudonym,
@@ -165,7 +185,45 @@ def delete_many(
         ura_number: UraNumber,
         encrypted_pseudonym: EncryptedPseudonym | None = None,
         source: str | None = None,
-        id: str | UUID | None = None,
+    ) -> int:
+        deleted_count = self._delete(ura_number=ura_number, encrypted_pseudonym=encrypted_pseudonym, source=source)
+        if deleted_count < 1:
+            return deleted_count
+
+        if encrypted_pseudonym is not None:
+            gflog.emit(
+                logger,
+                Log.ALL_PATIENT_REFERRALS_DELETED,
+                "All patient referrals deleted",
+                fields={"pseudonym_hash": str(encrypted_pseudonym), "deleted_count": deleted_count},
+            )
+        else:
+            gflog.emit(
+                logger,
+                Log.ALL_URA_REFERRALS_DELETED,
+                "All URA referrals deleted",
+                fields={"deleted_count": deleted_count},
+            )
+        return deleted_count
+
+    def delete_by_id(self, id: UUID, ura_number: UraNumber, source: str) -> None:
+        referral = self._get_owned(id, ura_number)
+        if self._delete(ura_number=ura_number, source=source, id=id) < 1:
+            raise NotFoundError()
+
+        gflog.emit(
+            logger,
+            Log.REFERRAL_DELETED,
+            "Referral deleted",
+            fields={"pseudonym_hash": referral.pseudonym},
+        )
+
+    def _delete(
+        self,
+        ura_number: UraNumber,
+        encrypted_pseudonym: EncryptedPseudonym | None = None,
+        source: str | None = None,
+        id: UUID | None = None,
     ) -> int:
         with self.database.get_db_session() as session:
             repo = session.get_repository(ReferralRepository)
@@ -181,15 +239,3 @@ def delete_many(
         if affected_rows > 0:
             self.usage_metrics.deleted(ura_number, affected_rows)
         return affected_rows
-
-    def delete_by_id(self, id: UUID, ura_number: UraNumber, source: str) -> None:
-        referral = self._get_owned(id, ura_number)
-        if self.delete_many(ura_number=ura_number, source=source, id=id) < 1:
-            raise NotFoundError()
-
-        gflog.emit(
-            logger,
-            Log.REFERRAL_DELETED,
-            "Referral deleted",
-            fields={"pseudonym_hash": referral.pseudonym},
-        )

tests/services/test_referral_service.py

@@ -230,27 +230,65 @@ def test_delet_by_id_should_raise_exception_when_no_match_found(
     assert "Record not found" in str(exec.value)
 
 
+def test_delete_many_with_a_pseudonym_logs_patient_scope(
+    referral_service: ReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    store_referral(referral_service, key_info_service, ura_number)
+
+    with caplog.at_level(logging.INFO):
+        deleted = referral_service.delete_many(ura_number, encrypted_pseudonym=PSEUDONYM, source=SOURCE)
+
+    (fields,) = logged_fields(caplog, Log.ALL_PATIENT_REFERRALS_DELETED)
+    assert deleted == 1
+    assert fields["pseudonym_hash"] == str(PSEUDONYM)
+    assert fields["deleted_count"] == 1
+
+
+def test_delete_many_without_a_pseudonym_logs_ura_scope(
+    referral_service: ReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    store_referral(referral_service, key_info_service, ura_number)
+
+    with caplog.at_level(logging.INFO):
+        referral_service.delete_many(ura_number, source=SOURCE)
+
+    (fields,) = logged_fields(caplog, Log.ALL_URA_REFERRALS_DELETED)
+    assert fields["deleted_count"] == 1
+
+
+def test_delete_many_logs_nothing_when_nothing_matched(
+    referral_service: ReferralService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    with caplog.at_level(logging.INFO):
+        deleted = referral_service.delete_many(ura_number, encrypted_pseudonym=PSEUDONYM)
+
+    assert deleted == 0
+    assert logged_fields(caplog, Log.ALL_PATIENT_REFERRALS_DELETED) == []
+    assert logged_fields(caplog, Log.ALL_URA_REFERRALS_DELETED) == []
+
+
 def test_localize_logs_success_with_the_pseudonym_and_result_count(
     referral_service: ReferralService,
     key_info_service: KeyInfoService,
     ura_number: UraNumber,
     caplog: pytest.LogCaptureFixture,
 ) -> None:
-    key_info = key_info_service.add_one("label-1", "AES_CBC")
-    pseudonym = EncryptedPseudonym("ps-1", "123")
-    referral_service.add_one(
-        encrypted_pseudonym=pseudonym,
-        ura_number=ura_number,
-        source="SomeDevice",
-        key_id=key_info.id,
-    )
+    store_referral(referral_service, key_info_service, ura_number)
 
     with caplog.at_level(logging.INFO):
-        _, referrals = referral_service.localize(pseudonym, REQUESTING_URA)
+        _, referrals = referral_service.localize(PSEUDONYM, REQUESTING_URA)
 
     (fields,) = logged_fields(caplog, Log.LOCALIZATION_SUCCESS)
     assert len(referrals) == 1
-    assert fields["pseudonym_hash"] == str(pseudonym)
+    assert fields["pseudonym_hash"] == str(PSEUDONYM)
     assert fields["result_count"] == 1
 
 
@@ -259,8 +297,47 @@ def test_localize_logs_no_match_with_a_zero_result_count(
     caplog: pytest.LogCaptureFixture,
 ) -> None:
     with caplog.at_level(logging.INFO):
-        _, referrals = referral_service.localize(EncryptedPseudonym("ps-1", "123"), REQUESTING_URA)
+        _, referrals = referral_service.localize(PSEUDONYM, REQUESTING_URA)
 
     (fields,) = logged_fields(caplog, Log.LOCALIZATION_NO_MATCH)
     assert len(referrals) == 0
     assert fields["result_count"] == 0
+
+
+def test_localize_does_not_log_a_query(
+    referral_service: ReferralService,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    with caplog.at_level(logging.INFO):
+        referral_service.localize(PSEUDONYM, REQUESTING_URA)
+
+    assert logged_fields(caplog, Log.REFERRALS_QUERIED) == []
+
+
+def test_query_logs_the_result_count(
+    referral_service: ReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    store_referral(referral_service, key_info_service, ura_number)
+
+    with caplog.at_level(logging.INFO):
+        _, referrals = referral_service.query(ura_number, encrypted_pseudonym=PSEUDONYM)
+
+    (fields,) = logged_fields(caplog, Log.REFERRALS_QUERIED)
+    assert len(referrals) == 1
+    assert fields["result_count"] == 1
+
+
+def test_query_is_scoped_to_the_callers_ura(
+    referral_service: ReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+) -> None:
+    store_referral(referral_service, key_info_service, ura_number)
+
+    total, referrals = referral_service.query(REQUESTING_URA, encrypted_pseudonym=PSEUDONYM)
+
+    assert total == 0
+    assert len(referrals) == 0