EW-1029 adding additional information for http error logs

apps/server/src/core/error/domain/domainErrorHandler.ts

@@ -1,6 +1,9 @@
 import { Injectable } from '@nestjs/common';
+import { HttpArgumentsHost } from '@nestjs/common/interfaces';
+import { ErrorLogger, Loggable, LoggingUtils, LogMessageDataObject } from '@src/core/logger';
+import { ICurrentUser } from '@src/infra/auth-guard';
+import { Request } from 'express';
 import util from 'util';
-import { ErrorLogger, Loggable, LoggingUtils } from '@src/core/logger';
 import { ErrorLoggable } from '../loggable';
 
 @Injectable()
@@ -12,16 +15,33 @@ export class DomainErrorHandler {
 		this.logger.error(loggable);
 	}
 
-	private createErrorLoggable(error: unknown): Loggable {
+	public execHttpContext(error: unknown, context: HttpArgumentsHost): void {
+		const request: Request = context.getRequest();
+		const user = request.user as ICurrentUser | undefined;
+		const requestInfo = {
+			userId: user?.userId,
+			request: {
+				method: request.method,
+				endpoint: request.url,
+				params: JSON.stringify(request.params),
+				query: JSON.stringify(request.query),
+			},
+		};
+		const loggable = this.createErrorLoggable(error, requestInfo);
+
+		this.logger.error(loggable);
+	}
+
+	private createErrorLoggable(error: unknown, data?: LogMessageDataObject): Loggable {
 		let loggable: Loggable;
 
 		if (LoggingUtils.isInstanceOfLoggable(error)) {
 			loggable = error;
 		} else if (error instanceof Error) {
-			loggable = new ErrorLoggable(error);
+			loggable = new ErrorLoggable(error, data);
 		} else {
 			const unknownError = new Error(util.inspect(error));
-			loggable = new ErrorLoggable(unknownError);
+			loggable = new ErrorLoggable(unknownError, data);
 		}
 
 		return loggable;

apps/server/src/core/error/filter/global-error.filter.spec.ts

@@ -3,14 +3,14 @@
 import { createMock, DeepMocked } from '@golevelup/ts-jest';
 import { ArgumentsHost, BadRequestException, HttpStatus, InternalServerErrorException } from '@nestjs/common';
 import { Test, TestingModule } from '@nestjs/testing';
+import { WsException } from '@nestjs/websockets';
 import { BusinessError } from '@shared/common';
 import { ErrorLogMessage, Loggable } from '@src/core/logger';
 import { Response } from 'express';
-import { WsException } from '@nestjs/websockets';
+import { DomainErrorHandler } from '../domain';
 import { ErrorResponse } from '../dto';
 import { ErrorUtils } from '../utils';
-import { GlobalErrorFilter } from './global-error.filter';
-import { DomainErrorHandler } from '../domain';
+import { GlobalErrorFilter, UseableContextType } from './global-error.filter';
 
 class SampleBusinessError extends BusinessError {
 	constructor() {
@@ -45,7 +45,7 @@
 
 describe('GlobalErrorFilter', () => {
 	let module: TestingModule;
 	let service: GlobalErrorFilter<any>;
 	let domainErrorHandler: DeepMocked<DomainErrorHandler>;
 
 	beforeAll(async () => {
@@ -78,19 +78,27 @@
 	describe('catch', () => {
 		describe('when any error is passed as parameter', () => {
 			const setup = () => {
-				const argumentsHost = createMock<ArgumentsHost>();
-				argumentsHost.getType.mockReturnValueOnce('http');
+				const allContextTypes = Object.keys(UseableContextType);
+				const contextTypes = [...allContextTypes];
+				const argumentsHost = createMock<ArgumentsHost>({
+					getType: () => contextTypes.pop() || '',
+				});
 				const error = new Error('test');
 
-				return { error, argumentsHost };
+				return { allContextTypes, argumentsHost, error };
 			};
 
-			it('should be pass the error to domain error handler', () => {
-				const { error, argumentsHost } = setup();
+			it('should call exec on domain error handler', () => {
+				const { allContextTypes, argumentsHost, error } = setup();
 
-				service.catch(error, argumentsHost);
+				allContextTypes.forEach(() => {
+					service.catch(error, argumentsHost);
+				});
 
 				expect(domainErrorHandler.exec).toBeCalledWith(error);
+				expect(domainErrorHandler.exec).toBeCalledTimes(allContextTypes.length - 1);
+				expect(domainErrorHandler.execHttpContext).toBeCalledWith(error, {});
+				expect(domainErrorHandler.execHttpContext).toBeCalledTimes(1);
 			});
 		});
 

apps/server/src/core/error/filter/global-error.filter.ts

@@ -1,17 +1,17 @@
 import { IError, RpcMessage } from '@infra/rabbitmq';
 import { ArgumentsHost, Catch, ExceptionFilter, HttpException, InternalServerErrorException } from '@nestjs/common';
+import { WsException } from '@nestjs/websockets';
 import { ApiValidationError, BusinessError } from '@shared/common';
 import { Response } from 'express';
 import _ from 'lodash';
-import { WsException } from '@nestjs/websockets';
+import { DomainErrorHandler } from '../domain';
 import { ApiValidationErrorResponse, ErrorResponse } from '../dto';
 import { FeathersError } from '../interface';
 import { ErrorUtils } from '../utils';
-import { DomainErrorHandler } from '../domain';
 
 // We are receiving rmq instead of rpc and rmq is missing in context type.
 // @nestjs/common export type ContextType = 'http' | 'ws' | 'rpc';
-enum UseableContextType {
+export enum UseableContextType {
 	http = 'http',
 	rpc = 'rpc',
 	ws = 'ws',
@@ -23,18 +23,20 @@ export class GlobalErrorFilter<E extends IError> implements ExceptionFilter<E> {
 	constructor(private readonly domainErrorHandler: DomainErrorHandler) {}
 
 	catch(error: E, host: ArgumentsHost): void | RpcMessage<undefined> | WsException {
-		this.domainErrorHandler.exec(error);
-
 		const contextType = host.getType<UseableContextType>();
 		switch (contextType) {
 			case UseableContextType.http:
+				this.domainErrorHandler.execHttpContext(error, host.switchToHttp());
 				return this.sendHttpResponse(error, host);
 			case UseableContextType.rpc:
 			case UseableContextType.rmq:
+				this.domainErrorHandler.exec(error);
 				return this.sendRpcResponse(error);
 			case UseableContextType.ws:
+				this.domainErrorHandler.exec(error);
 				return this.sendWsResponse(error);
 			default:
+				this.domainErrorHandler.exec(error);
 				return undefined;
 		}
 	}

apps/server/src/core/error/loggable/error.loggable.ts

@@ -1,19 +1,20 @@
+import { ValidationError } from '@nestjs/common';
 import { ApiValidationError } from '@shared/common';
 import { getMetadataStorage } from 'class-validator';
-import { ValidationError } from '@nestjs/common';
 import { Loggable } from '../../logger/interfaces';
-import { ErrorLogMessage, ValidationErrorLogMessage } from '../../logger/types';
+import { ErrorLogMessage, LogMessageDataObject, ValidationErrorLogMessage } from '../../logger/types';
 import { ErrorUtils } from '../utils/error.utils';
 
 export class ErrorLoggable implements Loggable {
-	constructor(private readonly error: Error) {}
+	constructor(private readonly error: Error, private readonly data?: LogMessageDataObject) {}
 
 	private readonly classValidatorMetadataStorage = getMetadataStorage();
 
 	getLogMessage(): ErrorLogMessage | ValidationErrorLogMessage {
 		let logMessage: ErrorLogMessage | ValidationErrorLogMessage = {
 			error: this.error,
 			type: '',
+			data: this.data,
 		};
 
 		if (this.error instanceof ApiValidationError) {

apps/server/src/core/logger/types/logging.types.ts

@@ -26,6 +26,6 @@ export type LogMessageWithContext = {
 
 export type LogMessageData = LogMessageDataObject | string | number | boolean | undefined;
 
-type LogMessageDataObject = {
+export type LogMessageDataObject = {
 	[key: string]: LogMessageData;
 };

apps/server/src/infra/sync/sync.module.ts

@@ -1,12 +1,13 @@
 import { Configuration } from '@hpi-schul-cloud/commons/lib';
 import { ConsoleWriterModule } from '@infra/console';
+import { RabbitMQWrapperModule } from '@infra/rabbitmq';
 import { TspClientModule } from '@infra/tsp-client/tsp-client.module';
 import { LegacySchoolModule } from '@modules/legacy-school';
 import { SchoolModule } from '@modules/school';
 import { SystemModule } from '@modules/system';
 import { Module } from '@nestjs/common';
 import { LoggerModule } from '@src/core/logger';
-import { RabbitMQWrapperModule } from '@infra/rabbitmq';
+import { ProvisioningModule } from '@src/modules/provisioning';
 import { SyncConsole } from './console/sync.console';
 import { SyncService } from './service/sync.service';
 import { TspSyncService } from './tsp/tsp-sync.service';
@@ -18,7 +19,7 @@ import { SyncUc } from './uc/sync.uc';
 		LoggerModule,
 		ConsoleWriterModule,
 		...((Configuration.get('FEATURE_TSP_SYNC_ENABLED') as boolean)
-			? [TspClientModule, SystemModule, SchoolModule, LegacySchoolModule, RabbitMQWrapperModule]
+			? [TspClientModule, SystemModule, SchoolModule, LegacySchoolModule, RabbitMQWrapperModule, ProvisioningModule]
 			: []),
 	],
 	providers: [

apps/server/src/infra/sync/tsp/loggable/tsp-data-fetched.loggable.spec.ts

@@ -0,0 +1,29 @@
+import { TspDataFetchedLoggable } from './tsp-data-fetched.loggable';
+
+describe(TspDataFetchedLoggable.name, () => {
+	let loggable: TspDataFetchedLoggable;
+
+	beforeAll(() => {
+		loggable = new TspDataFetchedLoggable(1, 2, 3, 4);
+	});
+
+	describe('when loggable is initialized', () => {
+		it('should be defined', () => {
+			expect(loggable).toBeDefined();
+		});
+	});
+
+	describe('getLogMessage', () => {
+		it('should return a log message', () => {
+			expect(loggable.getLogMessage()).toEqual({
+				message: `Fetched 1 teachers, 2 students and 3 classes for the last 4 days from TSP`,
+				data: {
+					tspTeacherCount: 1,
+					tspStudentCount: 2,
+					tspClassesCount: 3,
+					daysFetched: 4,
+				},
+			});
+		});
+	});
+});

apps/server/src/infra/sync/tsp/loggable/tsp-data-fetched.loggable.ts

@@ -0,0 +1,24 @@
+import { Loggable, LogMessage } from '@src/core/logger';
+
+export class TspDataFetchedLoggable implements Loggable {
+	constructor(
+		private readonly tspTeacherCount: number,
+		private readonly tspStudentCount: number,
+		private readonly tspClassesCount: number,
+		private readonly daysFetched: number
+	) {}
+
+	getLogMessage(): LogMessage {
+		const message: LogMessage = {
+			message: `Fetched ${this.tspTeacherCount} teachers, ${this.tspStudentCount} students and ${this.tspClassesCount} classes for the last ${this.daysFetched} days from TSP`,
+			data: {
+				tspTeacherCount: this.tspTeacherCount,
+				tspStudentCount: this.tspStudentCount,
+				tspClassesCount: this.tspClassesCount,
+				daysFetched: this.daysFetched,
+			},
+		};
+
+		return message;
+	}
+}

apps/server/src/infra/sync/tsp/loggable/tsp-missing-external-id.loggable.spec.ts

@@ -0,0 +1,26 @@
+import { TspMissingExternalIdLoggable } from './tsp-missing-external-id.loggable';
+
+describe(TspMissingExternalIdLoggable.name, () => {
+	let loggable: TspMissingExternalIdLoggable;
+
+	beforeAll(() => {
+		loggable = new TspMissingExternalIdLoggable('teacher');
+	});
+
+	describe('when loggable is initialized', () => {
+		it('should be defined', () => {
+			expect(loggable).toBeDefined();
+		});
+	});
+
+	describe('getLogMessage', () => {
+		it('should return a log message', () => {
+			expect(loggable.getLogMessage()).toEqual({
+				message: `A teacher is missing an id. It is skipped.`,
+				data: {
+					objectType: 'teacher',
+				},
+			});
+		});
+	});
+});

apps/server/src/infra/sync/tsp/loggable/tsp-missing-external-id.loggable.ts

@@ -0,0 +1,16 @@
+import { Loggable, LogMessage } from '@src/core/logger';
+
+export class TspMissingExternalIdLoggable implements Loggable {
+	constructor(private readonly objectType: string) {}
+
+	getLogMessage(): LogMessage {
+		const message: LogMessage = {
+			message: `A ${this.objectType} is missing an id. It is skipped.`,
+			data: {
+				objectType: this.objectType,
+			},
+		};
+
+		return message;
+	}
+}

apps/server/src/infra/sync/tsp/loggable/tsp-synced-users.loggable.spec.ts

@@ -0,0 +1,26 @@
+import { TspSyncedUsersLoggable } from './tsp-synced-users.loggable';
+
+describe(TspSyncedUsersLoggable.name, () => {
+	let loggable: TspSyncedUsersLoggable;
+
+	beforeAll(() => {
+		loggable = new TspSyncedUsersLoggable(10);
+	});
+
+	describe('when loggable is initialized', () => {
+		it('should be defined', () => {
+			expect(loggable).toBeDefined();
+		});
+	});
+
+	describe('getLogMessage', () => {
+		it('should return a log message', () => {
+			expect(loggable.getLogMessage()).toEqual({
+				message: `Synced 10 users from TSP.`,
+				data: {
+					syncedUsers: 10,
+				},
+			});
+		});
+	});
+});

apps/server/src/infra/sync/tsp/loggable/tsp-synced-users.loggable.ts

@@ -0,0 +1,16 @@
+import { Loggable, LogMessage } from '@src/core/logger';
+
+export class TspSyncedUsersLoggable implements Loggable {
+	constructor(private readonly syncedUsers: number) {}
+
+	getLogMessage(): LogMessage {
+		const message: LogMessage = {
+			message: `Synced ${this.syncedUsers} users from TSP.`,
+			data: {
+				syncedUsers: this.syncedUsers,
+			},
+		};
+
+		return message;
+	}
+}

apps/server/src/infra/sync/tsp/loggable/tsp-syncing-users.loggable.spec.ts

@@ -0,0 +1,26 @@
+import { TspSyncingUsersLoggable } from './tsp-syncing-users.loggable';
+
+describe(TspSyncingUsersLoggable.name, () => {
+	let loggable: TspSyncingUsersLoggable;
+
+	beforeAll(() => {
+		loggable = new TspSyncingUsersLoggable(10);
+	});
+
+	describe('when loggable is initialized', () => {
+		it('should be defined', () => {
+			expect(loggable).toBeDefined();
+		});
+	});
+
+	describe('getLogMessage', () => {
+		it('should return a log message', () => {
+			expect(loggable.getLogMessage()).toEqual({
+				message: `Syncing 10 users from TSP.`,
+				data: {
+					syncingUsers: 10,
+				},
+			});
+		});
+	});
+});

apps/server/src/infra/sync/tsp/loggable/tsp-syncing-users.loggable.ts

@@ -0,0 +1,16 @@
+import { Loggable, LogMessage } from '@src/core/logger';
+
+export class TspSyncingUsersLoggable implements Loggable {
+	constructor(private readonly syncingUsers: number) {}
+
+	getLogMessage(): LogMessage {
+		const message: LogMessage = {
+			message: `Syncing ${this.syncingUsers} users from TSP.`,
+			data: {
+				syncingUsers: this.syncingUsers,
+			},
+		};
+
+		return message;
+	}
+}

apps/server/src/infra/sync/tsp/tsp-sync.config.ts

@@ -1,4 +1,6 @@
 export interface TspSyncConfig {
 	TSP_SYNC_SCHOOL_LIMIT: number;
 	TSP_SYNC_SCHOOL_DAYS_TO_FETCH: number;
+	TSP_SYNC_DATA_LIMIT: number;
+	TSP_SYNC_DATA_DAYS_TO_FETCH: number;
 }