feat: ORV2-1756 logging - handle type orm errors (#914)

docker-compose.yml

@@ -46,6 +46,9 @@ services:
       dockerfile: Dockerfile
     environment:
       NODE_ENV: development
+      VECHICLES_API_LOG_LEVEL: ${VECHICLES_API_LOG_LEVEL}
+      VECHICLES_API_TYPEORM_LOG_LEVEL: ${VECHICLES_API_TYPEORM_LOG_LEVEL}
+      VECHICLES_API_MAX_QUERY_EXECUTION_TIME_MS: ${VECHICLES_API_MAX_QUERY_EXECUTION_TIME_MS}
       DB_TYPE: ${DB_TYPE}
       MSSQL_HOST: sql-server-db
       MSSQL_PORT: ${MSSQL_PORT}
@@ -90,6 +93,9 @@ services:
       dockerfile: Dockerfile
     environment:
       NODE_ENV: development
+      DOPS_API_LOG_LEVEL: ${DOPS_API_LOG_LEVEL}
+      DOPS_API_TYPEORM_LOG_LEVEL: ${DOPS_API_TYPEORM_LOG_LEVEL}
+      DOPS_API_MAX_QUERY_EXECUTION_TIME_MS: ${DOPS_API_MAX_QUERY_EXECUTION_TIME_MS}
       DB_TYPE: ${DB_TYPE}
       MSSQL_HOST: sql-server-db
       MSSQL_PORT: ${MSSQL_PORT}

dops/Dockerfile

@@ -33,6 +33,9 @@ ENV NODE_ENV production
 
 # Set environment variables
 ENV DB_TYPE ${DB_TYPE}
+ENV DOPS_API_LOG_LEVEL ${DOPS_API_LOG_LEVEL}
+ENV DOPS_API_TYPEORM_LOG_LEVEL ${DOPS_API_TYPEORM_LOG_LEVEL}
+ENV DOPS_API_MAX_QUERY_EXECUTION_TIME_MS ${DOPS_API_MAX_QUERY_EXECUTION_TIME_MS}
 ENV POSTGRESQL_HOST ${POSTGRESQL_HOST}
 ENV POSTGRESQL_USER ${POSTGRESQL_USER}
 ENV POSTGRESQL_PASSWORD ${POSTGRESQL_PASSWORD}

dops/src/app.module.ts

@@ -18,6 +18,7 @@ import { CacheModule } from '@nestjs/cache-manager';
 import { DgenModule } from './modules/dgen/dgen.module';
 import { CommonModule } from './modules/common/common.module';
 import { HTTPLoggerMiddleware } from './middleware/req.res.logger';
+import { TypeormCustomLogger } from './logger/typeorm-logger.config';
 
 const envPath = path.resolve(process.cwd() + '/../');
 
@@ -34,7 +35,14 @@ const envPath = path.resolve(process.cwd() + '/../');
       options: { encrypt: process.env.MSSQL_ENCRYPT === 'true', useUTC: true },
       autoLoadEntities: true, // Auto load all entities regiestered by typeorm forFeature method.
       synchronize: false, // This changes the DB schema to match changes to entities, which we might not want.
-      logging: false,
+      maxQueryExecutionTime:
+        +process.env.DOPS_API_MAX_QUERY_EXECUTION_TIME_MS || 5000, //5 seconds by default
+      logger: new TypeormCustomLogger(
+        // eslint-disable-next-line @typescript-eslint/no-unsafe-argument
+        process.env.DOPS_API_TYPEORM_LOG_LEVEL
+          ? JSON.parse(process.env.DOPS_API_TYPEORM_LOG_LEVEL)
+          : ['error'],
+      ),
     }),
     AutomapperModule.forRoot({
       strategyInitializer: classes(),

dops/src/app.service.ts

@@ -1,4 +1,4 @@
-import { Inject, Injectable } from '@nestjs/common';
+import { Inject, Injectable, Logger } from '@nestjs/common';
 import { CACHE_MANAGER } from '@nestjs/cache-manager';
 import { Cache } from 'cache-manager';
 
@@ -16,6 +16,8 @@ import { LogMethodExecution } from './decorator/log-method-execution.decorator';
 
 @Injectable()
 export class AppService {
+  private readonly logger = new Logger(AppService.name);
+
   constructor(
     @Inject(CACHE_MANAGER)
     private readonly cacheManager: Cache,
@@ -73,7 +75,7 @@ export class AppService {
 
     const endDateTime = new Date();
     const processingTime = endDateTime.getTime() - startDateTime.getTime();
-    console.info(
+    this.logger.log(
       `initializeCache() -> Start time: ${startDateTime.toISOString()},` +
         `End time: ${endDateTime.toISOString()},` +
         `Processing time: ${processingTime}ms`,

dops/src/decorator/log-method-execution.decorator.ts

@@ -11,9 +11,9 @@ export function LogMethodExecution() {
     const originalMethod = descriptor.value;
 
     descriptor.value = function (...args: any[]) {
-      logger.log(`Entering ${propertyKey} method`);
+      logger.debug(`Entering ${propertyKey} method`);
       const result = originalMethod.apply(this, args);
-      logger.log(`Exiting ${propertyKey} method`);
+      logger.debug(`Exiting ${propertyKey} method`);
       return result;
     };
     /* eslint-enable */

dops/src/filters/fallback.filter.ts

@@ -1,18 +1,49 @@
-import { ArgumentsHost, Catch, ExceptionFilter, Logger } from '@nestjs/common';
+import {
+  ArgumentsHost,
+  Catch,
+  ExceptionFilter,
+  HttpException,
+  HttpStatus,
+  Logger,
+} from '@nestjs/common';
 import { Response } from 'express';
 import { ExceptionDto } from '../exception/exception.dto';
+import { TypeORMError } from 'typeorm';
 
 /*Catch all but http exceptions */
 @Catch()
 export class FallbackExceptionFilter implements ExceptionFilter {
   private readonly logger = new Logger(FallbackExceptionFilter.name);
+
   catch(exception: unknown, host: ArgumentsHost) {
     const ctx = host.switchToHttp(),
-      //request = ctx.getRequest<Request>(),
+      request = ctx.getRequest<Request>(),
       response = ctx.getResponse<Response>();
-    this.logger.error(getErrorMessage(exception), getErrorStack(exception));
-    const exceptionDto = new ExceptionDto(500, getErrorMessage(exception));
-    return response.status(500).json(exceptionDto);
+    let message: string, status: HttpStatus;
+
+    if (exception instanceof TypeORMError) {
+      status = HttpStatus.UNPROCESSABLE_ENTITY;
+      message = exception.message;
+    } else if (exception instanceof HttpException) {
+      status = exception.getStatus();
+      message = (exception as Error).message;
+    } else {
+      status = HttpStatus.INTERNAL_SERVER_ERROR;
+      message = getErrorMessage(exception);
+    }
+
+    this.logger.error(
+      message,
+      getErrorStack(exception),
+      `${request.method} ${request.url}`,
+    );
+    // TODO : Update the below implemenation to send 422 instead of 500.
+    if (status === HttpStatus.UNPROCESSABLE_ENTITY) {
+      status = HttpStatus.INTERNAL_SERVER_ERROR;
+      message = 'Internal Server Error';
+    }
+    const exceptionDto = new ExceptionDto(status, message);
+    return response.status(status).json(exceptionDto);
   }
 }
 

dops/src/filters/http.filter.ts

@@ -4,16 +4,18 @@ import {
   ExceptionFilter,
   HttpException,
   HttpStatus,
+  Logger,
 } from '@nestjs/common';
 import { Response } from 'express';
 import { ExceptionDto } from '../exception/exception.dto';
 
 /*Catch all http exceptions */
 @Catch(HttpException)
 export class HttpExceptionFilter implements ExceptionFilter {
+  private readonly logger = new Logger(HttpExceptionFilter.name);
   catch(exception: HttpException, host: ArgumentsHost) {
     let exceptionDto: ExceptionDto;
-    console.error(
+    this.logger.error(
       'HTTP exception handler triggered',
       JSON.stringify(exception),
     );

dops/src/helper/gov-common-services.helper.ts

@@ -1,12 +1,14 @@
 import { HttpService } from '@nestjs/axios';
-import { AxiosRequestConfig } from 'axios';
+import { AxiosRequestConfig, AxiosError } from 'axios';
 import { lastValueFrom } from 'rxjs';
 import { GovCommonServices } from '../enum/gov-common-services.enum';
-import { InternalServerErrorException } from '@nestjs/common';
+import { InternalServerErrorException, Logger } from '@nestjs/common';
 import { Cache } from 'cache-manager';
 import { GovCommonServicesToken } from '../interface/gov-common-services-token.interface';
 import { CacheKey } from '../enum/cache-key.enum';
 
+const logger = new Logger('GocCommonServicesHelper');
+
 export async function getAccessToken(
   govCommonServices: GovCommonServices,
   httpService: HttpService,
@@ -57,9 +59,26 @@ export async function getAccessToken(
     .then((response) => {
       return response.data as GovCommonServicesToken;
     })
-    .catch((error) => {
-      console.error('Error: getCommonServiceAccessToken() ', error);
-      throw new InternalServerErrorException();
+
+    .catch((error: AxiosError) => {
+      if (error.response) {
+        const errorData = error.response.data as {
+          error: string;
+          error_description?: string;
+        };
+        logger.error(
+          `Error response from token issuer: ${JSON.stringify(
+            errorData,
+            null,
+            2,
+          )}`,
+        );
+      } else {
+        logger.error(error?.message, error?.stack);
+      }
+      throw new InternalServerErrorException(
+        `Error acquiring token from ${tokenUrl}`,
+      );
     });
 
   token.expires_at = Date.now() + (token.expires_in - 15) * 1000;

dops/src/logger/logger.config.ts

@@ -12,7 +12,8 @@ const globalLoggerFormat: winston.Logform.Format = winston.format.combine(
 const localLoggerFormat: winston.Logform.Format = winston.format.combine(
   winston.format.colorize(),
   winston.format.align(),
-  utilities.format.nestLike('Vehicles', { colors: true, prettyPrint: true }),
+  winston.format.splat(),
+  utilities.format.nestLike('Dops', { colors: true, prettyPrint: true }),
 );
 
 const errorStack: winston.Logform.Format = winston.format.combine(
@@ -22,7 +23,7 @@ const errorStack: winston.Logform.Format = winston.format.combine(
 export const customLogger: LoggerService = WinstonModule.createLogger({
   transports: [
     new winston.transports.Console({
-      level: 'silly',
+      level: process.env.DOPS_API_LOG_LEVEL || 'silly',
       format: winston.format.combine(
         globalLoggerFormat,
         localLoggerFormat,

dops/src/logger/typeorm-logger.config.ts

@@ -0,0 +1,83 @@
+import { Logger } from '@nestjs/common';
+import { AbstractLogger, LogLevel, LogMessage } from 'typeorm';
+
+/**
+ * To prevent sensitive information being printed onto logs
+ */
+class CustomError extends Error {
+  constructor(message, printStack = false) {
+    // eslint-disable-next-line @typescript-eslint/no-unsafe-argument
+    super(message);
+    if (!printStack) {
+      this.stack = '';
+    }
+  }
+}
+
+export class TypeormCustomLogger extends AbstractLogger {
+  private readonly logger = new Logger(TypeormCustomLogger.name);
+  /**
+   * Write log to specific output.
+   */
+  protected writeLog(level: LogLevel, logMessage: LogMessage | LogMessage[]) {
+    const messages = this.prepareLogMessages(logMessage, {
+      highlightSql: true,
+      appendParameterAsComment: false,
+      addColonToPrefix: false,
+    });
+
+    for (const message of messages) {
+      this.logMessage(message, level);
+    }
+  }
+
+  private logMessage(message: LogMessage, level: LogLevel) {
+    switch (message.type ?? level) {
+      case 'log':
+      case 'schema-build':
+      case 'migration':
+        this.logger.log(message.message);
+        break;
+
+      case 'info':
+      case 'query':
+        this.logInfoOrQuery(message);
+        break;
+
+      case 'warn':
+      case 'query-slow':
+        this.logWarnOrQuerySlow(message);
+        break;
+
+      case 'error':
+      case 'query-error':
+        this.logErrorOrQueryError(message);
+        break;
+    }
+  }
+
+  private logInfoOrQuery(message: LogMessage) {
+    if (message.prefix) {
+      this.logger.log(`${message.prefix} : ${message.message?.toString()}`);
+    } else {
+      this.logger.log(message.message);
+    }
+  }
+
+  private logWarnOrQuerySlow(message: LogMessage) {
+    if (message.prefix) {
+      this.logger.warn(`${message.prefix} : ${message.message?.toString()}`);
+    } else {
+      this.logger.warn(message.message);
+    }
+  }
+
+  private logErrorOrQueryError(message: LogMessage) {
+    if (message.prefix === 'query failed') {
+      this.logger.error(`${message.prefix} : ${message.message?.toString()}`);
+      this.logger.error(message.parameters); // Mask sensitive information before logging if needed
+    } else {
+      this.logger.error(new CustomError(message.message));
+    }
+  }
+}

dops/src/modules/common/cdogs.service.ts

@@ -2,8 +2,14 @@
  * Service responsible for interacting with CDOGS (Common Document Generation
  * Service).
  */
-import { Inject, Injectable } from '@nestjs/common';
+import {
+  Inject,
+  Injectable,
+  InternalServerErrorException,
+  Logger,
+} from '@nestjs/common';
 import { HttpService } from '@nestjs/axios';
+import { AxiosError } from 'axios';
 import { lastValueFrom } from 'rxjs';
 import { IUserJWT } from '../../interface/user-jwt.interface';
 import { CreateGeneratedDocumentDto } from '../dgen/dto/request/create-generated-document.dto';
@@ -22,6 +28,7 @@ import {
 
 @Injectable()
 export class CdogsService {
+  private readonly logger = new Logger(CdogsService.name);
   constructor(
     @Inject(CACHE_MANAGER)
     private readonly cacheManager: Cache,
@@ -110,9 +117,16 @@ export class CdogsService {
       .then((response) => {
         return response;
       })
-      .catch((error) => {
-        console.error('generate Document error: ', error);
-        throw error;
+      .catch((error: AxiosError) => {
+        if (error.response) {
+          const errorData = error.response.data;
+          this.logger.error(
+            `Error response from CHES: ${JSON.stringify(errorData, null, 2)}`,
+          );
+        } else {
+          this.logger.error(error?.message, error?.stack);
+        }
+        throw new InternalServerErrorException('Error rendering via CDOGS');
       });
 
     const generatedDocument: IFile = {

dops/src/modules/common/s3.service.ts

@@ -1,7 +1,7 @@
 /**
  * Service responsible for interacting with S3 Object Store
  */
-import { Injectable } from '@nestjs/common';
+import { Injectable, Logger } from '@nestjs/common';
 import { HttpService } from '@nestjs/axios';
 import {
   CompleteMultipartUploadCommandOutput,
@@ -16,6 +16,7 @@ import { Upload } from '@aws-sdk/lib-storage';
 
 @Injectable()
 export class S3Service {
+  private readonly logger = new Logger(S3Service.name);
   constructor(private readonly httpService: HttpService) {}
 
   private readonly _s3AccessKeyId = process.env.DOPS_S3_ACCESSKEYID;
@@ -71,8 +72,8 @@ export class S3Service {
       if (res) this._processS3Headers(response, res);
       const stream = response.Body as NodeJS.ReadableStream;
       return stream;
-    } catch (e) {
-      console.log(e);
+    } catch (error) {
+      this.logger.error(error);
     }
   }