Chore: [AEA-0000] - Timeout diagnosing

packages/cognito/src/token.ts

@@ -71,7 +71,9 @@ const lambdaHandler = async (event: APIGatewayProxyEvent): Promise<APIGatewayPro
   logger.appendKeys({
     "apigw-request-id": event.requestContext?.requestId
   })
+  let start = Date.now()
   const axiosInstance = axios.create()
+  logger.info(`Creating the axios instance took ${Date.now() - start}ms`)
 
   const body = event.body
   if (body === undefined) {
@@ -80,7 +82,9 @@ const lambdaHandler = async (event: APIGatewayProxyEvent): Promise<APIGatewayPro
   const objectBodyParameters = parse(body as string)
   let rewrittenObjectBodyParameters: ParsedUrlQuery
 
+  start = Date.now()
   const jwtPrivateKey = await getSecret(jwtPrivateKeyArn)
+  logger.info(`Getting the secret took ${Date.now() - start}ms`)
   rewrittenObjectBodyParameters = rewriteBodyToAddSignedJWT(
     logger, objectBodyParameters, idpTokenPath, jwtPrivateKey as PrivateKey, jwtKid)
 

packages/common/authFunctions/src/cis2.ts

@@ -180,14 +180,15 @@ export const verifyCIS2Token = async (
 
   // Fetch the signing key from the JWKS endpoint
   let signingKey
+  let start = Date.now()
   try {
     logger.info("Fetching signing key", {kid})
     signingKey = await getSigningKey(oidcConfig.jwksClient, kid)
   } catch (err) {
     logger.error("Error getting signing key", {err})
     throw new Error("Error getting signing key")
   }
-  logger.info("Signing key fetched successfully")
+  logger.info(`Signing key fetched successfully. Took ${Date.now() - start}ms`)
 
   // Verify the token signature
   const verifyOptions: jwt.VerifyOptions = {

packages/trackerUserInfoLambda/src/handler.ts

@@ -51,7 +51,6 @@ const CPT_ACCESS_ACTIVITY_CODES = ["B0570", "B0278"]
 
 const lambdaHandler = async (event: APIGatewayProxyEvent): Promise<APIGatewayProxyResult> => {
   logger.appendKeys({"apigw-request-id": event.requestContext?.requestId})
-  logger.info("Lambda handler invoked", {event})
 
   // Mock usernames start with "Mock_", and real requests use usernames starting with "Primary_"
   const username = getUsernameFromEvent(event)
@@ -66,23 +65,29 @@ const lambdaHandler = async (event: APIGatewayProxyEvent): Promise<APIGatewayPro
 
   logger.info("Is this a mock request?", {isMockRequest})
 
+  let start = Date.now()
   // eslint-disable-next-line @typescript-eslint/no-unused-vars
   const {cis2AccessToken, cis2IdToken} = await fetchAndVerifyCIS2Tokens(
     event,
     documentClient,
     logger,
     isMockRequest ? mockOidcConfig : cis2OidcConfig
   )
+  logger.info(`Fetch and verify CIS2 tokens took: ${Date.now() - start}`)
 
+  start = Date.now()
   const userInfoResponse = await fetchUserInfo(
     cis2AccessToken,
     CPT_ACCESS_ACTIVITY_CODES,
     undefined,
     logger,
     isMockRequest ? mockOidcConfig : cis2OidcConfig
   )
+  logger.info(`fetch user info took: ${Date.now() - start}`)
 
+  start = Date.now()
   updateDynamoTable(username, userInfoResponse, documentClient, logger, tokenMappingTableName)
+  logger.info(`Update dynamo table took: ${Date.now() - start}`)
 
   return {
     statusCode: 200,

packages/trackerUserInfoLambda/src/userInfoHelpers.ts

@@ -41,7 +41,7 @@ export const fetchUserInfo = async (
         Authorization: `Bearer ${cis2AccessToken}`
       }
     })
-    logger.info("User info fetched successfully", {data: response.data})
+    logger.info("User info fetched successfully")
 
     // Extract the roles from the user info response
     const data: UserInfoResponse = response.data
@@ -55,17 +55,14 @@ export const fetchUserInfo = async (
     const roles = data.nhsid_nrbac_roles || []
 
     roles.forEach((role) => {
-      logger.debug("Processing role", {role})
       const activityCodes = role.activity_codes || []
-
       const hasAccess = activityCodes.some((code: string) => accepted_access_codes.includes(code))
-      logger.debug("Role CPT access?", {hasAccess})
 
       const roleInfo: RoleDetails = {
         role_name: removeRoleCategories(role.role_name),
         role_id: role.person_roleid,
         org_code: role.org_code,
-        org_name: getOrgNameFromOrgCode(data, role.org_code, logger)
+        org_name: getOrgNameFromOrgCode(data, role.org_code)
       }
 
       // Ensure the role has at least one of the required fields
@@ -77,14 +74,11 @@ export const fetchUserInfo = async (
 
       if (hasAccess) {
         rolesWithAccess.push(roleInfo)
-        logger.debug("Role has access; adding to rolesWithAccess", {roleInfo})
       } else {
         rolesWithoutAccess.push(roleInfo)
-        logger.debug("Role does not have access; adding to rolesWithoutAccess", {roleInfo})
       }
 
       // Determine the currently selected role
-      logger.debug("Checking if role is currently selected", {selectedRoleId, role_id: role.person_roleid, roleInfo})
       if (selectedRoleId && role.person_roleid === selectedRoleId) {
         logger.debug("Role is currently selected", {role_id: role.person_roleid, roleInfo})
         if (hasAccess) {
@@ -112,11 +106,9 @@ export const fetchUserInfo = async (
 }
 
 // Helper function to get organization name from org_code
-function getOrgNameFromOrgCode(data: UserInfoResponse, org_code: string, logger: Logger): string | undefined {
-  logger.info("Getting org name from org code", {org_code, data})
+function getOrgNameFromOrgCode(data: UserInfoResponse, org_code: string): string | undefined {
   const orgs = data.nhsid_user_orgs || []
   const org = orgs.find((o) => o.org_code === org_code)
-  logger.info("Found org", {org})
   return org ? org.org_name : undefined
 }