Chore: [AEA-5970] - expand batched logs (#2437)

## Summary

- 🤖 Operational or Infrastructure Change

### Details

Instead of logging requests to Notify in the batches they are sent, log
individually to facilitate reporting.

---------

Signed-off-by: dependabot[bot] <[email protected]>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
Co-authored-by: Connor Avery <[email protected]>

Author: 3 people

package.json

@@ -52,6 +52,7 @@
   "dependencies": {
     "@psu-common/commonTypes": "^1.0.0",
     "@psu-common/middyErrorHandler": "^1.0.0",
+    "@psu-common/utilities": "^1.0.0",
     "esbuild": "^0.27.0"
   }
 }

packages/common/utilities/src/index.ts

@@ -1,2 +1,8 @@
-export {testPrescriptionsConfig, TestPrescriptionsConfig, getTestPrescriptions} from "./testConfig"
-export {initiatedSSMProvider} from "./ssmUtil"
+export {testPrescriptionsConfig, TestPrescriptionsConfig, getTestPrescriptions} from "./testConfig.js"
+export const LOG_MESSAGES = {
+  PSU0001: "Transitioning item status.",
+  PSU0002: "Notify request",
+  PSU0003: "Updated notification state"
+} as const
+
+export {initiatedSSMProvider} from "./ssmUtil.js"

packages/nhsNotifyLambda/src/utils/notify.ts

@@ -1,8 +1,9 @@
 import {Logger} from "@aws-lambda-powertools/logger"
 
 import axios from "axios"
-
 import {setupAxios} from "./axios"
