mirror of
https://github.com/MBombeck/HealthLog.git
synced 2026-11-09 04:50:59 +00:00
feat(logging): keep warnings and errors in their own ring and find them by error id
This commit is contained in:
1 parent
2fd62cc115
commit
1af0de5e87
7 files changed
+186
-13
No files matched your search
@@ -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);
|
||||
});
|
||||
});
|
||||
@@ -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,
|
||||
},
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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<LogLevel | "__all__">("__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<AppLogsResponse>(
|
||||
`/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). */}
|
||||
<div className="grid gap-2 md:grid-cols-2 lg:grid-cols-[repeat(4,minmax(0,1fr))_auto]">
|
||||
<div className="grid gap-2 md:grid-cols-2 lg:grid-cols-[repeat(5,minmax(0,1fr))_auto]">
|
||||
<Input
|
||||
type="search"
|
||||
placeholder={t("admin.section.app-logs.filterErrorId")}
|
||||
value={requestId}
|
||||
maxLength={64}
|
||||
onChange={(e) => {
|
||||
setRequestId(e.target.value);
|
||||
setPage(1);
|
||||
}}
|
||||
aria-label={t("admin.section.app-logs.filterErrorId")}
|
||||
data-slot="app-logs-error-id-filter"
|
||||
/>
|
||||
<Input
|
||||
type="search"
|
||||
placeholder={t("admin.section.app-logs.filterTraceId")}
|
||||
|
||||
@@ -3,7 +3,9 @@ import {
|
||||
appendLogEvent,
|
||||
readLogBuffer,
|
||||
clearLogBuffer,
|
||||
getLogBufferSize,
|
||||
LOG_BUFFER_MAX,
|
||||
PROBLEMS_BUFFER_MAX,
|
||||
} from "../in-memory-buffer";
|
||||
import type { WideEvent } from "../types";
|
||||
|
||||
@@ -116,4 +118,39 @@ describe("in-memory log buffer", () => {
|
||||
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);
|
||||
});
|
||||
});
|
||||
@@ -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;
|
||||
}
|
||||
@@ -17,5 +17,7 @@ export {
|
||||
clearLogBuffer,
|
||||
getLogBufferSize,
|
||||
LOG_BUFFER_MAX,
|
||||
PROBLEMS_BUFFER_MAX,
|
||||
type LogRing,
|
||||
type ReadLogBufferOptions,
|
||||
} from "./in-memory-buffer";
|
||||
@@ -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: () =>
|
||||
|
||||
Reference in new issue
Block a user