feat: request lifecycle request ID

backend/package-lock.json

@@ -24,6 +24,7 @@
         "@fastify/multipart": "8.3.0",
         "@fastify/passport": "^2.4.0",
         "@fastify/rate-limit": "^9.0.0",
+        "@fastify/request-context": "^5.1.0",
         "@fastify/session": "^10.7.0",
         "@fastify/swagger": "^8.14.0",
         "@fastify/swagger-ui": "^2.1.0",
@@ -5528,6 +5529,15 @@
         "toad-cache": "^3.3.0"
       }
     },
+    "node_modules/@fastify/request-context": {
+      "version": "5.1.0",
+      "resolved": "https://registry.npmjs.org/@fastify/request-context/-/request-context-5.1.0.tgz",
+      "integrity": "sha512-PM7wrLJOEylVDpxabOFLaYsdAiaa0lpDUcP2HMFJ1JzgiWuC6k4r3duf6Pm9YLnzlGmT+Yp4tkQjqsu7V/pSOA==",
+      "license": "MIT",
+      "dependencies": {
+        "fastify-plugin": "^4.0.0"
+      }
+    },
     "node_modules/@fastify/send": {
       "version": "2.1.0",
       "resolved": "https://registry.npmjs.org/@fastify/send/-/send-2.1.0.tgz",

backend/package.json

@@ -132,6 +132,7 @@
     "@fastify/multipart": "8.3.0",
     "@fastify/passport": "^2.4.0",
     "@fastify/rate-limit": "^9.0.0",
+    "@fastify/request-context": "^5.1.0",
     "@fastify/session": "^10.7.0",
     "@fastify/swagger": "^8.14.0",
     "@fastify/swagger-ui": "^2.1.0",

backend/src/@types/fastify-request-context.d.ts

@@ -0,0 +1,7 @@
+import "@fastify/request-context";
+
+declare module "@fastify/request-context" {
+  interface RequestContextData {
+    requestId: string;
+  }
+}

backend/src/@types/fastify-zod.d.ts

@@ -1,6 +1,6 @@
 import { FastifyInstance, RawReplyDefaultExpression, RawRequestDefaultExpression, RawServerDefault } from "fastify";
-import { Logger } from "pino";
 
+import { CustomLogger } from "@app/lib/logger/logger";
 import { ZodTypeProvider } from "@app/server/plugins/fastify-zod";
 
 declare global {
@@ -8,7 +8,7 @@ declare global {
     RawServerDefault,
     RawRequestDefaultExpression<RawServerDefault>,
     RawReplyDefaultExpression<RawServerDefault>,
-    Readonly<Logger>,
+    Readonly<CustomLogger>,
     ZodTypeProvider
   >;
 

backend/src/ee/services/hsm/hsm-fns.ts

@@ -27,7 +27,7 @@ export const initializeHsmModule = () => {
 
       logger.info("PKCS#11 module initialized");
     } catch (err) {
-      logger.error("Failed to initialize PKCS#11 module:", err);
+      logger.error(err, "Failed to initialize PKCS#11 module");
       throw err;
     }
   };
@@ -39,7 +39,7 @@ export const initializeHsmModule = () => {
         isInitialized = false;
         logger.info("PKCS#11 module finalized");
       } catch (err) {
-        logger.error("Failed to finalize PKCS#11 module:", err);
+        logger.error(err, "Failed to finalize PKCS#11 module");
         throw err;
       }
     }

backend/src/ee/services/license/license-service.ts

@@ -161,8 +161,8 @@ export const licenseServiceFactory = ({
       }
     } catch (error) {
       logger.error(
-        `getPlan: encountered an error when fetching pan [orgId=${orgId}] [projectId=${projectId}] [error]`,
+        error,
-        error
+        `getPlan: encountered an error when fetching pan [orgId=${orgId}] [projectId=${projectId}] [error]`
       );
       await keyStore.setItemWithExpiry(
         FEATURE_CACHE_KEY(orgId),

backend/src/ee/services/rate-limit/rate-limit-service.ts

@@ -46,7 +46,7 @@ export const rateLimitServiceFactory = ({ rateLimitDAL, licenseService }: TRateL
       }
       return rateLimit;
     } catch (err) {
-      logger.error("Error fetching rate limits %o", err);
+      logger.error(err, "Error fetching rate limits");
       return undefined;
     }
   };
@@ -69,12 +69,12 @@ export const rateLimitServiceFactory = ({ rateLimitDAL, licenseService }: TRateL
           mfaRateLimit: rateLimit.mfaRateLimit
         };
 
-        logger.info(`syncRateLimitConfiguration: rate limit configuration: %o`, newRateLimitMaxConfiguration);
+        logger.info(newRateLimitMaxConfiguration, "syncRateLimitConfiguration: rate limit configuration");
         Object.freeze(newRateLimitMaxConfiguration);
         rateLimitMaxConfiguration = newRateLimitMaxConfiguration;
       }
     } catch (error) {
-      logger.error(`Error syncing rate limit configurations: %o`, error);
+      logger.error(error, "Error syncing rate limit configurations");
     }
   };
 

