feat: log request and response metadata

Signed-off-by: Camila Belo <camilaibs@gmail.com>

.changeset/five-goats-travel.md

@@ -0,0 +1,5 @@
+---
+'@backstage/backend-defaults': patch
+---
+
+Log request and response metadata as logging fields so they can be used for filtering log messages.

packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts

@@ -29,6 +29,9 @@ import request from 'supertest';
 import { MiddlewareFactory } from './MiddlewareFactory';
 import { ConfigReader } from '@backstage/config';
 
+jest.useFakeTimers();
+jest.setSystemTime(new Date('2024-11-20T00:00:00Z'));
+
 describe('MiddlewareFactory', () => {
   describe('middleware.error', () => {
     const childLogger = {
@@ -44,7 +47,7 @@ describe('MiddlewareFactory', () => {
       warn: jest.fn(),
       error: jest.fn(),
       debug: jest.fn(),
-      child: () => childLogger,
+      child: jest.fn(() => childLogger),
     };
 
     const middleware = MiddlewareFactory.create({
@@ -53,7 +56,7 @@ describe('MiddlewareFactory', () => {
     });
 
     beforeEach(() => {
-      jest.resetAllMocks();
+      jest.clearAllMocks();
     });
 
     it('gives default code and message', async () => {
@@ -254,5 +257,57 @@ describe('MiddlewareFactory', () => {
 
       expect(childLogger.error).toHaveBeenCalled();
     });
+
+    it('should log incoming requests', async () => {
+      const app = express();
+      app.use(middleware.logging());
+      app.get('/', (_req, res) => res.send('Hello World'));
+
+      await request(app).get('/').expect(200);
+
+      expect(logger.child).toHaveBeenCalledWith(
+        expect.objectContaining({
+          type: 'incomingRequest',
+          method: 'GET',
+          url: '/',
+          status: '200',
+        }),
+      );
+
+      expect(childLogger.info).toHaveBeenCalledWith(
+        expect.stringContaining(
+          '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "-" "-"',
+        ),
+      );
+    });
+
+    it('should log request with all data fields', async () => {
+      const app = express();
+      app.use(middleware.logging());
+      app.get('/', (_req, res) => res.send('Hello World'));
+
+      await request(app)
+        .get('/')
+        .set('User-Agent', 'test-agent')
+        .set('referrer', 'test-referrer')
+        .expect(200);
+
+      expect(logger.child).toHaveBeenCalledWith(
+        expect.objectContaining({
+          type: 'incomingRequest',
+          method: 'GET',
+          url: '/',
+          status: '200',
+          userAgent: 'test-agent',
+          referrer: 'test-referrer',
+        }),
+      );
+
+      expect(childLogger.info).toHaveBeenCalledWith(
+        expect.stringContaining(
+          '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "test-referrer" "test-agent"',
+        ),
+      );
+    });
   });
 });

packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts

@@ -18,6 +18,7 @@ import {
   RootConfigService,
   LoggerService,
 } from '@backstage/backend-plugin-api';
+import { IncomingMessage, ServerResponse } from 'http';
 import {
   Request,
   Response,
@@ -27,7 +28,7 @@ import {
 } from 'express';
 import cors from 'cors';
 import helmet from 'helmet';
-import morgan from 'morgan';
+import morgan, { TokenIndexer } from 'morgan';
 import compression from 'compression';
 import { readHelmetOptions } from './readHelmetOptions';
 import { readCorsOptions } from './readCorsOptions';
@@ -45,6 +46,27 @@ import {
 import { NotImplementedError } from '@backstage/errors';
 import { applyInternalErrorFilter } from './applyInternalErrorFilter';
 
+const getLogMessage = morgan.compile(
+  '[:date[clf]] ":method :url HTTP/:http-version" :status :res[content-length] ":referrer" ":user-agent"',
+);
+
+function getLogMeta(
+  tokens: TokenIndexer,
+  req: IncomingMessage,
+  res: ServerResponse,
+) {
+  return {
+    date: tokens.date(req, res, 'clf') ?? '-',
+    method: tokens.method(req, res) ?? '-',
+    url: tokens.url(req, res) ?? '-',
+    httpVersion: tokens['http-version'](req, res) ?? '-',
+    status: tokens.status(req, res) ?? '-',
+    contentLength: tokens.res(req, res, 'content-length') ?? '-',
+    referrer: tokens.referrer(req, res) ?? '-',
+    userAgent: tokens.req(req, res, 'user-agent') ?? '-',
+  };
+}
+
 /**
  * Options used to create a {@link MiddlewareFactory}.
  *
@@ -137,18 +159,25 @@ export class MiddlewareFactory {
    * @returns An Express request handler
    */
   logging(): RequestHandler {
-    const logger = this.#logger.child({
-      type: 'incomingRequest',
-    });
-    const customMorganFormat =
-      '[:date[clf]] ":method :url HTTP/:http-version" :status :res[content-length] ":referrer" ":user-agent"';
-    return morgan(customMorganFormat, {
-      stream: {
-        write(message: string) {
-          logger.info(message.trimEnd());
+    const logger = this.#logger;
+    let meta: Record<string, string> = {};
+    return morgan(
+      (tokens: TokenIndexer, req: IncomingMessage, res: ServerResponse) => {
+        meta = getLogMeta(tokens, req, res);
+        return getLogMessage(tokens, req, res);
+      },
+      {
+        stream: {
+          write(message: string) {
+            const middlewareLogger = logger.child({
+              type: 'incomingRequest',
+              ...meta,
+            });
+            middlewareLogger.info(message.trimEnd());
+          },
         },
       },
-    });
+    );
   }
 
   /**