Fix: [AEA-5722] - Fix cooldown checking bug in notify processor lambda (#2152)

## Summary

- Routine Change

### Details

A small number of patients are getting lots of notifications. 

The cooldown check was only grabbing one record from the table - I'd
thought that if you sort by ODS code, then the latest record would be at
the top. This is not true, so we can be checking against old records
when newer ones exist.

In some rare cases (approx 1 in 10,000), a patient may get a LOT of PSU
requests about their medications. In one case study, a patient had 61
distinct PSU requests pertaining to 6 prescription IDs, of which 24
requests were ready to collect. All of that was from one ODS code. This
resulted in 5 SQS messages being posted ~5 minutes apart. However, when
the cooldown check came for subsequent requests, it always passed. I
believe this is because the cooldown check is essentially a `return
true` check once there are enough records.

This PR fixes this bug by instead grabbing all records, and then taking
the maximum timestamp and checking if that is within the cooldown
period.

Author: wildjames

packages/nhsNotifyLambda/src/utils/dynamo.ts

@@ -50,14 +50,18 @@ export async function addPrescriptionMessagesToNotificationStateStore(
         TableName: dynamoTable,
         Item: item
       }))
-      logger.info("Upserted prescription")
+      logger.debug("Upserted prescription")
     } catch (err) {
       logger.error("Failed to write to DynamoDB", {
         error: err,
         item
       })
       throw err
     }
+    logger.info(
+      "Finished upserting records to the dynamo table",
+      {nhsNumbers: dataArray.map(el => el.PSUDataItem.PatientNHSNumber)}
+    )
   }
 }
 
@@ -80,17 +84,15 @@ export async function checkCooldownForUpdate(
   }
 
   try {
-    // Retrieve the last notification state for this patient/pharmacy combo
+    // Retrieve the notification states for this patient/pharmacy combo
     const q = new QueryCommand({
       TableName: dynamoTable,
       IndexName: "PatientPharmacyIndex",
       KeyConditionExpression: "NHSNumber = :n AND ODSCode = :o",
       ExpressionAttributeValues: {
         ":n": {S: update.PatientNHSNumber},
         ":o": {S: update.PharmacyODSCode}
-      },
-      ScanIndexForward: false, // descending on the ODSCode key (i.e. newest RequestID)
-      Limit: 1
+      }
     })
 
     let result
@@ -101,18 +103,41 @@ export async function checkCooldownForUpdate(
       throw err
     }
 
