Merge pull request #443 from Dayz-tech-co/feat/238-request-logger

feat(server): add request logging middleware

Author: Anuoluwapo25

server/src/index.ts

@@ -15,6 +15,7 @@ import { initDb } from "./db/index"
 import { createNonceStore } from "./db/nonce-store"
 import { errorHandler } from "./middleware/error.middleware"
 import { globalLimiter } from "./middleware/rate-limit.middleware"
+import { requestLogger } from "./middleware/request-logger.middleware"
 import { buildOpenApiSpec } from "./openapi"
 import { adminMilestonesRouter } from "./routes/admin-milestones.routes"
 import { adminRouter } from "./routes/admin.routes"
@@ -93,8 +94,11 @@ if (!jwtPrivateKey || !jwtPublicKey) {
 	jwtPublicKey = ephemeral.publicKeyPem
 }
 
-process.env.JWT_PRIVATE_KEY = jwtPrivateKey
-process.env.JWT_PUBLIC_KEY = jwtPublicKey
+if (!jwtPrivateKey || !jwtPublicKey) {
+	throw new Error(
+		"JWT_PRIVATE_KEY and JWT_PUBLIC_KEY must be configured to start the server",
+	)
+}
 
 const nonceStore = createNonceStore(env.REDIS_URL)
 const jwtService = createJwtService(jwtPrivateKey, jwtPublicKey)
@@ -105,7 +109,7 @@ const openApiSpec = buildOpenApiSpec()
 const openApiYaml = YAML.stringify(openApiSpec)
 
 app.set("trust proxy", 1)
-app.use(morgan("dev"))
+app.use(requestLogger)
 app.use(
 	cors({
 		origin: (origin, callback) => {

server/src/middleware/request-logger.middleware.ts

@@ -0,0 +1,64 @@
+import { randomUUID } from "crypto"
+import type { NextFunction, Request, Response } from "express"
+
+type LogPayload = {
+	requestId: string
+	method: string
+	path: string
+	statusCode: number
+	durationMs: number
+}
+
+type Logger = {
+	info: (payload: LogPayload) => void
+}
+
+type RequestLoggerOptions = {
+	logger?: Logger
+	enabled?: boolean
+}
+
+const jsonLogger: Logger = {
+	info(payload) {
+		process.stdout.write(`${JSON.stringify(payload)}\n`)
+	},
+}
+
+export function createRequestLogger(
+	options: RequestLoggerOptions = {},
+) {
+	const enabled = options.enabled ?? process.env.NODE_ENV !== "test"
+	const logger = options.logger ?? jsonLogger
+
+	return function requestLogger(
+		req: Request,
+		res: Response,
+		next: NextFunction,
+	) {
+		const requestId = randomUUID()
+		const startedAt = process.hrtime.bigint()
+
+		req.requestId = requestId
+		res.setHeader("X-Request-Id", requestId)
+
+		res.on("finish", () => {
+			if (!enabled) {
+				return
+			}
+
+			const durationMs = Number(process.hrtime.bigint() - startedAt) / 1_000_000
+
+			logger.info({
+				requestId,
+				method: req.method,
+				path: req.originalUrl || req.path,
+				statusCode: res.statusCode,
+				durationMs: Number(durationMs.toFixed(3)),
+			})
+		})
+
+		next()
+	}
+}
+
+export const requestLogger = createRequestLogger()

server/src/tests/request-logger.middleware.test.ts

@@ -0,0 +1,70 @@
+import express from "express"
+import request from "supertest"
+
+import {
+	createRequestLogger,
+} from "../middleware/request-logger.middleware"
+
+describe("requestLogger middleware", () => {
+	it("attaches a request id header to every response", async () => {
+		const app = express()
+
+		app.use(createRequestLogger({ enabled: false }))
+		app.get("/api/ping", (req, res) => {
+			res.json({ requestId: req.requestId })
+		})
+
+		const response = await request(app).get("/api/ping?source=test")
+
+		expect(response.status).toBe(200)
+		expect(response.headers["x-request-id"]).toMatch(
+			/^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i,
+		)
+		expect(response.body.requestId).toBe(response.headers["x-request-id"])
+	})
+
+	it("logs structured request data on response finish", async () => {
+		const info = jest.fn()
+		const app = express()
+
+		app.use(createRequestLogger({ enabled: true, logger: { info } }))
+		app.get("/api/users", (_req, res) => {
+			res.status(201).json({ ok: true })
+		})
+
+		const response = await request(app).get("/api/users?page=1")
+
+		expect(response.status).toBe(201)
+		expect(info).toHaveBeenCalledTimes(1)
+		expect(info).toHaveBeenCalledWith(
+			expect.objectContaining({
+				requestId: response.headers["x-request-id"],
+				method: "GET",
+				path: "/api/users?page=1",
+				statusCode: 201,
+				durationMs: expect.any(Number),
+			}),
+		)
+	})
+
+	it("stays silent in the test environment by default", async () => {
+		const previousNodeEnv = process.env.NODE_ENV
+		process.env.NODE_ENV = "test"
+
+		const info = jest.fn()
+		const app = express()
+
+		app.use(createRequestLogger({ logger: { info } }))
+		app.get("/api/quiet", (_req, res) => {
+			res.sendStatus(204)
+		})
+
+		const response = await request(app).get("/api/quiet")
+
+		expect(response.status).toBe(204)
+		expect(response.headers["x-request-id"]).toBeTruthy()
+		expect(info).not.toHaveBeenCalled()
+
+		process.env.NODE_ENV = previousNodeEnv
+	})
+})

server/src/types/express.d.ts

@@ -1,6 +1,8 @@
 declare global {
 	namespace Express {
 		interface Request {
+			/** Correlation ID attached to each request */
+			requestId?: string
 			/** Stellar public key (G...) after JWT verification */
 			walletAddress?: string
 		}