backend/src/ee/services/secret-scanning/secret-scanning-queue/secret-scanning-queue.ts

@@ -238,11 +238,11 @@ export const secretScanningQueueFactory = ({
   });
 
   queueService.listen(QueueName.SecretPushEventScan, "failed", (job, err) => {
-    logger.error("Failed to secret scan on push", job?.data, err);
+    logger.error(err, "Failed to secret scan on push", job?.data);
   });
 
   queueService.listen(QueueName.SecretFullRepoScan, "failed", (job, err) => {
-    logger.error("Failed to do full repo secret scan", job?.data, err);
+    logger.error(err, "Failed to do full repo secret scan", job?.data);
   });
 
   return { startFullRepoScan, startPushEventScan };

backend/src/lib/config/env.ts

@@ -1,7 +1,7 @@
-import { Logger } from "pino";
 import { z } from "zod";
 
 import { removeTrailingSlash } from "../fn";
+import { CustomLogger } from "../logger/logger";
 import { zpStr } from "../zod";
 
 export const GITLAB_URL = "https://gitlab.com";
@@ -212,7 +212,7 @@ let envCfg: Readonly<z.infer<typeof envSchema>>;
 
 export const getConfig = () => envCfg;
 // cannot import singleton logger directly as it needs config to load various transport
