fix(diagnostics): honest live console after review

- Live stops polling on a failed read and marks the list as possibly
  stale (with Retry), instead of re-raising the error dialog every tick.
- While live, a refetch reads the newest page only, whatever the cache
  holds (a late "Load older", a revisited filter set).
- Copy is disabled and the list dimmed while a filter change loads.
- Dates follow the UI language; the pivot chip uses the shared .chip.
- Tests: query-string wire test, Copy, every facet's skip key.
This commit is contained in:
2026-09-19 03:42:26 +02:00
parent 1c49870a7a
commit 8f6f89832f
7 changed files with 213 additions and 17 deletions
+4 -2
View File
@@ -39,6 +39,8 @@ PAGE_MAX = 200
FACET_EVENTS_MAX = 100
Level = Literal["TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]
# The filters a facet can leave out of its own count (`LogFilters.conditions`).
Facet = Literal["levels", "sources", "user", "event"]
# `none` selects the rows that have no account / no event code (a scheduler line, an anonymous
# request) — a real value to filter on, not the absence of a filter.
NONE = "none"
@@ -106,7 +108,7 @@ class LogFilters:
since: datetime | None
until: datetime | None
def conditions(self, skip: str | None = None) -> list:
def conditions(self, skip: Facet | None = None) -> list:
"""The WHERE conditions, ANDed by the caller. `skip` leaves one filter out: a facet counts
its own values under every OTHER filter, so picking a level does not zero the other
levels' counts (the way back), while a request pivot does narrow them (honest counts)."""
@@ -210,7 +212,7 @@ def log_facets(
most frequent events — each counted under every filter but its own (`LogFilters.conditions`).
`total` is the "all levels" count: every filter but the level one."""
def counts(col, skip: str, cap: int | None = None) -> list[dict]:
def counts(col, skip: Facet, cap: int | None = None) -> list[dict]:
n = func.count().label("n")
stmt = select(col, n).where(*filters.conditions(skip)).group_by(col).order_by(n.desc(), col)
if cap is not None:
+17
View File
@@ -172,3 +172,20 @@ def test_a_facet_counts_under_every_other_filter_but_not_its_own(db, admin):
assert body["total"] == 2
# Every other facet counts under the level filter too.
assert body["sources"] == [{"value": "worker", "count": 1}]
@pytest.mark.parametrize(
("params", "facet", "expected"),
[
({"sources": ["worker"]}, "sources", {"api", "worker"}),
({"user": "1"}, "users", {"1", "none"}),
({"event": "sync.rss.failed"}, "events", {"http.request", "sync.rss.failed"}),
],
)
def test_every_facet_keeps_its_siblings_under_its_own_filter(db, admin, params, facet, expected):
# The way back from a pick: the picked facet still offers the values it was picked from.
_add(db, _row(user_id=1), _row(source="worker", event="sync.rss.failed"))
body = admin.get("/api/admin/logs/facets", params=params).json()
assert {f["value"] for f in body[facet]} == expected
+78 -2
View File
@@ -2,9 +2,10 @@
//
// E22.6: the admin log console. A request id narrows the list to that request (and says so, in the
// filter row and the URL); a filter value the facets no longer count stays pickable; "Live" watches
// the newest page only; a failed read is an error, not an empty log.
// the newest page only, and stops on a failed read instead of re-raising it; a failed read is an
// error, not an empty log; Copy takes every loaded line, oldest first.
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
import { cleanup, fireEvent, render, screen, waitFor, within } from "@testing-library/react";
import { act, cleanup, fireEvent, render, screen, waitFor, within } from "@testing-library/react";
import { QueryClient, QueryClientProvider } from "@tanstack/react-query";
import type { LogFacets, LogPage, LogQuery, ServerLogRow } from "../lib/api";
@@ -35,6 +36,14 @@ vi.mock("../lib/api", async (importOriginal) => {
};
});
const copied: string[] = [];
vi.mock("../lib/clipboard", () => ({
copyText: (text: string) => {
copied.push(text);
return Promise.resolve(true);
},
}));
import AdminLogs from "./AdminLogs";
function row(id: number, extra: Partial<ServerLogRow> = {}): ServerLogRow {
@@ -75,6 +84,9 @@ function renderConsole() {
);
}
// react-query hands its updates to React on a (real) timer tick, after the promise that caused them.
const settle = () => act(() => new Promise((resolve) => setTimeout(resolve, 20)));
const lines = () =>
within(screen.getByTestId("admin-logs-lines"))
.queryAllByRole("button")
@@ -85,6 +97,7 @@ beforeEach(() => {
facetsMock.mockResolvedValue(FACETS);
});
afterEach(() => {
vi.useRealTimers();
cleanup();
logsMock.mockReset();
facetsMock.mockReset();
@@ -142,6 +155,69 @@ describe("AdminLogs", () => {
).toBe("true");
});
it("a page that lands after Live went on is dropped at the next tick", async () => {
let landOlder!: (page: LogPage) => void;
logsMock.mockImplementation((_q, before) =>
before === null
? Promise.resolve({ items: [row(3), row(2)], accounts: {}, next_cursor: "c1" })
: new Promise<LogPage>((resolve) => (landOlder = resolve)),
);
renderConsole();
await waitFor(() => expect(lines()).toHaveLength(2));
fireEvent.click(screen.getByRole("button", { name: "adminLogs.older" }));
await waitFor(() => expect(landOlder).toBeTypeOf("function"));
vi.useFakeTimers({ toFake: ["setInterval", "clearInterval"] });
fireEvent.click(screen.getByRole("button", { name: "adminLogs.live" }));
await act(async () => landOlder({ items: [row(1)], accounts: {}, next_cursor: null }));
await settle();
expect(lines()).toHaveLength(3);
const olderReads = logsMock.mock.calls.filter(([, before]) => before !== null).length;
await act(async () => vi.advanceTimersByTimeAsync(4000));
await settle();
expect(lines()).toHaveLength(2);
expect(logsMock.mock.calls.filter(([, before]) => before !== null)).toHaveLength(olderReads);
});
it("a failed live read stops the polling and says the list may be old", async () => {
logsMock.mockResolvedValueOnce({ items: [row(1)], accounts: {}, next_cursor: null });
renderConsole();
await waitFor(() => expect(lines()).toHaveLength(1));
logsMock.mockRejectedValue(new Error("500"));
vi.useFakeTimers({ toFake: ["setInterval", "clearInterval"] });
fireEvent.click(screen.getByRole("button", { name: "adminLogs.live" }));
await act(async () => vi.advanceTimersByTimeAsync(4000));
await settle();
expect(screen.getByRole("alert").textContent).toContain("adminLogs.stale");
expect(lines()).toHaveLength(1);
const reads = logsMock.mock.calls.length;
await act(async () => vi.advanceTimersByTimeAsync(12000));
expect(logsMock.mock.calls.length).toBe(reads);
});
it("copies every loaded line, oldest first", async () => {
logsMock.mockImplementation(async (_q, before) =>
before === null
? { items: [row(3), row(2)], accounts: {}, next_cursor: "c1" }
: { items: [row(1)], accounts: {}, next_cursor: null },
);
renderConsole();
await waitFor(() => expect(lines()).toHaveLength(2));
fireEvent.click(screen.getByRole("button", { name: "adminLogs.older" }));
await waitFor(() => expect(lines()).toHaveLength(3));
await act(async () => {
fireEvent.click(screen.getByRole("button", { name: "adminLogs.copy" }));
});
const ids = copied[copied.length - 1]!.split("\n").map((l) => JSON.parse(l).id);
expect(ids).toEqual([1, 2, 3]);
});
it("the keyboard can walk the lines and open one (NavGrid items)", async () => {
logsMock.mockResolvedValue({ items: [row(2), row(1)], accounts: {}, next_cursor: null });
renderConsole();
+48 -13
View File
@@ -1,4 +1,4 @@
import { useMemo, useState } from "react";
import { useMemo, useRef, useState } from "react";
import { useTranslation } from "react-i18next";
import {
keepPreviousData,
@@ -10,6 +10,7 @@ import { Copy, Radio, Search, X } from "lucide-react";
import { api, type LogFacet, type LogQuery, type ServerLogRow } from "../lib/api";
import { copyText } from "../lib/clipboard";
import { formatDateTime } from "../lib/format";
import { LEVEL_GROUPS, type LevelGroup } from "../lib/log";
import {
DEFAULT_LOGS_STATE,
@@ -35,7 +36,8 @@ import { LoadingState, StateMessage } from "./ui/QueryState";
// opens in place to its full record, and its request id / job id narrow the list to that request or
// job. Filters live in the URL, so a filtered view is a link. "Élő" re-reads the newest page every
// few seconds while the tab is visible — the newest page only: live is watching the top, so paging
// into older rows turns it off.
// into older rows turns it off. A failed read stops the polling (the request already reported it
// once) and marks the list as possibly stale, instead of re-raising the failure every few seconds.
const LIVE_MS = 4000;
const GROUPS: readonly LevelGroup[] = ["all", "error", "warning", "info", "detail"];
@@ -68,7 +70,15 @@ export default function AdminLogs() {
const [state, setState] = useState<LogsUrlState>(() =>
logsParamsToState(new URLSearchParams(window.location.search)),
);
const [live, setLive] = useState(false);
const [live, setLiveState] = useState(false);
// Read by `getNextPageParam` when a page is fetched, not when it renders: while live, a refetch
// stops after the newest page, however many pages the cache holds — a "Load older" that lands
// after Live was switched on, or a filter set revisited with older pages still cached.
const liveRef = useRef(false);
const setLive = (on: boolean) => {
liveRef.current = on;
setLiveState(on);
};
const [open, setOpen] = useState<number | null>(null);
const q = useDebounced(state.q, 300);
useUrlMirror(logsParamUpdates(state));
@@ -85,16 +95,25 @@ export default function AdminLogs() {
queryFn: ({ pageParam }) =>
api.adminLogs({ ...query, since: sinceOf(state.window) }, pageParam),
initialPageParam: null as string | null,
getNextPageParam: (last) => last.next_cursor ?? undefined,
getNextPageParam: (last) => (liveRef.current ? undefined : (last.next_cursor ?? undefined)),
placeholderData: keepPreviousData,
refetchInterval: live ? LIVE_MS : false,
refetchInterval: (q) => (live && q.state.status !== "error" ? LIVE_MS : false),
});
const facets = useQuery({
queryKey: qk.adminLogFacets({ ...query, window: state.window }),
queryFn: () => api.adminLogFacets({ ...query, since: sinceOf(state.window) }),
placeholderData: keepPreviousData,
refetchInterval: live ? LIVE_MS * 4 : false,
refetchInterval: (q) => (live && q.state.status !== "error" ? LIVE_MS * 4 : false),
});
// What "Load older" continues from — read off the data, since `hasNextPage` is off while live.
const olderCursor = logs.data?.pages[logs.data.pages.length - 1]?.next_cursor ?? null;
// A read failed while rows (or counts) were already on screen: they are kept, and said to be old.
const stale = (logs.isError && !!logs.data) || facets.isError;
const retryStale = () => {
if (logs.isFetchNextPageError) void logs.fetchNextPage();
else if (logs.isError) void logs.refetch();
if (facets.isError) void facets.refetch();
};
const rows = useMemo(() => logs.data?.pages.flatMap((p) => p.items) ?? [], [logs.data]);
const accounts = useMemo(
@@ -111,7 +130,7 @@ export default function AdminLogs() {
const toggleLive = () => {
if (!live) {
// Watching the top: drop the older pages, or every tick would re-read all of them.
// Watching the top: drop the older pages now; `liveRef` keeps each tick to the first page.
qc.setQueryData<typeof logs.data>(key, (d) =>
d ? { pages: d.pages.slice(0, 1), pageParams: d.pageParams.slice(0, 1) } : d,
);
@@ -249,7 +268,8 @@ export default function AdminLogs() {
variant="outline"
size="xs"
icon={<Copy className="h-3.5 w-3.5" />}
disabled={rows.length === 0}
// While a filter change loads, the rows on screen are the previous filter's.
disabled={rows.length === 0 || logs.isPlaceholderData}
onClick={() => void copy()}
>
{t("adminLogs.copy")}
@@ -276,7 +296,22 @@ export default function AdminLogs() {
</div>
)}
<div className="font-mono text-2xs" data-testid="admin-logs-lines">
{stale && (
<StateMessage
tone="error"
compact
onRetry={retryStale}
className="border-b border-border"
>
{t("adminLogs.stale")}
</StateMessage>
)}
<div
className={`font-mono text-2xs ${logs.isPlaceholderData ? "opacity-60" : ""}`}
data-testid="admin-logs-lines"
aria-busy={logs.isPlaceholderData}
>
{logs.isError && !logs.data ? (
<StateMessage tone="error" onRetry={() => void logs.refetch()}>
{t("common.loadError")}
@@ -297,7 +332,7 @@ export default function AdminLogs() {
level={row.level}
event={row.event ?? "—"}
msg={row.msg}
title={new Date(row.ts).toLocaleString()}
title={formatDateTime(row.ts)}
open={open === row.id}
onToggle={() => setOpen(open === row.id ? null : row.id)}
>
@@ -315,7 +350,7 @@ export default function AdminLogs() {
<div className="flex flex-wrap items-center justify-between gap-2 border-t border-border px-3 py-1.5 text-xs text-muted">
<span>{t("adminLogs.count", { count: rows.length })}</span>
{logs.hasNextPage && (
{olderCursor !== null && (
<Button
variant="outline"
size="xs"
@@ -342,7 +377,7 @@ function PivotChip({
onClear: () => void;
}) {
return (
<span className="inline-flex items-center gap-1 rounded-full border border-accent/40 bg-accent/10 py-0.5 pl-2.5 pr-1 text-accent">
<span className="chip py-0.5 pl-2.5 pr-1">
<span className="font-mono">{label}</span>
<button
type="button"
@@ -375,7 +410,7 @@ function RowDetail({
<div className="flex flex-col gap-2">
<dl className="grid grid-cols-[max-content_minmax(0,1fr)] gap-x-3 gap-y-0.5 font-sans text-xs">
<dt>{t("adminLogs.fields.when")}</dt>
<dd className="tabular-nums">{new Date(row.ts).toLocaleString()}</dd>
<dd className="tabular-nums">{formatDateTime(row.ts)}</dd>
<dt>{t("adminLogs.fields.source")}</dt>
<dd className="font-mono">
{row.source} · {row.logger}
@@ -26,6 +26,7 @@
"showRequest": "Only this request's lines",
"showJob": "Only this job's lines",
"empty": "No lines match the filters.",
"stale": "The last refresh failed; what you see may be out of date.",
"count_one": "{{count}} line loaded · newest first",
"count_other": "{{count}} lines loaded · newest first",
"older": "Load older",
@@ -26,6 +26,7 @@
"showRequest": "Csak ennek a kérésnek a sorai",
"showJob": "Csak ennek a jobnak a sorai",
"empty": "Nincs a szűrésnek megfelelő sor.",
"stale": "Az utolsó frissítés nem sikerült, amit látsz, elavult lehet.",
"count_one": "{{count}} sor betöltve · a legújabb felül",
"count_other": "{{count}} sor betöltve · a legújabb felül",
"older": "Régebbiek betöltése",
@@ -0,0 +1,64 @@
// @vitest-environment jsdom
//
// The log console's query strings. The console's DOM tests mock this slice, so nothing else in the
// suite looks at the URL that goes out — and a multi-level group is the case that breaks quietly:
// `levels` must repeat, or FastAPI's list reads only the last one.
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
import { adminApi } from "./admin";
const fetchMock = vi.fn();
beforeEach(() => {
fetchMock.mockReset().mockResolvedValue({
ok: true,
status: 200,
headers: new Headers({ "content-type": "application/json" }),
json: async () => ({}),
text: async () => "{}",
});
vi.stubGlobal("fetch", fetchMock);
});
afterEach(() => vi.unstubAllGlobals());
const lastQuery = (): URLSearchParams => {
const calls = fetchMock.mock.calls;
return new URL(String(calls[calls.length - 1]?.[0]), "http://x").searchParams;
};
describe("adminApi log query strings", () => {
it("repeats the list filters and sends every single one it is given", async () => {
await adminApi.adminLogs(
{
levels: ["ERROR", "CRITICAL"],
sources: ["api", "worker"],
user: "none",
event: "sync.rss.failed",
request_id: "req-abcdef12",
job_id: 42,
q: "100% done",
since: "2026-09-19T11:00:00.000Z",
},
"cursor-1",
);
const p = lastQuery();
expect(p.getAll("levels")).toEqual(["ERROR", "CRITICAL"]);
expect(p.getAll("sources")).toEqual(["api", "worker"]);
expect(Object.fromEntries([...p].filter(([k]) => k !== "levels" && k !== "sources"))).toEqual({
user: "none",
event: "sync.rss.failed",
request_id: "req-abcdef12",
job_id: "42",
q: "100% done",
since: "2026-09-19T11:00:00.000Z",
before: "cursor-1",
});
});
it("leaves out what is not set, and the facets carry no cursor", async () => {
await adminApi.adminLogs({ q: "", user: undefined }, null);
expect(String(fetchMock.mock.calls[0]?.[0])).toBe("/api/admin/logs");
await adminApi.adminLogFacets({ levels: ["WARNING"], since: "2026-09-19T11:00:00.000Z" });
expect([...lastQuery().keys()]).toEqual(["levels", "since"]);
});
});