feat(api): add more debug logging (#61980)

api/src/app.ts

@@ -86,6 +86,7 @@ export const buildOptions: FastifyHttpOptions<
 > = {
   loggerInstance: getLogger(),
   genReqId: () => randomBytes(8).toString('hex'),
+  // disabled so we can customise the request/response logging
   disableRequestLogging: true
 };
 
@@ -104,6 +105,17 @@ export const build = async (
   const fastify = Fastify(options).withTypeProvider<TypeBoxTypeProvider>();
 
   fastify.setValidatorCompiler(({ schema }) => ajv.compile(schema));
+  fastify.addHook('onRequest', (req, _reply, done) => {
+    const logger = fastify.log.child({ req });
+    logger.debug({ req }, 'received request');
+    done();
+  });
+
+  fastify.addHook('onResponse', (req, reply, done) => {
+    const logger = fastify.log.child({ res: reply });
+    logger.debug({ req, res: reply }, 'responding to request');
+    done();
+  });
 
   void fastify.register(redirectWithMessage);
   void fastify.register(security);

api/src/plugins/cors.test.ts

@@ -2,12 +2,11 @@ import { describe, test, expect, beforeAll, afterAll, vi } from 'vitest';
 import Fastify, { FastifyInstance, LogLevel } from 'fastify';
 import cors from './cors';
 
-const LOG_LEVELS: LogLevel[] = [
+const NON_DEBUG_LOG_LEVELS: LogLevel[] = [
   'fatal',
   'error',
   'warn',
   'info',
-  'debug',
   'trace'
 ];
 
@@ -22,9 +21,10 @@ describe('cors', () => {
     await fastify.close();
   });
 
-  test('should not log for /status/* routes', async () => {
+  test('should only debug log for /status/* routes', async () => {
     const logger = fastify.log.child({ req: { url: '/status/ping' } });
-    const spies = LOG_LEVELS.map(level => vi.spyOn(logger, level));
+    const spies = NON_DEBUG_LOG_LEVELS.map(level => vi.spyOn(logger, level));
+    const debugSpy = vi.spyOn(logger, 'debug');
     await fastify.inject({
       url: '/status/ping'
     });
@@ -32,11 +32,13 @@ describe('cors', () => {
     spies.forEach(spy => {
       expect(spy).not.toHaveBeenCalled();
     });
+    expect(debugSpy).toHaveBeenCalled();
   });
 
-  test('should not log if the origin is undefined', async () => {
+  test('should debug log if the origin is undefined', async () => {
     const logger = fastify.log.child({ req: { url: '/api/some-endpoint' } });
-    const spies = LOG_LEVELS.map(level => vi.spyOn(logger, level));
+    const spies = NON_DEBUG_LOG_LEVELS.map(level => vi.spyOn(logger, level));
+    const debugSpy = vi.spyOn(logger, 'debug');
     await fastify.inject({
       url: '/api/some-endpoint'
     });
@@ -44,5 +46,6 @@ describe('cors', () => {
     spies.forEach(spy => {
       expect(spy).not.toHaveBeenCalled();
     });
+    expect(debugSpy).toHaveBeenCalled();
   });
 });

api/src/plugins/cors.ts

@@ -10,10 +10,10 @@ const cors: FastifyPluginCallback = (fastify, _options, done) => {
   });
 
   fastify.addHook('onRequest', async (req, reply) => {
-    const logger = fastify.log.child({ req, res: reply });
+    const logger = fastify.log.child({ req });
     const origin = req.headers.origin;
     if (origin && allowedOrigins.includes(origin)) {
-      // Do we want to log allowed origins?
+      logger.debug(`Allowing access to origin: ${origin}`);
       void reply.header('Access-Control-Allow-Origin', origin);
     } else {
       // TODO: Discuss if this is the correct approach. Standard practice is to
@@ -24,6 +24,8 @@ const cors: FastifyPluginCallback = (fastify, _options, done) => {
 
       if (origin && !req.url?.startsWith('/status/')) {
         logger.info(`Received request from disallowed origin: ${origin}`);
+      } else {
+        logger.debug(`Unknown or missing origin: ${origin}`);
       }
     }