-export const initEnvConfig = (logger?: Logger) => {
+export const initEnvConfig = (logger?: CustomLogger) => {
   const parsedEnv = envSchema.safeParse(process.env);
   if (!parsedEnv.success) {
     (logger ?? console).error("Invalid environment variables. Check the error below");

backend/src/lib/logger/logger.ts

@@ -1,6 +1,8 @@
+/* eslint-disable @typescript-eslint/no-unsafe-argument */
 /* eslint-disable @typescript-eslint/no-unsafe-assignment */
 // logger follows a singleton pattern
 // easier to use it that's all.
+import { requestContext } from "@fastify/request-context";
 import pino, { Logger } from "pino";
 import { z } from "zod";
 
@@ -13,14 +15,37 @@ const logLevelToSeverityLookup: Record<string, string> = {
   "60": "CRITICAL"
 };
 
-// eslint-disable-next-line import/no-mutable-exports
-export let logger: Readonly<Logger>;
 // akhilmhdh:
 // The logger is not placed in the main app config to avoid a circular dependency.
 // The config requires the logger to display errors when an invalid environment is supplied.
 // On the other hand, the logger needs the config to obtain credentials for AWS or other transports.
 // By keeping the logger separate, it becomes an independent package.
 
+// We define our own custom logger interface to enforce structure to the logging methods.
+
+export interface CustomLogger extends Omit<Logger, "info" | "error" | "warn" | "debug"> {
+  info: {
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (obj: unknown, msg?: string, ...args: any[]): void;
+  };
+
+  error: {
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (obj: unknown, msg?: string, ...args: any[]): void;
+  };
+  warn: {
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (obj: unknown, msg?: string, ...args: any[]): void;
+  };
+  debug: {
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (obj: unknown, msg?: string, ...args: any[]): void;
+  };
+}
+
+// eslint-disable-next-line import/no-mutable-exports
+export let logger: Readonly<CustomLogger>;
+
 const loggerConfig = z.object({
   AWS_CLOUDWATCH_LOG_GROUP_NAME: z.string().default("infisical-log-stream"),
   AWS_CLOUDWATCH_LOG_REGION: z.string().default("us-east-1"),
@@ -62,6 +87,17 @@ const redactedKeys = [
   "config"
 ];
 
+const UNKNOWN_REQUEST_ID = "UNKNOWN_REQUEST_ID";
+
+const extractRequestId = () => {
+  try {
+    return requestContext.get("requestId") || UNKNOWN_REQUEST_ID;
+  } catch (err) {
+    console.log("failed to get request context", err);
+    return UNKNOWN_REQUEST_ID;
+  }
+};
+
 export const initLogger = async () => {
   const cfg = loggerConfig.parse(process.env);
   const targets: pino.TransportMultiOptions["targets"][number][] = [
@@ -94,6 +130,30 @@ export const initLogger = async () => {
     targets
   });
 
+  const wrapLogger = (originalLogger: Logger): CustomLogger => {
+    // eslint-disable-next-line no-param-reassign, @typescript-eslint/no-explicit-any
+    originalLogger.info = (obj: unknown, msg?: string, ...args: any[]) => {
+      return originalLogger.child({ requestId: extractRequestId() }).info(obj, msg, ...args);
+    };
+
+    // eslint-disable-next-line no-param-reassign, @typescript-eslint/no-explicit-any
+    originalLogger.error = (obj: unknown, msg?: string, ...args: any[]) => {
+      return originalLogger.child({ requestId: extractRequestId() }).error(obj, msg, ...args);
+    };
+
+    // eslint-disable-next-line no-param-reassign, @typescript-eslint/no-explicit-any
+    originalLogger.warn = (obj: unknown, msg?: string, ...args: any[]) => {
+      return originalLogger.child({ requestId: extractRequestId() }).warn(obj, msg, ...args);
+    };
+
+    // eslint-disable-next-line no-param-reassign, @typescript-eslint/no-explicit-any
+    originalLogger.debug = (obj: unknown, msg?: string, ...args: any[]) => {
+      return originalLogger.child({ requestId: extractRequestId() }).debug(obj, msg, ...args);
+    };
+
+    return originalLogger;
+  };
+
   logger = pino(
     {
       mixin(_context, level) {
@@ -113,5 +173,6 @@ export const initLogger = async () => {
     // eslint-disable-next-line @typescript-eslint/no-unsafe-argument
     transport
   );
-  return logger;
+
+  return wrapLogger(logger);
 };

backend/src/server/app.ts

@@ -10,13 +10,14 @@ import fastifyFormBody from "@fastify/formbody";
 import helmet from "@fastify/helmet";
 import type { FastifyRateLimitOptions } from "@fastify/rate-limit";
 import ratelimiter from "@fastify/rate-limit";
+import { fastifyRequestContext } from "@fastify/request-context";
 import fastify from "fastify";
 import { Knex } from "knex";
-import { Logger } from "pino";
 
 import { HsmModule } from "@app/ee/services/hsm/hsm-types";
 import { TKeyStoreFactory } from "@app/keystore/keystore";
 import { getConfig, IS_PACKAGED } from "@app/lib/config/env";
+import { CustomLogger } from "@app/lib/logger/logger";
 import { alphaNumericNanoId } from "@app/lib/nanoid";
 import { TQueueServiceFactory } from "@app/queue";
 import { TSmtpService } from "@app/services/smtp/smtp-service";
@@ -36,7 +37,7 @@ type TMain = {
   auditLogDb?: Knex;
   db: Knex;
   smtp: TSmtpService;
-  logger?: Logger;
+  logger?: CustomLogger;
   queue: TQueueServiceFactory;
   keyStore: TKeyStoreFactory;
   hsmModule: HsmModule;
@@ -50,6 +51,7 @@ export const main = async ({ db, hsmModule, auditLogDb, smtp, logger, queue, key
     logger: appCfg.NODE_ENV === "test" ? false : logger,
     genReqId: () => `req-${alphaNumericNanoId(14)}`,
     trustProxy: true,
+
     connectionTimeout: appCfg.isHsmConfigured ? 90_000 : 30_000,
     ignoreTrailingSlash: true,
     pluginTimeout: 40_000
@@ -106,6 +108,13 @@ export const main = async ({ db, hsmModule, auditLogDb, smtp, logger, queue, key
 
     await server.register(maintenanceMode);
 
+    await server.register(fastifyRequestContext, {
+      defaultStoreValues: (request) => ({
+        requestId: request.id,
+        log: request.log.child({ requestId: request.id })
+      })
+    });
+
     await server.register(registerRoutes, { smtp, queue, db, auditLogDb, keyStore, hsmModule });
 
     if (appCfg.isProductionMode) {

backend/src/server/plugins/secret-scanner.ts

@@ -19,7 +19,7 @@ export const registerSecretScannerGhApp = async (server: FastifyZodProvider) =>
 
     app.on("installation", async (context) => {
       const { payload } = context;
-      logger.info("Installed secret scanner to:", { repositories: payload.repositories });
+      logger.info({ repositories: payload.repositories }, "Installed secret scanner to");
     });
 
     app.on("push", async (context) => {

backend/src/services/project/project-queue.ts

@@ -285,11 +285,14 @@ export const projectQueueFactory = ({
 
           if (!orgMembership) {
             // This can happen. Since we don't remove project memberships and project keys when a user is removed from an org, this is a valid case.
-            logger.info("User is not in organization", {
+            logger.info(
-              userId: key.receiverId,
+              {
-              orgId: project.orgId,
+                userId: key.receiverId,
-              projectId: project.id
+                orgId: project.orgId,
-            });
+                projectId: project.id
+              },
+              "User is not in organization"
+            );
             // eslint-disable-next-line no-continue
             continue;
           }
@@ -551,10 +554,10 @@ export const projectQueueFactory = ({
         .catch(() => [null]);
 
       if (!project) {
-        logger.error("Failed to upgrade project, because no project was found", data);
+        logger.error(data, "Failed to upgrade project, because no project was found");
       } else {
         await projectDAL.setProjectUpgradeStatus(data.projectId, ProjectUpgradeStatus.Failed);
-        logger.error("Failed to upgrade project", err, {
+        logger.error(err, "Failed to upgrade project", {
           extra: {
             project,
             jobData: data

backend/src/services/webhook/webhook-fns.ts

@@ -142,7 +142,7 @@ export const fnTriggerWebhook = async ({
       !isDisabled && picomatch.isMatch(secretPath, hookSecretPath, { strictSlashes: false })
   );
   if (!toBeTriggeredHooks.length) return;
-  logger.info("Secret webhook job started", { environment, secretPath, projectId });
+  logger.info({ environment, secretPath, projectId }, "Secret webhook job started");
   const project = await projectDAL.findById(projectId);
   const webhooksTriggered = await Promise.allSettled(
     toBeTriggeredHooks.map((hook) =>
@@ -195,5 +195,5 @@ export const fnTriggerWebhook = async ({
       );
     }
   });
-  logger.info("Secret webhook job ended", { environment, secretPath, projectId });
+  logger.info({ environment, secretPath, projectId }, "Secret webhook job ended");
 };