From 3b31be89872090808312aa2e147c61bb17abac05 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 15:24:22 +0100 Subject: [PATCH 01/25] log resources --- lambdas/id_sync/src/record_processor.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 5b5eac7c6..915ef7224 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -30,6 +30,7 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: body = body_text nhs_number = body.get("subject") + # Reached logger.info("process record NHS number: %s", nhs_number) if nhs_number: return process_nhs_number(nhs_number) @@ -57,6 +58,9 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) return make_status(str(e), nhs_number, "error") + logger.info("Fetched PDS details: %s", pds_patient_resource) + logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), ieds_resources if ieds_resources else 0) + if not ieds_resources: logger.info("No IEDS records returned for NHS number: %s", nhs_number) return make_status(f"No records returned for ID: {nhs_number}", nhs_number) @@ -86,14 +90,22 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: # Function to fetch PDS Patient details and IEDS Immunisation records def fetch_pds_and_ieds_resources(nhs_number: str): + logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: pds = pds_get_patient_details(nhs_number) + logger.info("fetch_pds_resources: fetching for %s", pds) except Exception as e: + logger.exception("fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number) raise RuntimeError("Failed to fetch PDS details") from e + try: ieds = get_items_from_patient_id(nhs_number) except Exception as e: + logger.exception("fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number) raise RuntimeError("Failed to fetch IEDS items") from e + + count = len(ieds) + logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) return pds, ieds From 1c3eb9c2928a66a025a08d6a8324d1edc2ca58fa Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 16:38:24 +0100 Subject: [PATCH 02/25] debugging demographics match --- lambdas/id_sync/src/record_processor.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 915ef7224..3ec466b92 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -144,6 +144,7 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) + logger.debug("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) @@ -155,6 +156,7 @@ def normalize_strings(item: Any) -> str | None: ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) + logger.debug("demographics_match: demographics match for %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]): @@ -174,6 +176,7 @@ def normalize_strings(item: Any) -> str | None: logger.debug("demographics_match: name mismatch %s != %s", pds_name, ieds_name) return False + logger.debug("demographics_match: demographics match for %s", patient) return True except Exception: logger.exception("demographics_match: comparison failed with exception") From 3081b06aac830e9d7814a2ecc566090abd9bbf7e Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 16:52:50 +0100 Subject: [PATCH 03/25] change debug logs --- lambdas/id_sync/src/record_processor.py | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 3ec466b92..5f4d85713 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -68,11 +68,13 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: # Compare demographics from PDS to each IEDS item, keep only matching records matching_records = [] discarded_count = 0 + discarded_records = [] for detail in ieds_resources: if demographics_match(pds_patient_resource, detail): matching_records.append(detail) else: discarded_count += 1 + discarded_records.append(detail) if not matching_records: logger.info("No records matched PDS demographics: %d", discarded_count) @@ -144,39 +146,39 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) - logger.debug("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) + logger.info("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) if not patient: - logger.debug("demographics_match: no patient resource in IEDS table item") + logger.info("demographics_match: no patient resource in IEDS table item") return False # normalize patient fields from IEDS ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) - logger.debug("demographics_match: demographics match for %s", patient) + logger.info("demographics_match: demographics match for %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]): - logger.debug("demographics_match: missing required demographics") + logger.info("demographics_match: missing required demographics") return False # Compare fields if pds_birth != ieds_birth: - logger.debug("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) + logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) return False if pds_gender != ieds_gender: - logger.debug("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) + logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) return False if pds_name != ieds_name: - logger.debug("demographics_match: name mismatch %s != %s", pds_name, ieds_name) + logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) return False - logger.debug("demographics_match: demographics match for %s", patient) + logger.info("demographics_match: demographics match for %s", patient) return True except Exception: logger.exception("demographics_match: comparison failed with exception") From 4cb13c947f45a7f0c75947e14b175b5fb50365db Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 17:59:15 +0100 Subject: [PATCH 04/25] confirm logs info --- lambdas/id_sync/src/record_processor.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 5f4d85713..6e2842035 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -77,7 +77,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_records.append(detail) if not matching_records: - logger.info("No records matched PDS demographics: %d", discarded_count) + logger.info("No records matched PDS demographics: %d", discarded_count, discarded_records) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( From abd7ca2ea35c999194f742b7b684ab6a4caa0a44 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 17:59:47 +0100 Subject: [PATCH 05/25] add info logs --- lambdas/shared/src/common/clients.py | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/lambdas/shared/src/common/clients.py b/lambdas/shared/src/common/clients.py index 9f7bf308b..b02138593 100644 --- a/lambdas/shared/src/common/clients.py +++ b/lambdas/shared/src/common/clients.py @@ -2,9 +2,19 @@ import logging from boto3 import client as boto3_client, resource as boto3_resource -logging.basicConfig(level="INFO") -logger = logging.getLogger() -logger.setLevel("INFO") +# Configure root logger with a numeric level and ensure any handlers accept INFO. +logging.basicConfig(level=logging.INFO) +root_logger = logging.getLogger() +root_logger.setLevel(logging.INFO) +for handler in root_logger.handlers: + # make sure handler level is not higher than INFO + try: + handler.setLevel(logging.INFO) + except Exception: + pass + +# Export the configured root logger for modules to use +logger = root_logger STREAM_NAME = os.getenv("SPLUNK_FIREHOSE_NAME", "firehose-name-not-defined") CONFIG_BUCKET_NAME = os.getenv("CONFIG_BUCKET_NAME", "variconfig-bucketable-not-defined") From 40b6e059523c8bf63367e455245e81319d2ade06 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 18:10:17 +0100 Subject: [PATCH 06/25] fix lint issues --- lambdas/shared/src/common/clients.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/lambdas/shared/src/common/clients.py b/lambdas/shared/src/common/clients.py index b02138593..adfdf14fc 100644 --- a/lambdas/shared/src/common/clients.py +++ b/lambdas/shared/src/common/clients.py @@ -6,12 +6,12 @@ logging.basicConfig(level=logging.INFO) root_logger = logging.getLogger() root_logger.setLevel(logging.INFO) + for handler in root_logger.handlers: - # make sure handler level is not higher than INFO - try: - handler.setLevel(logging.INFO) - except Exception: - pass + try: + handler.setLevel(logging.INFO) + except Exception: + pass # Export the configured root logger for modules to use logger = root_logger From 85e86ba89815dd2848ac7f9f2716693a5eb753b6 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 18:34:40 +0100 Subject: [PATCH 07/25] logging INFO issues --- lambdas/shared/src/common/clients.py | 14 +--- .../shared/tests/test_common/test_clients.py | 72 +++++++++---------- 2 files changed, 37 insertions(+), 49 deletions(-) diff --git a/lambdas/shared/src/common/clients.py b/lambdas/shared/src/common/clients.py index adfdf14fc..501418c12 100644 --- a/lambdas/shared/src/common/clients.py +++ b/lambdas/shared/src/common/clients.py @@ -2,19 +2,9 @@ import logging from boto3 import client as boto3_client, resource as boto3_resource -# Configure root logger with a numeric level and ensure any handlers accept INFO. logging.basicConfig(level=logging.INFO) -root_logger = logging.getLogger() -root_logger.setLevel(logging.INFO) - -for handler in root_logger.handlers: - try: - handler.setLevel(logging.INFO) - except Exception: - pass - -# Export the configured root logger for modules to use -logger = root_logger +logger = logging.getLogger() +logger.setLevel(logging.INFO) STREAM_NAME = os.getenv("SPLUNK_FIREHOSE_NAME", "firehose-name-not-defined") CONFIG_BUCKET_NAME = os.getenv("CONFIG_BUCKET_NAME", "variconfig-bucketable-not-defined") diff --git a/lambdas/shared/tests/test_common/test_clients.py b/lambdas/shared/tests/test_common/test_clients.py index 54f86ef8d..0adb21eb0 100644 --- a/lambdas/shared/tests/test_common/test_clients.py +++ b/lambdas/shared/tests/test_common/test_clients.py @@ -1,63 +1,61 @@ import unittest -from unittest.mock import patch -import common.clients as clients +from unittest.mock import patch, MagicMock +import logging import importlib +import common.clients as clients class TestClients(unittest.TestCase): - BUCKET_NAME = "default-bucket" AWS_REGION = "eu-west-2" def setUp(self): - self.boto3_client_patch = patch("boto3.client") + # Patch boto3.client + self.boto3_client_patch = patch("boto3.client", autospec=True) self.mock_boto3_client = self.boto3_client_patch.start() - self.logging_patch = patch("logging.getLogger") - self.mock_logging = self.logging_patch.start() - self.logger_info_patcher = patch("logging.Logger.info") - self.mock_logger_info = self.logger_info_patcher.start() - self.getenv_patch = patch("os.getenv") + self.addCleanup(self.boto3_client_patch.stop) + + # Patch logging.getLogger + self.logging_patch = patch("logging.getLogger", autospec=True) + self.mock_getLogger = self.logging_patch.start() + self.addCleanup(self.logging_patch.stop) + + # Patch os.getenv + self.getenv_patch = patch("os.getenv", autospec=True) self.mock_getenv = self.getenv_patch.start() + self.addCleanup(self.getenv_patch.stop) + + # Set environment variable mock return values self.mock_getenv.side_effect = lambda key, default=None: { "CONFIG_BUCKET_NAME": self.BUCKET_NAME, "AWS_REGION": self.AWS_REGION, }.get(key, default) - self.mock_boto3_client.return_value = self.mock_boto3_client - self.mock_boto3_client.return_value.send_message = {} - - def tearDown(self): - patch.stopall() + # Simulate logger instance and patch setLevel + self.mock_logger_instance = MagicMock() + self.mock_getLogger.return_value = self.mock_logger_instance - def test_os_environ(self): - # Test if environment variables are set correctly + # Reload the module under test to apply patches importlib.reload(clients) + + def test_env_variables_loaded(self): + """Test that environment variables are loaded correctly""" self.assertEqual(clients.CONFIG_BUCKET_NAME, self.BUCKET_NAME) self.assertEqual(clients.REGION_NAME, self.AWS_REGION) - def test_boto3_client(self): - ''' Test boto3 client is created with correct parameters ''' - importlib.reload(clients) + def test_boto3_client_created_for_s3(self): + """Test that S3 boto3 client is created with correct region""" self.mock_boto3_client.assert_any_call("s3", region_name=self.AWS_REGION) - def test_firehose_client(self): - ''' Test firehose client is created with correct parameters ''' - importlib.reload(clients) + def test_boto3_client_created_for_firehose(self): + """Test that Firehose boto3 client is created with correct region""" self.mock_boto3_client.assert_any_call("firehose", region_name=self.AWS_REGION) - def test_logging_setup(self): - ''' Test logging is set up correctly ''' - importlib.reload(clients) - self.assertTrue(hasattr(clients, 'logger')) + def test_logger_is_initialized(self): + """Test that a logger instance is initialized""" + self.mock_getLogger.assert_called_once_with() + self.assertTrue(hasattr(clients, "logger")) - def test_logging_configuration(self): - ''' Test logging configuration ''' - importlib.reload(clients) - clients.logger.setLevel.assert_called_once_with("INFO") - - def test_logging_initialization(self): - ''' Test logging initialization ''' - importlib.reload(clients) - self.mock_logging.assert_called_once_with() - self.assertTrue(hasattr(clients, 'logger')) - clients.logger.setLevel.assert_any_call("INFO") + def test_logger_set_level(self): + """Test that logger level is set to INFO""" + self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) \ No newline at end of file From ffcb6f897720930378ce7daca180837b34d76e59 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 18:36:41 +0100 Subject: [PATCH 08/25] fix git issues --- lambdas/shared/tests/test_common/test_clients.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lambdas/shared/tests/test_common/test_clients.py b/lambdas/shared/tests/test_common/test_clients.py index 0adb21eb0..d9680a047 100644 --- a/lambdas/shared/tests/test_common/test_clients.py +++ b/lambdas/shared/tests/test_common/test_clients.py @@ -58,4 +58,4 @@ def test_logger_is_initialized(self): def test_logger_set_level(self): """Test that logger level is set to INFO""" - self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) \ No newline at end of file + self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) From b2d312fb2c9770fa7e97f370a43808c69931d1d9 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 19:15:43 +0100 Subject: [PATCH 09/25] fix duplicate logs and missing logs --- lambdas/shared/src/common/clients.py | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/lambdas/shared/src/common/clients.py b/lambdas/shared/src/common/clients.py index 501418c12..6bb77434b 100644 --- a/lambdas/shared/src/common/clients.py +++ b/lambdas/shared/src/common/clients.py @@ -2,9 +2,19 @@ import logging from boto3 import client as boto3_client, resource as boto3_resource -logging.basicConfig(level=logging.INFO) logger = logging.getLogger() -logger.setLevel(logging.INFO) +logger.setLevel(logging.INFO) # Root logger level + +if logger.hasHandlers(): + logger.handlers.clear() + +console = logging.StreamHandler() +console.setLevel(logging.INFO) # Handler must also allow INFO logs + +formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s') +console.setFormatter(formatter) + +logger.addHandler(console) STREAM_NAME = os.getenv("SPLUNK_FIREHOSE_NAME", "firehose-name-not-defined") CONFIG_BUCKET_NAME = os.getenv("CONFIG_BUCKET_NAME", "variconfig-bucketable-not-defined") From c96c0b379c000efdb896ee4520ff4bc6f4170549 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 19:40:38 +0100 Subject: [PATCH 10/25] probe logs --- lambdas/id_sync/src/record_processor.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 6e2842035..13b0aa851 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -14,6 +14,17 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: logger.info("process_record. Processing record: %s", event_record) + # Probe logger configuration to help debug missing logs in CloudWatch + try: + import logging as _logging + logger.info( + "probe: logger id=%s module=%s level=%s handlers=%d", + hex(id(logger)), getattr(logger, "__module__", None), + _logging.getLevelName(logger.getEffectiveLevel()), len(logger.handlers), + ) + except Exception: + # Keep probe non-fatal in production + pass body_text = event_record.get('body', '') # convert body to json (try JSON first, then fall back to Python literal) From 53c90da541f718627237ed4655a2b43a4c2a14cd Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 19:43:53 +0100 Subject: [PATCH 11/25] probe logs --- lambdas/id_sync/src/record_processor.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 13b0aa851..632d75d0f 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -16,11 +16,10 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: logger.info("process_record. Processing record: %s", event_record) # Probe logger configuration to help debug missing logs in CloudWatch try: - import logging as _logging logger.info( - "probe: logger id=%s module=%s level=%s handlers=%d", + "probe: logger id=%s module=%s level=%d handlers=%d", hex(id(logger)), getattr(logger, "__module__", None), - _logging.getLevelName(logger.getEffectiveLevel()), len(logger.handlers), + logger.getEffectiveLevel(), len(logger.handlers), ) except Exception: # Keep probe non-fatal in production From e5735381cc39b1945f20b699b9c14ca1f678e6ee Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 20:25:26 +0100 Subject: [PATCH 12/25] create seperate logger per module --- lambdas/id_sync/src/record_processor.py | 90 ++++++++++++++++--------- 1 file changed, 58 insertions(+), 32 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 632d75d0f..2a1909730 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -1,5 +1,9 @@ -from common.clients import logger +import logging +import json +import ast from typing import Dict, Any + +from common.clients import logger as clients_logger from pds_details import pds_get_patient_id, pds_get_patient_details from ieds_db_operations import ( ieds_update_patient_id, @@ -7,19 +11,31 @@ get_items_from_patient_id, ) from utils import make_status -import json -import ast + +# Module-local logger for records processing. Use this for logs local to this module +# so they can be managed separately from the shared clients logger. +module_logger = logging.getLogger(__name__) +# Keep a module-level `logger` symbol for backwards compatibility with tests +# and other modules that patch or import `record_processor.logger`. +logger = module_logger def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: - logger.info("process_record. Processing record: %s", event_record) - # Probe logger configuration to help debug missing logs in CloudWatch + module_logger.info("process_record. Processing record: %s", event_record) + # Probe logger configuration to help debug missing logs in CloudWatch. + # Log both the module-local logger and the shared clients logger so it's + # possible to compare their handlers/levels in CloudWatch. try: - logger.info( - "probe: logger id=%s module=%s level=%d handlers=%d", - hex(id(logger)), getattr(logger, "__module__", None), - logger.getEffectiveLevel(), len(logger.handlers), + module_logger.info( + "probe: module_logger id=%s module=%s level=%d handlers=%d", + hex(id(module_logger)), getattr(module_logger, "__module__", None), + module_logger.getEffectiveLevel(), len(module_logger.handlers), + ) + module_logger.info( + "probe: clients_logger id=%s module=%s level=%d handlers=%d", + hex(id(clients_logger)), getattr(clients_logger, "__module__", None), + clients_logger.getEffectiveLevel(), len(clients_logger.handlers), ) except Exception: # Keep probe non-fatal in production @@ -34,18 +50,18 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: try: body = ast.literal_eval(body_text) except (ValueError, SyntaxError): - logger.error("Failed to parse body: %s", body_text) + module_logger.error("Failed to parse body: %s", body_text) return {"status": "error", "message": "Invalid body format"} else: body = body_text nhs_number = body.get("subject") # Reached - logger.info("process record NHS number: %s", nhs_number) + module_logger.info("process record NHS number: %s", nhs_number) if nhs_number: return process_nhs_number(nhs_number) - logger.info("No NHS number found in event record") + module_logger.info("No NHS number found in event record") return {"status": "error", "message": "No NHS number found in event record"} @@ -59,20 +75,21 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: if new_nhs_number == nhs_number: return make_status("No update required", nhs_number) - logger.info("Update patient ID from %s to %s", nhs_number, new_nhs_number) + module_logger.info("Update patient ID from %s to %s", nhs_number, new_nhs_number) try: # Fetch PDS Patient resource and IEDS resources for the old NHS number pds_patient_resource, ieds_resources = fetch_pds_and_ieds_resources(nhs_number) except Exception as e: - logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) + module_logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) return make_status(str(e), nhs_number, "error") - logger.info("Fetched PDS details: %s", pds_patient_resource) - logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), ieds_resources if ieds_resources else 0) + module_logger.info("Fetched PDS details: %s", pds_patient_resource) + module_logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), + ieds_resources if ieds_resources else 0) if not ieds_resources: - logger.info("No IEDS records returned for NHS number: %s", nhs_number) + module_logger.info("No IEDS records returned for NHS number: %s", nhs_number) return make_status(f"No records returned for ID: {nhs_number}", nhs_number) # Compare demographics from PDS to each IEDS item, keep only matching records @@ -87,7 +104,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_records.append(detail) if not matching_records: - logger.info("No records matched PDS demographics: %d", discarded_count, discarded_records) + module_logger.info("No records matched PDS demographics: %d %s", discarded_count, discarded_records) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( @@ -102,22 +119,26 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: # Function to fetch PDS Patient details and IEDS Immunisation records def fetch_pds_and_ieds_resources(nhs_number: str): - logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) + module_logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: pds = pds_get_patient_details(nhs_number) - logger.info("fetch_pds_resources: fetching for %s", pds) + module_logger.info("fetch_pds_resources: fetching for %s", pds) except Exception as e: - logger.exception("fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number) + module_logger.exception( + "fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number + ) raise RuntimeError("Failed to fetch PDS details") from e try: ieds = get_items_from_patient_id(nhs_number) except Exception as e: - logger.exception("fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number) + module_logger.exception( + "fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number + ) raise RuntimeError("Failed to fetch IEDS items") from e count = len(ieds) - logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) + module_logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) return pds, ieds @@ -156,40 +177,45 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) - logger.info("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) + module_logger.info( + "demographics_match: demographics from PDS: %s %s %s", + pds_name, + pds_gender, + pds_birth, + ) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) if not patient: - logger.info("demographics_match: no patient resource in IEDS table item") + module_logger.info("demographics_match: no patient resource in IEDS table item") return False # normalize patient fields from IEDS ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) - logger.info("demographics_match: demographics match for %s", patient) + module_logger.info("demographics_match: demographics from IEDS: %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]): - logger.info("demographics_match: missing required demographics") + module_logger.info("demographics_match: missing required demographics") return False # Compare fields if pds_birth != ieds_birth: - logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) + module_logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) return False if pds_gender != ieds_gender: - logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) + module_logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) return False if pds_name != ieds_name: - logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) + module_logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) return False - logger.info("demographics_match: demographics match for %s", patient) + module_logger.info("demographics_match: demographics match for %s", patient) return True except Exception: - logger.exception("demographics_match: comparison failed with exception") + module_logger.exception("demographics_match: comparison failed with exception") return False From 2b299c177bde4f7e43b9d9a7a4bba523fbceed6e Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 21:22:36 +0100 Subject: [PATCH 13/25] spotted log issue --- lambdas/id_sync/src/record_processor.py | 90 ++++++++----------------- 1 file changed, 27 insertions(+), 63 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 2a1909730..6e2842035 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -1,9 +1,5 @@ -import logging -import json -import ast +from common.clients import logger from typing import Dict, Any - -from common.clients import logger as clients_logger from pds_details import pds_get_patient_id, pds_get_patient_details from ieds_db_operations import ( ieds_update_patient_id, @@ -11,35 +7,13 @@ get_items_from_patient_id, ) from utils import make_status - -# Module-local logger for records processing. Use this for logs local to this module -# so they can be managed separately from the shared clients logger. -module_logger = logging.getLogger(__name__) -# Keep a module-level `logger` symbol for backwards compatibility with tests -# and other modules that patch or import `record_processor.logger`. -logger = module_logger +import json +import ast def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: - module_logger.info("process_record. Processing record: %s", event_record) - # Probe logger configuration to help debug missing logs in CloudWatch. - # Log both the module-local logger and the shared clients logger so it's - # possible to compare their handlers/levels in CloudWatch. - try: - module_logger.info( - "probe: module_logger id=%s module=%s level=%d handlers=%d", - hex(id(module_logger)), getattr(module_logger, "__module__", None), - module_logger.getEffectiveLevel(), len(module_logger.handlers), - ) - module_logger.info( - "probe: clients_logger id=%s module=%s level=%d handlers=%d", - hex(id(clients_logger)), getattr(clients_logger, "__module__", None), - clients_logger.getEffectiveLevel(), len(clients_logger.handlers), - ) - except Exception: - # Keep probe non-fatal in production - pass + logger.info("process_record. Processing record: %s", event_record) body_text = event_record.get('body', '') # convert body to json (try JSON first, then fall back to Python literal) @@ -50,18 +24,18 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: try: body = ast.literal_eval(body_text) except (ValueError, SyntaxError): - module_logger.error("Failed to parse body: %s", body_text) + logger.error("Failed to parse body: %s", body_text) return {"status": "error", "message": "Invalid body format"} else: body = body_text nhs_number = body.get("subject") # Reached - module_logger.info("process record NHS number: %s", nhs_number) + logger.info("process record NHS number: %s", nhs_number) if nhs_number: return process_nhs_number(nhs_number) - module_logger.info("No NHS number found in event record") + logger.info("No NHS number found in event record") return {"status": "error", "message": "No NHS number found in event record"} @@ -75,21 +49,20 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: if new_nhs_number == nhs_number: return make_status("No update required", nhs_number) - module_logger.info("Update patient ID from %s to %s", nhs_number, new_nhs_number) + logger.info("Update patient ID from %s to %s", nhs_number, new_nhs_number) try: # Fetch PDS Patient resource and IEDS resources for the old NHS number pds_patient_resource, ieds_resources = fetch_pds_and_ieds_resources(nhs_number) except Exception as e: - module_logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) + logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) return make_status(str(e), nhs_number, "error") - module_logger.info("Fetched PDS details: %s", pds_patient_resource) - module_logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), - ieds_resources if ieds_resources else 0) + logger.info("Fetched PDS details: %s", pds_patient_resource) + logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), ieds_resources if ieds_resources else 0) if not ieds_resources: - module_logger.info("No IEDS records returned for NHS number: %s", nhs_number) + logger.info("No IEDS records returned for NHS number: %s", nhs_number) return make_status(f"No records returned for ID: {nhs_number}", nhs_number) # Compare demographics from PDS to each IEDS item, keep only matching records @@ -104,7 +77,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_records.append(detail) if not matching_records: - module_logger.info("No records matched PDS demographics: %d %s", discarded_count, discarded_records) + logger.info("No records matched PDS demographics: %d", discarded_count, discarded_records) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( @@ -119,26 +92,22 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: # Function to fetch PDS Patient details and IEDS Immunisation records def fetch_pds_and_ieds_resources(nhs_number: str): - module_logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) + logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: pds = pds_get_patient_details(nhs_number) - module_logger.info("fetch_pds_resources: fetching for %s", pds) + logger.info("fetch_pds_resources: fetching for %s", pds) except Exception as e: - module_logger.exception( - "fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number - ) + logger.exception("fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number) raise RuntimeError("Failed to fetch PDS details") from e try: ieds = get_items_from_patient_id(nhs_number) except Exception as e: - module_logger.exception( - "fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number - ) + logger.exception("fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number) raise RuntimeError("Failed to fetch IEDS items") from e count = len(ieds) - module_logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) + logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) return pds, ieds @@ -177,45 +146,40 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) - module_logger.info( - "demographics_match: demographics from PDS: %s %s %s", - pds_name, - pds_gender, - pds_birth, - ) + logger.info("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) if not patient: - module_logger.info("demographics_match: no patient resource in IEDS table item") + logger.info("demographics_match: no patient resource in IEDS table item") return False # normalize patient fields from IEDS ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) - module_logger.info("demographics_match: demographics from IEDS: %s", patient) + logger.info("demographics_match: demographics match for %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]): - module_logger.info("demographics_match: missing required demographics") + logger.info("demographics_match: missing required demographics") return False # Compare fields if pds_birth != ieds_birth: - module_logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) + logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) return False if pds_gender != ieds_gender: - module_logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) + logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) return False if pds_name != ieds_name: - module_logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) + logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) return False - module_logger.info("demographics_match: demographics match for %s", patient) + logger.info("demographics_match: demographics match for %s", patient) return True except Exception: - module_logger.exception("demographics_match: comparison failed with exception") + logger.exception("demographics_match: comparison failed with exception") return False From 3c7bffe0dbdcb6041d93a11074d441ef879d68c7 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 22:03:45 +0100 Subject: [PATCH 14/25] record_processor logs --- lambdas/id_sync/src/record_processor.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 6e2842035..496e70be9 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -59,7 +59,8 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: return make_status(str(e), nhs_number, "error") logger.info("Fetched PDS details: %s", pds_patient_resource) - logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources), ieds_resources if ieds_resources else 0) + logger.info("Fetched IEDS resources: %s", ieds_resources) + logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources) if ieds_resources else 0) if not ieds_resources: logger.info("No IEDS records returned for NHS number: %s", nhs_number) @@ -77,7 +78,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_records.append(detail) if not matching_records: - logger.info("No records matched PDS demographics: %d", discarded_count, discarded_records) + logger.info("No records matched PDS demographics: %d %s", discarded_count, discarded_records) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( @@ -90,7 +91,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: return response -# Function to fetch PDS Patient details and IEDS Immunisation records +# Function to fetch PDS Patient details and IEDS Immunisation records. WORKS def fetch_pds_and_ieds_resources(nhs_number: str): logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: @@ -108,6 +109,7 @@ def fetch_pds_and_ieds_resources(nhs_number: str): count = len(ieds) logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) + logger.info("fetch_ieds_resources:", ieds) return pds, ieds From 5b72fe6277d1fb99b49fd521b06c4422d43d6723 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 22:36:44 +0100 Subject: [PATCH 15/25] resolve log issues --- lambdas/id_sync/src/id_sync.py | 21 +++++++++++++++++---- lambdas/id_sync/tests/test_id_sync.py | 19 ++++++++++--------- 2 files changed, 27 insertions(+), 13 deletions(-) diff --git a/lambdas/id_sync/src/id_sync.py b/lambdas/id_sync/src/id_sync.py index c42c333f3..4d24e46c5 100644 --- a/lambdas/id_sync/src/id_sync.py +++ b/lambdas/id_sync/src/id_sync.py @@ -24,11 +24,24 @@ def handler(event_data: Dict[str, Any], _context) -> Dict[str, Any]: logger.info("id_sync processing event with %d records", len(records)) - results = [process_record(record) for record in records] - nhs_numbers = [result["nhs_number"] for result in results] - error_count = sum(1 for result in results if result.get("status") == "error") + # Use explicit loops instead of list comprehensions so we can more + # easily inspect intermediate results and avoid building temporary + # comprehension constructs. + results = [] + nhs_numbers = [] + error_count = 0 - if error_count: + for record in records: + result = process_record(record) + results.append(result) + + if "nhs_number" in result: + nhs_numbers.append(result["nhs_number"]) + + if result.get("status") == "error": + error_count += 1 + + if error_count > 0: raise IdSyncException(message=f"Processed {len(records)} records with {error_count} errors", nhs_numbers=nhs_numbers) diff --git a/lambdas/id_sync/tests/test_id_sync.py b/lambdas/id_sync/tests/test_id_sync.py index 3d7c54cf8..f438d87f0 100644 --- a/lambdas/id_sync/tests/test_id_sync.py +++ b/lambdas/id_sync/tests/test_id_sync.py @@ -235,29 +235,30 @@ def test_handler_process_record_exception(self): self.assertEqual(exception.message, "Error processing id_sync event") def test_handler_process_record_missing_nhs_number(self): - """Test handler when process_record returns incomplete data""" + """Test handler when process_record returns error and missing NHS number""" + # Setup mocks mock_event = MagicMock() mock_event.records = [MagicMock()] self.mock_aws_lambda_event.return_value = mock_event - # Missing "nhs_number" in response + # Return result without 'nhs_number' but with an 'error' status self.mock_process_record.return_value = { - "status": "success" - # Missing "nhs_number" + "status": "error", + "message": "Missing NHS number" + # No 'nhs_number' } - # Call handler + # Call handler and expect exception with self.assertRaises(IdSyncException) as exception_context: handler(self.single_sqs_event, None) exception = exception_context.exception - # convert exception payload to json self.assertIsInstance(exception, IdSyncException) - self.assertEqual(exception.nhs_numbers, None) - self.assertEqual(exception.message, "Error processing id_sync event") - self.mock_logger.exception.assert_called_once_with("Error processing id_sync event") + self.assertEqual(exception.nhs_numbers, []) # Since no nhs_number was collected + self.assertEqual(exception.message, "Processed 1 records with 1 errors") + self.mock_logger.exception.assert_called_once_with(f"id_sync error: {exception.message}") def test_handler_context_parameter_ignored(self): """Test that context parameter is properly ignored""" From 01cdff5f2f7cd6434f2cdfb6b8b077aa8d762a75 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 23:08:41 +0100 Subject: [PATCH 16/25] record processor --- lambdas/id_sync/src/record_processor.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 496e70be9..992558760 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -78,7 +78,8 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_records.append(detail) if not matching_records: - logger.info("No records matched PDS demographics: %d %s", discarded_count, discarded_records) + logger.info("No records matched PDS demographics: %d\nDiscarded:\n%s", discarded_count, + json.dumps(discarded_records, indent=2)) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( @@ -109,7 +110,7 @@ def fetch_pds_and_ieds_resources(nhs_number: str): count = len(ieds) logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) - logger.info("fetch_ieds_resources:", ieds) + logger.info("fetch_ieds_resources: %s", ieds) return pds, ieds @@ -148,7 +149,8 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) - logger.info("demographics_match: demographics match for %s", pds_name, pds_gender, pds_birth) + logger.info("demographics_match: demographics match for name=%s, gender=%s, birthDate=%s", + pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) From 2697aca84c5b42dc4a5e04ffd8153eab3b185d0a Mon Sep 17 00:00:00 2001 From: Akol125 Date: Wed, 24 Sep 2025 23:45:23 +0100 Subject: [PATCH 17/25] extract patient resource --- lambdas/id_sync/src/ieds_db_operations.py | 26 ++++++++++++++++++++++- lambdas/id_sync/src/record_processor.py | 3 ++- 2 files changed, 27 insertions(+), 2 deletions(-) diff --git a/lambdas/id_sync/src/ieds_db_operations.py b/lambdas/id_sync/src/ieds_db_operations.py index cfff62697..0a975f8be 100644 --- a/lambdas/id_sync/src/ieds_db_operations.py +++ b/lambdas/id_sync/src/ieds_db_operations.py @@ -2,6 +2,9 @@ from os_vars import get_ieds_table_name from common.aws_dynamodb import get_dynamodb_table from common.clients import logger, dynamodb_client +import json +import ast + from utils import make_status from exceptions.id_sync_exception import IdSyncException @@ -136,13 +139,34 @@ def extract_patient_resource_from_item(item: dict) -> dict | None: Extract a Patient resource dict from an IEDS database. """ patient_resource = item.get("Resource", None) + logger.info(f"patient_resource (raw): {patient_resource}") + + # Accept either a dict (preferred) or a JSON / Python-literal string + if isinstance(patient_resource, str): + # Try JSON first, then fall back to ast.literal_eval for single-quotes + try: + patient_resource_parsed = json.loads(patient_resource) + except Exception: + try: + patient_resource_parsed = ast.literal_eval(patient_resource) + except Exception: + logger.debug("extract_patient_resource_from_item: Resource is a string but could not be parsed") + return None + patient_resource = patient_resource_parsed + if not isinstance(patient_resource, dict): return None - for response in patient_resource.get("contained", []): + # The Patient resource may be nested under 'contained' or be the resource itself + contained = patient_resource.get("contained") or [] + for response in contained: if isinstance(response, dict) and response.get("resourceType") == "Patient": return response + # Fallback: if the resource is itself a Patient, return it + if patient_resource.get("resourceType") == "Patient": + return patient_resource + return None diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 992558760..4074ebb07 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -71,6 +71,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_count = 0 discarded_records = [] for detail in ieds_resources: + logger.info("Processing IEDS record: %s", detail) if demographics_match(pds_patient_resource, detail): matching_records.append(detail) else: @@ -79,7 +80,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: if not matching_records: logger.info("No records matched PDS demographics: %d\nDiscarded:\n%s", discarded_count, - json.dumps(discarded_records, indent=2)) + json.dumps(discarded_records, indent=2), default=str) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( From df943c8e1a147d930313721e2ad97b3bc51fbe09 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 01:53:01 +0100 Subject: [PATCH 18/25] reverting some changes --- lambdas/id_sync/src/id_sync.py | 3 --- lambdas/id_sync/src/ieds_db_operations.py | 2 +- lambdas/id_sync/src/pds_details.py | 1 - lambdas/id_sync/src/record_processor.py | 5 +---- lambdas/shared/src/common/clients.py | 14 ++------------ lambdas/shared/tests/test_common/test_clients.py | 2 +- 6 files changed, 5 insertions(+), 22 deletions(-) diff --git a/lambdas/id_sync/src/id_sync.py b/lambdas/id_sync/src/id_sync.py index 4d24e46c5..ef9b5f595 100644 --- a/lambdas/id_sync/src/id_sync.py +++ b/lambdas/id_sync/src/id_sync.py @@ -24,9 +24,6 @@ def handler(event_data: Dict[str, Any], _context) -> Dict[str, Any]: logger.info("id_sync processing event with %d records", len(records)) - # Use explicit loops instead of list comprehensions so we can more - # easily inspect intermediate results and avoid building temporary - # comprehension constructs. results = [] nhs_numbers = [] error_count = 0 diff --git a/lambdas/id_sync/src/ieds_db_operations.py b/lambdas/id_sync/src/ieds_db_operations.py index 0a975f8be..f5779cf60 100644 --- a/lambdas/id_sync/src/ieds_db_operations.py +++ b/lambdas/id_sync/src/ieds_db_operations.py @@ -22,7 +22,7 @@ def get_ieds_table(): def ieds_update_patient_id(old_id: str, new_id: str, items_to_update: list | None = None) -> dict: - """Update the patient ID in the IEDS table.""" + """Update the patient ID (new NHS number) in the IEDS table.""" logger.info(f"ieds_update_patient_id. Update patient ID from {old_id} to {new_id}") if not old_id or not new_id or not old_id.strip() or not new_id.strip(): return make_status("Old ID and New ID cannot be empty", old_id, "error") diff --git a/lambdas/id_sync/src/pds_details.py b/lambdas/id_sync/src/pds_details.py index e9af7601a..d0d5f4074 100644 --- a/lambdas/id_sync/src/pds_details.py +++ b/lambdas/id_sync/src/pds_details.py @@ -43,7 +43,6 @@ def pds_get_patient_id(nhs_number: str) -> str: :return: PDS patient ID """ try: - logger.info(f"get_pds_patient_id. nhs_number: {nhs_number}") patient_details = pds_get_patient_details(nhs_number) if not patient_details: return None diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 4074ebb07..f2aadc68b 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -69,18 +69,15 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: # Compare demographics from PDS to each IEDS item, keep only matching records matching_records = [] discarded_count = 0 - discarded_records = [] for detail in ieds_resources: logger.info("Processing IEDS record: %s", detail) if demographics_match(pds_patient_resource, detail): matching_records.append(detail) else: discarded_count += 1 - discarded_records.append(detail) if not matching_records: - logger.info("No records matched PDS demographics: %d\nDiscarded:\n%s", discarded_count, - json.dumps(discarded_records, indent=2), default=str) + logger.info("No records matched PDS demographics: %d", discarded_count,) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( diff --git a/lambdas/shared/src/common/clients.py b/lambdas/shared/src/common/clients.py index 6bb77434b..501418c12 100644 --- a/lambdas/shared/src/common/clients.py +++ b/lambdas/shared/src/common/clients.py @@ -2,19 +2,9 @@ import logging from boto3 import client as boto3_client, resource as boto3_resource +logging.basicConfig(level=logging.INFO) logger = logging.getLogger() -logger.setLevel(logging.INFO) # Root logger level - -if logger.hasHandlers(): - logger.handlers.clear() - -console = logging.StreamHandler() -console.setLevel(logging.INFO) # Handler must also allow INFO logs - -formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s') -console.setFormatter(formatter) - -logger.addHandler(console) +logger.setLevel(logging.INFO) STREAM_NAME = os.getenv("SPLUNK_FIREHOSE_NAME", "firehose-name-not-defined") CONFIG_BUCKET_NAME = os.getenv("CONFIG_BUCKET_NAME", "variconfig-bucketable-not-defined") diff --git a/lambdas/shared/tests/test_common/test_clients.py b/lambdas/shared/tests/test_common/test_clients.py index d9680a047..0adb21eb0 100644 --- a/lambdas/shared/tests/test_common/test_clients.py +++ b/lambdas/shared/tests/test_common/test_clients.py @@ -58,4 +58,4 @@ def test_logger_is_initialized(self): def test_logger_set_level(self): """Test that logger level is set to INFO""" - self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) + self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) \ No newline at end of file From 2df8adbf9c38e30939e52ded28c7976b11290e4c Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 01:56:34 +0100 Subject: [PATCH 19/25] fix lint issues --- lambdas/shared/tests/test_common/test_clients.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lambdas/shared/tests/test_common/test_clients.py b/lambdas/shared/tests/test_common/test_clients.py index 0adb21eb0..d9680a047 100644 --- a/lambdas/shared/tests/test_common/test_clients.py +++ b/lambdas/shared/tests/test_common/test_clients.py @@ -58,4 +58,4 @@ def test_logger_is_initialized(self): def test_logger_set_level(self): """Test that logger level is set to INFO""" - self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) \ No newline at end of file + self.mock_logger_instance.setLevel.assert_called_once_with(logging.INFO) From a95ae31189479636dead6aa4211e42e65b0268c1 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 02:05:59 +0100 Subject: [PATCH 20/25] fixes --- lambdas/id_sync/src/record_processor.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index f2aadc68b..237229363 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -30,7 +30,6 @@ def process_record(event_record: Dict[str, Any]) -> Dict[str, Any]: body = body_text nhs_number = body.get("subject") - # Reached logger.info("process record NHS number: %s", nhs_number) if nhs_number: return process_nhs_number(nhs_number) @@ -90,7 +89,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: return response -# Function to fetch PDS Patient details and IEDS Immunisation records. WORKS +# Function to fetch PDS Patient details and IEDS Immunisation records. def fetch_pds_and_ieds_resources(nhs_number: str): logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: From aae949a606826a70c3d1a8162c41a7bf8fde105c Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 03:14:35 +0100 Subject: [PATCH 21/25] improve coverage --- lambdas/id_sync/src/ieds_db_operations.py | 20 ++------- .../id_sync/tests/test_ieds_db_operations.py | 43 ++++++++++++++++++- 2 files changed, 46 insertions(+), 17 deletions(-) diff --git a/lambdas/id_sync/src/ieds_db_operations.py b/lambdas/id_sync/src/ieds_db_operations.py index f5779cf60..ce2137f36 100644 --- a/lambdas/id_sync/src/ieds_db_operations.py +++ b/lambdas/id_sync/src/ieds_db_operations.py @@ -3,8 +3,6 @@ from common.aws_dynamodb import get_dynamodb_table from common.clients import logger, dynamodb_client import json -import ast - from utils import make_status from exceptions.id_sync_exception import IdSyncException @@ -136,37 +134,27 @@ def paginate_items_for_patient_pk(patient_pk: str) -> list: def extract_patient_resource_from_item(item: dict) -> dict | None: """ - Extract a Patient resource dict from an IEDS database. + Extract a Patient resource from an IEDS database. """ patient_resource = item.get("Resource", None) logger.info(f"patient_resource (raw): {patient_resource}") - # Accept either a dict (preferred) or a JSON / Python-literal string if isinstance(patient_resource, str): - # Try JSON first, then fall back to ast.literal_eval for single-quotes try: patient_resource_parsed = json.loads(patient_resource) - except Exception: - try: - patient_resource_parsed = ast.literal_eval(patient_resource) - except Exception: - logger.debug("extract_patient_resource_from_item: Resource is a string but could not be parsed") - return None + except json.JSONDecodeError: + logger.warning("Failed to decode patient_resource JSON string") + return None patient_resource = patient_resource_parsed if not isinstance(patient_resource, dict): return None - # The Patient resource may be nested under 'contained' or be the resource itself contained = patient_resource.get("contained") or [] for response in contained: if isinstance(response, dict) and response.get("resourceType") == "Patient": return response - # Fallback: if the resource is itself a Patient, return it - if patient_resource.get("resourceType") == "Patient": - return patient_resource - return None diff --git a/lambdas/id_sync/tests/test_ieds_db_operations.py b/lambdas/id_sync/tests/test_ieds_db_operations.py index 6a9d956c5..b4a55060e 100644 --- a/lambdas/id_sync/tests/test_ieds_db_operations.py +++ b/lambdas/id_sync/tests/test_ieds_db_operations.py @@ -1,10 +1,51 @@ import unittest + +from ieds_db_operations import extract_patient_resource_from_item from unittest.mock import patch, MagicMock from exceptions.id_sync_exception import IdSyncException - import ieds_db_operations +class TestExtractPatientResourceFromItem(unittest.TestCase): + + def test_extract_from_dict_with_contained_patient(self): + item = { + "Resource": { + "resourceType": "Immunization", + "contained": [ + {"resourceType": "Patient", "id": "P1", "name": [{"family": "Doe"}]} + ], + } + } + + patient = extract_patient_resource_from_item(item) + self.assertIsNotNone(patient) + self.assertIsInstance(patient, dict) + self.assertEqual(patient.get("resourceType"), "Patient") + self.assertEqual(patient.get("id"), "P1") + + def test_extract_from_json_string(self): + resource_json = '{"resourceType": "Immunization", "contained": [{"resourceType": "Patient", "id": "P2"}]}' + item = {"Resource": resource_json} + + patient = extract_patient_resource_from_item(item) + self.assertIsNotNone(patient) + self.assertEqual(patient.get("id"), "P2") + + def test_malformed_json_string_returns_none(self): + # A malformed JSON string should not raise, but return None + item = {"Resource": "{not: valid json}"} + self.assertIsNone(extract_patient_resource_from_item(item)) + + def test_non_dict_resource_returns_none(self): + item = {"Resource": 12345} + self.assertIsNone(extract_patient_resource_from_item(item)) + + def test_missing_resource_returns_none(self): + item = {} + self.assertIsNone(extract_patient_resource_from_item(item)) + + class TestIedsDbOperations(unittest.TestCase): """Base test class for IEDS database operations""" From ae64fdee0166afe4f9e733024bea275d8a4c190d Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 09:25:43 +0100 Subject: [PATCH 22/25] remove PII logs --- lambdas/id_sync/src/record_processor.py | 22 ++++++++-------------- lambdas/id_sync/tests/test_id_sync.py | 2 +- 2 files changed, 9 insertions(+), 15 deletions(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 237229363..9d4d1a725 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -57,8 +57,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) return make_status(str(e), nhs_number, "error") - logger.info("Fetched PDS details: %s", pds_patient_resource) - logger.info("Fetched IEDS resources: %s", ieds_resources) + logger.debug("Fetched PDS details: %s", pds_patient_resource) logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources) if ieds_resources else 0) if not ieds_resources: @@ -76,7 +75,7 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: discarded_count += 1 if not matching_records: - logger.info("No records matched PDS demographics: %d", discarded_count,) + logger.info("No records matched PDS demographics: %d", discarded_count) return make_status("No records matched PDS demographics; update skipped", nhs_number) response = ieds_update_patient_id( @@ -94,7 +93,6 @@ def fetch_pds_and_ieds_resources(nhs_number: str): logger.info("fetch_pds_and_ieds_resources: fetching for %s", nhs_number) try: pds = pds_get_patient_details(nhs_number) - logger.info("fetch_pds_resources: fetching for %s", pds) except Exception as e: logger.exception("fetch_pds_and_ieds_resources: failed to fetch PDS details for %s", nhs_number) raise RuntimeError("Failed to fetch PDS details") from e @@ -105,9 +103,6 @@ def fetch_pds_and_ieds_resources(nhs_number: str): logger.exception("fetch_pds_and_ieds_resources: failed to fetch IEDS items for %s", nhs_number) raise RuntimeError("Failed to fetch IEDS items") from e - count = len(ieds) - logger.info("fetch_pds_and_ieds_resources: fetched PDS and %d IEDS items for %s", count, nhs_number) - logger.info("fetch_ieds_resources: %s", ieds) return pds, ieds @@ -146,7 +141,7 @@ def normalize_strings(item: Any) -> str | None: pds_name = normalize_strings(extract_normalized_name_from_patient(pds_details)) pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) - logger.info("demographics_match: demographics match for name=%s, gender=%s, birthDate=%s", + logger.debug("demographics_match: demographics match for name=%s, gender=%s, birthDate=%s", pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item @@ -159,27 +154,26 @@ def normalize_strings(item: Any) -> str | None: ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) - logger.info("demographics_match: demographics match for %s", patient) + logger.debug("demographics_match: demographics match for %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]): - logger.info("demographics_match: missing required demographics") + logger.debug("demographics_match: missing required demographics") return False # Compare fields if pds_birth != ieds_birth: - logger.info("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) + logger.debug("demographics_match: birthDate mismatch %s != %s", pds_birth, ieds_birth) return False if pds_gender != ieds_gender: - logger.info("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) + logger.debug("demographics_match: gender mismatch %s != %s", pds_gender, ieds_gender) return False if pds_name != ieds_name: - logger.info("demographics_match: name mismatch %s != %s", pds_name, ieds_name) + logger.debug("demographics_match: name mismatch %s != %s", pds_name, ieds_name) return False - logger.info("demographics_match: demographics match for %s", patient) return True except Exception: logger.exception("demographics_match: comparison failed with exception") diff --git a/lambdas/id_sync/tests/test_id_sync.py b/lambdas/id_sync/tests/test_id_sync.py index f438d87f0..d85b0293a 100644 --- a/lambdas/id_sync/tests/test_id_sync.py +++ b/lambdas/id_sync/tests/test_id_sync.py @@ -256,7 +256,7 @@ def test_handler_process_record_missing_nhs_number(self): exception = exception_context.exception self.assertIsInstance(exception, IdSyncException) - self.assertEqual(exception.nhs_numbers, []) # Since no nhs_number was collected + self.assertEqual(exception.nhs_numbers, []) self.assertEqual(exception.message, "Processed 1 records with 1 errors") self.mock_logger.exception.assert_called_once_with(f"id_sync error: {exception.message}") From 837ba1e0a114f52ac86c38beb9c9e012452b2a4c Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 09:30:16 +0100 Subject: [PATCH 23/25] fix lint issues3 --- lambdas/id_sync/src/record_processor.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index 9d4d1a725..fe6e466b6 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -142,7 +142,7 @@ def normalize_strings(item: Any) -> str | None: pds_gender = normalize_strings(pds_details.get("gender")) pds_birth = normalize_strings(pds_details.get("birthDate")) logger.debug("demographics_match: demographics match for name=%s, gender=%s, birthDate=%s", - pds_name, pds_gender, pds_birth) + pds_name, pds_gender, pds_birth) # Retrieve patient resource from IEDS item patient = extract_patient_resource_from_item(ieds_item) From 97d7d0a6572d220e5599e324277ebc1f79e3b5ae Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 10:38:30 +0100 Subject: [PATCH 24/25] remove pii2 --- lambdas/id_sync/src/ieds_db_operations.py | 1 - 1 file changed, 1 deletion(-) diff --git a/lambdas/id_sync/src/ieds_db_operations.py b/lambdas/id_sync/src/ieds_db_operations.py index ce2137f36..86072551f 100644 --- a/lambdas/id_sync/src/ieds_db_operations.py +++ b/lambdas/id_sync/src/ieds_db_operations.py @@ -137,7 +137,6 @@ def extract_patient_resource_from_item(item: dict) -> dict | None: Extract a Patient resource from an IEDS database. """ patient_resource = item.get("Resource", None) - logger.info(f"patient_resource (raw): {patient_resource}") if isinstance(patient_resource, str): try: From 3335d7a0dd71575c7e5ade1e808a5fed2850f6c9 Mon Sep 17 00:00:00 2001 From: Akol125 Date: Thu, 25 Sep 2025 11:57:40 +0100 Subject: [PATCH 25/25] remove pii logs --- lambdas/id_sync/src/ieds_db_operations.py | 2 +- lambdas/id_sync/src/record_processor.py | 2 -- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/lambdas/id_sync/src/ieds_db_operations.py b/lambdas/id_sync/src/ieds_db_operations.py index 86072551f..e918e6dae 100644 --- a/lambdas/id_sync/src/ieds_db_operations.py +++ b/lambdas/id_sync/src/ieds_db_operations.py @@ -142,7 +142,7 @@ def extract_patient_resource_from_item(item: dict) -> dict | None: try: patient_resource_parsed = json.loads(patient_resource) except json.JSONDecodeError: - logger.warning("Failed to decode patient_resource JSON string") + logger.error("Failed to decode patient_resource JSON string") return None patient_resource = patient_resource_parsed diff --git a/lambdas/id_sync/src/record_processor.py b/lambdas/id_sync/src/record_processor.py index fe6e466b6..67263ea06 100644 --- a/lambdas/id_sync/src/record_processor.py +++ b/lambdas/id_sync/src/record_processor.py @@ -57,7 +57,6 @@ def process_nhs_number(nhs_number: str) -> Dict[str, Any]: logger.exception("process_nhs_number: failed to fetch demographic details: %s", e) return make_status(str(e), nhs_number, "error") - logger.debug("Fetched PDS details: %s", pds_patient_resource) logger.info("Fetched IEDS resources. IEDS count: %d", len(ieds_resources) if ieds_resources else 0) if not ieds_resources: @@ -154,7 +153,6 @@ def normalize_strings(item: Any) -> str | None: ieds_name = normalize_strings(extract_normalized_name_from_patient(patient)) ieds_gender = normalize_strings(patient.get("gender")) ieds_birth = normalize_strings(patient.get("birthDate")) - logger.debug("demographics_match: demographics match for %s", patient) # All required fields must be present if not all([pds_name, pds_gender, pds_birth, ieds_name, ieds_gender, ieds_birth]):