diff --git a/.changeset/five-goats-travel.md b/.changeset/five-goats-travel.md new file mode 100644 index 0000000000..361c530fca --- /dev/null +++ b/.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`. diff --git a/packages/backend-defaults/package.json b/packages/backend-defaults/package.json index 73f90fd153..ea5d0abd94 100644 --- a/packages/backend-defaults/package.json +++ b/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", diff --git a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts index 418d170365..f5256f5a25 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/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, + }, + ); + }); }); }); diff --git a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts index f38c10820a..a22b783f24 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/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(); + }; } /** diff --git a/yarn.lock b/yarn.lock index 811f17157c..01b3ea83df 100644 --- a/yarn.lock +++ b/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