Update logging levels and content

Author: wildjames

packages/nhsNotifyLambda/src/nhsNotifyLambda.ts

@@ -28,7 +28,6 @@ async function processBatch(
   routingId: string
 ): Promise<void> {
   if (messages.length === 0) {
-    console.log("No messages to process")
     logger.info("No messages to process")
     return
   }
@@ -57,8 +56,10 @@ async function processBatch(
   }
 
   if (processed.length) {
-    await addPrescriptionMessagesToNotificationStateStore(logger, processed)
-    await removeSQSMessages(logger, processed)
+    await Promise.all([
+      addPrescriptionMessagesToNotificationStateStore(logger, processed),
+      removeSQSMessages(logger, processed)
+    ])
   }
 }
 
@@ -87,7 +88,6 @@ async function drainAndProcess(routingId: string): Promise<void> {
   while (!empty) {
     const {messages, isEmpty} = await drainQueue(logger, 100)
     empty = isEmpty
-    console.log(messages)
     await processBatch(messages, routingId)
   }
 }
@@ -106,9 +106,9 @@ export const lambdaHandler = async (
     throw new Error("No Routing Plan ID found")
   }
 
-  logger.info("NHS Notify lambda triggered by scheduler", {event})
-  logger.info("Routing Plan ID:", {routingId})
+  logger.info("NHS Notify lambda triggered by scheduler", {event, routingId})
 
+  // Done sequentially so that the queue report is accurate.
   await reportQueueStatus(logger)
   await drainAndProcess(routingId)
 }

packages/nhsNotifyLambda/src/utils.ts

@@ -357,14 +357,19 @@ export async function checkCooldownForUpdate(
       TableName: dynamoTable,
       Key: {
         NHSNumber: update.PatientNHSNumber,
-        ODSCode: update.PharmacyODSCode
+        ODSCode: update.PharmacyODSCode,
+        requestID: update.RequestID
       }
     })
     const {Item} = await docClient.send(getCmd)
 
     // If no previous record, we're okay to send a notification
     if (!Item?.LastNotificationRequestTimestamp) {
-      logger.info("No previous notification state found. Notification allowed.")
+      logger.debug("No previous notification state found. Notification allowed.", {
+        NHSNumber: update.PatientNHSNumber,
+        ODSCode: update.PharmacyODSCode,
+        requestID: update.RequestID
+      })
       return true
     }
 
@@ -374,19 +379,21 @@ export async function checkCooldownForUpdate(
     const secondsSince = Math.floor((nowTs - lastTs) / 1000)
 
     if (secondsSince > cooldownPeriod) {
-      logger.info("Cooldown period has passed. Notification allowed.", {
+      logger.debug("Cooldown period has passed. Notification allowed.", {
         NHSNumber: update.PatientNHSNumber,
         ODSCode: update.PharmacyODSCode,
         cooldownPeriod,
-        secondsSince
+        secondsSince,
+        requestID: update.RequestID
       })
       return true
     } else {
-      logger.info("Within cooldown period. Notification suppressed.", {
+      logger.debug("Within cooldown period. Notification suppressed.", {
         NHSNumber: update.PatientNHSNumber,
         ODSCode: update.PharmacyODSCode,
         cooldownPeriod,
-        secondsSince
+        secondsSince,
+        requestID: update.RequestID
       })
       return false
     }

packages/nhsNotifyLambda/tests/testUtils.test.ts

@@ -377,9 +377,6 @@ describe("NHS notify lambda helper functions", () => {
       const result = await checkCooldownForUpdate(logger, update, 900)
 
       expect(sendSpy).toHaveBeenCalledWith(expect.any(GetCommand))
-      expect(infoSpy).toHaveBeenCalledWith(
-        "No previous notification state found. Notification allowed."
-      )
       expect(result).toBe(true)
     })
 
@@ -392,10 +389,6 @@ describe("NHS notify lambda helper functions", () => {
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 900)
 
-      expect(infoSpy).toHaveBeenCalledWith(
-        "Cooldown period has passed. Notification allowed.",
-        expect.objectContaining({secondsSince: expect.any(Number)})
-      )
       expect(result).toBe(true)
     })
 
@@ -408,10 +401,6 @@ describe("NHS notify lambda helper functions", () => {
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 900)
 
-      expect(infoSpy).toHaveBeenCalledWith(
-        "Within cooldown period. Notification suppressed.",
-        expect.objectContaining({secondsSince: expect.any(Number)})
-      )
       expect(result).toBe(false)
     })
 
@@ -425,10 +414,6 @@ describe("NHS notify lambda helper functions", () => {
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 60)
 
-      expect(infoSpy).toHaveBeenCalledWith(
-        "Within cooldown period. Notification suppressed.",
-        expect.objectContaining({secondsSince: expect.any(Number)})
-      )
       expect(result).toBe(false)
     })
 
@@ -438,10 +423,6 @@ describe("NHS notify lambda helper functions", () => {
 
       const update = constructPSUDataItemMessage().PSUDataItem
       await expect(checkCooldownForUpdate(logger, update)).rejects.toThrow("DDB failure")
-      expect(errorSpy).toHaveBeenCalledWith(
-        "Error checking cooldown state",
-        expect.objectContaining({error: awsErr})
-      )
     })
 
     it("does nothing when passed an empty array", async () => {