From e5255f18b3aad59a567e50d36e9742621481ab04 Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 11:21:32 +0100 Subject: [PATCH] feat: log request and response metadata Signed-off-by: Camila Belo --- .changeset/five-goats-travel.md | 5 ++ .../http/MiddlewareFactory.test.ts | 59 ++++++++++++++++++- .../rootHttpRouter/http/MiddlewareFactory.ts | 51 ++++++++++++---- 3 files changed, 102 insertions(+), 13 deletions(-) create mode 100644 .changeset/five-goats-travel.md diff --git a/.changeset/five-goats-travel.md b/.changeset/five-goats-travel.md new file mode 100644 index 0000000000..6bcc12e36e --- /dev/null +++ b/.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. 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..c179ea4dba 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/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"', + ), + ); + }); }); }); diff --git a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts index f38c10820a..20959dcbe5 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/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 = {}; + 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()); + }, }, }, - }); + ); } /**