Add logging with filters

This commit is contained in:
Twirre
2025-11-12 14:35:38 +00:00
committed by Gerla, J. (Justin)
parent b7eb0cb5ec
commit 231d7a5ba1
22 changed files with 1899 additions and 68 deletions

View File

@@ -0,0 +1,328 @@
import {render, screen, waitFor, fireEvent} from "@testing-library/react";
import userEvent from "@testing-library/user-event";
import * as React from "react";
type ControlledUseState = typeof React.useState & {
__forceNextReturn?: (value: any) => jest.Mock;
__resetMockState?: () => void;
};
jest.mock("react", () => {
const actual = jest.requireActual("react");
const queue: Array<{value: any; setter: jest.Mock}> = [];
const mockUseState = ((initial: any) => {
if (queue.length) {
const {value, setter} = queue.shift()!;
return [value, setter];
}
return actual.useState(initial);
}) as ControlledUseState;
mockUseState.__forceNextReturn = (value: any) => {
const setter = jest.fn();
queue.push({value, setter});
return setter;
};
mockUseState.__resetMockState = () => {
queue.length = 0;
};
return {
__esModule: true,
...actual,
useState: mockUseState,
};
});
import Filters from "../../../src/components/Logging/Filters.tsx";
import type {LogFilterPredicate, LogRecord} from "../../../src/components/Logging/useLogs.ts";
const GLOBAL = "global_log_level";
const AGENT_PREFIX = "agent_log_level_";
const optionMapping = new Map([
["ALL", 0],
["DEBUG", 10],
["INFO", 20],
["WARNING", 30],
["ERROR", 40],
["CRITICAL", 50],
["NONE", 999_999_999_999],
]);
const controlledUseState = React.useState as ControlledUseState;
afterEach(() => {
controlledUseState.__resetMockState?.();
});
function getCallArg<T>(mock: jest.Mock, index = 0): T {
return mock.mock.calls[index][0] as T;
}
function sampleRecord(levelno: number, name = "any.logger"): LogRecord {
return {
levelname: "UNKNOWN",
levelno,
name,
message: "Whatever",
created: 0,
relativeCreated: 0,
firstCreated: 0,
firstRelativeCreated: 0,
};
}
// --------------------------------------------------------------------------
describe("Filters", () => {
describe("Global level filter", () => {
it("initializes to INFO when missing", async () => {
const setFilterPredicates = jest.fn();
const filterPredicates = new Map<string, LogFilterPredicate>();
const view = render(
<Filters
filterPredicates={filterPredicates}
setFilterPredicates={setFilterPredicates}
agentNames={new Set<string>()}
/>
);
// Effect sets default to INFO
await waitFor(() => {
expect(setFilterPredicates).toHaveBeenCalled();
});
const updater = getCallArg<(prev: Map<string, LogFilterPredicate>) => Map<string, LogFilterPredicate>>(setFilterPredicates);
const newMap = updater(filterPredicates);
const global = newMap.get(GLOBAL)!;
expect(global.value).toBe("INFO");
expect(global.priority).toBe(0);
// Predicate gate at INFO (>= 20)
expect(global.predicate(sampleRecord(10))).toBe(false);
expect(global.predicate(sampleRecord(20))).toBe(true);
// UI shows INFO selected after parent state updates
view.rerender(
<Filters
filterPredicates={newMap}
setFilterPredicates={setFilterPredicates}
agentNames={new Set<string>()}
/>
);
const globalSelect = screen.getByLabelText("Global:");
expect((globalSelect as HTMLSelectElement).value).toBe("INFO");
});
it("updates predicate when selecting a higher level", async () => {
// Start with INFO already present
const existing = new Map<string, LogFilterPredicate>([
[
GLOBAL,
{
value: "INFO",
priority: 0,
predicate: (r: any) => r.levelno >= optionMapping.get("INFO")!
}
]
]);
const setFilterPredicates = jest.fn();
const user = userEvent.setup();
render(
<Filters
filterPredicates={existing}
setFilterPredicates={setFilterPredicates}
agentNames={new Set<string>()}
/>
);
const select = screen.getByLabelText("Global:");
await user.selectOptions(select, "ERROR");
const updater = getCallArg<(prev: Map<string, LogFilterPredicate>) => Map<string, LogFilterPredicate>>(setFilterPredicates);
const updated = updater(existing);
const global = updated.get(GLOBAL)!;
expect(global.value).toBe("ERROR");
expect(global.priority).toBe(0);
expect(global.predicate(sampleRecord(30))).toBe(false);
expect(global.predicate(sampleRecord(40))).toBe(true);
});
});
describe("Agent level filters", () => {
it("adds an agent using the current global level when none specified", async () => {
// Global set to WARNING
const existing = new Map<string, LogFilterPredicate>([
[
GLOBAL,
{
value: "WARNING",
priority: 0,
predicate: (r: any) => r.levelno >= optionMapping.get("WARNING")!
}
]
]);
const setFilterPredicates = jest.fn();
const user = userEvent.setup();
render(
<Filters
filterPredicates={existing}
setFilterPredicates={setFilterPredicates}
agentNames={new Set<string>(["pepper.speech", "vision.agent"])}
/>
);
const addSelect = screen.getByLabelText("Add:");
await user.selectOptions(addSelect, "pepper.speech");
// Agent setter is functional: prev => next
const updater = getCallArg<(prev: Map<string, LogFilterPredicate>) => Map<string, LogFilterPredicate>>(setFilterPredicates);
const next = updater(existing);
const key = AGENT_PREFIX + "pepper.speech";
const agentPred = next.get(key)!;
expect(agentPred.priority).toBe(1);
expect(agentPred.value).toEqual({agentName: "pepper.speech", level: "WARNING"});
// When agentName matches, enforce WARNING (>= 30)
expect(agentPred.predicate(sampleRecord(20, "pepper.speech"))).toBe(false);
expect(agentPred.predicate(sampleRecord(30, "pepper.speech"))).toBe(true);
// Other agents -> null
expect(agentPred.predicate(sampleRecord(999, "other"))).toBeNull();
});
it("changes an agent's level when its select is updated", async () => {
// Prepopulate agent predicate at WARNING
const key = AGENT_PREFIX + "pepper.speech";
const existing = new Map<string, LogFilterPredicate>([
[
GLOBAL,
{
value: "INFO",
priority: 0,
predicate: (r: any) => r.levelno >= optionMapping.get("INFO")!
}
],
[
key,
{
value: {agentName: "pepper.speech", level: "WARNING"},
priority: 1,
predicate: (r: any) => (r.name === "pepper.speech" ? r.levelno >= optionMapping.get("WARNING")! : null)
}
]
]);
const setFilterPredicates = jest.fn();
const user = userEvent.setup();
const element = render(
<Filters
filterPredicates={existing}
setFilterPredicates={setFilterPredicates}
agentNames={new Set(["pepper.speech"])}
/>
);
const agentSelect = element.container.querySelector("select#log_level_pepper\\.speech")!;
await user.selectOptions(agentSelect, "ERROR");
const updater = getCallArg<(prev: Map<string, LogFilterPredicate>) => Map<string, LogFilterPredicate>>(setFilterPredicates);
const next = updater(existing);
const updated = next.get(key)!;
expect(updated.value).toEqual({agentName: "pepper.speech", level: "ERROR"});
// Threshold moved to ERROR (>= 40)
expect(updated.predicate(sampleRecord(30, "pepper.speech"))).toBe(false);
expect(updated.predicate(sampleRecord(40, "pepper.speech"))).toBe(true);
});
it("deletes an agent predicate when clicking its name button", async () => {
const key = AGENT_PREFIX + "pepper.speech";
const existing = new Map<string, LogFilterPredicate>([
[
GLOBAL,
{
value: "INFO",
priority: 0,
predicate: (r: any) => r.levelno >= optionMapping.get("INFO")!
}
],
[
key,
{
value: {agentName: "pepper.speech", level: "INFO"},
priority: 1,
predicate: (r: any) => (r.name === "pepper.speech" ? r.levelno >= optionMapping.get("INFO")! : null)
}
]
]);
const setFilterPredicates = jest.fn();
const user = userEvent.setup();
render(
<Filters
filterPredicates={existing}
setFilterPredicates={setFilterPredicates}
agentNames={new Set<string>(["pepper.speech"])}
/>
);
const deleteBtn = screen.getByRole("button", {name: "speech:"});
await user.click(deleteBtn);
const updater = getCallArg<(prev: Map<string, LogFilterPredicate>) => Map<string, LogFilterPredicate>>(setFilterPredicates);
const next = updater(existing);
expect(next.has(key)).toBe(false);
});
});
describe("Filter popup behavior", () => {
function renderWithPopupOpen() {
const existing = new Map<string, LogFilterPredicate>([
[
GLOBAL,
{
value: "INFO",
priority: 0,
predicate: (r: any) => r.levelno >= optionMapping.get("INFO")!
}
]
]);
const setFilterPredicates = jest.fn();
const forceNext = controlledUseState.__forceNextReturn;
if (!forceNext) throw new Error("useState mock missing helper");
const setOpen = forceNext(true);
render(
<Filters
filterPredicates={existing}
setFilterPredicates={setFilterPredicates}
agentNames={new Set(["pepper.vision"])}
/>
);
return { setOpen };
}
it("closes the popup when clicking outside", () => {
const { setOpen } = renderWithPopupOpen();
fireEvent.mouseDown(document.body);
expect(setOpen).toHaveBeenCalledWith(false);
});
it("closes the popup when pressing Escape", () => {
const { setOpen } = renderWithPopupOpen();
fireEvent.keyDown(document, { key: "Escape" });
expect(setOpen).toHaveBeenCalledWith(false);
});
});
});

