BC-8556 implement request logging in nestjs

apps/server/src/apps/admin-api-server.app.ts

@@ -6,6 +6,7 @@ import { LegacyLogger, Logger } from '@src/core/logger';
 import { AdminApiServerModule } from '@modules/server/admin-api.server.module';
 import express from 'express';
 import { install as sourceMapInstall } from 'source-map-support';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import {
 	AppStartLoggable,
 	enableOpenApiDocs,
@@ -23,6 +24,8 @@ async function bootstrap() {
 	const nestAdminServerApp = await NestFactory.create(AdminApiServerModule, nestAdminServerExpressAdapter);
 	const logger = await nestAdminServerApp.resolve(Logger);
 	const legacyLogger = await nestAdminServerApp.resolve(LegacyLogger);
+	nestAdminServerApp.use(createRequestLoggerMiddleware());
+
 	nestAdminServerApp.useLogger(legacyLogger);
 	nestAdminServerApp.enableCors();
 

apps/server/src/apps/board-collaboration.app.ts

@@ -12,6 +12,7 @@ import { RedisIoAdapter } from '@infra/socketio';
 import { BoardCollaborationModule } from '@modules/board/board-collaboration.app.module';
 import express from 'express';
 import { ExpressAdapter } from '@nestjs/platform-express';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import {
 	enableOpenApiDocs,
 	addPrometheusMetricsMiddlewaresIfEnabled,
@@ -37,6 +38,7 @@ async function bootstrap() {
 	};
 	enableOpenApiDocs(nestApp, 'docs', options);
 	const logger = await nestApp.resolve(Logger);
+	nestApp.use(createRequestLoggerMiddleware());
 
 	await nestApp.init();
 

apps/server/src/apps/common-cartridge.app.ts

@@ -6,6 +6,7 @@ import { LegacyLogger, Logger } from '@src/core/logger';
 import { CommonCartridgeApiModule } from '@modules/common-cartridge/common-cartridge-api.module';
 import express from 'express';
 import { install as sourceMapInstall } from 'source-map-support';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import {
 	AppStartLoggable,
 	enableOpenApiDocs,
@@ -27,6 +28,7 @@ async function bootstrap() {
 
 	const rootExpress = express();
 	const logger = await nestApp.resolve(Logger);
+	nestApp.use(createRequestLoggerMiddleware());
 
 	addPrometheusMetricsMiddlewaresIfEnabled(logger, rootExpress);
 

apps/server/src/apps/files-storage.app.ts

@@ -12,6 +12,7 @@ import { FilesStorageApiModule } from '@modules/files-storage/files-storage-api.
 import { API_VERSION_PATH } from '@modules/files-storage/files-storage.const';
 import { SwaggerDocumentOptions } from '@nestjs/swagger';
 import { LegacyLogger } from '@src/core/logger';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import { enableOpenApiDocs } from './helpers';
 
 async function bootstrap() {
@@ -28,6 +29,7 @@ async function bootstrap() {
 
 	// customize nest app settings
 	nestApp.enableCors({ exposedHeaders: ['Content-Disposition'] });
+	nestApp.use(createRequestLoggerMiddleware());
 
 	const options: SwaggerDocumentOptions = {
 		operationIdFactory: (_controllerKey: string, methodKey: string) => methodKey,

apps/server/src/apps/fwu-learning-contents.app.ts

@@ -10,6 +10,7 @@ import { install as sourceMapInstall } from 'source-map-support';
 // application imports
 import { LegacyLogger } from '@src/core/logger';
 import { FwuLearningContentsModule } from '@modules/fwu-learning-contents';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import { enableOpenApiDocs } from './helpers';
 
 async function bootstrap() {
@@ -26,6 +27,7 @@ async function bootstrap() {
 	// customize nest app settings
 	nestApp.enableCors({ exposedHeaders: ['Content-Disposition'] });
 	enableOpenApiDocs(nestApp, 'docs');
+	nestApp.use(createRequestLoggerMiddleware());
 
 	await nestApp.init();
 

apps/server/src/apps/h5p-editor.app.ts

@@ -10,6 +10,7 @@ import { install as sourceMapInstall } from 'source-map-support';
 // application imports
 import { LegacyLogger } from '@src/core/logger';
 import { H5PEditorModule } from '@modules/h5p-editor';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import { enableOpenApiDocs } from './helpers';
 
 async function bootstrap() {
@@ -24,6 +25,8 @@ async function bootstrap() {
 	// WinstonLogger
 	nestApp.useLogger(await nestApp.resolve(LegacyLogger));
 
+	nestApp.use(createRequestLoggerMiddleware());
+
 	// customize nest app settings
 	nestApp.enableCors({ exposedHeaders: ['Content-Disposition'] });
 	enableOpenApiDocs(nestApp, 'docs');

apps/server/src/apps/helpers/request-logger-middleware.spec.ts

@@ -0,0 +1,99 @@
+import { Configuration } from '@hpi-schul-cloud/commons/lib';
+import { Logger } from '@nestjs/common';
+import { Request, Response, NextFunction } from 'express';
+import { createRequestLoggerMiddleware } from './request-logger-middleware';
+
+jest.mock('@hpi-schul-cloud/commons/lib', () => {
+	return {
+		Configuration: {
+			get: jest.fn(),
+		},
+	};
+});
+
+describe('RequestLoggerMiddleware', () => {
+	let mockRequest: Partial<Request>;
+	let mockResponse: Partial<Response>;
+	let nextFunction: NextFunction;
+	let loggerSpy: jest.SpyInstance;
+	let errorLoggerSpy: jest.SpyInstance;
+
+	beforeEach(() => {
+		mockRequest = {
+			method: 'GET',
+			originalUrl: '/test',
+		};
+
+		mockResponse = {
+			statusCode: 200,
+			get: jest.fn(),
+			on: jest.fn(),
+		};
+
+		nextFunction = jest.fn();
+
+		loggerSpy = jest.spyOn(Logger.prototype, 'log');
+		errorLoggerSpy = jest.spyOn(Logger.prototype, 'error');
+	});
+
+	afterEach(() => {
+		jest.clearAllMocks();
+	});
+
+	it('should call next() when logging is disabled', () => {
+		jest.spyOn(Configuration, 'get').mockReturnValue(false);
+
+		const middleware = createRequestLoggerMiddleware();
+		middleware(mockRequest as Request, mockResponse as Response, nextFunction);
+
+		expect(nextFunction).toHaveBeenCalled();
+		expect(mockResponse.on).not.toHaveBeenCalled();
+	});
+
+	it('should log request details when logging is enabled', () => {
+		jest.spyOn(Configuration, 'get').mockReturnValue(true);
+
+		jest.spyOn(process, 'hrtime').mockReturnValueOnce([0, 0]);
+		jest.spyOn(mockResponse, 'get').mockImplementation().mockReturnValue('100');
+
+		// eslint-disable-next-line @typescript-eslint/ban-types
+		let finishCallback: Function | undefined;
+		// eslint-disable-next-line @typescript-eslint/ban-types
+		mockResponse.on = jest.fn().mockImplementation((event: string, callback: Function) => {
+			finishCallback = callback;
+		});
+
+		const middleware = createRequestLoggerMiddleware();
+		middleware(mockRequest as Request, mockResponse as Response, nextFunction);
+
+		expect(nextFunction).toHaveBeenCalled();
+		expect(mockResponse.on).toHaveBeenCalledWith('finish', expect.any(Function));
+
+		// Simulate response finish
+		jest.spyOn(process, 'hrtime').mockReturnValueOnce([1, 0]);
+
+		// Make sure callback was set before calling it
+		expect(finishCallback).toBeDefined();
+		finishCallback?.();
+
+		expect(loggerSpy).toHaveBeenCalledWith('GET /test 200 1000ms 100');
+	});
+
+	it('should handle errors during logging', () => {
+		jest.spyOn(Configuration, 'get').mockReturnValue(true);
+		// eslint-disable-next-line @typescript-eslint/ban-types
+		mockResponse.on = jest.fn().mockImplementation((event: string, callback: Function) => {
+			callback();
+		});
+
+		// Force an error by making response.get throw
+		mockResponse.get = jest.fn().mockImplementation(() => {
+			throw new Error('Test error');
+		});
+
+		const middleware = createRequestLoggerMiddleware();
+		middleware(mockRequest as Request, mockResponse as Response, nextFunction);
+
+		expect(errorLoggerSpy).toHaveBeenCalledWith('unable to write accesslog', Error('Test error'));
+	});
+});

apps/server/src/apps/helpers/request-logger-middleware.ts

@@ -0,0 +1,33 @@
+import { Request, Response, NextFunction } from 'express';
+import { Configuration } from '@hpi-schul-cloud/commons/lib';
+import { Logger } from '@nestjs/common';
+
+export const createRequestLoggerMiddleware = (): ((
+	request: Request,
+	response: Response,
+	next: NextFunction
+) => void) => {
+	const enabled = Configuration.get('REQUEST_LOGGING_ENABLED') as boolean;
+	const logger = new Logger('REQUEST_LOG');
+
+	return (request: Request, response: Response, next: NextFunction): void => {
+		if (enabled) {
+			const startAt = process.hrtime();
+			const { method, originalUrl } = request;
+
+			response.on('finish', () => {
+				try {
+					const { statusCode } = response;
+					const contentLength = response.get('content-length') || 'unknown';
+					const diff = process.hrtime(startAt);
+					const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
+					logger.log(`${method} ${originalUrl} ${statusCode} ${responseTime}ms ${contentLength}`);
+				} catch (error) {
+					logger.error('unable to write accesslog', error);
+				}
+			});
+		}
+
+		next();
+	};
+};

apps/server/src/apps/management.app.ts

@@ -10,17 +10,20 @@ import { install as sourceMapInstall } from 'source-map-support';
 // application imports
 import { LegacyLogger } from '@src/core/logger';
 import { ManagementServerModule } from '@modules/management';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import { enableOpenApiDocs } from './helpers';
 
 async function bootstrap() {
 	sourceMapInstall();
 
-	// create the NestJS application on a seperate express instance
+	// create the NestJS application on a separate express instance
 	const nestExpress = express();
 
 	const nestExpressAdapter = new ExpressAdapter(nestExpress);
 	const nestApp = await NestFactory.create(ManagementServerModule, nestExpressAdapter);
 
+	nestApp.use(createRequestLoggerMiddleware());
+
 	// WinstonLogger
 	nestApp.useLogger(await nestApp.resolve(LegacyLogger));
 

apps/server/src/apps/server.app.ts

@@ -23,6 +23,7 @@ import { join } from 'path';
 
 // register source-map-support for debugging
 import { install as sourceMapInstall } from 'source-map-support';
+import { createRequestLoggerMiddleware } from './helpers/request-logger-middleware';
 import {
 	AppStartLoggable,
 	enableOpenApiDocs,
@@ -34,7 +35,7 @@ import legacyAppPromise = require('../../../../src/app');
 async function bootstrap() {
 	sourceMapInstall();
 
-	// create the NestJS application on a seperate express instance
+	// create the NestJS application on a separate express instance
 	const nestExpress = express();
 	const nestExpressAdapter = new ExpressAdapter(nestExpress);
 	const nestApp = await NestFactory.create(ServerModule, nestExpressAdapter);
@@ -45,6 +46,7 @@ async function bootstrap() {
 	nestApp.useLogger(legacyLogger);
 
 	const logger = await nestApp.resolve(Logger);
+	nestApp.use(createRequestLoggerMiddleware());
 
 	// load the legacy feathers/express server
 	// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment