From 983fa835b4010cb514d128564bfb2b8f729094dc Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Mon, 18 May 2026 16:42:00 +0100 Subject: [PATCH 1/5] CCM-15342: Configure python lambda to output level https://www.structlog.org/en/21.4.0/standard-library.html#stdlib-config --- utils/py-utils/dl_utils/log_config.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/utils/py-utils/dl_utils/log_config.py b/utils/py-utils/dl_utils/log_config.py index 11baa2e39..563513d2f 100644 --- a/utils/py-utils/dl_utils/log_config.py +++ b/utils/py-utils/dl_utils/log_config.py @@ -1,4 +1,4 @@ import structlog -structlog.configure(processors=[structlog.processors.JSONRenderer()]) +structlog.configure(processors=[structlog.stdlib.add_log_level, structlog.processors.JSONRenderer()]) log = structlog.get_logger() From a8cf1cc6caab91eba84b0eeb00153afb1344ce5e Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Tue, 19 May 2026 09:22:41 +0100 Subject: [PATCH 2/5] CCM-15342: Updating logs --- .../mesh-download/mesh_download/processor.py | 28 ++++++++----------- lambdas/mesh-poll/mesh_poll/processor.py | 3 +- 2 files changed, 14 insertions(+), 17 deletions(-) diff --git a/lambdas/mesh-download/mesh_download/processor.py b/lambdas/mesh-download/mesh_download/processor.py index 7800c0983..a892373c1 100644 --- a/lambdas/mesh-download/mesh_download/processor.py +++ b/lambdas/mesh-download/mesh_download/processor.py @@ -28,7 +28,7 @@ def __init__(self, **kwargs): def process_sqs_message(self, sqs_record): try: validated_event = self._parse_and_validate_event(sqs_record) - logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId) + logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId, message_reference=validated_event.data.messageReference, sender_id=validated_event.data.senderId) logger.info("Processing MESH download request") return self._handle_download(validated_event, logger) @@ -88,7 +88,6 @@ def _handle_download(self, event, logger): logger.info( "Retrieved MESH message", - sender=getattr(message, 'sender', ''), local_id=getattr(message, 'local_id', ''), workflow_id=getattr(message, 'workflow_id', ''), subject=getattr(message, 'subject', ''), @@ -96,15 +95,20 @@ def _handle_download(self, event, logger): ) content = message.read() - logger.info("Downloaded MESH message content") + logger.info( + "Downloaded MESH message content", + local_id=getattr(message, 'local_id', ''), + workflow_id=getattr(message, 'workflow_id', ''), + subject=getattr(message, 'subject', ''), + message_type=getattr(message, 'message_type', '') + ) try: self._validate_fhir_content(content) except Exception as e: logger.error( "FHIR content is invalid", - error=str(e), - mesh_message_id=data.meshMessageId + error=str(e) ) self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_005') message.acknowledge() @@ -121,9 +125,7 @@ def _handle_download(self, event, logger): ) except DocumentAlreadyExistsInternalRetryError: logger.warning( - "Internal retry detected. Message already stored with same meshMessageId, skipping", - mesh_message_id=data.meshMessageId, - message_reference=data.messageReference + "Internal retry detected. Message already stored with same meshMessageId, skipping" ) self.__internal_duplicate_download_metric.record(1) message.acknowledge() @@ -131,9 +133,7 @@ def _handle_download(self, event, logger): return 'skipped' except DocumentAlreadyExistsError: logger.warning( - "Trust duplicate detected. Same senderId + messageReference but different meshMessageId", - mesh_message_id=data.meshMessageId, - message_reference=data.messageReference + "Trust duplicate detected. Same senderId + messageReference but different meshMessageId" ) self.__trust_duplicate_download_metric.record(1) self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_004') @@ -199,9 +199,7 @@ def _publish_downloaded_event(self, incoming_event, message_uri): self.__log.info( "Published MESHInboxMessageDownloaded event", - sender_id=incoming_event.data.senderId, message_uri=message_uri, - message_reference=incoming_event.data.messageReference ) def _publish_message_invalid_event(self, incoming_event, failure_code: str): @@ -235,7 +233,5 @@ def _publish_message_invalid_event(self, incoming_event, failure_code: str): raise RuntimeError(msg) self.__log.info( - "Published MESHInboxMessageInvalid event", - sender_id=incoming_event.data.senderId, - message_reference=incoming_event.data.messageReference + "Published MESHInboxMessageInvalid event" ) diff --git a/lambdas/mesh-poll/mesh_poll/processor.py b/lambdas/mesh-poll/mesh_poll/processor.py index 9f9b7e360..75d2d5f83 100644 --- a/lambdas/mesh-poll/mesh_poll/processor.py +++ b/lambdas/mesh-poll/mesh_poll/processor.py @@ -197,7 +197,8 @@ def _publish_mesh_inbox_message_received_event(self, event_detail): self.__log.info("Published MESHInboxMessageReceived event", mesh_message_id=event_detail["data"]["meshMessageId"], - sender_id=event_detail["data"]["senderId"]) + sender_id=event_detail["data"]["senderId"], + message_reference=event_detail["data"]["messageReference"]) def _publish_mesh_inbox_message_invalid_event(self, event_detail): """ From 06aab81f9021e8009a879525d4812b6aff608afa Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Tue, 19 May 2026 12:14:39 +0100 Subject: [PATCH 3/5] CCM-15342: logs --- .../mesh_acknowledge/acknowledger.py | 4 ++-- .../mesh-download/mesh_download/processor.py | 23 +++++++++++-------- .../src/__tests__/apis/sqs-handler.test.ts | 5 ++++ .../pdm-poll-lambda/src/apis/sqs-handler.ts | 5 ++++ lambdas/pdm-poll-lambda/src/app/pdm.ts | 12 +++++++++- .../src/__tests__/app/upload-to-pdm.test.ts | 3 +++ .../src/app/upload-to-pdm.ts | 2 ++ .../src/__tests__/apis/sqs-handler.test.ts | 2 ++ .../print-analyser/src/apis/sqs-handler.ts | 3 ++- 9 files changed, 45 insertions(+), 14 deletions(-) diff --git a/lambdas/mesh-acknowledge/mesh_acknowledge/acknowledger.py b/lambdas/mesh-acknowledge/mesh_acknowledge/acknowledger.py index 2d4d05efb..722b949ce 100644 --- a/lambdas/mesh-acknowledge/mesh_acknowledge/acknowledger.py +++ b/lambdas/mesh-acknowledge/mesh_acknowledge/acknowledger.py @@ -59,7 +59,7 @@ def acknowledge_message(self, "Acknowledged MESH message", mesh_mailbox_id=mailbox_id, mesh_message_id=message_id, - mesh_message_reference=message_reference, + message_reference=message_reference, ack_message_id=ack_message_id ) @@ -70,7 +70,7 @@ def acknowledge_message(self, "Failed to acknowledge MESH message", mesh_mailbox_id=mailbox_id, mesh_message_id=message_id, - mesh_message_reference=message_reference, + message_reference=message_reference, error=str(e) ) diff --git a/lambdas/mesh-download/mesh_download/processor.py b/lambdas/mesh-download/mesh_download/processor.py index a892373c1..28d5944d7 100644 --- a/lambdas/mesh-download/mesh_download/processor.py +++ b/lambdas/mesh-download/mesh_download/processor.py @@ -28,7 +28,9 @@ def __init__(self, **kwargs): def process_sqs_message(self, sqs_record): try: validated_event = self._parse_and_validate_event(sqs_record) - logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId, message_reference=validated_event.data.messageReference, sender_id=validated_event.data.senderId) + logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId, + message_reference=validated_event.data.messageReference, + sender_id=validated_event.data.senderId) logger.info("Processing MESH download request") return self._handle_download(validated_event, logger) @@ -110,7 +112,7 @@ def _handle_download(self, event, logger): "FHIR content is invalid", error=str(e) ) - self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_005') + self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_005', logger=logger) message.acknowledge() logger.info("Acknowledged message") return @@ -136,14 +138,15 @@ def _handle_download(self, event, logger): "Trust duplicate detected. Same senderId + messageReference but different meshMessageId" ) self.__trust_duplicate_download_metric.record(1) - self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_004') + self._publish_message_invalid_event(incoming_event=event, failure_code='DL_CLIV_004', logger=logger) message.acknowledge() logger.info("Acknowledged message") return 'duplicate' self._publish_downloaded_event( incoming_event=event, - message_uri=uri + message_uri=uri, + logger=logger ) self.__download_metric.record(1) message.acknowledge() @@ -165,7 +168,7 @@ def _store_message_content(self, sender_id, message_reference, mesh_message_id, return message_uri - def _publish_downloaded_event(self, incoming_event, message_uri): + def _publish_downloaded_event(self, incoming_event, message_uri, logger): """ Publishes a MESHInboxMessageDownloaded event. """ @@ -194,15 +197,15 @@ def _publish_downloaded_event(self, incoming_event, message_uri): failed = self.__event_publisher.send_events([cloud_event], MESHInboxMessageDownloaded) if failed: msg = f"Failed to publish MESHInboxMessageDownloaded event: {failed}" - self.__log.error(msg, failed_count=len(failed)) + logger.error(msg, failed_count=len(failed)) raise RuntimeError(msg) - self.__log.info( + logger.info( "Published MESHInboxMessageDownloaded event", message_uri=message_uri, ) - def _publish_message_invalid_event(self, incoming_event, failure_code: str): + def _publish_message_invalid_event(self, incoming_event, failure_code: str, logger): """ Publishes a MESHInboxMessageInvalid event. """ @@ -229,9 +232,9 @@ def _publish_message_invalid_event(self, incoming_event, failure_code: str): failed = self.__event_publisher.send_events([cloud_event], MESHInboxMessageInvalid) if failed: msg = f"Failed to publish MESHInboxMessageInvalid event: {failed}" - self.__log.error(msg, failed_count=len(failed)) + logger.error(msg, failed_count=len(failed)) raise RuntimeError(msg) - self.__log.info( + logger.info( "Published MESHInboxMessageInvalid event" ) diff --git a/lambdas/pdm-poll-lambda/src/__tests__/apis/sqs-handler.test.ts b/lambdas/pdm-poll-lambda/src/__tests__/apis/sqs-handler.test.ts index 271cfdbd1..399d93d92 100644 --- a/lambdas/pdm-poll-lambda/src/__tests__/apis/sqs-handler.test.ts +++ b/lambdas/pdm-poll-lambda/src/__tests__/apis/sqs-handler.test.ts @@ -254,6 +254,10 @@ describe('SQS Handler', () => { expect(logger.warn).toHaveBeenCalledWith({ err: 'PDM error', description: 'Failed processing message', + messageId: '1', + messageReference: pdmResourceSubmittedEvent.data.messageReference, + senderId: pdmResourceSubmittedEvent.data.senderId, + resourceId: pdmResourceSubmittedEvent.data.resourceId, }); expect(logger.info).toHaveBeenCalledWith( @@ -276,6 +280,7 @@ describe('SQS Handler', () => { `Unexpected token 'o', "not-json" is not valid JSON`, ), description: 'Error parsing SQS record', + messageId: '1', }); expect(logger.info).toHaveBeenCalledWith( diff --git a/lambdas/pdm-poll-lambda/src/apis/sqs-handler.ts b/lambdas/pdm-poll-lambda/src/apis/sqs-handler.ts index dc83e6b7d..81f709388 100644 --- a/lambdas/pdm-poll-lambda/src/apis/sqs-handler.ts +++ b/lambdas/pdm-poll-lambda/src/apis/sqs-handler.ts @@ -55,6 +55,7 @@ function validateRecord( logger.warn({ err: error, description: 'Error parsing SQS record', + messageId, }); return null; } @@ -184,6 +185,10 @@ export const createHandler = ({ logger.warn({ err: error.message, description: 'Failed processing message', + messageId: validatedRecord.messageId, + messageReference: validatedRecord.event.data.messageReference, + senderId: validatedRecord.event.data.senderId, + resourceId: validatedRecord.event.data.resourceId, }); batchItemFailures.push({ itemIdentifier: validatedRecord.messageId }); } diff --git a/lambdas/pdm-poll-lambda/src/app/pdm.ts b/lambdas/pdm-poll-lambda/src/app/pdm.ts index a26e1e035..d240b1b5c 100644 --- a/lambdas/pdm-poll-lambda/src/app/pdm.ts +++ b/lambdas/pdm-poll-lambda/src/app/pdm.ts @@ -32,7 +32,13 @@ export class Pdm { async poll(item: any): Promise { try { - this.logger.info(item); + this.logger.info({ + description: 'Polling PDM for document resource', + messageId: item.messageId, + senderId: item.data.senderId, + messageReference: item.data.messageReference, + resourceId: item.data.resourceId, + }); const response = await this.pdmClient.getDocumentReference( item.data.resourceId, @@ -59,6 +65,10 @@ export class Pdm { } catch (error) { this.logger.error({ description: 'Error getting document resource from PDM', + messageId: item.messageId, + senderId: item.data.senderId, + messageReference: item.data.messageReference, + resourceId: item.data.resourceId, err: error, }); diff --git a/lambdas/pdm-uploader-lambda/src/__tests__/app/upload-to-pdm.test.ts b/lambdas/pdm-uploader-lambda/src/__tests__/app/upload-to-pdm.test.ts index be4f14b3f..117456499 100644 --- a/lambdas/pdm-uploader-lambda/src/__tests__/app/upload-to-pdm.test.ts +++ b/lambdas/pdm-uploader-lambda/src/__tests__/app/upload-to-pdm.test.ts @@ -96,6 +96,7 @@ describe('UploadToPdm', () => { name: error.name, }), messageReference: mockEvent.data.messageReference, + senderId: mockEvent.data.senderId, }); expect(mockPdmClient.createDocumentReference).not.toHaveBeenCalled(); }); @@ -115,6 +116,7 @@ describe('UploadToPdm', () => { message: error.message, }), messageReference: mockEvent.data.messageReference, + senderId: mockEvent.data.senderId, }); expect(mockPdmClient.createDocumentReference).not.toHaveBeenCalled(); }); @@ -134,6 +136,7 @@ describe('UploadToPdm', () => { name: error.name, }), messageReference: mockEvent.data.messageReference, + senderId: mockEvent.data.senderId, }); }); }); diff --git a/lambdas/pdm-uploader-lambda/src/app/upload-to-pdm.ts b/lambdas/pdm-uploader-lambda/src/app/upload-to-pdm.ts index 57fc37eb6..54cfdc2a9 100644 --- a/lambdas/pdm-uploader-lambda/src/app/upload-to-pdm.ts +++ b/lambdas/pdm-uploader-lambda/src/app/upload-to-pdm.ts @@ -28,6 +28,7 @@ export class UploadToPdm { description: 'Successfully sent request to PDM', eventId: event.id, messageReference, + senderId: event.data.senderId, resourceId: response.id, }); @@ -36,6 +37,7 @@ export class UploadToPdm { this.logger.error({ description: 'Error sending request to PDM', messageReference: event.data.messageReference, + senderId: event.data.senderId, err: error instanceof Error ? { message: error.message, name: error.name, stack: error.stack } diff --git a/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts b/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts index a84fa41af..a139b5a13 100644 --- a/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts +++ b/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts @@ -125,6 +125,8 @@ describe('SQS Handler', () => { expect(logger.child).toHaveBeenCalledWith({ messageReference: fileSafeEvent.data.messageReference, + senderId: fileSafeEvent.data.senderId, + messageId: '1', }); expect(mockChildLogger.error).toHaveBeenCalledWith({ err: expect.arrayContaining([ diff --git a/lambdas/print-analyser/src/apis/sqs-handler.ts b/lambdas/print-analyser/src/apis/sqs-handler.ts index f7c1a7c05..f5d588228 100644 --- a/lambdas/print-analyser/src/apis/sqs-handler.ts +++ b/lambdas/print-analyser/src/apis/sqs-handler.ts @@ -40,7 +40,8 @@ function validateRecord( const messageReference = sqsEventDetail?.data?.messageReference || 'not present'; - const childLogger = logger.child({ messageReference }); + const senderId = sqsEventDetail?.data?.senderId || 'not present'; + const childLogger = logger.child({ messageReference, senderId, messageId }); validateFileSafe(sqsEventDetail, childLogger); From 0b841ae7389b9def90d1c361b597be1738b0e371 Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Wed, 20 May 2026 11:26:04 +0100 Subject: [PATCH 4/5] npm update @nhsdigital/nhs-notify-event-schemas-supplier-api --- package-lock.json | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/package-lock.json b/package-lock.json index c9c8ebcfe..e5f263e90 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9995,9 +9995,9 @@ } }, "node_modules/@nhsdigital/nhs-notify-event-schemas-supplier-api": { - "version": "1.0.18", - "resolved": "https://npm.pkg.github.com/download/@nhsdigital/nhs-notify-event-schemas-supplier-api/1.0.18/e81996aca0271b686b521dec9ec33a8735b351b5", - "integrity": "sha512-+PJ4XSWYZ+hZ2jhbvt2Wpi0QzPAYug2bnl6NrdEQmcURVhAh5JxJkuQ7OayHXFS2A7hiEF+4nJnS6B0ZLiWSgw==", + "version": "1.0.19", + "resolved": "https://npm.pkg.github.com/download/@nhsdigital/nhs-notify-event-schemas-supplier-api/1.0.19/46a72901639161b3dafa0d47af70d1e9ec8f4686", + "integrity": "sha512-DqS0GmQ64jfLuKDerUuUFMZEdTjsEtpHROoMeXsjc54zELH4RLmZTok/gJozDXqSpn0twWPLu8QlP7bss7tmXQ==", "license": "MIT", "dependencies": { "@asyncapi/bundler": "^0.6.4", From a1e189a9553ebf06df2c1d027c7c98e9aa880d22 Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Wed, 20 May 2026 17:33:36 +0100 Subject: [PATCH 5/5] CCM-15342: extra logging --- .../src/__tests__/apis/sqs-handler.test.ts | 2 ++ lambdas/file-scanner-lambda/src/apis/sqs-handler.ts | 2 ++ lambdas/mesh-download/mesh_download/processor.py | 9 ++++++--- .../move-scanned-files-lambda/src/apis/sqs-handler.ts | 4 ++++ 4 files changed, 14 insertions(+), 3 deletions(-) diff --git a/lambdas/file-scanner-lambda/src/__tests__/apis/sqs-handler.test.ts b/lambdas/file-scanner-lambda/src/__tests__/apis/sqs-handler.test.ts index 414e14a50..d080626b4 100644 --- a/lambdas/file-scanner-lambda/src/__tests__/apis/sqs-handler.test.ts +++ b/lambdas/file-scanner-lambda/src/__tests__/apis/sqs-handler.test.ts @@ -112,6 +112,7 @@ describe('SQS Handler', () => { description: 'Processing ItemDequeued event', messageReference: 'ref-001', senderId: 'SENDER_001', + messageId: 'msg-001', }), ); @@ -347,6 +348,7 @@ describe('SQS Handler', () => { expect(mockLogger.warn).toHaveBeenCalledWith( expect.objectContaining({ description: 'Error parsing SQS record', + messageId: 'msg-001', }), ); }); diff --git a/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts b/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts index 7f438f5d3..c292b5f4a 100644 --- a/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts +++ b/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts @@ -33,6 +33,7 @@ function validateRecord( logger.warn({ err: error, description: 'Error parsing SQS record', + messageId, }); return null; } @@ -49,6 +50,7 @@ async function processRecord( eventId: event.id, messageReference: event.data.messageReference, senderId: event.data.senderId, + messageId: validatedRecord.messageId, }); const result = await fileScanner.scanFile(event.data.messageUri, { diff --git a/lambdas/mesh-download/mesh_download/processor.py b/lambdas/mesh-download/mesh_download/processor.py index 28d5944d7..38d30cdb7 100644 --- a/lambdas/mesh-download/mesh_download/processor.py +++ b/lambdas/mesh-download/mesh_download/processor.py @@ -26,11 +26,13 @@ def __init__(self, **kwargs): self.__storage_bucket = self.__config.transactional_data_bucket def process_sqs_message(self, sqs_record): + sqs_message_id = sqs_record.get('messageId') try: - validated_event = self._parse_and_validate_event(sqs_record) + validated_event = self._parse_and_validate_event(sqs_record, sqs_message_id) logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId, message_reference=validated_event.data.messageReference, - sender_id=validated_event.data.senderId) + sender_id=validated_event.data.senderId, + sqs_message_id=sqs_message_id) logger.info("Processing MESH download request") return self._handle_download(validated_event, logger) @@ -43,7 +45,7 @@ def process_sqs_message(self, sqs_record): ) raise - def _parse_and_validate_event(self, sqs_record): + def _parse_and_validate_event(self, sqs_record, sqs_message_id) -> MESHInboxMessageReceived: message_body = json.loads(sqs_record['body']) event_detail = message_body.get('detail', {}) @@ -55,6 +57,7 @@ def _parse_and_validate_event(self, sqs_record): self.__log.error( "CloudEvent validation failed", validation_errors=str(e), + sqs_message_id=sqs_message_id, event_detail=event_detail ) raise diff --git a/lambdas/move-scanned-files-lambda/src/apis/sqs-handler.ts b/lambdas/move-scanned-files-lambda/src/apis/sqs-handler.ts index 11a2b9399..81753cbdb 100644 --- a/lambdas/move-scanned-files-lambda/src/apis/sqs-handler.ts +++ b/lambdas/move-scanned-files-lambda/src/apis/sqs-handler.ts @@ -55,6 +55,10 @@ export const createHandler = ({ } } else { // there was something wrong with the event + logger.warn({ + description: 'Failed to process event', + messageId: sqsRecord.messageId, + }); batchItemFailures.push({ itemIdentifier: sqsRecord.messageId }); } } catch (error: any) {