AEA-3477 set timeout on call to spine (#140)

- sets a lambda timeout of 50 seconds - sets timeout on call to spine of 45 seconds - adds function_request_id to splunk logs for lambda logs that are not JSON
NHSDigital · Aug 22, 2023 · c4f2eb0 · c4f2eb0
1 parent 9b3699b
commit c4f2eb0
Show file tree

Hide file tree

Showing 12 changed files with 642 additions and 396 deletions.
diff --git a/.vscode/prescriptionsforpatients.code-workspace b/.vscode/prescriptionsforpatients.code-workspace
@@ -44,7 +44,6 @@
 	"settings": {
 		"jest.disabledWorkspaceFolders": [
 			"prescriptionsforpatients-monorepo",
-			"packages/splunkProcessor",
 			"packages/getSecretLayer",
 			"packages/common"
 		],

diff --git a/Makefile b/Makefile
@@ -119,6 +119,7 @@ test: compile
 	npm run test --workspace packages/sandbox
 	npm run test --workspace packages/statusLambda
 	npm run test --workspace packages/spineClient
+	npm run test --workspace packages/splunkProcessor
 
 clean:
 	rm -rf packages/capabilityStatement/coverage

diff --git a/package-lock.json b/package-lock.json
diff --git a/packages/getMyPrescriptions/tests/test-handler.test.ts b/packages/getMyPrescriptions/tests/test-handler.test.ts
@@ -197,6 +197,19 @@ describe("Unit test for app handler", function () {
       "apigw-request-id": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef"
     })
   })
+
+  it("return error when spine does not respond in time", async () => {
+    mock.onGet("https://live/mm/patientfacingprescriptions").timeout()
+    const event: APIGatewayProxyEvent = JSON.parse(exampleEvent)
+    const result: APIGatewayProxyResult = (await handler(event, dummyContext)) as APIGatewayProxyResult
+
+    expect(result.statusCode).toBe(500)
+    expect(result.headers).toEqual({
+      "Content-Type": "application/fhir+json",
+      "Cache-Control": "no-cache"
+    })
+    expect(JSON.parse(result.body)).toEqual(responseStatus500)
+  })
 })
 
 export {}
diff --git a/packages/spineClient/src/live-spine-client.ts b/packages/spineClient/src/live-spine-client.ts
@@ -6,6 +6,8 @@ import axios, {AxiosResponse} from "axios"
 import {APIGatewayProxyEventHeaders} from "aws-lambda"
 import {extractNHSNumber} from "./extractNHSNumber"
 
+// timeout in ms to wait for response from spine to avoid lambda timeout
+const SPINE_TIMEOUT = 45000
 export class LiveSpineClient implements SpineClient {
   private readonly SPINE_URL_SCHEME = "https"
   private readonly SPINE_ENDPOINT = process.env.TargetSpineServer
@@ -49,7 +51,8 @@ export class LiveSpineClient implements SpineClient {
       const response = await axios.get(address, {
         headers: outboundHeaders,
         params: queryParams,
-        httpsAgent: this.httpsAgent
+        httpsAgent: this.httpsAgent,
+        timeout: SPINE_TIMEOUT
       })
 
       // This can be removed when https://nhsd-jira.digital.nhs.uk/browse/AEA-3448 is complete

diff --git a/packages/spineClient/tests/live-spine-client.test.ts b/packages/spineClient/tests/live-spine-client.test.ts
@@ -105,4 +105,14 @@ describe("live spine client", () => {
     }
     await expect(spineClient.getPrescriptions(headers, logger)).rejects.toThrow("Network Error")
   })
+
+  test("should throw error when timout on http request", async () => {
+    mock.onGet("https://spine/mm/patientfacingprescriptions").timeout()
+
+    const spineClient = new LiveSpineClient()
+    const headers: APIGatewayProxyEventHeaders = {
+      "nhsd-nhslogin-user": "P9:9912003071"
+    }
+    await expect(spineClient.getPrescriptions(headers, logger)).rejects.toThrow("timeout of 45000ms exceeded")
+  })
 })
diff --git a/packages/splunkProcessor/.eslintrc b/packages/splunkProcessor/.eslintrc
@@ -6,6 +6,9 @@
   },
   "plugins": ["import-newlines"],
   "extends": ["eslint:recommended"],
