diff --git a/app/controllers/healthcheck.controller.js b/app/controllers/healthcheck.controller.js index 0c3b68e51..2a29feace 100644 --- a/app/controllers/healthcheck.controller.js +++ b/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 diff --git a/app/middleware/correlation-header.js b/app/middleware/correlation-header.js index 27e68e235..0e1f6ad20 100644 --- a/app/middleware/correlation-header.js +++ b/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() } diff --git a/app/middleware/correlation-header.test.js b/app/middleware/correlation-header.test.js new file mode 100644 index 000000000..c74337412 --- /dev/null +++ b/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) + }) +}) diff --git a/app/services/clients/adminusers.client.js b/app/services/clients/adminusers.client.js index e1840f0ae..e77a0f3f1 100644 --- a/app/services/clients/adminusers.client.js +++ b/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 } diff --git a/app/services/clients/base/config.js b/app/services/clients/base/config.js index 814aa5672..f4888a475 100644 --- a/app/services/clients/base/config.js +++ b/app/services/clients/base/config.js @@ -1,11 +1,13 @@ '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 @@ -13,20 +15,34 @@ function transformRequestAddHeaders () { 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, diff --git a/app/services/clients/base/config.test.js b/app/services/clients/base/config.test.js index dbe9b358a..2173a55ca 100644 --- a/app/services/clients/base/config.test.js +++ b/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' }) }) diff --git a/app/services/clients/base/request-context.js b/app/services/clients/base/request-context.js deleted file mode 100644 index a23298a06..000000000 --- a/app/services/clients/base/request-context.js +++ /dev/null @@ -1,38 +0,0 @@ -'use strict' - -const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys - -const { AsyncLocalStorage } = require('async_hooks') -const { CORRELATION_HEADER } = require('../../../../config/correlation-header') - -const asyncLocalStorage = new AsyncLocalStorage() - -function requestContextMiddleware (req, res, next) { - asyncLocalStorage.run({}, () => { - asyncLocalStorage.getStore()[CORRELATION_ID] = req.headers[CORRELATION_HEADER] - next() - }) -} - -function addField (key, value) { - if (asyncLocalStorage.getStore()) { - asyncLocalStorage.getStore()[key] = value - } -} - -function getRequestCorrelationIDField () { - if (asyncLocalStorage.getStore()) { - return asyncLocalStorage.getStore()[CORRELATION_ID] - } -} - -function getLoggingFields () { - return asyncLocalStorage.getStore() -} - -module.exports = { - requestContextMiddleware, - addField, - getRequestCorrelationIDField, - getLoggingFields -} diff --git a/app/services/clients/cardid.client.js b/app/services/clients/cardid.client.js index d31173c64..3470db653 100644 --- a/app/services/clients/cardid.client.js +++ b/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) { diff --git a/app/services/clients/connector.client.js b/app/services/clients/connector.client.js index fcea78b95..0eb5e5fba 100644 --- a/app/services/clients/connector.client.js +++ b/app/services/clients/connector.client.js @@ -22,6 +22,7 @@ const WORLDPAY_3DS_FLEX_JWT_PATH = '/v1/frontend/charges/{chargeId}/worldpay/3ds const client = new Client(SERVICE_NAME) let baseUrl +let correlationId /** @private */ const _getFindChargeUrlFor = chargeId => baseUrl + CARD_CHARGE_PATH.replace('{chargeId}', chargeId) @@ -64,18 +65,10 @@ const _getWorldpay3dsFlexUrlFor = chargeId => baseUrl + WORLDPAY_3DS_FLEX_JWT_PA /** @private */ async function _putConnector (url, payload, description, loggingFields = {}, callingFunctionName) { const startTime = new Date() - const context = { - ...loggingFields, - url: url, - method: 'PUT', - description: description, - service: SERVICE_NAME - } - requestLogger.logRequestStart(context, loggingFields) + try { - configureClient(client, url) + configureClient(client, url, correlationId) const response = await client.put(url, payload, description) - logger.info('PUT to %s ended - total time %dms', url, new Date() - startTime, loggingFields) incrementStatusCodeCounter(callingFunctionName, response.status) if (response.status > 499 && response.status < 600) { logger.error(`Error communicating with ${url}`, { @@ -88,14 +81,6 @@ async function _putConnector (url, payload, description, loggingFields = {}, cal } return response } catch (err) { - logger.info('PUT to %s ended - total time %dms', url, new Date() - startTime, loggingFields) - logger.error('Calling connector threw exception', { - ...loggingFields, - service: 'connector', - method: 'PUT', - url: url, - error: err - }) incrementStatusCodeCounter(callingFunctionName, 'error') throw err } @@ -104,18 +89,12 @@ async function _putConnector (url, payload, description, loggingFields = {}, cal /** @private */ async function _postConnector (url, payload, description, loggingFields = {}, callingFunctionName) { const startTime = new Date() - const context = { - url: url, - method: 'POST', - description: description, - service: SERVICE_NAME - } - requestLogger.logRequestStart(context, loggingFields) + try { - configureClient(client, url) + configureClient(client, url, correlationId) const response = await client.post(url, payload, description) - logger.info('POST to %s ended - total time %dms', url, new Date() - startTime, loggingFields) + incrementStatusCodeCounter(callingFunctionName, response.status) if (response.status > 499 && response.status < 600) { logger.error(`Error communicating with ${url}`, { @@ -128,14 +107,6 @@ async function _postConnector (url, payload, description, loggingFields = {}, ca } return response } catch (err) { - logger.info('POST to %s ended - total time %dms', url, new Date() - startTime, loggingFields) - logger.error('Calling connector threw exception', { - ...loggingFields, - service: 'connector', - method: 'POST', - url: url, - error: err - }) incrementStatusCodeCounter(callingFunctionName, 'error') throw err } @@ -143,19 +114,11 @@ async function _postConnector (url, payload, description, loggingFields = {}, ca /** @private */ async function _patchConnector (url, payload, description, loggingFields = {}, callingFunctionName) { - const startTime = new Date() - const context = { - url: url, - method: 'PATCH', - description: description, - service: SERVICE_NAME - } - requestLogger.logRequestStart(context, loggingFields) try { - configureClient(client, url) + configureClient(client, url, correlationId) const response = await client.patch(url, payload, description) - logger.info('PATCH to %s ended - total time %dms', url, new Date() - startTime, loggingFields) + incrementStatusCodeCounter(callingFunctionName, response.status) if (response.status > 499 && response.status < 600) { logger.error(`Error communicating with ${url}`, { @@ -168,14 +131,6 @@ async function _patchConnector (url, payload, description, loggingFields = {}, c } return response } catch (err) { - logger.info('PATCH %s to %s ended - total time %dms', url, new Date() - startTime, loggingFields) - logger.error('Calling connector threw exception', { - ...loggingFields, - service: 'connector', - method: 'PATCH', - url: url, - error: err - }) incrementStatusCodeCounter(callingFunctionName, 'error') throw err } @@ -183,19 +138,11 @@ async function _patchConnector (url, payload, description, loggingFields = {}, c /** @private */ async function _getConnector (url, description, loggingFields = {}, callingFunctionName) { - const startTime = new Date() - const context = { - url: url, - method: 'GET', - description: description, - service: SERVICE_NAME - } - requestLogger.logRequestStart(context, loggingFields) try { - configureClient(client, url) + configureClient(client, url, correlationId) const response = await client.get(`${url}`, description) - logger.info('GET to %s ended - total time %dms', url, new Date() - startTime, loggingFields) + // logger.info('GET to %s ended - total time %dms', url, new Date() - startTime, loggingFields) incrementStatusCodeCounter(callingFunctionName, response.status) if (response.status !== 200) { logger.error(`Error communicating with ${url}`, { @@ -208,14 +155,6 @@ async function _getConnector (url, description, loggingFields = {}, callingFunct } return response } catch (err) { - logger.info('GET to %s ended - total time %dms', url, new Date() - startTime, loggingFields) - logger.error('Calling connector threw exception', { - ...loggingFields, - service: 'connector', - method: 'GET', - url: url, - error: err - }) incrementStatusCodeCounter(callingFunctionName, 'error') throw err } @@ -286,6 +225,8 @@ const markTokenAsUsed = (chargeOptions, loggingFields = {}) => { module.exports = function (clientOptions = {}) { baseUrl = clientOptions.baseUrl || process.env.CONNECTOR_HOST + correlationId = clientOptions.correlationId + return { chargeAuth, chargeAuthWithWallet, diff --git a/server.js b/server.js index c0a6cef36..1111d7a49 100644 --- a/server.js +++ b/server.js @@ -24,7 +24,6 @@ const Sentry = require('./app/utils/sentry.js').initialiseSentry() const { setReportingEndpoints, worldpayIframe } = require('./app/middleware/csp') const correlationHeader = require('./app/middleware/correlation-header') const errorHandlers = require('./app/middleware/error-handlers') -const { requestContextMiddleware } = require('./app/services/clients/base/request-context') // Global constants const { @@ -62,7 +61,6 @@ function initialiseGlobalMiddleware (app) { app.use(staticify.middleware) app.use(function (req, res, next) { - app.use(requestContextMiddleware) res.locals.asset_path = '/public/' res.locals.googlePayMerchantID = GOOGLE_PAY_MERCHANT_ID if (typeof ANALYTICS_TRACKING_ID === 'undefined') {