-    const Item = result.Items?.[0]
-    if (!Item?.LastNotificationRequestTimestamp) {
-      logger.debug("No previous notification state found. Notification allowed.", {
-        NHSNumber: update.PatientNHSNumber,
-        ODSCode: update.PharmacyODSCode,
-        requestID: update.RequestID
-      })
+    const items = result.Items ?? []
+
+    if (items.length === 0) {
+      logger.debug(
+        "No previous notification states. Notification allowed",
+        {
+          NHSNumber: update.PatientNHSNumber,
+          ODSCode: update.PharmacyODSCode,
+          requestID: update.RequestID
+        }
+      )
       return true
     }
 
+    const timestamps = items
+      .map(i => i.LastNotificationRequestTimestamp?.S)
+      .filter((ts): ts is string => Boolean(ts)) // If we get some weird variable type, ignore it
+      .map(ts => new Date(ts).getTime())
+
+    if (!timestamps.length) {
+      logger.debug(
+        "No valid timestamps found in the returned records. " +
+        "Assuming something is broken for this patient, and blocking notifications",
+        {
+          LastNotificationRequestTimestamps: items.map(i => i.LastNotificationRequestTimestamp?.S),
+          NHSNumber: update.PatientNHSNumber,
+          ODSCode: update.PharmacyODSCode,
+          requestID: update.RequestID
+        }
+      )
+      return false
+    }
+
     // Compute seconds since last notification
-    const lastTs = new Date(Item.LastNotificationRequestTimestamp.S as string).getTime()
+    const lastTs = Math.max(...timestamps)
     const nowTs = Date.now()
     const secondsSince = Math.floor((nowTs - lastTs) / 1000)
 

packages/nhsNotifyLambda/tests/testUtils.test.ts

@@ -319,11 +319,7 @@ describe("NHS notify lambda helper functions", () => {
         addPrescriptionMessagesToNotificationStateStore(logger, [item])
       ).rejects.toThrow("AWS error")
 
-      // first info for count
-      expect(infoSpy).toHaveBeenCalledWith(
-        "Attempting to push data to DynamoDB",
-        {count: 1}
-      )
+      expect(sendSpy).toHaveBeenCalledTimes(1)
       // error log includes the item that failed, and the error
       expect(errorSpy).toHaveBeenCalledWith(
         "Failed to write to DynamoDB",
@@ -350,8 +346,6 @@ describe("NHS notify lambda helper functions", () => {
       const cmd = sendSpy.mock.calls[0][0] as PutCommand
       expect(cmd).toBeInstanceOf(PutCommand)
 
-      expect(infoSpy).toHaveBeenCalledWith("Upserted prescription")
-
       // No errors
       expect(errorSpy).not.toHaveBeenCalled()
     })
@@ -408,21 +402,33 @@ describe("NHS notify lambda helper functions", () => {
 
     it("returns true when last notification is older than default cooldown", async () => {
       const pastTs = new Date(Date.now() - (1000 * 901)).toISOString() // 901s ago
-      sendSpy.mockImplementationOnce(() =>
-        Promise.resolve({Item: {LastNotificationRequestTimestamp: pastTs}})
-      )
+      sendSpy.mockImplementationOnce(() => {
+        return {
+          Items: [
+            {LastNotificationRequestTimestamp: {S: new Date(Date.now() - 1000 * 5000).toISOString()}}, // very old
+            {LastNotificationRequestTimestamp: {S: pastTs}}
+          ]
+        }
+      })
 
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 900)
 
       expect(result).toBe(true)
     })
 
-    it("returns false when last notification is within default cooldown", async () => {
-      const recentTs = new Date(Date.now() - (1000 * 300)).toISOString() // 300s ago
-      sendSpy.mockImplementationOnce(() =>
-        Promise.resolve({Items: [{LastNotificationRequestTimestamp: recentTs}]})
-      )
+    it("returns false when ANY item is within the cooldown window", async () => {
+      const recentTs = new Date(Date.now() - 1000 * 300).toISOString() // 300s ago
+      const oldTs = new Date(Date.now() - 1000 * 10_000).toISOString() // old
+
+      sendSpy.mockImplementationOnce(() => {
+        return {
+          Items: [
+            {LastNotificationRequestTimestamp: {S: oldTs}},
+            {LastNotificationRequestTimestamp: {S: recentTs}} // within cooldown → should suppress
+          ]
+        }
+      })
 
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 900)
@@ -433,16 +439,34 @@ describe("NHS notify lambda helper functions", () => {
     it("honours a custom cooldownPeriod", async () => {
       // custom cooldown = 60 seconds, but timestamp is only 30s ago
       const recentTs = new Date(Date.now() - 30000).toISOString()
-      sendSpy.mockImplementationOnce(() =>
-        Promise.resolve({Items: [{LastNotificationRequestTimestamp: recentTs}]})
-      )
+      sendSpy.mockImplementationOnce(() => {
+        return {
+          Items: [{LastNotificationRequestTimestamp: {S: recentTs}}]
+        }
+      })
 
       const update = constructPSUDataItemMessage().PSUDataItem
       const result = await checkCooldownForUpdate(logger, update, 60)
 
       expect(result).toBe(false)
     })
 
+    it("returns false when items exist but none have valid timestamps", async () => {
+      sendSpy.mockImplementationOnce(() => {
+        return {
+          Items: [
+            {}, // no timestamp attribute
+            {SomeOtherField: {S: "foo"}}
+          ]
+        }
+      })
+
+      const update = constructPSUDataItemMessage().PSUDataItem
+      const result = await checkCooldownForUpdate(logger, update, 900)
+
+      expect(result).toBe(false)
+    })
+
     it("propagates and logs errors from DynamoDB", async () => {
       const awsErr = new Error("DDB failure")
       sendSpy.mockImplementationOnce(() => Promise.reject(awsErr))