From 91a50cf261a3416a6c66543bd46c224d531178e5 Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Wed, 20 May 2026 14:22:17 +0100 Subject: [PATCH 1/2] CCM-15342: Set python lambdas the log level --- package-lock.json | 6 +++--- utils/py-utils/dl_utils/log_config.py | 2 +- 2 files changed, 4 insertions(+), 4 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", 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 ec1517eae49b3b69b8a801b874977f424f0ae0bd Mon Sep 17 00:00:00 2001 From: Angel Pastor Date: Wed, 20 May 2026 15:24:28 +0100 Subject: [PATCH 2/2] CCM-15342: logging --- .../src/__tests__/apis/sqs-handler.test.ts | 20 +++++++++++++++---- .../src/apis/sqs-handler.ts | 20 +++++++++++++------ .../mesh_acknowledge/events.py | 8 ++------ .../mesh-download/mesh_download/processor.py | 11 +++++----- .../src/apis/sqs-handler.ts | 4 ++++ .../src/apis/sqs-trigger-lambda.ts | 2 ++ .../src/__tests__/apis/sqs-handler.test.ts | 4 ++++ .../pdm-poll-lambda/src/apis/sqs-handler.ts | 4 ++++ .../src/apis/sqs-trigger-lambda.ts | 4 ++++ .../src/__tests__/apis/sqs-handler.test.ts | 8 +++++--- .../print-analyser/src/apis/sqs-handler.ts | 18 +++++++++++------ .../src/apis/sqs-trigger-lambda.ts | 8 +++++++- .../src/apis/sqs-trigger-lambda.ts | 3 +++ .../report_sender/report_sender_processor.py | 16 ++++++++------- .../src/apis/sqs-trigger-lambda.ts | 1 + 15 files changed, 93 insertions(+), 38 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..9e8ca596f 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 @@ -8,6 +8,7 @@ import { EventPublisher, Logger } from 'utils'; const mockFileScanner = mockDeep(); const mockEventPublisher = mockDeep(); const mockLogger = mockDeep(); +const mockChildLogger = mockDeep(); const createSQSEvent = ( records: { @@ -68,6 +69,7 @@ describe('SQS Handler', () => { beforeEach(() => { jest.clearAllMocks(); + mockLogger.child.mockReturnValue(mockChildLogger); dependencies = { eventPublisher: mockEventPublisher, logger: mockLogger, @@ -107,9 +109,15 @@ describe('SQS Handler', () => { }), ); - expect(mockLogger.info).toHaveBeenCalledWith( + expect(mockChildLogger.info).toHaveBeenCalledWith( expect.objectContaining({ description: 'Processing ItemDequeued event', + }), + ); + + expect(mockLogger.child).toHaveBeenCalledWith( + expect.objectContaining({ + messageId: 'msg-001', messageReference: 'ref-001', senderId: 'SENDER_001', }), @@ -192,9 +200,14 @@ describe('SQS Handler', () => { { itemIdentifier: 'msg-001' }, ]); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockChildLogger.error).toHaveBeenCalledWith( expect.objectContaining({ description: 'Error processing record', + }), + ); + + expect(mockLogger.child).toHaveBeenCalledWith( + expect.objectContaining({ messageId: 'msg-001', }), ); @@ -300,11 +313,10 @@ describe('SQS Handler', () => { { itemIdentifier: 'msg-002' }, ]); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockChildLogger.error).toHaveBeenCalledWith( expect.objectContaining({ description: 'Error processing record', err: 'string error', - messageId: 'msg-002', }), ); }); diff --git a/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts b/lambdas/file-scanner-lambda/src/apis/sqs-handler.ts index 7f438f5d3..cf465fcae 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; } @@ -42,13 +43,16 @@ async function processRecord( validatedRecord: ValidatedRecord, { fileScanner, logger }: HandlerDependencies, ): Promise { - const { event } = validatedRecord; + const { event, messageId } = validatedRecord; + const recordLogger = logger.child({ + messageId, + messageReference: event.data.messageReference, + senderId: event.data.senderId, + }); - logger.info({ + recordLogger.info({ description: 'Processing ItemDequeued event', eventId: event.id, - messageReference: event.data.messageReference, - senderId: event.data.senderId, }); const result = await fileScanner.scanFile(event.data.messageUri, { @@ -82,7 +86,12 @@ export function createHandler(dependencies: HandlerDependencies) { try { await processRecord(validatedRecord, dependencies); } catch (error) { - logger.error({ + const recordLogger = logger.child({ + messageId: validatedRecord.messageId, + messageReference: validatedRecord.event.data.messageReference, + senderId: validatedRecord.event.data.senderId, + }); + recordLogger.error({ description: 'Error processing record', err: error instanceof Error @@ -92,7 +101,6 @@ export function createHandler(dependencies: HandlerDependencies) { stack: error.stack, } : error, - messageId: validatedRecord.messageId, }); itemFailures.push({ itemIdentifier: validatedRecord.messageId }); diff --git a/lambdas/mesh-acknowledge/mesh_acknowledge/events.py b/lambdas/mesh-acknowledge/mesh_acknowledge/events.py index 0a8d5fe81..ef825a55e 100644 --- a/lambdas/mesh-acknowledge/mesh_acknowledge/events.py +++ b/lambdas/mesh-acknowledge/mesh_acknowledge/events.py @@ -21,15 +21,13 @@ def parse_downloaded_event(sqs_record, logger) -> MESHInboxMessageDownloaded: except Exception as e: logger.error( "MESHInboxMessageDownloaded validation failed", - validation_errors=str(e), - event_detail=event_detail + validation_errors=str(e) ) raise ValueError( "Error processing MESHInboxMessageDownloaded event") from e except json.JSONDecodeError as e: logger.error( "Error parsing SQS record body as JSON", - body=sqs_record.get('body', ''), error=str(e) ) raise ValueError("Error parsing SQS record") from e @@ -47,15 +45,13 @@ def parse_invalid_event(sqs_record, logger) -> MESHInboxMessageInvalid: except Exception as e: logger.error( "MESHInboxMessageInvalid validation failed", - validation_errors=str(e), - event_detail=event_detail + validation_errors=str(e) ) raise ValueError( "Error processing MESHInboxMessageInvalid event") from e except json.JSONDecodeError as e: logger.error( "Error parsing SQS record body as JSON", - body=sqs_record.get('body', ''), error=str(e) ) raise ValueError("Error parsing SQS record") from e diff --git a/lambdas/mesh-download/mesh_download/processor.py b/lambdas/mesh-download/mesh_download/processor.py index 7800c0983..d595a9088 100644 --- a/lambdas/mesh-download/mesh_download/processor.py +++ b/lambdas/mesh-download/mesh_download/processor.py @@ -26,9 +26,10 @@ 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) - logger = self.__log.bind(mesh_message_id=validated_event.data.meshMessageId) + validated_event = self._parse_and_validate_event(sqs_record, sqs_message_id) + logger = self.__log.bind(sqs_message_id=sqs_message_id, mesh_message_id=validated_event.data.meshMessageId) logger.info("Processing MESH download request") return self._handle_download(validated_event, logger) @@ -37,11 +38,11 @@ def process_sqs_message(self, sqs_record): self.__log.error( "Error processing SQS message", error=str(exc), - sqs_record=sqs_record + sqs_message_id=sqs_message_id ) raise - def _parse_and_validate_event(self, sqs_record): + def _parse_and_validate_event(self, sqs_record, sqs_message_id=None): message_body = json.loads(sqs_record['body']) event_detail = message_body.get('detail', {}) @@ -53,7 +54,7 @@ def _parse_and_validate_event(self, sqs_record): self.__log.error( "CloudEvent validation failed", validation_errors=str(e), - event_detail=event_detail + sqs_message_id=sqs_message_id ) 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) { diff --git a/lambdas/nhsapp-status-handler/src/apis/sqs-trigger-lambda.ts b/lambdas/nhsapp-status-handler/src/apis/sqs-trigger-lambda.ts index 93b4d3a74..259aa8e87 100644 --- a/lambdas/nhsapp-status-handler/src/apis/sqs-trigger-lambda.ts +++ b/lambdas/nhsapp-status-handler/src/apis/sqs-trigger-lambda.ts @@ -47,6 +47,7 @@ export const createHandler = ({ err: parseError, messageReference: sqsEventDetail?.data?.messageReference || 'not present', + messageId, description: 'Error parsing sqs record', }); @@ -66,6 +67,7 @@ export const createHandler = ({ logger.warn({ err: error, description: 'Error during SQS trigger handler', + messageId, }); batchItemFailures.push({ itemIdentifier: messageId }); 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..1d1616d46 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,9 @@ describe('SQS Handler', () => { expect(logger.warn).toHaveBeenCalledWith({ err: 'PDM error', description: 'Failed processing message', + messageId: '1', + messageReference: pdmResourceSubmittedEvent.data.messageReference, + senderId: pdmResourceSubmittedEvent.data.senderId, }); expect(logger.info).toHaveBeenCalledWith( @@ -276,6 +279,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..bc83d5d50 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,9 @@ 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, }); batchItemFailures.push({ itemIdentifier: validatedRecord.messageId }); } diff --git a/lambdas/pdm-uploader-lambda/src/apis/sqs-trigger-lambda.ts b/lambdas/pdm-uploader-lambda/src/apis/sqs-trigger-lambda.ts index 38f402dcb..e348d95d1 100644 --- a/lambdas/pdm-uploader-lambda/src/apis/sqs-trigger-lambda.ts +++ b/lambdas/pdm-uploader-lambda/src/apis/sqs-trigger-lambda.ts @@ -49,6 +49,7 @@ function validateRecord( logger.error({ err: error, description: 'Error parsing SQS record', + messageId, }); return null; } @@ -73,6 +74,9 @@ async function processRecord( logger.error({ err: error, description: 'Error during SQS trigger handler', + messageId, + messageReference: event.data.messageReference, + senderId: event.data.senderId, }); batchItemFailures.push({ itemIdentifier: messageId }); return { result: { outcome: 'failed' } }; 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..796bef9bd 100644 --- a/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts +++ b/lambdas/print-analyser/src/__tests__/apis/sqs-handler.test.ts @@ -103,6 +103,7 @@ describe('SQS Handler', () => { `Unexpected token 'o', "not-json" is not valid JSON`, ), description: 'Error parsing SQS record', + messageId: '1', }); expect(logger.info).toHaveBeenCalledWith( @@ -124,7 +125,9 @@ describe('SQS Handler', () => { const result = await handler(event); expect(logger.child).toHaveBeenCalledWith({ + messageId: '1', messageReference: fileSafeEvent.data.messageReference, + senderId: fileSafeEvent.data.senderId, }); expect(mockChildLogger.error).toHaveBeenCalledWith({ err: expect.arrayContaining([ @@ -177,7 +180,7 @@ describe('SQS Handler', () => { const result = await handler(event); - expect(logger.warn).toHaveBeenCalledWith({ + expect(mockChildLogger.warn).toHaveBeenCalledWith({ err: expect.objectContaining({ message: 'S3 GetObject failed' }), description: 'Failed processing message', }); @@ -230,9 +233,8 @@ describe('SQS Handler', () => { expect.any(Function), ); - expect(logger.warn).toHaveBeenCalledWith({ + expect(mockChildLogger.warn).toHaveBeenCalledWith({ err: expect.any(Error), - messageReference: fileSafeEvent.data.messageReference, reasonCode: 'DL_CLIV_002', description: 'Failed to analyze PDF - invalid attachment format', }); diff --git a/lambdas/print-analyser/src/apis/sqs-handler.ts b/lambdas/print-analyser/src/apis/sqs-handler.ts index f7c1a7c05..e6440be54 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({ messageId, messageReference, senderId }); validateFileSafe(sqsEventDetail, childLogger); @@ -49,6 +50,7 @@ function validateRecord( logger.warn({ err: error, description: 'Error parsing SQS record', + messageId, }); return null; @@ -139,8 +141,13 @@ export const createHandler = ({ await Promise.all( validatedRecords.map(async (validatedRecord: ValidatedRecord) => { + const { event, messageId } = validatedRecord; + const recordLogger = logger.child({ + messageId, + messageReference: event.data.messageReference, + senderId: event.data.senderId, + }); try { - const { event } = validatedRecord; const pdfBuffer = await getS3ObjectBufferFromUri( event.data.letterUri, ); @@ -152,20 +159,19 @@ export const createHandler = ({ const invalidAttachmentEvent = generateInvalidAttachmentEvent(event); validEvents.push(invalidAttachmentEvent); - logger.warn({ + recordLogger.warn({ err: pdfError, - messageReference: event.data.messageReference, reasonCode: 'DL_CLIV_002', description: 'Failed to analyze PDF - invalid attachment format', }); } } catch (error: any) { - logger.warn({ + recordLogger.warn({ err: error, description: 'Failed processing message', }); batchItemFailures.push({ - itemIdentifier: validatedRecord.messageId, + itemIdentifier: messageId, }); } }), diff --git a/lambdas/print-sender-lambda/src/apis/sqs-trigger-lambda.ts b/lambdas/print-sender-lambda/src/apis/sqs-trigger-lambda.ts index f06751e65..b1df30c17 100644 --- a/lambdas/print-sender-lambda/src/apis/sqs-trigger-lambda.ts +++ b/lambdas/print-sender-lambda/src/apis/sqs-trigger-lambda.ts @@ -28,7 +28,12 @@ export const createHandler = ({ const messageReference = sqsEventDetail?.data?.messageReference || 'not present'; - const childLogger = logger.child({ messageReference }); + const senderId = sqsEventDetail?.data?.senderId || 'not present'; + const childLogger = logger.child({ + messageId, + messageReference, + senderId, + }); validatePDFAnalysed(sqsEventDetail, childLogger); @@ -44,6 +49,7 @@ export const createHandler = ({ logger.error({ err: error, description: 'Error during SQS trigger handler', + messageId, }); batchItemFailures.push({ itemIdentifier: messageId }); diff --git a/lambdas/report-generator/src/apis/sqs-trigger-lambda.ts b/lambdas/report-generator/src/apis/sqs-trigger-lambda.ts index 14c321f96..5b1262570 100644 --- a/lambdas/report-generator/src/apis/sqs-trigger-lambda.ts +++ b/lambdas/report-generator/src/apis/sqs-trigger-lambda.ts @@ -48,6 +48,7 @@ function validateRecord( logger.error({ err: error, description: 'Error parsing SQS record', + messageId, }); return null; } @@ -71,6 +72,8 @@ async function processRecord( logger.error({ err: error, description: 'Error during SQS trigger handler', + messageId, + senderId: event.data.senderId, }); batchItemFailures.push({ itemIdentifier: messageId }); return { result: { outcome: 'failed' }, item: event }; diff --git a/lambdas/report-sender/report_sender/report_sender_processor.py b/lambdas/report-sender/report_sender/report_sender_processor.py index 76b1313d8..978cde372 100644 --- a/lambdas/report-sender/report_sender/report_sender_processor.py +++ b/lambdas/report-sender/report_sender/report_sender_processor.py @@ -38,8 +38,7 @@ def _parse_and_validate_event(self, sqs_record) -> ReportGenerated: except ValidationError as e: self.__log.error( "CloudEvent validation failed", - validation_errors=str(e), - event_detail=event_detail + validation_errors=str(e) ) raise @@ -54,21 +53,24 @@ def process_sqs_message(self, sqs_record): """ Iterates over and processes messages in the SQS queue """ - self.__log.info('Extract data from SQS record') + sqs_message_id = sqs_record.get('messageId') + self.__log.info('Extract data from SQS record', sqs_message_id=sqs_message_id) report_generated_event : ReportGenerated = self._parse_and_validate_event(sqs_record) sender_id = report_generated_event.data.senderId report_uri = str(report_generated_event.data.reportUri) - self.__log.info(f'Fetching sender details for sender ID: {sender_id}') + log = self.__log.bind(sqs_message_id=sqs_message_id, sender_id=sender_id) + + log.info('Fetching sender details', report_uri=report_uri) reporting_mailbox = self.__sender_lookup.get_mesh_mailbox_reports_id_from_sender(sender_id) - self.__log.info(f'Fetching reporting URI : {report_uri} for sender ID: {sender_id}') + log.info('Fetching reporting URI', report_uri=report_uri) report_bytes = self.__reports_store.download_report(report_uri) report_date = self._extract_report_date_from_report_uri(report_uri) report_reference = str(uuid4()) - self.__log.info(f'Sending MESH message to the sender: {sender_id} using mailbox: {reporting_mailbox} for date: {report_date} with reference: {report_reference}') + log.info('Sending MESH message', reporting_mailbox=reporting_mailbox, report_date=report_date, report_reference=report_reference) sent_mesh_message_id = self.__mesh_report_sender.send_report( reporting_mailbox, @@ -77,7 +79,7 @@ def process_sqs_message(self, sqs_record): report_reference ) - self.__log.info(f'Publishing ReportEventSent for the sender: {sender_id} using mailbox: {reporting_mailbox} for date: {report_date}') + log.info('Publishing ReportEventSent', reporting_mailbox=reporting_mailbox, report_date=report_date) self._publish_report_sent_event(sender_id, reporting_mailbox, report_reference, sent_mesh_message_id) self.__send_metric.record(1) diff --git a/lambdas/ttl-create-lambda/src/apis/sqs-trigger-lambda.ts b/lambdas/ttl-create-lambda/src/apis/sqs-trigger-lambda.ts index 1ed224098..d5fc55784 100644 --- a/lambdas/ttl-create-lambda/src/apis/sqs-trigger-lambda.ts +++ b/lambdas/ttl-create-lambda/src/apis/sqs-trigger-lambda.ts @@ -51,6 +51,7 @@ export const createHandler = ({ logger.error({ err: error, description: 'Error during SQS trigger handler', + messageId, }); batchItemFailures.push({ itemIdentifier: messageId });