Refactor requestErrorHandler, adjust request errors to appropriate pino log level

backend/src/middleware/requestErrorHandler.ts

@@ -3,52 +3,44 @@ import { ErrorRequestHandler } from "express";
 import { TokenExpiredError } from "jsonwebtoken";
 import { InternalServerError, UnauthorizedRequestError } from "../utils/errors";
 import { logger } from "../utils/logging";
-import RequestError from "../utils/requestError";
+import RequestError, { mapToPinoLogLevel } from "../utils/requestError";
 import { ForbiddenError } from "@casl/ability";
 
 export const requestErrorHandler: ErrorRequestHandler = async (
-  error: RequestError | Error,
+  err: RequestError | Error,
   req,
   res,
   next
 ) => {
   if (res.headersSent) return next();
 
-  const logAndCaptureException = async (error: RequestError) => {
-    // TODO: tie pino error-handling to error types/levels
+  let error: RequestError;
   
-    // (await getLogger("backend-main")).log(
-    //   (<RequestError>error).levelName.toLowerCase(),
-    //   `${error.stack}\n${error.message}`
-    // );
-    
-    logger.error(error.stack, error.message);
-
-    //* Set Sentry user identification if req.user is populated
-    if (req.user !== undefined && req.user !== null) {
-      Sentry.setUser({ email: (req.user as any).email });
-    }
-
-    Sentry.captureException(error);
-  };
-
-  if (error instanceof RequestError) {
-    if (error instanceof TokenExpiredError) {
-      error = UnauthorizedRequestError({ stack: error.stack, message: "Token expired" });
-    }
-    await logAndCaptureException((<RequestError>error));
-  } else {
-    if (error instanceof ForbiddenError) {
-      error = UnauthorizedRequestError({ context: { exception: error.message }, stack: error.stack })
-    } else {
-      error = InternalServerError({ context: { exception: error.message }, stack: error.stack });
-    }
-
-    await logAndCaptureException((<RequestError>error));
+  switch (true) {
+    case err instanceof TokenExpiredError:
+      error = UnauthorizedRequestError({ stack: err.stack, message: "Token expired" });
+      break;
+    case err instanceof ForbiddenError:
+      error = UnauthorizedRequestError({ context: { exception: err.message }, stack: err.stack })
+      break;
+    case err instanceof RequestError:
+      error = err as RequestError;
+      break;
+    default:
+      error = InternalServerError({ context: { exception: err.message }, stack: err.stack });
+      break;
   }
 
+  logger[mapToPinoLogLevel(error.level)](error);
+
+  if (req.user) {
+    Sentry.setUser({ email: (req.user as any).email });
+  }
+
+  Sentry.captureException(error);
+
   delete (<any>error).stacktrace // remove stack trace from being sent to client
-  res.status((<RequestError>error).statusCode).json(error);
+  res.status((<RequestError>error).statusCode).json(error); // revise json part here
 
   next();
 };

backend/src/utils/errors.ts

@@ -29,7 +29,7 @@ export const UnauthorizedRequestError = (error?: Partial<RequestErrorContext>) =
 });
 
 export const ForbiddenRequestError = (error?: Partial<RequestErrorContext>) => new RequestError({
-    logLevel: error?.logLevel ?? LogLevel.INFO,
+    logLevel: error?.logLevel ?? LogLevel.WARN,
     statusCode: error?.statusCode ?? 403,
     type: error?.type ?? "forbidden",
     message: error?.message ?? "You are not allowed to access this resource",

backend/src/utils/logging/logger.ts

@@ -13,9 +13,12 @@ export const logger = pino({
     },
   },
   transport: {
-    target: "pino-pretty",
-    options: {
-        colorize: true
-    }
+    targets: [
+      {
+        target: "pino-pretty",
+        level: process.env.PINO_LOG_LEVEL || "trace",
+        options: { colorize: true }
+      }
+    ]
   }
 });

backend/src/utils/requestError.ts

@@ -2,34 +2,30 @@ import { Request } from "express"
 import { getVerboseErrorOutput } from "../config";
 
 export enum LogLevel {
-    DEBUG = 100,
-    INFO = 200,
-    NOTICE = 250,
-    WARNING = 300,
-    ERROR = 400,
-    CRITICAL = 500,
-    ALERT = 550,
-    EMERGENCY = 600,
+  TRACE = 10,
+  DEBUG = 20,
+  INFO = 30,
+  WARN = 40,
+  ERROR = 50,
+  FATAL = 60
 }
 
