From 0548ebb181fc47b64c70764d6d49faed0dfb6713 Mon Sep 17 00:00:00 2001 From: Caitlin Cooling Date: Wed, 11 Dec 2024 12:11:40 +0000 Subject: [PATCH 1/2] OJ-2708: Capture response latency for OTG API and add context to all lambda logs --- lambdas/ci-mapping/src/ci-mapping-handler.ts | 3 +- .../src/credential-subject-handler.ts | 5 +- lambdas/jwt-signer/src/jwt-signer-handler.ts | 3 +- lambdas/logging/log-helper.ts | 12 +++- .../{matching/src => logging}/metric-types.ts | 0 lambdas/logging/metrics-helper.ts | 23 ++++++++ lambdas/logging/tests/log-helper.test.ts | 21 ++++++- lambdas/logging/tests/metrics-helper.test.ts | 44 ++++++++++++++ lambdas/matching/src/matching-handler.ts | 58 ++++++++----------- .../matching/tests/matching-handler.test.ts | 19 ++++-- lambdas/otg-api/src/otg-api-handler.ts | 23 +++++++- lambdas/otg-api/tests/otg-api-handler.test.ts | 50 +++++++++++++--- .../src/ssm-parameters-handler.ts | 3 +- lambdas/time-handler/src/time-handler.ts | 6 +- 14 files changed, 209 insertions(+), 61 deletions(-) rename lambdas/{matching/src => logging}/metric-types.ts (100%) create mode 100644 lambdas/logging/metrics-helper.ts create mode 100644 lambdas/logging/tests/metrics-helper.test.ts diff --git a/lambdas/ci-mapping/src/ci-mapping-handler.ts b/lambdas/ci-mapping/src/ci-mapping-handler.ts index 4ff2a1db..89bc29ce 100644 --- a/lambdas/ci-mapping/src/ci-mapping-handler.ts +++ b/lambdas/ci-mapping/src/ci-mapping-handler.ts @@ -10,13 +10,12 @@ import { getHmrcErrsCiRecord, ContraIndicator } from "./utils/ci-mapping-util"; import { CiMappingEvent } from "./ci-mapping-event"; import { LogHelper } from "../../logging/log-helper"; -const logHelper = new LogHelper(); - export class CiMappingHandler implements LambdaInterface { public async handler( event: CiMappingEvent, context: Context ): Promise> { + const logHelper = new LogHelper(context); logHelper.logEntry(context.functionName, event.govJourneyId); try { return getCIsForHmrcErrors(event); diff --git a/lambdas/credential-subject/src/credential-subject-handler.ts b/lambdas/credential-subject/src/credential-subject-handler.ts index 65e27f08..1c3eae16 100644 --- a/lambdas/credential-subject/src/credential-subject-handler.ts +++ b/lambdas/credential-subject/src/credential-subject-handler.ts @@ -9,7 +9,6 @@ import { import { LogHelper } from "../../logging/log-helper"; import { Context } from "aws-lambda"; -const logHelper = new LogHelper(); const credentialSubjectBuilder = new CredentialSubjectBuilder(); export class CredentialSubjectHandler implements LambdaInterface { @@ -17,8 +16,10 @@ export class CredentialSubjectHandler implements LambdaInterface { event: UserInfoEvent, context: Context ): Promise { + const logHelper = new LogHelper(context); + logHelper.logEntry(context.functionName, event.govJourneyId); + try { - logHelper.logEntry(context.functionName, event.govJourneyId); return credentialSubjectBuilder .setPersonalNumber(event?.nino) .addNames(this.convertToCredentialSubjectNames(event)) diff --git a/lambdas/jwt-signer/src/jwt-signer-handler.ts b/lambdas/jwt-signer/src/jwt-signer-handler.ts index 15596a27..27198658 100644 --- a/lambdas/jwt-signer/src/jwt-signer-handler.ts +++ b/lambdas/jwt-signer/src/jwt-signer-handler.ts @@ -14,8 +14,6 @@ import { import { LogHelper } from "../../logging/log-helper"; import { Context } from "aws-lambda"; -const logHelper = new LogHelper(); - export class JwtSignerHandler implements LambdaInterface { constructor(private kmsClient: KMSClient) {} @@ -23,6 +21,7 @@ export class JwtSignerHandler implements LambdaInterface { event: SignerPayLoad, context: Context ): Promise { + const logHelper = new LogHelper(context); logHelper.logEntry(context.functionName, event.govJourneyId); const parsedHeader = JSON.parse(event.header) as SignerHeader; diff --git a/lambdas/logging/log-helper.ts b/lambdas/logging/log-helper.ts index db0fe72e..6ef7e6b6 100644 --- a/lambdas/logging/log-helper.ts +++ b/lambdas/logging/log-helper.ts @@ -1,7 +1,14 @@ import { Logger } from "@aws-lambda-powertools/logger"; +import { Context } from "aws-lambda"; export class LogHelper { - constructor(public logger = new Logger()) {} + constructor( + context: Context, + public logger = new Logger() + ) { + logger.addContext(context); + } + logEntry(source: string, govJourneyId: string) { this.logger.appendKeys({ govuk_signin_journey_id: govJourneyId, @@ -10,6 +17,7 @@ export class LogHelper { `${source} invoked with government journey id: ${govJourneyId}` ); } + logError(source: string, govJourneyId: string, message: string) { this.logger.error({ message: `Error in ${source}: ${message}`, @@ -17,5 +25,3 @@ export class LogHelper { }); } } - -export const { logEntry, logError } = new LogHelper(); diff --git a/lambdas/matching/src/metric-types.ts b/lambdas/logging/metric-types.ts similarity index 100% rename from lambdas/matching/src/metric-types.ts rename to lambdas/logging/metric-types.ts diff --git a/lambdas/logging/metrics-helper.ts b/lambdas/logging/metrics-helper.ts new file mode 100644 index 00000000..309467f6 --- /dev/null +++ b/lambdas/logging/metrics-helper.ts @@ -0,0 +1,23 @@ +import { Metrics, MetricUnits } from "@aws-lambda-powertools/metrics"; +import { MetricDimensions, MetricNames } from "./metric-types"; + +export class MetricsHelper { + singleMetric: Metrics; + + constructor(metrics = new Metrics()) { + this.singleMetric = metrics.singleMetric(); + } + + captureResponseLatency(start: number, metricValue: string): number { + const latency = Math.floor(performance.now()) - start; + + this.singleMetric.addDimension(MetricDimensions.HTTP, metricValue); + this.singleMetric.addMetric( + MetricNames.ResponseLatency, + MetricUnits.Milliseconds, + latency + ); + + return latency; + } +} diff --git a/lambdas/logging/tests/log-helper.test.ts b/lambdas/logging/tests/log-helper.test.ts index 1c7c5696..fad64856 100644 --- a/lambdas/logging/tests/log-helper.test.ts +++ b/lambdas/logging/tests/log-helper.test.ts @@ -1,18 +1,37 @@ import { LogHelper } from "../log-helper"; +import { Context } from "aws-lambda"; jest.mock("@aws-lambda-powertools/logger", () => ({ Logger: jest.fn(() => ({ appendKeys: jest.fn(), + addContext: jest.fn(), info: jest.fn(), error: jest.fn(), })), })); +export const context: Context = { + awsRequestId: "", + callbackWaitsForEmptyEventLoop: false, + functionName: "", + functionVersion: "", + invokedFunctionArn: "", + logGroupName: "", + logStreamName: "", + memoryLimitInMB: "", + done(): void {}, + fail(): void {}, + getRemainingTimeInMillis(): number { + return 0; + }, + succeed(): void {}, +}; + describe("log-helper", () => { let logHelper: LogHelper; beforeEach(() => { - logHelper = new LogHelper(); + logHelper = new LogHelper(context); }); afterEach(() => { diff --git a/lambdas/logging/tests/metrics-helper.test.ts b/lambdas/logging/tests/metrics-helper.test.ts new file mode 100644 index 00000000..a594d1f2 --- /dev/null +++ b/lambdas/logging/tests/metrics-helper.test.ts @@ -0,0 +1,44 @@ +import { MetricUnits } from "@aws-lambda-powertools/metrics"; +import { MetricsHelper } from "../metrics-helper"; +import { MetricDimensions, MetricNames } from "../metric-types"; + +jest.mock("@aws-lambda-powertools/metrics", () => ({ + ...jest.requireActual("@aws-lambda-powertools/metrics"), + Metrics: jest.fn(() => ({ + singleMetric: () => ({ + addDimension: jest.fn(), + addMetric: jest.fn(), + }), + })), +})); + +const monday31st2021InMilliseconds = 1622502000000; +jest.spyOn(performance, "now").mockReturnValue(monday31st2021InMilliseconds); + +describe("metrics-helper", () => { + let metricsHelper: MetricsHelper; + + beforeEach(() => { + metricsHelper = new MetricsHelper(); + }); + + afterEach(() => { + jest.clearAllMocks(); + }); + + it("should add dimension and metric", () => { + const value = "TestHandler"; + const latency = metricsHelper.captureResponseLatency(1622501999000, value); + + expect(latency).toEqual(1000); + expect(metricsHelper.singleMetric.addDimension).toHaveBeenCalledWith( + MetricDimensions.HTTP, + value + ); + expect(metricsHelper.singleMetric.addMetric).toHaveBeenCalledWith( + MetricNames.ResponseLatency, + MetricUnits.Milliseconds, + latency + ); + }); +}); diff --git a/lambdas/matching/src/matching-handler.ts b/lambdas/matching/src/matching-handler.ts index c8bba685..1fa36b73 100644 --- a/lambdas/matching/src/matching-handler.ts +++ b/lambdas/matching/src/matching-handler.ts @@ -1,19 +1,30 @@ import { Logger } from "@aws-lambda-powertools/logger"; import { LambdaInterface } from "@aws-lambda-powertools/commons"; -import { Metrics, MetricUnits } from "@aws-lambda-powertools/metrics"; import { Context } from "aws-lambda"; +import { LogHelper } from "../../logging/log-helper"; +import { MetricsHelper } from "../../logging/metrics-helper"; import { MatchEvent } from "./match-event"; -import { MetricDimensions, MetricNames } from "./metric-types"; import { Names } from "./name-part"; -export const logger = new Logger(); -const metrics = new Metrics(); +const metricsHelper = new MetricsHelper(); export class MatchingHandler implements LambdaInterface { + logger: Logger; + + constructor() { + this.logger = new Logger(); + } + public async handler( event: MatchEvent, context: Context ): Promise<{ status: string; body: string; txn: string }> { + const logHelper = new LogHelper(context, this.logger); + logHelper.logEntry( + context.functionName, + event.user.govuk_signin_journey_id + ); + try { const namePart = extractName(event.userDetails.names); @@ -39,16 +50,19 @@ export class MatchingHandler implements LambdaInterface { nino: event.nino, }), }); - const latency = captureResponseLatency(requestStartTime); - logger.info({ - message: "API response received", + + const latency = metricsHelper.captureResponseLatency( + requestStartTime, + "MatchingHandler" + ); + this.logger.info({ + message: "HMRC API response received", url: event.apiURL, status: response.status, latencyInMs: latency, }); const txn = response.headers.get("x-amz-cf-id") ?? ""; - addLogEntry(event, txn, context); const contentType = response.headers.get("content-type"); if (contentType?.includes("application/json")) { @@ -57,7 +71,7 @@ export class MatchingHandler implements LambdaInterface { try { responseBody = JSON.parse(responseBody); } catch (error) { - logger.info( + this.logger.info( "Received a non-json body for the application/json content-type" ); } @@ -76,7 +90,7 @@ export class MatchingHandler implements LambdaInterface { } } catch (error: unknown) { const message = error instanceof Error ? error.message : String(error); - logger.error({ + this.logger.error({ message: `Error in ${context.functionName}: ${message}`, govuk_signin_journey_id: event.user.govuk_signin_journey_id, }); @@ -88,30 +102,6 @@ export class MatchingHandler implements LambdaInterface { const handlerClass = new MatchingHandler(); export const lambdaHandler = handlerClass.handler.bind(handlerClass); -function addLogEntry(event: MatchEvent, txn: string | null, context: Context) { - logger.appendKeys({ - govuk_signin_journey_id: event.user.govuk_signin_journey_id, - txn: txn, - }); - logger.info( - `${context.functionName} invoked with government journey id: ${event.user.govuk_signin_journey_id}` - ); -} - -function captureResponseLatency(start: number): number { - const latency = Math.floor(performance.now()) - start; - - const singleMetric = metrics.singleMetric(); - singleMetric.addDimension(MetricDimensions.HTTP, "MatchingHandler"); - singleMetric.addMetric( - MetricNames.ResponseLatency, - MetricUnits.Milliseconds, - latency - ); - - return latency; -} - function extractName(name: Names): { firstName: string; lastName: string } { let firstName = ""; let surname = ""; diff --git a/lambdas/matching/tests/matching-handler.test.ts b/lambdas/matching/tests/matching-handler.test.ts index 30dd388b..22caaedf 100644 --- a/lambdas/matching/tests/matching-handler.test.ts +++ b/lambdas/matching/tests/matching-handler.test.ts @@ -1,4 +1,4 @@ -import { MatchingHandler, logger } from "../src/matching-handler"; +import { MatchingHandler } from "../src/matching-handler"; import { MatchEvent } from "../src/match-event"; import { Context } from "aws-lambda"; import { Names } from "../src/name-part"; @@ -8,6 +8,17 @@ jest.mock("@aws-lambda-powertools/logger", () => ({ info: jest.fn(), error: jest.fn(), appendKeys: jest.fn(), + addContext: jest.fn(), + })), +})); + +jest.mock("@aws-lambda-powertools/metrics", () => ({ + ...jest.requireActual("@aws-lambda-powertools/metrics"), + Metrics: jest.fn(() => ({ + singleMetric: () => ({ + addDimension: jest.fn(), + addMetric: jest.fn(), + }), })), })); @@ -65,7 +76,6 @@ describe("matching-handler", () => { afterEach(() => { jest.clearAllMocks(); - jest.resetAllMocks(); }); it("should return a matching response for a given nino and user", async () => { @@ -163,9 +173,10 @@ describe("matching-handler", () => { const matchingHandler = new MatchingHandler(); await matchingHandler.handler(testEvent, {} as Context); - expect(logger.info).toHaveBeenCalledWith( + expect(matchingHandler.logger.info).toHaveBeenNthCalledWith( + 2, expect.objectContaining({ - message: "API response received", + message: "HMRC API response received", url: testEvent.apiURL, status: 200, latencyInMs: expect.anything(), diff --git a/lambdas/otg-api/src/otg-api-handler.ts b/lambdas/otg-api/src/otg-api-handler.ts index 91bb89ac..a6ae6d9d 100644 --- a/lambdas/otg-api/src/otg-api-handler.ts +++ b/lambdas/otg-api/src/otg-api-handler.ts @@ -1,21 +1,42 @@ import { LambdaInterface } from "@aws-lambda-powertools/commons"; +import { Logger } from "@aws-lambda-powertools/logger"; import { LogHelper } from "../../logging/log-helper"; +import { MetricsHelper } from "../../logging/metrics-helper"; import { Context } from "aws-lambda"; -const logHelper = new LogHelper(); +const metricsHelper = new MetricsHelper(); export class OTGApiHandler implements LambdaInterface { + logger: Logger; + + constructor() { + this.logger = new Logger(); + } + public async handler( event: { apiURL: string; govJourneyId: string }, context: Context ): Promise<{ token: string; expiry: number }> { + const logHelper = new LogHelper(context, this.logger); logHelper.logEntry(context.functionName, event.govJourneyId); try { + const requestStartTime = Math.floor(performance.now()); const response = await fetch(event.apiURL, { method: "GET", }); + const latency = metricsHelper.captureResponseLatency( + requestStartTime, + "OTGHandler" + ); + this.logger.info({ + message: "OTG API response received", + url: event.apiURL, + status: response.status, + latencyInMs: latency, + }); + if (response.ok) { const body = await response.json(); const expiry = body.expiry; diff --git a/lambdas/otg-api/tests/otg-api-handler.test.ts b/lambdas/otg-api/tests/otg-api-handler.test.ts index d00c946b..1c3153a1 100644 --- a/lambdas/otg-api/tests/otg-api-handler.test.ts +++ b/lambdas/otg-api/tests/otg-api-handler.test.ts @@ -1,12 +1,25 @@ import { Context } from "aws-lambda"; import { OTGApiHandler } from "../src/otg-api-handler"; +jest.mock("@aws-lambda-powertools/logger", () => ({ + Logger: jest.fn().mockImplementation(() => ({ + info: jest.fn(), + error: jest.fn(), + appendKeys: jest.fn(), + addContext: jest.fn(), + })), +})); + const mockGovJourneyId = "test-government-journey-id"; +const testEvent = { + apiURL: + "https://apigwId-vpceId.execute-api.eu-west-2.amazonaws.com/dev/token/?tokenType=stub", + govJourneyId: mockGovJourneyId, +}; describe("otg-api-handler", () => { beforeEach(() => { jest.clearAllMocks(); - jest.resetAllMocks(); }); it("should return a token and expiry", async () => { @@ -23,16 +36,39 @@ describe("otg-api-handler", () => { }); const otgApiHandler = new OTGApiHandler(); - const event = { - apiURL: - "https://apigwId-vpceId.execute-api.eu-west-2.amazonaws.com/dev/token/?tokenType=stub", - govJourneyId: mockGovJourneyId, - }; - const result = await otgApiHandler.handler(event, {} as Context); + const result = await otgApiHandler.handler(testEvent, {} as Context); expect(result.token).toBe(mockToken); expect(result.expiry).toBe(mockExpiry); }); + it("should log API latency", async () => { + const mockToken = "goodToken"; + const mockExpiry = Date.now() + 600000; + + global.fetch = jest.fn(); + (global.fetch as jest.Mock).mockResolvedValueOnce({ + json: jest.fn().mockResolvedValueOnce({ + token: mockToken, + expiry: mockExpiry, + }), + status: 200, + ok: true, + }); + + const otgApiHandler = new OTGApiHandler(); + await otgApiHandler.handler(testEvent, {} as Context); + + expect(otgApiHandler.logger.info).toHaveBeenNthCalledWith( + 2, + expect.objectContaining({ + message: "OTG API response received", + url: testEvent.apiURL, + status: 200, + latencyInMs: expect.anything(), + }) + ); + }); + it("should throw when an invalid response is returned from OTG", async () => { global.fetch = jest.fn(); (global.fetch as jest.Mock).mockResolvedValueOnce({ diff --git a/lambdas/ssm-parameters/src/ssm-parameters-handler.ts b/lambdas/ssm-parameters/src/ssm-parameters-handler.ts index 45483cdf..57eb1ef0 100644 --- a/lambdas/ssm-parameters/src/ssm-parameters-handler.ts +++ b/lambdas/ssm-parameters/src/ssm-parameters-handler.ts @@ -7,13 +7,12 @@ import { Context } from "aws-lambda"; const cacheTtlInSecond = Number(process.env.POWERTOOLS_PARAMETERS_MAX_AGE) || 300; -const logHelper = new LogHelper(); - export class SsmParametersHandler implements LambdaInterface { public async handler( event: { parameters: string[]; govJourneyId: string }, context: Context ): Promise { + const logHelper = new LogHelper(context); logHelper.logEntry(context.functionName, event.govJourneyId); if (!Array.isArray(event.parameters)) { diff --git a/lambdas/time-handler/src/time-handler.ts b/lambdas/time-handler/src/time-handler.ts index 6b0c3454..f04503fa 100644 --- a/lambdas/time-handler/src/time-handler.ts +++ b/lambdas/time-handler/src/time-handler.ts @@ -5,9 +5,9 @@ import { LogHelper } from "../../logging/log-helper"; import { Context } from "aws-lambda"; export class TimeHandler implements LambdaInterface { - constructor(private readonly logger: LogHelper = new LogHelper()) {} public async handler(event: TimeEvent, context: Context) { - this.logger.logEntry(context.functionName, event.govJourneyId); + const logHelper = new LogHelper(context); + logHelper.logEntry(context.functionName, event.govJourneyId); try { return { @@ -17,7 +17,7 @@ export class TimeHandler implements LambdaInterface { }; } catch (error: unknown) { const message = error instanceof Error ? error.message : String(error); - this.logger.logError(context.functionName, event.govJourneyId, message); + logHelper.logError(context.functionName, event.govJourneyId, message); throw error; } } From bea730465d66c89667f61135f0a34c42ab97414a Mon Sep 17 00:00:00 2001 From: Caitlin Cooling Date: Wed, 11 Dec 2024 15:46:22 +0000 Subject: [PATCH 2/2] OJ-2708: Changes node version in unit tests workflow --- .github/workflows/run-unit-tests.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 3bc4cc4e..100a0717 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -27,6 +27,7 @@ jobs: uses: actions/setup-node@v4 with: cache: npm + node-version: 20 - name: Install dependencies run: npm ci