fix(logger): contextual logs (#2019)

src/hooks.server.ts

@@ -1,5 +1,11 @@
 import { config, ready } from "$lib/server/config";
-import type { Handle, HandleServerError, ServerInit, HandleFetch } from "@sveltejs/kit";
+import type {
+	Handle,
+	HandleServerError,
+	ServerInit,
+	HandleFetch,
+	RequestEvent,
+} from "@sveltejs/kit";
 import { collections } from "$lib/server/database";
 import { base } from "$app/paths";
 import {
@@ -20,6 +26,15 @@ import { adminTokenManager } from "$lib/server/adminToken";
 import { isHostLocalhost } from "$lib/server/isURLLocal";
 import { MetricsServer } from "$lib/server/metrics";
 import { loadMcpServersOnStartup } from "$lib/server/mcp/registry";
+import { runWithRequestContext, updateRequestContext } from "$lib/server/requestContext";
+
+function getClientAddressSafe(event: RequestEvent): string | undefined {
+	try {
+		return event.getClientAddress();
+	} catch {
+		return undefined;
+	}
+}
 
 export const init: ServerInit = async () => {
 	// Wait for config to be fully loaded
@@ -100,194 +115,214 @@ export const handleError: HandleServerError = async ({ error, event, status, mes
 };
 
 export const handle: Handle = async ({ event, resolve }) => {
-	await ready.then(() => {
-		config.checkForUpdates();
-	});
+	// Generate a unique request ID for this request
+	const requestId = crypto.randomUUID();
+
+	// Run the entire request handling within the request context
+	return runWithRequestContext(
+		async () => {
+			await ready.then(() => {
+				config.checkForUpdates();
+			});
+
+			logger.debug(
+				{
+					locals: event.locals,
+					url: event.url.pathname,
+					params: event.params,
+					request: event.request,
+				},
+				"Request received"
+			);
 
-	logger.debug({
-		locals: event.locals,
-		url: event.url.pathname,
-		params: event.params,
-		request: event.request,
-	});
+			function errorResponse(status: number, message: string) {
+				const sendJson =
+					event.request.headers.get("accept")?.includes("application/json") ||
+					event.request.headers.get("content-type")?.includes("application/json");
+				return new Response(sendJson ? JSON.stringify({ error: message }) : message, {
+					status,
+					headers: {
+						"content-type": sendJson ? "application/json" : "text/plain",
+					},
+				});
+			}
 
-	function errorResponse(status: number, message: string) {
-		const sendJson =
-			event.request.headers.get("accept")?.includes("application/json") ||
-			event.request.headers.get("content-type")?.includes("application/json");
-		return new Response(sendJson ? JSON.stringify({ error: message }) : message, {
-			status,
-			headers: {
-				"content-type": sendJson ? "application/json" : "text/plain",
-			},
-		});
-	}
+			if (
+				event.url.pathname.startsWith(`${base}/admin/`) ||
+				event.url.pathname === `${base}/admin`
+			) {
+				const ADMIN_SECRET = config.ADMIN_API_SECRET || config.PARQUET_EXPORT_SECRET;
 
-	if (event.url.pathname.startsWith(`${base}/admin/`) || event.url.pathname === `${base}/admin`) {
-		const ADMIN_SECRET = config.ADMIN_API_SECRET || config.PARQUET_EXPORT_SECRET;
+				if (!ADMIN_SECRET) {
+					return errorResponse(500, "Admin API is not configured");
+				}
 
-		if (!ADMIN_SECRET) {
-			return errorResponse(500, "Admin API is not configured");
-		}
+				if (event.request.headers.get("Authorization") !== `Bearer ${ADMIN_SECRET}`) {
+					return errorResponse(401, "Unauthorized");
+				}
+			}
 
-		if (event.request.headers.get("Authorization") !== `Bearer ${ADMIN_SECRET}`) {
-			return errorResponse(401, "Unauthorized");
-		}
-	}
+			const auth = await authenticateRequest(
+				{ type: "svelte", value: event.request.headers },
+				{ type: "svelte", value: event.cookies },
+				event.url
+			);
 
-	const auth = await authenticateRequest(
-		{ type: "svelte", value: event.request.headers },
-		{ type: "svelte", value: event.cookies },
-		event.url
-	);
+			event.locals.sessionId = auth.sessionId;
+
+			if (loginEnabled && !auth.user && !event.url.pathname.startsWith(`${base}/.well-known/`)) {
+				if (config.AUTOMATIC_LOGIN === "true") {
+					// AUTOMATIC_LOGIN: always redirect to OAuth flow (unless already on login or healthcheck pages)
+					if (
+						!event.url.pathname.startsWith(`${base}/login`) &&
+						!event.url.pathname.startsWith(`${base}/healthcheck`)
+					) {
+						// To get the same CSRF token after callback
+						refreshSessionCookie(event.cookies, auth.secretSessionId);
+						return await triggerOauthFlow(event);
+					}
+				} else {
+					// Redirect to OAuth flow unless on the authorized pages (home, shared conversation, login, healthcheck, model thumbnails)
+					if (
+						event.url.pathname !== `${base}/` &&
+						event.url.pathname !== `${base}` &&
+						!event.url.pathname.startsWith(`${base}/login`) &&
+						!event.url.pathname.startsWith(`${base}/login/callback`) &&
+						!event.url.pathname.startsWith(`${base}/healthcheck`) &&
+						!event.url.pathname.startsWith(`${base}/r/`) &&
+						!event.url.pathname.startsWith(`${base}/conversation/`) &&
+						!event.url.pathname.startsWith(`${base}/models/`) &&
+						!event.url.pathname.startsWith(`${base}/api`)
+					) {
+						refreshSessionCookie(event.cookies, auth.secretSessionId);
+						return triggerOauthFlow(event);
+					}
+				}
+			}
 
-	event.locals.sessionId = auth.sessionId;
+			event.locals.user = auth.user || undefined;
+			event.locals.token = auth.token;
 
-	if (loginEnabled && !auth.user && !event.url.pathname.startsWith(`${base}/.well-known/`)) {
-		if (config.AUTOMATIC_LOGIN === "true") {
-			// AUTOMATIC_LOGIN: always redirect to OAuth flow (unless already on login or healthcheck pages)
-			if (
-				!event.url.pathname.startsWith(`${base}/login`) &&
-				!event.url.pathname.startsWith(`${base}/healthcheck`)
-			) {
-				// To get the same CSRF token after callback
-				refreshSessionCookie(event.cookies, auth.secretSessionId);
-				return await triggerOauthFlow(event);
+			// Update request context with user after authentication
+			if (auth.user?.username) {
+				updateRequestContext({ user: auth.user.username });
 			}
-		} else {
-			// Redirect to OAuth flow unless on the authorized pages (home, shared conversation, login, healthcheck, model thumbnails)
-			if (
-				event.url.pathname !== `${base}/` &&
-				event.url.pathname !== `${base}` &&
-				!event.url.pathname.startsWith(`${base}/login`) &&
-				!event.url.pathname.startsWith(`${base}/login/callback`) &&
-				!event.url.pathname.startsWith(`${base}/healthcheck`) &&
-				!event.url.pathname.startsWith(`${base}/r/`) &&
-				!event.url.pathname.startsWith(`${base}/conversation/`) &&
-				!event.url.pathname.startsWith(`${base}/models/`) &&
-				!event.url.pathname.startsWith(`${base}/api`)
-			) {
-				refreshSessionCookie(event.cookies, auth.secretSessionId);
-				return triggerOauthFlow(event);
-			}
-		}
-	}
 
-	event.locals.user = auth.user || undefined;
-	event.locals.token = auth.token;
+			event.locals.isAdmin =
+				event.locals.user?.isAdmin || adminTokenManager.isAdmin(event.locals.sessionId);
+
+			// CSRF protection
+			const requestContentType = event.request.headers.get("content-type")?.split(";")[0] ?? "";
+			/** https://developer.mozilla.org/en-US/docs/Web/HTML/Element/form#attr-enctype */
+			const nativeFormContentTypes = [
+				"multipart/form-data",
+				"application/x-www-form-urlencoded",
+				"text/plain",
+			];
 
-	event.locals.isAdmin =
-		event.locals.user?.isAdmin || adminTokenManager.isAdmin(event.locals.sessionId);
+			if (event.request.method === "POST") {
+				if (nativeFormContentTypes.includes(requestContentType)) {
+					const origin = event.request.headers.get("origin");
 
-	// CSRF protection
-	const requestContentType = event.request.headers.get("content-type")?.split(";")[0] ?? "";
-	/** https://developer.mozilla.org/en-US/docs/Web/HTML/Element/form#attr-enctype */
-	const nativeFormContentTypes = [
-		"multipart/form-data",
-		"application/x-www-form-urlencoded",
-		"text/plain",
-	];
+					if (!origin) {
+						return errorResponse(403, "Non-JSON form requests need to have an origin");
+					}
 
-	if (event.request.method === "POST") {
-		if (nativeFormContentTypes.includes(requestContentType)) {
-			const origin = event.request.headers.get("origin");
+					const validOrigins = [
+						new URL(event.request.url).host,
+						...(config.PUBLIC_ORIGIN ? [new URL(config.PUBLIC_ORIGIN).host] : []),
+					];
 
-			if (!origin) {
-				return errorResponse(403, "Non-JSON form requests need to have an origin");
+					if (!validOrigins.includes(new URL(origin).host)) {
+						return errorResponse(403, "Invalid referer for POST request");
+					}
+				}
 			}
 
-			const validOrigins = [
-				new URL(event.request.url).host,
-				...(config.PUBLIC_ORIGIN ? [new URL(config.PUBLIC_ORIGIN).host] : []),
-			];
+			if (
+				event.request.method === "POST" ||
+				event.url.pathname.startsWith(`${base}/login`) ||
+				event.url.pathname.startsWith(`${base}/login/callback`)
+			) {
+				// if the request is a POST request or login-related we refresh the cookie
+				refreshSessionCookie(event.cookies, auth.secretSessionId);
 
-			if (!validOrigins.includes(new URL(origin).host)) {
-				return errorResponse(403, "Invalid referer for POST request");
+				await collections.sessions.updateOne(
+					{ sessionId: auth.sessionId },
+					{ $set: { updatedAt: new Date(), expiresAt: addWeeks(new Date(), 2) } }
+				);
 			}
-		}
-	}
-
-	if (
-		event.request.method === "POST" ||
-		event.url.pathname.startsWith(`${base}/login`) ||
-		event.url.pathname.startsWith(`${base}/login/callback`)
-	) {
-		// if the request is a POST request or login-related we refresh the cookie
-		refreshSessionCookie(event.cookies, auth.secretSessionId);
-
-		await collections.sessions.updateOne(
-			{ sessionId: auth.sessionId },
-			{ $set: { updatedAt: new Date(), expiresAt: addWeeks(new Date(), 2) } }
-		);
-	}
 
-	if (
-		loginEnabled &&
-		!event.locals.user &&
-		!event.url.pathname.startsWith(`${base}/login`) &&
-		!event.url.pathname.startsWith(`${base}/admin`) &&
-		!event.url.pathname.startsWith(`${base}/settings`) &&
-		!["GET", "OPTIONS", "HEAD"].includes(event.request.method)
-	) {
-		return errorResponse(401, ERROR_MESSAGES.authOnly);
-	}
+			if (
+				loginEnabled &&
+				!event.locals.user &&
+				!event.url.pathname.startsWith(`${base}/login`) &&
+				!event.url.pathname.startsWith(`${base}/admin`) &&
+				!event.url.pathname.startsWith(`${base}/settings`) &&
+				!["GET", "OPTIONS", "HEAD"].includes(event.request.method)
+			) {
+				return errorResponse(401, ERROR_MESSAGES.authOnly);
+			}
 
-	let replaced = false;
+			let replaced = false;
+
+			const response = await resolve(event, {
+				transformPageChunk: (chunk) => {
+					// For some reason, Sveltekit doesn't let us load env variables from .env in the app.html template
+					if (replaced || !chunk.html.includes("%gaId%")) {
+						return chunk.html;
+					}
+					replaced = true;
+
+					return chunk.html.replace("%gaId%", config.PUBLIC_GOOGLE_ANALYTICS_ID);
+				},
+				filterSerializedResponseHeaders: (header) => {
+					return header.includes("content-type");
+				},
+			});
+
+			// Add CSP header to disallow framing if ALLOW_IFRAME is not "true"
+			if (config.ALLOW_IFRAME !== "true") {
+				response.headers.append("Content-Security-Policy", "frame-ancestors 'none';");
+			}
 
-	const response = await resolve(event, {
-		transformPageChunk: (chunk) => {
-			// For some reason, Sveltekit doesn't let us load env variables from .env in the app.html template
-			if (replaced || !chunk.html.includes("%gaId%")) {
-				return chunk.html;
+			if (
+				event.url.pathname.startsWith(`${base}/login/callback`) ||
+				event.url.pathname.startsWith(`${base}/login`)
+			) {
+				response.headers.append("Cache-Control", "no-store");
 			}
-			replaced = true;
 
-			return chunk.html.replace("%gaId%", config.PUBLIC_GOOGLE_ANALYTICS_ID);
-		},
-		filterSerializedResponseHeaders: (header) => {
-			return header.includes("content-type");
+			if (event.url.pathname.startsWith(`${base}/api/`)) {
+				// get origin from the request
+				const requestOrigin = event.request.headers.get("origin");
+
+				// get origin from the config if its defined
+				let allowedOrigin = config.PUBLIC_ORIGIN ? new URL(config.PUBLIC_ORIGIN).origin : undefined;
+
+				if (
+					dev || // if we're in dev mode
+					!requestOrigin || // or the origin is null (SSR)
+					isHostLocalhost(new URL(requestOrigin).hostname) // or the origin is localhost
+				) {
+					allowedOrigin = "*"; // allow all origins
+				} else if (allowedOrigin === requestOrigin) {
+					allowedOrigin = requestOrigin; // echo back the caller
+				}
+
+				if (allowedOrigin) {
+					response.headers.set("Access-Control-Allow-Origin", allowedOrigin);
+					response.headers.set(
+						"Access-Control-Allow-Methods",
+						"GET, POST, PUT, PATCH, DELETE, OPTIONS"
+					);
+					response.headers.set("Access-Control-Allow-Headers", "Content-Type, Authorization");
+				}
+			}
+			return response;
 		},
-	});
-
-	// Add CSP header to disallow framing if ALLOW_IFRAME is not "true"
-	if (config.ALLOW_IFRAME !== "true") {
-		response.headers.append("Content-Security-Policy", "frame-ancestors 'none';");
-	}
-
-	if (
-		event.url.pathname.startsWith(`${base}/login/callback`) ||
-		event.url.pathname.startsWith(`${base}/login`)
-	) {
-		response.headers.append("Cache-Control", "no-store");
-	}
-
-	if (event.url.pathname.startsWith(`${base}/api/`)) {
-		// get origin from the request
-		const requestOrigin = event.request.headers.get("origin");
-
-		// get origin from the config if its defined
-		let allowedOrigin = config.PUBLIC_ORIGIN ? new URL(config.PUBLIC_ORIGIN).origin : undefined;
-
-		if (
-			dev || // if we're in dev mode
-			!requestOrigin || // or the origin is null (SSR)
-			isHostLocalhost(new URL(requestOrigin).hostname) // or the origin is localhost
-		) {
-			allowedOrigin = "*"; // allow all origins
-		} else if (allowedOrigin === requestOrigin) {
-			allowedOrigin = requestOrigin; // echo back the caller
-		}
-
-		if (allowedOrigin) {
-			response.headers.set("Access-Control-Allow-Origin", allowedOrigin);
-			response.headers.set(
-				"Access-Control-Allow-Methods",
-				"GET, POST, PUT, PATCH, DELETE, OPTIONS"
-			);
-			response.headers.set("Access-Control-Allow-Headers", "Content-Type, Authorization");
-		}
-	}
-	return response;
+		{ requestId, url: event.url.pathname, ip: getClientAddressSafe(event) }
+	);
 };
 
 export const handleFetch: HandleFetch = async ({ event, request, fetch }) => {

src/lib/server/logger.ts

@@ -1,6 +1,7 @@
 import pino from "pino";
 import { dev } from "$app/environment";
 import { config } from "$lib/server/config";
+import { getRequestContext } from "$lib/server/requestContext";
 
 let options: pino.LoggerOptions = {};
 
@@ -15,7 +16,7 @@ if (dev) {
 	};
 }
 
-export const logger = pino({
+const baseLogger = pino({
 	...options,
 	messageKey: "message",
 	level: config.LOG_LEVEL || "info",
@@ -24,4 +25,17 @@ export const logger = pino({
 			return { level: label };
 		},
 	},
+	mixin() {
+		const ctx = getRequestContext();
+		if (!ctx) return {};
+
+		const result: Record<string, string> = {};
+		if (ctx.requestId) result.requestId = ctx.requestId;
+		if (ctx.url) result.url = ctx.url;
+		if (ctx.ip) result.ip = ctx.ip;
+		if (ctx.user) result.user = ctx.user;
+		return result;
+	},
 });
+
+export const logger = baseLogger;

src/lib/server/requestContext.ts

@@ -0,0 +1,53 @@
+import { AsyncLocalStorage } from "node:async_hooks";
+import { randomUUID } from "node:crypto";
+
+export interface RequestContext {
+	requestId: string;
+	url?: string;
+	ip?: string;
+	user?: string;
+}
+
+const asyncLocalStorage = new AsyncLocalStorage<RequestContext>();
+
+/**
+ * Run a function within a request context.
+ * All logs within this context will automatically include the requestId.
+ */
+export function runWithRequestContext<T>(
+	fn: () => T,
+	context: Partial<RequestContext> & { requestId?: string } = {}
+): T {
+	const fullContext: RequestContext = {
+		requestId: context.requestId ?? randomUUID(),
+		url: context.url,
+		ip: context.ip,
+		user: context.user,
+	};
+	return asyncLocalStorage.run(fullContext, fn);
+}
+
+/**
+ * Update the current request context with additional information.
+ * Useful for adding user information after authentication.
+ */
+export function updateRequestContext(updates: Partial<Omit<RequestContext, "requestId">>): void {
+	const store = asyncLocalStorage.getStore();
+	if (store) {
+		Object.assign(store, updates);
+	}
+}
+
+/**
+ * Get the current request context, if any.
+ */
+export function getRequestContext(): RequestContext | undefined {
+	return asyncLocalStorage.getStore();
+}
+
+/**
+ * Get the current request ID, or undefined if not in a request context.
+ */
+export function getRequestId(): string | undefined {
+	return asyncLocalStorage.getStore()?.requestId;
+}