-export const mapToWinstonLogLevel = (customLogLevel: LogLevel): string => {
+type PinoLogLevel = "trace" | "debug" | "info" | "warn" | "error" | "fatal";
+
+export const mapToPinoLogLevel = (customLogLevel: LogLevel): PinoLogLevel => {
   switch (customLogLevel) {
+    case LogLevel.TRACE:
+      return "trace";
     case LogLevel.DEBUG:
       return "debug";
     case LogLevel.INFO:
       return "info";
-    case LogLevel.NOTICE:
-      return "notice";
-    case LogLevel.WARNING:
+    case LogLevel.WARN:
       return "warn";
     case LogLevel.ERROR:
       return "error";
-    case LogLevel.CRITICAL:
-      return "crit";
-    case LogLevel.ALERT:
-      return "alert";
-    case LogLevel.EMERGENCY:
-      return "emerg";
+    case LogLevel.FATAL:
+      return "fatal";
   }
 }
 
@@ -42,10 +38,10 @@ export type RequestErrorContext =  {
 	stack?: string|undefined
 }
 
-export default class RequestError extends Error{
+export default class RequestError extends Error {
 
     private _logLevel: LogLevel
-    private _logName: string
+    private _logName: string;
     statusCode: number
     type: string
     context: Record<string, unknown>
@@ -55,9 +51,10 @@ export default class RequestError extends Error{
     constructor(
         {logLevel, statusCode, type, message, context, stack} : RequestErrorContext
         ){
+        
         super(message)
         this._logLevel = logLevel || LogLevel.INFO
-        this._logName = LogLevel[this._logLevel]
+        this._logName = LogLevel[this._logLevel];
         this.statusCode = statusCode
         this.type = type
         this.context = context || {}
@@ -83,8 +80,12 @@ export default class RequestError extends Error{
         })
     }
 
-    get level(){ return this._logLevel }
-    get levelName(){ return this._logName }
+    get level(){ 
+      return this._logLevel 
+    }
+    get levelName(){ 
+      return this._logName 
+    }
 
     withTags(...tags: string[]|number[]){
         this.context["tags"] = Object.assign(tags, this.context["tags"])

backend/src/utils/setup/backfillData.ts

@@ -1,4 +1,3 @@
-/* eslint-disable no-console */
 import crypto from "crypto";
 import { Types } from "mongoose";
 import { encryptSymmetric128BitHexKeyUTF8 } from "../crypto";
@@ -47,6 +46,7 @@ import {
   ProjectPermissionSub,
   memberProjectPermissions
 } from "../../ee/services/ProjectRoleService";
+import { logger } from "../logging";
 
 /**
  * Backfill secrets to ensure that they're all versioned and have
@@ -88,7 +88,7 @@ export const backfillSecretVersions = async () => {
       )
     });
   }
-  console.log("Migration: Secret version migration v1 complete");
+  logger.info("Migration: Secret version migration v1 complete");
 };
 
 /**
@@ -518,7 +518,7 @@ export const backfillSecretFolders = async () => {
       .limit(50);
   }
 
-  console.log("Migration: Folder migration v1 complete");
+  logger.info("Migration: Folder migration v1 complete");
 };
 
 export const backfillServiceToken = async () => {
@@ -534,7 +534,7 @@ export const backfillServiceToken = async () => {
       }
     }
   );
-  console.log("Migration: Service token migration v1 complete");
+  logger.info("Migration: Service token migration v1 complete");
 };
 
 export const backfillIntegration = async () => {
@@ -550,7 +550,7 @@ export const backfillIntegration = async () => {
       }
     }
   );
-  console.log("Migration: Integration migration v1 complete");
+  logger.info("Migration: Integration migration v1 complete");
 };
 
 export const backfillServiceTokenMultiScope = async () => {
@@ -575,7 +575,7 @@ export const backfillServiceTokenMultiScope = async () => {
     }
   }
 
-  console.log("Migration: Service token migration v2 complete");
+  logger.info("Migration: Service token migration v2 complete");
 };
 
 /**
@@ -650,7 +650,7 @@ export const backfillTrustedIps = async () => {
     });
 
     await TrustedIP.bulkWrite(operations);
-    console.log("Backfill: Trusted IPs complete");
+    logger.info("Backfill: Trusted IPs complete");
   }
 };
 
@@ -698,7 +698,7 @@ export const backfillPermission = async () => {
 
   if (lock) {
     try {
-      console.info("Lock acquired for script [backfillPermission]");
+      logger.info("Lock acquired for script [backfillPermission]");
 
       const memberships = await Membership.find({
         deniedPermissions: {
@@ -801,7 +801,7 @@ export const backfillPermission = async () => {
         }
       }
 
-      console.info("Backfill: Finished converting old denied permission in workspace to viewers");
+      logger.info("Backfill: Finished converting old denied permission in workspace to viewers");
 
       await MembershipOrg.updateMany(
         {
@@ -814,14 +814,14 @@ export const backfillPermission = async () => {
         }
       );
 
-      console.info("Backfill: Finished converting owner role to member");
+      logger.info("Backfill: Finished converting owner role to member");
 
     } catch (error) {
-      console.error("An error occurred when running script [backfillPermission]:", error);
+      logger.error(error, "An error occurred when running script [backfillPermission]");
     }
 
   } else {
-    console.info("Could not acquire lock for script [backfillPermission], skipping");
+    logger.info("Could not acquire lock for script [backfillPermission], skipping");
   }
 };
 
@@ -837,5 +837,5 @@ export const migrateRoleFromOwnerToAdmin = async () => {
     }
   );
 
-  console.info("Backfill: Finished converting owner role to member");
+  logger.info("Backfill: Finished converting owner role to member");
 }