Merge pull request #528 from govuk-one-login/OJ-2708-logs

OJ-2708: Add context to lambda logs

.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

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<Array<ContraIndicator>> {
+    const logHelper = new LogHelper(context);
     logHelper.logEntry(context.functionName, event.govJourneyId);
     try {
       return getCIsForHmrcErrors(event);

lambdas/credential-subject/src/credential-subject-handler.ts

@@ -9,16 +9,17 @@ 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 {
   public async handler(
     event: UserInfoEvent,
     context: Context
   ): Promise<CredentialSubject> {
+    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))

lambdas/jwt-signer/src/jwt-signer-handler.ts

@@ -14,15 +14,14 @@ 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) {}
 
   public async handler(
     event: SignerPayLoad,
     context: Context
   ): Promise<string> {
+    const logHelper = new LogHelper(context);
     logHelper.logEntry(context.functionName, event.govJourneyId);
 
     const parsedHeader = JSON.parse(event.header) as SignerHeader;

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,12 +17,11 @@ 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}`,
       govuk_signin_journey_id: govJourneyId,
     });
   }
 }
-
-export const { logEntry, logError } = new LogHelper();

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;
+  }
+}

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(() => {

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
+    );
+  });
+});

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 = "";

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(),

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;