PP-13119 Fix logging of correlation ID to log messages

- Remove references to `async local storage`.
- No longer using this as that will be a big change.
- Instead continue to save logging context fields to the request instead.
- Remove all references to `async local storage` - including the
  `request-context` file.
- Fix bug where the correlation id was not getting logged and not sent
  as a header to backend services.
  - When configuring a client that calls the backend - we now pass the
    correlation id and save it for each request.
  - Pass the correlation id to the backend as a header.
  - Log the correlation id as part of logging messages.
- Remove logging messages that are no longer required as the
  `pay-js-commons/axios-base-client` will do the logging instead.

app/controllers/healthcheck.controller.js

@@ -6,6 +6,7 @@ const { Client } = require('@govuk-pay/pay-js-commons/lib/utils/axios-base-clien
 const { configureClient } = require('../services/clients/base/config')
 const SERVICE_NAME = 'frontend'
 const client = new Client(SERVICE_NAME)
+const { CORRELATION_HEADER } = require('../../config/correlation-header')
 
 const healthyPingResponse = { ping: { healthy: true } }
 
@@ -18,7 +19,7 @@ module.exports.healthcheck = async (req, res) => {
   if (process.env.FORWARD_PROXY_URL) {
     const url = `${process.env.FORWARD_PROXY_URL}/nginx_status`
 
-    configureClient(client, url)
+    configureClient(client, url, req.headers[CORRELATION_HEADER])
 
     let response
 

app/middleware/correlation-header.js

@@ -1,11 +1,18 @@
 'use strict'
 
-const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys
+const crypto = require('crypto')
+
 const { CORRELATION_HEADER } = require('../../config/correlation-header')
 const { setLoggingField } = require('../utils/logging-fields-helper')
+const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys
 
 module.exports = (req, res, next) => {
-  req.correlationId = req.headers[CORRELATION_HEADER] || ''
+  if (!req.headers[CORRELATION_HEADER]) {
+    req.headers[CORRELATION_HEADER] = crypto.randomBytes(16).toString('hex')
+  }
+
+  req.correlationId = req.headers[CORRELATION_HEADER]
   setLoggingField(req, CORRELATION_ID, req.correlationId)
+
   next()
 }

app/middleware/correlation-header.test.js

@@ -0,0 +1,53 @@
+'use strict'
+
+const proxyquire = require('proxyquire')
+const sinon = require('sinon')
+const { CORRELATION_HEADER } = require('../../config/correlation-header')
+
+const { expect } = require('chai')
+
+function getCorrelationHeader () {
+  return proxyquire('./correlation-header', {
+    crypto: {
+      randomBytes: function () {
+        return 'test-correlation-id'
+      }
+    }
+  })
+}
+
+describe('Correlation header', () => {
+  it('sets the correlation id when there is no x_request_id header', () => {
+    const correlationHeader = getCorrelationHeader()
+
+    const req = {
+      headers: {}
+    }
+    const res = null
+    const next = sinon.spy()
+
+    correlationHeader(req, res, next)
+    expect(req.headers[CORRELATION_HEADER]).to.equal('test-correlation-id')
+    expect(req.correlationId).to.equal('test-correlation-id')
+    sinon.assert.calledWithExactly(next)
+  })
+
+  it('sets the correlation id using the x-request-id header when it exists', () => {
+    const correlationHeader = getCorrelationHeader()
+    const xRequestIdHeaderValue = 'x-request-id-value'
+
+    const req = {
+      headers: {}
+    }
+
+    req.headers[CORRELATION_HEADER] = xRequestIdHeaderValue
+
+    const res = null
+    const next = sinon.spy()
+
+    correlationHeader(req, res, next)
+    expect(req.headers[CORRELATION_HEADER]).to.equal(xRequestIdHeaderValue)
+    expect(req.correlationId).to.equal(xRequestIdHeaderValue)
+    sinon.assert.calledWithExactly(next)
+  })
+})

app/services/clients/adminusers.client.js

@@ -4,7 +4,6 @@
 const { Client } = require('@govuk-pay/pay-js-commons/lib/utils/axios-base-client/axios-base-client')
 const { configureClient } = require('./base/config')
 const logger = require('../../utils/logger')(__filename)
-const requestLogger = require('../../utils/request-logger')
 const Service = require('../../models/Service.class')
 const { getCounter } = require('../../metrics/graphite-reporter')
 
@@ -14,27 +13,16 @@ const METRICS_PREFIX = 'internal-rest-call.adminusers'
 const SUCCESS_CODES = [200, 201, 202, 204, 206]
 
 let baseUrl
+let correlationId
 
 /** @private */
 async function _getAdminUsers (url, description, findOptions, loggingFields = {}, callingFunctionName) {
-  const startTime = new Date()
-  const context = {
-    url: url,
-    startTime: startTime,
-    method: 'GET',
-    description: description,
-    service: SERVICE_NAME
-  }
-  requestLogger.logRequestStart(context, loggingFields)
-
   const client = new Client(SERVICE_NAME)
-  configureClient(client, url)
+  configureClient(client, url, correlationId)
 
   try {
     const fullUrl = `${url}?gatewayAccountId=${findOptions.gatewayAccountId}`
     const response = await client.get(fullUrl, description)
-
-    requestLogger.logRequestEnd(context, response.status, loggingFields)
     incrementStatusCodeCounter(callingFunctionName, response.status)
     if (SUCCESS_CODES.includes(response.status)) {
       return new Service(response.data)
@@ -51,7 +39,6 @@ async function _getAdminUsers (url, description, findOptions, loggingFields = {}
       return response
     }
   } catch (err) {
-    requestLogger.logRequestError(context, err, loggingFields)
     incrementStatusCodeCounter(callingFunctionName, 'error')
     throw err
   }
@@ -68,6 +55,8 @@ const findServiceBy = function findServiceBy (findOptions, loggingFields = {}) {
 
 module.exports = function (clientOptions = {}) {
   baseUrl = clientOptions.baseUrl || process.env.ADMINUSERS_URL
+  correlationId = clientOptions.correlationId
+
   return {
     findServiceBy
   }

app/services/clients/base/config.js

@@ -1,32 +1,48 @@
 'use strict'
 
 const requestLogger = require('./request-logger')
-const { getRequestCorrelationIDField } = require('./request-context')
 const { CORRELATION_HEADER } = require('../../../../config/correlation-header')
+const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys
+
+let correlationIdFromRequest
 
 function transformRequestAddHeaders () {
-  const correlationId = getRequestCorrelationIDField()
+  const correlationId = correlationIdFromRequest
   const headers = {}
   if (correlationId) {
     headers[CORRELATION_HEADER] = correlationId
   }
   return headers
 }
 
+function addCorrelationIdToContext (context) {
+  context = context || {}
+
+  context.additionalLoggingFields = context.additionalLoggingFields || {}
+  context.additionalLoggingFields[CORRELATION_ID] = correlationIdFromRequest
+
+  return context
+}
+
 function onRequestStart (context) {
+  addCorrelationIdToContext(context)
   requestLogger.logRequestStart(context)
 }
 
 function onSuccessResponse (context) {
+  addCorrelationIdToContext(context)
   requestLogger.logRequestEnd(context)
 }
 
 function onFailureResponse (context) {
+  addCorrelationIdToContext(context)
   requestLogger.logRequestEnd(context)
   requestLogger.logRequestFailure(context)
 }
 
-function configureClient (client, baseUrl) {
+function configureClient (client, baseUrl, correlationId) {
+  correlationIdFromRequest = correlationId
+
   client.configure(baseUrl, {
     transformRequestAddHeaders,
     onRequestStart,

app/services/clients/base/config.test.js

@@ -8,14 +8,12 @@ const { Client } = require('@govuk-pay/pay-js-commons/lib/utils/axios-base-clien
 
 const baseUrl = 'http://localhost:8000'
 const app = 'an-app'
+const correlationId = 'abc123'
 
 const logInfoSpy = sinon.spy()
 
-function getConfigWithMocks (correlationId) {
+function getConfigWithMocks () {
   const config = proxyquire('./config.js', {
-    './request-context': {
-      getRequestCorrelationIDField: () => correlationId
-    },
     './request-logger': proxyquire('./request-logger', {
       '../../../utils/logger': () => ({
         info: logInfoSpy
@@ -33,9 +31,9 @@ describe('Client config', () => {
   describe('Headers', () => {
     it('should add correlation ID as header when correlation ID exists on request context', async () => {
       const client = new Client(app)
-      const config = getConfigWithMocks('abc123')
+      const config = getConfigWithMocks()
 
-      config.configureClient(client, baseUrl)
+      config.configureClient(client, baseUrl, correlationId)
 
       nock(baseUrl)
         .get('/')
@@ -65,8 +63,8 @@ describe('Client config', () => {
   describe('Logging', () => {
     it('should log request start', async () => {
       const client = new Client(app)
-      const config = getConfigWithMocks('abc123')
-      config.configureClient(client, baseUrl)
+      const config = getConfigWithMocks()
+      config.configureClient(client, baseUrl, correlationId)
 
       nock(baseUrl)
         .get('/')
@@ -83,6 +81,7 @@ describe('Client config', () => {
         method: 'get',
         url: '/',
         description: 'do something',
+        x_request_id: 'abc123',
         foo: 'bar'
       })
     })

app/services/clients/cardid.client.js

@@ -7,7 +7,6 @@ const { configureClient } = require('./base/config')
 // Constants
 const CARD_URL = process.env.CARDID_HOST + '/v1/api/card'
 const client = new Client('cardid')
-configureClient(client, CARD_URL)
 
 /**
  *
@@ -18,6 +17,7 @@ configureClient(client, CARD_URL)
 
 exports.post = async (args) => {
   try {
+    configureClient(client, CARD_URL, args.correlationId)
     const response = await client.post(CARD_URL, args.payload, 'card id')
     return response
   } catch (err) {