Merge pull request #27756 from backstage/camilaibs/add-meta-to-logging-middleware

[Core] Enable structured request logging

.changeset/five-goats-travel.md

@@ -0,0 +1,6 @@
+---
+'@backstage/backend-defaults': patch
+---
+
+Log request and response metadata so it can be used for filtering log messages.
+The format of the request date was also changed from `clf` to `utc`.

packages/backend-defaults/package.json

@@ -163,7 +163,6 @@
     "luxon": "^3.0.0",
     "minimatch": "^9.0.0",
     "minimist": "^1.2.5",
-    "morgan": "^1.10.0",
     "mysql2": "^3.0.0",
     "node-fetch": "^2.7.0",
     "node-forge": "^1.3.1",
@@ -193,7 +192,6 @@
     "@types/base64-stream": "^1.0.2",
     "@types/concat-stream": "^2.0.0",
     "@types/http-errors": "^2.0.0",
-    "@types/morgan": "^1.9.0",
     "@types/node-forge": "^1.3.0",
     "@types/pg-format": "^1.0.5",
     "@types/stoppable": "^1.1.0",

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

@@ -27,33 +27,22 @@ import express from 'express';
 import createError from 'http-errors';
 import request from 'supertest';
 import { MiddlewareFactory } from './MiddlewareFactory';
-import { ConfigReader } from '@backstage/config';
+import { mockServices } from '@backstage/backend-test-utils';
+
+jest.useFakeTimers({ now: new Date('2024-11-20T00:00:00Z') });
 
 describe('MiddlewareFactory', () => {
   describe('middleware.error', () => {
-    const childLogger = {
-      info: jest.fn(),
-      warn: jest.fn(),
-      error: jest.fn(),
-      debug: jest.fn(),
-      child: jest.fn(),
-    };
-
-    const logger = {
-      info: jest.fn(),
-      warn: jest.fn(),
-      error: jest.fn(),
-      debug: jest.fn(),
-      child: () => childLogger,
-    };
+    const childLogger = mockServices.logger.mock();
+    const logger = mockServices.logger.mock({ child: () => childLogger });
 
     const middleware = MiddlewareFactory.create({
       logger,
-      config: new ConfigReader({}),
+      config: mockServices.rootConfig.mock(),
     });
 
     beforeEach(() => {
-      jest.resetAllMocks();
+      jest.clearAllMocks();
     });
 
     it('gives default code and message', async () => {
@@ -195,9 +184,7 @@ describe('MiddlewareFactory', () => {
     it('should filter out internal errors', async () => {
       const app = express();
 
-      const grandChildLogger = {
-        error: jest.fn(),
-      };
+      const grandChildLogger = mockServices.logger.mock();
       childLogger.child.mockReturnValue(grandChildLogger);
 
       class DatabaseError extends Error {}
@@ -254,5 +241,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.info).toHaveBeenCalledWith(
+        expect.stringContaining(
+          '[2024-11-20T00:00:00.000Z] "GET / HTTP/1.1" 200 11 "-" "-"',
+        ),
+        {
+          type: 'incomingRequest',
+          date: '2024-11-20T00:00:00.000Z',
+          method: 'GET',
+          url: '/',
+          status: 200,
+          httpVersion: '1.1',
+          contentLength: 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.info).toHaveBeenCalledWith(
+        expect.stringContaining(
+          '[2024-11-20T00:00:00.000Z] "GET / HTTP/1.1" 200 11 "test-referrer" "test-agent"',
+        ),
+        {
+          type: 'incomingRequest',
+          date: '2024-11-20T00:00:00.000Z',
+          method: 'GET',
+          url: '/',
+          status: 200,
+          httpVersion: '1.1',
+          userAgent: 'test-agent',
+          referrer: 'test-referrer',
+          contentLength: 11,
+        },
+      );
+    });
   });
 });

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

@@ -27,7 +27,6 @@ import {
 } from 'express';
 import cors from 'cors';
 import helmet from 'helmet';
-import morgan from 'morgan';
 import compression from 'compression';
 import { readHelmetOptions } from './readHelmetOptions';
 import { readCorsOptions } from './readCorsOptions';
@@ -45,6 +44,45 @@ import {
 import { NotImplementedError } from '@backstage/errors';
 import { applyInternalErrorFilter } from './applyInternalErrorFilter';
 
+type LogMeta = {
+  date: string;
+  method: string;
+  url: string;
+  status: number;
+  httpVersion: string;
+  userAgent?: string;
+  contentLength?: number;
+  referrer?: string;
+};
+
+function getLogMeta(req: Request, res: Response): LogMeta {
+  const referrer = req.headers.referer ?? req.headers.referrer;
+  const userAgent = req.headers['user-agent'];
+  const contentLength = Number(res.getHeader('content-length'));
+
+  const meta: LogMeta = {
+    date: new Date().toISOString(),
+    method: req.method,
+    url: req.originalUrl ?? req.url,
+    status: res.statusCode,
+    httpVersion: `${req.httpVersionMajor}.${req.httpVersionMinor}`,
+  };
+
+  if (userAgent) {
+    meta.userAgent = userAgent;
+  }
+
+  if (isFinite(contentLength)) {
+    meta.contentLength = contentLength;
+  }
+
+  if (referrer) {
+    meta.referrer = Array.isArray(referrer) ? referrer.join(', ') : referrer;
+  }
+
+  return meta;
+}
+
 /**
  * Options used to create a {@link MiddlewareFactory}.
  *
@@ -137,18 +175,24 @@ 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;
+    return (req: Request, res: Response, next: NextFunction) => {
+      res.on('finish', () => {
+        const meta = getLogMeta(req, res);
+        logger.info(
+          `[${meta.date}] "${meta.method} ${meta.url} HTTP/${
+            meta.httpVersion
+          }" ${meta.status} ${meta.contentLength} "${meta.referrer ?? '-'}" "${
+            meta.userAgent ?? '-'
+          }"`,
+          {
+            type: 'incomingRequest',
+            ...meta,
+          },
+        );
+      });
+      next();
+    };
   }
 
   /**

yarn.lock

@@ -3611,7 +3611,6 @@ __metadata:
     "@types/cors": ^2.8.6
     "@types/express": ^4.17.6
     "@types/http-errors": ^2.0.0
-    "@types/morgan": ^1.9.0
     "@types/node-forge": ^1.3.0
     "@types/pg-format": ^1.0.5
     "@types/stoppable": ^1.1.0
@@ -3640,7 +3639,6 @@ __metadata:
     luxon: ^3.0.0
     minimatch: ^9.0.0
     minimist: ^1.2.5
-    morgan: ^1.10.0
     msw: ^1.0.0
     mysql2: ^3.0.0
     node-fetch: ^2.7.0