From e5255f18b3aad59a567e50d36e9742621481ab04 Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 11:21:32 +0100 Subject: [PATCH 1/6] 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()); + }, }, }, - }); + ); } /** From 7fc368041ae57751ac548c40a5e9f2c33db014e9 Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 13:00:01 +0100 Subject: [PATCH 2/6] refactor: apply review suggestions Signed-off-by: Camila Belo --- .../http/MiddlewareFactory.test.ts | 69 ++++++++----------- .../rootHttpRouter/http/MiddlewareFactory.ts | 25 +++---- 2 files changed, 40 insertions(+), 54 deletions(-) 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 c179ea4dba..9bc5d53960 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts @@ -27,32 +27,19 @@ 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(); jest.setSystemTime(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: jest.fn(() => 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(() => { @@ -198,9 +185,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 {} @@ -265,19 +250,19 @@ describe('MiddlewareFactory', () => { await request(app).get('/').expect(200); - expect(logger.child).toHaveBeenCalledWith( - expect.objectContaining({ - type: 'incomingRequest', - method: 'GET', - url: '/', - status: '200', - }), - ); - - expect(childLogger.info).toHaveBeenCalledWith( + expect(logger.info).toHaveBeenCalledWith( expect.stringContaining( '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "-" "-"', ), + { + type: 'incomingRequest', + date: '20/Nov/2024:00:00:00 +0000', + method: 'GET', + url: '/', + status: '200', + httpVersion: '1.1', + contentLength: '11', + }, ); }); @@ -292,21 +277,21 @@ describe('MiddlewareFactory', () => { .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(logger.info).toHaveBeenCalledWith( expect.stringContaining( '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "test-referrer" "test-agent"', ), + { + type: 'incomingRequest', + date: '20/Nov/2024:00:00:00 +0000', + 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 20959dcbe5..6376cc0cff 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts @@ -56,14 +56,14 @@ function getLogMeta( 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') ?? '-', + 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'), }; } @@ -160,7 +160,7 @@ export class MiddlewareFactory { */ logging(): RequestHandler { const logger = this.#logger; - let meta: Record = {}; + let meta: Record = {}; return morgan( (tokens: TokenIndexer, req: IncomingMessage, res: ServerResponse) => { meta = getLogMeta(tokens, req, res); @@ -169,11 +169,12 @@ export class MiddlewareFactory { { stream: { write(message: string) { - const middlewareLogger = logger.child({ + logger.info(message.trimEnd(), { type: 'incomingRequest', - ...meta, + ...Object.entries(meta).reduce((reduced, [key, value]) => { + return value ? { ...reduced, [key]: value } : reduced; + }, {}), }); - middlewareLogger.info(message.trimEnd()); }, }, }, From 4e7001b8c8ccd043fff8ccd9691f48a700e69c67 Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 15:06:29 +0100 Subject: [PATCH 3/6] refactor: apply second review suggestions Signed-off-by: Camila Belo --- .../http/MiddlewareFactory.test.ts | 11 +++++------ .../rootHttpRouter/http/MiddlewareFactory.ts | 18 ++++++++++-------- 2 files changed, 15 insertions(+), 14 deletions(-) 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 9bc5d53960..cd9101bae4 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts @@ -29,8 +29,7 @@ import request from 'supertest'; import { MiddlewareFactory } from './MiddlewareFactory'; import { mockServices } from '@backstage/backend-test-utils'; -jest.useFakeTimers(); -jest.setSystemTime(new Date('2024-11-20T00:00:00Z')); +jest.useFakeTimers({ now: new Date('2024-11-20T00:00:00Z') }); describe('MiddlewareFactory', () => { describe('middleware.error', () => { @@ -256,10 +255,10 @@ describe('MiddlewareFactory', () => { ), { type: 'incomingRequest', - date: '20/Nov/2024:00:00:00 +0000', + date: 'Wed, 20 Nov 2024 00:00:00 GMT', method: 'GET', url: '/', - status: '200', + status: 200, httpVersion: '1.1', contentLength: '11', }, @@ -283,10 +282,10 @@ describe('MiddlewareFactory', () => { ), { type: 'incomingRequest', - date: '20/Nov/2024:00:00:00 +0000', + date: 'Wed, 20 Nov 2024 00:00:00 GMT', method: 'GET', url: '/', - status: '200', + status: 200, httpVersion: '1.1', userAgent: 'test-agent', referrer: 'test-referrer', diff --git a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts index 6376cc0cff..55ca9e158a 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts @@ -55,12 +55,13 @@ function getLogMeta( req: IncomingMessage, res: ServerResponse, ) { + const status = Number(tokens.status(req, res)); return { - date: tokens.date(req, res, 'clf'), + date: tokens.date(req, res, 'web'), method: tokens.method(req, res), url: tokens.url(req, res), httpVersion: tokens['http-version'](req, res), - status: tokens.status(req, res), + status: isNaN(status) ? undefined : status, contentLength: tokens.res(req, res, 'content-length'), referrer: tokens.referrer(req, res), userAgent: tokens.req(req, res, 'user-agent'), @@ -160,19 +161,20 @@ export class MiddlewareFactory { */ logging(): RequestHandler { 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); + const meta = getLogMeta(tokens, req, res); + const message = getLogMessage(tokens, req, res); + return JSON.stringify({ meta, message }); }, { stream: { - write(message: string) { + write(json: string) { + const { meta, message } = JSON.parse(json); logger.info(message.trimEnd(), { type: 'incomingRequest', - ...Object.entries(meta).reduce((reduced, [key, value]) => { - return value ? { ...reduced, [key]: value } : reduced; + ...Object.entries(meta).reduce((rest, [key, value]) => { + return value ? { ...rest, [key]: value } : rest; }, {}), }); }, From 7fc03dc1c171749167baad6aa6c4d21e732caa1f Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 16:00:16 +0100 Subject: [PATCH 4/6] =?UTF-8?q?refactor:=20more=20review=20suggestions=20?= =?UTF-8?q?=F0=9F=8E=89?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Camila Belo --- .../rootHttpRouter/http/MiddlewareFactory.test.ts | 8 ++++---- .../rootHttpRouter/http/MiddlewareFactory.ts | 11 +++++------ 2 files changed, 9 insertions(+), 10 deletions(-) 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 cd9101bae4..1c99c0e020 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts @@ -255,12 +255,12 @@ describe('MiddlewareFactory', () => { ), { type: 'incomingRequest', - date: 'Wed, 20 Nov 2024 00:00:00 GMT', + date: '2024-11-20T00:00:00.000Z', method: 'GET', url: '/', status: 200, httpVersion: '1.1', - contentLength: '11', + contentLength: 11, }, ); }); @@ -282,14 +282,14 @@ describe('MiddlewareFactory', () => { ), { type: 'incomingRequest', - date: 'Wed, 20 Nov 2024 00:00:00 GMT', + date: '2024-11-20T00:00:00.000Z', method: 'GET', url: '/', status: 200, httpVersion: '1.1', userAgent: 'test-agent', referrer: 'test-referrer', - contentLength: '11', + 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 55ca9e158a..070ffb19cf 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts @@ -56,13 +56,14 @@ function getLogMeta( res: ServerResponse, ) { const status = Number(tokens.status(req, res)); + const contentLength = Number(tokens.res(req, res, 'content-length')); return { - date: tokens.date(req, res, 'web'), + date: tokens.date(req, res, 'iso'), method: tokens.method(req, res), url: tokens.url(req, res), httpVersion: tokens['http-version'](req, res), - status: isNaN(status) ? undefined : status, - contentLength: tokens.res(req, res, 'content-length'), + status: isFinite(status) ? status : undefined, + contentLength: isFinite(contentLength) ? contentLength : undefined, referrer: tokens.referrer(req, res), userAgent: tokens.req(req, res, 'user-agent'), }; @@ -173,9 +174,7 @@ export class MiddlewareFactory { const { meta, message } = JSON.parse(json); logger.info(message.trimEnd(), { type: 'incomingRequest', - ...Object.entries(meta).reduce((rest, [key, value]) => { - return value ? { ...rest, [key]: value } : rest; - }, {}), + ...meta, }); }, }, From e3e8d06450b8293c994cae5cd3b1909dbcbd5450 Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Thu, 21 Nov 2024 22:04:07 +0100 Subject: [PATCH 5/6] refactor: remove usage of morgan Signed-off-by: Camila Belo --- packages/backend-defaults/package.json | 2 - .../http/MiddlewareFactory.test.ts | 4 +- .../rootHttpRouter/http/MiddlewareFactory.ts | 89 +++++++++++-------- yarn.lock | 2 - 4 files changed, 53 insertions(+), 44 deletions(-) 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 1c99c0e020..f5256f5a25 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.test.ts @@ -251,7 +251,7 @@ describe('MiddlewareFactory', () => { expect(logger.info).toHaveBeenCalledWith( expect.stringContaining( - '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "-" "-"', + '[2024-11-20T00:00:00.000Z] "GET / HTTP/1.1" 200 11 "-" "-"', ), { type: 'incomingRequest', @@ -278,7 +278,7 @@ describe('MiddlewareFactory', () => { expect(logger.info).toHaveBeenCalledWith( expect.stringContaining( - '[20/Nov/2024:00:00:00 +0000] "GET / HTTP/1.1" 200 11 "test-referrer" "test-agent"', + '[2024-11-20T00:00:00.000Z] "GET / HTTP/1.1" 200 11 "test-referrer" "test-agent"', ), { type: 'incomingRequest', diff --git a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts index 070ffb19cf..a22b783f24 100644 --- a/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts +++ b/packages/backend-defaults/src/entrypoints/rootHttpRouter/http/MiddlewareFactory.ts @@ -18,7 +18,6 @@ import { RootConfigService, LoggerService, } from '@backstage/backend-plugin-api'; -import { IncomingMessage, ServerResponse } from 'http'; import { Request, Response, @@ -28,7 +27,6 @@ import { } from 'express'; import cors from 'cors'; import helmet from 'helmet'; -import morgan, { TokenIndexer } from 'morgan'; import compression from 'compression'; import { readHelmetOptions } from './readHelmetOptions'; import { readCorsOptions } from './readCorsOptions'; @@ -46,27 +44,43 @@ 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"', -); +type LogMeta = { + date: string; + method: string; + url: string; + status: number; + httpVersion: string; + userAgent?: string; + contentLength?: number; + referrer?: string; +}; -function getLogMeta( - tokens: TokenIndexer, - req: IncomingMessage, - res: ServerResponse, -) { - const status = Number(tokens.status(req, res)); - const contentLength = Number(tokens.res(req, res, 'content-length')); - return { - date: tokens.date(req, res, 'iso'), - method: tokens.method(req, res), - url: tokens.url(req, res), - httpVersion: tokens['http-version'](req, res), - status: isFinite(status) ? status : undefined, - contentLength: isFinite(contentLength) ? contentLength : undefined, - referrer: tokens.referrer(req, res), - userAgent: tokens.req(req, res, 'user-agent'), +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; } /** @@ -162,24 +176,23 @@ export class MiddlewareFactory { */ logging(): RequestHandler { const logger = this.#logger; - return morgan( - (tokens: TokenIndexer, req: IncomingMessage, res: ServerResponse) => { - const meta = getLogMeta(tokens, req, res); - const message = getLogMessage(tokens, req, res); - return JSON.stringify({ meta, message }); - }, - { - stream: { - write(json: string) { - const { meta, message } = JSON.parse(json); - logger.info(message.trimEnd(), { - type: 'incomingRequest', - ...meta, - }); + 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 cda2b4bbc0..caa650f862 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 From 45379e8116c63ef876020191c9f388e94b88159c Mon Sep 17 00:00:00 2001 From: Camila Belo Date: Fri, 22 Nov 2024 08:26:28 +0100 Subject: [PATCH 6/6] refactor: mention date format change in changelog Signed-off-by: Camila Belo --- .changeset/five-goats-travel.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.changeset/five-goats-travel.md b/.changeset/five-goats-travel.md index 6bcc12e36e..361c530fca 100644 --- a/.changeset/five-goats-travel.md +++ b/.changeset/five-goats-travel.md @@ -2,4 +2,5 @@ '@backstage/backend-defaults': patch --- -Log request and response metadata as logging fields so they can be used for filtering log messages. +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`.