From 14825ddae08230eae98cf7385f4aed1090b41eba Mon Sep 17 00:00:00 2001 From: Steve Buxton Date: Thu, 29 Jan 2026 16:01:37 +0000 Subject: [PATCH] CCM-12845 Structure logs --- internal/helpers/package.json | 1 + internal/helpers/src/__tests__/logger.test.ts | 15 ++++ internal/helpers/src/index.ts | 1 + internal/helpers/src/logger.ts | 26 ++++++ .../src/config/__tests__/deps.test.ts | 11 ++- lambdas/api-handler/src/config/deps.ts | 14 ++-- lambdas/api-handler/src/config/env.ts | 1 + .../__tests__/letter-status-update.test.ts | 16 ++-- .../src/handlers/get-letter-data.ts | 19 +++-- .../api-handler/src/handlers/get-letter.ts | 1 + .../api-handler/src/handlers/get-letters.ts | 1 + .../api-handler/src/handlers/get-status.ts | 8 +- .../src/handlers/letter-status-update.ts | 22 +++--- .../api-handler/src/handlers/patch-letter.ts | 8 ++ .../api-handler/src/handlers/post-letters.ts | 7 ++ lambdas/api-handler/src/handlers/post-mi.ts | 6 ++ .../api-handler/src/mappers/error-mapper.ts | 27 +++---- .../__tests__/letter-operations.test.ts | 79 ++++++++++--------- .../src/services/letter-operations.ts | 28 ++++--- lambdas/authorizer/package.json | 1 + .../authorizer/src/__tests__/index.test.ts | 6 +- lambdas/authorizer/src/authorizer.ts | 20 +++-- lambdas/authorizer/src/deps.ts | 9 ++- lambdas/authorizer/src/env.ts | 1 + .../letter-updates-transformer.test.ts | 2 +- .../letter-updates-transformer/src/deps.ts | 7 +- lambdas/letter-updates-transformer/src/env.ts | 1 + .../src/letter-updates-transformer.ts | 2 +- lambdas/mi-updates-transformer/package.json | 1 + lambdas/mi-updates-transformer/src/deps.ts | 7 +- lambdas/mi-updates-transformer/src/env.ts | 1 + lambdas/upsert-letter/package.json | 1 + .../src/config/__tests__/deps.test.ts | 12 +-- lambdas/upsert-letter/src/config/deps.ts | 9 ++- lambdas/upsert-letter/src/config/env.ts | 1 + .../handler/__tests__/upsert-handler.test.ts | 35 +++++--- .../src/handler/upsert-handler.ts | 29 ++++++- package-lock.json | 33 ++++++-- 38 files changed, 313 insertions(+), 156 deletions(-) create mode 100644 internal/helpers/src/__tests__/logger.test.ts create mode 100644 internal/helpers/src/logger.ts diff --git a/internal/helpers/package.json b/internal/helpers/package.json index 4e1a73f5a..f02df328c 100644 --- a/internal/helpers/package.json +++ b/internal/helpers/package.json @@ -1,5 +1,6 @@ { "dependencies": { + "pino": "^9.7.0", "zod": "^4.1.11" }, "description": "Common helper utilities for NHS Notify Supplier API", diff --git a/internal/helpers/src/__tests__/logger.test.ts b/internal/helpers/src/__tests__/logger.test.ts new file mode 100644 index 000000000..2bc1a28df --- /dev/null +++ b/internal/helpers/src/__tests__/logger.test.ts @@ -0,0 +1,15 @@ +import { createLogger } from "../logger"; + +describe("createLogger", () => { + it("should create a logger with default log level", () => { + const logger = createLogger(); + + expect(logger.level).toBe("info"); + }); + + it("should create a logger with custom log level", () => { + const logger = createLogger({ logLevel: "debug" }); + + expect(logger.level).toBe("debug"); + }); +}); diff --git a/internal/helpers/src/index.ts b/internal/helpers/src/index.ts index cc2c27e58..27ed9b65a 100644 --- a/internal/helpers/src/index.ts +++ b/internal/helpers/src/index.ts @@ -7,3 +7,4 @@ export * from "./version"; export { default as $Environment } from "./environment"; export * from "./id-ref"; +export * from "./logger"; diff --git a/internal/helpers/src/logger.ts b/internal/helpers/src/logger.ts new file mode 100644 index 000000000..051e793be --- /dev/null +++ b/internal/helpers/src/logger.ts @@ -0,0 +1,26 @@ +import pino, { Logger } from "pino"; + +export type LoggerOptions = { + logLevel?: string; +}; + +/** + * Creates a configured pino logger instance for use across lambdas. + * + * @param options - Optional configuration for the logger + * @param options.logLevel - The log level (defaults to "info") + * @returns A configured pino Logger instance + */ +export function createLogger(options: LoggerOptions = {}): Logger { + const { logLevel = "info" } = options; + + return pino({ + level: logLevel, + formatters: { + level: (label) => { + return { level: label.toUpperCase() }; + }, + }, + timestamp: () => `,"timestamp":"${new Date(Date.now()).toISOString()}"`, + }); +} diff --git a/lambdas/api-handler/src/config/__tests__/deps.test.ts b/lambdas/api-handler/src/config/__tests__/deps.test.ts index 64762d662..269bda443 100644 --- a/lambdas/api-handler/src/config/__tests__/deps.test.ts +++ b/lambdas/api-handler/src/config/__tests__/deps.test.ts @@ -15,14 +15,13 @@ describe("createDependenciesContainer", () => { jest.clearAllMocks(); jest.resetModules(); - // pino - jest.mock("pino", () => ({ - __esModule: true, - default: jest.fn(() => ({ + jest.mock("@internal/helpers", () => ({ + createLogger: jest.fn(() => ({ info: jest.fn(), error: jest.fn(), warn: jest.fn(), debug: jest.fn(), + level: "info", })), })); @@ -49,7 +48,7 @@ describe("createDependenciesContainer", () => { // get current mock instances const { S3Client } = jest.requireMock("@aws-sdk/client-s3"); const { SQSClient } = jest.requireMock("@aws-sdk/client-sqs"); - const pinoMock = jest.requireMock("pino"); + const { createLogger } = jest.requireMock("@internal/helpers"); const { LetterRepository, MIRepository } = jest.requireMock( "@internal/datastore", ); @@ -63,7 +62,7 @@ describe("createDependenciesContainer", () => { expect(SQSClient).toHaveBeenCalledTimes(1); - expect(pinoMock.default).toHaveBeenCalledTimes(1); + expect(createLogger).toHaveBeenCalledTimes(1); expect(LetterRepository).toHaveBeenCalledTimes(1); const letterRepoCtorArgs = LetterRepository.mock.calls[0]; diff --git a/lambdas/api-handler/src/config/deps.ts b/lambdas/api-handler/src/config/deps.ts index c8d187bf4..1a64998f4 100644 --- a/lambdas/api-handler/src/config/deps.ts +++ b/lambdas/api-handler/src/config/deps.ts @@ -2,12 +2,13 @@ import { S3Client } from "@aws-sdk/client-s3"; import { DynamoDBClient } from "@aws-sdk/client-dynamodb"; import { DynamoDBDocumentClient } from "@aws-sdk/lib-dynamodb"; import { SQSClient } from "@aws-sdk/client-sqs"; -import pino from "pino"; +import { Logger } from "pino"; import { DBHealthcheck, LetterRepository, MIRepository, } from "@internal/datastore"; +import { createLogger } from "@internal/helpers"; import { EnvVars, envVars } from "./env"; export type Deps = { @@ -16,7 +17,7 @@ export type Deps = { letterRepo: LetterRepository; miRepo: MIRepository; dbHealthcheck: DBHealthcheck; - logger: pino.Logger; + logger: Logger; env: EnvVars; }; @@ -26,7 +27,7 @@ function createDocumentClient(): DynamoDBDocumentClient { } function createLetterRepository( - log: pino.Logger, + log: Logger, environment: EnvVars, ): LetterRepository { const config = { @@ -46,10 +47,7 @@ function createDBHealthcheck(environment: EnvVars): DBHealthcheck { return new DBHealthcheck(createDocumentClient(), config); } -function createMIRepository( - log: pino.Logger, - environment: EnvVars, -): MIRepository { +function createMIRepository(log: Logger, environment: EnvVars): MIRepository { const config = { miTableName: environment.MI_TABLE_NAME, miTtlHours: environment.MI_TTL_HOURS, @@ -59,7 +57,7 @@ function createMIRepository( } export function createDependenciesContainer(): Deps { - const log = pino(); + const log = createLogger({ logLevel: envVars.PINO_LOG_LEVEL }); return { s3Client: new S3Client(), diff --git a/lambdas/api-handler/src/config/env.ts b/lambdas/api-handler/src/config/env.ts index fbdc0924d..0a98f2b4d 100644 --- a/lambdas/api-handler/src/config/env.ts +++ b/lambdas/api-handler/src/config/env.ts @@ -10,6 +10,7 @@ const EnvVarsSchema = z.object({ DOWNLOAD_URL_TTL_SECONDS: z.coerce.number().int(), MAX_LIMIT: z.coerce.number().int().optional(), QUEUE_URL: z.coerce.string().optional(), + PINO_LOG_LEVEL: z.coerce.string().optional(), }); export type EnvVars = z.infer; diff --git a/lambdas/api-handler/src/handlers/__tests__/letter-status-update.test.ts b/lambdas/api-handler/src/handlers/__tests__/letter-status-update.test.ts index 908ba1a3d..7ec1866b9 100644 --- a/lambdas/api-handler/src/handlers/__tests__/letter-status-update.test.ts +++ b/lambdas/api-handler/src/handlers/__tests__/letter-status-update.test.ts @@ -143,14 +143,12 @@ describe("createLetterStatusUpdateHandler", () => { expect(mockedDeps.letterRepo.updateLetterStatus).toHaveBeenCalledWith( updateLetterCommands[0], ); - expect(mockedDeps.logger.error).toHaveBeenCalledWith( - { - err: mockError, - messageId: "mid-id1", - correlationId: "correlationId-id1", - messageBody: '{"id":"id1","status":"ACCEPTED","supplierId":"s1"}', - }, - "Error processing letter status update", - ); + expect(mockedDeps.logger.error).toHaveBeenCalledWith({ + description: "Error processing letter status update", + err: mockError, + messageId: "mid-id1", + correlationId: "correlationId-id1", + messageBody: '{"id":"id1","status":"ACCEPTED","supplierId":"s1"}', + }); }); }); diff --git a/lambdas/api-handler/src/handlers/get-letter-data.ts b/lambdas/api-handler/src/handlers/get-letter-data.ts index 4d516645b..c60f9d2d6 100644 --- a/lambdas/api-handler/src/handlers/get-letter-data.ts +++ b/lambdas/api-handler/src/handlers/get-letter-data.ts @@ -33,14 +33,23 @@ export default function createGetLetterDataHandler( ), ); + const presignedUrl = await getLetterDataUrl( + commonIds.value.supplierId, + letterId, + deps, + ); + + deps.logger.info({ + description: "Generated presigned URL", + supplierId: commonIds.value.supplierId, + letterId, + correlationId: commonIds.value.correlationId, + }); + return { statusCode: 303, headers: { - Location: await getLetterDataUrl( - commonIds.value.supplierId, - letterId, - deps, - ), + Location: presignedUrl, }, body: "", }; diff --git a/lambdas/api-handler/src/handlers/get-letter.ts b/lambdas/api-handler/src/handlers/get-letter.ts index a88a48822..c30e18ac8 100644 --- a/lambdas/api-handler/src/handlers/get-letter.ts +++ b/lambdas/api-handler/src/handlers/get-letter.ts @@ -46,6 +46,7 @@ export default function createGetLetterHandler( description: "Letter successfully fetched by id", supplierId: commonIds.value.supplierId, letterId, + correlationId: commonIds.value.correlationId, }); return { diff --git a/lambdas/api-handler/src/handlers/get-letters.ts b/lambdas/api-handler/src/handlers/get-letters.ts index adc3febc4..091fb1d1f 100644 --- a/lambdas/api-handler/src/handlers/get-letters.ts +++ b/lambdas/api-handler/src/handlers/get-letters.ts @@ -121,6 +121,7 @@ export default function createGetLettersHandler( limitNumber, status, lettersCount: letters.length, + correlationId: commonIds.value.correlationId, }); return { diff --git a/lambdas/api-handler/src/handlers/get-status.ts b/lambdas/api-handler/src/handlers/get-status.ts index f1973296c..a7afc6c3a 100644 --- a/lambdas/api-handler/src/handlers/get-status.ts +++ b/lambdas/api-handler/src/handlers/get-status.ts @@ -26,10 +26,10 @@ export default function createGetStatusHandler( body: JSON.stringify({ code: 200 }, null, 2), }; } catch (error) { - deps.logger.error( - { err: error }, - "Status endpoint error, services not available", - ); + deps.logger.error({ + err: error, + description: "Status endpoint error, services not available", + }); return { statusCode: 500, body: JSON.stringify({ code: 500 }, null, 2), diff --git a/lambdas/api-handler/src/handlers/letter-status-update.ts b/lambdas/api-handler/src/handlers/letter-status-update.ts index fa14e672d..b49f8702a 100644 --- a/lambdas/api-handler/src/handlers/letter-status-update.ts +++ b/lambdas/api-handler/src/handlers/letter-status-update.ts @@ -17,16 +17,20 @@ export default function createLetterStatusUpdateHandler( await deps.letterRepo.updateLetterStatus( mapToUpdateLetter(letterToUpdate), ); + deps.logger.info({ + description: "Updated letter status", + letterId: letterToUpdate.id, + messageId: message.messageId, + correlationId: message.messageAttributes.CorrelationId.stringValue, + }); } catch (error) { - deps.logger.error( - { - err: error, - messageId: message.messageId, - correlationId: message.messageAttributes.CorrelationId.stringValue, - messageBody: message.body, - }, - "Error processing letter status update", - ); + deps.logger.error({ + description: "Error processing letter status update", + err: error, + messageId: message.messageId, + correlationId: message.messageAttributes.CorrelationId.stringValue, + messageBody: message.body, + }); } }); diff --git a/lambdas/api-handler/src/handlers/patch-letter.ts b/lambdas/api-handler/src/handlers/patch-letter.ts index 6d0be3c2c..3257649a7 100644 --- a/lambdas/api-handler/src/handlers/patch-letter.ts +++ b/lambdas/api-handler/src/handlers/patch-letter.ts @@ -57,6 +57,14 @@ export default function createPatchLetterHandler( throw typedError; } + deps.logger.info({ + description: "Received patch letter request", + supplierId: commonIds.value.supplierId, + letterId, + newStatus: patchLetterRequest.data.attributes.status, + correlationId: commonIds.value.correlationId, + }); + const updateLetterCommand: UpdateLetterCommand = mapToUpdateCommand( patchLetterRequest, commonIds.value.supplierId, diff --git a/lambdas/api-handler/src/handlers/post-letters.ts b/lambdas/api-handler/src/handlers/post-letters.ts index d8f147878..bf87c6a87 100644 --- a/lambdas/api-handler/src/handlers/post-letters.ts +++ b/lambdas/api-handler/src/handlers/post-letters.ts @@ -58,6 +58,13 @@ export default function createPostLettersHandler( throw typedError; } + deps.logger.info({ + description: "Received post letters request", + supplierId: commonIds.value.supplierId, + letterIds: postLettersRequest.data.map((letter) => letter.id), + correlationId: commonIds.value.correlationId, + }); + if (postLettersRequest.data.length > maxUpdateItems) { throw new ValidationError( ApiErrorDetail.InvalidRequestLettersToUpdate, diff --git a/lambdas/api-handler/src/handlers/post-mi.ts b/lambdas/api-handler/src/handlers/post-mi.ts index 74fc82e18..670212c2c 100644 --- a/lambdas/api-handler/src/handlers/post-mi.ts +++ b/lambdas/api-handler/src/handlers/post-mi.ts @@ -53,6 +53,12 @@ export default function createPostMIHandler( deps.miRepo, ); + deps.logger.info({ + description: "Posted management information", + supplierId: commonIds.value.supplierId, + correlationId: commonIds.value.correlationId, + }); + return { statusCode: 201, body: JSON.stringify(result, null, 2), diff --git a/lambdas/api-handler/src/mappers/error-mapper.ts b/lambdas/api-handler/src/mappers/error-mapper.ts index 408fe26c7..f4875fdee 100644 --- a/lambdas/api-handler/src/mappers/error-mapper.ts +++ b/lambdas/api-handler/src/mappers/error-mapper.ts @@ -72,10 +72,7 @@ export function logAndMapToApiError( logger: Logger, ): ApiError { if (error instanceof ValidationError) { - logger.info( - { err: error }, - `Validation error correlationId=${correlationId}`, - ); + logger.info({ description: "Validation error", err: error, correlationId }); return mapToApiError( ApiErrorCode.InvalidRequest, error.detail, @@ -83,27 +80,25 @@ export function logAndMapToApiError( ); } if (error instanceof NotFoundError) { - logger.info( - { err: error }, - `Not found error correlationId=${correlationId}`, - ); + logger.info({ description: "Not found error", err: error, correlationId }); return mapToApiError(ApiErrorCode.NotFound, error.detail, correlationId); } if (error instanceof Error) { - logger.error( - { err: error }, - `Internal server error correlationId=${correlationId}`, - ); + logger.error({ + description: "Internal server error", + err: error, + correlationId, + }); return mapToApiError( ApiErrorCode.InternalServerError, "Unexpected error", correlationId, ); } - logger.error( - { err: error }, - `Internal server error (non-Error thrown) correlationId=${correlationId}`, - ); + logger.error({ + description: "Internal server error (non-Error thrown)", + correlationId, + }); return mapToApiError( ApiErrorCode.InternalServerError, "Unexpected error", diff --git a/lambdas/api-handler/src/services/__tests__/letter-operations.test.ts b/lambdas/api-handler/src/services/__tests__/letter-operations.test.ts index 204d24550..08e103ab0 100644 --- a/lambdas/api-handler/src/services/__tests__/letter-operations.test.ts +++ b/lambdas/api-handler/src/services/__tests__/letter-operations.test.ts @@ -205,14 +205,17 @@ describe("enqueueLetterUpdateRequests function", () => { jest.clearAllMocks(); }); - it("should update the letter status successfully", async () => { - const sqsClient = { send: jest.fn() } as unknown as SQSClient; - const logger = { error: jest.fn() } as unknown as pino.Logger; - const env = { - QUEUE_URL: "sqsUrl", - }; - const deps: Deps = { sqsClient, logger, env } as Deps; + const sqsClient = { send: jest.fn() } as unknown as SQSClient; + const logger = { + info: jest.fn(), + error: jest.fn(), + } as unknown as pino.Logger; + const env = { + QUEUE_URL: "sqsUrl", + }; + const deps: Deps = { sqsClient, logger, env } as Deps; + it("should update the letter status successfully", async () => { const updateLetterCommands = Array.from({ length: 25 }, (_, i) => makeUpdateLetterCommand(i), ); @@ -256,22 +259,34 @@ describe("enqueueLetterUpdateRequests function", () => { expect(thirdInput.Entries[0].Id).toBe("2-0"); }); + it("should log when SendMessageBatch returns Successful entries", async () => { + (sqsClient.send as jest.Mock).mockResolvedValue({ + Successful: [{ MessageId: "msg-001" }, { MessageId: "msg-002" }], + Failed: [], + }); + const updateLetterCommands = [makeUpdateLetterCommand(0)]; + + await enqueueLetterUpdateRequests( + updateLetterCommands, + "correlationId1", + deps, + ); + + expect(deps.logger.info).toHaveBeenCalledWith({ + description: "Enqueued letter updates", + correlationId: "correlationId1", + messageIds: ["msg-001", "msg-002"], + }); + }); + it("should log error when SendMessageBatch returns Failed entries", async () => { - const sqsClient = { - send: jest - .fn() - .mockResolvedValueOnce({ Failed: [] }) // first batch succeeds - .mockResolvedValueOnce({ - Failed: [ - { Id: "1-1", SenderFault: false, Code: "Err", Message: "failed" }, - ], - }), - } as unknown as SQSClient; - const logger = { error: jest.fn() } as unknown as pino.Logger; - const env = { - QUEUE_URL: "sqsUrl", - }; - const deps: Deps = { sqsClient, logger, env } as Deps; + (sqsClient.send as jest.Mock) + .mockResolvedValueOnce({ Failed: [] }) // first batch succeeds + .mockResolvedValueOnce({ + Failed: [ + { Id: "1-1", SenderFault: false, Code: "Err", Message: "failed" }, + ], + }); const updateLetterCommands = Array.from({ length: 12 }, (_, i) => makeUpdateLetterCommand(i), @@ -296,20 +311,12 @@ describe("enqueueLetterUpdateRequests function", () => { }); it("should log error if enqueueing fails", async () => { - const sqsClient = { - send: jest - .fn() - .mockResolvedValueOnce({ Failed: [] }) // batch 0 - .mockImplementationOnce(() => { - throw new Error("some failure"); - }) // batch 1 - .mockResolvedValueOnce({ Failed: [] }), // batch 2 - } as unknown as SQSClient; - const logger = { error: jest.fn() } as unknown as pino.Logger; - const env = { - QUEUE_URL: "sqsUrl", - }; - const deps: Deps = { sqsClient, logger, env } as Deps; + (sqsClient.send as jest.Mock) + .mockResolvedValueOnce({ Failed: [] }) // batch 0 + .mockImplementationOnce(() => { + throw new Error("some failure"); + }) // batch 1 + .mockResolvedValueOnce({ Failed: [] }); const lettersToUpdate = Array.from({ length: 21 }, (_, i) => makeUpdateLetterCommand(i), diff --git a/lambdas/api-handler/src/services/letter-operations.ts b/lambdas/api-handler/src/services/letter-operations.ts index 558c2c90c..dc2de921d 100644 --- a/lambdas/api-handler/src/services/letter-operations.ts +++ b/lambdas/api-handler/src/services/letter-operations.ts @@ -123,20 +123,26 @@ export async function enqueueLetterUpdateRequests( try { const result = await deps.sqsClient.send(cmd); + if (result.Successful && result.Successful.length > 0) { + deps.logger.info({ + description: "Enqueued letter updates", + correlationId, + messageIds: result.Successful.map((entry) => entry.MessageId), + }); + } if (result.Failed && result.Failed.length > 0) { - deps.logger.error( - { failed: result.Failed }, - "Some batch entries failed", - ); + deps.logger.error({ + failed: result.Failed, + description: "Some batch entries failed", + correlationId, + }); } } catch (error) { - deps.logger.error( - { - err: error, - correlationId, - }, - "Error enqueuing letter status updates", - ); + deps.logger.error({ + err: error, + description: "Error enqueuing letter status updates", + correlationId, + }); } }), ); diff --git a/lambdas/authorizer/package.json b/lambdas/authorizer/package.json index 108b76dc2..3434dc860 100644 --- a/lambdas/authorizer/package.json +++ b/lambdas/authorizer/package.json @@ -3,6 +3,7 @@ "@aws-sdk/client-dynamodb": "^3.858.0", "@aws-sdk/lib-dynamodb": "^3.858.0", "@internal/datastore": "*", + "@internal/helpers": "*", "aws-lambda": "^1.0.7", "esbuild": "^0.25.11", "pino": "^9.7.0", diff --git a/lambdas/authorizer/src/__tests__/index.test.ts b/lambdas/authorizer/src/__tests__/index.test.ts index e7567c70e..4020b55e9 100644 --- a/lambdas/authorizer/src/__tests__/index.test.ts +++ b/lambdas/authorizer/src/__tests__/index.test.ts @@ -10,7 +10,11 @@ import { EnvVars } from "../env"; import createAuthorizerHandler from "../authorizer"; const mockedDeps: jest.Mocked = { - logger: { info: jest.fn(), error: jest.fn() } as unknown as pino.Logger, + logger: { + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + } as unknown as pino.Logger, env: { CLOUDWATCH_NAMESPACE: "cloudwatch-namespace", CLIENT_CERTIFICATE_EXPIRATION_ALERT_DAYS: 14, diff --git a/lambdas/authorizer/src/authorizer.ts b/lambdas/authorizer/src/authorizer.ts index 73c8fef5d..d5a0bd556 100644 --- a/lambdas/authorizer/src/authorizer.ts +++ b/lambdas/authorizer/src/authorizer.ts @@ -18,17 +18,23 @@ export default function createAuthorizerHandler( context: Context, callback: Callback, ): void => { - deps.logger.info(event, "Received event"); - checkCertificateExpiry(event.requestContext.identity.clientCert, deps); getSupplier(event.headers, deps) .then((supplier: Supplier) => { - deps.logger.info("Allow event"); + deps.logger.info({ + description: "Allowed event", + methodArn: event.methodArn, + supplierId: supplier.id, + }); callback(null, generateAllow(event.methodArn, supplier.id)); }) .catch((error) => { - deps.logger.info(error, "Deny event"); + deps.logger.warn({ + description: "Denied event", + err: error, + methodArn: event.methodArn, + }); callback(null, generateDeny(event.methodArn)); }); }; @@ -127,9 +133,9 @@ async function checkCertificateExpiry( ): Promise { deps.logger.info({ description: "Client certificate details", - issuerDN: certificate?.issuerDN, - subjectDN: certificate?.subjectDN, - validity: certificate?.validity, + issuerDN: certificate?.issuerDN || "-", + subjectDN: certificate?.subjectDN || "-", + validity: certificate?.validity || "-", }); if (!certificate) { diff --git a/lambdas/authorizer/src/deps.ts b/lambdas/authorizer/src/deps.ts index 9f2ce0ed3..6ea7ee079 100644 --- a/lambdas/authorizer/src/deps.ts +++ b/lambdas/authorizer/src/deps.ts @@ -1,12 +1,13 @@ import { DynamoDBClient } from "@aws-sdk/client-dynamodb"; import { DynamoDBDocumentClient } from "@aws-sdk/lib-dynamodb"; -import pino from "pino"; +import { Logger } from "pino"; import { SupplierRepository } from "@internal/datastore"; +import { createLogger } from "@internal/helpers/src"; import { EnvVars, envVars } from "./env"; export type Deps = { supplierRepo: SupplierRepository; - logger: pino.Logger; + logger: Logger; env: EnvVars; }; @@ -17,7 +18,7 @@ function createDocumentClient(): DynamoDBDocumentClient { function createSupplierRepository( documentClient: DynamoDBDocumentClient, - log: pino.Logger, + log: Logger, suppliersTableName: string, ): SupplierRepository { const config = { @@ -28,7 +29,7 @@ function createSupplierRepository( } export function createDependenciesContainer(): Deps { - const log = pino(); + const log = createLogger({ logLevel: envVars.PINO_LOG_LEVEL }); return { supplierRepo: createSupplierRepository( diff --git a/lambdas/authorizer/src/env.ts b/lambdas/authorizer/src/env.ts index 40a569174..a81f82f2d 100644 --- a/lambdas/authorizer/src/env.ts +++ b/lambdas/authorizer/src/env.ts @@ -5,6 +5,7 @@ const EnvVarsSchema = z.object({ CLOUDWATCH_NAMESPACE: z.string(), APIM_SUPPLIER_ID_HEADER: z.string(), CLIENT_CERTIFICATE_EXPIRATION_ALERT_DAYS: z.coerce.number().int(), + PINO_LOG_LEVEL: z.coerce.string().optional(), }); export type EnvVars = z.infer; diff --git a/lambdas/letter-updates-transformer/src/__tests__/letter-updates-transformer.test.ts b/lambdas/letter-updates-transformer/src/__tests__/letter-updates-transformer.test.ts index 065a9a1e3..f00e62935 100644 --- a/lambdas/letter-updates-transformer/src/__tests__/letter-updates-transformer.test.ts +++ b/lambdas/letter-updates-transformer/src/__tests__/letter-updates-transformer.test.ts @@ -205,7 +205,7 @@ describe("letter-updates-transformer Lambda", () => { expect(mockedDeps.logger.error).toHaveBeenCalledWith( expect.objectContaining({ description: "Error extracting payload", - error: expect.any(Error), + err: expect.any(Error), record: expect.objectContaining({ kinesis: expect.objectContaining({ data: Buffer.from("invalid-json-data").toString("base64"), diff --git a/lambdas/letter-updates-transformer/src/deps.ts b/lambdas/letter-updates-transformer/src/deps.ts index 9332410ea..57831c7a3 100644 --- a/lambdas/letter-updates-transformer/src/deps.ts +++ b/lambdas/letter-updates-transformer/src/deps.ts @@ -1,10 +1,11 @@ -import pino from "pino"; +import { Logger } from "pino"; import { SNSClient } from "@aws-sdk/client-sns"; +import { createLogger } from "@internal/helpers/src"; import { EnvVars, envVars } from "./env"; export type Deps = { snsClient: SNSClient; - logger: pino.Logger; + logger: Logger; env: EnvVars; }; @@ -13,7 +14,7 @@ function createSNSClient(): SNSClient { } export function createDependenciesContainer(): Deps { - const log = pino(); + const log = createLogger({ logLevel: envVars.PINO_LOG_LEVEL }); return { snsClient: createSNSClient(), diff --git a/lambdas/letter-updates-transformer/src/env.ts b/lambdas/letter-updates-transformer/src/env.ts index a91381864..33030ad8b 100644 --- a/lambdas/letter-updates-transformer/src/env.ts +++ b/lambdas/letter-updates-transformer/src/env.ts @@ -3,6 +3,7 @@ import { z } from "zod"; const EnvVarsSchema = z.object({ EVENTPUB_SNS_TOPIC_ARN: z.string(), EVENT_SOURCE: z.string(), + PINO_LOG_LEVEL: z.coerce.string().optional(), }); export type EnvVars = z.infer; diff --git a/lambdas/letter-updates-transformer/src/letter-updates-transformer.ts b/lambdas/letter-updates-transformer/src/letter-updates-transformer.ts index c53151c07..7d0fa0c0f 100644 --- a/lambdas/letter-updates-transformer/src/letter-updates-transformer.ts +++ b/lambdas/letter-updates-transformer/src/letter-updates-transformer.ts @@ -96,7 +96,7 @@ function extractPayload( } catch (error) { deps.logger.error({ description: "Error extracting payload", - error, + err: error, record, }); throw error; diff --git a/lambdas/mi-updates-transformer/package.json b/lambdas/mi-updates-transformer/package.json index 35dd5567d..b20312209 100644 --- a/lambdas/mi-updates-transformer/package.json +++ b/lambdas/mi-updates-transformer/package.json @@ -3,6 +3,7 @@ "@aws-sdk/client-sns": "^3.954.0", "@aws-sdk/util-dynamodb": "^3.943.0", "@internal/datastore": "^0.1.0", + "@internal/helpers": "*", "@nhsdigital/nhs-notify-event-schemas-supplier-api": "*", "aws-lambda": "^1.0.7", "esbuild": "^0.24.0", diff --git a/lambdas/mi-updates-transformer/src/deps.ts b/lambdas/mi-updates-transformer/src/deps.ts index 9332410ea..57831c7a3 100644 --- a/lambdas/mi-updates-transformer/src/deps.ts +++ b/lambdas/mi-updates-transformer/src/deps.ts @@ -1,10 +1,11 @@ -import pino from "pino"; +import { Logger } from "pino"; import { SNSClient } from "@aws-sdk/client-sns"; +import { createLogger } from "@internal/helpers/src"; import { EnvVars, envVars } from "./env"; export type Deps = { snsClient: SNSClient; - logger: pino.Logger; + logger: Logger; env: EnvVars; }; @@ -13,7 +14,7 @@ function createSNSClient(): SNSClient { } export function createDependenciesContainer(): Deps { - const log = pino(); + const log = createLogger({ logLevel: envVars.PINO_LOG_LEVEL }); return { snsClient: createSNSClient(), diff --git a/lambdas/mi-updates-transformer/src/env.ts b/lambdas/mi-updates-transformer/src/env.ts index f93bbf39f..fb4fe6089 100644 --- a/lambdas/mi-updates-transformer/src/env.ts +++ b/lambdas/mi-updates-transformer/src/env.ts @@ -2,6 +2,7 @@ import { z } from "zod"; const EnvVarsSchema = z.object({ EVENTPUB_SNS_TOPIC_ARN: z.string(), + PINO_LOG_LEVEL: z.coerce.string().optional(), }); export type EnvVars = z.infer; diff --git a/lambdas/upsert-letter/package.json b/lambdas/upsert-letter/package.json index e4858da0d..059c3d02a 100644 --- a/lambdas/upsert-letter/package.json +++ b/lambdas/upsert-letter/package.json @@ -3,6 +3,7 @@ "@aws-sdk/client-dynamodb": "^3.858.0", "@aws-sdk/lib-dynamodb": "^3.858.0", "@internal/datastore": "*", + "@internal/helpers": "*", "@nhsdigital/nhs-notify-event-schemas-letter-rendering": "^2.0.1", "@nhsdigital/nhs-notify-event-schemas-letter-rendering-v1": "npm:@nhsdigital/nhs-notify-event-schemas-letter-rendering@^1.1.5", "@nhsdigital/nhs-notify-event-schemas-supplier-api": "^1.0.8", diff --git a/lambdas/upsert-letter/src/config/__tests__/deps.test.ts b/lambdas/upsert-letter/src/config/__tests__/deps.test.ts index a532da6f5..3e05e5b3c 100644 --- a/lambdas/upsert-letter/src/config/__tests__/deps.test.ts +++ b/lambdas/upsert-letter/src/config/__tests__/deps.test.ts @@ -10,14 +10,14 @@ describe("createDependenciesContainer", () => { jest.clearAllMocks(); jest.resetModules(); - // pino - jest.mock("pino", () => ({ - __esModule: true, - default: jest.fn(() => ({ + // @internal/helpers - createLogger + jest.mock("@internal/helpers", () => ({ + createLogger: jest.fn(() => ({ info: jest.fn(), error: jest.fn(), warn: jest.fn(), debug: jest.fn(), + level: "info", })), })); @@ -32,14 +32,14 @@ describe("createDependenciesContainer", () => { test("constructs deps and wires repository config correctly", async () => { // get current mock instances - const pinoMock = jest.requireMock("pino"); + const { createLogger } = jest.requireMock("@internal/helpers"); const { LetterRepository } = jest.requireMock("@internal/datastore"); // eslint-disable-next-line @typescript-eslint/no-require-imports const { createDependenciesContainer } = require("../deps"); const deps: Deps = createDependenciesContainer(); - expect(pinoMock.default).toHaveBeenCalledTimes(1); + expect(createLogger).toHaveBeenCalledTimes(1); expect(LetterRepository).toHaveBeenCalledTimes(1); const letterRepoCtorArgs = LetterRepository.mock.calls[0]; diff --git a/lambdas/upsert-letter/src/config/deps.ts b/lambdas/upsert-letter/src/config/deps.ts index 7320af6f2..9303e1152 100644 --- a/lambdas/upsert-letter/src/config/deps.ts +++ b/lambdas/upsert-letter/src/config/deps.ts @@ -1,12 +1,13 @@ import { DynamoDBClient } from "@aws-sdk/client-dynamodb"; import { DynamoDBDocumentClient } from "@aws-sdk/lib-dynamodb"; -import pino from "pino"; +import { Logger } from "pino"; import { LetterRepository } from "@internal/datastore"; +import { createLogger } from "@internal/helpers"; import { EnvVars, envVars } from "./env"; export type Deps = { letterRepo: LetterRepository; - logger: pino.Logger; + logger: Logger; env: EnvVars; }; @@ -16,7 +17,7 @@ function createDocumentClient(): DynamoDBDocumentClient { } function createLetterRepository( - log: pino.Logger, + log: Logger, // eslint-disable-next-line @typescript-eslint/no-shadow envVars: EnvVars, ): LetterRepository { @@ -29,7 +30,7 @@ function createLetterRepository( } export function createDependenciesContainer(): Deps { - const log = pino(); + const log = createLogger({ logLevel: envVars.PINO_LOG_LEVEL }); return { letterRepo: createLetterRepository(log, envVars), diff --git a/lambdas/upsert-letter/src/config/env.ts b/lambdas/upsert-letter/src/config/env.ts index ef527258f..8230088bc 100644 --- a/lambdas/upsert-letter/src/config/env.ts +++ b/lambdas/upsert-letter/src/config/env.ts @@ -16,6 +16,7 @@ const EnvVarsSchema = z.object({ const parsed = JSON.parse(str); return LetterVariantSchema.parse(parsed); }), + PINO_LOG_LEVEL: z.coerce.string().optional(), }); export type EnvVars = z.infer; diff --git a/lambdas/upsert-letter/src/handler/__tests__/upsert-handler.test.ts b/lambdas/upsert-letter/src/handler/__tests__/upsert-handler.test.ts index 3f4341340..73826cd53 100644 --- a/lambdas/upsert-letter/src/handler/__tests__/upsert-handler.test.ts +++ b/lambdas/upsert-letter/src/handler/__tests__/upsert-handler.test.ts @@ -322,8 +322,11 @@ describe("createUpsertLetterHandler", () => { expect(result.batchItemFailures).toHaveLength(1); expect(result.batchItemFailures[0].itemIdentifier).toBe("bad-json"); - expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][1]).toBe( - "Error processing upsert of record bad-json", + expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][0]).toEqual( + expect.objectContaining({ + description: "Error processing upsert of record", + messageId: "bad-json", + }), ); expect(mockedDeps.letterRepo.putLetter).not.toHaveBeenCalled(); }); @@ -349,8 +352,11 @@ describe("createUpsertLetterHandler", () => { "bad-notification-schema", ); - expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][1]).toBe( - "Error processing upsert of record bad-notification-schema", + expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][0]).toEqual( + expect.objectContaining({ + description: "Error processing upsert of record", + messageId: "bad-notification-schema", + }), ); expect(mockedDeps.letterRepo.putLetter).not.toHaveBeenCalled(); }); @@ -378,8 +384,11 @@ describe("createUpsertLetterHandler", () => { expect(result.batchItemFailures[0].itemIdentifier).toBe("bad-event-type"); expect(mockedDeps.letterRepo.putLetter).not.toHaveBeenCalled(); expect(mockedDeps.letterRepo.updateLetterStatus).not.toHaveBeenCalled(); - expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][1]).toBe( - "Error processing upsert of record bad-event-type", + expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][0]).toEqual( + expect.objectContaining({ + description: "Error processing upsert of record", + messageId: "bad-event-type", + }), ); }); @@ -406,8 +415,11 @@ describe("createUpsertLetterHandler", () => { expect(result.batchItemFailures[0].itemIdentifier).toBe("bad-event-type"); expect(mockedDeps.letterRepo.putLetter).not.toHaveBeenCalled(); expect(mockedDeps.letterRepo.updateLetterStatus).not.toHaveBeenCalled(); - expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][1]).toBe( - "Error processing upsert of record bad-event-type", + expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][0]).toEqual( + expect.objectContaining({ + description: "Error processing upsert of record", + messageId: "bad-event-type", + }), ); }); @@ -437,8 +449,11 @@ describe("createUpsertLetterHandler", () => { expect(result.batchItemFailures[0].itemIdentifier).toBe("bad-event-schema"); expect(mockedDeps.letterRepo.putLetter).not.toHaveBeenCalled(); expect(mockedDeps.letterRepo.updateLetterStatus).not.toHaveBeenCalled(); - expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][1]).toBe( - "Error processing upsert of record bad-event-schema", + expect((mockedDeps.logger.error as jest.Mock).mock.calls[0][0]).toEqual( + expect.objectContaining({ + description: "Error processing upsert of record", + messageId: "bad-event-schema", + }), ); }); diff --git a/lambdas/upsert-letter/src/handler/upsert-handler.ts b/lambdas/upsert-letter/src/handler/upsert-handler.ts index a1b2ea08b..0422ff184 100644 --- a/lambdas/upsert-letter/src/handler/upsert-handler.ts +++ b/lambdas/upsert-letter/src/handler/upsert-handler.ts @@ -50,6 +50,13 @@ function getOperationFromType(type: string): UpsertOperation { supplierSpec.specId, // use specId for now ); await deps.letterRepo.putLetter(letterToInsert); + + deps.logger.info({ + description: "Inserted letter", + eventId: preparedRequest.id, + letterId: letterToInsert.id, + supplierId: letterToInsert.supplierId, + }); }, }; if (type.startsWith("uk.nhs.notify.supplier-api.letter")) @@ -60,6 +67,13 @@ function getOperationFromType(type: string): UpsertOperation { const supplierEvent = request as LetterEvent; const letterToUpdate: UpdateLetter = mapToUpdateLetter(supplierEvent); await deps.letterRepo.updateLetterStatus(letterToUpdate); + + deps.logger.info({ + description: "Inserted letter", + eventId: supplierEvent.id, + letterId: letterToUpdate.id, + supplierId: letterToUpdate.supplierId, + }); }, }; throw new Error(`Unknown operation from type=${type}`); @@ -164,16 +178,23 @@ export default function createUpsertLetterHandler(deps: Deps): SQSHandler { const letterEvent: unknown = removeEventBridgeWrapper(snsEvent); + deps.logger.info({ + description: "Extracted letter event", + messageId: record.messageId, + }); + const type = getType(letterEvent); const operation = getOperationFromType(type); await runUpsert(operation, letterEvent, deps); } catch (error) { - deps.logger.error( - { err: error, message: record.body }, - `Error processing upsert of record ${record.messageId}`, - ); + deps.logger.error({ + description: "Error processing upsert of record", + err: error, + messageId: record.messageId, + message: record.body, + }); batchItemFailures.push({ itemIdentifier: record.messageId }); } }); diff --git a/package-lock.json b/package-lock.json index 64a58b073..c7ec7df8a 100644 --- a/package-lock.json +++ b/package-lock.json @@ -125,7 +125,7 @@ }, "internal/events": { "name": "@nhsdigital/nhs-notify-event-schemas-supplier-api", - "version": "1.0.9", + "version": "1.0.10", "license": "MIT", "dependencies": { "@asyncapi/bundler": "^0.6.4", @@ -151,6 +151,7 @@ "version": "0.1.0", "license": "MIT", "dependencies": { + "pino": "^9.7.0", "zod": "^4.1.11" }, "devDependencies": { @@ -167,6 +168,28 @@ "typescript": "^5.9.3" } }, + "internal/helpers/node_modules/pino": { + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-9.14.0.tgz", + "integrity": "sha512-8OEwKp5juEvb/MjpIc4hjqfgCNysrS94RIOMXYvpYCdm/jglrKEiAYmiumbmGhCvs+IcInsphYDFwqrjr7398w==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^2.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^3.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, "lambdas/api-handler": { "name": "nhs-notify-supplier-api-handler", "version": "0.0.1", @@ -794,6 +817,7 @@ "@aws-sdk/client-dynamodb": "^3.858.0", "@aws-sdk/lib-dynamodb": "^3.858.0", "@internal/datastore": "*", + "@internal/helpers": "*", "@nhsdigital/nhs-notify-event-schemas-letter-rendering": "^2.0.1", "@nhsdigital/nhs-notify-event-schemas-letter-rendering-v1": "npm:@nhsdigital/nhs-notify-event-schemas-letter-rendering@^1.1.5", "@nhsdigital/nhs-notify-event-schemas-supplier-api": "^1.0.8", @@ -21309,13 +21333,6 @@ "node": ">=18.17" } }, - "node_modules/undici-types": { - "version": "7.18.2", - "resolved": "https://registry.npmjs.org/undici-types/-/undici-types-7.18.2.tgz", - "integrity": "sha512-AsuCzffGHJybSaRrmr5eHr81mwJU3kjw6M+uprWvCXiNeN9SOGwQ3Jn8jb8m3Z6izVgknn1R0FTCEAP2QrLY/w==", - "extraneous": true, - "license": "MIT" - }, "node_modules/universalify": { "version": "2.0.1", "resolved": "https://registry.npmjs.org/universalify/-/universalify-2.0.1.tgz",