diff --git a/backend/app/routes/admin_logs.py b/backend/app/routes/admin_logs.py index 01d19ef0..43ae3c65 100644 --- a/backend/app/routes/admin_logs.py +++ b/backend/app/routes/admin_logs.py @@ -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: diff --git a/backend/tests/test_admin_logs.py b/backend/tests/test_admin_logs.py index 7d634616..87660e41 100644 --- a/backend/tests/test_admin_logs.py +++ b/backend/tests/test_admin_logs.py @@ -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 diff --git a/frontend/src/components/AdminLogs.dom.test.tsx b/frontend/src/components/AdminLogs.dom.test.tsx index f4646334..e06e6575 100644 --- a/frontend/src/components/AdminLogs.dom.test.tsx +++ b/frontend/src/components/AdminLogs.dom.test.tsx @@ -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 { @@ -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((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(); diff --git a/frontend/src/components/AdminLogs.tsx b/frontend/src/components/AdminLogs.tsx index 1d8b9992..9608491e 100644 --- a/frontend/src/components/AdminLogs.tsx +++ b/frontend/src/components/AdminLogs.tsx @@ -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(() => 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(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(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={} - 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() { )} -
+ {stale && ( + + {t("adminLogs.stale")} + + )} + +
{logs.isError && !logs.data ? ( 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() {
{t("adminLogs.count", { count: rows.length })} - {logs.hasNextPage && ( + {olderCursor !== null && (