+  "parserOptions": {
+    "ecmaVersion": 2018
+  },
   "rules": {
     "block-spacing": "error",
     "brace-style": ["error", "1tbs"],

diff --git a/packages/splunkProcessor/.vscode/settings.json b/packages/splunkProcessor/.vscode/settings.json
@@ -0,0 +1,3 @@
+{
+  "jest.jestCommandLine": "/workspaces/prescriptionsforpatients/node_modules/.bin/jest"
+}
diff --git a/packages/splunkProcessor/package.json b/packages/splunkProcessor/package.json
@@ -6,9 +6,8 @@
   "author": "SAM CLI",
   "license": "MIT",
   "scripts": {
-    "unit": "jest",
+    "test": "jest",
     "lint": "eslint . --ext .js --max-warnings 0 --fix",
-    "test": "npm run compile && npm run unit",
     "check-licenses": "license-checker --failOn GPL --failOn LGPL --start ../.."
   },
   "dependencies": {

diff --git a/packages/splunkProcessor/src/app.js b/packages/splunkProcessor/src/app.js
@@ -70,12 +70,46 @@ const {Kinesis} = require("@aws-sdk/client-kinesis")
 const SPLUNK_SOURCE_TYPE = "aws:cloudwatch"
 
 function transformLogEvent(logEvent, logGroup, accountNumber) {
-  // Parse message as JSON or wrap as string if not
+  // Try and parse message as JSON
   let eventMessage = ""
   try {
     eventMessage = JSON.parse(logEvent.message)
   } catch (_) {
-    eventMessage = logEvent.message
+    /*
+    if its a lambda log that we could not parse to json object
+    then we want to try and extract the function_request_id to easier search and link in splunk
+    possible messages are
+    REPORT RequestId: ff7fe271-9934-4688-b9f9-f2c0cd9857cd	....
+    END RequestId: ff7fe271-9934-4688-b9f9-f2c0cd9857cd ...
+    START RequestId: ff7fe271-9934-4688-b9f9-f2c0cd9857cd ...
+    2023-08-22T09:52:29.585Z 720f4d20-ffd3-4a06-924a-0a61c9c594c8 <message>
+    */
+    if (logGroup.startsWith("/aws/lambda/")) {
+      let functionRequestId = ""
+      const summaryPattern = /RequestId:\s*([a-fA-F0-9-]+)/
+      const match = logEvent.message.match(summaryPattern)
+      if (match) {
+        functionRequestId = match[1]
+      } else {
+        const noSummaryPattern = /\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z\s+([a-fA-F0-9-]+)/
+        const match = logEvent.message.match(noSummaryPattern)
+        if (match) {
+          functionRequestId = match[1]
+        }
+      }
+      if (functionRequestId === "") {
+        // could not get function request id so just log message as a string
+        eventMessage = logEvent.message
+      } else {
+        eventMessage = {
+          message: logEvent.message,
+          function_request_id: functionRequestId
+        }
+      }
+    } else {
+      // not a lambda log and can not parse as json so just log message as a string
+      eventMessage = logEvent.message
+    }
   }
 
   const event = {
@@ -349,3 +383,5 @@ exports.handler = (event, context, callback) => {
       callback(ex, null)
     })
 }
+
+module.exports = transformLogEvent
diff --git a/packages/splunkProcessor/tests/transformLogEvent.test.js b/packages/splunkProcessor/tests/transformLogEvent.test.js
@@ -0,0 +1,172 @@
+const transformLogEvent = require("../src/app.js")
+const {expect, describe, it} = require("@jest/globals")
+
+/* eslint-disable  max-len */
+
+describe("transformLogEvent", () => {
+
+  it("should parse a json log event", async () => {
+    const logEvent = {
+      message: JSON.stringify({
+        field1: "foo",
+        field2: "bar"
+      }),
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:{
+          field1:"foo",
+          field2:"bar"
+        }
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should get a function request id from string START log event", async () => {
+    const logEvent = {
+      message: "START RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8 Version: $LATEST",
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:{
+          message:"START RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8 Version: $LATEST",
+          function_request_id:"720f4d20-ffd3-4a06-924a-0a61c9c594c8"
+        }
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should get a function request id from string END log event", async () => {
+    const logEvent = {
+      message: "END RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8",
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:{
+          message:"END RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8",
+          function_request_id:"720f4d20-ffd3-4a06-924a-0a61c9c594c8"
+        }
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should get a function request id from string REPORT log event", async () => {
+    const logEvent = {
+      message: "REPORT RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8	Duration: 1006.29 ms	Billed Duration: 1000 ms	Memory Size: 256 MB	Max Memory Used: 87 MB	Init Duration: 669.74 ms",
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:{
+          message: "REPORT RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8	Duration: 1006.29 ms	Billed Duration: 1000 ms	Memory Size: 256 MB	Max Memory Used: 87 MB	Init Duration: 669.74 ms",
+          function_request_id:"720f4d20-ffd3-4a06-924a-0a61c9c594c8"
+        }
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should get a function request id from console log event", async () => {
+    const logEvent = {
+      message: "2023-08-22T09:52:29.585Z 720f4d20-ffd3-4a06-924a-0a61c9c594c8 Task timed out after 1.01 seconds",
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:{
+          message: "2023-08-22T09:52:29.585Z 720f4d20-ffd3-4a06-924a-0a61c9c594c8 Task timed out after 1.01 seconds",
+          function_request_id:"720f4d20-ffd3-4a06-924a-0a61c9c594c8"
+        }
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should not get a function request id when it is not specified", async () => {
+    const logEvent = {
+      message: "No new layer was specified, unsetting AWS_LAMBDA_EXEC_WRAPPER",
+      id: 1
+    }
+    const logGroup = "/aws/lambda/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/lambda/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message: "No new layer was specified, unsetting AWS_LAMBDA_EXEC_WRAPPER"
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+
+  it("should not get a function request id when log group is not lambda", async () => {
+    const logEvent = {
+      message: "END RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8",
+      id: 1
+    }
+    const logGroup = "/aws/foo"
+    const accountNumber = 1234
+    const transformedLogEvent = await transformLogEvent(logEvent, logGroup, accountNumber)
+    const expectedResult = {
+      host:"AWS:AccountNumber:1234",
+      source:"AWS:LogGroup:/aws/foo",
+      sourcetype:"aws:cloudwatch",
+      event:{
+        id:1,
+        message:"END RequestId: 720f4d20-ffd3-4a06-924a-0a61c9c594c8"
+      }
+    }
+
+    expect(transformedLogEvent).toEqual(JSON.stringify(expectedResult))
+  })
+})
diff --git a/template.yaml b/template.yaml
@@ -6,7 +6,7 @@ Description: >
 # More info about Globals: https://github.com/awslabs/serverless-application-model/blob/master/docs/globals.rst
 Globals:
   Function:
-    Timeout: 30
+    Timeout: 50
     MemorySize: 256
     Architectures:
       - x86_64