Merge pull request #1146 from Infisical/pino

Replace winston with pino logging

backend/package.json

@@ -6,7 +6,7 @@
     "@godaddy/terminus": "^4.12.0",
     "@node-saml/passport-saml": "^4.0.4",
     "@octokit/rest": "^19.0.5",
-    "@sentry/node": "^7.49.0",
+    "@sentry/node": "^7.77.0",
     "@sentry/tracing": "^7.48.0",
     "@types/crypto-js": "^4.1.1",
     "@types/libsodium-wrappers": "^0.7.10",
@@ -42,6 +42,8 @@
     "passport-github": "^1.1.0",
     "passport-gitlab2": "^5.0.0",
     "passport-google-oauth20": "^2.0.0",
+    "pino": "^8.16.1",
+    "pino-http": "^8.5.1",
     "posthog-node": "^2.6.0",
     "probot": "^12.3.1",
     "query-string": "^7.1.3",
@@ -52,8 +54,6 @@
     "tweetnacl-util": "^0.15.1",
     "typescript": "^4.9.3",
     "utility-types": "^3.10.0",
-    "winston": "^3.8.2",
-    "winston-loki": "^6.0.6",
     "zod": "^3.22.3"
   },
   "overrides": {
@@ -66,7 +66,7 @@
   "main": "src/index.js",
   "scripts": {
     "start": "node build/index.js",
-    "dev": "nodemon",
+    "dev": "nodemon index.js | pino-pretty --colorize",
     "swagger-autogen": "node ./swagger/index.ts",
     "build": "rimraf ./build && tsc && cp -R ./src/templates ./build && cp -R ./src/data ./build",
     "lint": "eslint . --ext .ts",
@@ -104,6 +104,7 @@
     "@types/nodemailer": "^6.4.6",
     "@types/passport": "^1.0.12",
     "@types/picomatch": "^2.3.0",
+    "@types/pino": "^7.0.5",
     "@types/supertest": "^2.0.12",
     "@types/swagger-jsdoc": "^6.0.1",
     "@types/swagger-ui-express": "^4.1.3",
@@ -117,6 +118,7 @@
     "jest-junit": "^15.0.0",
     "nodemon": "^2.0.19",
     "npm": "^8.19.3",
+    "pino-pretty": "^10.2.3",
     "smee-client": "^1.2.3",
     "supertest": "^6.3.3",
     "swagger-autogen": "^2.23.5",

backend/src/helpers/database.ts

@@ -1,5 +1,5 @@
 import mongoose from "mongoose";
-import { getLogger } from "../utils/logger";
+import { logger } from "../utils/logging";
 
 /**
  * Initialize database connection
@@ -18,10 +18,10 @@ export const initDatabaseHelper = async ({
         // allow empty strings to pass the required validator
         mongoose.Schema.Types.String.checkRequired(v => typeof v === "string");
 
-        (await getLogger("database")).info("Database connection established");
+        logger.info("Database connection established");
 
     } catch (err) {
-        (await getLogger("database")).error(`Unable to establish Database connection due to the error.\n${err}`);
+        logger.error(err, "Unable to establish database connection");
     }
 
     return mongoose.connection;

backend/src/index.ts

@@ -5,6 +5,8 @@ import express from "express";
 require("express-async-errors");
 import helmet from "helmet";
 import cors from "cors";
+import { logger } from "./utils/logging";
+import httpLogger from "pino-http";
 import { DatabaseService } from "./services";
 import { EELicenseService, GithubSecretScanningService } from "./ee/services";
 import { setUpHealthEndpoint } from "./services/health";
@@ -73,7 +75,7 @@ import {
   workspaces as v3WorkspacesRouter
 } from "./routes/v3";
 import { healthCheck } from "./routes/status";
-import { getLogger } from "./utils/logger";
+// import { getLogger } from "./utils/logger";
 import { RouteNotFoundError } from "./utils/errors";
 import { requestErrorHandler } from "./middleware/requestErrorHandler";
 import {
@@ -94,12 +96,20 @@ import path from "path";
 let handler: null | any = null;
 
 const main = async () => {
+  const port = await getPort();
+
   await setup();
 
   await EELicenseService.initGlobalFeatureSet();
 
   const app = express();
   app.enable("trust proxy");
+  
+  app.use(httpLogger({
+    logger,
+    autoLogging: false
+  }));
+
   app.use(express.json());
   app.use(express.urlencoded({ extended: false }));
   app.use(cookieParser());
@@ -164,7 +174,7 @@ const main = async () => {
     const nextApp = new NextServer({
       dev: false,
       dir: nextJsBuildPath,
-      port: await getPort(),
+      port,
       conf,
       hostname: "local",
       customServer: false
@@ -255,8 +265,8 @@ const main = async () => {
 
   app.use(requestErrorHandler);
 
-  const server = app.listen(await getPort(), async () => {
+  const server = app.listen(port, async () => {
-    (await getLogger("backend-main")).info(`Server started listening at port ${await getPort()}`);
+    logger.info(`Server started listening at port ${port}`);
   });
 
   // await createTestUserForDevelopment();

backend/src/middleware/requestErrorHandler.ts

@@ -2,49 +2,45 @@ import * as Sentry from "@sentry/node";
 import { ErrorRequestHandler } from "express";
 import { TokenExpiredError } from "jsonwebtoken";
 import { InternalServerError, UnauthorizedRequestError } from "../utils/errors";
-import { getLogger } from "../utils/logger";
+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) => {
+  let error: RequestError;
-    (await getLogger("backend-main")).log(
+  
-      (<RequestError>error).levelName.toLowerCase(),
+  switch (true) {
-      `${error.stack}\n${error.message}`
+    case err instanceof TokenExpiredError:
-    );
+      error = UnauthorizedRequestError({ stack: err.stack, message: "Token expired" });
-
+      break;
-    //* Set Sentry user identification if req.user is populated
+    case err instanceof ForbiddenError:
-    if (req.user !== undefined && req.user !== null) {
+      error = UnauthorizedRequestError({ context: { exception: err.message }, stack: err.stack })
-      Sentry.setUser({ email: (req.user as any).email });
+      break;
-    }
+    case err instanceof RequestError:
-
+      error = err as RequestError;
-    Sentry.captureException(error);
+      break;
-  };
+    default:
-
+      error = InternalServerError({ context: { exception: err.message }, stack: err.stack });
-  if (error instanceof RequestError) {
+      break;
-    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));
   }
 
+  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/services/TelemetryService.ts

@@ -1,5 +1,5 @@
 import { PostHog } from "posthog-node";
-import { getLogger } from "../utils/logger";
+import { logger } from "../utils/logging";
 import { AuthData } from "../interfaces/middleware";
 import {
   getNodeEnv,
@@ -22,13 +22,13 @@ class Telemetry {
    * Logs telemetry enable/disable notice.
    */
   static logTelemetryMessage = async () => {
+
     if(!(await getTelemetryEnabled())){
-      (await getLogger("backend-main")).info([
+      [
-        "",
         "To improve, Infisical collects telemetry data about general usage.",
         "This helps us understand how the product is doing and guide our product development to create the best possible platform; it also helps us demonstrate growth as we support Infisical as open-source software.",
         "To opt into telemetry, you can set `TELEMETRY_ENABLED=true` within the environment variables.",
-      ].join("\n"))
+      ].forEach(line => logger.info(line));
     }
   }
 

backend/src/services/health.ts

@@ -1,10 +1,10 @@
 import mongoose from "mongoose";
 import { createTerminus } from "@godaddy/terminus";
-import { getLogger } from "../utils/logger";
+import { logger } from "../utils/logging";
 
 export const setUpHealthEndpoint = <T>(server: T) => {
   const onSignal = async () => {
-    (await getLogger("backend-main")).info("Server is starting clean-up");
+    logger.info("Server is starting clean-up");
     return Promise.all([
       new Promise((resolve) => {
         if (mongoose.connection && mongoose.connection.readyState == 1) {

backend/src/services/smtp.ts

@@ -16,7 +16,7 @@ import {
   getSmtpSecure,
   getSmtpUsername,
 } from "../config";
-import { getLogger } from "../utils/logger";
+import { logger } from "../utils/logging";
 
 export const initSmtp = async () => {
   const mailOpts: SMTPConnection.Options = {
@@ -84,15 +84,14 @@ export const initSmtp = async () => {
     .then(async () => {
       Sentry.setUser(null);
       Sentry.captureMessage("SMTP - Successfully connected");
-      (await getLogger("backend-main")).info(
+      logger.info("SMTP - Successfully connected");
-        "SMTP - Successfully connected"
-      );
     })
     .catch(async (err) => {
       Sentry.setUser(null);
       Sentry.captureException(
         `SMTP - Failed to connect to ${await getSmtpHost()}:${await getSmtpPort()} \n\t${err}`
       );
+      logger.error(err, `SMTP - Failed to connect to ${await getSmtpHost()}:${await getSmtpPort()}`);
     });
 
   return transporter;

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/logger.ts

@@ -1,67 +0,0 @@
-/* eslint-disable no-console */
-import { createLogger, format, transports } from "winston";
-import LokiTransport from "winston-loki";
-import { getLokiHost, getNodeEnv } from "../config";
-
-const { combine, colorize, label, printf, splat, timestamp } = format;
-
-const logFormat = (prefix: string) => combine(
-  timestamp(),
-  splat(),
-  label({ label: prefix }),
-  printf((info) => `${info.timestamp} ${info.label} ${info.level}: ${info.message}`)
-);
-
-const createLoggerWithLabel = async (level: string, label: string) => {
-  const _level = level.toLowerCase() || "info"
-  //* Always add Console output to transports
-  const _transports: any[] = [
-    new transports.Console({
-      format: combine(
-        colorize(),
-        logFormat(label),
-        // format.json()
-      ),
-    }),
-  ]
-  //* Add LokiTransport if it's enabled
-  if((await getLokiHost()) !== undefined){
-    _transports.push(
-      new LokiTransport({
-        host: await getLokiHost(),
-        handleExceptions: true,
-        handleRejections: true,
-        batching: true,
-        level: _level,
-        timeout: 30000,
-        format: format.combine(
-          format.json()
-        ),
-        labels: {
-          app: process.env.npm_package_name, 
-          version: process.env.npm_package_version, 
-          environment: await getNodeEnv(),
-        },
-        onConnectionError: (err: Error)=> console.error("Connection error while connecting to Loki Server.\n", err),
-      })
-    )
-  }
-  
-  
-  return createLogger({
-    level: _level,
-    transports: _transports,
-    format: format.combine(
-      logFormat(label),
-      format.metadata({ fillExcept: ["message", "level", "timestamp", "label"] })
-    ),
-  });
-}
-
-export const getLogger = async (loggerName: "backend-main" | "database") => {
-  const logger = {
-    "backend-main": await createLoggerWithLabel("info", "[IFSC:backend-main]"),
-    "database": await createLoggerWithLabel("info", "[IFSC:database]"),
-  }
-  return logger[loggerName]
-} 

backend/src/utils/logging/index.ts

@@ -0,0 +1 @@
+export { logger } from "./logger";

backend/src/utils/logging/logger.ts

@@ -0,0 +1,15 @@
+import pino from "pino";
+
+export const logger = pino({
+  level: process.env.PINO_LOG_LEVEL || "trace",
+  timestamp: pino.stdTimeFunctions.isoTime,
+  formatters: {
+    bindings: (bindings) => {
+        return {
+            pid: bindings.pid,
+            hostname: bindings.hostname
+            // node_version: process.version
+        };
+    },
+  }
+});

backend/src/utils/requestError.ts

@@ -2,34 +2,30 @@ import { Request } from "express"
 import { getVerboseErrorOutput } from "../config";
 
 export enum LogLevel {
-    DEBUG = 100,
+  TRACE = 10,
-    INFO = 200,
+  DEBUG = 20,
-    NOTICE = 250,
+  INFO = 30,
-    WARNING = 300,
+  WARN = 40,
-    ERROR = 400,
+  ERROR = 50,
-    CRITICAL = 500,
+  FATAL = 60
-    ALERT = 550,
-    EMERGENCY = 600,
 }
 
-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:
+    case LogLevel.WARN:
-      return "notice";
-    case LogLevel.WARNING:
       return "warn";
     case LogLevel.ERROR:
       return "error";
-    case LogLevel.CRITICAL:
+    case LogLevel.FATAL:
-      return "crit";
+      return "fatal";
-    case LogLevel.ALERT:
-      return "alert";
-    case LogLevel.EMERGENCY:
-      return "emerg";
   }
 }
 
@@ -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 level(){ 
-    get levelName(){ return this._logName }
+      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");
 }

docs/self-hosting/configuration/envars.mdx

@@ -153,29 +153,18 @@ Other environment variables are listed below to increase the functionality of yo
       JWT token lifetime expressed in seconds or a string describing a time span
     </ParamField>
 
-{" "}
+#### Logging
-
-<ParamField
-  query="MONGO_USERNAME"
-  type="string"
-  default="none"
-  optional
-></ParamField>
-
-{" "}
-
-<ParamField
-  query="MONGO_PASSWORD"
-  type="string"
-  default="none"
-  optional
-></ParamField>
-
-#### Error logging
 
 Infisical uses Sentry to report error logs
 
-{" "}
+<ParamField
+  query="PINO_LOG_LEVEL"
+  type="string"
+  default="info"
+  optional
+>
+  The minimum log level for application logging; can be one of `trace`, `debug`, `info`, `warn`, `error`, or `fatal`.
+</ParamField>
 
 <ParamField
   query="SENTRY_DSN"