add and refactor logs for health dashboard

app/auth/authenticate.js

@@ -1,11 +1,12 @@
+import { getDirective, MapperKind, mapSchema } from '@graphql-tools/utils'
+import { defaultFieldResolver } from 'graphql'
 import jwt from 'jsonwebtoken'
 import jwksClient from 'jwks-rsa'
-import { defaultFieldResolver } from 'graphql'
-import { MapperKind, getDirective, mapSchema } from '@graphql-tools/utils'
+import { FCP_REQUEST_AUTHENTICATION_001 } from '../logger/codes.js'
 
-import { logger } from '../utils/logger.js'
 import { Unauthorized } from '../errors/graphql.js'
 import { AuthRole } from '../graphql/resolvers/authenticate.js'
+import { logger } from '../logger/logger.js'
 
 export async function getJwtPublicKey (kid) {
   const client = jwksClient({
@@ -25,9 +26,11 @@ export async function getAuth (request, getJwtPublicKeyFunc = getJwtPublicKey) {
     const decodedToken = jwt.decode(token, { complete: true })
     const header = decodedToken.header
     const signingKey = await getJwtPublicKeyFunc(header.kid)
-    return jwt.verify(token, signingKey)
+    const verified = jwt.verify(token, signingKey)
+    logger.health('#authenticate - JWT verified', { code: FCP_REQUEST_AUTHENTICATION_001 })
+    return verified
   } catch (error) {
-    logger.error('#authenticate - Error verifying jwt', { error })
+    logger.error('#authenticate - Error verifying jwt', { error, code: FCP_REQUEST_AUTHENTICATION_001 })
     return {}
   }
 }

app/data-sources/authenticate/AuthenticateDatabase.js

@@ -1,5 +1,6 @@
-import { Sequelize, DataTypes } from 'sequelize'
-import { logger } from '../../utils/logger.js'
+import { DataTypes, Sequelize } from 'sequelize'
+import { AUTHENTICATE_DATABASE_ALL_001 } from '../../logger/codes.js'
+import { logger } from '../../logger/logger.js'
 
 const dbOptions = {
   database: process.env.AUTHENTICATE_DB_SCHEMA,
@@ -34,22 +35,41 @@ export class AuthenticateDatabase {
     Updated: DataTypes.DATE
   })
 
+  async healthCheck () {
+    try {
+      await this.dbRead.authenticate()
+      logger.health('#authenticate - database authenticated', { code: AUTHENTICATE_DATABASE_ALL_001 })
+    } catch (error) {
+      logger.error('Authenticate database error', { error, code: AUTHENTICATE_DATABASE_ALL_001 })
+      throw error
+    }
+  }
+
   async getAuthenticateQuestionsAnswersByCRN (crn, employeeId) {
-    await this.dbAuditWrite.query(`
+    try {
+      logger.silly('Creating audit record in authenticate database', { employeeId, crn })
+      await this.dbAuditWrite.query(`
       INSERT INTO Audits ([Date], [User], [Action], [Value])
       VALUES(?, ?, ?, ?);
     `, {
-      replacements: [new Date().toISOString(), employeeId, 'Search', crn]
-    })
-
-    const answers = await this.Answer.findOne({
-      attributes: ['CRN', 'Date', 'Event', 'Location', 'Updated'],
-      where: {
-        CRN: crn
-      }
-    })
-
-    logger.info(`getAuthenticateQuestionsAnswersByCRN: got answers for ${crn}`)
-    return answers
+        replacements: [new Date().toISOString(), employeeId, 'Search', crn]
+      })
+      logger.debug('Created audit record in authenticate database', { employeeId, crn })
+
+      logger.silly('Getting authenticate questions answers by CRN', { crn, employeeId })
+      const answers = await this.Answer.findOne({
+        attributes: ['CRN', 'Date', 'Event', 'Location', 'Updated'],
+        where: {
+          CRN: crn
+        }
+      })
+      logger.debug('Got authenticate questions answers by CRN', { crn, answers })
+
+      logger.health('#authenticate - answers retrieved', { code: AUTHENTICATE_DATABASE_ALL_001 })
+      return answers
+    } catch (error) {
+      logger.error('Authenticate database error', { error, code: AUTHENTICATE_DATABASE_ALL_001 })
+      throw error
+    }
   }
 }

app/data-sources/entra-id/EntraIdApi.js

@@ -1,6 +1,7 @@
 import { RESTDataSource } from '@apollo/datasource-rest'
 import { DefaultAzureCredential } from '@azure/identity'
-import { logger } from '../../utils/logger.js'
+import { ENTRA_REQUEST_EMPLOYEE_LOOKUP_001 } from '../../logger/codes.js'
+import { logger } from '../../logger/logger.js'
 
 const credential = new DefaultAzureCredential()
 
@@ -24,17 +25,19 @@ export class EntraIdApi extends RESTDataSource {
           }
         }
       )
-
       employeeId = response.employeeId
-    } catch (err) {
-      logger.error(err)
+    } catch (error) {
+      logger.error('Could not get the employee ID for the user', { entraIdUserObjectId, error, code: ENTRA_REQUEST_EMPLOYEE_LOOKUP_001 })
       throw new Error(`Could not get the employee ID for the user: ${entraIdUserObjectId}`)
     }
 
     if (!employeeId) {
+      logger.error('Missing employee ID for user', { entraIdUserObjectId, code: ENTRA_REQUEST_EMPLOYEE_LOOKUP_001 })
       throw new Error(`Missing employee ID for user: ${entraIdUserObjectId}`)
     }
 
+    logger.health('Successful get employee ID for user', { code: ENTRA_REQUEST_EMPLOYEE_LOOKUP_001 })
+
     return employeeId
   }
 }

app/data-sources/rural-payments-portal/RuralPaymentsSession.js

@@ -8,7 +8,7 @@ import { HttpsProxyAgent } from 'https-proxy-agent'
 import qs from 'qs'
 import { CookieJar } from 'tough-cookie'
 import { URL } from 'url'
-import { logger } from '../../utils/logger.js'
+import { logger } from '../../logger/logger.js'
 
 const defaultHeaders = {
   'Accept-Encoding': 'gzip, deflate, br',
@@ -26,7 +26,7 @@ const apiCredentials = {
   password: process.env.RURAL_PAYMENTS_PORTAL_PASSWORD
 }
 
-logger.debug('#RuralPaymentsSession - Set api credentials', { apiCredentials })
+logger.verbose('#RuralPaymentsSession - Set api credentials', { apiCredentials })
 
 export class RuralPaymentsSession extends RESTDataSource {
   baseURL = process.env.RURAL_PAYMENTS_PORTAL_API_URL
@@ -85,7 +85,7 @@ export class RuralPaymentsSession extends RESTDataSource {
   async handleRedirects (response) {
     if ([301, 302, 303].includes(response?.status)) {
       const redirectUrl = new URL(response.headers.get('location'))
-      logger.debug('#RuralPaymentsSession - handle redirect', {
+      logger.verbose('#RuralPaymentsSession - handle redirect', {
         status: response?.status,
         redirect: redirectUrl.pathname
       })
@@ -107,7 +107,7 @@ export class RuralPaymentsSession extends RESTDataSource {
   }
 
   async fetch (path, incomingRequest) {
-    logger.debug('#RuralPaymentsSession - new request ', {
+    logger.verbose('#RuralPaymentsSession - new request ', {
       path,
       method: incomingRequest.method,
       cookies: this.jar
@@ -116,7 +116,7 @@ export class RuralPaymentsSession extends RESTDataSource {
         .join(', ')
     })
     const result = await super.fetch(path, incomingRequest)
-    logger.debug('#RuralPaymentsSession - response ', {
+    logger.verbose('#RuralPaymentsSession - response ', {
       path,
       status: result.response?.status,
       body: result.response.parsedBody,

app/data-sources/rural-payments/RuralPayments.js

@@ -1,8 +1,10 @@
 import { RESTDataSource } from '@apollo/datasource-rest'
-import { StatusCodes } from 'http-status-codes'
+import { GraphQLError } from 'graphql'
+import StatusCodes from 'http-status-codes'
 import fetch from 'node-fetch'
 import qs from 'qs'
-import { logger } from '../../utils/logger.js'
+import { APIM_REQUEST_ACCESS_TOKEN_001, APIM_REQUEST_RURAL_PAYMENTS_REQUEST_001, RURALPAYMENTS_REQUEST_ALL_001 } from '../../logger/codes.js'
+import { logger } from '../../logger/logger.js'
 
 const defaultHeaders = {
   'Ocp-Apim-Subscription-Key': process.env.RP_INTERNAL_APIM_SUBSCRIPTION_KEY
@@ -20,33 +22,56 @@ export class RuralPayments extends RESTDataSource {
   }
 
   async fetch (path, incomingRequest) {
-    logger.debug('#RuralPayments - new request', {
+    logger.verbose('#RuralPayments - new request', {
       path,
       method: incomingRequest.method
     })
 
     const doRequest = async (count = 1) => {
       try {
+        const requestStart = Date.now()
         const result = await super.fetch(path, incomingRequest)
-        logger.debug('#RuralPayments - response ', {
+        const requestEnd = (Date.now() - requestStart)
+        logger.verbose('#RuralPayments - response ', {
           path,
-          status: result.response?.status,
-          body: result.response?.parsedBody
+          status: result.response?.status
+        })
+        logger.health('#RuralPayments - request success', {
+          code: RURALPAYMENTS_REQUEST_ALL_001,
+          requestTimeMs: requestEnd
+        })
+        logger.health('#APIM - request success', {
+          code: APIM_REQUEST_RURAL_PAYMENTS_REQUEST_001
         })
         return result
       } catch (error) {
         // Handle occasionally 500 error produced by APIM
-        // TODO: Once APIM has been fixed remove retry logic
+        // TODO: Once APIM has been fixed, remove retry logic
         if (error?.extensions?.response?.status === StatusCodes.INTERNAL_SERVER_ERROR && count < maximumRetries) {
-          logger.error(`#RuralPayments - Error, Retrying request (${count})`, {
+          logger.warn(`#RuralPayments - Error, Retrying request (${count})`, { error })
+          return doRequest(count + 1)
+        }
+        // if response is text, then the error is from RoralPayments
+        if (error?.extensions?.response?.headers?.get('Content-Type')?.includes('text/html')) {
+          logger.error('#RuralPayments - error', {
+            error,
             path,
             method: incomingRequest.method,
             count,
-            error
+            response: error?.extensions?.response,
+            code: RURALPAYMENTS_REQUEST_ALL_001
+          })
+        } else {
+        // if response is json, then the error is from APIM
+          logger.error('#APIM - error', {
+            error,
+            path,
+            method: incomingRequest.method,
+            count,
+            response: error?.extensions?.response,
+            code: APIM_REQUEST_RURAL_PAYMENTS_REQUEST_001
           })
-          return doRequest(count + 1)
         }
-        logger.error('#RuralPayments - Error fetching data', { error })
         throw error
       }
     }
@@ -59,19 +84,17 @@ export class RuralPayments extends RESTDataSource {
     if (response.ok) {
       return
     }
-    logger.error('#RuralPayments - error', {
-      status: response?.status,
-      url: response?.url,
-      error: response?.error
+
+    throw new GraphQLError(`${options.response.status}: ${options.response.statusText}`, {
+      extensions: options
     })
-    throw await this.errorFromResponse(options)
   }
 
   async willSendRequest (_path, request) {
     if (!this.apimAccessToken) {
-      logger.debug('Getting APIM access token')
+      logger.verbose('Getting APIM access token')
       await this.getApimAccessToken()
-      logger.debug('APIM access token', {
+      logger.verbose('APIM access token', {
         apimAccessToken: this.apimAccessToken
       })
     }
@@ -105,7 +128,7 @@ export class RuralPayments extends RESTDataSource {
     }
 
     try {
-      logger.debug(
+      logger.verbose(
         `Token request url: ${process.env.RP_INTERNAL_APIM_ACCESS_TOKEN_URL}${process.env.RP_INTERNAL_APIM_TENANT_ID}/oauth2/v2.0/token`
       )
       const response = await fetch(
@@ -123,9 +146,10 @@ export class RuralPayments extends RESTDataSource {
         throw new Error('No access token returned')
       }
 
+      logger.health('Successfully got APIM access token', { code: APIM_REQUEST_ACCESS_TOKEN_001 })
       this.apimAccessToken = data.access_token
     } catch (error) {
-      logger.error('Error getting APIM access token', { error })
+      logger.error('Error getting APIM access token', { error, code: APIM_REQUEST_ACCESS_TOKEN_001 })
       throw error
     }
   }

app/data-sources/rural-payments/RuralPaymentsBusiness.js

@@ -1,13 +1,14 @@
-import { logger, sampleResponse } from '../../utils/logger.js'
+import { logger } from '../../logger/logger.js'
+import { sampleResponse } from '../../logger/utils.js'
 import { RuralPayments } from './RuralPayments.js'
 
 export class RuralPaymentsBusiness extends RuralPayments {
   async getOrganisationById (id) {
-    logger.debug('Getting organisation by ID', { id })
+    logger.verbose('Getting organisation by ID', { id })
     try {
       const organisationResponse = await this.get(`organisation/${id}`)
 
-      logger.debug('Organisation by ID', { organisationResponse })
+      logger.verbose('Organisation by ID', { organisationResponse })
       return organisationResponse._data
     } catch (error) {
       logger.error('Error getting organisation by ID', { id, error })
@@ -16,7 +17,7 @@ export class RuralPaymentsBusiness extends RuralPayments {
   }
 
   async getOrganisationBySBI (sbi) {
-    logger.debug('Getting organisation by SBI', { sbi })
+    logger.verbose('Getting organisation by SBI', { sbi })
     const body = JSON.stringify({
       searchFieldType: 'SBI',
       primarySearchPhrase: sbi,