View File

@@ -0,0 +1,239 @@
import {render, screen, fireEvent, act, waitFor} from "@testing-library/react";
import userEvent from "@testing-library/user-event";
import "@testing-library/jest-dom";
import type {Cell} from "../../../src/utils/cellStore.ts";
import {cell} from "../../../src/utils/cellStore.ts";
import type {LogFilterPredicate, LogRecord} from "../../../src/components/Logging/useLogs.ts";
const mockFiltersRender = jest.fn();
const loggingStoreRef: { current: null | { setState: (state: Partial<LoggingSettingsState>) => void } } = { current: null };
type LoggingSettingsState = {
showRelativeTime: boolean;
setShowRelativeTime: (show: boolean) => void;
scrollToBottom: boolean;
setScrollToBottom: (scroll: boolean) => void;
};
jest.mock("zustand", () => {
const actual = jest.requireActual("zustand");
const actualCreate = actual.create;
return {
__esModule: true,
...actual,
create: (...args: any[]) => {
const store = actualCreate(...args);
const state = store.getState();
if ("setShowRelativeTime" in state && "setScrollToBottom" in state) {
loggingStoreRef.current = store;
}
return store;
},
};
});
jest.mock("../../../src/components/Logging/Filters.tsx", () => {
const React = jest.requireActual("react");
return {
__esModule: true,
default: (props: any) => {
mockFiltersRender(props);
return React.createElement("div", {"data-testid": "filters-mock"}, "filters");
},
};
});
jest.mock("../../../src/components/Logging/useLogs.ts", () => {
const actual = jest.requireActual("../../../src/components/Logging/useLogs.ts");
return {
__esModule: true,
...actual,
useLogs: jest.fn(),
};
});
import {useLogs} from "../../../src/components/Logging/useLogs.ts";
const mockUseLogs = useLogs as jest.MockedFunction<typeof useLogs>;
type LoggingComponent = typeof import("../../../src/components/Logging/Logging.tsx").default;
let Logging: LoggingComponent;
beforeAll(async () => {
if (!Element.prototype.scrollIntoView) {
Object.defineProperty(Element.prototype, "scrollIntoView", {
configurable: true,
writable: true,
value: function () {},
});
}
({default: Logging} = await import("../../../src/components/Logging/Logging.tsx"));
});
beforeEach(() => {
mockUseLogs.mockReset();
mockFiltersRender.mockReset();
mockUseLogs.mockReturnValue({filteredLogs: [], distinctNames: new Set()});
resetLoggingStore();
});
afterEach(() => {
jest.restoreAllMocks();
});
function resetLoggingStore() {
loggingStoreRef.current?.setState({
showRelativeTime: false,
scrollToBottom: true,
});
}
function makeRecord(overrides: Partial<LogRecord> = {}): LogRecord {
return {
name: "pepper.logger",
message: "default",
levelname: "INFO",
levelno: 20,
created: 1,
relativeCreated: 1,
firstCreated: 1,
firstRelativeCreated: 1,
...overrides,
};
}
function makeCell(overrides: Partial<LogRecord> = {}): Cell<LogRecord> {
return cell(makeRecord(overrides));
}
describe("Logging component", () => {
it("renders log messages and toggles the timestamp between absolute and relative view", async () => {
const logCell = makeCell({
name: "pepper.trace.logging",
message: "Ping",
levelname: "WARNING",
levelno: 30,
created: 1_700_000_000,
relativeCreated: 12_345,
firstCreated: 1_700_000_000,
firstRelativeCreated: 12_345,
});
const names = new Set(["pepper.trace.logging"]);
mockUseLogs.mockReturnValue({filteredLogs: [logCell], distinctNames: names});
jest.spyOn(Date.prototype, "toLocaleTimeString").mockReturnValue("ABS TIME");
const user = userEvent.setup();
render(<Logging/>);
expect(screen.getByText("Logs")).toBeInTheDocument();
expect(screen.getByText("WARNING")).toBeInTheDocument();
expect(screen.getByText("logging")).toBeInTheDocument();
expect(screen.getByText("Ping")).toBeInTheDocument();
let timestamp = screen.queryByText("ABS TIME");
if (!timestamp) {
// if previous test left the store toggled, click once to show absolute time
timestamp = screen.getByText("00:00:12.345");
await user.click(timestamp);
timestamp = screen.getByText("ABS TIME");
}
await user.click(timestamp);
expect(screen.getByText("00:00:12.345")).toBeInTheDocument();
});
it("shows the scroll-to-bottom button after a manual scroll and scrolls when clicked", async () => {
const logs = [
makeCell({message: "first", firstRelativeCreated: 1}),
makeCell({message: "second", firstRelativeCreated: 2}),
];
mockUseLogs.mockReturnValue({filteredLogs: logs, distinctNames: new Set()});
const scrollSpy = jest.spyOn(Element.prototype, "scrollIntoView").mockImplementation(() => {});
const user = userEvent.setup();
const view = render(<Logging/>);
expect(screen.queryByRole("button", {name: "Scroll to bottom"})).toBeNull();
const scrollable = view.container.querySelector(".scroll-y");
expect(scrollable).toBeTruthy();
fireEvent.wheel(scrollable!);
const button = await screen.findByRole("button", {name: "Scroll to bottom"});
await user.click(button);
expect(scrollSpy).toHaveBeenCalled();
await waitFor(() => {
expect(screen.queryByRole("button", {name: "Scroll to bottom"})).toBeNull();
});
});
it("scrolls the last element into view when a log cell updates", async () => {
const logCell = makeCell({message: "Initial", firstRelativeCreated: 42});
mockUseLogs.mockReturnValue({filteredLogs: [logCell], distinctNames: new Set()});
const scrollSpy = jest.spyOn(Element.prototype, "scrollIntoView").mockImplementation(() => {});
render(<Logging/>);
await waitFor(() => {
expect(scrollSpy).toHaveBeenCalledTimes(1);
});
scrollSpy.mockClear();
act(() => {
const current = logCell.get();
logCell.set({...current, message: "Updated"});
});
expect(screen.getByText("Updated")).toBeInTheDocument();
await waitFor(() => {
expect(scrollSpy).toHaveBeenCalledTimes(1);
});
});
it("passes filter state to Filters and re-invokes useLogs when predicates change", async () => {
const distinct = new Set(["pepper.core"]);
mockUseLogs.mockImplementation((_filters: Map<string, LogFilterPredicate>) => ({
filteredLogs: [],
distinctNames: distinct,
}));
render(<Logging/>);
expect(mockFiltersRender).toHaveBeenCalledTimes(1);
const firstProps = mockFiltersRender.mock.calls[0][0];
expect(firstProps.agentNames).toBe(distinct);
const initialMap = firstProps.filterPredicates;
expect(initialMap).toBeInstanceOf(Map);
expect(initialMap.size).toBe(0);
expect(mockUseLogs).toHaveBeenCalledWith(initialMap);
const updatedPredicate: LogFilterPredicate = {
value: "custom",
priority: 0,
predicate: () => true,
};
act(() => {
firstProps.setFilterPredicates((prev: Map<string, LogFilterPredicate>) => {
const next = new Map(prev);
next.set("custom", updatedPredicate);
return next;
});
});
await waitFor(() => {
expect(mockUseLogs).toHaveBeenCalledTimes(2);
});
const nextFilters = mockUseLogs.mock.calls[1][0];
expect(nextFilters.get("custom")).toBe(updatedPredicate);
const secondProps = mockFiltersRender.mock.calls[mockFiltersRender.mock.calls.length - 1][0];
expect(secondProps.filterPredicates).toBe(nextFilters);
});
});

