fix: use pino-http for logging within controller (#22)

Author: WipeAir

package.json

@@ -61,6 +61,7 @@
 		"octokit": "^4.0.2",
 		"openid-client": "^5.7.0",
 		"pino": "^9.4.0",
+		"pino-http": "^10.3.0",
 		"pino-pretty": "^11.2.2",
 		"zod": "^3.23.8"
 	},

src/bootstrap.ts

@@ -1,5 +1,7 @@
 import bodyParser from "body-parser";
 import expressApp, { Router } from "express";
+import { randomUUID } from "node:crypto";
+import { pinoHttp } from "pino-http";
 
 import { dispatchControllerFactory } from "./dispatch/controller.js";
 import { getConfig } from "./utils/config.js";
@@ -31,6 +33,15 @@ interface BootstrapResult {
 }
 
 const logger = getLogger("bootstrap");
+const loggerMiddleware = pinoHttp({
+	logger: getLogger("http"),
+	genReqId: (_, res) => {
+		const id = randomUUID();
+		res.setHeader("x-request-id", id);
+
+		return id;
+	},
+});
 
 // Main entrypoint to the application, where all the startup logic is defined.
 // This function is immediately invoked when the file is imported.
@@ -84,6 +95,9 @@ export const bootstrap = (async (): Promise<BootstrapResult> => {
 		});
 	});
 
+	// Mount the logger middleware.
+	app.use(loggerMiddleware);
+
 	// Mount the router on the base path.
 	// By default, the router is mounted on "/".
 	app.use(config.BASE_PATH, baseRouter);

src/dispatch/controller.ts

@@ -3,13 +3,11 @@ import { z } from "zod";
 import { sendWorkflowDispatch } from "./github.js";
 import { decodeIdToken, getJwtVerifier } from "./id-token.js";
 import { evaluatePolicyForRequest, getPolicy } from "./policy.js";
-import { getLogger } from "../utils/logger.js";
+import { getLoggerForRequest } from "../utils/logger.js";
 
 import type { IdTokenClaims } from "./id-token.js";
 import type { PolicyInput } from "./policy.js";
-import type { RequestHandler, Request } from "express";
-
-const _logger = getLogger("handler/controller");
+import type { Request, RequestHandler } from "express";
 
 const bodySchema = z.object({
 	target: z.object({
@@ -75,14 +73,15 @@ export const dispatchControllerFactory: () => Promise<RequestHandler> =
 		const policy = await getPolicy();
 
 		return async (req, res) => {
-			_logger.debug({ req }, "Processing request");
+			const _reqLogger = getLoggerForRequest(req);
+			_reqLogger.debug({ req }, "Processing request");
 
 			// Validate the ID token.
 			let idToken;
 			try {
 				const idTokenValue = await extractIdToken(req);
 				if (!idTokenValue) {
-					_logger.warn("Missing ID token");
+					_reqLogger.warn("Missing ID token");
 					return res
 						.status(401)
 						.header("content-type", responseContentType)
@@ -91,7 +90,7 @@ export const dispatchControllerFactory: () => Promise<RequestHandler> =
 
 				idToken = await decodeIdToken(jwtVerifier, idTokenValue);
 			} catch (e) {
-				_logger.warn({ error: e }, "Failed to decode ID token");
+				_reqLogger.warn({ error: e }, "Failed to decode ID token");
 				return res
 					.status(400)
 					.header("content-type", responseContentType)
@@ -126,7 +125,7 @@ export const dispatchControllerFactory: () => Promise<RequestHandler> =
 						.json({ error: "Request blocked by policy" });
 				}
 			} catch (e) {
-				_logger.warn({ error: e }, "Failed to evaluate policy");
+				_reqLogger.warn({ error: e }, "Failed to evaluate policy");
 				return res
 					.status(401)
 					.header("content-type", responseContentType)
@@ -140,14 +139,14 @@ export const dispatchControllerFactory: () => Promise<RequestHandler> =
 					inputs: body.inputs,
 				});
 			} catch (e) {
-				_logger.warn({ error: e }, "Failed to send workflow dispatch");
+				_reqLogger.warn({ error: e }, "Failed to send workflow dispatch");
 				return res
 					.status(500)
 					.header("content-type", responseContentType)
 					.json({ error: "Failed to send workflow dispatch" });
 			}
 
-			_logger.info(policyInput, "Workflow dispatch created");
+			_reqLogger.info(policyInput, "Workflow dispatch created");
 
 			return res.status(200).json({
 				message: "workflow dispatch created",

src/utils/logger.ts

@@ -1,10 +1,15 @@
 import { pino } from "pino";
 
+import type { Request } from "express";
 import type { Logger } from "pino";
 
 const _logger = pino({
 	level: process.env.APP_LOG_LEVEL || "info",
-	redact: ["config.GH_AUTH_APP_PRIVATE_KEY", "config.GH_AUTH_TOKEN"],
+	redact: [
+		"config.GH_AUTH_APP_PRIVATE_KEY",
+		"config.GH_AUTH_TOKEN",
+		"req.headers.authorization",
+	],
 });
 
 /**
@@ -19,3 +24,17 @@ export const getLogger = (module?: string): Logger => {
 
 	return _logger.child({ module });
 };
+
+/**
+ * Provides the logger for the given request.
+ *
+ * @param req The request to get the logger for.
+ */
+export const getLoggerForRequest = (req: Request): Logger => {
+	const logInterface = (req as any).log as pino.Logger;
+	if (!logInterface) {
+		throw new Error("Request does not have a logger");
+	}
+
+	return logInterface;
+};

yarn.lock

@@ -3846,6 +3846,7 @@ __metadata:
     octokit: "npm:^4.0.2"
     openid-client: "npm:^5.7.0"
     pino: "npm:^9.4.0"
+    pino-http: "npm:^10.3.0"
     pino-pretty: "npm:^11.2.2"
     prettier: "npm:^3.3.3"
     sort-package-json: "npm:^2.10.1"
@@ -5672,6 +5673,18 @@ __metadata:
   languageName: node
   linkType: hard
 
+"pino-http@npm:^10.3.0":
+  version: 10.3.0
+  resolution: "pino-http@npm:10.3.0"
+  dependencies:
+    get-caller-file: "npm:^2.0.5"
+    pino: "npm:^9.0.0"
+    pino-std-serializers: "npm:^7.0.0"
+    process-warning: "npm:^4.0.0"
+  checksum: 10/495e7d4ea66ab47a3dc951def40eaf36c7f67555a590e6abd6a6f65152ad98a1fe74442d70f3ce8fefca53b455861d6ac7a8f918c56075bbbefa47b63d99394e
+  languageName: node
+  linkType: hard
+
 "pino-pretty@npm:^11.2.2":
   version: 11.2.2
   resolution: "pino-pretty@npm:11.2.2"
@@ -5703,7 +5716,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"pino@npm:^9.4.0":
+"pino@npm:^9.0.0, pino@npm:^9.4.0":
   version: 9.4.0
   resolution: "pino@npm:9.4.0"
   dependencies: