diff --git a/app/services/clients/base/config.js b/app/services/clients/base/config.js new file mode 100644 index 0000000000..93fbd3f7b7 --- /dev/null +++ b/app/services/clients/base/config.js @@ -0,0 +1,40 @@ +'use strict' + +const requestLogger = require('./request-logger') +const { getRequestCorrelationIDField } = require('./request-context') +const { CORRELATION_HEADER } = require('../../../../config') + +function transformRequestAddHeaders () { + const correlationId = getRequestCorrelationIDField() + const headers = {} + if (correlationId) { + headers[CORRELATION_HEADER] = correlationId + } + return headers +} + +function onRequestStart (context) { + requestLogger.logRequestStart(context) +} + +function onSuccessResponse (context) { + requestLogger.logRequestEnd(context) +} + +function onFailureResponse (context) { + requestLogger.logRequestEnd(context) + requestLogger.logRequestFailure(context) +} + +function configureClient (client, baseUrl) { + client.configure(baseUrl, { + transformRequestAddHeaders, + onRequestStart, + onSuccessResponse, + onFailureResponse + }) +} + +module.exports = { + configureClient +} diff --git a/app/services/clients/base/config.test.js b/app/services/clients/base/config.test.js new file mode 100644 index 0000000000..dbe9b358a3 --- /dev/null +++ b/app/services/clients/base/config.test.js @@ -0,0 +1,90 @@ +'use strict' + +const nock = require('nock') +const sinon = require('sinon') +const proxyquire = require('proxyquire') +const { expect } = require('chai') +const { Client } = require('@govuk-pay/pay-js-commons/lib/utils/axios-base-client/axios-base-client') + +const baseUrl = 'http://localhost:8000' +const app = 'an-app' + +const logInfoSpy = sinon.spy() + +function getConfigWithMocks (correlationId) { + const config = proxyquire('./config.js', { + './request-context': { + getRequestCorrelationIDField: () => correlationId + }, + './request-logger': proxyquire('./request-logger', { + '../../../utils/logger': () => ({ + info: logInfoSpy + }) + }) + }) + return config +} + +describe('Client config', () => { + beforeEach(() => { + logInfoSpy.resetHistory() + }) + + 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') + + config.configureClient(client, baseUrl) + + nock(baseUrl) + .get('/') + .reply(200) + + const response = await client.get('/', 'foo') + + expect(response.status).to.equal(200) + expect(response.request.headers).to.have.property('x-request-id', 'abc123') + }) + + it('should not add correlation ID as header when correlation ID does not exist on request context', async () => { + const client = new Client(app) + const config = getConfigWithMocks() + config.configureClient(client, baseUrl) + + nock(baseUrl) + .get('/') + .reply(200) + + const response = await client.get('/', 'foo') + expect(response.status).to.equal(200) + expect(response.request.headers).to.not.have.key('x-request-id') + }) + }) + + describe('Logging', () => { + it('should log request start', async () => { + const client = new Client(app) + const config = getConfigWithMocks('abc123') + config.configureClient(client, baseUrl) + + nock(baseUrl) + .get('/') + .reply(200) + + const response = await client.get('/', 'do something', { + additionalLoggingFields: { foo: 'bar' } + }) + + expect(response.status).to.equal(200) + + sinon.assert.calledWith(logInfoSpy, 'Calling an-app to do something', { + service: app, + method: 'get', + url: '/', + description: 'do something', + foo: 'bar' + }) + }) + }) +}) diff --git a/app/services/clients/base/request-context.js b/app/services/clients/base/request-context.js new file mode 100644 index 0000000000..cbb1b50096 --- /dev/null +++ b/app/services/clients/base/request-context.js @@ -0,0 +1,38 @@ +'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 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/base/request-logger.js b/app/services/clients/base/request-logger.js new file mode 100644 index 0000000000..38c794d625 --- /dev/null +++ b/app/services/clients/base/request-logger.js @@ -0,0 +1,53 @@ +const logger = require('../../../utils/logger')(__filename) + +module.exports = { + logRequestStart: context => { + logger.info(`Calling ${context.service} to ${context.description}`, { + service: context.service, + method: context.method, + url: context.url, + description: context.description, + ...context.additionalLoggingFields + }) + }, + + logRequestEnd: (context) => { + const responseTime = (context.startTime && new Date() - context.startTime) || context.responseTime + logger.info(`${context.method} to ${context.url} ended - elapsed time: ${responseTime} ms`, { + service: context.service, + method: context.method, + url: context.url, + description: context.description, + response_time: responseTime, + status: context.status, + ...context.additionalLoggingFields + }) + }, + + logRequestFailure: (context) => { + let message = `Calling ${context.service} to ${context.description} failed` + if (context.retry) { + message = message + ' - request will be retried' + } + + logger.info(message, { + service: context.service, + method: context.method, + url: context.url, + description: context.description, + status: context.status, + ...context.additionalLoggingFields + }) + }, + + logRequestError: (context, error) => { + logger.error(`Calling ${context.service} to ${context.description} threw exception`, { + service: context.service, + method: context.method, + url: context.url, + description: context.description, + error: error, + ...context.additionalLoggingFields + }) + } +} diff --git a/package-lock.json b/package-lock.json index 82740a756a..71d7565499 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,7 +9,7 @@ "version": "0.0.1-SNAPSHOT", "license": "MIT", "dependencies": { - "@govuk-pay/pay-js-commons": "4.0.10", + "@govuk-pay/pay-js-commons": "4.0.16", "@govuk-pay/pay-js-metrics": "^1.0.6", "@sentry/node": "6.12.0", "accessible-autocomplete": "2.0.4", @@ -1988,10 +1988,11 @@ } }, "node_modules/@govuk-pay/pay-js-commons": { - "version": "4.0.10", - "resolved": "https://registry.npmjs.org/@govuk-pay/pay-js-commons/-/pay-js-commons-4.0.10.tgz", - "integrity": "sha512-I7Ddrg/+4WZiDtmAjpNkxllwWIjufHydJEhmeZDttxy+F5n2MjKKgkSMEw9chMweUXLjCEEQ/qFC+W6zZ1hZZQ==", + "version": "4.0.16", + "resolved": "https://registry.npmjs.org/@govuk-pay/pay-js-commons/-/pay-js-commons-4.0.16.tgz", + "integrity": "sha512-CMXVvNlutG3SNeE3o/pgTML0YlXJ0BHPkojKQiaURhDGwjGVuiSAjP/3Gxvu/5ckA9O2dh4pIHzk3HM3dnzu1g==", "dependencies": { + "axios": "^1.6.5", "lodash": "4.17.21", "moment-timezone": "0.5.43", "rfc822-validate": "1.0.0", @@ -3281,9 +3282,9 @@ "integrity": "sha512-xh1Rl34h6Fi1DC2WWKfxUTVqRsNnr6LsKz2+hfwDxQJWmrx8+c7ylaqBMcHfl1U1r2dsifOvKX3LQuLNZ+XSvA==" }, "node_modules/axios": { - "version": "1.6.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-1.6.4.tgz", - "integrity": "sha512-heJnIs6N4aa1eSthhN9M5ioILu8Wi8vmQW9iHQ9NUvfkJb0lEEDUiIdQNAuBtfUt3FxReaKdpQA5DbmMOqzF/A==", + "version": "1.6.7", + "resolved": "https://registry.npmjs.org/axios/-/axios-1.6.7.tgz", + "integrity": "sha512-/hDJGff6/c7u0hDkvkGxR/oy6CbCs8ziCsC7SqmhjfozqiJGc8Z11wrv9z9lYfY4K8l+H9TpjcMDX0xOZmx+RA==", "dependencies": { "follow-redirects": "^1.15.4", "form-data": "^4.0.0", @@ -19003,10 +19004,11 @@ } }, "@govuk-pay/pay-js-commons": { - "version": "4.0.10", - "resolved": "https://registry.npmjs.org/@govuk-pay/pay-js-commons/-/pay-js-commons-4.0.10.tgz", - "integrity": "sha512-I7Ddrg/+4WZiDtmAjpNkxllwWIjufHydJEhmeZDttxy+F5n2MjKKgkSMEw9chMweUXLjCEEQ/qFC+W6zZ1hZZQ==", + "version": "4.0.16", + "resolved": "https://registry.npmjs.org/@govuk-pay/pay-js-commons/-/pay-js-commons-4.0.16.tgz", + "integrity": "sha512-CMXVvNlutG3SNeE3o/pgTML0YlXJ0BHPkojKQiaURhDGwjGVuiSAjP/3Gxvu/5ckA9O2dh4pIHzk3HM3dnzu1g==", "requires": { + "axios": "^1.6.5", "lodash": "4.17.21", "moment-timezone": "0.5.43", "rfc822-validate": "1.0.0", @@ -20028,9 +20030,9 @@ "integrity": "sha512-xh1Rl34h6Fi1DC2WWKfxUTVqRsNnr6LsKz2+hfwDxQJWmrx8+c7ylaqBMcHfl1U1r2dsifOvKX3LQuLNZ+XSvA==" }, "axios": { - "version": "1.6.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-1.6.4.tgz", - "integrity": "sha512-heJnIs6N4aa1eSthhN9M5ioILu8Wi8vmQW9iHQ9NUvfkJb0lEEDUiIdQNAuBtfUt3FxReaKdpQA5DbmMOqzF/A==", + "version": "1.6.7", + "resolved": "https://registry.npmjs.org/axios/-/axios-1.6.7.tgz", + "integrity": "sha512-/hDJGff6/c7u0hDkvkGxR/oy6CbCs8ziCsC7SqmhjfozqiJGc8Z11wrv9z9lYfY4K8l+H9TpjcMDX0xOZmx+RA==", "requires": { "follow-redirects": "^1.15.4", "form-data": "^4.0.0", diff --git a/package.json b/package.json index 653a633f49..694b818372 100644 --- a/package.json +++ b/package.json @@ -82,7 +82,7 @@ } }, "dependencies": { - "@govuk-pay/pay-js-commons": "4.0.10", + "@govuk-pay/pay-js-commons": "4.0.16", "@govuk-pay/pay-js-metrics": "^1.0.6", "@sentry/node": "6.12.0", "accessible-autocomplete": "2.0.4",