View File

@@ -0,0 +1,246 @@
import { render, screen, act } from "@testing-library/react";
import "@testing-library/jest-dom";
import {type LogRecord, useLogs} from "../../../src/components/Logging/useLogs.ts";
import {type cell, useCell} from "../../../src/utils/cellStore.ts";
import { StrictMode } from "react";
jest.mock("../../../src/utils/priorityFiltering.ts", () => ({
applyPriorityPredicates: jest.fn((_log, preds: any[]) =>
preds.every(() => true) // default: pass all
),
}));
import {applyPriorityPredicates} from "../../../src/utils/priorityFiltering.ts";
class MockEventSource {
url: string;
onmessage: ((event: { data: string }) => void) | null = null;
onerror: ((event: unknown) => void) | null = null;
close = jest.fn();
constructor(url: string) {
this.url = url;
// expose the latest instance for tests:
(globalThis as any).__es = this;
}
}
beforeAll(() => {
globalThis.EventSource = MockEventSource as any;
});
afterEach(() => {
// reset mock so previous instance not reused accidentally
(globalThis as any).__es = undefined;
jest.clearAllMocks();
});
function LogsProbe({ filters }: { filters: Map<string, any> }) {
const { filteredLogs, distinctNames } = useLogs(filters);
return (
<div>
<div data-testid="names-count">{distinctNames.size}</div>
<ul data-testid="logs">
{filteredLogs.map((c, i) => (
<LogItem key={i} cell={c} index={i} />
))}
</ul>
</div>
);
}
function LogItem({ cell: c, index }: { cell: ReturnType<typeof cell<LogRecord>>; index: number }) {
const value = useCell(c);
return (
<li data-testid={`log-${index}`}>
<span data-testid={`log-${index}-name`}>{value.name}</span>
<span data-testid={`log-${index}-msg`}>{value.message}</span>
<span data-testid={`log-${index}-first`}>{String(value.firstCreated)}</span>
<span data-testid={`log-${index}-created`}>{String(value.created)}</span>
<span data-testid={`log-${index}-ref`}>{value.reference ?? ""}</span>
</li>
);
}
function emit(log: LogRecord) {
const eventSource = (globalThis as any).__es as MockEventSource;
if (!eventSource || !eventSource.onmessage) throw new Error("EventSource not initialized");
act(() => {
eventSource.onmessage!({ data: JSON.stringify(log) });
});
}
describe("useLogs (unit)", () => {
it("creates EventSource once and closes on unmount", () => {
const filters = new Map(); // allow all by default
const { unmount } = render(
<StrictMode>
<LogsProbe filters={filters} />
</StrictMode>
);
const es = (globalThis as any).__es as MockEventSource;
expect(es).toBeTruthy();
expect(es.url).toBe("http://localhost:8000/logs/stream");
unmount();
expect(es.close).toHaveBeenCalledTimes(1);
});
it("appends filtered logs and collects distinct names", () => {
const filters = new Map();
render(
<StrictMode>
<LogsProbe filters={filters} />
</StrictMode>
);
expect(screen.getByTestId("names-count")).toHaveTextContent("0");
emit({
levelname: "DEBUG",
levelno: 10,
name: "alpha",
message: "m1",
created: 1,
relativeCreated: 1,
firstCreated: 1,
firstRelativeCreated: 1,
});
emit({
levelname: "DEBUG",
levelno: 10,
name: "beta",
message: "m2",
created: 2,
relativeCreated: 2,
firstCreated: 2,
firstRelativeCreated: 2,
});
emit({
levelname: "DEBUG",
levelno: 10,
name: "alpha",
message: "m3",
created: 3,
relativeCreated: 3,
firstCreated: 3,
firstRelativeCreated: 3,
});
// 3 messages (no reference), 2 distinct names
expect(screen.getAllByRole("listitem")).toHaveLength(3);
expect(screen.getByTestId("names-count")).toHaveTextContent("2");
expect(screen.getByTestId("log-0-name")).toHaveTextContent("alpha");
expect(screen.getByTestId("log-1-name")).toHaveTextContent("beta");
expect(screen.getByTestId("log-2-name")).toHaveTextContent("alpha");
});
it("updates first message with reference when a second one with that reference comes", () => {
const filters = new Map();
render(<LogsProbe filters={filters} />);
// First message with ref r1
emit({
levelname: "DEBUG",
levelno: 10,
name: "svc",
message: "first",
reference: "r1",
created: 10,
relativeCreated: 10,
firstCreated: 10,
firstRelativeCreated: 10,
});
// Second message with same ref r1, should still be a single item
emit({
levelname: "DEBUG",
levelno: 10,
name: "svc",
message: "second",
reference: "r1",
created: 20,
relativeCreated: 20,
firstCreated: 20,
firstRelativeCreated: 20,
});
const items = screen.getAllByRole("listitem");
expect(items).toHaveLength(1);
// Same single item, but message should be "second"
expect(screen.getByTestId("log-0-msg")).toHaveTextContent("second");
// The "firstCreated" should remain the original (10), while "created" is now 20
expect(screen.getByTestId("log-0-first")).toHaveTextContent("10");
expect(screen.getByTestId("log-0-created")).toHaveTextContent("20");
expect(screen.getByTestId("log-0-ref")).toHaveTextContent("r1");
});
it("runs recomputeFiltered when filters change", () => {
const allowAll = new Map<string, any>();
const { rerender } = render(<LogsProbe filters={allowAll} />);
emit({
levelname: "DEBUG",
levelno: 10,
name: "n1",
message: "ok",
created: 1,
relativeCreated: 1,
firstCreated: 1,
firstRelativeCreated: 1,
});
emit({
levelname: "DEBUG",
levelno: 10,
name: "n2",
message: "ok",
created: 2,
relativeCreated: 2,
firstCreated: 2,
firstRelativeCreated: 2,
});
emit({
levelname: "INFO",
levelno: 20,
name: "n3",
message: "ok1",
reference: "r1",
created: 3,
relativeCreated: 3,
firstCreated: 3,
firstRelativeCreated: 3,
});
emit({
levelname: "INFO",
levelno: 20,
name: "n3",
message: "ok2",
reference: "r1",
created: 4,
relativeCreated: 4,
firstCreated: 4,
firstRelativeCreated: 4,
});
expect(screen.getAllByRole("listitem")).toHaveLength(3);
// Now change filters to block all < INFO
(applyPriorityPredicates as jest.Mock).mockImplementation((l) => l.levelno >= 20);
const blockDebug = new Map<string, any>([["dummy", { value: true }]]);
rerender(<LogsProbe filters={blockDebug} />);
// Should recompute with shorter list
expect(screen.queryAllByRole("listitem")).toHaveLength(1);
// Switch back to allow-all
(applyPriorityPredicates as jest.Mock).mockImplementation((_log, preds: any[]) =>
preds.every(() => true)
);
rerender(<LogsProbe filters={allowAll} />);
// recompute should restore all three
expect(screen.getAllByRole("listitem")).toHaveLength(3);
});
});