From 1af0de5e877b27ba6003fc3925f76bae0785debb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Thu, 15 Oct 2026 22:06:39 +0200 Subject: [PATCH] feat(logging): keep warnings and errors in their own ring and find them by error id --- .../admin/app-logs/__tests__/route.test.ts | 34 +++++++++++ src/app/api/admin/app-logs/route.ts | 28 ++++++++- .../admin/app-log-preview-section.tsx | 36 +++++++++++- .../__tests__/in-memory-buffer.test.ts | 37 ++++++++++++ src/lib/logging/in-memory-buffer.ts | 57 ++++++++++++++++--- src/lib/logging/index.ts | 2 + src/lib/query-keys/admin.ts | 5 +- 7 files changed, 186 insertions(+), 13 deletions(-) diff --git a/src/app/api/admin/app-logs/__tests__/route.test.ts b/src/app/api/admin/app-logs/__tests__/route.test.ts index adfff8b0f..b20edbc84 100644 --- a/src/app/api/admin/app-logs/__tests__/route.test.ts +++ b/src/app/api/admin/app-logs/__tests__/route.test.ts @@ -136,4 +136,38 @@ describe("GET /api/admin/app-logs", () => { expect(json.error).toBe("Validation failed"); expect(json.details.issues.length).toBeGreaterThan(0); }); + + it("finds an error by the first 8 characters of its id in the problems ring", async () => { + appendLogEvent( + makeEvent({ level: "error", request_id: "3f9a2c1b-1111-4000-8000-0000" }), + ); + for (let i = 0; i < 600; i++) { + appendLogEvent(makeEvent({ level: "info" })); + } + const gone = await GET(req("requestId=3f9a2c1b")); + const goneJson = (await gone.json()) as { data: { events: WideEvent[] } }; + expect(goneJson.data.events).toHaveLength(0); + + const res = await GET(req("requestId=3f9a2c1b&ring=problems")); + const json = (await res.json()) as { + data: { + events: WideEvent[]; + meta: { problemsBufferMax: number; ring: string }; + }; + }; + expect(json.data.events.map((e) => e.request_id)).toEqual([ + "3f9a2c1b-1111-4000-8000-0000", + ]); + expect(json.data.meta.problemsBufferMax).toBe(1000); + expect(json.data.meta.ring).toBe("problems"); + }); + + it("refuses a request id shorter than 8 characters or outside the id alphabet", async () => { + for (const bad of ["3f9a2c1", "3f9a2c1b%20OR%201", "a".repeat(65)]) { + const res = await GET(req(`requestId=${bad}`)); + expect(res.status).toBe(422); + } + const ring = await GET(req("ring=everything")); + expect(ring.status).toBe(422); + }); }); diff --git a/src/app/api/admin/app-logs/route.ts b/src/app/api/admin/app-logs/route.ts index c5e3e3478..2482a1600 100644 --- a/src/app/api/admin/app-logs/route.ts +++ b/src/app/api/admin/app-logs/route.ts @@ -1,7 +1,11 @@ import { apiHandler, requireAdmin } from "@/lib/api-handler"; import { apiSuccess, returnAllZodIssues } from "@/lib/api-response"; import { annotate } from "@/lib/logging/context"; -import { readLogBuffer, LOG_BUFFER_MAX } from "@/lib/logging/in-memory-buffer"; +import { + readLogBuffer, + LOG_BUFFER_MAX, + PROBLEMS_BUFFER_MAX, +} from "@/lib/logging/in-memory-buffer"; import { redactSecrets } from "@/lib/logging/redact"; import type { WideEvent } from "@/lib/logging/types"; import { NextRequest } from "next/server"; @@ -10,17 +14,31 @@ import { z } from "zod/v4"; export const dynamic = "force-dynamic"; const querySchema = z.object({ + // The error id a person reads out is the first 8 characters of the request + // id; the full id (up to 64) matches as well. Same alphabet as an accepted + // incoming `x-request-id`. + requestId: z + .string() + .trim() + .regex(/^[A-Za-z0-9-]{8,64}$/) + .optional(), + ring: z.enum(["all", "problems"]).default("all"), traceId: z.string().trim().min(1).max(200).optional(), level: z.enum(["debug", "info", "warn", "error"]).optional(), action: z.string().trim().min(1).max(200).optional(), since: z.string().datetime().optional(), until: z.string().datetime().optional(), - limit: z.coerce.number().int().min(1).max(500).default(200), + limit: z.coerce.number().int().min(1).max(PROBLEMS_BUFFER_MAX).default(200), }); /** * Admin endpoint: tail of the per-process in-memory wide-event ring buffer. * + * `ring=problems` reads the second ring, which keeps the last 1,000 `warn` and + * `error` events only, so a failure a person reported an hour ago is still + * there after the main ring has turned over. `requestId` finds the event + * behind an error id by prefix. + * * The buffer is populated by `transports.emitEvent()` so the result mirrors * what would be shipped to Loki (sampler-gated). Per-process and volatile — * see `src/lib/logging/in-memory-buffer.ts` for the limitations. @@ -36,6 +54,8 @@ export const GET = apiHandler(async (request: NextRequest) => { const { searchParams } = new URL(request.url); const result = querySchema.safeParse({ + requestId: searchParams.get("requestId") ?? undefined, + ring: searchParams.get("ring") ?? undefined, traceId: searchParams.get("traceId") ?? undefined, level: searchParams.get("level") ?? undefined, action: searchParams.get("action") ?? undefined, @@ -47,6 +67,8 @@ export const GET = apiHandler(async (request: NextRequest) => { const parsed = result.data; const events = readLogBuffer({ + ring: parsed.ring, + requestId: parsed.requestId, traceId: parsed.traceId, level: parsed.level, action: parsed.action, @@ -62,6 +84,8 @@ export const GET = apiHandler(async (request: NextRequest) => { meta: { total: redacted.length, bufferMax: LOG_BUFFER_MAX, + problemsBufferMax: PROBLEMS_BUFFER_MAX, + ring: parsed.ring, }, }); }); diff --git a/src/components/admin/app-log-preview-section.tsx b/src/components/admin/app-log-preview-section.tsx index b043500c3..92453a839 100644 --- a/src/components/admin/app-log-preview-section.tsx +++ b/src/components/admin/app-log-preview-section.tsx @@ -67,6 +67,7 @@ interface AppLogsResponse { meta: { total: number; bufferMax: number; + problemsBufferMax?: number; }; } @@ -94,6 +95,7 @@ function levelIcon(level: LogLevel) { export function AppLogPreviewSection() { const { t } = useTranslations(); + const [requestId, setRequestId] = useState(""); const [traceId, setTraceId] = useState(""); const [actionFilter, setActionFilter] = useState(""); const [level, setLevel] = useState("__all__"); @@ -103,16 +105,32 @@ export function AppLogPreviewSection() { const params = useMemo(() => { const p = new URLSearchParams(); + // An error id is the first characters of a request id. The ids people + // read out come from 5xx answers, which are logged at `error`, so a + // search by id, like a filter on warn or error, reads the problems ring: + // it keeps the last 1,000 warnings and errors, where the main ring keeps + // 500 events of every kind and turns over in minutes on a busy host. + const id = requestId.trim(); + if (id.length >= 8) p.set("requestId", id); + if (id.length >= 8 || level === "warn" || level === "error") { + p.set("ring", "problems"); + } if (traceId.trim()) p.set("traceId", traceId.trim()); if (actionFilter.trim()) p.set("action", actionFilter.trim()); if (level !== "__all__") p.set("level", level); const since = rangeToSince(range); if (since) p.set("since", since); return p; - }, [traceId, actionFilter, level, range]); + }, [requestId, traceId, actionFilter, level, range]); const { data, isLoading, refetch, isFetching } = useQuery({ - queryKey: queryKeys.adminAppLogs(traceId, actionFilter, level, range), + queryKey: queryKeys.adminAppLogs( + traceId, + actionFilter, + level, + range, + requestId.trim(), + ), queryFn: async () => { return apiGet( `/api/admin/app-logs?${params.toString()}`, @@ -144,7 +162,19 @@ export function AppLogPreviewSection() { {/* Filters and the refresh share one toolbar row above the table; the header status slot carries status, not actions (design standards §12). */} -
+
+ { + setRequestId(e.target.value); + setPage(1); + }} + aria-label={t("admin.section.app-logs.filterErrorId")} + data-slot="app-logs-error-id-filter" + /> { clearLogBuffer(); expect(readLogBuffer({})).toHaveLength(0); }); + + it("keeps warn and error in the problems ring while info traffic turns the main ring over", () => { + expect(PROBLEMS_BUFFER_MAX).toBe(1000); + appendLogEvent( + makeEvent({ level: "error", request_id: "3f9a2c1b-dead-beef" }), + ); + appendLogEvent(makeEvent({ level: "warn", request_id: "warn-0001" })); + for (let i = 0; i < LOG_BUFFER_MAX + 50; i++) { + appendLogEvent(makeEvent({ level: "info" })); + } + // The main ring lost both; the problems ring kept them. + expect(readLogBuffer({ requestId: "3f9a2c1b" })).toHaveLength(0); + const found = readLogBuffer({ ring: "problems", requestId: "3f9a2c1b" }); + expect(found.map((e) => e.request_id)).toEqual(["3f9a2c1b-dead-beef"]); + expect(getLogBufferSize("problems")).toBe(2); + }); + + it("FIFO-evicts the problems ring at its own cap and never admits info or debug", () => { + appendLogEvent(makeEvent({ level: "debug" })); + for (let i = 0; i < PROBLEMS_BUFFER_MAX + 5; i++) { + appendLogEvent(makeEvent({ level: "error", request_id: `e-${i}` })); + } + const out = readLogBuffer({ ring: "problems" }); + expect(out).toHaveLength(PROBLEMS_BUFFER_MAX); + expect(out[0].request_id).toBe(`e-${PROBLEMS_BUFFER_MAX + 4}`); + expect(out.every((e) => e.level === "error")).toBe(true); + }); + + it("matches a request id by case-insensitive prefix", () => { + appendLogEvent(makeEvent({ request_id: "ABCDEF12-0000" })); + appendLogEvent(makeEvent({ request_id: "abcdef99-0000" })); + expect(readLogBuffer({ requestId: "abcdef12" })).toHaveLength(1); + expect(readLogBuffer({ requestId: "abcdef" })).toHaveLength(2); + expect(readLogBuffer({ requestId: "ABCDEF12-0000" })).toHaveLength(1); + }); }); diff --git a/src/lib/logging/in-memory-buffer.ts b/src/lib/logging/in-memory-buffer.ts index 74f052aa8..5e5120b27 100644 --- a/src/lib/logging/in-memory-buffer.ts +++ b/src/lib/logging/in-memory-buffer.ts @@ -12,6 +12,11 @@ * web buffer doesn't see worker events and vice-versa. The UI surfaces * this caveat in the section header. * - 500-entry cap (~500KB max @ ~1KB/event). FIFO eviction on overflow. + * - A second ring, `problems`, keeps the last 1,000 `warn` and `error` + * events only. On a busy host the 500 entries of the main ring turn over + * in minutes of ordinary traffic, so the one failure a person reports + * was gone by the time the operator looked for it. Info traffic never + * enters the problems ring and cannot evict from it. * - Volatile — restart drops the buffer. For durable storage configure * `LOKI_ENDPOINT` and tail Loki instead. * @@ -23,20 +28,49 @@ import type { WideEvent, LogLevel } from "./types"; export const LOG_BUFFER_MAX = 500; -// Plain array with FIFO eviction. A linked list would be technically tighter -// but for 500 entries the array shift overhead (~microseconds) is invisible +/** Capacity of the warn/error-only ring. */ +export const PROBLEMS_BUFFER_MAX = 1000; + +/** Which ring a read walks: every event, or only `warn` and `error`. */ +export type LogRing = "all" | "problems"; + +// Plain arrays with FIFO eviction. A linked list would be technically tighter +// but for 1,000 entries the array shift overhead (~microseconds) is invisible // next to the rest of the request lifecycle. let buffer: WideEvent[] = []; +let problems: WideEvent[] = []; -/** Append an event to the buffer; evict the oldest entry once cap is hit. */ +/** Whether an event belongs in the problems ring. */ +function isProblem(event: WideEvent): boolean { + return event.level === "warn" || event.level === "error"; +} + +/** + * Append an event to the main ring and, for `warn` and `error`, to the + * problems ring; each evicts its oldest entry once its cap is hit. The same + * object sits in both, so an event costs its memory once. + */ export function appendLogEvent(event: WideEvent): void { buffer.push(event); if (buffer.length > LOG_BUFFER_MAX) { buffer.shift(); } + if (isProblem(event)) { + problems.push(event); + if (problems.length > PROBLEMS_BUFFER_MAX) { + problems.shift(); + } + } } export interface ReadLogBufferOptions { + /** The ring to read; `all` when absent. */ + ring?: LogRing; + /** + * Prefix match on `event.request_id`, case-insensitive. A person reads out + * the first 8 characters of an error id; the full id matches too. + */ + requestId?: string; /** Exact match on `event.trace_id`. */ traceId?: string; /** Exact match on `event.level`. */ @@ -60,11 +94,19 @@ export function readLogBuffer(opts: ReadLogBufferOptions): WideEvent[] { const sinceMs = opts.since?.getTime(); const untilMs = opts.until?.getTime(); const actionLower = opts.action?.toLowerCase(); + const requestIdLower = opts.requestId?.toLowerCase(); + const source = opts.ring === "problems" ? problems : buffer; // Walk back-to-front so the result is newest-first without an extra reverse. const out: WideEvent[] = []; - for (let i = buffer.length - 1; i >= 0; i--) { - const event = buffer[i]; + for (let i = source.length - 1; i >= 0; i--) { + const event = source[i]; + if ( + requestIdLower && + !(event.request_id ?? "").toLowerCase().startsWith(requestIdLower) + ) { + continue; + } if (opts.traceId && event.trace_id !== opts.traceId) continue; if (opts.level && event.level !== opts.level) continue; if (actionLower) { @@ -85,9 +127,10 @@ export function readLogBuffer(opts: ReadLogBufferOptions): WideEvent[] { /** Reset the buffer (test-only — not exported from the package index). */ export function clearLogBuffer(): void { buffer = []; + problems = []; } /** Current buffer size (test-only). */ -export function getLogBufferSize(): number { - return buffer.length; +export function getLogBufferSize(ring: LogRing = "all"): number { + return ring === "problems" ? problems.length : buffer.length; } diff --git a/src/lib/logging/index.ts b/src/lib/logging/index.ts index 88b6df6ba..f7ebb66ba 100644 --- a/src/lib/logging/index.ts +++ b/src/lib/logging/index.ts @@ -17,5 +17,7 @@ export { clearLogBuffer, getLogBufferSize, LOG_BUFFER_MAX, + PROBLEMS_BUFFER_MAX, + type LogRing, type ReadLogBufferOptions, } from "./in-memory-buffer"; diff --git a/src/lib/query-keys/admin.ts b/src/lib/query-keys/admin.ts index 59b402bb4..f3eeda9b7 100644 --- a/src/lib/query-keys/admin.ts +++ b/src/lib/query-keys/admin.ts @@ -32,7 +32,10 @@ export const adminKeys = { action: string | undefined, level: string | undefined, range: string | undefined, - ) => ["admin", "app-logs", traceId, action, level, range] as const, + requestId?: string, + ) => ["admin", "app-logs", traceId, action, level, range, requestId] as const, + /** v1.43 — the redacted support report on the admin status page. */ + adminSupportReport: () => ["admin", "support-report"] as const, adminAssistantFlags: () => ["admin", "settings", "assistant-flags"] as const, /** v1.18.0 — operator-level server-wide module availability matrix. */ adminModuleAvailability: () =>