Merge pull request #2760 from Infisical/daniel/request-ids

feat: request ID support

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,14 +1,14 @@
 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 {
   type FastifyZodProvider = FastifyInstance<
     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/ldap-config/ldap-fns.ts

@@ -36,8 +36,7 @@ export const testLDAPConfig = async (ldapConfig: TLDAPConfig): Promise<boolean>
     });
 
     ldapClient.on("error", (err) => {
-      logger.error("LDAP client error:", err);
-      logger.error(err);
+      logger.error(err, "LDAP client error");
       resolve(false);
     });
 

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,15 @@ 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";
 
@@ -35,7 +37,7 @@ type TMain = {
   auditLogDb?: Knex;
   db: Knex;
   smtp: TSmtpService;
-  logger?: Logger;
+  logger?: CustomLogger;
   queue: TQueueServiceFactory;
   keyStore: TKeyStoreFactory;
   hsmModule: HsmModule;
@@ -47,7 +49,9 @@ export const main = async ({ db, hsmModule, auditLogDb, smtp, logger, queue, key
 
   const server = fastify({
     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
@@ -104,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) {