BC-8559 implement request logging in nestjs

hpi-schul-cloud · Dec 12, 2024 · 167c336 · 167c336
1 parent acb3c2e
commit 167c336
Show file tree

Hide file tree

Showing 12 changed files with 105 additions and 5 deletions.
diff --git a/apps/server/src/apps/admin-api-server.app.ts b/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 { createAppLoggerMiddleware } from '@src/apps/helpers/app-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(createAppLoggerMiddleware(await nestAdminServerApp.resolve(Logger)));
+
 	nestAdminServerApp.useLogger(legacyLogger);
 	nestAdminServerApp.enableCors();
 

diff --git a/apps/server/src/apps/board-collaboration.app.ts b/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 { createAppLoggerMiddleware } from '@src/apps/helpers/app-logger-middleware';
 import {
 	enableOpenApiDocs,
 	addPrometheusMetricsMiddlewaresIfEnabled,
@@ -37,6 +38,7 @@ async function bootstrap() {
 	};
 	enableOpenApiDocs(nestApp, 'docs', options);
 	const logger = await nestApp.resolve(Logger);
+	nestApp.use(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 
 	await nestApp.init();
 

diff --git a/apps/server/src/apps/common-cartridge.app.ts b/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 { createAppLoggerMiddleware } from '@src/apps/helpers/app-logger-middleware';
 import {
 	AppStartLoggable,
 	enableOpenApiDocs,
@@ -27,6 +28,7 @@ async function bootstrap() {
 
 	const rootExpress = express();
 	const logger = await nestApp.resolve(Logger);
+	nestApp.use(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 
 	addPrometheusMetricsMiddlewaresIfEnabled(logger, rootExpress);
 

diff --git a/apps/server/src/apps/files-storage.app.ts b/apps/server/src/apps/files-storage.app.ts
@@ -11,7 +11,8 @@ import { install as sourceMapInstall } from 'source-map-support';
 import { FilesStorageApiModule } from '@modules/files-storage/files-storage-api.module';
 import { API_VERSION_PATH } from '@modules/files-storage/files-storage.const';
 import { SwaggerDocumentOptions } from '@nestjs/swagger';
-import { LegacyLogger } from '@src/core/logger';
+import { LegacyLogger, Logger } from '@src/core/logger';
+import { createAppLoggerMiddleware } from '@src/apps/helpers/app-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(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 
 	const options: SwaggerDocumentOptions = {
 		operationIdFactory: (_controllerKey: string, methodKey: string) => methodKey,

diff --git a/apps/server/src/apps/fwu-learning-contents.app.ts b/apps/server/src/apps/fwu-learning-contents.app.ts
@@ -8,8 +8,9 @@ import express from 'express';
 import { install as sourceMapInstall } from 'source-map-support';
 
 // application imports
-import { LegacyLogger } from '@src/core/logger';
+import { LegacyLogger, Logger } from '@src/core/logger';
 import { FwuLearningContentsModule } from '@modules/fwu-learning-contents';
+import { createAppLoggerMiddleware } from '@src/apps/helpers/app-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(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 
 	await nestApp.init();
 

diff --git a/apps/server/src/apps/h5p-editor.app.ts b/apps/server/src/apps/h5p-editor.app.ts
@@ -8,8 +8,9 @@ import express from 'express';
 import { install as sourceMapInstall } from 'source-map-support';
 
 // application imports
-import { LegacyLogger } from '@src/core/logger';
+import { LegacyLogger, Logger } from '@src/core/logger';
 import { H5PEditorModule } from '@modules/h5p-editor';
+import { createAppLoggerMiddleware } from '@src/apps/helpers/app-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(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
+
 	// customize nest app settings
 	nestApp.enableCors({ exposedHeaders: ['Content-Disposition'] });
 	enableOpenApiDocs(nestApp, 'docs');

diff --git a/apps/server/src/apps/helpers/app-logger-middleware.ts b/apps/server/src/apps/helpers/app-logger-middleware.ts
@@ -0,0 +1,28 @@
+import { Request, Response, NextFunction } from 'express';
+import { Logger } from '@src/core/logger';
+import { RequestLoggable } from '@src/apps/helpers/request-loggable';
+import { Configuration } from '@hpi-schul-cloud/commons/lib';
+
+export const createAppLoggerMiddleware = (
+	logger: Logger
+): ((request: Request, response: Response, next: NextFunction) => void) => {
+	logger.setContext('AppLoggerMiddleware');
+	const enabled = Configuration.get('REQUEST_LOGGING_ENABLED') as boolean;
+
+	return (request: Request, response: Response, next: NextFunction): void => {
+		if (enabled) {
+			const startAt = process.hrtime();
+			const { method, originalUrl } = request;
+
+			response.on('finish', () => {
+				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.info(new RequestLoggable({ method, originalUrl, statusCode, responseTime, contentLength }));
+			});
+		}
+
+		next();
+	};
+};
diff --git a/apps/server/src/apps/helpers/logger-middleware.ts b/apps/server/src/apps/helpers/logger-middleware.ts
@@ -0,0 +1,22 @@
+import { Request, Response, NextFunction } from 'express';
+import { Injectable, NestMiddleware, Logger } from '@nestjs/common';
+
+@Injectable()
+export class LoggerMiddleware implements NestMiddleware {
+	private logger = new Logger('HTTP');
+
+	public use(request: Request, response: Response, next: NextFunction): void {
+		const startAt = process.hrtime();
+		const { method, originalUrl } = request;
+
+		response.on('finish', () => {
+			const { statusCode } = response;
+			const contentLength = response.get('content-length') || 'unknown';
+			const diff = process.hrtime(startAt);
+			const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
+			this.logger.log(`${method} ${originalUrl} ${statusCode} ${responseTime}ms ${contentLength}`);
+		});
+
+		next();
+	}
+}
diff --git a/apps/server/src/apps/helpers/request-loggable.ts b/apps/server/src/apps/helpers/request-loggable.ts
@@ -0,0 +1,29 @@
+import { Loggable, LogMessage } from '@src/core/logger';
+
+interface RequestLogInfo {
+	method: string;
+	originalUrl: string;
+	statusCode: number;
+	responseTime: number;
+	contentLength: string;
+}
+
+export class RequestLoggable implements Loggable {
+	constructor(private readonly requestLog: RequestLogInfo) {}
+
+	public getLogMessage(): LogMessage {
+		return {
+			message: `${this.requestLog.method} ${this.requestLog.originalUrl} ${this.requestLog.statusCode} ${this.requestLog.responseTime}ms ${this.requestLog.contentLength}`,
+		};
+		// return {
+		// 	message: 'loggables rock',
+		// 	data: {
+		// 		method: this.requestLog.method,
+		// 		originalUrl: this.requestLog.originalUrl,
+		// 		statusCode: this.requestLog.statusCode,
+		// 		responseTime: `${this.requestLog.responseTime}ms`,
+		// 		contentLength: this.requestLog.contentLength,
+		// 	},
+		// };
+	}
+}
diff --git a/apps/server/src/apps/management.app.ts b/apps/server/src/apps/management.app.ts
@@ -8,8 +8,9 @@ import express from 'express';
 import { install as sourceMapInstall } from 'source-map-support';
 
 // application imports
-import { LegacyLogger } from '@src/core/logger';
+import { LegacyLogger, Logger } from '@src/core/logger';
 import { ManagementServerModule } from '@modules/management';
+import { createAppLoggerMiddleware } from '@src/apps/helpers/app-logger-middleware';
 import { enableOpenApiDocs } from './helpers';
 
 async function bootstrap() {
@@ -21,6 +22,8 @@ async function bootstrap() {
 	const nestExpressAdapter = new ExpressAdapter(nestExpress);
 	const nestApp = await NestFactory.create(ManagementServerModule, nestExpressAdapter);
 
+	nestApp.use(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
+
 	// WinstonLogger
 	nestApp.useLogger(await nestApp.resolve(LegacyLogger));
 

diff --git a/apps/server/src/apps/server.app.ts b/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 { createAppLoggerMiddleware } from '@src/apps/helpers/app-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(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 
 	// load the legacy feathers/express server
 	// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment

diff --git a/apps/server/src/apps/tldraw.app.ts b/apps/server/src/apps/tldraw.app.ts
@@ -9,6 +9,7 @@ import * as WebSocket from 'ws';
 import { WsAdapter } from '@nestjs/platform-ws';
 import { ExpressAdapter } from '@nestjs/platform-express';
 import express from 'express';
+import { createAppLoggerMiddleware } from '@src/apps/helpers/app-logger-middleware';
 import {
 	AppStartLoggable,
 	enableOpenApiDocs,
@@ -23,6 +24,7 @@ async function bootstrap() {
 	const nestExpressAdapter = new ExpressAdapter(nestExpress);
 	const nestApp = await NestFactory.create(TldrawApiModule, nestExpressAdapter);
 	nestApp.useLogger(await nestApp.resolve(LegacyLogger));
+	nestApp.use(createAppLoggerMiddleware(await nestApp.resolve(Logger)));
 	nestApp.enableCors();
 
 	const nestAppWS = await NestFactory.create(TldrawWsModule);