feat(devops): diagnose slow HK requests and dependency timings

src/lib/api-handler-correlation.test.ts

@@ -6,6 +6,7 @@ const state = vi.hoisted(() => ({
 	authorized: true,
 	permitted: true,
 	csrf: true,
+	record: vi.fn(),
 }));
 vi.mock("@/lib/admin/authorization-events", () => ({
 	logAuthorizationEvent: vi.fn(),
@@ -20,6 +21,7 @@ vi.mock("@/lib/permissions", () => ({
 			: null,
 	canAccess: () => state.permitted,
 }));
+vi.mock("@/lib/performance-store", () => ({ recordPerformance: state.record }));
 vi.mock("@/lib/server-log", () => ({
 	logServerError: () => "error-reference",
 }));
@@ -40,6 +42,7 @@ describe("admin API correlation", () => {
 		state.authorized = true;
 		state.permitted = true;
 		state.csrf = true;
+		state.record.mockClear();
 	});
 	it("matches the response ID to asynchronous work without trusting a supplied ID", async () => {
 		const handler = withAdmin({ permission: "users.view" }, async () => {
@@ -108,6 +111,9 @@ describe("admin API correlation", () => {
 		controller?.enqueue(new TextEncoder().encode("data: last\n\n"));
 		controller?.close();
 		expect(await body).toBe("data: first\n\ndata: last\n\n");
+		expect(state.record).toHaveBeenCalledWith(
+			expect.objectContaining({ streaming: true }),
+		);
 	});
 	it("adds correlation to authentication, permission and handler failures", async () => {
 		const handler = withAdmin({ permission: "users.view" }, () => {
@@ -116,6 +122,7 @@ describe("admin API correlation", () => {
 		state.authorized = false;
 		const unauthorized = await handler(request());
 		expect(unauthorized.status).toBe(401);
+		expect(state.record).not.toHaveBeenCalled();
 		expect(unauthorized.headers.get("x-operation-id")).toBeTruthy();
 		state.authorized = true;
 		state.permitted = false;

src/lib/api-handler.ts

@@ -7,6 +7,11 @@ import {
 } from "@/lib/foundation/request-context";
 import { validateCsrfToken } from "@/lib/foundation/security";
 import type { IpAddress, UserId } from "@/lib/foundation/types";
+import {
+	collectPerformance,
+	routeTemplate,
+} from "@/lib/performance-diagnostics";
+import { recordPerformance } from "@/lib/performance-store";
 import { canAccess, getApiAdminContext } from "@/lib/permissions";
 import { logServerError } from "@/lib/server-log";
 
@@ -37,110 +42,128 @@ export function withAdmin(
 ) {
 	return async (request: NextRequest, routeContext: RouteContext = {}) => {
 		const store = createStore("unknown" as IpAddress);
-		const response = await runWithStore(store, async () => {
-			// CSRF required for mutating admin APIs unless explicitly opted out.
-			const csrfRequired =
-				options.requireCsrf !== false && MUTATING_METHODS.has(request.method);
-			if (csrfRequired) {
-				const csrfToken =
-					request.headers.get("x-csrf-token") ??
-					request.headers.get("csrf-token") ??
-					"";
-				const valid = await validateCsrfToken(csrfToken);
-				if (!valid) {
+		const { value: response, metrics } = await collectPerformance(() =>
+			runWithStore(store, async () => {
+				// CSRF required for mutating admin APIs unless explicitly opted out.
+				const csrfRequired =
+					options.requireCsrf !== false && MUTATING_METHODS.has(request.method);
+				if (csrfRequired) {
+					const csrfToken =
+						request.headers.get("x-csrf-token") ??
+						request.headers.get("csrf-token") ??
+						"";
+					const valid = await validateCsrfToken(csrfToken);
+					if (!valid) {
+						return NextResponse.json(
+							{ ok: false, error: "Invalid or missing CSRF token" },
+							{ status: 403 },
+						);
+					}
+				}
+
+				if (MUTATING_METHODS.has(request.method)) {
+					const contentLength = request.headers.get("content-length");
+					const maxBytes = options.maxBodyBytes ?? MAX_BODY_BYTES;
+					if (contentLength && Number(contentLength) > maxBytes) {
+						return NextResponse.json(
+							{ ok: false, error: `Request body exceeds ${maxBytes} bytes` },
+							{ status: 413 },
+						);
+					}
+				}
+
+				const context = await getApiAdminContext();
+				if (!context)
 					return NextResponse.json(
-						{ ok: false, error: "Invalid or missing CSRF token" },
+						{ ok: false, error: "Unauthorized" },
+						{ status: 401 },
+					);
+				if (
+					options.permission &&
+					!canAccess(
+						context.permissions,
+						options.permission,
+						context.session.user.rank,
+					)
+				) {
+					await logAuthorizationEvent({
+						kind: "permission.denied",
+						userId: context.session.user.id,
+						username: context.session.user.username,
+						rank: context.session.user.rank,
+						permission: options.permission,
+						source: request.nextUrl.pathname,
+						reason: "API permission check denied",
+					});
+					return NextResponse.json(
+						{ ok: false, error: "Forbidden" },
 						{ status: 403 },
 					);
 				}
-			}
-
-			if (MUTATING_METHODS.has(request.method)) {
-				const contentLength = request.headers.get("content-length");
-				const maxBytes = options.maxBodyBytes ?? MAX_BODY_BYTES;
-				if (contentLength && Number(contentLength) > maxBytes) {
+				setContextUserId(Number(context.session.user.id) as UserId);
+				let finishExport: (() => Promise<void>) | undefined;
+				try {
+					if (
+						catalogExportEnabled() &&
+						isCatalogMutation(request.method, request.nextUrl.pathname)
+					) {
+						finishExport = await beginCatalogExport();
+					}
+					const response = await handler(request, context, routeContext);
+					if (
+						finishExport &&
+						response.body &&
+						response.headers.get("content-type")?.includes("text/event-stream")
+					) {
+						const [client, completion] = response.body.tee();
+						const finish = finishExport;
+						after(async () => {
+							const reader = completion.getReader();
+							try {
+								while (!(await reader.read()).done) {
+									/* Wait for all import results. */
+								}
+							} finally {
+								reader.releaseLock();
+								await finish();
+							}
+						});
+						return new Response(client, {
+							status: response.status,
+							headers: response.headers,
+						});
+					}
+					await finishExport?.();
+					return response;
+				} catch (error) {
+					await finishExport?.().catch(() => undefined);
+					const errorId = logServerError("admin.api_failed", error, {
+						path: request.nextUrl.pathname,
+						userId: context.session.user.id,
+					});
 					return NextResponse.json(
-						{ ok: false, error: `Request body exceeds ${maxBytes} bytes` },
-						{ status: 413 },
+						{ ok: false, error: "Internal server error", errorId },
+						{ status: 500 },
 					);
 				}
-			}
-
-			const context = await getApiAdminContext();
-			if (!context)
-				return NextResponse.json(
-					{ ok: false, error: "Unauthorized" },
-					{ status: 401 },
-				);
-			if (
-				options.permission &&
-				!canAccess(
-					context.permissions,
-					options.permission,
-					context.session.user.rank,
-				)
-			) {
-				await logAuthorizationEvent({
-					kind: "permission.denied",
-					userId: context.session.user.id,
-					username: context.session.user.username,
-					rank: context.session.user.rank,
-					permission: options.permission,
-					source: request.nextUrl.pathname,
-					reason: "API permission check denied",
-				});
-				return NextResponse.json(
-					{ ok: false, error: "Forbidden" },
-					{ status: 403 },
-				);
-			}
-			setContextUserId(Number(context.session.user.id) as UserId);
-			let finishExport: (() => Promise<void>) | undefined;
-			try {
-				if (
-					catalogExportEnabled() &&
-					isCatalogMutation(request.method, request.nextUrl.pathname)
-				) {
-					finishExport = await beginCatalogExport();
-				}
-				const response = await handler(request, context, routeContext);
-				if (
-					finishExport &&
-					response.body &&
-					response.headers.get("content-type")?.includes("text/event-stream")
-				) {
-					const [client, completion] = response.body.tee();
-					const finish = finishExport;
-					after(async () => {
-						const reader = completion.getReader();
-						try {
-							while (!(await reader.read()).done) {
-								/* Wait for all import results. */
-							}
-						} finally {
-							reader.releaseLock();
-							await finish();
-						}
-					});
-					return new Response(client, {
-						status: response.status,
-						headers: response.headers,
-					});
-				}
-				await finishExport?.();
-				return response;
-			} catch (error) {
-				await finishExport?.().catch(() => undefined);
-				const errorId = logServerError("admin.api_failed", error, {
-					path: request.nextUrl.pathname,
-					userId: context.session.user.id,
-				});
-				return NextResponse.json(
-					{ ok: false, error: "Internal server error", errorId },
-					{ status: 500 },
-				);
-			}
-		});
+			}),
+		);
+		if (store.userId !== null) {
+			recordPerformance({
+				operationId: store.requestId,
+				route: routeTemplate(
+					request.nextUrl.pathname,
+					await routeContext.params,
+				),
+				method: request.method,
+				status: response.status,
+				at: Date.now(),
+				metrics,
+				streaming:
+					response.headers.get("content-type")?.includes("text/event-stream") ??
+					false,
+			});
+		}
 		const headers = new Headers(response.headers);
 		headers.set("x-operation-id", store.requestId);
 		return new Response(response.body, {

src/lib/db.ts

@@ -5,6 +5,8 @@ import * as schema from "@/db/schema";
 import { env } from "@/env";
 import { resolveConnectionLimit } from "@/lib/db-pool";
 
+import { instrumentDatabase } from "@/lib/performance-diagnostics";
+
 const fullSchema = { ...schema, ...relations };
 
 const globalForDb = globalThis as unknown as {
@@ -42,7 +44,7 @@ function createDb() {
 		supportBigNumbers: true,
 	});
 
-	return drizzle(pool, {
+	return drizzle(instrumentDatabase(pool), {
 		schema: fullSchema,
 		mode: "default",
 		logger:

src/lib/performance-diagnostics.test.ts

@@ -0,0 +1,87 @@
+import { describe, expect, it } from "vitest";
+import {
+	collectPerformance,
+	instrumentDatabase,
+	measureDependency,
+	routeTemplate,
+} from "./performance-diagnostics";
+
+describe("performance diagnostics", () => {
+	it("isolates concurrent requests and preserves results and errors", async () => {
+		const error = new Error("private SQL parameters");
+		const [a, b] = await Promise.all([
+			collectPerformance(async () => {
+				await measureDependency("database", async () => 42);
+				await expect(
+					measureDependency("external", async () => {
+						throw error;
+					}),
+				).rejects.toBe(error);
+				return "first";
+			}),
+			collectPerformance(async () => "second"),
+		]);
+		expect(a.value).toBe("first");
+		expect(a.metrics.database.count).toBe(1);
+		expect(a.metrics.external.count).toBe(1);
+		expect(a.metrics.external.errors).toBe(1);
+		expect(b.metrics.database.count).toBe(0);
+		expect(JSON.stringify(a.metrics)).not.toContain("private");
+	});
+	it("measures pool and transaction queries without changing receiver or arguments", async () => {
+		const connection = {
+			query: async (sql: string) => sql,
+			release() {
+				return this;
+			},
+		};
+		const original = {
+			marker: 42,
+			async execute(value: number) {
+				return this.marker + value;
+			},
+			async getConnection() {
+				return connection;
+			},
+		};
+		const pool = instrumentDatabase(original);
+		const result = await collectPerformance(async () => {
+			expect(await pool.execute(8)).toBe(50);
+			const conn = await pool.getConnection();
+			expect(await conn.query("secret SQL")).toBe("secret SQL");
+			expect(conn.release()).toBe(connection);
+		});
+		expect(result.metrics.database.count).toBe(2);
+		expect(JSON.stringify(result.metrics)).not.toContain("secret");
+	});
+	it("removes query strings and dynamic path values including encoded catch-all segments", () => {
+		expect(
+			routeTemplate("/api/admin/users/Life?token=private", {
+				username: "Life",
+			}),
+		).toBe("/api/admin/users/[username]");
+		expect(
+			routeTemplate("/api/admin/assets/a%20b/file.png", {
+				path: ["a b", "file.png"],
+			}),
+		).toBe("/api/admin/assets/[path]/[path]");
+	});
+});
+
+it("does not change a completed snapshot when background work finishes", async () => {
+	let finish!: () => void;
+	let background!: Promise<void>;
+	const result = await collectPerformance(async () => {
+		background = measureDependency(
+			"external",
+			() =>
+				new Promise<void>((resolve) => {
+					finish = resolve;
+				}),
+		);
+	});
+	expect(result.metrics.external.count).toBe(0);
+	finish();
+	await background;
+	expect(result.metrics.external.count).toBe(0);
+});

src/lib/performance-diagnostics.ts

@@ -0,0 +1,86 @@
+import { AsyncLocalStorage } from "node:async_hooks";
+
+type Dependency = "database" | "external";
+type Measurement = { count: number; durationMs: number; errors: number };
+export type PerformanceMetrics = Record<Dependency, Measurement> & {
+	durationMs: number;
+};
+const context = new AsyncLocalStorage<PerformanceMetrics>();
+
+export async function collectPerformance<T>(work: () => Promise<T>) {
+	const metrics: PerformanceMetrics = {
+		durationMs: 0,
+		database: { count: 0, durationMs: 0, errors: 0 },
+		external: { count: 0, durationMs: 0, errors: 0 },
+	};
+	const start = performance.now();
+	const value = await context.run(metrics, work);
+	metrics.durationMs = performance.now() - start;
+	// Background work may keep the async context: return a detached snapshot.
+	return { value, metrics: structuredClone(metrics) };
+}
+
+export async function measureDependency<T>(
+	kind: Dependency,
+	work: () => Promise<T>,
+): Promise<T> {
+	const metrics = context.getStore();
+	if (!metrics) return work();
+	const start = performance.now();
+	const measurement = metrics[kind];
+	try {
+		return await work();
+	} catch (error) {
+		measurement.errors++;
+		throw error;
+	} finally {
+		measurement.count++;
+		measurement.durationMs += performance.now() - start;
+	}
+}
+
+/** Promise driver only. Preserve receiver, overloads and connection release behavior. */
+export function instrumentDatabase<T extends object>(driver: T): T {
+	return new Proxy(driver, {
+		get(target, property) {
+			const value = Reflect.get(target, property, target);
+			if (typeof value !== "function") return value;
+			if (property === "query" || property === "execute") {
+				return (...args: unknown[]) =>
+					measureDependency("database", () =>
+						Reflect.apply(value, target, args),
+					);
+			}
+			if (property === "getConnection") {
+				return async (...args: unknown[]) =>
+					instrumentDatabase(await Reflect.apply(value, target, args));
+			}
+			return value.bind(target);
+		},
+	});
+}
+
+export function routeTemplate(
+	pathname: string,
+	params: Record<string, string | string[]> = {},
+) {
+	const dynamic = new Map<string, string>();
+	for (const [key, value] of Object.entries(params)) {
+		for (const part of Array.isArray(value) ? value : [value])
+			dynamic.set(part, `[${key}]`);
+	}
+	return pathname
+		.split("?")[0]
+		.split("/")
+		.map((part) => {
+			let decoded = part;
+			try {
+				decoded = decodeURIComponent(part);
+			} catch {
+				return "[invalid]";
+			}
+			return dynamic.get(decoded) ?? (/^\d+$/.test(part) ? "[id]" : part);
+		})
+		.join("/")
+		.slice(0, 300);
+}

src/lib/performance-store.test.ts

@@ -0,0 +1,70 @@
+import { beforeEach, expect, it, vi } from "vitest";
+
+const mock = vi.hoisted(() => ({
+	status: "ready",
+	exec: vi.fn(),
+	lrange: vi.fn(),
+}));
+vi.mock("@/lib/redis", () => ({
+	redis: {
+		get status() {
+			return mock.status;
+		},
+		multi() {
+			const chain = {
+				lpush: () => chain,
+				ltrim: () => chain,
+				expire: () => chain,
+				exec: mock.exec,
+			};
+			return chain;
+		},
+		lrange: mock.lrange,
+	},
+}));
+
+import { readPerformance, recordPerformance } from "./performance-store";
+
+const sample = {
+	operationId: "op",
+	route: "/api/admin/test",
+	method: "GET",
+	status: 200,
+	at: Date.now(),
+	streaming: false,
+	metrics: {
+		durationMs: 1200,
+		database: { count: 2, durationMs: 1000, errors: 0 },
+		external: { count: 0, durationMs: 0, errors: 0 },
+	},
+};
+beforeEach(() => {
+	mock.status = "ready";
+	mock.exec.mockResolvedValue([]);
+	mock.lrange.mockResolvedValue([]);
+});
+it("does not fail a request when storage rejects writes", async () => {
+	mock.exec.mockRejectedValue(new Error("offline"));
+	expect(() => recordPerformance(sample)).not.toThrow();
+	await Promise.resolve();
+	await Promise.resolve();
+});
+it("falls back to bounded local samples when Redis is unavailable", async () => {
+	mock.status = "end";
+	for (let n = 0; n < 250; n++)
+		recordPerformance({ ...sample, operationId: String(n) });
+	const result = await readPerformance();
+	expect(result.shared).toBe(false);
+	expect(result.samples).toHaveLength(200);
+	expect(result.samples[0].operationId).toBe("249");
+});
+it("ignores expired and malformed shared records", async () => {
+	mock.lrange.mockResolvedValue([
+		"bad",
+		JSON.stringify({ ...sample, at: 1 }),
+		JSON.stringify(sample),
+	]);
+	const result = await readPerformance();
+	expect(result.shared).toBe(true);
+	expect(result.samples).toEqual([sample]);
+});

src/lib/performance-store.ts

@@ -0,0 +1,101 @@
+import { z } from "zod";
+import type { PerformanceMetrics } from "@/lib/performance-diagnostics";
+import { redis } from "@/lib/redis";
+
+const KEY = "cms:performance:v1";
+const LIMIT = 200;
+const RETENTION_MS = 60 * 60 * 1000;
+const measurement = z.object({
+	count: z.number().nonnegative(),
+	durationMs: z.number().nonnegative(),
+	errors: z.number().nonnegative(),
+});
+const schema = z.object({
+	operationId: z.string().max(100),
+	route: z.string().max(300),
+	method: z.string().max(10),
+	status: z.number().int(),
+	at: z.number(),
+	streaming: z.boolean(),
+	metrics: z.object({
+		durationMs: z.number().nonnegative(),
+		database: measurement,
+		external: measurement,
+	}),
+});
+export interface PerformanceSample {
+	operationId: string;
+	route: string;
+	method: string;
+	status: number;
+	at: number;
+	streaming: boolean;
+	metrics: PerformanceMetrics;
+}
+const state = globalThis as typeof globalThis & {
+	cmsPerformance?: { samples: PerformanceSample[]; pending: number };
+};
+const buffer = state.cmsPerformance ?? { samples: [], pending: 0 };
+state.cmsPerformance = buffer;
+
+/** Best effort: no connection wait, no unbounded offline queue, no request failure. */
+export function recordPerformance(sample: PerformanceSample): void {
+	buffer.samples.unshift(sample);
+	buffer.samples.length = Math.min(buffer.samples.length, LIMIT);
+	if (redis?.status !== "ready" || buffer.pending >= 4) return;
+	buffer.pending++;
+	try {
+		void redis
+			.multi()
+			.lpush(KEY, JSON.stringify(sample))
+			.ltrim(KEY, 0, LIMIT - 1)
+			.expire(KEY, 3600)
+			.exec()
+			.catch(() => undefined)
+			.finally(() => {
+				buffer.pending--;
+			});
+	} catch {
+		buffer.pending--;
+	}
+}
+
+export async function readPerformance(): Promise<{
+	samples: PerformanceSample[];
+	shared: boolean;
+}> {
+	const cutoff = Date.now() - RETENTION_MS;
+	if (redis?.status === "ready") {
+		let timer: ReturnType<typeof setTimeout> | undefined;
+		try {
+			const rows = await Promise.race([
+				redis.lrange(KEY, 0, LIMIT - 1),
+				new Promise<never>((_, reject) => {
+					timer = setTimeout(
+						() => reject(new Error("Diagnostic storage timeout")),
+						1000,
+					);
+				}),
+			]);
+			const samples = rows.flatMap((row) => {
+				try {
+					const sample = schema.safeParse(JSON.parse(row));
+					return sample.success && sample.data.at >= cutoff
+						? [sample.data]
+						: [];
+				} catch {
+					return [];
+				}
+			});
+			return { samples, shared: true };
+		} catch {
+			/* Keep local diagnostics available during a Redis outage. */
+		} finally {
+			clearTimeout(timer);
+		}
+	}
+	return {
+		samples: buffer.samples.filter((sample) => sample.at >= cutoff),
+		shared: false,
+	};
+}

src/lib/services/import/core/curl-fetch.ts

@@ -1,6 +1,7 @@
 import { execFile } from "node:child_process";
 import { existsSync, promises as fs } from "node:fs";
 import { promisify } from "node:util";
+import { measureDependency } from "@/lib/performance-diagnostics";
 
 const execFileAsync = promisify(execFile);
 
@@ -46,10 +47,12 @@ export async function curlFetchText(
 	url: string,
 	timeoutMs = 30_000,
 ): Promise<string> {
-	const { stdout } = await execFileAsync(CURL_BIN, curlArgs(url, []), {
-		timeout: timeoutMs,
-		maxBuffer: 512 * 1024 * 1024,
-	});
+	const { stdout } = await measureDependency("external", () =>
+		execFileAsync(CURL_BIN, curlArgs(url, []), {
+			timeout: timeoutMs,
+			maxBuffer: 512 * 1024 * 1024,
+		}),
+	);
 	return stdout;
 }
 
@@ -62,28 +65,30 @@ export async function curlDownload(
 ): Promise<{ ok: boolean; size: number }> {
 	try {
 		const cookieArgs = cookieHeader ? ["-H", `Cookie: ${cookieHeader}`] : [];
-		await execFileAsync(
-			CURL_BIN,
-			[
-				"-sSL",
-				"--compressed",
-				"--fail",
-				"--max-time",
-				"30",
-				"--connect-timeout",
-				"10",
-				"-A",
-				CURL_USER_AGENT,
-				"-H",
-				"Accept: application/octet-stream,*/*;q=0.9",
-				"-H",
-				"Accept-Language: en-US,en;q=0.9",
-				...cookieArgs,
-				"-o",
-				destPath,
-				url,
-			],
-			{ timeout: timeoutMs },
+		await measureDependency("external", () =>
+			execFileAsync(
+				CURL_BIN,
+				[
+					"-sSL",
+					"--compressed",
+					"--fail",
+					"--max-time",
+					"30",
+					"--connect-timeout",
+					"10",
+					"-A",
+					CURL_USER_AGENT,
+					"-H",
+					"Accept: application/octet-stream,*/*;q=0.9",
+					"-H",
+					"Accept-Language: en-US,en;q=0.9",
+					...cookieArgs,
+					"-o",
+					destPath,
+					url,
+				],
+				{ timeout: timeoutMs },
+			),
 		);
 		const stat = await fs.stat(destPath);
 		return { ok: stat.size > 0, size: stat.size };