fix(ui): record a repeated log message once per session with a count

@react-three/fiber creates a THREE.Clock on every scene mount, and
three prints a deprecation warning each time. The frontend log sent
every one of them to the daemon, so System > Logs held hundreds of
identical warnings and pushed real messages out of the 200-event view.
The dependency cannot change here, so the log handles it:

- The ui-log buffer records an entry identical to an earlier one of the
  session (level, source, project, message) once and counts the
  repeats. The running count goes out with the same text at 10, 100,
  1000 repeats and when the page is left, in the detail field the
  daemon keeps.
- System > Logs shows identical messages as one row with "xN" at their
  latest position, for these counts and for older sessions that still
  recorded every occurrence.

Signed-off-by: Bernhard Jackiewicz <bj@techport.io>
This commit is contained in:
Bernhard Jackiewicz
2026-10-03 19:02:34 +02:00
parent 1999aaba8a
commit d2f08261d8
8 changed files with 192 additions and 8 deletions
+25 -1
View File
@@ -9,7 +9,7 @@
import { afterEach, describe, expect, it, vi } from 'vitest';
import { reportError } from '../provider/error-observer';
import { UiLogBuffer } from './ui-log';
import { repeatCount, UiLogBuffer } from './ui-log';
import type { UiLogPayload } from './ui-log';
import { describeArgs, installUiLog, safeStringify } from './ui-log-install';
import type { UiLogHandle } from './ui-log-install';
@@ -210,4 +210,28 @@ describe('httpUiLogTransport', () => {
});
expect(await failing.send({ page: '/', session: 's', entries: [] }, false)).toBe(false);
});
it('sends 120 identical console warnings through the transport as one entry with a count', async () => {
const bodies: UiLogPayload[] = [];
const fetch = vi.fn(async (_url: string | URL | Request, init?: RequestInit) => { bodies.push(JSON.parse(String(init?.body))); return new Response('{}'); });
const beaconed: Promise<void>[] = [];
const beacon = vi.fn((_url: string, body: Blob) => { beaconed.push(new Promise<string>((resolve) => { const reader = new FileReader(); reader.onload = () => resolve(String(reader.result)); reader.readAsText(body); }).then((text) => { bodies.push(JSON.parse(text)); })); return true; });
const buffer = new UiLogBuffer({ page: '/?project=cbm', session: 'three', transport: httpUiLogTransport({ fetch: fetch as typeof globalThis.fetch, beacon }),
schedule: () => 0, cancel: () => undefined, bufferMax: 200, batchMax: 200 });
const printed: unknown[] = [];
const fakeConsole = { debug: () => undefined, log: () => undefined, info: () => undefined, error: () => undefined,
warn: (...args: unknown[]) => printed.push(args[0]) } as unknown as Console;
handle = installUiLog({ buffer, console: fakeConsole, session: 'three', getProject: () => 'cbm' });
const clock = 'THREE.THREE.Clock: This module has been deprecated. Please use THREE.Timer instead.';
for (let i = 0; i < 120; i++) fakeConsole.warn(clock);
await buffer.flush();
window.dispatchEvent(new Event('pagehide'));
await vi.waitFor(() => expect(beaconed).toHaveLength(1));
await Promise.all(beaconed);
// The console still prints every call; the server gets the first in full and the counts.
expect(printed).toHaveLength(120);
const posted = bodies.flatMap((body) => body.entries).filter((entry) => entry.message === clock);
expect(posted.map((entry) => repeatCount(entry.detail) ?? 1)).toEqual([1, 10, 100, 120]);
expect(beacon).toHaveBeenCalledOnce();
});
});
+20 -1
View File
@@ -6,7 +6,7 @@
import { describe, expect, it } from 'vitest';
import { capField, UI_LOG_FIELD_MAX, UiLogBuffer } from './ui-log';
import { capField, repeatCount, UI_LOG_FIELD_MAX, UiLogBuffer } from './ui-log';
import type { UiLogPayload, UiLogTransport } from './ui-log';
interface Timer {
@@ -171,6 +171,25 @@ describe('UiLogBuffer', () => {
expect(timers.every((timer) => timer.cancelled)).toBe(true);
});
it('records a repeated identical entry once and counts the repeats instead of queueing each one', async () => {
const posts: UiLogPayload[] = [];
const buffer = new UiLogBuffer({ page: '/', session: 'repeats', schedule: () => 0, cancel: () => undefined, bufferMax: 200, batchMax: 200,
transport: { send: async (payload) => { posts.push(payload); return true; } } });
const clock = 'THREE.THREE.Clock: This module has been deprecated. Please use THREE.Timer instead.';
for (let i = 0; i < 25; i++) buffer.record('warn', 'console', clock, { project: 'cbm' });
buffer.record('warn', 'console', 'a different warning', { project: 'cbm' });
buffer.record('warn', 'console', clock, { project: 'django-demo' });
await buffer.flush();
const sent = posts.flatMap((post) => post.entries);
// The first one in full, one count at ten, and the same text in another project as its own first entry.
expect(sent.map((entry) => [entry.message === clock ? 'clock' : entry.message, entry.project, repeatCount(entry.detail)])).toEqual([
['clock', 'cbm', undefined], ['clock', 'cbm', 10], ['a different warning', 'cbm', undefined], ['clock', 'django-demo', undefined]]);
// Leaving the page reports the exact total.
await buffer.flush(true);
expect(posts.at(-1)?.entries.map((entry) => [entry.project, repeatCount(entry.detail)])).toEqual([['cbm', 25]]);
expect(buffer.stats().sent).toBe(5);
});
it('does not throw when the transport does', async () => {
const throwing: UiLogTransport = {
send: async () => {
+66
View File
@@ -30,6 +30,13 @@
* - **Capped fields.** Every text field is cut at UI_LOG_FIELD_MAX
* characters, the same cap the server applies; a cut is marked so nobody
* reads a truncated stack as a complete one.
* - **Once per session, then counted.** An entry identical to an earlier
* one of this session (level, source, project and message) is counted,
* not queued. A deprecation warning that a library prints on every scene
* mount (THREE.Clock from @react-three/fiber) would otherwise push the
* real messages out of System › Logs. The count goes out as one more
* entry with the same text at 10, 100, 1000 repeats and when the page is
* left (`final`), so the journal holds a handful of lines, not hundreds.
*
* Time and timers are injectable so a test runs in one tick.
*/
@@ -92,6 +99,8 @@ export const UI_LOG_BATCH_MAX = 25;
export const UI_LOG_FLUSH_MS = 1500;
export const UI_LOG_BUFFER_MAX = 200;
export const UI_LOG_BACKOFF_MS: readonly number[] = [2000, 5000, 15000, 60000];
/** Distinct entries counted per session; beyond this, new texts are recorded one by one again. */
export const UI_LOG_REPEAT_KEYS_MAX = 256;
export interface UiLogOptions {
page: string;
@@ -108,13 +117,37 @@ export interface UiLogOptions {
backoffMs?: readonly number[];
}
/**
* The detail of a repeat count. The server keeps only the known fields of an
* entry, so the count travels in `detail`, in words a reader understands and
* in a form System › Logs reads back (repeatCount).
*/
export function repeatDetail(count: number): string {
return `${count} identical entries in this session; only the first is recorded in full`;
}
/** The count of a repeat entry, undefined for an ordinary one. */
export function repeatCount(detail: string | undefined): number | undefined {
const match = /^(\d+) identical entries in this session\b/.exec(detail ?? '');
return match ? Number(match[1]) : undefined;
}
/** Cut a text field at the shared cap and say so. */
export function capField(text: string, max = UI_LOG_FIELD_MAX): string {
return text.length > max ? `${text.slice(0, max)} [cut at ${max}]` : text;
}
interface Repeat {
entry: UiLogEntry;
count: number;
reported: number;
}
const powerOfTen = (count: number): boolean => count >= 10 && /^10*$/.test(String(count));
export class UiLogBuffer {
private readonly queue: UiLogEntry[] = [];
private readonly repeats = new Map<string, Repeat>();
private seq = 0;
private sent = 0;
private dropped = 0;
@@ -178,10 +211,35 @@ export class UiLogBuffer {
if (typeof extra.col === 'number' && Number.isFinite(extra.col)) {
entry.col = extra.col;
}
const key = [entry.level, entry.source, entry.project ?? '', entry.message].join('\u0000');
const repeat = this.repeats.get(key);
if (repeat !== undefined) {
this.seq -= 1;
repeat.count += 1;
if (powerOfTen(repeat.count)) {
this.report(repeat);
this.arm(this.flushMs);
}
return;
}
if (this.repeats.size < UI_LOG_REPEAT_KEYS_MAX) {
this.repeats.set(key, { entry, count: 1, reported: 1 });
}
this.push(entry);
this.arm(this.flushMs);
}
/** Queue the running count of a repeated entry, with the text of its first occurrence. */
private report(repeat: Repeat): void {
const { level, source, message, project } = repeat.entry;
const entry: UiLogEntry = { ts: this.now().toISOString(), seq: ++this.seq, level, source, message, detail: repeatDetail(repeat.count) };
if (project !== undefined) {
entry.project = project;
}
repeat.reported = repeat.count;
this.push(entry);
}
stats(): UiLogStats {
return {
queued: this.queue.length,
@@ -204,6 +262,14 @@ export class UiLogBuffer {
if (this.inFlight && !final) {
return;
}
if (final) {
// The page is going away: every count not yet reported goes with it.
for (const repeat of this.repeats.values()) {
if (repeat.count > repeat.reported) {
this.report(repeat);
}
}
}
if (this.queue.length === 0) {
return;
}
@@ -199,4 +199,17 @@ describe('System workspace', () => {
expect(record?.querySelector('time')?.dateTime).toBe('2026-09-09T12:00:00Z');
expect(container.textContent).toContain('SQLite history');
});
it('combines repeated identical frontend warnings into one line with a count', async () => {
const api = source();
const clock = 'THREE.THREE.Clock: This module has been deprecated. Please use THREE.Timer instead.';
const records = Array.from({ length: 120 }, (_, index) => ({ id: 100 + index, ts: '2026-10-03T16:05:22Z', level: 'warn', source: 'console', project: 'cbm',
message: JSON.stringify({ session: 'a31adcaf', seq: index + 2, level: 'warn', source: 'console', message: clock, project: 'cbm' }) }));
records.push({ id: 400, ts: '2026-10-03T16:06:00Z', level: 'error', source: 'rpc', project: 'cbm', message: JSON.stringify({ session: 'a31adcaf', seq: 300, level: 'error', source: 'rpc', message: '/rpc query_graph: Failed to fetch' }) });
api.logs = vi.fn().mockResolvedValue(readLogs({ lines: [], total: 121, persistent: true, retention_limit: 5000, generation: 'fixture', records }));
await render(api); await click('Logs');
const rows = [...container.querySelectorAll('.system-log-record')];
expect(rows.filter((row) => row.textContent?.includes('THREE.THREE.Clock'))).toHaveLength(1);
expect(rows.find((row) => row.textContent?.includes('THREE.THREE.Clock'))?.querySelector('.system-log-repeat')?.textContent).toBe('×120');
expect(rows.find((row) => row.textContent?.includes('Failed to fetch'))?.querySelector('.system-log-repeat')).toBeNull();
});
});
+6 -4
View File
@@ -1,8 +1,8 @@
import { useCallback, useEffect, useRef, useState, type KeyboardEvent, type ReactNode } from 'react';
import { useCallback, useEffect, useMemo, useRef, useState, type KeyboardEvent, type ReactNode } from 'react';
import type { AtlasApi } from '../app/atlas-api';
import type { ProjectEntry } from '../provider/rpc-schemas';
import IndexesPanel, { type IndexesApi } from './IndexesPanel';
import { cpuText, logLevel, memoryLabel, memoryText } from './system-model';
import { collapseRepeats, cpuText, logLevel, memoryLabel, memoryText, repeatTitle } from './system-model';
import { useSystemPoll, type SystemReading } from './useSystemPoll';
import './system.css';
@@ -61,6 +61,8 @@ export default function SystemWorkspace({ api, onOpenProjects, active = true, ve
const self = report?.processes.find((process) => process.isSelf);
const visibleLines = logs.data?.lines ?? [];
const visibleRecords = logs.data?.records;
// Identical messages read as one line with a count; a repeated warning cannot push the rest out of view.
const logRows = useMemo(() => visibleRecords ? collapseRepeats(visibleRecords) : undefined, [visibleRecords]);
const selectedReading = tab === 'logs' ? logs : tab === 'indexes' ? jobs : processes;
useEffect(() => {
@@ -71,7 +73,7 @@ export default function SystemWorkspace({ api, onOpenProjects, active = true, ve
const copyLogs = async () => {
try {
if (!navigator.clipboard?.writeText) throw new Error('Clipboard access is unavailable. Select and copy the visible text.');
await navigator.clipboard.writeText(visibleRecords ? visibleRecords.map((record) => `${record.ts} ${record.level.toUpperCase()} ${record.source} #${record.id}\n${record.message}`).join('\n') : visibleLines.join('\n'));
await navigator.clipboard.writeText(logRows ? logRows.map(({ record, count }) => `${record.ts} ${record.level.toUpperCase()} ${record.source} #${record.id}${count > 1 ? ` ×${count}` : ''}\n${record.message}`).join('\n') : visibleLines.join('\n'));
setCopyStatus('Visible lines copied');
} catch (error) {
setCopyStatus(error instanceof Error ? error.message : 'Could not copy the log.');
@@ -165,7 +167,7 @@ export default function SystemWorkspace({ api, onOpenProjects, active = true, ve
const element = logRef.current;
if (element && element.scrollHeight - element.scrollTop - element.clientHeight > 32) setFollowTail(false);
}}>
{visibleRecords ? visibleRecords.map((record) => <div className={`system-log-line system-log-record system-log-${logLevel(`level=${record.level}`)}`} key={`${logs.data?.generation ?? ''}:${record.id}`}><strong>{record.level.toUpperCase() || 'UNCLASSIFIED'}</strong> · <time dateTime={record.ts}>{record.ts || 'Time unavailable'}</time> · {record.source || 'Source unavailable'} · Event #{record.id} · {record.project ? `Project: ${record.project}` : 'Project not recorded'}<pre>{record.message}</pre></div>) : visibleLines.map((line, index) => <div className={`system-log-line system-log-${logLevel(line)}`} key={index}>{line || '\u00a0'}</div>)}
{logRows ? logRows.map((row) => { const { record } = row; return <div className={`system-log-line system-log-record system-log-${logLevel(`level=${record.level}`)}`} key={`${logs.data?.generation ?? ''}:${record.id}`}><strong>{record.level.toUpperCase() || 'UNCLASSIFIED'}</strong> · <time dateTime={record.ts}>{record.ts || 'Time unavailable'}</time> · {record.source || 'Source unavailable'} · Event #{record.id} · {record.project ? `Project: ${record.project}` : 'Project not recorded'}{row.count > 1 && <> · <span className="system-log-repeat" title={repeatTitle(row)}>×{row.count}</span></>}<pre>{record.message}</pre></div>; }) : visibleLines.map((line, index) => <div className={`system-log-line system-log-${logLevel(line)}`} key={index}>{line || '\u00a0'}</div>)}
{(visibleRecords?.length ?? visibleLines.length) === 0 && <p>{logs.loading ? 'Reading log…' : !logs.data ? 'No log reading available.' : 'No retained events match these filters.'}</p>}
</div>
</section>
+16 -1
View File
@@ -1,6 +1,7 @@
import { describe, expect, it } from 'vitest';
import { readProcesses } from '../projects/projects-model';
import { cpuText, filterLogs, logLevel, memoryLabel, memoryText } from './system-model';
import { collapseRepeats, cpuText, filterLogs, logLevel, memoryLabel, memoryText } from './system-model';
import { repeatDetail } from '../app/ui-log';
describe('System measurements', () => {
it('keeps missing readings distinct from measured zero', () => {
@@ -51,4 +52,18 @@ describe('System log levels', () => {
expect(filterLogs(lines, 'INDEX', 'error')).toEqual([lines[1]]);
expect(filterLogs(lines, '', 'all')).toEqual(lines);
});
it('shows identical frontend messages once with how often they occurred', () => {
const clock = 'THREE.THREE.Clock: This module has been deprecated. Please use THREE.Timer instead.';
const line = (session: string, seq: number, message: string, detail?: string) => JSON.stringify({ received: '2026-10-03T16:05:22Z', page: '/?project=cbm', session, seq, ts: '2026-10-03T16:05:20.914Z', level: 'warn', source: 'console', message, ...(detail ? { detail } : {}), project: 'cbm' });
const record = (id: number, message: string, source = 'console') => ({ id, ts: `2026-10-03T16:05:${String(id).padStart(2, '0')}Z`, level: 'warn', source, message, project: 'cbm' });
const rows = collapseRepeats([
// Before the fix every occurrence was its own record; after it, one record and its counts.
record(1, line('old', 3, clock)), record(2, line('old', 5, clock)), record(3, 'level=warn msg=watcher.slow path=src'),
record(4, line('old', 9, clock)), record(5, line('new', 2, clock)), record(6, line('new', 3, 'Another warning')),
record(7, line('new', 4, clock, repeatDetail(10))), record(8, line('new', 5, clock, repeatDetail(100))), record(9, line('new', 6, clock, repeatDetail(120))),
]);
expect(rows.map((row) => [row.record.id, row.count])).toEqual([[3, 1], [6, 1], [9, 123]]);
expect(rows[2]?.first).toBe('2026-10-03T16:05:01Z');
});
});
+44 -1
View File
@@ -1,4 +1,5 @@
import type { ProcessCpuUnit, ProcessMemoryKind } from '../projects/projects-model';
import type { DaemonLogRecord, ProcessCpuUnit, ProcessMemoryKind } from '../projects/projects-model';
import { repeatCount } from '../app/ui-log';
export function cpuText(value: number | null | undefined, unit: ProcessCpuUnit | undefined): string {
if (value == null || !Number.isFinite(value) || value < 0) return 'Unavailable';
@@ -43,3 +44,45 @@ export function filterLogs(lines: readonly string[], query: string, level: LogLe
const needle = query.trim().toLocaleLowerCase();
return lines.filter((line) => (level === 'all' || logLevel(line) === level) && line.toLocaleLowerCase().includes(needle));
}
export interface LogRow { record: DaemonLogRecord; count: number; first: string }
/** The text that makes two records the same message: a frontend line names its session and its own message. */
function repeatIdentity(record: DaemonLogRecord): { key: string; session: string; repeat?: number } {
try {
const line: unknown = JSON.parse(record.message);
if (typeof line === 'object' && line !== null && typeof (line as Record<string, unknown>)['message'] === 'string') {
const entry = line as Record<string, unknown>;
const detail = typeof entry['detail'] === 'string' ? entry['detail'] : undefined;
const repeat = repeatCount(detail);
const own = repeat === undefined && detail ? `\u0000${detail}` : '';
return { key: `${record.level}\u0000${record.source}\u0000${record.project ?? ''}\u0000${String(entry['message'])}${own}`,
session: typeof entry['session'] === 'string' ? entry['session'] : '', repeat };
}
} catch { /* A daemon line is plain text. */ }
return { key: `${record.level}\u0000${record.source}\u0000${record.project ?? ''}\u0000${record.message}`, session: '' };
}
/**
* Identical messages become one row at their latest position, with how often
* they occurred. A frontend session records a repeated entry once and then
* reports running counts (app/ui-log.ts); older sessions recorded every
* occurrence. Per session the larger of the two is the number of occurrences.
*/
export function collapseRepeats(records: readonly DaemonLogRecord[]): LogRow[] {
const groups = new Map<string, { last: number; first: string; sessions: Map<string, { plain: number; counted: number }> }>();
records.forEach((record, index) => {
const { key, session, repeat } = repeatIdentity(record);
const group = groups.get(key) ?? { last: index, first: record.ts, sessions: new Map() };
const tally = group.sessions.get(session) ?? { plain: 0, counted: 0 };
if (repeat === undefined) tally.plain += 1; else tally.counted = Math.max(tally.counted, repeat);
group.sessions.set(session, tally); group.last = index; groups.set(key, group);
});
return [...groups.values()].sort((a, b) => a.last - b.last).map((group) => ({ record: records[group.last]!, first: group.first,
count: [...group.sessions.values()].reduce((sum, tally) => sum + Math.max(tally.plain, tally.counted), 0) }));
}
/** The tooltip of a combined row. */
export function repeatTitle(row: LogRow): string {
return `${row.count.toLocaleString()} identical events from ${row.first} to ${row.record.ts}`;
}
+2
View File
@@ -67,3 +67,5 @@
@media (max-width: 550px) { .system-metrics { grid-template-columns: 1fr; }.system-section { padding: 14px; }.system-heading-actions { gap: 8px; } }
@media (max-width: 800px) { .system-layout { grid-template-columns: 134px minmax(0, 1fr); gap: 14px; }.system-tabs { padding-right: 9px; }.system-tabs button { padding: 11px 9px; font-size: 12px; }.system-metrics { grid-template-columns: 1fr; } }
@media (max-width: 550px) { .system-workspace { padding: 14px 9px; }.system-layout { grid-template-columns: 112px minmax(0, 1fr); gap: 9px; }.system-tabs button { padding: 10px 5px; }.system-metrics article { padding: 13px; } }
/* How often a combined message occurred; the tooltip names the time span. */
.system-log-repeat { display: inline-block; padding: 0 6px; border: 1px solid currentColor; border-radius: 9px; font-weight: 600; font-variant-numeric: tabular-nums; line-height: 1.5; }