From 38917327d9577fb22aeeb484a1235a6d3a1e1a6c Mon Sep 17 00:00:00 2001 From: Daniel Hougaard Date: Fri, 22 Nov 2024 23:19:07 +0400 Subject: [PATCH] feat: request lifecycle request ID --- backend/package-lock.json | 10 +++ backend/package.json | 1 + .../src/@types/fastify-request-context.d.ts | 7 ++ backend/src/@types/fastify-zod.d.ts | 4 +- backend/src/ee/services/hsm/hsm-fns.ts | 4 +- .../ee/services/license/license-service.ts | 4 +- .../services/rate-limit/rate-limit-service.ts | 6 +- .../secret-scanning-queue.ts | 4 +- backend/src/lib/config/env.ts | 4 +- backend/src/lib/logger/logger.ts | 67 ++++++++++++++++++- backend/src/server/app.ts | 13 +++- backend/src/server/plugins/secret-scanner.ts | 2 +- backend/src/services/project/project-queue.ts | 17 +++-- backend/src/services/webhook/webhook-fns.ts | 4 +- 14 files changed, 119 insertions(+), 28 deletions(-) create mode 100644 backend/src/@types/fastify-request-context.d.ts diff --git a/backend/package-lock.json b/backend/package-lock.json index 0d7544314..ef7203d2c 100644 --- a/backend/package-lock.json +++ b/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", diff --git a/backend/package.json b/backend/package.json index 82b2df024..7db48d56d 100644 --- a/backend/package.json +++ b/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", diff --git a/backend/src/@types/fastify-request-context.d.ts b/backend/src/@types/fastify-request-context.d.ts new file mode 100644 index 000000000..caef4d5b2 --- /dev/null +++ b/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; + } +} diff --git a/backend/src/@types/fastify-zod.d.ts b/backend/src/@types/fastify-zod.d.ts index 393579391..440e3393f 100644 --- a/backend/src/@types/fastify-zod.d.ts +++ b/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, RawReplyDefaultExpression, - Readonly, + Readonly, ZodTypeProvider >; diff --git a/backend/src/ee/services/hsm/hsm-fns.ts b/backend/src/ee/services/hsm/hsm-fns.ts index f91f9a004..3124e1012 100644 --- a/backend/src/ee/services/hsm/hsm-fns.ts +++ b/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; } } diff --git a/backend/src/ee/services/license/license-service.ts b/backend/src/ee/services/license/license-service.ts index dc56e7bc3..6becaaf2b 100644 --- a/backend/src/ee/services/license/license-service.ts +++ b/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), diff --git a/backend/src/ee/services/rate-limit/rate-limit-service.ts b/backend/src/ee/services/rate-limit/rate-limit-service.ts index 208fa8428..61b18be91 100644 --- a/backend/src/ee/services/rate-limit/rate-limit-service.ts +++ b/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"); } }; diff --git a/backend/src/ee/services/secret-scanning/secret-scanning-queue/secret-scanning-queue.ts b/backend/src/ee/services/secret-scanning/secret-scanning-queue/secret-scanning-queue.ts index 1907ddd9a..42ff90055 100644 --- a/backend/src/ee/services/secret-scanning/secret-scanning-queue/secret-scanning-queue.ts +++ b/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 }; diff --git a/backend/src/lib/config/env.ts b/backend/src/lib/config/env.ts index 279ca057d..12ab33118 100644 --- a/backend/src/lib/config/env.ts +++ b/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>; 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"); diff --git a/backend/src/lib/logger/logger.ts b/backend/src/lib/logger/logger.ts index 942efc40a..5563499e5 100644 --- a/backend/src/lib/logger/logger.ts +++ b/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 = { "60": "CRITICAL" }; -// eslint-disable-next-line import/no-mutable-exports -export let logger: Readonly; // 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 { + 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; + 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); }; diff --git a/backend/src/server/app.ts b/backend/src/server/app.ts index 439514031..83c34e5a7 100644 --- a/backend/src/server/app.ts +++ b/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) { diff --git a/backend/src/server/plugins/secret-scanner.ts b/backend/src/server/plugins/secret-scanner.ts index d20008de7..d9b5801b9 100644 --- a/backend/src/server/plugins/secret-scanner.ts +++ b/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) => { diff --git a/backend/src/services/project/project-queue.ts b/backend/src/services/project/project-queue.ts index d59bde6c1..e845ebd35 100644 --- a/backend/src/services/project/project-queue.ts +++ b/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", { - userId: key.receiverId, - orgId: project.orgId, - projectId: project.id - }); + logger.info( + { + userId: key.receiverId, + 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 diff --git a/backend/src/services/webhook/webhook-fns.ts b/backend/src/services/webhook/webhook-fns.ts index ffa4b4a04..58f51f880 100644 --- a/backend/src/services/webhook/webhook-fns.ts +++ b/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"); };