From 97ab662de6b52328471eb5829ae8e0ed47295881 Mon Sep 17 00:00:00 2001 From: Iqbal Ahmed Date: Fri, 30 Aug 2024 09:57:19 +0100 Subject: [PATCH] PP-13118 Fix issues with correlation id - Remove all references to `log-context` - Everything now uses the `base/request-context` - The `request-context` is now responsible for setting the correlation ID - This is done as middleware for every request. - If the `x-request-id` already exists, then it uses this value instead. - Removed the old request logger as file replaces it. - It is also responsible for saving values to the request logging context so they are automatically added to API request log messages. - e.g. gateway account ID. - This also means that `correlation id` middleware and all references can be removed. --- app/clients/base/request-context.js | 7 +- app/clients/base/request-context.test.js | 104 ++++++++++++++++++ app/middleware/correlation-id.js | 18 --- app/middleware/correlation-id.test.js | 34 ------ app/middleware/resolve-payment-and-product.js | 10 +- app/middleware/resolve-product.js | 8 +- app/routes.js | 5 - app/utils/log-context.js | 31 ------ app/utils/logger.js | 2 +- app/utils/request-logger.js | 34 ------ config/server.js | 4 +- test/integration/log-context.it.test.js | 41 ------- 12 files changed, 121 insertions(+), 177 deletions(-) create mode 100644 app/clients/base/request-context.test.js delete mode 100644 app/middleware/correlation-id.js delete mode 100644 app/middleware/correlation-id.test.js delete mode 100644 app/utils/log-context.js delete mode 100644 app/utils/request-logger.js delete mode 100644 test/integration/log-context.it.test.js diff --git a/app/clients/base/request-context.js b/app/clients/base/request-context.js index f688febdf..6dc2a9bfc 100644 --- a/app/clients/base/request-context.js +++ b/app/clients/base/request-context.js @@ -3,13 +3,16 @@ const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys const { AsyncLocalStorage } = require('async_hooks') -const { CORRELATION_HEADER } = require('../../../config') +const crypto = require('crypto') const asyncLocalStorage = new AsyncLocalStorage() function requestContextMiddleware (req, res, next) { asyncLocalStorage.run({}, () => { - asyncLocalStorage.getStore()[CORRELATION_ID] = req.headers[CORRELATION_HEADER] + const correlationId = req.headers[CORRELATION_ID] || crypto.randomBytes(16).toString('hex') + + asyncLocalStorage.getStore()[CORRELATION_ID] = correlationId + next() }) } diff --git a/app/clients/base/request-context.test.js b/app/clients/base/request-context.test.js new file mode 100644 index 000000000..26085fc83 --- /dev/null +++ b/app/clients/base/request-context.test.js @@ -0,0 +1,104 @@ +'use strict' + +const proxyquire = require('proxyquire') +const sinon = require('sinon') +const { CORRELATION_ID } = require('@govuk-pay/pay-js-commons').logging.keys + +const { expect } = require('chai') + +let asyncStorageMock = {} + +function getRequestContext () { + return proxyquire('./request-context', { + 'crypto': { + randomBytes : function () { + return 'test-correlation-id' + } + }, + 'async_hooks': { + AsyncLocalStorage : function () { + return { + getStore: function (){ + return asyncStorageMock + }, + run: function (object, callback) { + callback() + } + } + } + } + }) +} + +describe('Request Context', () => { + beforeEach(() => { + asyncStorageMock = {} + }) + + it('sets the correlation id when there is no x-request-id header', () => { + const requestContext = getRequestContext() + + const req = { + headers: {} + } + const res = null + const next = sinon.spy() + + requestContext.requestContextMiddleware(req, res, next) + expect(asyncStorageMock[CORRELATION_ID]).to.equal('test-correlation-id') + sinon.assert.calledWithExactly(next) + }) + + it('sets the correlation id using the x-request-id header when it exists', () => { + const requestContext = getRequestContext() + const xRequestIdHeaderValue = 'x-request-id-value' + + const req = { + headers: {} + } + + req.headers[CORRELATION_ID] = xRequestIdHeaderValue + + const res = null + const next = sinon.spy() + + requestContext.requestContextMiddleware(req, res, next) + expect(asyncStorageMock[CORRELATION_ID]).to.equal('x-request-id-value') + sinon.assert.calledWithExactly(next) + }) + + it('check it can add a field to the request context', () => { + const testKey = 'test-key' + const testValue = 'test-value' + + const requestContext = getRequestContext() + + requestContext.addField(testKey, testValue) + expect(asyncStorageMock[testKey]).to.equal(testValue) + }) + + it('get the correlation id from the async storage', () => { + const testCorrelationId = 'test-correlation-id' + asyncStorageMock[CORRELATION_ID] = testCorrelationId + const requestContext = getRequestContext() + + const correlationId = requestContext.getRequestCorrelationIDField() + expect(correlationId).to.equal(testCorrelationId) + }) + + it('get the loggingFields from the async storage', () => { + const testKey1 = 'test-key-1' + const testKey2 = 'test-key-2' + const testValue1 = 'test-value-1' + const testValue2 = 'test-value-2' + + asyncStorageMock[testKey1] = testValue1 + asyncStorageMock[testKey2] = testValue2 + + const requestContext = getRequestContext() + + const loggingFields = requestContext.getLoggingFields() + expect(loggingFields[testKey1]).to.equal(testValue1) + expect(loggingFields[testKey2]).to.equal(testValue2) + }) +}) diff --git a/app/middleware/correlation-id.js b/app/middleware/correlation-id.js deleted file mode 100644 index 716e048f7..000000000 --- a/app/middleware/correlation-id.js +++ /dev/null @@ -1,18 +0,0 @@ -'use strict' - -// Core Dependencies -const crypto = require('crypto') - -// NPM Dependencies -const correlator = require('correlation-id') - -// Local Dependencies -const CORRELATION_HEADER = require('../../config').CORRELATION_HEADER - -module.exports = correlationMiddleware - -function correlationMiddleware (req, res, next) { - const id = req.headers[CORRELATION_HEADER] || crypto.randomBytes(16).toString('hex') - req.correlationId = id - correlator.withId(id, next) -} diff --git a/app/middleware/correlation-id.test.js b/app/middleware/correlation-id.test.js deleted file mode 100644 index 9bbe8f144..000000000 --- a/app/middleware/correlation-id.test.js +++ /dev/null @@ -1,34 +0,0 @@ -'use strict' - -// NPM Dependencies -const correlator = require('correlation-id') -const { expect } = require('chai') - -// Local Dependencies -const { CORRELATION_HEADER } = require('../../config') -const correlationMiddleware = require('./correlation-id') -let req - -describe('correlation ID middleware', () => { - beforeEach(() => { - req = { - headers: {} - } - req.headers[CORRELATION_HEADER] = `${Math.floor(Math.random() * 100000) + 1}` - }) - it('should store a request\'s correlation id using the \'correlation-id\' npm module', done => { - correlationMiddleware(req, {}, (err) => { - expect(err).to.equal(undefined) - expect(correlator.getId()).to.equal(req.headers[CORRELATION_HEADER]) - done() - }) - }) - - it('should store a request\'s correlation id on it\'s \'correlationId\' property', done => { - correlationMiddleware(req, {}, (err) => { - expect(err).to.equal(undefined) - expect(req.correlationId).to.equal(req.headers[CORRELATION_HEADER]) - done() - }) - }) -}) diff --git a/app/middleware/resolve-payment-and-product.js b/app/middleware/resolve-payment-and-product.js index 3f8a764b1..49a3f8c27 100644 --- a/app/middleware/resolve-payment-and-product.js +++ b/app/middleware/resolve-payment-and-product.js @@ -4,7 +4,7 @@ const { renderErrorView } = require('../utils/response') const productsClient = require('../clients/products/products.client') const adminusersClient = require('../clients/adminusers/adminusers.client') -const { addLoggingField } = require('../utils/log-context') +const { addField } = require('../clients/base/request-context') const { GATEWAY_ACCOUNT_ID, SERVICE_EXTERNAL_ID, PAYMENT_EXTERNAL_ID, PRODUCT_EXTERNAL_ID } = require('@govuk-pay/pay-js-commons').logging.keys module.exports = function (req, res, next) { @@ -12,21 +12,21 @@ module.exports = function (req, res, next) { const correlationId = req.correlationId productsClient.payment.getByPaymentExternalId(paymentExternalId) .then(payment => { - addLoggingField(PAYMENT_EXTERNAL_ID, payment.externalId) + addField(PAYMENT_EXTERNAL_ID, payment.externalId) req.payment = res.locals.payment = payment return productsClient.product.getByProductExternalId(payment.productExternalId) }) .then(product => { req.product = res.locals.product = product - addLoggingField(PRODUCT_EXTERNAL_ID, product.externalId) + addField(PRODUCT_EXTERNAL_ID, product.externalId) return product }) .then(product => { - addLoggingField(GATEWAY_ACCOUNT_ID, product.gatewayAccountId) + addField(GATEWAY_ACCOUNT_ID, product.gatewayAccountId) return adminusersClient.getServiceByGatewayAccountId(product.gatewayAccountId, correlationId) }) .then(service => { - addLoggingField(SERVICE_EXTERNAL_ID, service.externalId) + addField(SERVICE_EXTERNAL_ID, service.externalId) req.service = service res.locals.service = service next() diff --git a/app/middleware/resolve-product.js b/app/middleware/resolve-product.js index 56c6473f0..96b39a58c 100644 --- a/app/middleware/resolve-product.js +++ b/app/middleware/resolve-product.js @@ -5,23 +5,23 @@ const { renderErrorView } = require('../utils/response') const productsClient = require('../clients/products/products.client') const adminusersClient = require('../clients/adminusers/adminusers.client') const { GATEWAY_ACCOUNT_ID, SERVICE_EXTERNAL_ID, PRODUCT_EXTERNAL_ID } = require('@govuk-pay/pay-js-commons').logging.keys -const { addLoggingField } = require('../utils/log-context') +const { addField } = require('../clients/base/request-context') module.exports = function (req, res, next) { const { productExternalId } = req.params productsClient.product.getByProductExternalId(productExternalId) .then(product => { - addLoggingField(PRODUCT_EXTERNAL_ID, product.externalId) + addField(PRODUCT_EXTERNAL_ID, product.externalId) req.product = product res.locals.product = product return product }) .then(product => { - addLoggingField(GATEWAY_ACCOUNT_ID, product.gatewayAccountId) + addField(GATEWAY_ACCOUNT_ID, product.gatewayAccountId) return adminusersClient.getServiceByGatewayAccountId(product.gatewayAccountId, req.correlationId) }) .then(service => { - addLoggingField(SERVICE_EXTERNAL_ID, service.externalId) + addField(SERVICE_EXTERNAL_ID, service.externalId) req.service = service res.locals.service = service next() diff --git a/app/routes.js b/app/routes.js index f2a19d8e2..9b16f871a 100644 --- a/app/routes.js +++ b/app/routes.js @@ -22,8 +22,6 @@ const { validateAndRefreshCsrf, ensureSessionHasCsrfSecret } = require('./middle const resolveProduct = require('./middleware/resolve-product') const resolvePaymentAndProduct = require('./middleware/resolve-payment-and-product') const resolveLanguage = require('./middleware/resolve-language') -// - Middleware -const correlationId = require('./middleware/correlation-id') // Assignments const { healthcheck, staticPaths, friendlyUrl, pay, demoPayment, paymentLinks } = paths @@ -35,9 +33,6 @@ module.exports.paths = paths module.exports.bind = function (app) { app.get('/style-guide', (req, res) => response(req, res, 'style_guide')) - // APPLY CORRELATION MIDDLEWARE - app.use('*', correlationId) - // HEALTHCHECK app.get(healthcheck.path, healthcheckCtrl) diff --git a/app/utils/log-context.js b/app/utils/log-context.js deleted file mode 100644 index 78404f9c7..000000000 --- a/app/utils/log-context.js +++ /dev/null @@ -1,31 +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') - -const asyncLocalStorage = new AsyncLocalStorage() - -function logContextMiddleware (req, res, next) { - asyncLocalStorage.run({}, () => { - asyncLocalStorage.getStore()[CORRELATION_ID] = req.headers[CORRELATION_HEADER] - next() - }) -} - -function addLoggingField (key, value) { - if (asyncLocalStorage.getStore()) { - asyncLocalStorage.getStore()[key] = value - } -} - -function getLoggingFields () { - return asyncLocalStorage.getStore() -} - -module.exports = { - logContextMiddleware, - addLoggingField, - getLoggingFields -} diff --git a/app/utils/logger.js b/app/utils/logger.js index 044f17b8c..c0bd74e6b 100644 --- a/app/utils/logger.js +++ b/app/utils/logger.js @@ -2,7 +2,7 @@ const { createLogger, format, transports } = require('winston') const { json, splat, prettyPrint } = format const { govUkPayLoggingFormat } = require('@govuk-pay/pay-js-commons').logging const { addSentryToErrorLevel } = require('./sentry.js') -const { getLoggingFields } = require('./log-context') +const { getLoggingFields } = require('../clients/base/request-context') const supplementSharedLoggingFields = format((info) => { if (getLoggingFields()) { diff --git a/app/utils/request-logger.js b/app/utils/request-logger.js deleted file mode 100644 index 6551f34b9..000000000 --- a/app/utils/request-logger.js +++ /dev/null @@ -1,34 +0,0 @@ -const logger = require('./logger')(__filename) - -module.exports = { - logRequestStart: context => { - logger.debug(`Calling ${context.service} ${context.description}`, { - service: context.service, - method: context.method, - url: context.url - }) - }, - - logRequestEnd: context => { - const duration = new Date() - context.startTime - logger.info(`[${context.correlationId}] - ${context.method} to ${context.url} ended - elapsed time: ${duration} ms`) - }, - - logRequestFailure: (context, response) => { - logger.info(`[${context.correlationId}] Calling ${context.service} to ${context.description} failed`, { - service: context.service, - method: context.method, - url: context.url, - status: response.statusCode - }) - }, - - logRequestError: (context, error) => { - logger.error(`[${context.correlationId}] Calling ${context.service} to ${context.description} threw exception`, { - service: context.service, - method: context.method, - url: context.url, - error: error - }) - } -} diff --git a/config/server.js b/config/server.js index a2a18ae8c..4705184da 100644 --- a/config/server.js +++ b/config/server.js @@ -25,7 +25,7 @@ const cookieUtil = require('../app/utils/cookie') const i18nConfig = require('./i18n') const logger = require('../app/utils/logger')(__filename) const loggingMiddleware = require('../app/middleware/logging-middleware') -const { logContextMiddleware } = require('../app/utils/log-context') +const { requestContextMiddleware } = require('../app/clients/base/request-context') const Sentry = require('../app/utils/sentry.js').initialiseSentry() const replaceParamsInPath = require('../app/utils/replace-params-in-path') @@ -52,7 +52,7 @@ const APP_VIEWS = [ function initialiseGlobalMiddleware (app) { app.use(cookieParser()) - app.use(logContextMiddleware) + app.use(requestContextMiddleware) logger.stream = { write: function (message) { logger.info(message) diff --git a/test/integration/log-context.it.test.js b/test/integration/log-context.it.test.js deleted file mode 100644 index 187ca43b5..000000000 --- a/test/integration/log-context.it.test.js +++ /dev/null @@ -1,41 +0,0 @@ -'use strict' - -const express = require('express') -const request = require('supertest') -const { expect } = require('chai') - -const logContext = require('../../app/utils/log-context') - -describe('Log context async storage', () => { - const path = '/test-log-context' - let app - let assignedLoggingFields - - before(() => { - app = express() - app.use(logContext.logContextMiddleware) - app.use((req, res, next) => { - logContext.addLoggingField('a_key', 'foo') - next() - }) - app.get(path, (req, res) => { - assignedLoggingFields = logContext.getLoggingFields() - res.status(200) - res.end() - }) - }) - - it('should retrieve logging fields from log context', done => { - request(app) - .get(path) - .set('x-request-id', 'bar') - .expect(200) - .end(() => { - expect(assignedLoggingFields).to.deep.equal({ - 'x_request_id': 'bar', - 'a_key': 'foo' - }) - done() - }) - }) -})