diff --git a/.github/dependabot.yml b/.github/dependabot.yml index 3210d890..a493e276 100644 --- a/.github/dependabot.yml +++ b/.github/dependabot.yml @@ -42,6 +42,7 @@ updates: forms: patterns: + - '@defra/forms-common' - '@defra/forms-model' aws: diff --git a/jest.config.cjs b/jest.config.cjs index 5c7f0d1d..fdf4102d 100644 --- a/jest.config.cjs +++ b/jest.config.cjs @@ -40,6 +40,7 @@ module.exports = { // See: https://jestjs.io/docs/ecmascript-modules transformIgnorePatterns: [ `node_modules/(?!${[ + '@defra/forms-common', // Supports ESM only '@defra/forms-model/.*', '@joi/date', // Supports ESM only 'nanoid', // Supports ESM only diff --git a/package-lock.json b/package-lock.json index 132fff38..aa9cc6b4 100644 --- a/package-lock.json +++ b/package-lock.json @@ -13,6 +13,7 @@ "@aws-sdk/client-s3": "^3.1062.0", "@aws-sdk/client-sns": "^3.1062.0", "@aws-sdk/credential-providers": "3.1073.0", + "@defra/forms-common": "^0.1.0", "@defra/forms-model": "^4.0.0", "@defra/hapi-tracing": "^1.30.0", "@elastic/ecs-pino-format": "^1.5.0", @@ -2498,6 +2499,20 @@ "node": ">=0.1.90" } }, + "node_modules/@defra/forms-common": { + "version": "0.1.4", + "resolved": "https://registry.npmjs.org/@defra/forms-common/-/forms-common-0.1.4.tgz", + "integrity": "sha512-c620nL5kd7RW48Jw17B6xXSoyLKVjwS9mQrnd9OmiBoFGlCoNyK0Qu3gCIbBmjtXsp7O/0M+evvU6048ed46/g==", + "license": "OGL-UK-3.0", + "engines": { + "node": "^24.19.0", + "npm": "^11.17.0 || >=12.0.2" + }, + "peerDependencies": { + "@hapi/hapi": "^21.0.0", + "pino": "^10.0.0" + } + }, "node_modules/@defra/forms-model": { "version": "4.0.1", "resolved": "https://registry.npmjs.org/@defra/forms-model/-/forms-model-4.0.1.tgz", diff --git a/package.json b/package.json index b2b40bcb..3bd7642c 100644 --- a/package.json +++ b/package.json @@ -44,6 +44,7 @@ "@aws-sdk/client-s3": "^3.1062.0", "@aws-sdk/client-sns": "^3.1062.0", "@aws-sdk/credential-providers": "3.1073.0", + "@defra/forms-common": "^0.1.0", "@defra/forms-model": "^4.0.0", "@defra/hapi-tracing": "^1.30.0", "@elastic/ecs-pino-format": "^1.5.0", diff --git a/src/helpers/logging/logger-options.js b/src/helpers/logging/logger-options.js index 8bbeb7ff..f77940df 100644 --- a/src/helpers/logging/logger-options.js +++ b/src/helpers/logging/logger-options.js @@ -1,4 +1,4 @@ -import { getTraceId } from '@defra/hapi-tracing' +import { addLogContextToMessage, logContextMixin } from '@defra/forms-common' import { ecsFormat } from '@elastic/ecs-pino-format' import { config } from '~/src/config/index.js' @@ -28,13 +28,9 @@ export const loggerOptions = /** @type {any} */ ({ level: logConfig.level, ...formatters[/** @type {'ecs' | 'pino-pretty'} */ (logConfig.format)], nesting: true, - mixin() { - const mixinValues = {} - const traceId = getTraceId() - if (traceId) { - mixinValues.trace = { id: traceId } - } - return mixinValues + mixin: logContextMixin, + hooks: { + logMethod: addLogContextToMessage } }) diff --git a/src/helpers/logging/logger-options.test.js b/src/helpers/logging/logger-options.test.js new file mode 100644 index 00000000..e02fd98c --- /dev/null +++ b/src/helpers/logging/logger-options.test.js @@ -0,0 +1,13 @@ +import { addLogContextToMessage, logContextMixin } from '@defra/forms-common' + +import { loggerOptions } from '~/src/helpers/logging/logger-options.js' + +describe('logger-options', () => { + it('should use the forms-common log context mixin', () => { + expect(loggerOptions.mixin).toBe(logContextMixin) + }) + + it('should use the forms-common log message hook', () => { + expect(loggerOptions.hooks.logMethod).toBe(addLogContextToMessage) + }) +}) diff --git a/src/helpers/logging/request-logger.js b/src/helpers/logging/request-logger.js index 7fa54419..5928f14f 100644 --- a/src/helpers/logging/request-logger.js +++ b/src/helpers/logging/request-logger.js @@ -12,19 +12,7 @@ export const requestLogger = { log4xxResponseErrors: true, logRequestComplete: true, customRequestCompleteMessage(request, responseTime) { - const { credentials, isAuthenticated } = request.auth - - let userPrefix = '' - - if (isAuthenticated && credentials.user) { - const { user } = credentials - - if (user.oid) { - userPrefix = ` [${user.oid}] ` - } - } - - return `[response]${userPrefix} ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)` + return `[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)` } } } diff --git a/src/helpers/request-tracing.js b/src/helpers/request-tracing.js index f45d95ef..3e1a0e5d 100644 --- a/src/helpers/request-tracing.js +++ b/src/helpers/request-tracing.js @@ -1,10 +1,55 @@ +import { + applyTraceHeaders as applyTraceHeader, + requestTracing as requestTracingPlugin +} from '@defra/forms-common' import { tracing } from '@defra/hapi-tracing' import { config } from '~/src/config/index.js' +const tracingHeader = config.get('tracing.header') + +/** + * Adds the correlation ID of the current log context to the headers of an + * outbound HTTP request, so the receiving service logs the same ID + * @template {Record} Headers + * @param {Headers} [headers] - the existing headers + * @returns {Headers | undefined} + */ +export function applyTraceHeaders(headers) { + return applyTraceHeader(headers, tracingHeader) +} + +/** + * Gets the unique ID (`oid`) of the authenticated user + * @param {Request} request + * @returns {string | undefined} + */ +export function getRequestUserId(request) { + const { credentials, isAuthenticated } = request.auth + + if (!isAuthenticated) { + return undefined + } + + return credentials.user?.oid +} + +/** + * Starts a log context for every request, holding the correlation ID from the + * tracing header (or a new ID when the caller sent none) and the ID of the + * authenticated user. The logger writes both on every log line. + * @satisfies {ServerRegisterPluginObject} + */ export const requestTracing = { - plugin: tracing, + plugin: requestTracingPlugin, options: { - tracingHeader: config.get('tracing.header') + tracingHeader, + tracingPlugin: tracing.plugin, + getUserId: getRequestUserId } } + +/** + * @import { RequestTracingOptions } from '@defra/forms-common' + * @import { Request, ServerRegisterPluginObject } from '@hapi/hapi' + */ diff --git a/src/helpers/request-tracing.test.js b/src/helpers/request-tracing.test.js new file mode 100644 index 00000000..da8920d7 --- /dev/null +++ b/src/helpers/request-tracing.test.js @@ -0,0 +1,165 @@ +import { + createLogContext, + getCorrelationId, + getUserId, + runWithLogContext +} from '@defra/forms-common' +import { getTraceId } from '@defra/hapi-tracing' +import hapi from '@hapi/hapi' + +import { + applyTraceHeaders, + getRequestUserId, + requestTracing +} from '~/src/helpers/request-tracing.js' + +describe('request-tracing', () => { + const tracingHeader = 'x-cdp-request-id' + const correlationId = '1066e8cc-8e1e-4671-8ad7-b4cd9c95bb94' + const userId = '86758ba9-92e7-4287-9751-7705e449f0a5' + + describe('plugin', () => { + /** @type {Server} */ + let server + + /** @type {{ correlationId?: string, userId?: string }} */ + let responseContext + + beforeEach(async () => { + server = hapi.server() + responseContext = {} + + server.auth.scheme('test', () => ({ + authenticate(request, h) { + return h.authenticated({ + credentials: /** @type {AuthCredentials} */ ( + /** @type {unknown} */ ({ user: { oid: userId } }) + ) + }) + } + })) + server.auth.strategy('test', 'test') + + await server.register(requestTracing) + + const handler = () => ({ + correlationId: getCorrelationId(), + traceId: getTraceId(), + userId: getUserId() + }) + + server.route([ + { method: 'GET', path: '/open', handler }, + { + method: 'GET', + path: '/secure', + handler, + options: { auth: 'test' } + } + ]) + + // The response log is written when this event is emitted + server.events.on('response', () => { + responseContext = { + correlationId: getCorrelationId(), + userId: getUserId() + } + }) + }) + + afterEach(async () => { + await server.stop() + }) + + it('should use the correlation ID from the tracing header', async () => { + const { result } = await server.inject({ + method: 'GET', + url: '/open', + headers: { [tracingHeader]: correlationId } + }) + + expect(result).toEqual({ + correlationId, + traceId: correlationId, + userId: undefined + }) + expect(responseContext).toEqual({ correlationId, userId: undefined }) + }) + + it('should add the ID of the authenticated user', async () => { + const { result } = await server.inject({ + method: 'GET', + url: '/secure', + headers: { [tracingHeader]: correlationId } + }) + + expect(result).toEqual({ + correlationId, + traceId: correlationId, + userId + }) + expect(responseContext).toEqual({ correlationId, userId }) + }) + }) + + describe('getRequestUserId', () => { + /** + * @param {object} auth + */ + function buildRequest(auth) { + return /** @type {Request} */ (/** @type {unknown} */ ({ auth })) + } + + it('should return the oid of the user', () => { + const request = buildRequest({ + isAuthenticated: true, + credentials: { user: { oid: userId } } + }) + + expect(getRequestUserId(request)).toBe(userId) + }) + + it('should return undefined when the user has no oid', () => { + const request = buildRequest({ + isAuthenticated: true, + credentials: { user: {} } + }) + + expect(getRequestUserId(request)).toBeUndefined() + }) + + it('should return undefined when the request is not authenticated', () => { + const request = buildRequest({ + isAuthenticated: false, + credentials: { user: { oid: userId } } + }) + + expect(getRequestUserId(request)).toBeUndefined() + }) + }) + + describe('applyTraceHeaders', () => { + it('should return the headers unchanged outside of a log context', () => { + const headers = { accept: 'application/json' } + + expect(applyTraceHeaders(headers)).toBe(headers) + expect(applyTraceHeaders(undefined)).toBeUndefined() + }) + + it('should add the tracing header', () => { + runWithLogContext(createLogContext({ correlationId }), () => { + expect(applyTraceHeaders({ accept: 'application/json' })).toEqual({ + accept: 'application/json', + [tracingHeader]: correlationId + }) + expect(applyTraceHeaders(undefined)).toEqual({ + [tracingHeader]: correlationId + }) + }) + }) + }) +}) + +/** + * @import { AuthCredentials, Request, Server } from '@hapi/hapi' + */ diff --git a/src/lib/fetch.js b/src/lib/fetch.js index b0a427ac..224c7032 100644 --- a/src/lib/fetch.js +++ b/src/lib/fetch.js @@ -1,6 +1,8 @@ import Boom from '@hapi/boom' import Wreck from '@hapi/wreck' +import { applyTraceHeaders } from '~/src/helpers/request-tracing.js' + const MIN_OK_STATUS = 200 const MAX_OK_STATUS = 299 @@ -12,6 +14,14 @@ const MAX_OK_STATUS = 299 * @returns {Promise<{response: object, body: any}>} */ export async function request(method, url, options) { + const headers = applyTraceHeaders( + /** @type {{ headers?: Record }} */ (options).headers + ) + + if (headers) { + options = { ...options, headers } + } + const response = await Wreck.request(method, url.href, options) const body = await Wreck.read(response, options) diff --git a/src/lib/fetch.test.js b/src/lib/fetch.test.js index 4e35491b..4fae0aaf 100644 --- a/src/lib/fetch.test.js +++ b/src/lib/fetch.test.js @@ -1,3 +1,4 @@ +import { createLogContext, runWithLogContext } from '@defra/forms-common' import Boom from '@hapi/boom' import Wreck from '@hapi/wreck' @@ -43,6 +44,31 @@ describe('fetch utilities', () => { expect(jest.mocked(Wreck.read)).toHaveBeenCalledWith(mockResponse, {}) }) + it('should send the correlation ID of the log context', async () => { + /** @type {any} */ + const mockResponse = { statusCode: 200, headers: {} } + const context = createLogContext({ correlationId: 'correlation-id' }) + + jest.mocked(Wreck.request).mockResolvedValue(mockResponse) + jest.mocked(Wreck.read).mockResolvedValue({}) + + const url = new URL('http://example.com/api') + await runWithLogContext(context, () => + request('get', url, { headers: { accept: 'application/json' } }) + ) + + expect(jest.mocked(Wreck.request)).toHaveBeenCalledWith( + 'get', + 'http://example.com/api', + { + headers: { + accept: 'application/json', + 'x-cdp-request-id': 'correlation-id' + } + } + ) + }) + it('should throw Boom error for non-200 status with message in body', async () => { /** @type {any} */ const mockResponse = { statusCode: 404 } diff --git a/src/messaging/publish-base.js b/src/messaging/publish-base.js index 03d49dd7..9a6b8161 100644 --- a/src/messaging/publish-base.js +++ b/src/messaging/publish-base.js @@ -1,4 +1,5 @@ import { PublishCommand } from '@aws-sdk/client-sns' +import { getMessageAttributes } from '@defra/forms-common' import { config } from '~/src/config/index.js' import { logger } from '~/src/helpers/logging/logger.js' @@ -18,7 +19,8 @@ export async function publishEvent(message) { if (shouldPublish) { const command = new PublishCommand({ TopicArn: snsTopicArn, - Message: JSON.stringify(message) + Message: JSON.stringify(message), + MessageAttributes: getMessageAttributes() }) const result = await client.send(command) diff --git a/src/messaging/publish-base.test.js b/src/messaging/publish-base.test.js index b30cc4b1..4aa9b70a 100644 --- a/src/messaging/publish-base.test.js +++ b/src/messaging/publish-base.test.js @@ -1,4 +1,5 @@ import { PublishCommand, SNSClient } from '@aws-sdk/client-sns' +import { createLogContext, runWithLogContext } from '@defra/forms-common' import { buildFormCreatedMessage } from '@defra/forms-model/stubs' import { mockClient } from 'aws-sdk-client-mock' @@ -67,5 +68,26 @@ describe('publish-base', () => { Message: JSON.stringify(message) }) }) + + it('should send the log context with the message', async () => { + const context = createLogContext({ + correlationId: 'correlation-id', + userId: 'user-id' + }) + + jest.mocked(config.get).mockReturnValue(true) + snsMock.on(PublishCommand).resolves({ + MessageId: '00000000-0000-0000-0000-000000000000' + }) + + await runWithLogContext(context, () => publishEvent(message)) + expect(snsMock).toHaveReceivedCommandWith(PublishCommand, { + Message: JSON.stringify(message), + MessageAttributes: { + correlationId: { DataType: 'String', StringValue: 'correlation-id' }, + userId: { DataType: 'String', StringValue: 'user-id' } + } + }) + }) }) }) diff --git a/src/typings/hapi-tracing/index.d.ts b/src/typings/hapi-tracing/index.d.ts index 2034ec52..4a31df06 100644 --- a/src/typings/hapi-tracing/index.d.ts +++ b/src/typings/hapi-tracing/index.d.ts @@ -1,6 +1,8 @@ declare module '@defra/hapi-tracing' { import { type Plugin } from '@hapi/hapi' - export const tracing: Plugin + export const tracing: { + plugin: Plugin<{ tracingHeader?: string }> + } export function getTraceId(): string | null }