+import {LOG_MESSAGES} from "@psu-common/utilities"
+
 import {
   NotifyDataItemMessage,
   CreateMessageBatchRequest,
@@ -96,6 +97,23 @@ async function makeFakeNotifyRequest(
   const messageStatus = "silent running"
   const messageBatchReference = crypto.randomUUID()
 
+  logNotificationRequest(logger, messageBatchReference, messages, data, messageStatus)
+
+  // Map each input item to a "successful" NotifyDataItemMessage
+  return data.map(item => {
+    return {
+      ...item,
+      messageBatchReference,
+      messageStatus,
+      notifyMessageId: crypto.randomUUID() // Create a dummy UUID
+    }
+  })
+}
+
+function logNotificationRequest(logger: Logger,
+  messageBatchReference: string, messages: Array<MessageBatchItem>,
+  data: Array<NotifyDataItemMessage>, messageStatus: string) {
+  // TODO: preserve legacy logging until reports updated
   logger.info("Requested notifications OK!", {
     messageBatchReference,
     messageReferences: messages.map(e => ({
@@ -105,15 +123,21 @@ async function makeFakeNotifyRequest(
     })),
     messageStatus: messageStatus
   })
-
-  // Map each input item to a "successful" NotifyDataItemMessage
-  return data.map(item => {
-    return {
-      ...item,
+  // Log each message individually for less memory intensive reporting
+  const code = Object.keys(LOG_MESSAGES)
+    .find(key => LOG_MESSAGES[key as keyof typeof LOG_MESSAGES] === LOG_MESSAGES.PSU0002)
+  messages.forEach((message, index) => {
+    const correspondingData = data.find(item => item.messageReference === message.messageReference)
+    logger.info(LOG_MESSAGES.PSU0002, {
+      reportCode: code,
       messageBatchReference,
-      messageStatus,
-      notifyMessageId: crypto.randomUUID() // Create a dummy UUID
-    }
+      messageIndex: index,
+      nhsNumber: message.recipient.nhsNumber,
+      messageReference: message.messageReference,
+      psuRequestId: correspondingData?.PSUDataItem.RequestID,
+      notifyMessageId: messageStatus === "silent running" ? crypto.randomUUID() : correspondingData?.notifyMessageId,
+      messageStatus: messageStatus
+    })
   })
 }
 
@@ -186,16 +210,7 @@ export async function makeRealNotifyRequest(
     // From here is just logging stuff for reporting, and mapping the response back to the input data
 
     if (resp.status === 201) {
-      logger.info("Requested notifications OK!", {
-        messageBatchReference,
-        messageReferences: messages.map(e => ({
-          nhsNumber: e.recipient.nhsNumber,
-          messageReference: e.messageReference,
-          psuRequestId: data.find((el) => el.messageReference === e.messageReference)?.PSUDataItem.RequestID,
-          pharmacyODSCode: e.originator.odsCode
-        })),
-        messageStatus: "requested"
-      })
+      logNotificationRequest(logger, messageBatchReference, messages, data, "requested")
 
       // Map each input item to a NotifyDataItemMessage, marking success and attaching the notify ID.
       // Only return items that belong to *this* batch (so we handle recursive splits correctly).

packages/nhsNotifyLambda/tests/testUtils.test.ts

@@ -6,6 +6,7 @@ import axiosRetry from "axios-retry"
 import {Logger} from "@aws-lambda-powertools/logger"
 import {DynamoDBDocumentClient, PutCommand} from "@aws-sdk/lib-dynamodb"
 import {GetQueueAttributesCommand, DeleteMessageBatchCommand, Message} from "@aws-sdk/client-sqs"
+import {LOG_MESSAGES} from "@psu-common/utilities"
 
 import {constructMessage, constructPSUDataItemMessage, mockSQSClient} from "./testHelpers"
 
@@ -564,6 +565,24 @@ describe("NHS notify lambda helper functions", () => {
         messageBatchReference: expect.any(String),
         messageReference: expect.any(String)
       })
+
+      // Check that both log messages are present
+      // TODO, first will be removed once reports updated
+      expect(infoSpy).toHaveBeenCalledWith(
+        "Requested notifications OK!",
+        expect.objectContaining({
+          messageBatchReference: expect.any(String),
+          messageReferences: expect.any(Array),
+          messageStatus: "requested"
+        })
+      )
+      expect(infoSpy).toHaveBeenCalledWith(
+        LOG_MESSAGES.PSU0002,
+        expect.objectContaining({
+          messageBatchReference: expect.any(String),
+          messageIndex: expect.any(Number)
+        })
+      )
     })
 
     it("handles non-ok response by marking all as failed", async () => {
@@ -814,6 +833,25 @@ describe("NHS notify lambda helper functions", () => {
         messageBatchReference: expect.any(String),
         messageReference: expect.any(String)
       })
+
+      // Check that both log messages are present
+      // TODO, first will be removed once reports updated
+      expect(infoSpy).toHaveBeenCalledWith(
+        "Requested notifications OK!",
+        expect.objectContaining({
+          messageBatchReference: expect.any(String),
+          messageReferences: expect.any(Array),
+          messageStatus: "silent running"
+        })
+      )
+      expect(infoSpy).toHaveBeenCalledWith(
+        LOG_MESSAGES.PSU0002,
+        expect.objectContaining({
+          reportCode: "PSU0002",
+          messageBatchReference: expect.any(String),
+          messageIndex: expect.any(Number)
+        })
+      )
     })
   })
 

packages/nhsNotifyUpdateCallback/src/helpers.ts

@@ -8,6 +8,7 @@ import {getSecret} from "@aws-lambda-powertools/parameters/secrets"
 import {createHmac, timingSafeEqual} from "crypto"
 
 import {LastNotificationStateType, NotificationUpdate} from "@psu-common/commonTypes"
+import {LOG_MESSAGES} from "@psu-common/utilities"
 
 import {CallbackResource, CallbackResponse, CallbackType} from "./types"
 
@@ -230,7 +231,7 @@ export async function updateNotificationsTable(
         }))
 
         logger.info(
-          "Updated notification state",
+          LOG_MESSAGES.PSU0003,
           {
             NotifyMessageID: item.NotifyMessageID,
             nhsNumber: item.NHSNumber,

packages/updatePrescriptionStatus/package.json

@@ -25,7 +25,6 @@
     "@nhs/fhir-middy-error-handler": "^2.1.59"
   },
   "devDependencies": {
-    "@psu-common/utilities": "^1.0.0",
     "@faker-js/faker": "^10.1.0",
     "@types/fhir": "^0.0.41",
     "aws-sdk-client-mock": "^4.1.0"