fix(provider,api-express-router,logger): stop request-logger context bleed and log every endpoint's envelope (#2820)

Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

Author: forgetso

.changeset/request-logger-context-bleed.md

@@ -0,0 +1,42 @@
+---
+"@prosopo/logger": patch
+"@prosopo/api-express-router": patch
+"@prosopo/provider": patch
+---
+
+Fix request-scoped logger fields leaking across concurrent captcha requests, and give every endpoint a proper request/response envelope in OpenObserve.
+
+Three interlocking changes:
+
+- **`Tasks.setLogger` no longer mutates `db.logger`.** `env.getDb()` returns a
+  process-wide singleton; overwriting `db.logger` on every request meant two
+  concurrent captcha submits raced, and whichever request landed second
+  stamped its `user`/`siteKey`/`sessionId` bindings onto the *other* request's
+  DB-level log lines. In practice you'd see a `PuzzleCaptcha record updated
+  successfully` for user A's challenge tagged with user B's account and site
+  key, breaking log-based forensics. `setLogger` still updates the per-request
+  Tasks instance and its per-request manager instances (those are safe —
+  they're constructed inside the Tasks constructor) but stops mutating the
+  shared DB. Callers in `getPoWCaptchaChallenge` and `getPuzzleCaptchaChallenge`
+  now pass `req.logger` directly into `new Tasks(env, req.logger)` and drop
+  the redundant `.setLogger(req.logger)` call that followed.
+
+- **`requestLoggerMiddleware` now emits `Request received` and `Response sent`
+  envelope lines on every route** (with `method`, `path`, `status`,
+  `durationMs`, and the request id). Previously only `/frictionless` had a
+  `res.on('finish', ...)` block, so `getPow/PuzzleCaptchaChallenge`,
+  `submitPow/PuzzleCaptchaSolution`, `verify.ts` etc. produced no envelope in
+  OO — a challenge issued by one endpoint and verified by another shared
+  nothing you could group on. Health-probe paths (`/healthz`, `/health`,
+  `/readyz`) are excluded so they don't drown the stream. The middleware
+  also now mirrors `x-request-id` back on the outbound response so callers
+  downstream of the Node process can correlate without depending on Caddy.
+
+- **`requestId` (set on the request logger via `.with({requestId})`) is
+  promoted to a top-level `req_id` field on the emitted JSON log record.**
+  OpenObserve indexes top-level fields as their own columns, so
+  `WHERE req_id = '…'` is now cheap; previously the id only lived inside
+  `data.requestId`, which flattened to `data_requestid` in OO's ingestion
+  and had no top-level column. `data.requestId` is preserved for backwards
+  compatibility with existing dashboards. Two new unit tests in
+  `@prosopo/logger` cover the promotion and the "absent when unset" case.

packages/api-express-router/src/middlewares/requestLoggerMiddleware.ts

@@ -27,13 +27,18 @@ const getHeaderValue = (
 	return undefined;
 };
 
+const HEALTH_CHECK_PATHS = new Set(["/healthz", "/health", "/readyz"]);
+
 export function requestLoggerMiddleware(env: ProviderEnvironment) {
 	return (req: Request, res: Response, next: NextFunction) => {
+		// Honour an inbound `x-request-id` (Caddy/upstream proxy assigns one and
+		// we want the same value to link Caddy access logs to Node app logs).
+		// Fall back to `e-<uuid>` when the upstream didn't set one.
 		const requestId =
-			(req.headers["x-request-id"] as string) || `e-${uuidv4()}`; // use prefix to differentiate from other IDs
+			(req.headers["x-request-id"] as string) || `e-${uuidv4()}`;
 		const user = getHeaderValue(req, "prosopo-user");
 		const siteKey = getHeaderValue(req, "prosopo-site-key");
-		const sessionId = req.body?.sessionId ? req.body.sessionId : null;
+		const sessionId = req.body?.sessionId ? req.body.sessionId : undefined;
 
 		const logger = getLogger(
 			parseLogLevel(env.config.logLevel),
@@ -45,11 +50,55 @@ export function requestLoggerMiddleware(env: ProviderEnvironment) {
 			...(sessionId ? { sessionId } : {}),
 		});
 
-		// Attach logger to the request
 		req.logger = logger;
 		req.requestId = requestId;
 
-		// Continue to next middleware
+		// Mirror the requestId back to the client so downstream systems can
+		// correlate their own logs to ours.
+		res.setHeader("x-request-id", requestId);
+
+		// Skip request/response envelope logging for high-volume health probes
+		// so they don't drown out useful captcha-endpoint entries.
+		if (HEALTH_CHECK_PATHS.has(req.path)) {
+			next();
+			return;
+		}
+
+		// Emit a single request-received line so every endpoint has an entry
+		// log in OpenObserve even when the handler itself doesn't log. Kept at
+		// info level; drop to debug if the volume becomes a problem.
+		const startNs = process.hrtime.bigint();
+		logger.info(() => ({
+			msg: "Request received",
+			data: {
+				method: req.method,
+				path: req.path,
+			},
+		}));
+
+		// Log a response-finished line. `finish` fires when the response was
+		// sent successfully; `close` fires when the client disconnects before
+		// the response was fully sent. Guard against both firing (once() would
+		// only cover a single event source).
+		let finished = false;
+		const emitFinish = (outcome: "finish" | "close") => {
+			if (finished) return;
+			finished = true;
+			const durationMs = Number(process.hrtime.bigint() - startNs) / 1e6;
+			logger.info(() => ({
+				msg: "Response sent",
+				data: {
+					method: req.method,
+					path: req.path,
+					status: res.statusCode,
+					durationMs,
+					outcome,
+				},
+			}));
+		};
+		res.on("finish", () => emitFinish("finish"));
+		res.on("close", () => emitFinish("close"));
+
 		next();
 	};
 }

packages/logger/src/logger.ts

@@ -348,15 +348,30 @@ export class NativeLogger implements Logger {
 		if (this.defaultData) {
 			data = { ...this.defaultData, ...data };
 		}
+		// Promote `requestId` (set via `.with({requestId})` in the request
+		// logger middleware) to a top-level `req_id` on the emitted record.
+		// OpenObserve indexes top-level fields as their own columns, so this
+		// makes `WHERE req_id = '…'` cheap and lets us correlate to Caddy's
+		// `X-Request-ID` without a schema alias per stream. Keep the copy in
+		// `data.requestId` for backwards compat with existing dashboards.
+		const dataMaybeRequestId = data as { requestId?: unknown } | undefined;
+		const reqId =
+			dataMaybeRequestId && typeof dataMaybeRequestId.requestId === "string"
+				? dataMaybeRequestId.requestId
+				: undefined;
 		const baseRecord: {
 			scope: string;
 			ts: string;
 			level: LogLevel;
+			req_id?: string;
 			data?: LogObject;
 			msg?: string;
 			err?: string;
 			errData?: Record<string, unknown>;
 		} = { scope: this.scope, ts, level };
+		if (reqId) {
+			baseRecord.req_id = reqId;
+		}
 		if (data) {
 			baseRecord.data = data;
 		}

packages/logger/src/tests/logger.unit.test.ts

@@ -397,4 +397,45 @@ describe("Logger.with subscope", () => {
 			setGlobalDirectives(process.env.PROSOPO_LOG_LEVEL ?? "");
 		}
 	});
+
+	it("promotes requestId from default data to a top-level req_id field", () => {
+		setGlobalDirectives("trace");
+		const logger = getLogger("info", "test").with({ requestId: "abc-123" });
+		const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {});
+		try {
+			logger.info(() => ({ msg: "hello" }));
+			expect(infoSpy).toHaveBeenCalledTimes(1);
+			const output = infoSpy.mock.calls[0]?.[0];
+			const record: {
+				req_id?: string;
+				data?: { requestId?: string };
+			} = JSON.parse(output as string);
+			expect(record.req_id).toBe("abc-123");
+			// Backwards compat: still available inside `data` for existing dashboards.
+			expect(record.data?.requestId).toBe("abc-123");
+		} finally {
+			infoSpy.mockRestore();
+			setGlobalDirectives(process.env.PROSOPO_LOG_LEVEL ?? "");
+		}
+	});
+
+	it("omits req_id when the log record has no requestId in scope", () => {
+		setGlobalDirectives("trace");
+		const logger = getLogger("info", "test");
+		const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {});
+		try {
+			logger.info(() => ({ msg: "hello", data: { foo: "bar" } }));
+			expect(infoSpy).toHaveBeenCalledTimes(1);
+			const output = infoSpy.mock.calls[0]?.[0];
+			const record: {
+				req_id?: string;
+				data?: Record<string, unknown>;
+			} = JSON.parse(output as string);
+			expect(record.req_id).toBeUndefined();
+			expect(record.data).toEqual({ foo: "bar" });
+		} finally {
+			infoSpy.mockRestore();
+			setGlobalDirectives(process.env.PROSOPO_LOG_LEVEL ?? "");
+		}
+	});
 });

packages/provider/src/api/captcha/getPoWCaptchaChallenge.ts

@@ -73,8 +73,7 @@ export default (
 			return res.json(buildPowMaintenanceResponse(user, dapp));
 		}
 
-		const tasks = new Tasks(env);
-		tasks.setLogger(req.logger);
+		const tasks = new Tasks(env, req.logger);
 
 		try {
 			const clientSettings = await tasks.db.getClientRecord(dapp);

packages/provider/src/api/captcha/getPuzzleCaptchaChallenge.ts

@@ -74,7 +74,6 @@ export default (
 		}
 
 		const tasks = new Tasks(env, req.logger);
-		tasks.setLogger(req.logger);
 
 		try {
 			const clientSettings = await tasks.db.getClientRecord(dapp);

packages/provider/src/tasks/tasks.ts

@@ -213,14 +213,22 @@ export class Tasks {
 	}
 
 	setLogger(logger: Logger): void {
-		// Use a logger from the request
+		// Use a logger from the request.
+		//
+		// The Tasks instance and its managers are constructed per-request, so
+		// overwriting their `.logger` refs is safe. `this.db`, however, is a
+		// process-wide singleton from `env.getDb()` — mutating `db.logger` here
+		// races between concurrent requests and stamps the wrong user/siteKey/
+		// sessionId onto log lines emitted from inside DB methods. If a DB
+		// method needs request context in its log output, wrap the call in the
+		// caller (which already has the per-request logger via `this.logger`)
+		// or thread the logger through as an explicit argument.
 		this.logger = logger;
 		this.powCaptchaManager.logger = logger;
 		this.puzzleCaptchaManager.logger = logger;
 		this.datasetManager.logger = logger;
 		this.imgCaptchaManager.logger = logger;
 		this.clientTaskManager.logger = logger;
 		this.frictionlessManager.logger = logger;
-		this.db.logger = logger; // Ensure the database also uses the new logger
 	}
 }