Improved Logging

.github/dependabot.yml

@@ -42,6 +42,7 @@ updates:
 
       forms:
         patterns:
+          - '@defra/forms-common'
           - '@defra/forms-model'
 
       aws:

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

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",

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
   }
 })
 

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)
+  })
+})

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)`
     }
   }
 }

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<string, any>} 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<RequestTracingOptions>}
+ */
 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'
+ */

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'
+ */

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<string, string> }} */ (options).headers
+  )
+
+  if (headers) {
+    options = { ...options, headers }
+  }
+
   const response = await Wreck.request(method, url.href, options)
   const body = await Wreck.read(response, options)
 

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 }