diff --git a/CLAUDE.md b/CLAUDE.md index 3704b86..1d42539 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -852,6 +852,13 @@ keys; components/; lib/ is pure and tested). One responsibility per file; aliase ## Build, test, release - `npm run dev`, `npm test` (vitest), `npm run typecheck`, `npm run lint`. +- **THE DIAGNOSTICS LOG** (#140; owner, 2026-10-07: "robust logging and debugging ... especially to + catch stalls"). Both apps write `\logs\diag.jsonl` (PT `%APPDATA%\PrismTerminal\logs`, + the stable copy `%APPDATA%\PrismTerminalStable\logs`, Prism `%APPDATA%\Prism\logs`): stalls with + the scripts and the page stack, slow IPC, errors, crumbs. When the owner says something stalled or + failed, READ IT FIRST: `npm run diag -- --app stable --since 10m` (a `mark` line is their Mark + button). Schema, kinds and how to read them: [`docs/diagnostics.md`](docs/diagnostics.md). Local + only, never sent (`PRIVACY.md`); typed text, the clipboard and audio are never written. - **A test run leaves nothing in %TEMP%** (2026-09-28): `vitest.global.ts` points the whole run's TEMP at one folder and removes it afterwards (14 `pt-*` folders a run leaked before; Prism's suite had left 40,000, which is what made its tree stall). A new test may mkdtemp freely. diff --git a/PRIVACY.md b/PRIVACY.md index 00778a3..ea2cf0a 100644 --- a/PRIVACY.md +++ b/PRIVACY.md @@ -1,8 +1,18 @@ # Privacy Prism Terminal has no accounts, no analytics, no telemetry and no crash reporting. It keeps your -settings and open tabs on your own PC (`%APPDATA%\PrismTerminal`), and nothing about you or what -you do in it is sent anywhere. +settings, open tabs and a diagnostics log on your own PC (`%APPDATA%\PrismTerminal`), and nothing +about you or what you do in it is sent anywhere. + +## The diagnostics log + +To find out why the app froze or failed, Prism Terminal keeps a log on your PC +(`%APPDATA%\PrismTerminal\logs`, at most 10 MB, the oldest part removed as it grows): when the +window or the app was slow and for how long, errors, and a timeline of what you did in the app +(a tab opened, closed or switched, a Settings page, an update, dictation starting and stopping, a +shell starting and ending). Folder paths are written in full. What you type, what you copy and +what you say are never written to it. The log is **never sent anywhere**; it leaves your PC only if +you send it yourself. Settings > Diagnostics opens its folder, and has a switch for more detail. ## What reaches the network diff --git a/core/README.md b/core/README.md index 63ac446..54d2e6f 100644 --- a/core/README.md +++ b/core/README.md @@ -183,6 +183,24 @@ fourth, under the same bar. Spec and plan: `dictation/useDictationState.ts`, `dictation/parts.tsx`), so every rule has one copy and, for a few days, two layouts. +**THE DIAGNOSTICS LOG (#140, 2026-10-07)** is the fifth: both apps catch their +stalls and errors the same way. `main/diagnostics.ts` `startDiagnostics` wires +it in one call; its main deps include **`diagLogDir`** (`\logs`), and +**a host without it logs nothing** (the page's bridge still answers, so Prism +is unchanged until it passes one). Call it before any IPC is registered (it +times every call by wrapping `ipcMain` itself), `watchWindow(win)` once the +window exists, `stop()` on the quit that goes ahead, and add `withStackPolicy` +in the session's `onHeadersReceived` for `mainFrame` responses (without that +Document-Policy the page stack never comes). Optional: `longWaitChannels` +(the host's channels that wait on the user or a download, never `ipc-slow`), +`powerMonitor` (a getter, so a sleep is not a lag), and `log.flushSync()` in +the window's `session-end`, where no quit comes. The bridge is `DGCH` in +`shared/channels.ts`, `preload/diagApi.ts` and `main/diagIpc.ts`; the page +calls `startDiag(bridge)` and anything may call `crumb()`. The Settings page +is `settings/sections/DiagnosticsPage.tsx` (props only), its rows +`diagnosticsOptions.ts`. Schema and how to read it: Prism Terminal's +`docs/diagnostics.md`. + ## Rules for code in here (lint-enforced in Prism Terminal's `eslint.config.js`) - **Relative imports only.** No `@shared` / `@renderer` / `@core` aliases: a diff --git a/core/main/crashHooks.test.ts b/core/main/crashHooks.test.ts new file mode 100644 index 0000000..6854e58 --- /dev/null +++ b/core/main/crashHooks.test.ts @@ -0,0 +1,116 @@ +import { describe, expect, it, vi } from 'vitest' +import { EventEmitter } from 'events' +import type { DiagLog, DiagSource } from './diagLog' +import { hookCrashes, watchWindowHealth } from './crashHooks' + +interface Line { + src: DiagSource + k: string + fields: Record +} + +function fakeLog(): DiagLog & { lines: Line[]; syncs: number } { + const lines: Line[] = [] + const log = { + lines, + syncs: 0, + dir: '', + file: '', + write: (src: DiagSource, k: string, fields: Record = {}) => lines.push({ src, k, fields }), + writeAt: (src: DiagSource, k: string, _at: number, fields: Record = {}) => lines.push({ src, k, fields }), + verbose: () => false, + setVerbose: () => {}, + flush: async () => {}, + flushSync: () => { + log.syncs += 1 + }, + failed: () => false, + close: () => {} + } + return log +} + +describe('hookCrashes', () => { + it('logs an uncaught exception by observing only, and writes it to disk at once', () => { + const proc = new EventEmitter() + const log = fakeLog() + hookCrashes({ log, process: proc, app: new EventEmitter() }) + // The MONITOR event: observing it leaves Node's own handling untouched. + expect(proc.listenerCount('uncaughtExceptionMonitor')).toBe(1) + expect(proc.listenerCount('uncaughtException')).toBe(0) + proc.emit('uncaughtExceptionMonitor', new Error('kaput'), 'uncaughtException') + expect(log.lines[0]).toMatchObject({ src: 'main', k: 'main-error', fields: { msg: 'kaput', origin: 'uncaughtException' } }) + expect(typeof log.lines[0].fields.stack).toBe('string') + expect(log.syncs).toBe(1) + }) + + it('logs an unhandled rejection', () => { + const proc = new EventEmitter() + const log = fakeLog() + hookCrashes({ log, process: proc, app: new EventEmitter() }) + proc.emit('unhandledRejection', new Error('lost'), Promise.resolve()) + expect(log.lines[0]).toMatchObject({ k: 'main-rejection', fields: { msg: 'lost' } }) + }) + + it('writes a rejection in the batch, and the same one over and over once per 10 s with a count', () => { + vi.useFakeTimers() + try { + const proc = new EventEmitter() + const log = fakeLog() + let t = 0 + const off = hookCrashes({ log, process: proc, app: new EventEmitter(), now: () => t }) + // A poll that rejects every 250 ms for five seconds. + for (; t < 5000; t += 250) proc.emit('unhandledRejection', new Error('poll failed'), Promise.resolve()) + expect(log.lines.map((l) => l.k)).toEqual(['main-rejection']) + expect(log.syncs).toBe(0) + t = 10_000 + vi.advanceTimersByTime(10_000) + expect(log.lines.map((l) => l.k)).toEqual(['main-rejection', 'main-rejection']) + expect(log.lines[1].fields).toMatchObject({ msg: 'poll failed', repeats: 19 }) + off() + } finally { + vi.useRealTimers() + } + }) + + it('logs a renderer or a child process that went', () => { + const app = new EventEmitter() + const log = fakeLog() + hookCrashes({ log, process: new EventEmitter(), app }) + app.emit('render-process-gone', {}, {}, { reason: 'oom', exitCode: -536870904 }) + app.emit('child-process-gone', {}, { type: 'GPU', reason: 'crashed', exitCode: 1, name: 'gpu' }) + expect(log.lines.map((l) => l.fields)).toEqual([ + { type: 'renderer', reason: 'oom', exitCode: -536870904 }, + { type: 'GPU', reason: 'crashed', exitCode: 1, name: 'gpu' } + ]) + expect(log.lines.every((l) => l.k === 'gone')).toBe(true) + expect(log.syncs).toBe(2) + }) + + it('takes its listeners off again', () => { + const proc = new EventEmitter() + const app = new EventEmitter() + const off = hookCrashes({ log: fakeLog(), process: proc, app }) + off() + expect(proc.listenerCount('uncaughtExceptionMonitor') + proc.listenerCount('unhandledRejection')).toBe(0) + expect(app.listenerCount('render-process-gone') + app.listenerCount('child-process-gone')).toBe(0) + }) +}) + +describe('watchWindowHealth', () => { + it('logs unresponsive, then responsive with how long it was, and hands the hang to the watch', () => { + const win = new EventEmitter() + const log = fakeLog() + let t = 1000 + const unresponsive = vi.fn() + watchWindowHealth(win, log, { unresponsive }, () => t) + win.emit('unresponsive') + t = 4500 + win.emit('responsive') + expect(log.lines.map((l) => [l.k, l.fields])).toEqual([ + ['unresponsive', {}], + ['responsive', { ms: 3500 }] + ]) + expect(unresponsive).toHaveBeenCalledTimes(1) + }) +}) diff --git a/core/main/crashHooks.ts b/core/main/crashHooks.ts new file mode 100644 index 0000000..4669fd4 --- /dev/null +++ b/core/main/crashHooks.ts @@ -0,0 +1,117 @@ +import { performance } from 'perf_hooks' +import type { DiagLog } from './diagLog' +import { errorFields } from './diagSummary' +import { createDiagGate } from '../shared/diagGate' + +/** + * ERRORS AND CRASHES, OBSERVED (#140). + * + * Observe only: nothing here changes what the app does when something goes + * wrong. An uncaught exception is heard on `uncaughtExceptionMonitor`, which + * Node calls BEFORE its own handling and which does not count as handling it. + * `unhandledRejection` does count, but Electron's main runs Node in warn + * mode: MEASURED on Electron 43, an unhandled rejection only printed a + * warning and the app ran on, with or without a listener, so the listener + * costs the console warning and nothing else. + * + * An exception and a process that went are written to disk AT ONCE + * (`flushSync`): the process may be about to end, and the 250 ms batch would + * lose exactly the line that explains why. A rejection goes in the batch. + */ + +/* eslint-disable @typescript-eslint/no-explicit-any */ +export interface EmitterLike { + on(event: string, listener: (...args: any[]) => void): unknown + removeListener(event: string, listener: (...args: any[]) => void): unknown +} +/* eslint-enable @typescript-eslint/no-explicit-any */ + +export interface CrashHookDeps { + log: DiagLog + /** Node's `process`. */ + process: EmitterLike + /** Electron's `app`. */ + app: EmitterLike + /** Monotonic ms, for the repeat gate. */ + now?: () => number +} + +/** Hooks the process and the app; returns the function that unhooks them. */ +export function hookCrashes({ log, process: proc, app, now = () => performance.now() }: CrashHookDeps): () => void { + const land = (k: string, fields: Record): void => { + try { + log.write('main', k, fields) + log.flushSync() + } catch { + /* the log never adds a second failure to the first */ + } + } + // The same error over and over (a rejection inside a poll) is one line per + // 10 s with a count, not a line each time (`shared/diagGate`). + const gate = createDiagGate>() + const gated = (k: string, fields: Record, sync: boolean): void => { + try { + const line = gate.offer(k, `${k}|${String(fields.msg)}`, fields, now()) + if (!line) return + if (sync) land(k, line) + else log.write('main', k, line) + } catch { + /* silent */ + } + } + const sweep = setInterval(() => { + try { + // `k` rides in the held fields for this; the writer keeps its own `k` + // and drops a field of that name. + for (const line of gate.sweep(now())) log.write('main', String(line.k), line) + } catch { + /* silent */ + } + }, 10_000) + sweep.unref?.() + const onError = (err: unknown, origin: unknown): void => + gated('main-error', { ...errorFields(err), origin: typeof origin === 'string' ? origin : null, k: 'main-error' }, true) + // NOT written synchronously: a rejection does not end the process + // (MEASURED, above), and a promise that rejects inside a poll would pay a + // sync mkdir and append on main's thread every cycle. The batch takes it. + const onRejection = (reason: unknown): void => gated('main-rejection', { ...errorFields(reason), k: 'main-rejection' }, false) + const onRenderGone = (_e: unknown, _wc: unknown, d: { reason?: string; exitCode?: number } = {}): void => + land('gone', { type: 'renderer', reason: d.reason ?? null, exitCode: d.exitCode ?? null }) + const onChildGone = (_e: unknown, d: { type?: string; reason?: string; exitCode?: number; name?: string } = {}): void => + land('gone', { type: d.type ?? null, reason: d.reason ?? null, exitCode: d.exitCode ?? null, name: d.name ?? null }) + + proc.on('uncaughtExceptionMonitor', onError) + proc.on('unhandledRejection', onRejection) + app.on('render-process-gone', onRenderGone) + app.on('child-process-gone', onChildGone) + return () => { + clearInterval(sweep) + proc.removeListener('uncaughtExceptionMonitor', onError) + proc.removeListener('unhandledRejection', onRejection) + app.removeListener('render-process-gone', onRenderGone) + app.removeListener('child-process-gone', onChildGone) + } +} + +/** + * A window's own hang events: `unresponsive` (Chromium's hang monitor gave + * up waiting on the page), then `responsive` with how long it lasted. The + * hang is handed to the stall watch, which writes the page's stack for it. + */ +export function watchWindowHealth( + win: EmitterLike, + log: DiagLog, + watch?: { unresponsive(): void }, + now: () => number = () => performance.now() +): void { + let since: number | null = null + win.on('unresponsive', () => { + since = now() + log.write('main', 'unresponsive', {}) + watch?.unresponsive() + }) + win.on('responsive', () => { + log.write('main', 'responsive', since === null ? {} : { ms: Math.round(now() - since) }) + since = null + }) +} diff --git a/core/main/diagIpc.test.ts b/core/main/diagIpc.test.ts new file mode 100644 index 0000000..cd219f1 --- /dev/null +++ b/core/main/diagIpc.test.ts @@ -0,0 +1,144 @@ +import { describe, expect, it, vi } from 'vitest' +import { EventEmitter } from 'events' +import { DGCH } from '../shared/channels' +import type { DiagLog, DiagSource } from './diagLog' +import { pageLine, registerDiagIpc, withStackPolicy, STACK_POLICY } from './diagIpc' + +class FakeIpcMain extends EventEmitter { + handlers = new Map unknown>() + handle(ch: string, fn: (e: unknown, ...a: unknown[]) => unknown): void { + this.handlers.set(ch, fn) + } + invoke(ch: string, ...a: unknown[]): unknown { + return this.handlers.get(ch)!({}, ...a) + } +} + +interface Line { + src: DiagSource + k: string + at?: number + fields: Record +} + +function fakeLog(verbose = false): DiagLog & { lines: Line[] } { + const lines: Line[] = [] + let v = verbose + return { + lines, + dir: 'C:\\Users\\x\\AppData\\Roaming\\PrismTerminal\\logs', + file: '', + write: (src, k, fields = {}) => lines.push({ src, k, fields }), + writeAt: (src, k, at, fields = {}) => lines.push({ src, k, at, fields }), + verbose: () => v, + setVerbose: (on) => { + v = on + }, + flush: async () => {}, + flushSync: () => {}, + failed: () => false, + close: () => {} + } +} + +const NOW = 1_800_000_000_000 + +describe('pageLine', () => { + it('takes a page kind and its time, and refuses a kind only main may write', () => { + expect(pageLine({ k: 'page-stall', at: NOW - 300, ms: 2500 }, NOW, false)).toEqual({ k: 'page-stall', at: NOW - 300, fields: { ms: 2500 } }) + expect(pageLine({ k: 'session', at: NOW }, NOW, false)).toBeNull() + expect(pageLine({ k: 'main-lag', at: NOW }, NOW, false)).toBeNull() + expect(pageLine(null, NOW, false)).toBeNull() + expect(pageLine({ k: 'not a kind!' }, NOW, false)).toBeNull() + }) + it("takes an app's own -slow kind (Prism's sort-slow)", () => { + expect(pageLine({ k: 'sort-slow', at: NOW, ms: 80 }, NOW, false)?.k).toBe('sort-slow') + }) + it('reads a time that is missing or far off as now', () => { + expect(pageLine({ k: 'crumb', a: 'x' }, NOW, false)?.at).toBe(NOW) + expect(pageLine({ k: 'crumb', at: NOW - 3 * 86_400_000 }, NOW, false)?.at).toBe(NOW) + }) + it('keeps the high-rate lines for verbose only', () => { + expect(pageLine({ k: 'page-task', at: NOW, ms: 60 }, NOW, false)).toBeNull() + expect(pageLine({ k: 'page-task', at: NOW, ms: 60 }, NOW, true)).not.toBeNull() + expect(pageLine({ k: 'crumb', at: NOW, a: 'scroll', often: true }, NOW, false)).toBeNull() + expect(pageLine({ k: 'crumb', at: NOW, a: 'scroll', often: true }, NOW, true)?.fields).toEqual({ a: 'scroll' }) + }) +}) + +describe('registerDiagIpc', () => { + const setup = (verbose = false) => { + const ipcMain = new FakeIpcMain() + const log = fakeLog(verbose) + const watch = { beat: vi.fn(), pageStall: vi.fn() } + const openFolder = vi.fn() + registerDiagIpc({ ipcMain, log, watch, openFolder, wall: () => NOW }) + return { ipcMain, log, watch, openFolder } + } + + it("writes the page's batch, and tells the watch about each stall", () => { + const { ipcMain, log, watch } = setup() + ipcMain.emit(DGCH.batch, {}, [ + { k: 'crumb', at: NOW - 500, a: 'tab-open' }, + { k: 'page-stall', at: NOW - 400, ms: 2600, scripts: [{ src: 'index.js', fn: 'spin', ms: 2590 }] }, + { k: 'session', at: NOW } + ]) + expect(log.lines.map((l) => [l.src, l.k])).toEqual([ + ['page', 'crumb'], + ['page', 'page-stall'] + ]) + expect(watch.pageStall).toHaveBeenCalledWith(NOW - 400, 2600) + }) + + it('ignores a batch that is not a list, and caps a long one', () => { + const { ipcMain, log } = setup() + ipcMain.emit(DGCH.batch, {}, 'nope') + ipcMain.emit(DGCH.batch, {}, Array.from({ length: 500 }, () => ({ k: 'crumb', at: NOW }))) + expect(log.lines.length).toBe(200) + }) + + it('hears the beat', () => { + const { ipcMain, watch } = setup() + ipcMain.emit(DGCH.beat, {}) + expect(watch.beat).toHaveBeenCalledTimes(1) + }) + + it('answers info and the verbose switch', async () => { + const { ipcMain, log } = setup() + expect(await ipcMain.invoke(DGCH.info)).toEqual({ verbose: false, dir: log.dir }) + expect(await ipcMain.invoke(DGCH.setVerbose, true)).toBe(true) + expect(log.verbose()).toBe(true) + expect(await ipcMain.invoke(DGCH.setVerbose, 'yes')).toBe(true) + }) + + it('opens its own folder and never one the page names', () => { + const { ipcMain, openFolder, log } = setup() + ipcMain.emit(DGCH.openFolder, {}, 'C:\\Windows') + expect(openFolder).toHaveBeenCalledWith(log.dir) + }) + + it('writes a mark with its note, capped', () => { + const { ipcMain, log } = setup() + ipcMain.emit(DGCH.mark, {}, 'it stalled opening Downloads') + ipcMain.emit(DGCH.mark, {}) + expect(log.lines.map((l) => [l.src, l.k, l.fields.note])).toEqual([ + ['page', 'mark', 'it stalled opening Downloads'], + ['page', 'mark', null] + ]) + }) +}) + +describe('withStackPolicy', () => { + it('adds the Document-Policy header that lets main read the page stack, keeping the rest', () => { + const out = withStackPolicy({ 'Content-Type': ['text/html'] }) + expect(out).toEqual({ 'Content-Type': ['text/html'], 'Document-Policy': [STACK_POLICY] }) + }) + it('joins a Document-Policy the response already had', () => { + const out = withStackPolicy({ 'document-policy': ['force-load-at-top'] }) + expect(out['document-policy']).toEqual([`force-load-at-top, ${STACK_POLICY}`]) + }) + it('leaves one that already opts in alone', () => { + const out = withStackPolicy({ 'Document-Policy': [STACK_POLICY] }) + expect(out['Document-Policy']).toEqual([STACK_POLICY]) + }) +}) diff --git a/core/main/diagIpc.ts b/core/main/diagIpc.ts new file mode 100644 index 0000000..8a6b7f6 --- /dev/null +++ b/core/main/diagIpc.ts @@ -0,0 +1,100 @@ +import { DGCH } from '../shared/channels' +import type { DiagLog } from './diagLog' +import type { IpcMainLike } from './ipc' + +/** + * THE MAIN HALF OF THE DIAGNOSTICS BRIDGE (#140), for both hosts. The preload + * half is `core/preload/diagApi`; `startDiagnostics` registers this. + * + * The page's lines arrive here in batches and are held to the page's own + * kinds: a renderer cannot write a `session` or a `main-lag`, so a line's + * source is always true. The folder Open folder opens is the log's own, + * never a path the page sends. + */ + +export interface DiagIpcDeps { + ipcMain: IpcMainLike + log: DiagLog + watch?: { beat(): void; pageStall(startAt: number, ms: number): void } + /** Show a folder in Explorer. Under --e2e the host records instead. */ + openFolder(dir: string): void + wall?: () => number +} + +/** The kinds a page may write. An app's own timing kinds end in `-slow` + * (Prism's `sort-slow`, `guard-slow`), written through `diag.time`. */ +const PAGE_KINDS = new Set(['page-stall', 'page-task', 'page-error', 'page-rejection', 'crumb']) +const KIND = /^[a-z][a-z-]{1,30}$/ +/** Lines only Detailed logging keeps. */ +const VERBOSE_ONLY = new Set(['page-task']) +const MAX_BATCH = 200 +const DAY = 86_400_000 + +/** One line of a page batch as it will be written, or null to drop it. */ +export function pageLine( + raw: unknown, + wallNow: number, + verbose: boolean +): { k: string; at: number; fields: Record } | null { + if (!raw || typeof raw !== 'object' || Array.isArray(raw)) return null + const { k, at, often, ...fields } = raw as Record + if (typeof k !== 'string' || !KIND.test(k)) return null + if (!PAGE_KINDS.has(k) && !k.endsWith('-slow')) return null + if (!verbose && (VERBOSE_ONLY.has(k) || often === true)) return null + const when = typeof at === 'number' && Number.isFinite(at) && Math.abs(wallNow - at) < DAY ? at : wallNow + return { k, at: when, fields } +} + +export function registerDiagIpc(deps: DiagIpcDeps): void { + const { ipcMain, log } = deps + const wall = deps.wall ?? Date.now + + ipcMain.on(DGCH.batch, (_e: unknown, batch: unknown) => { + if (!Array.isArray(batch)) return + const verbose = log.verbose() + for (const raw of batch.slice(0, MAX_BATCH)) { + const line = pageLine(raw, wall(), verbose) + if (!line) continue + log.writeAt('page', line.k, line.at, line.fields) + if (line.k === 'page-stall' && typeof line.fields.ms === 'number') deps.watch?.pageStall(line.at, line.fields.ms) + } + }) + + ipcMain.on(DGCH.beat, () => deps.watch?.beat()) + + ipcMain.handle(DGCH.info, () => ({ verbose: log.verbose(), dir: log.dir })) + + ipcMain.handle(DGCH.setVerbose, (_e: unknown, on: unknown) => { + if (typeof on === 'boolean') log.setVerbose(on) + return log.verbose() + }) + + ipcMain.on(DGCH.openFolder, () => { + if (log.dir) deps.openFolder(log.dir) + }) + + ipcMain.on(DGCH.mark, (_e: unknown, note: unknown) => { + log.write('page', 'mark', { note: typeof note === 'string' && note.trim() ? note.trim() : null }) + }) +} + +/** The Document-Policy that lets main read the page's JavaScript stack + * (`collectJavaScriptCallStack`). MEASURED on Electron 43: without it the + * frame answers "Website owner has not opted in"; with it, served through + * `session.webRequest.onHeadersReceived`, the stack came back for a + * `file://` page and a dev server's `http://` page alike. */ +export const STACK_POLICY = 'include-js-call-stacks-in-crash-reports' + +/** A response's headers with the stack policy added, for the host's + * `onHeadersReceived` (the core never touches a session itself). */ +export function withStackPolicy(headers: Record | undefined): Record { + const out: Record = {} + let key: string | null = null + for (const [k, v] of Object.entries(headers ?? {})) { + out[k] = Array.isArray(v) ? [...v] : [v] + if (k.toLowerCase() === 'document-policy') key = k + } + if (!key) out['Document-Policy'] = [STACK_POLICY] + else if (!out[key].join(',').includes(STACK_POLICY)) out[key] = [[...out[key], STACK_POLICY].join(', ')] + return out +} diff --git a/core/main/diagLog.test.ts b/core/main/diagLog.test.ts new file mode 100644 index 0000000..e19bf1d --- /dev/null +++ b/core/main/diagLog.test.ts @@ -0,0 +1,197 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { existsSync, mkdirSync, mkdtempSync, readFileSync, rmSync, writeFileSync } from 'fs' +import { tmpdir } from 'os' +import { join } from 'path' +import { createDiagLog, diagMain, NULL_DIAG_LOG, setDiagMain, type DiagLog } from './diagLog' + +const scratch = (): string => mkdtempSync(join(tmpdir(), 'pt-diag-')) +const lines = (file: string): Array> => + existsSync(file) + ? readFileSync(file, 'utf8') + .split('\n') + .filter(Boolean) + .map((l) => JSON.parse(l) as Record) + : [] + +let open: DiagLog[] = [] +const make = (opts: Parameters[0]): DiagLog => { + const log = createDiagLog(opts) + open.push(log) + return log +} +afterEach(() => { + for (const l of open) l.close() + open = [] + vi.useRealTimers() +}) + +describe('createDiagLog', () => { + it('writes one flat JSON object per line, with the time, the uptime, the source and the kind', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir, now: () => Date.UTC(2026, 9, 7, 9, 12, 3, 412), uptime: () => 12345 }) + log.write('main', 'main-lag', { ms: 140 }) + await log.flush() + expect(lines(log.file)).toEqual([{ t: '2026-10-07T09:12:03.412Z', up: 12345, src: 'main', k: 'main-lag', ms: 140 }]) + }) + + it('batches the appends and keeps their order', async () => { + vi.useFakeTimers() + const dir = join(scratch(), 'logs') + const log = make({ dir }) + log.write('main', 'crumb', { a: 'one' }) + log.write('page', 'crumb', { a: 'two' }) + expect(lines(log.file)).toEqual([]) + await vi.advanceTimersByTimeAsync(300) + await log.flush() + expect(lines(log.file).map((l) => l.a)).toEqual(['one', 'two']) + }) + + it('flushes synchronously at quit, so the last line before a crash lands', () => { + const dir = join(scratch(), 'logs') + const log = make({ dir }) + log.write('main', 'crumb', { a: 'last' }) + log.flushSync() + expect(lines(log.file).map((l) => l.a)).toEqual(['last']) + }) + + it('rotates at the cap to .1 through .4, so an app never holds more than five files', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir, maxBytes: 1000 }) + for (let round = 0; round < 7; round += 1) { + for (let i = 0; i < 12; i += 1) log.write('main', 'crumb', { a: `r${round}-${i}`, pad: 'p'.repeat(40) }) + await log.flush() + } + expect(existsSync(log.file)).toBe(true) + for (const n of [1, 2, 3, 4]) expect(existsSync(`${log.file}.${n}`), `.${n}`).toBe(true) + expect(existsSync(`${log.file}.5`)).toBe(false) + // The newest line is in the live file, and no file grew far past the cap. + expect(lines(log.file).at(-1)?.a).toBe('r6-11') + for (const f of [log.file, `${log.file}.1`]) expect(readFileSync(f).length).toBeLessThan(2000) + }) + + it('keeps writing when a rotation fails, says so once, and rotates again later', async () => { + const dir = join(scratch(), 'logs') + let up = 1000 + const log = make({ dir, maxBytes: 300, uptime: () => up }) + // A folder with a file in it where `.4` goes: `rmSync` without recursive + // refuses it, as a rename refuses a file held open without share-delete. + mkdirSync(join(dir, 'diag.jsonl.4'), { recursive: true }) + writeFileSync(join(dir, 'diag.jsonl.4', 'held'), 'x') + for (let round = 0; round < 5; round += 1) { + for (let i = 0; i < 4; i += 1) log.write('main', 'crumb', { a: `r${round}-${i}`, pad: 'p'.repeat(40) }) + await log.flush() + } + const live = lines(log.file) + // Nothing was dropped: every line is in the live file, with the reason. + for (let round = 0; round < 5; round += 1) + for (let i = 0; i < 4; i += 1) expect(live.some((l) => l.a === `r${round}-${i}`)).toBe(true) + expect(live.filter((l) => l.k === 'logger-error')).toHaveLength(1) + expect(log.failed()).toBe(true) + expect(existsSync(`${log.file}.1`)).toBe(false) + // The obstacle goes; 30 s later the rotation is tried again and works. + rmSync(join(dir, 'diag.jsonl.4'), { recursive: true, force: true }) + up += 30_000 + log.write('main', 'crumb', { a: 'after', pad: 'p'.repeat(40) }) + await log.flush() + expect(existsSync(`${log.file}.1`)).toBe(true) + expect(lines(log.file).map((l) => l.a)).toEqual(['after']) + }) + + it('writes a batch the async path took ahead of the quit lines, never after them or twice', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir }) + log.write('main', 'crumb', { a: 'before' }) + const pending = log.flush() + // Let the async path take the batch and start its append. + for (let i = 0; i < 5; i += 1) await Promise.resolve() + log.write('main', 'quit', {}) + log.flushSync() + expect(lines(log.file).map((l) => l.a ?? l.k)).toEqual(['before', 'quit']) + await pending + expect(lines(log.file).map((l) => l.a ?? l.k)).toEqual(['before', 'quit']) + }) + + it('drops the newest lines of a flood, not the first, and counts them', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir }) + for (let i = 0; i < 2500; i += 1) log.write('page', 'page-error', { msg: `e${i}` }) + await log.flush() + const got = lines(log.file) + expect(got[0].msg).toBe('e0') + expect(got.filter((l) => l.k === 'page-error')).toHaveLength(2000) + expect(got.at(-1)).toMatchObject({ k: 'logger-dropped', n: 500 }) + }) + + it('picks up an existing file size, so a relaunch rotates on time too', async () => { + const dir = join(scratch(), 'logs') + const first = make({ dir, maxBytes: 500 }) + mkdirSync(dir, { recursive: true }) + writeFileSync(first.file, 'x'.repeat(490) + '\n') + first.close() + const log = make({ dir, maxBytes: 500 }) + log.write('main', 'crumb', { a: 'after' }) + await log.flush() + expect(existsSync(`${log.file}.1`)).toBe(true) + expect(lines(log.file).map((l) => l.a)).toEqual(['after']) + }) + + it('remembers the verbose switch across a relaunch, and logs the change', async () => { + const root = scratch() + const dir = join(root, 'logs') + const log = make({ dir }) + expect(log.verbose()).toBe(false) + log.setVerbose(true) + await log.flush() + expect(lines(log.file).at(-1)).toMatchObject({ k: 'verbose', on: true }) + expect(JSON.parse(readFileSync(join(root, 'diag.json'), 'utf8'))).toEqual({ verbose: true }) + log.close() + expect(make({ dir }).verbose()).toBe(true) + }) + + it('reads a damaged state file as quiet', () => { + const root = scratch() + writeFileSync(join(root, 'diag.json'), '{not json') + expect(make({ dir: join(root, 'logs') }).verbose()).toBe(false) + }) + + it('never throws, and says once that it could not write', async () => { + const root = scratch() + // A FILE where the folder should be: every write fails. + const dir = join(root, 'logs') + writeFileSync(dir, 'in the way') + const log = make({ dir }) + expect(() => log.write('main', 'crumb', { a: 'x' })).not.toThrow() + await expect(log.flush()).resolves.toBeUndefined() + expect(() => log.flushSync()).not.toThrow() + expect(log.failed()).toBe(true) + }) + + it('keeps its own four keys whatever the fields say (MEASURED: a page error named its script src)', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir, uptime: () => 7 }) + log.write('page', 'page-error', { src: null, k: 'session', up: 0, t: 'x', msg: 'm' }) + await log.flush() + expect(lines(log.file)[0]).toMatchObject({ src: 'page', k: 'page-error', up: 7, msg: 'm' }) + }) + + it('caps what a caller hands it', async () => { + const dir = join(scratch(), 'logs') + const log = make({ dir }) + log.write('page', 'page-error', { msg: 'm'.repeat(1000) }) + await log.flush() + expect((lines(log.file)[0].msg as string).length).toBeLessThan(320) + }) +}) + +describe('diagMain', () => { + it('is a log that writes nothing until a host starts one', () => { + expect(diagMain()).toBe(NULL_DIAG_LOG) + expect(() => diagMain().write('main', 'crumb', {})).not.toThrow() + const dir = join(scratch(), 'logs') + const log = make({ dir }) + setDiagMain(log) + expect(diagMain()).toBe(log) + setDiagMain(null) + expect(diagMain()).toBe(NULL_DIAG_LOG) + }) +}) diff --git a/core/main/diagLog.ts b/core/main/diagLog.ts new file mode 100644 index 0000000..6948921 --- /dev/null +++ b/core/main/diagLog.ts @@ -0,0 +1,347 @@ +import { appendFileSync, mkdirSync, readFileSync, renameSync, rmSync, statSync, writeFileSync } from 'fs' +import { open } from 'fs/promises' +import { dirname, join } from 'path' +import { performance } from 'perf_hooks' +import { cleanFields, errorFields } from './diagSummary' + +/** + * THE DIAGNOSTICS LOG'S WRITER (#140; owner, 2026-10-07: "implement some + * robust logging and debugging into the program especially to catch stalls"). + * For both hosts; spec `docs/superpowers/specs/2026-10-07-diagnostics-log-design.md`, + * schema `docs/diagnostics.md`. + * + * `\logs\diag.jsonl`, one JSON object per line. Appends are batched + * every 250 ms through one queue, so a burst of lines is one write and the + * order is the order they were said in. At 2 MB the file rotates to `.1` + * through `.4`, so an app holds at most 10 MB. At quit the queue is written + * SYNCHRONOUSLY (`flushSync`), so the line just before a crash lands. + * + * A LOGGER THAT FAILS IS SILENT. A write never throws into its caller: the + * first failure queues one `logger-error` line (which lands if the next write + * works, as after a moment's file lock) and the rest are dropped quietly. + * Nothing here may take the app down to report that the app is slow. + * + * A ROTATION THAT FAILS DOES NOT STOP THE LOG (review of #140). Renaming the + * full file fails with EBUSY or EPERM while something holds it open without + * share-delete (an editor, `Get-Content -Wait`, an antivirus scan). The batch + * is then appended to the live file anyway and the rotation is tried again + * 30 s later: before, every flush retried, failed and dropped its lines, the + * `logger-error` line with them, and the log went quiet for the session. + */ + +export type DiagSource = 'main' | 'page' + +export interface DiagLog { + /** The folder the files are in (Settings' Open folder). */ + readonly dir: string + /** The live file, `diag.jsonl`. */ + readonly file: string + write(src: DiagSource, k: string, fields?: Record): void + /** A page line whose own clock said when: `at` is its epoch ms. */ + writeAt(src: DiagSource, k: string, at: number, fields?: Record): void + /** Detailed logging (Settings > Diagnostics), remembered in `\diag.json`. */ + verbose(): boolean + setVerbose(on: boolean): void + /** Write what is queued now; resolves when it is on disk (or dropped). */ + flush(): Promise + /** The quit path's write: synchronous, so it lands before the process ends. */ + flushSync(): void + /** Did any write fail this session? */ + failed(): boolean + /** Stop the timer and write what is left. */ + close(): void +} + +export interface DiagLogOptions { + /** `\logs`. */ + dir: string + /** Where the verbose switch is kept: `\diag.json` by default. */ + stateFile?: string + /** Epoch ms, for `t`. */ + now?: () => number + /** Ms since the app started, for `up`: a clock change cannot reorder it. */ + uptime?: () => number + maxBytes?: number + flushMs?: number +} + +export const DIAG_FILE = 'diag.jsonl' +export const DIAG_MAX_BYTES = 2 * 1024 * 1024 +/** Rotated files kept beside the live one: `.1` (newest) to `.4`. */ +export const DIAG_KEEP = 4 +/** Every line's own keys, in this order, before its fields. */ +const LINE_KEYS = ['t', 'up', 'src', 'k'] as const +/** The writer's queue, at most. Past it the NEWEST lines are dropped and + * counted (`logger-dropped`): the first lines of a flood say what started it. */ +const QUEUE_MAX = 2000 +/** How long a failed rotation waits before it is tried again (uptime ms). */ +const ROTATE_RETRY_MS = 30_000 + +export function createDiagLog(opts: DiagLogOptions): DiagLog { + const dir = opts.dir + const file = join(dir, DIAG_FILE) + const stateFile = opts.stateFile ?? join(dirname(dir), 'diag.json') + const now = opts.now ?? Date.now + const uptime = opts.uptime ?? ((): number => Math.round(performance.now())) + const maxBytes = opts.maxBytes ?? DIAG_MAX_BYTES + const flushMs = opts.flushMs ?? 250 + + let verbose = readVerbose(stateFile) + let size = fileSize(file) + let queue: string[] = [] + let timer: ReturnType | null = null + let chain: Promise = Promise.resolve() + let anyFailed = false + let reported = false + let closed = false + let dirReady = false + let dropped = 0 + let rotateAfter = 0 + /** + * The batch the async path has taken and not yet seen land. `flushSync` + * (the quit, a crash) writes it first, ahead of what is queued, so the + * lines before the event are neither lost with the process nor written + * after it; `done` keeps the async path from counting it twice. + */ + let inflightBatch: { text: string; bytes: number; done: boolean } | null = null + + const line = (src: DiagSource, k: string, at: number, up: number, fields?: Record): string => { + let t: string + try { + t = new Date(at).toISOString() + } catch { + t = new Date(now()).toISOString() + } + // The four line keys are the writer's: a field named `src` (a page error's + // script, once) must not overwrite where the line came from. + const rest = cleanFields(fields ?? {}) + for (const key of LINE_KEYS) delete rest[key] + return JSON.stringify({ t, up, src, k, ...rest }) + '\n' + } + + const schedule = (): void => { + if (timer || closed) return + timer = setTimeout(() => { + timer = null + void flush() + }, flushMs) + timer.unref?.() + } + + const fail = (err: unknown): void => { + anyFailed = true + if (reported) return + reported = true + // Lands only if a later write works (a lock that passed); never retried. + try { + queue.unshift(line('main', 'logger-error', now(), uptime(), errorFields(err))) + } catch { + /* silent */ + } + } + + /** The folder is made once, and again only after a write failed (it may + * have been removed): an `mkdir` per flush was one more call on the fs + * threadpool that the canary measures. */ + const ensureDir = (): void => { + if (dirReady) return + mkdirSync(dir, { recursive: true }) + dirReady = true + } + + /** Rotation, synchronous: it happens once per 2 MB, and renames are fast. + * It never throws: a file held open stays the live one a while longer. */ + const rotateIfFull = (incoming: number): void => { + if (size === 0 || size + incoming <= maxBytes) return + if (uptime() < rotateAfter) return + try { + rmSync(`${file}.${DIAG_KEEP}`, { force: true }) + for (let n = DIAG_KEEP - 1; n >= 1; n -= 1) { + try { + renameSync(`${file}.${n}`, `${file}.${n + 1}`) + } catch { + /* that one did not exist yet */ + } + } + renameSync(file, `${file}.1`) + size = 0 + } catch (err) { + rotateAfter = uptime() + ROTATE_RETRY_MS + fail(err) + } + } + + /** Did the async write of `b` reach the file already? Its callback has + * not run, but the threadpool may have done the write. If it is still + * queued (a starved pool), it is written here too: at a quit the queued + * one never runs, and after a `main-error` a batch twice beats none. */ + const landed = (b: { bytes: number }): boolean => fileSize(file) >= size + b.bytes + + const take = (): string | null => { + if (dropped > 0) { + try { + queue.push(line('main', 'logger-dropped', now(), uptime(), { n: dropped })) + } catch { + /* silent */ + } + dropped = 0 + } + if (queue.length === 0) return null + const text = queue.join('') + queue = [] + return text + } + + const flush = (): Promise => { + if (timer) { + clearTimeout(timer) + timer = null + } + chain = chain.then(async () => { + const text = take() + if (text === null) return + const batch = { text, bytes: Buffer.byteLength(text), done: false } + try { + ensureDir() + rotateIfFull(batch.bytes) + inflightBatch = batch + // Opened, then written, and not `appendFile`: the open is a threadpool + // round trip of its own, and a `flushSync` that lands in it has + // already written this batch (MEASURED in the unit test: with + // `appendFile` the batch came out after the quit line, then again). + const fh = await open(file, 'a') + try { + if (batch.done) return + await fh.writeFile(text) + } finally { + await fh.close().catch(() => {}) + } + if (!batch.done) size += batch.bytes + } catch (err) { + if (!batch.done) { + dirReady = false + fail(err) + } + } finally { + batch.done = true + if (inflightBatch === batch) inflightBatch = null + } + }) + return chain + } + + const flushSync = (): void => { + if (timer) { + clearTimeout(timer) + timer = null + } + let text = take() ?? '' + const pending = inflightBatch + if (pending && !pending.done) { + // Taken by the async path and still on its way: written here, first, + // unless the threadpool has already put it in the file. + pending.done = true + inflightBatch = null + if (landed(pending)) size += pending.bytes + else text = pending.text + text + } + if (!text) return + try { + ensureDir() + const bytes = Buffer.byteLength(text) + rotateIfFull(bytes) + appendFileSync(file, text) + size += bytes + } catch (err) { + dirReady = false + fail(err) + } + } + + const writeAt = (src: DiagSource, k: string, at: number, fields?: Record): void => { + if (closed) return + try { + // `up` for a line said earlier (a page batch) is moved back by its age. + const age = Math.max(0, now() - at) + if (queue.length >= QUEUE_MAX) { + dropped += 1 + return + } + queue.push(line(src, k, at, Math.max(0, uptime() - age), fields)) + schedule() + } catch (err) { + fail(err) + } + } + + return { + dir, + file, + write: (src, k, fields) => writeAt(src, k, now(), fields), + writeAt, + verbose: () => verbose, + setVerbose: (on) => { + if (on === verbose) return + verbose = on + try { + mkdirSync(dirname(stateFile), { recursive: true }) + writeFileSync(stateFile, JSON.stringify({ verbose })) + } catch (err) { + fail(err) + } + writeAt('main', 'verbose', now(), { on }) + }, + flush, + flushSync, + failed: () => anyFailed, + close: () => { + if (closed) return + flushSync() + closed = true + } + } +} + +function readVerbose(stateFile: string): boolean { + try { + const v = JSON.parse(readFileSync(stateFile, 'utf8')) as { verbose?: unknown } + return v?.verbose === true + } catch { + return false + } +} + +function fileSize(file: string): number { + try { + return statSync(file).size + } catch { + return 0 + } +} + +/** The log of a host that gave no folder (`diagLogDir`): it writes nothing, + * so Prism is unchanged until it wires one. */ +export const NULL_DIAG_LOG: DiagLog = { + dir: '', + file: '', + write: () => {}, + writeAt: () => {}, + verbose: () => false, + setVerbose: () => {}, + flush: () => Promise.resolve(), + flushSync: () => {}, + failed: () => false, + close: () => {} +} + +let current: DiagLog = NULL_DIAG_LOG + +/** The running app's log, for code deep in main (a shell spawned, a shell + * gone) that should not need one handed through every call. The null log + * until the host starts diagnostics. */ +export const diagMain = (): DiagLog => current + +/** Set by `startDiagnostics`; null puts the null log back. */ +export function setDiagMain(log: DiagLog | null): void { + current = log ?? NULL_DIAG_LOG +} diff --git a/core/main/diagSummary.test.ts b/core/main/diagSummary.test.ts new file mode 100644 index 0000000..12fd56e --- /dev/null +++ b/core/main/diagSummary.test.ts @@ -0,0 +1,82 @@ +import { describe, expect, it } from 'vitest' +import { capString, cleanFields, errorFields, STACK_MAX, STRING_MAX, summariseArgs, summariseValue } from './diagSummary' + +describe('capString', () => { + it('leaves a short string alone and cuts a long one at the cap, saying so', () => { + expect(capString('abc')).toBe('abc') + const long = 'x'.repeat(STRING_MAX + 50) + const cut = capString(long) + expect(cut.length).toBeLessThanOrEqual(STRING_MAX + 12) + expect(cut.endsWith('(+50)')).toBe(true) + }) +}) + +describe('summariseValue', () => { + it('keeps primitives, caps strings, and logs an array as its length', () => { + expect(summariseValue(5)).toBe(5) + expect(summariseValue(true)).toBe(true) + expect(summariseValue(null)).toBe(null) + expect(summariseValue(undefined)).toBe(null) + expect(summariseValue([1, 2, 3])).toBe('[3]') + expect(summariseValue('y'.repeat(400))).toMatch(/\(\+100\)$/) + }) + it('logs bytes by size, never by content', () => { + expect(summariseValue(new Uint8Array(1234))).toBe('bytes:1234') + }) + it('flattens an object one level, deeper ones as their key count', () => { + expect(summariseValue({ a: 'x', b: [1, 2], c: { d: 1, e: 2 } })).toEqual({ a: 'x', b: '[2]', c: '{2}' }) + }) + it('stops at twelve keys', () => { + const big = Object.fromEntries(Array.from({ length: 20 }, (_, i) => [`k${i}`, i])) + expect(Object.keys(summariseValue(big) as object)).toHaveLength(12) + }) +}) + +describe('summariseArgs', () => { + it('summarises the first four arguments', () => { + expect(summariseArgs(['C:\\a', 2, [1], { x: 1 }, 'dropped'])).toEqual(['C:\\a', 2, '[1]', { x: 1 }]) + }) + it('logs an opaque channel argument as its kind and size alone', () => { + // Typed text and the clipboard are what somebody would not want written down. + expect(summariseArgs(['id-1', 'secret typed text'], true)).toEqual(['string:4', 'string:17']) + }) +}) + +describe('errorFields', () => { + it('takes the message and a longer stack from an Error', () => { + const e = new Error('nope') + const f = errorFields(e) + expect(f.msg).toBe('nope') + expect(typeof f.stack).toBe('string') + }) + it('reads anything thrown, a string or a plain object', () => { + expect(errorFields('bad')).toEqual({ msg: 'bad' }) + expect(errorFields({ message: 'obj' }).msg).toBe('obj') + expect(errorFields(undefined).msg).toBe('undefined') + }) + it('caps a stack at its own, longer cap', () => { + const e = new Error('x') + e.stack = 's'.repeat(STACK_MAX * 2) + expect(errorFields(e).stack!.length).toBeLessThanOrEqual(STACK_MAX + 12) + }) +}) + +describe('cleanFields', () => { + it('caps strings, keeps small lists of records, and drops what JSON cannot say', () => { + const out = cleanFields({ + s: 'z'.repeat(400), + stack: 'q'.repeat(1000), + scripts: [{ src: 'a', ms: 1 }], + n: Number.NaN, + f: () => 1 + }) + expect((out.s as string).length).toBeLessThan(330) + expect((out.stack as string).length).toBe(1000) + expect(out.scripts).toEqual([{ src: 'a', ms: 1 }]) + expect(out.n).toBe(null) + expect('f' in out).toBe(false) + }) + it('keeps at most ten items of a list', () => { + expect((cleanFields({ l: Array.from({ length: 30 }, (_, i) => i) }).l as unknown[]).length).toBe(10) + }) +}) diff --git a/core/main/diagSummary.ts b/core/main/diagSummary.ts new file mode 100644 index 0000000..a9ef6f0 --- /dev/null +++ b/core/main/diagSummary.ts @@ -0,0 +1,100 @@ +/** + * WHAT A DIAGNOSTICS LINE MAY HOLD (#140). Pure, for both hosts. + * + * A line is one flat JSON object, short enough that a 2 MB file holds hours of + * a quiet day and that `npm run diag` can print it on one row. So a string is + * capped at 300 characters, a stack at 2000 (300 is about two frames, and the + * frames are the point of a stack), an array of IPC arguments is logged as its + * length, and an object one level deep. Paths are kept in full (owner, + * 2026-10-07: the log stays local); typed text and the clipboard are not + * (`opaque`), since a slow keystroke would otherwise write the keystroke down. + */ + +export const STRING_MAX = 300 +export const STACK_MAX = 2000 +/** Fields whose strings take the longer cap. */ +const LONG_FIELDS = new Set(['stack']) +const MAX_KEYS = 12 +const MAX_ITEMS = 10 +const MAX_ARGS = 4 + +/** A string at most `max` characters, a cut one ending in how much was cut. */ +export function capString(s: string, max = STRING_MAX): string { + return s.length <= max ? s : `${s.slice(0, max)}...(+${s.length - max})` +} + +/** One value as an IPC argument is logged: primitives as they are, a string + * capped, an array as `[n]`, bytes as `bytes:n`, an object one level deep. */ +export function summariseValue(v: unknown, depth = 0): unknown { + if (v === null || v === undefined) return null + if (typeof v === 'string') return capString(v) + if (typeof v === 'number') return Number.isFinite(v) ? v : null + if (typeof v === 'boolean') return v + if (typeof v === 'bigint') return String(v) + if (typeof v === 'function' || typeof v === 'symbol') return typeof v + if (ArrayBuffer.isView(v)) return `bytes:${v.byteLength}` + if (v instanceof ArrayBuffer) return `bytes:${v.byteLength}` + if (Array.isArray(v)) return `[${v.length}]` + if (typeof v === 'object') { + const keys = Object.keys(v as object) + if (depth > 0) return `{${keys.length}}` + const out: Record = {} + for (const k of keys.slice(0, MAX_KEYS)) out[k] = summariseValue((v as Record)[k], depth + 1) + return out + } + return null +} + +/** The arguments of an IPC call as `ipc-slow` logs them. An OPAQUE channel + * (typed text, the clipboard, audio) says only each argument's kind and size. */ +export function summariseArgs(args: readonly unknown[], opaque = false): unknown[] { + const first = args.slice(0, MAX_ARGS) + if (!opaque) return first.map((a) => summariseValue(a)) + return first.map((a) => { + if (typeof a === 'string') return `string:${a.length}` + if (ArrayBuffer.isView(a)) return `bytes:${a.byteLength}` + if (Array.isArray(a)) return `[${a.length}]` + return typeof a + }) +} + +/** Anything thrown, as `msg` and (when there is one) `stack`. */ +export function errorFields(err: unknown): { msg: string; stack?: string } { + if (err instanceof Error) { + return err.stack ? { msg: capString(err.message), stack: capString(err.stack, STACK_MAX) } : { msg: capString(err.message) } + } + if (err && typeof err === 'object' && typeof (err as { message?: unknown }).message === 'string') { + const o = err as { message: string; stack?: unknown } + return typeof o.stack === 'string' + ? { msg: capString(o.message), stack: capString(o.stack, STACK_MAX) } + : { msg: capString(o.message) } + } + return { msg: capString(String(err)) } +} + +/** + * A line's fields made safe to write: every string capped (a `stack` at its + * own cap), a list kept to ten items, records inside a list cleaned the same + * way one level down, and what JSON cannot say dropped. The page's lines come + * through here too: they are text from a renderer, held to the same shape. + */ +export function cleanFields(fields: Record, depth = 0): Record { + const out: Record = {} + for (const [k, v] of Object.entries(fields).slice(0, depth === 0 ? 40 : MAX_KEYS)) { + const c = cleanValue(k, v, depth) + if (c !== undefined) out[k] = c + } + return out +} + +function cleanValue(key: string, v: unknown, depth: number): unknown { + if (v === null || v === undefined) return null + if (typeof v === 'string') return capString(v, LONG_FIELDS.has(key) ? STACK_MAX : STRING_MAX) + if (typeof v === 'number') return Number.isFinite(v) ? v : null + if (typeof v === 'boolean') return v + if (typeof v === 'function' || typeof v === 'symbol') return undefined + if (depth >= 2) return summariseValue(v, 1) + if (Array.isArray(v)) return v.slice(0, MAX_ITEMS).map((x) => cleanValue(key, x, depth + 1) ?? null) + if (typeof v === 'object') return cleanFields(v as Record, depth + 1) + return String(v) +} diff --git a/core/main/diagnostics.test.ts b/core/main/diagnostics.test.ts new file mode 100644 index 0000000..4575e8f --- /dev/null +++ b/core/main/diagnostics.test.ts @@ -0,0 +1,58 @@ +import { describe, expect, it } from 'vitest' +import { EventEmitter } from 'events' +import { existsSync, mkdtempSync, readFileSync } from 'fs' +import { tmpdir } from 'os' +import { join } from 'path' +import { DGCH } from '../shared/channels' +import { diagMain, NULL_DIAG_LOG } from './diagLog' +import { startDiagnostics } from './diagnostics' + +class FakeIpcMain extends EventEmitter { + handlers = new Map unknown>() + handle(ch: string, fn: (e: unknown, ...a: unknown[]) => unknown): void { + this.handlers.set(ch, fn) + } +} + +describe('startDiagnostics', () => { + it('logs nothing for a host that gave no folder, yet still answers the page', () => { + const ipcMain = new FakeIpcMain() + const d = startDiagnostics({ + ipcMain, + process: new EventEmitter(), + app: new EventEmitter(), + appInfo: { name: 'Prism', version: '1.0.0' }, + openFolder: () => {} + }) + expect(d.log).toBe(NULL_DIAG_LOG) + expect(diagMain()).toBe(NULL_DIAG_LOG) + expect(ipcMain.handlers.has(DGCH.info)).toBe(true) + expect(ipcMain.listenerCount(DGCH.batch)).toBe(1) + }) + + it('opens with a session line and closes with a quit line, written at stop', () => { + const dir = join(mkdtempSync(join(tmpdir(), 'pt-diag-')), 'logs') + const proc = new EventEmitter() + const d = startDiagnostics({ + diagLogDir: dir, + ipcMain: new FakeIpcMain(), + process: proc, + app: new EventEmitter(), + appInfo: { name: 'Prism Terminal', version: '0.34.0' }, + openFolder: () => {} + }) + expect(diagMain()).toBe(d.log) + d.stop() + const lines = readFileSync(join(dir, 'diag.jsonl'), 'utf8') + .split('\n') + .filter(Boolean) + .map((l) => JSON.parse(l) as Record) + expect(lines[0]).toMatchObject({ src: 'main', k: 'session', app: 'Prism Terminal', version: '0.34.0', verbose: false }) + expect(typeof lines[0].cpus).toBe('number') + expect(lines.at(-1)?.k).toBe('quit') + // Unhooked: the process carries none of its listeners any more. + expect(proc.listenerCount('uncaughtExceptionMonitor')).toBe(0) + expect(diagMain()).toBe(NULL_DIAG_LOG) + expect(existsSync(dir)).toBe(true) + }) +}) diff --git a/core/main/diagnostics.ts b/core/main/diagnostics.ts new file mode 100644 index 0000000..3440547 --- /dev/null +++ b/core/main/diagnostics.ts @@ -0,0 +1,129 @@ +import { cpus, release, totalmem } from 'os' +import { dirname } from 'path' +import { stat } from 'fs/promises' +import { hookCrashes, watchWindowHealth, type EmitterLike } from './crashHooks' +import { registerDiagIpc } from './diagIpc' +import { createDiagLog, NULL_DIAG_LOG, setDiagMain, type DiagLog } from './diagLog' +import type { IpcMainLike } from './ipc' +import { timeIpcMain, type IpcMainPatchable } from './ipcTiming' +import { startStallWatch, type StallWatch } from './stallWatch' + +/** + * THE DIAGNOSTICS LOG, WIRED IN ONE CALL (#140). A host calls this in main + * BEFORE it registers any IPC (the timing wraps `ipcMain` itself, so a + * channel registered earlier is not timed), then hands over its window once + * it exists (`watchWindow`) and calls `stop` on the quit path. + * + * `diagLogDir` is the contract: `\logs`. A host that passes none + * logs nothing at all (no file, no timer, no wrapper), but the page's bridge + * still answers, so a page built against this core never throws for want of + * a handler. That is Prism until it wires the folder. + */ + +export interface DiagnosticsDeps { + /** `\logs`. Absent: nothing is logged. */ + diagLogDir?: string + ipcMain: IpcMainLike & IpcMainPatchable + /** Node's `process`. */ + process: EmitterLike + /** Electron's `app`. */ + app: EmitterLike + /** For the session line. */ + appInfo: { name: string; version: string; e2e?: boolean } + /** Show the log folder (Settings' Open folder). */ + openFolder(dir: string): void + /** The host's channels that wait on the user or a download: never + * `ipc-slow`, never in `inflight` (`ipcTiming`'s `LONG_WAIT`). */ + longWaitChannels?: string[] + /** Electron's `powerMonitor`, as a getter: it cannot be used before the + * app is ready, so it is hooked in `watchWindow`. Its `suspend` and + * `resume` keep a sleep from being logged as a lag. */ + powerMonitor?: () => EmitterLike +} + +/** The slice of a BrowserWindow the watch needs. */ +export interface DiagWindow extends EmitterLike { + isDestroyed?(): boolean + webContents: { mainFrame?: { collectJavaScriptCallStack?(): Promise | Promise } | null } +} + +export interface Diagnostics { + log: DiagLog + /** The window's hang events, and its frame for the page stack. */ + watchWindow(win: DiagWindow): void + /** The quit path: timers stopped, the queue written synchronously. */ + stop(): void +} + +export function startDiagnostics(deps: DiagnosticsDeps): Diagnostics { + if (!deps.diagLogDir) { + registerDiagIpc({ ipcMain: deps.ipcMain, log: NULL_DIAG_LOG, openFolder: () => {} }) + return { log: NULL_DIAG_LOG, watchWindow: () => {}, stop: () => {} } + } + const dir = deps.diagLogDir + const log = createDiagLog({ dir }) + setDiagMain(log) + + const cpu = cpus() + log.write('main', 'session', { + app: deps.appInfo.name, + version: deps.appInfo.version, + electron: process.versions.electron ?? null, + chrome: process.versions.chrome ?? null, + windows: release(), + pid: process.pid, + verbose: log.verbose(), + cpus: cpu.length, + cpu: cpu[0]?.model?.trim() ?? null, + ramGb: Math.round(totalmem() / 1024 ** 3), + ...(deps.appInfo.e2e ? { e2e: true } : {}) + }) + + const timing = timeIpcMain(deps.ipcMain, log, { longWait: deps.longWaitChannels }) + let win: DiagWindow | null = null + const watch: StallWatch = startStallWatch({ + log, + inflight: timing.inflight, + // userData: local, small, and the folder every other write of the app goes to. + canary: () => stat(dirname(dir)), + collectStack: async () => { + if (!win || win.isDestroyed?.()) return null + const frame = win.webContents.mainFrame + const stack = frame?.collectJavaScriptCallStack ? await frame.collectJavaScriptCallStack() : null + return typeof stack === 'string' ? stack : null + } + }) + const unhook = hookCrashes({ log, process: deps.process, app: deps.app }) + registerDiagIpc({ ipcMain: deps.ipcMain, log, watch, openFolder: deps.openFolder }) + + let power: EmitterLike | null = null + const onSuspend = (): void => watch.suspend() + const onResume = (): void => watch.resume() + + return { + log, + watchWindow: (w) => { + win = w + watchWindowHealth(w, log, watch) + if (!power && deps.powerMonitor) { + try { + power = deps.powerMonitor() + power.on('suspend', onSuspend) + power.on('resume', onResume) + } catch { + power = null + } + } + }, + stop: () => { + watch.stop() + power?.removeListener('suspend', onSuspend) + power?.removeListener('resume', onResume) + power = null + unhook() + log.write('main', 'quit', {}) + log.close() + setDiagMain(null) + } + } +} diff --git a/core/main/ipcTiming.test.ts b/core/main/ipcTiming.test.ts new file mode 100644 index 0000000..a51169f --- /dev/null +++ b/core/main/ipcTiming.test.ts @@ -0,0 +1,243 @@ +import { describe, expect, it } from 'vitest' +import { EventEmitter } from 'events' +import type { DiagLog, DiagSource } from './diagLog' +import { timeIpcMain } from './ipcTiming' + +/** Electron's ipcMain, as far as the wrapper sees it: an emitter with a + * handler table. */ +class FakeIpcMain extends EventEmitter { + handlers = new Map unknown>() + handle(ch: string, fn: (e: unknown, ...a: unknown[]) => unknown): void { + this.handlers.set(ch, fn) + } + invoke(ch: string, ...a: unknown[]): Promise { + return Promise.resolve().then(() => this.handlers.get(ch)!({}, ...a)) + } +} + +interface Line { + src: DiagSource + k: string + fields: Record +} + +function fakeLog(verbose = false): DiagLog & { lines: Line[] } { + const lines: Line[] = [] + return { + lines, + dir: '', + file: '', + write: (src, k, fields = {}) => lines.push({ src, k, fields }), + writeAt: (src, k, _at, fields = {}) => lines.push({ src, k, fields }), + verbose: () => verbose, + setVerbose: () => {}, + flush: async () => {}, + flushSync: () => {}, + failed: () => false, + close: () => {} + } +} + +/** A clock the test moves by hand. */ +function clock(): { now: () => number; at: (ms: number) => void } { + let t = 0 + return { now: () => t, at: (ms) => (t = ms) } +} + +describe('timeIpcMain', () => { + it('logs a handle that settled after 500 ms, with its channel, time and arguments', async () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + const c = clock() + timeIpcMain(ipc, log, { now: c.now }) + let release!: (v: string) => void + ipc.handle('folder:list', () => new Promise((r) => (release = r))) + const p = ipc.invoke('folder:list', 'C:\\big', [1, 2, 3]) + await Promise.resolve() + await Promise.resolve() + c.at(640) + release('ok') + await expect(p).resolves.toBe('ok') + expect(log.lines).toEqual([ + { src: 'main', k: 'ipc-slow', fields: { ch: 'folder:list', ms: 640, args: ['C:\\big', '[3]'], ok: true } } + ]) + }) + + it('says nothing about a fast call in quiet mode, and logs every call in verbose', async () => { + const quiet = fakeLog(false) + const ipc = new FakeIpcMain() + timeIpcMain(ipc, quiet, { now: clock().now }) + ipc.handle('a', () => 1) + await ipc.invoke('a') + expect(quiet.lines).toEqual([]) + + const loud = fakeLog(true) + const ipc2 = new FakeIpcMain() + timeIpcMain(ipc2, loud, { now: clock().now }) + ipc2.handle('a', () => 1) + ipc2.on('b', () => {}) + await ipc2.invoke('a') + ipc2.emit('b', {}) + expect(loud.lines.map((l) => [l.k, l.fields.ch])).toEqual([ + ['ipc', 'a'], + ['ipc', 'b'] + ]) + }) + + it('never logs its own channels, which would feed back into the log', async () => { + const log = fakeLog(true) + const ipc = new FakeIpcMain() + timeIpcMain(ipc, log, { now: clock().now }) + ipc.on('diag:beat', () => {}) + ipc.emit('diag:beat', {}) + expect(log.lines).toEqual([]) + }) + + it('rethrows an error unchanged, and logs it with its stack', async () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + timeIpcMain(ipc, log, { now: clock().now }) + const boom = new Error('nope') + ipc.handle('sync-throw', () => { + throw boom + }) + ipc.handle('async-throw', async () => { + throw boom + }) + await expect(ipc.invoke('sync-throw')).rejects.toBe(boom) + await expect(ipc.invoke('async-throw')).rejects.toBe(boom) + expect(log.lines.map((l) => [l.k, l.fields.ch, l.fields.err])).toEqual([ + ['ipc-error', 'sync-throw', 'nope'], + ['ipc-error', 'async-throw', 'nope'] + ]) + expect(typeof log.lines[0].fields.stack).toBe('string') + }) + + it('times a sync on body, and logs one that ran 100 ms or more', () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + const c = clock() + timeIpcMain(ipc, log, { now: c.now }) + ipc.on('tabs:changed', () => c.at(c.now() + 150)) + ipc.on('quick', () => c.at(c.now() + 20)) + ipc.emit('tabs:changed', {}, { tabs: [] }) + ipc.emit('quick', {}) + expect(log.lines).toEqual([ + { src: 'main', k: 'ipc-slow', fields: { ch: 'tabs:changed', ms: 150, args: [{ tabs: '[0]' }], ok: true, sync: true } } + ]) + }) + + it('rethrows from an on listener too', () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + timeIpcMain(ipc, log, { now: clock().now }) + ipc.on('x', () => { + throw new Error('bad') + }) + expect(() => ipc.emit('x', {})).toThrow('bad') + expect(log.lines[0]).toMatchObject({ k: 'ipc-error', fields: { ch: 'x', err: 'bad' } }) + }) + + it('keeps removeListener working with the original listener (Prism open:listen)', () => { + const ipc = new FakeIpcMain() + timeIpcMain(ipc, fakeLog(), { now: clock().now }) + let n = 0 + const fn = (): void => { + n += 1 + } + ipc.on('open:listen', fn) + ipc.on('other', fn) + ipc.emit('open:listen', {}) + ipc.removeListener('open:listen', fn) + ipc.emit('open:listen', {}) + expect(n).toBe(1) + // The same listener on another channel is untouched. + ipc.emit('other', {}) + expect(n).toBe(2) + ipc.off('other', fn) + ipc.emit('other', {}) + expect(n).toBe(2) + expect(ipc.listenerCount('open:listen') + ipc.listenerCount('other')).toBe(0) + }) + + it('wraps once, and lets it be removed before it fires', () => { + const ipc = new FakeIpcMain() + timeIpcMain(ipc, fakeLog(), { now: clock().now }) + let n = 0 + const fn = (): void => { + n += 1 + } + ipc.once('a', fn) + ipc.emit('a', {}) + ipc.emit('a', {}) + expect(n).toBe(1) + ipc.once('b', fn) + ipc.removeListener('b', fn) + ipc.emit('b', {}) + expect(n).toBe(1) + }) + + it('keeps a table of the calls in flight, longest first', async () => { + const ipc = new FakeIpcMain() + const c = clock() + const timing = timeIpcMain(ipc, fakeLog(), { now: c.now }) + const hold: Array<() => void> = [] + ipc.handle('slow-a', () => new Promise((r) => hold.push(r))) + ipc.handle('slow-b', () => new Promise((r) => hold.push(r))) + const a = ipc.invoke('slow-a') + await Promise.resolve() + c.at(100) + const b = ipc.invoke('slow-b') + await Promise.resolve() + c.at(300) + expect(timing.inflight()).toEqual([ + { ch: 'slow-a', ms: 300 }, + { ch: 'slow-b', ms: 200 } + ]) + hold.forEach((r) => r()) + await Promise.all([a, b]) + expect(timing.inflight()).toEqual([]) + }) + + it('names a call that ended inside the window, since a lag is only seen once the loop is free', async () => { + const ipc = new FakeIpcMain() + const c = clock() + const timing = timeIpcMain(ipc, fakeLog(), { now: c.now }) + ipc.on('term:spawn', () => c.at(c.now() + 1800)) + c.at(1000) + ipc.emit('term:spawn', {}) + c.at(2850) + expect(timing.inflight()).toEqual([]) + expect(timing.inflight(2000)).toEqual([{ ch: 'term:spawn', ms: 1800, done: true }]) + expect(timing.inflight(10)).toEqual([]) + }) + + it('never calls a wait on the user or a download slow, and keeps it out of the in-flight table', async () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + const c = clock() + const timing = timeIpcMain(ipc, log, { now: c.now, longWait: ['dialog:pick-folder'] }) + const hold: Array<() => void> = [] + ipc.handle('dialog:pick-folder', () => new Promise((r) => hold.push(r))) + ipc.handle('dictation:download', () => new Promise((r) => hold.push(r))) + ipc.handle('folder:sizes', () => new Promise((r) => hold.push(r))) + const calls = [ipc.invoke('dialog:pick-folder'), ipc.invoke('dictation:download'), ipc.invoke('folder:sizes')] + await Promise.resolve() + c.at(90_000) + expect(timing.inflight(1000)).toEqual([{ ch: 'folder:sizes', ms: 90_000 }]) + hold.forEach((r) => r()) + await Promise.all(calls) + expect(log.lines.map((l) => l.fields.ch)).toEqual(['folder:sizes']) + expect(timing.inflight(1000)).toEqual([{ ch: 'folder:sizes', ms: 90_000, done: true }]) + }) + + it('logs only the sizes of an opaque channel', async () => { + const ipc = new FakeIpcMain() + const log = fakeLog() + const c = clock() + timeIpcMain(ipc, log, { now: c.now, opaque: (ch) => ch === 'term:input' }) + ipc.on('term:input', () => c.at(c.now() + 200)) + ipc.emit('term:input', {}, 't1', 'hunter2') + expect(log.lines[0].fields.args).toEqual(['string:2', 'string:7']) + }) +}) diff --git a/core/main/ipcTiming.ts b/core/main/ipcTiming.ts new file mode 100644 index 0000000..b1d874d --- /dev/null +++ b/core/main/ipcTiming.ts @@ -0,0 +1,240 @@ +import { performance } from 'perf_hooks' +import { CH, DCH } from '../shared/channels' +import type { DiagLog } from './diagLog' +import { errorFields, summariseArgs } from './diagSummary' + +/** + * EVERY IPC CALL, TIMED AT THE ONE PLACE THEY ALL PASS (#140). + * + * Both apps register every channel on Electron's one `ipcMain` object, and the + * core's register functions are handed that same object, so patching its + * `handle`, `on` and `once` here times every call in the app without touching + * a single registration. Cost per call: two `performance.now()` and a map + * entry for the in-flight table. + * + * - A `handle` that settles after 500 ms, or a sync `on` body that ran 100 ms + * or more, is `ipc-slow` with its channel, time and summarised arguments. + * - One that throws or rejects is `ipc-error`; the error is RETHROWN + * UNCHANGED, so behaviour is exactly what it was. + * - In verbose every call is `ipc` with its channel and time (no arguments). + * - `removeListener` / `off` with the ORIGINAL listener still remove it + * (Prism's `open:listen` depends on that): a map from each listener to its + * wrappers, per channel. + * - `inflight()` is the table of calls running now, which `main-lag` prints: + * a late event loop next to a 3 s `folder:sizes` call names the suspect. + */ + +/* eslint-disable @typescript-eslint/no-explicit-any */ +type Listener = (event: any, ...args: any[]) => any +export interface IpcMainPatchable { + handle(channel: string, listener: Listener): unknown + on(channel: string, listener: Listener): unknown + once?(channel: string, listener: Listener): unknown + removeListener(channel: string, listener: Listener): unknown + off?(channel: string, listener: Listener): unknown +} +/* eslint-enable @typescript-eslint/no-explicit-any */ + +export interface InflightCall { + ch: string + ms: number + /** It had ended by the time it was asked about, inside the window. */ + done?: true +} + +export interface IpcTiming { + /** + * Calls running now, and those that ENDED in the last `windowMs`, longest + * first, at most eight. The window is the point: a lag is only seen once + * the loop is free again, and by then the call that blocked it has + * usually settled (MEASURED, the first launch of the built app: a 1630 ms + * `main-lag` with nothing in flight, beside a 1837 ms `term:spawn` that + * had ended a millisecond before). + */ + inflight(windowMs?: number): InflightCall[] +} + +export interface IpcTimingOptions { + now?: () => number + /** A handle slower than this is `ipc-slow`. */ + slowMs?: number + /** A sync `on` body slower than this is `ipc-slow`. */ + syncSlowMs?: number + /** A channel whose arguments are logged by size only. */ + opaque?: (ch: string) => boolean + /** The host's own channels that wait on the user or a download, added to + * `LONG_WAIT` (PT: the folder picker, the update install). */ + longWait?: Iterable +} + +/** + * Calls that are SUPPOSED to take long (review of #140): a folder picker + * answers when the user has picked, a download when 643 MB have come. They + * are never `ipc-slow`, which `npm run diag` reads as a stall suspect, and + * never in `inflight`, where one running for minutes sat at the top of every + * `main-lag` and pushed the real suspect out of the eight slots. They are + * still `ipc-error` when they fail, and `ipc` in Detailed logging. + */ +export const LONG_WAIT: ReadonlySet = new Set([DCH.download]) + +/** Typed text, the clipboard and recorded audio: never written down, even + * when the call that carried them was slow. */ +const OPAQUE = new Set([CH.input, CH.clipboardWrite, DCH.transcribe]) +const isOwn = (ch: string): boolean => ch.startsWith('diag:') +const RECENT_MAX = 32 + +export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTimingOptions = {}): IpcTiming { + const now = opts.now ?? ((): number => performance.now()) + const slowMs = opts.slowMs ?? 500 + const syncSlowMs = opts.syncSlowMs ?? 100 + const opaque = opts.opaque ?? ((ch: string): boolean => OPAQUE.has(ch)) + const longWait = new Set([...LONG_WAIT, ...(opts.longWait ?? [])]) + + let nextId = 0 + const running = new Map() + /** The last calls to end, for `inflight`'s window. */ + const recent: Array<{ ch: string; start: number; end: number }> = [] + const wrappers = new WeakMap>() + + const remember = (fn: Listener, ch: string, w: Listener): void => { + let byCh = wrappers.get(fn) + if (!byCh) wrappers.set(fn, (byCh = new Map())) + const list = byCh.get(ch) ?? [] + list.push(w) + byCh.set(ch, list) + } + const recall = (fn: Listener, ch: string): Listener => { + const list = wrappers.get(fn)?.get(ch) + return list?.pop() ?? fn + } + + const ended = (ch: string, start: number, args: unknown[], ok: boolean, sync: boolean, err?: unknown): void => { + try { + const end = now() + const ms = Math.round(end - start) + const long = longWait.has(ch) + if (!long) { + recent.push({ ch, start, end }) + if (recent.length > RECENT_MAX) recent.shift() + } + if (!ok) log.write('main', 'ipc-error', { ch, ms, ...renameMsg(errorFields(err)) }) + if (!long && ms >= (sync ? syncSlowMs : slowMs)) + log.write('main', 'ipc-slow', { ch, ms, args: summariseArgs(args, opaque(ch)), ok, ...(sync ? { sync: true } : {}) }) + else if (log.verbose()) log.write('main', 'ipc', { ch, ms }) + } catch { + /* the log never breaks a call */ + } + } + + const wrapHandle = (ch: string, fn: Listener): Listener => { + if (isOwn(ch)) return fn + return (event, ...args) => { + const start = now() + const id = nextId++ + if (!longWait.has(ch)) running.set(id, { ch, start }) + let result: unknown + try { + result = fn(event, ...args) + } catch (err) { + running.delete(id) + ended(ch, start, args, false, false, err) + throw err + } + if (result && typeof (result as PromiseLike).then === 'function') { + return (result as Promise).then( + (v) => { + running.delete(id) + ended(ch, start, args, true, false) + return v + }, + (err) => { + running.delete(id) + ended(ch, start, args, false, false, err) + throw err + } + ) + } + running.delete(id) + ended(ch, start, args, true, false) + return result + } + } + + const wrapOn = (ch: string, fn: Listener): Listener => { + if (isOwn(ch)) return fn + return (event, ...args) => { + const start = now() + let result: unknown + try { + result = fn(event, ...args) + } catch (err) { + ended(ch, start, args, false, true, err) + throw err + } + ended(ch, start, args, true, true) + return result + } + } + + const orig = { + handle: ipcMain.handle.bind(ipcMain), + on: ipcMain.on.bind(ipcMain), + once: ipcMain.once?.bind(ipcMain), + removeListener: ipcMain.removeListener.bind(ipcMain), + off: ipcMain.off?.bind(ipcMain) + } + + ipcMain.handle = (ch, fn) => orig.handle(ch, wrapHandle(ch, fn)) + ipcMain.on = (ch, fn) => { + const w = wrapOn(ch, fn) + if (w !== fn) remember(fn, ch, w) + orig.on(ch, w) + return ipcMain + } + // NOT through the emitter's own `once`: it registers through `this.on`, + // which is the patched one, and its inner wrapper is then hidden inside + // ours where `removeListener(fn)` cannot find it (MEASURED in the unit + // test). A once is an `on` that removes itself first. + if (orig.once) { + ipcMain.once = (ch, fn) => { + const one: Listener = (event, ...args) => { + ipcMain.removeListener(ch, fn) + return fn(event, ...args) + } + const w = wrapOn(ch, one) + remember(fn, ch, w) + orig.on(ch, w) + return ipcMain + } + } + ipcMain.removeListener = (ch, fn) => { + orig.removeListener(ch, recall(fn, ch)) + return ipcMain + } + if (orig.off) { + const off = orig.off + ipcMain.off = (ch, fn) => { + off(ch, recall(fn, ch)) + return ipcMain + } + } + + return { + inflight: (windowMs = 0) => { + const t = now() + const live: InflightCall[] = [...running.values()].map((r) => ({ ch: r.ch, ms: Math.round(t - r.start) })) + const settled: InflightCall[] = + windowMs > 0 + ? recent + .filter((r) => r.end >= t - windowMs) + .map((r) => ({ ch: r.ch, ms: Math.round(r.end - r.start), done: true as const })) + : [] + return [...live, ...settled].sort((a, b) => b.ms - a.ms).slice(0, 8) + } + } +} + +/** `ipc-error` names the message `err`, beside `ch`. */ +function renameMsg(f: { msg: string; stack?: string }): { err: string; stack?: string } { + return f.stack ? { err: f.msg, stack: f.stack } : { err: f.msg } +} diff --git a/core/main/stallWatch.test.ts b/core/main/stallWatch.test.ts new file mode 100644 index 0000000..39a35ba --- /dev/null +++ b/core/main/stallWatch.test.ts @@ -0,0 +1,223 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import type { DiagLog, DiagSource } from './diagLog' +import { startStallWatch, type StallWatchDeps } from './stallWatch' + +interface Line { + src: DiagSource + k: string + fields: Record +} + +function fakeLog(): DiagLog & { lines: Line[] } { + const lines: Line[] = [] + return { + lines, + dir: '', + file: '', + write: (src, k, fields = {}) => lines.push({ src, k, fields }), + writeAt: (src, k, _at, fields = {}) => lines.push({ src, k, fields }), + verbose: () => false, + setVerbose: () => {}, + flush: async () => {}, + flushSync: () => {}, + failed: () => false, + close: () => {} + } +} + +/** The watch's monotonic clock, moved by hand: a fake timer fires exactly on + * time, so lateness is the clock running ahead of it. */ +let t = 0 +let wall = 1_000_000 +let log: ReturnType +let stops: Array<() => void> = [] + +function watch(extra: Partial = {}): ReturnType { + const w = startStallWatch({ + log, + inflight: () => [{ ch: 'folder:sizes', ms: 2900 }], + canary: () => Promise.resolve(), + now: () => t, + wall: () => wall, + ...extra + }) + stops.push(w.stop) + return w +} + +/** Move both clocks and the timers by `ms`, the clocks first. */ +async function pass(ms: number, late = 0): Promise { + t += ms + late + wall += ms + late + await vi.advanceTimersByTimeAsync(ms) +} + +beforeEach(() => { + vi.useFakeTimers() + t = 0 + wall = 1_000_000 + log = fakeLog() +}) +afterEach(() => { + stops.forEach((s) => s()) + stops = [] + vi.useRealTimers() +}) + +describe('the event loop', () => { + it('logs main-lag when the 50 ms tick came 100 ms or more late, with the calls in flight', async () => { + watch() + await pass(50) + await pass(50, 30) + expect(log.lines).toEqual([]) + await pass(50, 240) + expect(log.lines).toEqual([ + { src: 'main', k: 'main-lag', fields: { ms: 240, inflight: [{ ch: 'folder:sizes', ms: 2900 }] } } + ]) + }) +}) + +describe('the fs canary', () => { + it('logs fs-slow when one stat took 500 ms or more, and never runs two at once', async () => { + let calls = 0 + let release!: () => void + watch({ + canary: () => { + calls += 1 + return new Promise((r) => (release = r)) + } + }) + for (let i = 0; i < 100; i += 1) await pass(50) + expect(calls).toBe(1) + // Starved: still pending five seconds later, so no second stat started. + for (let i = 0; i < 100; i += 1) await pass(50) + expect(calls).toBe(1) + release() + await vi.advanceTimersByTimeAsync(0) + expect(log.lines.filter((l) => l.k === 'fs-slow')).toEqual([{ src: 'main', k: 'fs-slow', fields: { ms: 5000 } }]) + }) + + it('says nothing about a quick stat', async () => { + watch() + for (let i = 0; i < 220; i += 1) await pass(50) + expect(log.lines).toEqual([]) + }) +}) + +describe('the page heartbeat', () => { + const STACK = '\n at spinHard (file:///app/index.js:2:58)' + + it('asks for the stack after a 2 s gap, and writes it only when an overlapping page-stall arrives', async () => { + const collect = vi.fn(() => Promise.resolve(STACK)) + const w = watch({ collectStack: collect }) + w.beat() + const gapStart = wall + for (let i = 0; i < 39; i += 1) await pass(50) + expect(collect).not.toHaveBeenCalled() + for (let i = 0; i < 5; i += 1) await pass(50) + expect(collect).toHaveBeenCalledTimes(1) + // Asked once per gap, however long it lasts. + for (let i = 0; i < 20; i += 1) await pass(50) + expect(collect).toHaveBeenCalledTimes(1) + expect(log.lines).toEqual([]) + // The page comes back and reports its long frame: it covered the moment + // the stack was taken. + w.beat() + w.pageStall(gapStart, 3200) + expect(log.lines).toEqual([{ src: 'main', k: 'page-stack', fields: { stack: STACK, ms: 2000 } }]) + }) + + it('drops the stack when no stall covers it: a throttled timer is not a freeze', async () => { + const w = watch({ collectStack: () => Promise.resolve(STACK) }) + w.beat() + for (let i = 0; i < 45; i += 1) await pass(50) + w.beat() + // A stall far away from the stack's moment. + w.pageStall(wall + 60_000, 300) + expect(log.lines).toEqual([]) + }) + + it('ignores what the frame answers when the page has not opted in', async () => { + const w = watch({ + collectStack: () => Promise.resolve('Website owner has not opted in for JS call stacks in crash reports.') + }) + const gapStart = wall + w.beat() + for (let i = 0; i < 45; i += 1) await pass(50) + w.pageStall(gapStart, 3000) + expect(log.lines).toEqual([]) + }) + + it('writes a held stack when the window says it is unresponsive: a real hang, not a throttle', async () => { + const w = watch({ collectStack: () => Promise.resolve(STACK) }) + w.beat() + for (let i = 0; i < 45; i += 1) await pass(50) + w.unresponsive() + expect(log.lines).toEqual([{ src: 'main', k: 'page-stack', fields: { stack: STACK, ms: 2000, unresponsive: true } }]) + }) + + it("does not ask for the page's stack when it was MAIN that was blocked", async () => { + const collect = vi.fn(() => Promise.resolve(STACK)) + const w = watch({ collectStack: collect }) + w.beat() + await pass(50) + // Main stuck for 2.5 s: the page beat on, but its beats waited in the queue. + await pass(50, 2500) + expect(log.lines.map((l) => l.k)).toEqual(['main-lag']) + for (let i = 0; i < 5; i += 1) await pass(50) + expect(collect).not.toHaveBeenCalled() + // A real page freeze after it is still caught. + w.beat() + for (let i = 0; i < 45; i += 1) await pass(50) + expect(collect).toHaveBeenCalledTimes(1) + }) + + it('does not watch a page that has never beaten (it is still loading)', async () => { + const collect = vi.fn(() => Promise.resolve(STACK)) + watch({ collectStack: collect }) + for (let i = 0; i < 100; i += 1) await pass(50) + expect(collect).not.toHaveBeenCalled() + }) +}) + +describe('sleep', () => { + it('logs nothing for a sleep, not a lag, not a stack, not a slow stat', async () => { + const collect = vi.fn(() => Promise.resolve('\n at x (a.js:1:1)')) + let release!: () => void + let stats = 0 + const w = watch({ + collectStack: collect, + canary: () => { + stats += 1 + return stats === 1 ? new Promise((r) => (release = r)) : Promise.resolve() + } + }) + for (let i = 0; i < 100; i += 1) { + if (i % 10 === 0) w.beat() + await pass(50) + } + expect(stats).toBe(1) + w.suspend() + // Woken after ten minutes: the first tick runs before `resume` is heard. + await pass(50, 600_000) + w.resume() + release() + await vi.advanceTimersByTimeAsync(0) + w.beat() + for (let i = 0; i < 10; i += 1) await pass(50) + expect(log.lines).toEqual([]) + expect(collect).not.toHaveBeenCalled() + // And it watches again afterwards. + await pass(50, 300) + expect(log.lines.map((l) => l.k)).toEqual(['main-lag']) + }) +}) + +describe('stop', () => { + it('ends every timer', async () => { + const w = watch() + w.stop() + await pass(50, 500) + expect(log.lines).toEqual([]) + }) +}) diff --git a/core/main/stallWatch.ts b/core/main/stallWatch.ts new file mode 100644 index 0000000..93a644d --- /dev/null +++ b/core/main/stallWatch.ts @@ -0,0 +1,200 @@ +import { performance } from 'perf_hooks' +import type { DiagLog } from './diagLog' +import type { InflightCall } from './ipcTiming' + +/** + * WHAT MAIN WATCHES FOR (#140): its own event loop, the fs threadpool, and the + * page's heartbeat. + * + * - MAIN-LAG. A 50 ms tick; when it fires 100 ms or more after it was due, + * main was blocked that long. Logged with the IPC calls in flight, which + * is usually the answer. (A drift timer and not `monitorEventLoopDelay`: + * the histogram is sampled and says how bad, never WHEN, and a line in a + * timeline needs the when.) + * - FS-SLOW. One `stat` of userData every 5 s. libuv has four threads for + * every async fs call in the process, so a dead network drive or a folder + * size scan holds up everything behind it; a 500 ms stat of a local folder + * is that queue, not the disk. Never two at once: a starved stat is + * logged once, with its whole wait, when it finally lands. + * - PAGE-STACK. The page beats every 500 ms. After a 2 s gap main asks the + * frame for the JavaScript it is running (`collectJavaScriptCallStack`, + * MEASURED on Electron 43 to answer in about 1 ms during a busy loop, once + * the page is served with `Document-Policy: + * include-js-call-stacks-in-crash-reports`; without it the answer is a + * sentence saying so, which is ignored). The stack is HELD, and written + * only when a `page-stall` overlapping that moment arrives, or the window + * says it is unresponsive: a timer Chromium throttled also misses beats, + * and is not a freeze. + */ + +export interface StallWatchDeps { + log: DiagLog + inflight(windowMs?: number): InflightCall[] + /** One cheap async fs call: the host stats its userData folder. */ + canary(): Promise + /** The page's JavaScript stack now, or null. Absent: no page-stack. */ + collectStack?(): Promise + /** Monotonic ms. */ + now?: () => number + /** Epoch ms, the clock a page's stall is reported in. */ + wall?: () => number + tickMs?: number + lagMs?: number + canaryMs?: number + canarySlowMs?: number + beatGapMs?: number + /** How long a held stack waits for its stall. */ + stackKeepMs?: number +} + +export interface StallWatch { + /** `diag:beat`: the page is alive. */ + beat(): void + /** A `page-stall` arrived: it started at `startAt` (epoch ms) and lasted `ms`. */ + pageStall(startAt: number, ms: number): void + /** The window's own `unresponsive` event. */ + unresponsive(): void + /** + * `powerMonitor`'s `suspend` and `resume` (review of #140). The monotonic + * clock may run on through a sleep, and the first tick after a lid-close + * would otherwise log the whole sleep as a `main-lag` and ask for the + * page's stack, since no beat came either. + */ + suspend(): void + resume(): void + stop(): void +} + +/** How far either side of a stall a held stack still counts as inside it: + * the beat and the frame's clock are not the same clock. */ +const SLACK_MS = 250 + +/** A real stack has frames; the refusal is a sentence. */ +const isStack = (s: string | null): s is string => !!s && /\n\s*at /.test(s) + +export function startStallWatch(deps: StallWatchDeps): StallWatch { + const { log } = deps + const now = deps.now ?? ((): number => performance.now()) + const wall = deps.wall ?? Date.now + const tickMs = deps.tickMs ?? 50 + const lagMs = deps.lagMs ?? 100 + const canaryMs = deps.canaryMs ?? 5000 + const canarySlowMs = deps.canarySlowMs ?? 500 + const beatGapMs = deps.beatGapMs ?? 2000 + const stackKeepMs = deps.stackKeepMs ?? 60_000 + + let last = now() + let lastBeat: number | null = null + let askedThisGap = false + let held: { stack: string; at: number; ms: number; heldAt: number } | null = null + let canaryBusy = false + let suspended = false + /** Bumped at a resume: a canary stat that spanned the sleep is not timed. */ + let epoch = 0 + + const safe = (fn: () => void): void => { + try { + fn() + } catch { + /* a watcher never takes the app down */ + } + } + + const askStack = (gapMs: number): Promise => { + const collect = deps.collectStack + if (!collect) return Promise.resolve() + return collect().then( + (stack) => { + if (isStack(stack)) held = { stack, at: wall(), ms: Math.round(gapMs), heldAt: now() } + }, + () => {} + ) + } + + const tick = setInterval(() => { + safe(() => { + const n = now() + const late = Math.round(n - last - tickMs) + last = n + // Asleep (or just woken, before `resume` is heard): the clock ran on + // through the sleep, which is neither a lag nor a missed beat. + if (suspended) return + // The window covers the whole block: the call that caused it has often + // settled by the time this tick could run. + if (late >= lagMs) { + log.write('main', 'main-lag', { ms: late, inflight: deps.inflight(late + tickMs) }) + // While MAIN was blocked the page's beats waited in its IPC queue: + // that time is main's, and must not read as a page freeze (review of + // #140: the output held back then floods the page, its long frame + // overlaps the stack, and the page is blamed for main's stall). + if (lastBeat !== null) lastBeat = Math.min(n, lastBeat + late) + } + if (lastBeat !== null && !askedThisGap && n - lastBeat >= beatGapMs) { + askedThisGap = true + void askStack(n - lastBeat) + } + if (held && n - held.heldAt > stackKeepMs) held = null + }) + }, tickMs) + tick.unref?.() + + const canary = setInterval(() => { + if (canaryBusy) return + canaryBusy = true + const t0 = now() + const started = epoch + const done = (): void => { + canaryBusy = false + if (started !== epoch || suspended) return + safe(() => { + const ms = Math.round(now() - t0) + if (ms >= canarySlowMs) log.write('main', 'fs-slow', { ms }) + }) + } + try { + deps.canary().then(done, done) + } catch { + done() + } + }, canaryMs) + canary.unref?.() + + const writeHeld = (extra: Record = {}): void => { + if (!held) return + log.write('main', 'page-stack', { stack: held.stack, ms: held.ms, ...extra }) + held = null + } + + return { + beat: () => { + lastBeat = now() + askedThisGap = false + }, + pageStall: (startAt, ms) => + safe(() => { + if (!held) return + if (held.at >= startAt - SLACK_MS && held.at <= startAt + ms + SLACK_MS) writeHeld() + }), + unresponsive: () => + safe(() => { + if (held) return writeHeld({ unresponsive: true }) + // No beat gap seen yet (or no stack held): a hang the window reports + // is real, so ask now and write what comes back. + void askStack(lastBeat === null ? 0 : now() - lastBeat).then(() => writeHeld({ unresponsive: true })) + }), + suspend: () => { + suspended = true + }, + resume: () => { + suspended = false + epoch += 1 + last = now() + if (lastBeat !== null) lastBeat = now() + askedThisGap = false + }, + stop: () => { + clearInterval(tick) + clearInterval(canary) + } + } +} diff --git a/core/main/terminal.ts b/core/main/terminal.ts index de2b97b..0337962 100644 --- a/core/main/terminal.ts +++ b/core/main/terminal.ts @@ -3,6 +3,7 @@ import { cdCommand } from '../shared/termCwd' import { detectShells, shellById } from './shells' import { cmdPrompt } from './termPrompt' import { isOurPlugin } from './claudePlugin' +import { diagMain } from './diagLog' // The pty host. Sessions are keyed by an id the renderer assigns - the same // pattern as tabs, where the renderer owns the list and main owns the @@ -408,6 +409,15 @@ function withResume(def: { exe: string; args: string[]; id: string }, resume: st const pending = new Set() const killedWhilePending = new Set() +/** A shell's birth and end on the diagnostics timeline (#140). Never throws. */ +function shellCrumb(a: string, fields: Record): void { + try { + diagMain().write('main', 'crumb', { a, ...fields }) + } catch { + /* the log never breaks a spawn */ + } +} + export async function spawnTerm( id: string, root: string, @@ -452,17 +462,20 @@ async function spawnPending( outputTicks += 1 batcher.push(d) }), - w.pty.onExit(() => { + w.pty.onExit((e) => { batcher.flush() sessions.delete(id) + shellCrumb('shell-exit', { id, pid: w.pty.pid, exitCode: e?.exitCode ?? null }) send('term:exit', id) }) ] sessions.set(id, { pty: w.pty, batcher, subs, defId: w.defId }) + shellCrumb('shell-spawn', { id, pid: w.pty.pid, shell: def.id, warm: true }) const want = desiredSize.get(id) if (want) resizeTerm(id, want.cols, want.rows) return true } + const t0 = performance.now() try { const pty = await import('node-pty') const size = desiredSize.get(id) ?? { cols: 80, rows: 24 } @@ -485,15 +498,18 @@ async function spawnPending( outputTicks += 1 batcher.push(d) }), - p.onExit(() => { + p.onExit((e) => { batcher.flush() sessions.delete(id) + shellCrumb('shell-exit', { id, pid: p.pid, exitCode: e?.exitCode ?? null }) send('term:exit', id) }) ] sessions.set(id, { pty: p, batcher, subs, defId: def.id }) + shellCrumb('shell-spawn', { id, pid: p.pid, shell: def.id, cwd: root, resume: !!resume, ms: Math.round(performance.now() - t0) }) return true - } catch { + } catch (err) { + shellCrumb('shell-spawn-failed', { id, shell: def.id, cwd: root, err: err instanceof Error ? err.message : String(err) }) return false // shell missing or ConPTY refused; the renderer shows the line } } diff --git a/core/package.json b/core/package.json index 06a27fa..ad9bde4 100644 --- a/core/package.json +++ b/core/package.json @@ -1,6 +1,6 @@ { "name": "prism-term-core", - "version": "0.26.0", + "version": "0.27.0", "description": "What Prism Terminal and Prism share: the terminal (pty, shells, agent detection and indicator, themes, links, the panel, dictation) and the update chip with its window. TypeScript source, compiled by the host.", "license": "MIT", "private": true, diff --git a/core/preload/diagApi.ts b/core/preload/diagApi.ts new file mode 100644 index 0000000..f41ddf6 --- /dev/null +++ b/core/preload/diagApi.ts @@ -0,0 +1,42 @@ +import { DGCH } from '../shared/channels' +import type { IpcRendererLike } from './api' + +/** + * The preload half of the DIAGNOSTICS bridge (#140), for both hosts. A host + * spreads it into its bridge beside the terminal's; `startDiagnostics` in + * main is the other half. Every member is fire and forget except the two the + * Settings page reads back. + */ + +/** One line the page hands main: its kind, when (epoch ms), and fields. */ +export interface DiagPageLine { + k: string + at: number + [field: string]: unknown +} + +export interface DiagInfo { + verbose: boolean + /** The log folder, shown on the Settings page; '' where nothing is logged. */ + dir: string +} + +export interface DiagApi { + diagBatch(lines: DiagPageLine[]): void + diagBeat(): void + diagInfo(): Promise + diagSetVerbose(on: boolean): Promise + diagOpenFolder(): void + diagMark(note?: string): void +} + +export function createDiagApi(ipc: IpcRendererLike): DiagApi { + return { + diagBatch: (lines) => ipc.send(DGCH.batch, lines), + diagBeat: () => ipc.send(DGCH.beat), + diagInfo: () => ipc.invoke(DGCH.info) as Promise, + diagSetVerbose: (on) => ipc.invoke(DGCH.setVerbose, on) as Promise, + diagOpenFolder: () => ipc.send(DGCH.openFolder), + diagMark: (note) => ipc.send(DGCH.mark, note) + } +} diff --git a/core/renderer/lib/diag.test.ts b/core/renderer/lib/diag.test.ts new file mode 100644 index 0000000..33ae2bf --- /dev/null +++ b/core/renderer/lib/diag.test.ts @@ -0,0 +1,207 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import type { DiagApi, DiagPageLine } from '../../preload/diagApi' +import { crumb, crumbsBefore, errorLine, loafLine, recentCrumbs, resetDiag, shortSrc, startDiag, time } from './diag' + +function fakeApi(verbose = false): DiagApi & { batches: DiagPageLine[][]; beats: number } { + const api = { + batches: [] as DiagPageLine[][], + beats: 0, + diagBatch: (lines: DiagPageLine[]) => { + api.batches.push(lines) + }, + diagBeat: () => { + api.beats += 1 + }, + diagInfo: () => Promise.resolve({ verbose, dir: 'C:\\logs' }), + diagSetVerbose: (on: boolean) => Promise.resolve(on), + diagOpenFolder: () => {}, + diagMark: () => {} + } + return api +} + +beforeEach(() => { + vi.useFakeTimers() + vi.setSystemTime(1_800_000_000_000) + resetDiag() +}) +afterEach(() => { + resetDiag() + vi.useRealTimers() +}) + +describe('shortSrc', () => { + it("keeps a script's own name and drops where the app is installed", () => { + expect(shortSrc('file:///C:/Users/x/AppData/Local/Programs/PrismTerminal/resources/app.asar/out/renderer/assets/index-abc.js')).toBe( + 'assets/index-abc.js' + ) + expect(shortSrc('http://localhost:5173/src/App.tsx?t=1')).toBe('src/App.tsx') + expect(shortSrc('')).toBe(null) + }) +}) + +describe('loafLine', () => { + const ORIGIN = 1_800_000_000_000 + const entry = { + startTime: 1000, + duration: 2512.6, + blockingDuration: 2462.2, + scripts: [ + { sourceURL: 'file:///app/out/renderer/assets/index.js', sourceFunctionName: 'tick', invoker: 'TimerHandler:setTimeout', duration: 12 }, + { sourceURL: 'file:///app/out/renderer/assets/index.js', sourceFunctionName: 'spinHard', invoker: 'BUTTON.onclick', duration: 2490.4 } + ] + } + + it('names the time, how long it blocked, and the scripts that ran, longest first', () => { + const line = loafLine(entry, ORIGIN, []) + expect(line).toEqual({ + k: 'page-stall', + at: ORIGIN + 1000, + ms: 2513, + blocking: 2462, + scripts: [ + { src: 'assets/index.js', fn: 'spinHard', invoker: 'BUTTON.onclick', ms: 2490 }, + { src: 'assets/index.js', fn: 'tick', invoker: 'TimerHandler:setTimeout', ms: 12 } + ], + crumbs: [] + }) + }) + + it('carries the last five crumbs before the stall, and how long before', () => { + const ring = Array.from({ length: 8 }, (_, i) => ({ a: `c${i}`, at: ORIGIN + 100 * i })) + const line = loafLine(entry, ORIGIN, ring) + expect(line.crumbs).toEqual([ + { a: 'c3', ago: 700 }, + { a: 'c4', ago: 600 }, + { a: 'c5', ago: 500 }, + { a: 'c6', ago: 400 }, + { a: 'c7', ago: 300 } + ]) + }) + + it('reads an entry with no scripts', () => { + expect(loafLine({ startTime: 0, duration: 300 }, ORIGIN, []).scripts).toEqual([]) + }) +}) + +describe('crumbsBefore', () => { + it('leaves out a crumb that came after the stall ended', () => { + const ring = [ + { a: 'before', at: 100 }, + { a: 'after', at: 5000 } + ] + expect(crumbsBefore(ring, 200, 300).map((c) => c.a)).toEqual(['before']) + }) +}) + +describe('errorLine', () => { + it('reads an error event and a rejection', () => { + expect(errorLine('page-error', { message: 'x is undefined', error: new Error('x is undefined'), filename: 'file:///a/out/renderer/assets/index.js', lineno: 3, colno: 9 })).toMatchObject({ + k: 'page-error', + msg: 'x is undefined', + loc: 'assets/index.js:3:9' + }) + expect(errorLine('page-rejection', { reason: 'plain' })).toMatchObject({ k: 'page-rejection', msg: 'plain' }) + }) +}) + +describe('the crumb ring', () => { + it('keeps the last fifty, sent or not', () => { + for (let i = 0; i < 60; i += 1) crumb(`a${i}`) + const ring = recentCrumbs() + expect(ring).toHaveLength(50) + expect(ring[0].a).toBe('a10') + }) +}) + +describe('startDiag', () => { + it('batches crumbs every 250 ms, beats every 500 ms, and sends nothing before it starts', async () => { + crumb('early') + const api = fakeApi() + const stop = startDiag(api) + await vi.advanceTimersByTimeAsync(0) + crumb('tab-open', { cwd: 'C:\\x' }) + crumb('tab-switch') + expect(api.batches).toEqual([]) + await vi.advanceTimersByTimeAsync(260) + expect(api.batches).toHaveLength(1) + expect(api.batches[0].map((l) => [l.k, l.a])).toEqual([ + ['crumb', 'tab-open'], + ['crumb', 'tab-switch'] + ]) + expect(api.batches[0][0]).toMatchObject({ cwd: 'C:\\x', at: 1_800_000_000_000 }) + await vi.advanceTimersByTimeAsync(1000) + expect(api.beats).toBe(2) + stop() + }) + + it('keeps a high-rate crumb in the ring only, unless logging is detailed', async () => { + const quiet = fakeApi(false) + const stop = startDiag(quiet) + await vi.advanceTimersByTimeAsync(0) + crumb('scroll', {}, { often: true }) + await vi.advanceTimersByTimeAsync(300) + expect(quiet.batches).toEqual([]) + expect(recentCrumbs().at(-1)?.a).toBe('scroll') + stop() + + resetDiag() + const loud = fakeApi(true) + const stop2 = startDiag(loud) + await vi.advanceTimersByTimeAsync(0) + crumb('scroll', {}, { often: true }) + await vi.advanceTimersByTimeAsync(300) + expect(loud.batches.flat().map((l) => l.a)).toEqual(['scroll']) + stop2() + }) +}) + +describe('an error on every frame', () => { + it('is one line per 10 s with a count, not sixty a second', async () => { + const listeners = new Map void>() + const target = { + addEventListener: (type: string, fn: (ev: never) => void) => listeners.set(type, fn), + removeEventListener: (type: string) => listeners.delete(type) + } + const api = fakeApi() + const stop = startDiag(api, target) + await vi.advanceTimersByTimeAsync(0) + const fire = (): void => + listeners.get('error')!({ error: new Error('loop'), filename: 'file:///app/out/renderer/a.js', lineno: 1 } as never) + for (let i = 0; i < 60 * 5; i += 1) { + fire() + await vi.advanceTimersByTimeAsync(16) + } + const errors = (): Array> => api.batches.flat().filter((l) => l.k === 'page-error') + expect(errors()).toHaveLength(1) + await vi.advanceTimersByTimeAsync(6000) + expect(errors()).toHaveLength(2) + expect(errors()[1].repeats).toBe(299) + stop() + }) +}) + +describe('time', () => { + it('returns what the work returned, and logs it only past the threshold', async () => { + const api = fakeApi() + const stop = startDiag(api) + await vi.advanceTimersByTimeAsync(0) + expect(time('sort-slow', () => 7, { n: 3 })).toBe(7) + await vi.advanceTimersByTimeAsync(300) + expect(api.batches).toEqual([]) + const slow = time( + 'sort-slow', + () => { + vi.setSystemTime(Date.now() + 80) + return 'done' + }, + { n: 9000 }, + 50, + () => Date.now() + ) + expect(slow).toBe('done') + await vi.advanceTimersByTimeAsync(300) + expect(api.batches.flat()).toEqual([expect.objectContaining({ k: 'sort-slow', ms: 80, n: 9000 })]) + stop() + }) +}) diff --git a/core/renderer/lib/diag.ts b/core/renderer/lib/diag.ts new file mode 100644 index 0000000..65e04a0 --- /dev/null +++ b/core/renderer/lib/diag.ts @@ -0,0 +1,266 @@ +import type { DiagApi, DiagPageLine } from '../../preload/diagApi' +import { createDiagGate } from '../../shared/diagGate' + +/** + * THE PAGE'S HALF OF THE DIAGNOSTICS LOG (#140), for both hosts. + * + * - PAGE-STALL: Chromium's long-animation-frame entries of 200 ms or more. + * A LoAF names the scripts that ran in the frame, their function and what + * started them (a click, a timer, a message), which is what a stall report + * needs and what a long task alone never said. The last five crumbs ride + * along, so the line says what the user had just done. + * - PAGE-TASK (Detailed logging only): long tasks from 50 ms. + * - PAGE-ERROR / PAGE-REJECTION: `error` and `unhandledrejection`. + * - THE HEARTBEAT: one message every 500 ms. Main asks for the page's stack + * when it stops (`core/main/stallWatch`). + * - CRUMBS: `crumb(action, fields)` from anywhere in either app. The last 50 + * are kept in memory whether or not anything is sent; a crumb marked + * `often` (a scroll settling) is sent only while logging is detailed. + * + * Lines go to main in one batch every 250 ms. A crumb said before `startDiag` + * (or in a host that never starts it) only joins the ring. + */ + +export interface Crumb { + a: string + at: number +} + +const RING_MAX = 50 +const QUEUE_MAX = 200 +const STALL_MS = 200 +const TASK_MS = 50 +const CRUMBS_PER_STALL = 5 + +let api: DiagApi | null = null +let verbose = false +let ring: Crumb[] = [] +let queue: DiagPageLine[] = [] +let dropped = 0 +let errorGate = createDiagGate() +let stopFn: (() => void) | null = null + +/** A script's own name, without where the app happens to be installed. */ +export function shortSrc(url: string | undefined | null): string | null { + if (!url) return null + const clean = url.split(/[?#]/)[0] + const out = clean.lastIndexOf('/out/renderer/') + if (out >= 0) return clean.slice(out + '/out/renderer/'.length) + const m = /^[a-z]+:\/\/[^/]*\/(.*)$/i.exec(clean) + if (m && /^https?:/i.test(clean)) return m[1] || null + return clean.split('/').slice(-2).join('/') || null +} + +/** The crumbs said before a stall ended, the last five, each with how long + * before the stall began it was (negative: during it). */ +export function crumbsBefore(crumbs: readonly Crumb[], startAt: number, ms: number): Array<{ a: string; ago: number }> { + return crumbs + .filter((c) => c.at <= startAt + ms) + .slice(-CRUMBS_PER_STALL) + .map((c) => ({ a: c.a, ago: Math.round(startAt - c.at) })) +} + +interface LoafScript { + sourceURL?: string + sourceFunctionName?: string + invoker?: string + duration?: number +} +interface LoafEntry { + startTime: number + duration: number + blockingDuration?: number + scripts?: readonly LoafScript[] +} + +/** A long-animation-frame entry as a `page-stall` line. */ +export function loafLine(entry: LoafEntry, timeOrigin: number, crumbs: readonly Crumb[]): DiagPageLine { + const at = Math.round(timeOrigin + entry.startTime) + const ms = Math.round(entry.duration) + const scripts = [...(entry.scripts ?? [])] + .sort((a, b) => (b.duration ?? 0) - (a.duration ?? 0)) + .slice(0, 3) + .map((s) => ({ + src: shortSrc(s.sourceURL), + fn: s.sourceFunctionName || null, + invoker: s.invoker || null, + ms: Math.round(s.duration ?? 0) + })) + return { + k: 'page-stall', + at, + ms, + blocking: Math.round(entry.blockingDuration ?? 0), + scripts, + crumbs: crumbsBefore(crumbs, at, ms) + } +} + +/** An `error` event or an `unhandledrejection` as a line. */ +export function errorLine( + k: 'page-error' | 'page-rejection', + ev: { message?: string; error?: unknown; filename?: string; lineno?: number; colno?: number; reason?: unknown } +): DiagPageLine { + const err = k === 'page-error' ? ev.error : ev.reason + const msg = + err instanceof Error ? err.message : typeof err === 'string' ? err : (ev.message ?? String(err ?? 'unknown')) + const stack = err instanceof Error && err.stack ? err.stack : null + const loc = ev.filename ? `${shortSrc(ev.filename)}:${ev.lineno ?? 0}:${ev.colno ?? 0}` : null + return { k, at: Date.now(), msg, stack, loc } +} + +/** Past `QUEUE_MAX` the NEWEST lines are dropped, and counted: the first + * lines of a flood say what started it. */ +function enqueue(line: DiagPageLine): void { + if (!api) return + if (queue.length >= QUEUE_MAX) { + dropped += 1 + return + } + queue.push(line) +} + +/** An error or a rejection, through the repeat gate (`shared/diagGate`): an + * error thrown on every frame is one line per 10 s with a count, where it + * was 60 lines a second that rolled the whole log over in about 75 s. */ +function enqueueError(line: DiagPageLine): void { + const out = errorGate.offer(line.k, `${line.k}|${String(line.msg)}|${String(line.loc)}`, line, Date.now()) + if (out) enqueue(out) +} + +function send(): void { + if (!api) return + for (const held of errorGate.sweep(Date.now())) enqueue({ ...held, at: Date.now() }) + if (dropped > 0) { + queue.push({ k: 'crumb', at: Date.now(), a: 'diag-dropped', n: dropped }) + dropped = 0 + } + if (queue.length === 0) return + const lines = queue + queue = [] + try { + api.diagBatch(lines) + } catch { + /* the log never breaks the page */ + } +} + +/** + * Something the user did, for the timeline: `crumb('tab-open', { cwd })`. + * `often`: a high-rate action, sent only while logging is detailed. + */ +export function crumb(a: string, fields: Record = {}, opts: { often?: boolean } = {}): void { + const at = Date.now() + ring.push({ a, at }) + if (ring.length > RING_MAX) ring.splice(0, ring.length - RING_MAX) + if (opts.often && !verbose) return + enqueue({ ...fields, k: 'crumb', at, a }) +} + +/** + * Run `fn`, and log it as `k` (an app's own `-slow` kind: `sort-slow`) when it + * took `minMs` or more. Returns what `fn` returned; a throw passes through. + */ +export function time( + k: string, + fn: () => T, + fields: Record = {}, + minMs = 50, + clock: () => number = () => performance.now() +): T { + const t0 = clock() + try { + return fn() + } finally { + const ms = Math.round(clock() - t0) + if (ms >= minMs) enqueue({ ...fields, k, at: Date.now(), ms }) + } +} + +/** The ring, oldest first (the e2e and the tests read it). */ +export const recentCrumbs = (): Crumb[] => [...ring] + +/** Settings' switch moved: the page filters by it at once. */ +export function noteDiagVerbose(on: boolean): void { + verbose = on +} + +interface PageTarget { + addEventListener?(type: string, fn: (ev: never) => void): void + removeEventListener?(type: string, fn: (ev: never) => void): void +} + +/** Start the page's half; returns the function that stops it. Once per page. */ +export function startDiag(bridge: DiagApi, target: PageTarget = globalThis as unknown as PageTarget): () => void { + stopFn?.() + api = bridge + void bridge + .diagInfo() + .then((i) => { + verbose = !!i?.verbose + }) + .catch(() => {}) + + const flush = setInterval(send, 250) + const beat = setInterval(() => { + try { + bridge.diagBeat() + } catch { + /* silent */ + } + }, 500) + + const observers: PerformanceObserver[] = [] + const supported = typeof PerformanceObserver !== 'undefined' ? (PerformanceObserver.supportedEntryTypes ?? []) : [] + const origin = typeof performance !== 'undefined' ? performance.timeOrigin : Date.now() + if (supported.includes('long-animation-frame')) { + const o = new PerformanceObserver((list) => { + for (const e of list.getEntries() as unknown as LoafEntry[]) + if (e.duration >= STALL_MS) enqueue(loafLine(e, origin, ring)) + }) + o.observe({ type: 'long-animation-frame', buffered: true }) + observers.push(o) + } + if (supported.includes('longtask')) { + const o = new PerformanceObserver((list) => { + if (!verbose) return + for (const e of list.getEntries()) + if (e.duration >= TASK_MS) enqueue({ k: 'page-task', at: Math.round(origin + e.startTime), ms: Math.round(e.duration) }) + }) + o.observe({ type: 'longtask', buffered: true }) + observers.push(o) + } + + const onError = (ev: never): void => enqueueError(errorLine('page-error', ev)) + const onRejection = (ev: never): void => enqueueError(errorLine('page-rejection', ev)) + // A page going away (a reload) sends what it has rather than losing it. + const onHide = (): void => send() + target.addEventListener?.('error', onError) + target.addEventListener?.('unhandledrejection', onRejection) + target.addEventListener?.('pagehide', onHide) + + const stop = (): void => { + clearInterval(flush) + clearInterval(beat) + observers.forEach((o) => o.disconnect()) + target.removeEventListener?.('error', onError) + target.removeEventListener?.('unhandledrejection', onRejection) + target.removeEventListener?.('pagehide', onHide) + send() + if (stopFn === stop) stopFn = null + } + stopFn = stop + return stop +} + +/** For tests: forget everything, as a fresh page. */ +export function resetDiag(): void { + stopFn?.() + stopFn = null + api = null + verbose = false + ring = [] + queue = [] + dropped = 0 + errorGate = createDiagGate() +} diff --git a/core/renderer/lib/dictation.ts b/core/renderer/lib/dictation.ts index 15ded33..0ab92d0 100644 --- a/core/renderer/lib/dictation.ts +++ b/core/renderer/lib/dictation.ts @@ -1,5 +1,6 @@ import { engineFor, languageFor } from '../../shared/dictationCatalog' import { dictationHost } from '../host' +import { crumb } from './diag' import { cleanTranscript } from './dictationClean' import { initialKeyState, reduceKey, type KeyEvt, type KeyState } from './dictationKey' import { @@ -85,6 +86,9 @@ export function onDictationLevel(l: (level: number) => void): () => void { } } function setView(patch: Partial): void { + // The timeline (#140): listening is a start, transcribing the stop, idle + // the end of the pass. Never the text. + if (patch.phase && patch.phase !== view.phase) crumb('dictation', { phase: patch.phase }) view = { ...view, ...patch } viewListeners.forEach((l) => l()) } diff --git a/core/renderer/lib/useUpdateFlow.ts b/core/renderer/lib/useUpdateFlow.ts index 1ee8eb5..cb7b391 100644 --- a/core/renderer/lib/useUpdateFlow.ts +++ b/core/renderer/lib/useUpdateFlow.ts @@ -1,6 +1,7 @@ import { useCallback, useEffect, useReducer, useRef } from 'react' import type { UpdateInfo } from '../../shared/updateTypes' import { NO_UPDATE, updateFlow, type UpdateFlow } from './updateFlow' +import { crumb } from './diag' // The update chip and its window, wired to a host (#28). The rules are // `updateFlow`'s; this is only the plumbing both apps would otherwise write @@ -95,7 +96,10 @@ export function useUpdateFlow( return () => clearTimeout(t) }, [loose]) - const open = useCallback(() => dispatch({ type: 'open' }), []) + const open = useCallback(() => { + crumb('update-open') + dispatch({ type: 'open' }) + }, []) const cancel = useCallback(() => dispatch({ type: 'cancel' }), []) const dismissNotice = useCallback(() => dispatch({ type: 'dismiss' }), []) @@ -104,6 +108,7 @@ export function useUpdateFlow( const info = s.info if (!info || s.phase !== 'idle') return const start = (): void => { + crumb('update-install', { version: info.version, preview: !!info.mock }) dispatch({ type: 'install' }) void bridge.installUpdate(info.url).then( (ok) => dispatch({ type: 'settled', ok }), diff --git a/core/renderer/settings/coreIndex.ts b/core/renderer/settings/coreIndex.ts index fe86c2a..f6ada2d 100644 --- a/core/renderer/settings/coreIndex.ts +++ b/core/renderer/settings/coreIndex.ts @@ -1,3 +1,4 @@ +import { DIAGNOSTICS_OPTIONS } from './diagnosticsOptions' import { dictationOptionIds } from './dictationOptions' import { HELP_OPTIONS } from './helpOptions' import { terminalOptionIds } from './options' @@ -16,16 +17,20 @@ import { acrylicSub, opt, themeSub } from './sections/opts' export function coreSettingsIndex({ pageOf, nvidia, - help = true + help = true, + diagnostics = false }: { pageOf: (section: SettingsSectionId) => string nvidia: boolean help?: boolean + /** The Diagnostics page (#140): only in a host that wired the log. */ + diagnostics?: boolean }): SettingsIndexEntry[] { const ids = [ ...terminalOptionIds({ windowAcrylic: false }), ...dictationOptionIds({ nvidia }), - ...(help ? HELP_OPTIONS.map((o) => o.id) : []) + ...(help ? HELP_OPTIONS.map((o) => o.id) : []), + ...(diagnostics ? DIAGNOSTICS_OPTIONS.map((o) => o.id) : []) ] return ids.map((id) => { const o = opt(id) diff --git a/core/renderer/settings/diagnosticsOptions.ts b/core/renderer/settings/diagnosticsOptions.ts new file mode 100644 index 0000000..44c4e54 --- /dev/null +++ b/core/renderer/settings/diagnosticsOptions.ts @@ -0,0 +1,28 @@ +import type { SettingsSectionId } from './sectionIds' + +/** + * EVERY DIAGNOSTICS ROW, BY ID (#140): the same deal `options.ts`, + * `dictationOptions.ts` and `helpOptions.ts` make. Each renders as + * `data-pref=""`. A list of its own, so a host that has not wired the + * log (Prism, until it does) reads none of it. + * + * No row has a localStorage key: Detailed logging is kept by MAIN, in + * `\diag.json`, because main is what writes the log and must know + * the answer before any page has loaded. + */ +export interface DiagnosticsOption { + id: string + label: string + type: 'switch' | 'action' + key: null + section: SettingsSectionId + icon: string + sub: string + keywords?: string +} + +export const DIAGNOSTICS_OPTIONS: readonly DiagnosticsOption[] = [ + { id: 'diag-verbose', label: 'Detailed logging', type: 'switch', key: null, section: 'diagnostics', icon: 'log', sub: 'Records every call, for tracking down a problem.', keywords: 'verbose debug log trace' }, + { id: 'diag-folder', label: 'Log files', type: 'action', key: null, section: 'diagnostics', icon: 'folder', sub: 'Kept on this PC, never sent.', keywords: 'folder open logs diagnostics jsonl' }, + { id: 'diag-mark', label: 'Mark a problem', type: 'action', key: null, section: 'diagnostics', icon: 'flag', sub: 'Stamps this moment in the log.', keywords: 'stall freeze hang slow report' } +] diff --git a/core/renderer/settings/layout/icons.ts b/core/renderer/settings/layout/icons.ts index 43b8436..807fe7b 100644 --- a/core/renderer/settings/layout/icons.ts +++ b/core/renderer/settings/layout/icons.ts @@ -42,6 +42,11 @@ export const SETTING_ICONS = { download: 'M12 4v11M7 10.5l5 5 5-5M5 20h14', chip: 'M7 7h10v10H7zM10 3v4M14 3v4M10 17v4M14 17v4M3 10h4M3 14h4M17 10h4M17 14h4', version: 'M20 12l-8 8-9-9V3h8zM7.5 7.5h.01', + // Diagnostics (#140): the page, the log, its folder, the mark. + diagnostics: 'M4 5h16v14H4zM6.5 12h3l1.5-3 2 6 1.5-3h3', + log: 'M6 3h9l4 4v14H6zM14 3v5h5M9 12h7M9 16h7', + folder: 'M3 6.5A1.5 1.5 0 0 1 4.5 5H9l2 2h8.5A1.5 1.5 0 0 1 21 8.5v9a1.5 1.5 0 0 1-1.5 1.5h-15A1.5 1.5 0 0 1 3 17.5z', + flag: 'M5 21V4M5 4h12l-2.5 4.5L17 13H5', // Marks inside a row. warn: 'M12 4l9 16H3zM12 10v4M12 17h.01', x: 'M6 6l12 12M18 6L6 18' diff --git a/core/renderer/settings/options.test.ts b/core/renderer/settings/options.test.ts index ab95902..f4ddcf2 100644 --- a/core/renderer/settings/options.test.ts +++ b/core/renderer/settings/options.test.ts @@ -2,6 +2,7 @@ import { describe, expect, it } from 'vitest' import { readdirSync, readFileSync, statSync } from 'fs' import { join } from 'path' import { labelProblem, copyProblem, subTooLong } from '../../shared/settingsCopy' +import { DIAGNOSTICS_OPTIONS } from './diagnosticsOptions' import { DICTATION_OPTIONS, dictationOptionIds } from './dictationOptions' import { HELP_OPTIONS } from './helpOptions' import { isSettingIcon } from './layout/icons' @@ -34,8 +35,8 @@ const rendered = new Set( [...sections.matchAll(/<(?:Pref|SettingRow)\s+id="([a-z-]+)"|data-pref="([a-z-]+)"/g)].map((m) => m[1] ?? m[2]) ) -const ALL = [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS] -const LIST_FILES = ['options.ts', 'dictationOptions.ts', 'helpOptions.ts'] +const ALL = [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS, ...DIAGNOSTICS_OPTIONS] +const LIST_FILES = ['options.ts', 'dictationOptions.ts', 'helpOptions.ts', 'diagnosticsOptions.ts'] describe('the terminal options list', () => { it('names every row the shared sections render, and nothing they do not', () => { @@ -103,6 +104,9 @@ describe('the terminal options list', () => { "dictation-model=prism.dictation.model", "dictation-gpu=null", "help-enabled=prism.help.enabled", + "diag-verbose=null", + "diag-folder=null", + "diag-mark=null", ] `) }) @@ -148,7 +152,14 @@ describe('the grouped cards fields of the lists (2026-10-05)', () => { const src = readFileSync(join(__dirname, f), 'utf8') const entries = [...src.matchAll(/\{\s*id: '([a-z-]+)'[^}]*\}/g)] const ids = entries.map((m) => m[1]) - const list = f === 'options.ts' ? TERMINAL_OPTIONS : f === 'dictationOptions.ts' ? DICTATION_OPTIONS : HELP_OPTIONS + const list = + f === 'options.ts' + ? TERMINAL_OPTIONS + : f === 'dictationOptions.ts' + ? DICTATION_OPTIONS + : f === 'diagnosticsOptions.ts' + ? DIAGNOSTICS_OPTIONS + : HELP_OPTIONS expect(ids, f).toEqual(list.map((o) => o.id)) for (const m of entries) { expect(m[0].includes('\n'), m[1]).toBe(false) diff --git a/core/renderer/settings/sectionIds.ts b/core/renderer/settings/sectionIds.ts index 8bd7fcb..e7076a0 100644 --- a/core/renderer/settings/sectionIds.ts +++ b/core/renderer/settings/sectionIds.ts @@ -6,7 +6,8 @@ * holds every name to this record. * * `dictation` has no heading: it is the first section of the Dictation page, - * and the page's own title says what it is. + * and the page's own title says what it is. Nor has `diagnostics` (#140), the + * one section of its page. */ export const SETTINGS_SECTIONS = { shell: 'Shell', @@ -20,7 +21,8 @@ export const SETTINGS_SECTIONS = { listening: 'Listening', while: 'While dictating', models: 'Speech models', - gpu: 'GPU acceleration' + gpu: 'GPU acceleration', + diagnostics: '' } as const export type SettingsSectionId = keyof typeof SETTINGS_SECTIONS diff --git a/core/renderer/settings/sections/DiagnosticsPage.tsx b/core/renderer/settings/sections/DiagnosticsPage.tsx new file mode 100644 index 0000000..216eb1b --- /dev/null +++ b/core/renderer/settings/sections/DiagnosticsPage.tsx @@ -0,0 +1,90 @@ +import { useEffect, useRef, useState, type JSX } from 'react' +import type { DiagApi } from '../../../preload/diagApi' +import { noteDiagVerbose } from '../../lib/diag' +import { ROW_BUTTON, Switch } from '../fields' +import { SettingRow } from '../layout/SettingRow' +import { SettingsSection } from '../layout/SettingsSection' +import { opt } from './opts' + +/** What the page needs from the bridge: the host hands it in (props only, + * as the update window does), so the page never reaches for a global. */ +export type DiagSettingsBridge = Pick + +/** How long the Mark button says Marked. */ +const MARKED_MS = 1200 + +/** + * THE DIAGNOSTICS PAGE (#140): Detailed logging, the log folder, and Mark a + * problem. The log itself is always on, at a quiet level; this page is how + * somebody turns the detail up, finds the files, and stamps the moment + * something went wrong, so "it stalled just now" can be found in the log. + */ +export function DiagnosticsPage({ api }: { api: DiagSettingsBridge }): JSX.Element { + const [verbose, setVerbose] = useState(false) + const [dir, setDir] = useState('') + const [marked, setMarked] = useState(false) + const timer = useRef | null>(null) + + useEffect(() => { + let live = true + void api + .diagInfo() + .then((i) => { + if (!live) return + setVerbose(!!i?.verbose) + setDir(i?.dir ?? '') + }) + .catch(() => {}) + return () => { + live = false + if (timer.current) clearTimeout(timer.current) + } + }, [api]) + + const flip = (on: boolean): void => { + setVerbose(on) + noteDiagVerbose(on) + void api + .diagSetVerbose(on) + .then((v) => { + setVerbose(v) + noteDiagVerbose(v) + }) + .catch(() => {}) + } + + const mark = (): void => { + api.diagMark() + setMarked(true) + if (timer.current) clearTimeout(timer.current) + timer.current = setTimeout(() => setMarked(false), MARKED_MS) + } + + const v = opt('diag-verbose') + const f = opt('diag-folder') + const m = opt('diag-mark') + return ( + + + + + {/* The folder's path is the subtext, whole on its tooltip, so it can be + read off the page as well as opened. */} + + + + + {/* Both words in one cell, only one visible: the button never + changes width as it answers. A grid button puts its one row at + the top, where a plain one centres its text (the e2e shot showed + Mark sitting 3px above Open folder's line), so it is centred. */} + + + + ) +} diff --git a/core/renderer/settings/sections/opts.ts b/core/renderer/settings/sections/opts.ts index 8416594..ea6b6c9 100644 --- a/core/renderer/settings/sections/opts.ts +++ b/core/renderer/settings/sections/opts.ts @@ -1,4 +1,5 @@ import { followsHostStyle, hostOwnsWindowAcrylic } from '../../host' +import { DIAGNOSTICS_OPTIONS, type DiagnosticsOption } from '../diagnosticsOptions' import { DICTATION_OPTIONS, type DictationOption } from '../dictationOptions' import { HELP_OPTIONS, type HelpOption } from '../helpOptions' import { TERMINAL_OPTIONS, type TerminalOption } from '../options' @@ -8,10 +9,10 @@ import { SETTINGS_SECTIONS, type SettingsSectionId } from '../sectionIds' // resting subtext are read from its list entry, so the page and Find a setting // can never word a row two ways. -type AnyOption = TerminalOption | DictationOption | HelpOption +type AnyOption = TerminalOption | DictationOption | HelpOption | DiagnosticsOption const byId = new Map( - [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS].map((o) => [o.id, o]) + [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS, ...DIAGNOSTICS_OPTIONS].map((o) => [o.id, o]) ) /** A core option by id. Throws on a typo, which the unit suite then finds. */ diff --git a/core/shared/channels.ts b/core/shared/channels.ts index 9a5b7c9..7b4311a 100644 --- a/core/shared/channels.ts +++ b/core/shared/channels.ts @@ -22,6 +22,21 @@ export const CH = { openPath: 'term:open-path' } as const +/** The diagnostics log's channels (#140). A table of its own, like + * dictation's: a host wires it with one call on each side of the bridge + * (`createDiagApi`, `startDiagnostics`). Every `diag:` channel is left out of + * the IPC timing, which would otherwise log the log. */ +export const DGCH = { + /** The page's lines, batched every 250 ms. */ + batch: 'diag:batch', + /** The page is alive: every 500 ms. A 2 s gap asks for its stack. */ + beat: 'diag:beat', + info: 'diag:info', + setVerbose: 'diag:set-verbose', + openFolder: 'diag:open-folder', + mark: 'diag:mark' +} as const + /** Dictation's channels (#13). A table of its own: dictation is optional, and * a host wires it with a separate call on each side of the bridge. */ export const DCH = { diff --git a/core/shared/diagGate.test.ts b/core/shared/diagGate.test.ts new file mode 100644 index 0000000..f954c1b --- /dev/null +++ b/core/shared/diagGate.test.ts @@ -0,0 +1,35 @@ +import { describe, expect, it } from 'vitest' +import { createDiagGate } from './diagGate' + +describe('createDiagGate', () => { + it('writes an error once, holds its copies, and says how many on the next line', () => { + const gate = createDiagGate<{ msg: string }>(10_000, 10) + expect(gate.offer('page-error', 'boom', { msg: 'boom' }, 0)).toEqual({ msg: 'boom' }) + // Sixty a second for five seconds: none written. + for (let t = 16; t < 5000; t += 16) expect(gate.offer('page-error', 'boom', { msg: 'boom' }, t)).toBeNull() + expect(gate.sweep(5000)).toEqual([]) + const again = gate.offer('page-error', 'boom', { msg: 'boom' }, 10_000) + expect(again).toMatchObject({ msg: 'boom' }) + expect(again?.repeats).toBeGreaterThan(300) + }) + + it('sweeps a burst that stopped, so its copies are still counted', () => { + const gate = createDiagGate<{ msg: string }>(10_000, 10) + gate.offer('page-error', 'boom', { msg: 'boom' }, 0) + gate.offer('page-error', 'boom', { msg: 'boom' }, 100) + gate.offer('page-error', 'boom', { msg: 'boom' }, 200) + expect(gate.sweep(9_999)).toEqual([]) + expect(gate.sweep(10_000)).toEqual([{ msg: 'boom', repeats: 2 }]) + expect(gate.sweep(20_000)).toEqual([]) + }) + + it('caps the lines per kind, whatever they say: a message with a counter is a new key each time', () => { + const gate = createDiagGate<{ msg: string }>(10_000, 10) + const written = Array.from({ length: 100 }, (_, i) => gate.offer('page-error', `n${i}`, { msg: `n${i}` }, i)) + expect(written.filter(Boolean)).toHaveLength(10) + // Another kind has its own budget. + expect(gate.offer('page-rejection', 'r', { msg: 'r' }, 100)).not.toBeNull() + // The held ones come out as the budget allows, ten per window. + expect(gate.sweep(10_000)).toHaveLength(10) + }) +}) diff --git a/core/shared/diagGate.ts b/core/shared/diagGate.ts new file mode 100644 index 0000000..39c8d04 --- /dev/null +++ b/core/shared/diagGate.ts @@ -0,0 +1,81 @@ +/** + * ONE ERROR, NOT A FLOOD (#140, review of the branch). An error thrown on every + * frame (a requestAnimationFrame loop, a render loop) is 60 lines a second of + * up to 2.3 KB each, which would roll the 10 MB of log files over in about 75 s + * and take the session line and the FIRST error, the one that explains the + * rest, with it. Used by both halves: the page's errors and main's rejections. + * + * - The same error (its kind and key: message and place) is written once per + * `everyMs`. The copies in between are counted, and the next line written + * for it carries `repeats`, how many were not written since the last one. + * - At most `budget` lines per kind per `everyMs`, whatever they say: a + * message with a counter in it is a new key every time. + * - `sweep` writes what is still held once its time has come, so a burst that + * stops is still counted. + * + * Pure: the caller hands in the clock. + */ + +export interface DiagGate { + /** The line to write now (with `repeats` when copies were held), or null to hold it. */ + offer(k: string, key: string, line: T, now: number): (T & { repeats?: number }) | null + /** The held copies whose time has come: one line each, with `repeats`. */ + sweep(now: number): Array +} + +interface Entry { + k: string + line: T + lastSent: number + held: number +} + +/** Past this many distinct errors, a new one over budget is not remembered. */ +const MAX_KEYS = 200 + +export function createDiagGate(everyMs = 10_000, budget = 10): DiagGate { + const entries = new Map>() + const windows = new Map() + + const allow = (k: string, now: number): boolean => { + let w = windows.get(k) + if (!w || now - w.start >= everyMs) windows.set(k, (w = { start: now, sent: 0 })) + if (w.sent >= budget) return false + w.sent += 1 + return true + } + + return { + offer: (k, key, line, now) => { + const e = entries.get(key) + if (e && now - e.lastSent < everyMs) { + e.held += 1 + return null + } + if (!allow(k, now)) { + if (e) e.held += 1 + else if (entries.size < MAX_KEYS) entries.set(key, { k, line, lastSent: -Infinity, held: 1 }) + return null + } + const held = e?.held ?? 0 + entries.set(key, { k, line, lastSent: now, held: 0 }) + return held > 0 ? { ...line, repeats: held } : line + }, + sweep: (now) => { + const out: Array = [] + for (const [key, e] of entries) { + if (now - e.lastSent < everyMs) continue + if (e.held === 0) { + // Quiet for a while: forget it, so the map stays small. + if (now - e.lastSent >= everyMs * 6) entries.delete(key) + continue + } + if (!allow(e.k, now)) continue + out.push({ ...e.line, repeats: e.held }) + e.held = 0 + e.lastSent = now + } + return out + } + } +} diff --git a/core/shared/settingsCopy.test.ts b/core/shared/settingsCopy.test.ts index 77e5636..269d151 100644 --- a/core/shared/settingsCopy.test.ts +++ b/core/shared/settingsCopy.test.ts @@ -72,7 +72,7 @@ describe("the core's own settings", () => { it('keep every new label plain and every new subtext to eight words', () => { const fresh = source.filter((f) => { const r = relative(dir, f).replace(/\\/g, '/') - return /^(layout|sections)\//.test(r) || ['options.ts', 'dictationOptions.ts', 'helpOptions.ts', 'coreIndex.ts'].includes(r) + return /^(layout|sections)\//.test(r) || ['options.ts', 'dictationOptions.ts', 'helpOptions.ts', 'diagnosticsOptions.ts', 'coreIndex.ts'].includes(r) }) expect(fresh.length).toBeGreaterThan(10) const long: string[] = [] diff --git a/docs/diagnostics.md b/docs/diagnostics.md new file mode 100644 index 0000000..87dda12 --- /dev/null +++ b/docs/diagnostics.md @@ -0,0 +1,135 @@ +# The diagnostics log + +Both apps keep a local log of stalls, slow work, errors and what the user had just done (#140; owner, +2026-10-07: "implement some robust logging and debugging into the program especially to catch +stalls"). It is written by the core (`core/main/diag*.ts`, `core/main/ipcTiming.ts`, +`core/main/stallWatch.ts`, `core/main/crashHooks.ts`, `core/renderer/lib/diag.ts`). Design and +plan: `docs/superpowers/specs/2026-10-07-diagnostics-log-design.md`. It never leaves the PC +(`PRIVACY.md`). + +## Where it is + +| App | Folder | +| --- | --- | +| Prism Terminal | `%APPDATA%\PrismTerminal\logs` | +| Prism Terminal (Stable copy) | `%APPDATA%\PrismTerminalStable\logs` | +| Prism | `%APPDATA%\Prism\logs` (once Prism wires `diagLogDir`) | +| An e2e scenario | `\logs` (removed with the profile) | + +`diag.jsonl` is the live file. At 2 MB it rotates to `diag.jsonl.1` (newest) through +`diag.jsonl.4`, so an app holds at most 10 MB. Detailed logging is remembered in +`\diag.json` (`{"verbose":true}`). Settings > Diagnostics opens the folder and shows its +path. + +## Reading it + +``` +npm run diag newest 20 problems in Prism Terminal's log, crumbs before each +npm run diag -- --app stable the stable copy (the owner works in this one) +npm run diag -- --app prism Prism +npm run diag -- --since 10m only the last ten minutes (ms, s, m, h, d) +npm run diag -- --all every line, not only problems +npm run diag -- --kinds page-stall,main-lag +npm run diag -- --dir any folder holding a diag.jsonl +``` + +When the owner says "it stalled just now", run `npm run diag -- --app stable --since 10m` (or the +app they named) and read from the bottom: a `mark` line is the moment they pressed Mark a problem. +Lines are sorted by `t`; a page's lines are written up to a few seconds after they happened (they +arrive in batches), so the file itself is not in time order, `t` is. + +How to read a stall: +- **`page-stall`** says how long the page's frame ran and WHICH scripts: `fn` in `src`, started by + `invoker` (`BUTTON.onclick`, `TimerHandler:setTimeout`, `MessagePort.onmessage`...). Its `crumbs` + are what the user did just before, with `ago` in ms. +- **`page-stack`** (2 s or more) is the page's JavaScript stack taken WHILE it was stuck: the top + frame is the code that was running. +- **`main-lag`** lists `inflight`: the IPC calls running during the lag, or that ended inside it + (`done`). A long `ipc-slow` beside it usually names the cause. +- **`fs-slow`** next to slow listings means libuv's four fs threads were starved (a dead network or + optical drive, a size scan), not that one folder is slow. + +## The line + +One JSON object per line: + +```json +{"t":"2026-10-07T09:12:03.412Z","up":12345,"src":"main","k":"main-lag","ms":140,"inflight":[...]} +``` + +- `t`: when it happened (ISO, UTC). `up`: ms since the app started, on main's clock, so order + survives a clock change. `src`: `main` or `page`. `k`: the kind. These four are always the + writer's own; a field cannot overwrite them. +- Strings are capped at 300 characters (a `stack` at 2000) and end in `...(+n)` when cut. IPC + arguments are summarised: an array is `[n]`, bytes `bytes:n`, objects one level deep. Typed text + (`term:input`), the clipboard and recorded audio are logged by size only (`string:7`). +- Paths are written in full. + +## Kinds + +Quiet level, always on: + +| kind | src | when | fields | +| --- | --- | --- | --- | +| `session` | main | start | `app`, `version`, `electron`, `chrome`, `windows`, `pid`, `verbose`, `cpus`, `cpu`, `ramGb`, `e2e` | +| `quit` | main | the quit, last line | | +| `session-end` | main | Windows is shutting down or logging off (no `quit` follows) | | +| `main-lag` | main | main's 50 ms tick came 100 ms or more late (never for a sleep: `powerMonitor`) | `ms`, `inflight` (`ch`, `ms`, `done`) | +| `fs-slow` | main | a `stat` of userData (every 5 s) took 500 ms or more | `ms` | +| `ipc-slow` | main | a `handle` settled after 500 ms, or a sync `on` body ran 100 ms; never a call that waits on the user or a download (the folder picker, an update install, a dictation download: `LONG_WAIT` plus the host's `longWaitChannels`), which is also left out of `inflight` | `ch`, `ms`, `args`, `ok`, `sync` | +| `ipc-error` | main | a handler threw or rejected (rethrown unchanged) | `ch`, `ms`, `err`, `stack` | +| `page-stall` | page | a long animation frame of 200 ms or more | `ms`, `blocking`, `scripts` (`src`, `fn`, `invoker`, `ms`), `crumbs` (`a`, `ago`) | +| `page-stack` | main | the page missed its heartbeat for 2 s, and a `page-stall` covering that moment arrived (or the window said unresponsive) | `stack`, `ms`, `unresponsive` | +| `page-error` / `page-rejection` | page | `error`, `unhandledrejection` | `msg`, `stack`, `loc` (script:line:col), `repeats` | +| `main-error` / `main-rejection` | main | `uncaughtExceptionMonitor`, `unhandledRejection` (observed only) | `msg`, `stack`, `origin`, `repeats` | +| `gone` | main | a renderer or child process (GPU, utility) ended | `type`, `reason`, `exitCode`, `name` | +| `unresponsive` / `responsive` | main | the window's own hang events | `ms` (on `responsive`) | +| `crumb` | page, main | an action (below) | `a`, its own fields | +| `mark` | page | Settings > Diagnostics > Mark a problem | `note` | +| `verbose` | main | Detailed logging switched | `on` | +| `logger-error` | main | the log could not write, or could not rotate (once a session; a failed rotation keeps writing to the live file and tries again 30 s later) | `msg` | +| `logger-dropped` | main | the writer's queue was full (2000 lines): the NEWEST were dropped | `n` | +| `-slow` | page | an app's own timing through `time()` (Prism: `sort-slow`, `guard-slow`) | `ms`, its own fields | + +Detailed logging adds `ipc` (every call: `ch`, `ms`), `page-task` (long tasks from 50 ms: `ms`) and +the high-rate crumbs (`often`). + +**Errors are gated** (`core/shared/diagGate.ts`): the same error (kind, message, place) is written +once per 10 s, and the next line for it carries `repeats`, how many copies were not written in +between; at most 10 error lines per kind per 10 s whatever they say. An error thrown on every frame +would otherwise roll the whole 10 MB over in about 75 s and take the first error with it. The +page's own queue drops its newest lines past 200 the same way and says so with a `diag-dropped` +crumb (`n`). + +## Crumbs + +Prism Terminal and the core say these today: + +| `a` | from | fields | +| --- | --- | --- | +| `tab-open` | page | `id`, `cwd`, `resume` | +| `tab-close` | page | `id`, `kind` | +| `tab-switch` | page | `id` | +| `settings-page` | page | `page` | +| `update-open` / `update-install` | page (core) | `version`, `preview` | +| `dictation` | page (core) | `phase`: `listening`, `transcribing`, `idle` | +| `shell-spawn` | main (core) | `id`, `pid`, `shell`, `cwd`, `resume`, `ms`, `warm` | +| `shell-exit` | main (core) | `id`, `pid`, `exitCode` | +| `shell-spawn-failed` | main (core) | `id`, `shell`, `cwd`, `err` | + +Adding one: `crumb('name', { fields })` from `core/renderer/lib/diag` in a page, or +`diagMain().write('main', 'crumb', { a: 'name', ... })` in main. A crumb that can fire many times a +second passes `{ often: true }`. + +## Wiring (a host) + +- Main, before any IPC is registered: `startDiagnostics({ diagLogDir, ipcMain, process, app, + appInfo, openFolder, longWaitChannels, powerMonitor })`, then `watchWindow(win)` once the window + exists and `stop()` on the quit that goes ahead. No `diagLogDir`: nothing is logged and the + bridge still answers. `powerMonitor` is a getter (`() => powerMonitor`), hooked in `watchWindow` + since it cannot be used before ready. At a Windows shutdown no quit comes: call + `diag.log.flushSync()` in the window's `session-end`. +- `session.webRequest.onHeadersReceived`: `withStackPolicy` on `mainFrame` responses, or the page + stack never comes (MEASURED: "Website owner has not opted in"). +- Preload: `...createDiagApi(ipcRenderer)`. Page: `startDiag(bridge)` before the first render. +- Settings: `` and `coreSettingsIndex({ diagnostics: true })`. diff --git a/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md b/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md new file mode 100644 index 0000000..b854b3b --- /dev/null +++ b/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md @@ -0,0 +1,269 @@ +# Diagnostics log: design and plan (2026-10-07) + +Owner, 2026-10-07: "implement some robust logging and debugging into the program especially to catch +stalls for example in explorer or in general. that would help me and you". Settled by question round +the same day: + +- **Scope:** both apps. The logger is written once in `core/`, and the Explorer probes are Prism's own. +- **What it catches:** + - UI freezes + - slow work in main + - errors and crashes + - an action timeline (breadcrumbs) +- **Where it goes:** log files on disk, and a Settings > Diagnostics page. +- **Paths:** recorded in full, and the log stays local only. +- **When it runs:** on by default at a quiet level. A switch turns on verbose. +- **Thresholds:** + - page blocked 200 ms + - main event loop late 100 ms + - IPC answer slower than 500 ms + - more than 2 s also tries to capture what was running +- **E2E:** each scenario's stalls are reported at the end of the run. They do not fail the run. +- **Handoff:** the owner says "it stalled just now" and Claude reads the newest log files. A Mark + button stamps the moment. + +## What exists today (scouted 2026-10-07) + +- **Prism:** `window-crashes.log` (`crashLog.ts`, 64 KB cap) records only the window's crash, hang and + watchdog. `phone.log` covers the phone. There is no global error handler, no IPC timing and no + renderer probe. About 100 IPC registrations sit in `src/main/index.ts`. +- **PT:** nothing. It has no log, no crash reporter and no error handlers. +- **Both:** every `ipcMain.handle/on` goes through Electron's one `ipcMain` object, and the core's + register functions receive that same object. That object is the single choke point. +- **Explorer suspects, ranked (Prism, file:line in the scout report):** + 1. `realpathSync` guards over large path sets (`desktopAccess.ts:41-73`, from `folder:sizes-cached` + and `search:files`). + 2. libuv threadpool starvation (4 threads): 26 drive-letter stats, 16 stats per listing, size + scans. A dead network or optical drive holds up every async fs call. + 3. A full re-sort on every folder-size tick (`FolderBrowser.tsx:69-73`). + 4. Every scroll event goes to App state, then a whole App rerender plus a `tabsChanged` IPC. + 5. A full reread on every window focus. + +The log is meant to confirm or rule these out with numbers. It fixes none of them; each fix is its +own PR once the log shows the culprit. + +## Design + +### The file +- **Location:** `\logs\diag.jsonl`. That is `%APPDATA%\PrismTerminal\logs` and + `%APPDATA%\Prism\logs`, and the stable PT copy gets its own. +- **Rotation:** at 2 MB the file rotates to `.1` to `.4`, so at most 10 MB per app. +- **Format:** one JSON object per line: `{"t":"2026-10-07T09:12:03.412Z","up":12345,"src":"main|page","k":"",...fields}`. + - `up` is ms since the app started, so lines order correctly across a clock change. + - Fields are flat and short. Strings are capped at 300 characters and arrays are logged as their + length. +- **Writes:** async, through a single queue, with appends batched at 250 ms. A write never throws. On + `will-quit` the queue flushes synchronously, so the line just before a crash lands. +- **Session line at start:** app, version, Electron and Chromium versions, Windows build, pid, + `verbose`, and the CPU and RAM size. + +### Kinds (quiet level) + +| kind | from | when | fields | +| --- | --- | --- | --- | +| `session` | main | start | see above | +| `main-lag` | main | event loop late 100 ms+ (`monitorEventLoopDelay` plus a 50 ms drift timer) | `ms`, `inflight` (IPC calls running at that moment, with how long each had run) | +| `fs-slow` | main | the fs canary (one `fs.promises.stat` of userData every 5 s) took 500 ms+ | `ms`. This is the threadpool-starvation signal | +| `ipc-slow` | main | an `ipcMain.handle` settled after 500 ms+, or a sync `on` body ran 100 ms+ | `ch`, `ms`, `args` (summarised), `ok` | +| `ipc-error` | main | a handler threw or rejected | `ch`, `err`, `stack` | +| `page-stall` | page | long-animation-frame 200 ms+ (Chromium's LoAF, which names the script, function and what started it) | `ms`, `blocking`, `scripts[]` (`src`, `fn`, `invoker`, `ms`), `crumbs` (the last 5) | +| `page-stack` | main | the page sent no heartbeat for 2 s. Main asks the frame for its JavaScript stack (`collectJavaScriptCallStack`) and writes it ONLY when a `page-stall` overlapping that time then arrives, so a throttled background timer is never a false stall | `stack`, `ms` | +| `page-error` / `page-rejection` | page | `window.onerror`, `unhandledrejection` | `msg`, `stack`, `src` | +| `main-error` / `main-rejection` | main | `uncaughtExceptionMonitor` (observe only, so behaviour is unchanged), `unhandledRejection` | `msg`, `stack` | +| `gone` | main | `render-process-gone`, `child-process-gone` (GPU, utility) | `type`, `reason`, `exitCode` | +| `unresponsive` / `responsive` | main | the window's own events | `ms` | +| `crumb` | page or main | an action (below) | `a` (action), plus its own fields | +| `mark` | page | the Mark button | `note` (optional) | +| `verbose` | main | the switch changed | `on` | + +**Verbose adds:** +- `ipc` for every call, with its time. +- `crumb` for high-rate actions: scroll settles, hover previews. +- `page-task` for long tasks from 50 ms. + +### Breadcrumbs (`crumb`) +- **Low-rate actions,** logged at quiet level: + - **Both apps:** tab opened, closed and switched; Settings page opened; update window opened and + install started; dictation started and stopped. + - **PT:** a shell was spawned and its pid exited. + - **Prism Explorer:** + - `open-folder`, with path, reason (navigate, back, refresh, focus, dir-changed), ms, entry + count and cached + - sort or filter changed + - preview opened + - search started, finished or cancelled, with ms and hits + - folder-size scan finished, with path and ms + - the watcher set up, with ms + - the sort-and-filter pass, logged when it took 50 ms+, with the entry count + - **Prism, elsewhere:** project opened, player file opened, archive job started and ended. +- **The ring buffer:** the page also keeps the last 50 crumbs in memory and attaches the last 5 to + any `page-stall`. + +### Probes specific to Prism's Explorer +- **Path guard:** `desktopAccess` reports `guard-slow` when one guard call took 50 ms+, with the path + count and ms. This tests suspect 1 directly. +- **Re-sorts:** the `browseEntries` memo times itself and logs `sort-slow` at 50 ms+, with the entry + count and what triggered it (sizes, query or sort). +- **Starvation:** the fs canary covers suspect 2. The listing's own `ms` field next to it says whether + the pool was starved or the folder was slow. + +### Core pieces (`core/`, in PT) +- `core/main/diagLog.ts`: the writer: queue, rotation, flush at quit, verbose state (persisted in + `\diag.json`). +- `core/main/diagSummary.ts`: pure. Summarises IPC arguments and caps strings. +- `core/main/ipcTiming.ts`: `timeIpcMain(ipcMain, log)` patches `handle`, `on` and `removeListener`. + - A map from each original listener to its wrapper keeps `removeListener` working; Prism's + `open:listen` depends on it. + - It also keeps a table of the calls in flight. +- `core/main/stallWatch.ts`: event-loop lag, the fs canary, the heartbeat watcher and the + pending-stack logic. +- `core/main/crashHooks.ts`: `process` and `app` handlers, plus the window events. +- `core/main/diagIpc.ts`: the channels `diag:batch` (the page's batched lines), `diag:beat`, + `diag:info`, `diag:set-verbose`, `diag:open-folder` and `diag:mark`. They go in + `core/shared/channels.ts`, `core/preload/diagApi.ts` and the bridge. +- `core/renderer/lib/diag.ts`: + - the page side: the LoAF and long-task observers, error handlers, heartbeat, crumb ring and batch + sender + - `diag.crumb(action, fields)` and `diag.time(label, fn)` for the apps to call +- `core/renderer/settings/Diagnostics.tsx` and `diagnosticsOptions.ts`. The rows are: + - **Detailed logging:** the verbose switch + - **Log files:** Open folder, plus the folder path as text + - **Mark a problem:** a button that writes `mark` and says Marked for 1.2 s + - The wording passes `settingsCopy`. +- `core/README.md`: the contract adds `diagLogDir` to the main deps. A host without it logs nothing, + so Prism is unchanged until it wires it. + +### Each app's part +- **PT:** + - `src/main/index.ts` calls `timeIpcMain` before `wireIpc()` and starts the watchers. + - The renderer calls `diag.start()` in `main.tsx`. + - Crumbs go at the tab, settings, update and dictation sites. + - Settings gets a fourth rail tab, Diagnostics. +- **Prism:** + - The same wiring, before the whenReady block. + - `logWindow` also writes `window-crashes.log`, kept because the error box and the + `neverWindowless` e2e name it. + - Diagnostics is a rail tab in the last group, next to About. + - The Explorer crumbs and probes listed above. +- **Prism's preload** keeps its direct `ipcRenderer` calls; timing is main-side only. +- **Privacy:** PT's `PRIVACY.md` and Prism's README privacy line say a local diagnostics log is kept, + is never sent, and can be opened from Settings. + +### Reading the logs (for Claude) +- `docs/diagnostics.md` in PT gives the schema, the file locations and how to read them. +- `tools/diag.mjs`, run as `npm run diag -- [--app prism|pt|stable] [--since 10m] [--kinds stall]`, + prints the newest problems: stalls, errors and slow calls, each with its crumbs before it. +- Each repo's CLAUDE.md gets a short rule and a pointer. +- The memory notes where the logs live. + +### E2E +- **PT `diagLog` scenario:** + - It triggers each problem through e2e-only hooks: + - a 2.5 s page busy loop + - `e2e:slow-ipc`, which sleeps 600 ms + - a thrown page error + - a rejected promise + - It then reads `diag.jsonl` and asserts: + - `session` + - `page-stall` with a script attribution + - `page-stack`, if `collectJavaScriptCallStack` works for our page (MEASURED first; if it needs a + Document-Policy header we cannot set for `file://`, the kind is dropped and the LoAF + attribution carries it) + - `ipc-slow` with `ch` + - `page-error` + - crumbs before the stall + - the Mark button's line + - the verbose switch persisting across a relaunch + - Also checked: rotation at the cap (a unit test fills the file), and that quiet mode writes + nothing during an idle 3 s. +- **PT `options`:** gets the Diagnostics tab, and `diagnosticsOptions.ts` joins `wanted`, the way + `helpOptions` does. +- **Prism `diagLog`:** runner-safe and in `e2e:terminal`, so the core bump's gate holds it. A plus + `explorerDiag` opens a folder and reads its `open-folder` crumb, with `ms` and `entries`. +- **Both runners:** before a profile is removed (PT), or per scenario by clearing then reading the + shared profile's log (Prism), the runner collects stall and error lines over 1 s. It prints them in + a closing "Stalls" table. That table is a report only; the exit code is unchanged. + +### Cost and safety +- **Quiet level when nothing is wrong:** one session line, the crumbs (a handful a minute), the 5 s + stat and a 50 ms timer. +- **IPC wrapper:** two `performance.now()` calls per call. +- **Failures stay silent:** a logger that fails is silent and never takes the app down. The writer + swallows its own errors after one `logger-error` line. + +## Plan + +**PR A, PT** (issue first, branch `feat/-diagnostics-log`): core 0.26.x to 0.27.0, app minor bump. +- Tasks, in order, each test-first: + 1. `diagSummary` + `diagLog` (rotation, queue, flush, verbose persistence) + 2. `ipcTiming` (timing, errors rethrown unchanged, `removeListener`, in-flight) + 3. `stallWatch` with fake timers (lag, canary, heartbeat, pending stack only on an overlapping + stall) + 4. `crashHooks` + 5. the `diagIpc` + channels + preload `diagApi` + 6. renderer `diag.ts` (LoAF parsing, ring, batching) + 7. the `Diagnostics` settings component + options + copy test + 8. PT wiring + crumbs + Settings tab + 9. `tools/diag.mjs` + `docs/diagnostics.md` + CLAUDE.md + `PRIVACY.md` + 10. the e2e `diagLog`, `options` update, and the runner's Stalls table + 11. measure `collectJavaScriptCallStack` on our page and keep or drop `page-stack` +- **Gates:** typecheck, lint, the full unit suite, full PT e2e. Then install PT (not stable) for + hands-on. +- **Release candidate:** a `core-v0.27.0-rc.1` cut from the PR branch, so Prism's PR can be built + against it. + +**PR B, Prism** (its own issue and branch), against the rc pin, re-pinned to `core-v0.27.0` once A +merges. It also folds in the auto bump. +1. Main wiring, plus `logWindow` writing to both logs. +2. Settings Diagnostics tab. +3. Explorer crumbs and probes (`useFolderBrowsing`, `FolderBrowser`, `desktopAccess`, search, sizes, + watch). +4. Other crumbs (tabs, project, player, archive). +5. README privacy line, CLAUDE.md. +6. The e2e `diagLog` (in `e2e:terminal`) and `explorerDiag`, and the runner's Stalls table. +7. **Gates:** typecheck, unit, full Prism e2e, one run at a time. Then package and install. + +**Order:** +- The owner merges PT A first. Its core bump PR to Prism auto-merges when green. +- The owner then merges Prism B, rebased on that bump. +- A and B ride after the PRs already open (PT #139, which takes core 0.26.0, then this is 0.27.0). + +## Measured during PR A (2026-10-07) + +- **`page-stack` is KEPT (task 11).** Electron 43.7.3, a page spinning in a 3 s busy loop: + `mainFrame.collectJavaScriptCallStack()` answered in 0 to 1 ms, but with the sentence "Website + owner has not opted in for JS call stacks in crash reports." until the document was served with + `Document-Policy: include-js-call-stacks-in-crash-reports`. Set through + `session.webRequest.onHeadersReceived` (or a `protocol.handle('file')` wrapper), the stack came + back (`at spinHard ... at outerBusy ...`) for a `file://` page AND a dev server's `http://` page. + In the BUILT Prism Terminal under `--e2e` the whole chain landed: `page-stall` (3000 ms, invoker + `TimerHandler:setTimeout`), then `page-stack` with the busy function's name, 2012 ms after the + last beat. The core exports `withStackPolicy`; each host adds it for `mainFrame` responses. +- **The first run found a cause already:** the first `term:spawn` of a launch blocked main for + about 1.4 to 1.6 s (`main-lag` beside `ipc-slow term:spawn`, `shell-spawn` `ms` 1446 to 1647): + node-pty's import and the ConPTY start on the restore's spawn. Its own issue, not this PR. +- **It also found two bugs, fixed before the commit:** a page error's script location, named + `src`, overwrote the line's `src` (now `loc`, and the writer's four keys can never be + overwritten); and `main-lag` listed nothing in flight because the blocking call had settled a + millisecond before the late tick ran (now it names the calls that ended inside the lag, `done`). +- **Electron's main runs Node in warn mode** for unhandled rejections (MEASURED: a warning, the app + runs on, with or without a listener), so listening to `unhandledRejection` changes nothing but + the console warning. + +Deviations from the design above, each small: +- Strings cap at 300, but a `stack` at 2000: 300 characters is about two frames. +- `main-lag` uses the 50 ms drift timer alone: `monitorEventLoopDelay` is a sampled histogram and + says how bad, never when, and a timeline line needs the when. +- `page-stack` is also written when the window reports `unresponsive` (a real hang, no throttle), + not only on an overlapping `page-stall`. +- The page error's location field is `loc`, not `src` (above). `quit` is a kind of its own, the + last line of a session. +- The settings component is `core/renderer/settings/sections/DiagnosticsPage.tsx` (beside + `DictationPage`, so the grouped cards' copy rules hold it), and it takes the bridge as a prop + rather than through a new `TermHostConfig` field. In PT it is the rail's fifth page, directly + above About: the redesign (#134) had already given the rail four pages before About. +- `startDiagnostics` (`core/main/diagnostics.ts`) composes the pieces, so a host wires it in one + call; `pageLine` in `diagIpc.ts` holds the page to its own kinds. + +**After merge:** install both. The owner uses them, and the first "it stalled" is read with +`npm run diag`. diff --git a/package-lock.json b/package-lock.json index 89c2a93..265e25e 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "prism-terminal", - "version": "0.33.0", + "version": "0.34.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "prism-terminal", - "version": "0.33.0", + "version": "0.34.0", "license": "MIT", "dependencies": { "@xterm/addon-fit": "^0.11.0", diff --git a/package.json b/package.json index f534e97..9f09cc1 100644 --- a/package.json +++ b/package.json @@ -1,7 +1,7 @@ { "name": "prism-terminal", "productName": "Prism Terminal", - "version": "0.33.0", + "version": "0.34.0", "description": "A tabbed Windows terminal for AI CLIs.", "main": "./out/main/index.js", "author": "Max", @@ -16,6 +16,7 @@ "test": "vitest run --passWithNoTests", "test:watch": "vitest", "fetch:bin": "node core/tools/fetch-whisper.mjs vendor/whisper", + "diag": "node tools/diag.mjs", "install:stable": "powershell -NoProfile -ExecutionPolicy Bypass -File tools/install-stable.ps1", "e2e": "npm run fetch:bin && npm run build && node tools/e2e/run.mjs", "lint": "eslint .", diff --git a/src/main/index.ts b/src/main/index.ts index 81cdf60..8f5d7cf 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -1,4 +1,4 @@ -import { app, BrowserWindow, clipboard, dialog, ipcMain, Menu, nativeImage, session, shell } from 'electron' +import { app, BrowserWindow, clipboard, dialog, ipcMain, Menu, nativeImage, powerMonitor, session, shell } from 'electron' import pkg from '../../package.json' import { existsSync } from 'fs' import { stat } from 'fs/promises' @@ -8,6 +8,8 @@ import type { Restored, SavedTabs, UpdateInfo } from '@shared/types' import { claudeSessionsAsync } from '@core/main/agentResume' import { registerTermIpc } from '@core/main/ipc' import { registerDictationIpc } from '@core/main/dictationIpc' +import { startDiagnostics, type Diagnostics } from '@core/main/diagnostics' +import { withStackPolicy } from '@core/main/diagIpc' import { planRestore } from './planRestore' import { foldersFromArgv } from './argv' import { acrylicOk, createMaterial } from './material' @@ -187,6 +189,9 @@ const isDir = (p: unknown): Promise => * hands its folder over and ends. * ------------------------------------------------------------------ */ let quitting = false // app.quit() is under way +/** The diagnostics log (#140). Started first thing in the instance that holds + * the lock, before any IPC is registered: the timing wraps ipcMain itself. */ +let diag: Diagnostics | null = null /** Kills dictation's children (the speech server, the media helper). Set by wireIpc. */ let stopDictation: () => void = () => {} let quitWanted = false // a quit the close question interrupted; confirm resumes it @@ -295,6 +300,8 @@ function createWindow(): void { } }) mainWindow = win + // Its hang events, and its frame for the page's stack when the heartbeat stops. + diag?.watchWindow(win) win.on('ready-to-show', () => { // Maximised is restored after the window exists rather than at construction: // a window created maximised has no sensible un-maximised size to go back to. @@ -336,8 +343,14 @@ function createWindow(): void { agentBusy = false // Not prevented: the window closes, and window-all-closed ends the app. }) - // Windows is shutting down or logging off: no before-quit is coming. - win.on('session-end', () => tabs.flush()) + // Windows is shutting down or logging off: no before-quit is coming, nor + // the will-quit that writes out the diagnostics log, so its last lines + // (those just before a hang at shutdown) are written here. + win.on('session-end', () => { + tabs.flush() + diag?.log.write('main', 'session-end', {}) + diag?.log.flushSync() + }) win.on('enter-full-screen', () => { send('window:fullscreen', true) @@ -676,6 +689,9 @@ function wireIpc(): void { }) // The DWM border itself is off under --e2e, so the suite asks what main HEARD. if (E2E) ipcMain.handle('e2e:window-edges', () => windowEdges) + // The e2e's diagLog (#140): a call that answers after 600 ms, so the IPC + // timing's ipc-slow line (500 ms+) is proved on a real channel. + if (E2E) ipcMain.handle('e2e:slow-ipc', () => new Promise((r) => setTimeout(() => r(true), 600))) // THE TASKBAR BADGE (2026-09-28): the page draws the disc, main puts it on // the window's taskbar button as its overlay icon. Only a small PNG data url // is taken; anything else, or null, clears it. @@ -718,6 +734,25 @@ function wireIpc(): void { if (!app.requestSingleInstanceLock()) { app.quit() } else { + // THE DIAGNOSTICS LOG (#140; owner, 2026-10-07: "robust logging and + // debugging ... especially to catch stalls"), the core's, schema in + // docs/diagnostics.md. Here and not at ready: the crash hooks should hear a + // failure during startup too, and every ipcMain registration (all in + // wireIpc) comes after, so every call is timed. Only the instance holding + // the lock: a second launch hands its folder over and ends, and two writers + // on one file would interleave their batches. + diag = startDiagnostics({ + diagLogDir: join(app.getPath('userData'), 'logs'), + ipcMain, + process, + app, + appInfo: { name: 'Prism Terminal', version: pkg.version, e2e: E2E }, + // Never under --e2e: recorded, like every path the app opens (#64). + openFolder: (dir) => pathOpeners.openPath(dir), + // These wait on the user (the picker) or a download: never a stall. + longWaitChannels: ['dialog:pick-folder', 'update:install'], + powerMonitor: () => powerMonitor + }) app.on('second-instance', (_e, argv, workingDirectory) => { // Resolved against the folder the second launch was typed in (#16). const folders = foldersFromArgv(argv, undefined, workingDirectory) @@ -763,7 +798,13 @@ if (!app.requestSingleInstanceLock()) { // its app.quit() lands inside the quit it cancelled and Electron drops it, // so the app stayed up (MEASURED, the opacityAlpha quit). Hence also the // fresh tick before quitting again. - if (shellsSettled || shellsDying() === 0) return + if (shellsSettled || shellsDying() === 0) { + // The quit is going ahead: the log's queue is written synchronously, + // so its last lines land. + diag?.stop() + diag = null + return + } e.preventDefault() void shellsGone(3000).then(() => { shellsSettled = true @@ -791,6 +832,17 @@ if (!app.requestSingleInstanceLock()) { if (!own(wc) || !granted.has(permission)) return false return permission !== 'media' || (details as { mediaType?: string }).mediaType !== 'video' }) + // THE PAGE OPTS IN TO HAVING ITS STACK READ (#140): main asks for it when + // the heartbeat stops (`collectJavaScriptCallStack`), and the frame only + // answers for a document served with this Document-Policy. MEASURED on + // Electron 43: without the header the answer is "Website owner has not + // opted in"; with it, set here, the stack of a 3 s busy loop came back in + // about 1 ms, for the built file:// page and the dev server's page alike. + // Documents only; every other response passes untouched. + session.defaultSession.webRequest.onHeadersReceived((d, callback) => { + if (d.resourceType !== 'mainFrame') return callback({}) + callback({ responseHeaders: withStackPolicy(d.responseHeaders) }) + }) wireIpc() createWindow() // Warm the terminal's fixed costs shortly after launch: the native module diff --git a/src/preload/index.ts b/src/preload/index.ts index 93422d7..7a5245e 100644 --- a/src/preload/index.ts +++ b/src/preload/index.ts @@ -1,6 +1,7 @@ import { contextBridge, ipcRenderer, webUtils } from 'electron' import { createTermApi } from '@core/preload/api' import { createDictationApi } from '@core/preload/dictationApi' +import { createDiagApi } from '@core/preload/diagApi' import type { Restored, SavedTabs, UpdateInfo } from '@shared/types' import type { WindowEdges } from '@shared/windowEdges' @@ -24,6 +25,8 @@ const api = { ...createTermApi(ipcRenderer), // ...and so is dictation's (#13). ...createDictationApi(ipcRenderer), + // ...and the diagnostics log's (#140). + ...createDiagApi(ipcRenderer), /** The real path of a File from a drop (the sandbox hides `File.path`). */ getDroppedPath: (file: File): string => webUtils.getPathForFile(file), /** A dropped path as the folder a tab would open in: a folder is itself, a @@ -132,7 +135,9 @@ const api = { /** The e2e's: release checks sent and installs attempted this session. A * preview, fake install included, must leave both at 0. */ e2eUpdateCalls: (): Promise<{ checks: number; installs: number }> => - ipcRenderer.invoke('e2e:update-calls') + ipcRenderer.invoke('e2e:update-calls'), + /** The e2e's diagLog (#140): answers after 600 ms, past the 500 ms ipc-slow line. */ + e2eSlowIpc: (): Promise => ipcRenderer.invoke('e2e:slow-ipc') } export type PrismApi = typeof api diff --git a/src/renderer/src/App.tsx b/src/renderer/src/App.tsx index 3792e3f..3bcf21c 100644 --- a/src/renderer/src/App.tsx +++ b/src/renderer/src/App.tsx @@ -36,6 +36,7 @@ import { copyText } from '@core/renderer/lib/copyNotice' import UpdateChip from '@core/renderer/components/UpdateChip' import UpdateDialog from '@core/renderer/components/UpdateDialog' import { useUpdateFlow } from '@core/renderer/lib/useUpdateFlow' +import { crumb } from '@core/renderer/lib/diag' import { humanFor, workingFor } from '@core/renderer/lib/agentClock' import { forgetSession, markResume, markTouched } from '@core/renderer/lib/termActivity' import { onCwd, onResumingChange, pasteInto, resumingIds } from '@core/renderer/lib/termBus' @@ -192,6 +193,15 @@ export default function App(): JSX.Element { const findOpen = !!activeShell && findFor === activeShell.id const { agentIds, workingIds, doneIds, questionIds, failedIds, failedKinds, agentKinds } = indicator + // THE TIMELINE (#140): which tab is in front, and which Settings page, as + // crumbs, so a stall in the log says what the user had just done. + useEffect(() => { + if (activeId) crumb('tab-switch', { id: activeId }) + }, [activeId]) + useEffect(() => { + if (settingsOpen) crumb('settings-page', { page: settingsPage }) + }, [settingsOpen, settingsPage]) + // The latest of everything, for listeners registered once. const live = useRef({ state, workingIds, agentIds, blocked: false, front: '' }) @@ -223,6 +233,7 @@ export default function App(): JSX.Element { const openTab = useCallback( (cwd: string, resume?: string): string => { const id = nextId() + crumb('tab-open', { id, cwd, resume: !!resume }) spawnSession(id, cwd, resume) setState((s) => addTab(s, id, cwd)) return id @@ -292,6 +303,7 @@ export default function App(): JSX.Element { (id: string) => { const tab = live.current.state.tabs.find((t) => t.id === id) if (!tab) return + crumb('tab-close', { id, kind: tab.kind ?? 'shell' }) if (tab.kind !== 'settings') { window.prism.termKill(id) disposeTermSession(id) diff --git a/src/renderer/src/components/settings/Settings.tsx b/src/renderer/src/components/settings/Settings.tsx index 87e836e..c36e395 100644 --- a/src/renderer/src/components/settings/Settings.tsx +++ b/src/renderer/src/components/settings/Settings.tsx @@ -1,6 +1,7 @@ import { useEffect, useMemo, useState, type JSX } from 'react' import { dictationHost } from '@core/renderer/host' import { SettingsFrame } from '@core/renderer/settings/layout/SettingsFrame' +import { DiagnosticsPage } from '@core/renderer/settings/sections/DiagnosticsPage' import { DictationPage } from '@core/renderer/settings/sections/DictationPage' import { AboutPage } from './AboutPage' import { AgentsPage } from './AgentsPage' @@ -63,6 +64,8 @@ export default function Settings({ ) : page === 'dictation' ? ( + ) : page === 'diagnostics' ? ( + ) : ( )} diff --git a/src/renderer/src/components/settings/appOptions.test.ts b/src/renderer/src/components/settings/appOptions.test.ts index 175cb56..ac29a05 100644 --- a/src/renderer/src/components/settings/appOptions.test.ts +++ b/src/renderer/src/components/settings/appOptions.test.ts @@ -1,6 +1,7 @@ import { readFileSync, readdirSync } from 'node:fs' import { join } from 'node:path' import { describe, expect, it } from 'vitest' +import { DIAGNOSTICS_OPTIONS } from '@core/renderer/settings/diagnosticsOptions' import { DICTATION_OPTIONS } from '@core/renderer/settings/dictationOptions' import { HELP_OPTIONS } from '@core/renderer/settings/helpOptions' import { isSettingIcon } from '@core/renderer/settings/layout/icons' @@ -8,7 +9,7 @@ import { TERMINAL_OPTIONS } from '@core/renderer/settings/options' import { APP_OPTIONS, APP_SECTIONS } from './appOptions' import { ROW_ORDER, SETTINGS_PAGES, settingsIndex } from './settingsIndex' -const CORE = [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS] +const CORE = [...TERMINAL_OPTIONS, ...DICTATION_OPTIONS, ...HELP_OPTIONS, ...DIAGNOSTICS_OPTIONS] describe("this app's own settings rows", () => { it('have unique ids, none of them a core row', () => { @@ -72,5 +73,6 @@ describe('Find a setting', () => { expect(at['agent-hooks']).toBe('agents/Claude Code') expect(at['dictation-enabled']).toBe('dictation/') expect(at['app-version']).toBe('about/') + expect(at['diag-verbose']).toBe('diagnostics/') }) }) diff --git a/src/renderer/src/components/settings/appOptions.ts b/src/renderer/src/components/settings/appOptions.ts index d0611ee..75b1446 100644 --- a/src/renderer/src/components/settings/appOptions.ts +++ b/src/renderer/src/components/settings/appOptions.ts @@ -12,7 +12,7 @@ * keys, `registry` (the Explorer verb, read back from Windows), or null for a * row that stores nothing. One line per entry, as in the core's lists. */ -export type AppPageId = 'appearance' | 'terminal' | 'agents' | 'dictation' | 'about' +export type AppPageId = 'appearance' | 'terminal' | 'agents' | 'dictation' | 'diagnostics' | 'about' export interface AppOption { id: string diff --git a/src/renderer/src/components/settings/settingsIndex.ts b/src/renderer/src/components/settings/settingsIndex.ts index 85180ca..a53e011 100644 --- a/src/renderer/src/components/settings/settingsIndex.ts +++ b/src/renderer/src/components/settings/settingsIndex.ts @@ -12,6 +12,8 @@ export const SETTINGS_PAGES: Array = [ { id: 'terminal', label: 'Terminal', icon: 'terminal' }, { id: 'agents', label: 'Agents', icon: 'agents' }, { id: 'dictation', label: 'Dictation', icon: 'dictation' }, + // The log (#140): the last page above About, with the app's own matters. + { id: 'diagnostics', label: 'Diagnostics', icon: 'diagnostics' }, { id: 'about', label: 'About', icon: 'about', end: true } ] @@ -29,7 +31,8 @@ const PAGE_OF: Record = { listening: 'dictation', while: 'dictation', models: 'dictation', - gpu: 'dictation' + gpu: 'dictation', + diagnostics: 'diagnostics' } /** Every row in the order the pages draw them, which is the order Find a @@ -41,13 +44,14 @@ export const ROW_ORDER = [ 'agent-color', 'agent-done-color', 'agent-question-color', 'dictation-enabled', 'dictation-mode', 'dictation-hotkey', 'dictation-mic', 'dictation-language', 'dictation-pause-media', 'dictation-sounds', 'dictation-model', 'dictation-gpu', + 'diag-verbose', 'diag-folder', 'diag-mark', 'app-version' ] as const /** The index Find a setting reads: the core's rows drawn here, and this * app's own, in page order. */ export function settingsIndex(nvidia: boolean): SettingsIndexEntry[] { - const core = coreSettingsIndex({ pageOf: (s) => PAGE_OF[s], nvidia }) + const core = coreSettingsIndex({ pageOf: (s) => PAGE_OF[s], nvidia, diagnostics: true }) const own: SettingsIndexEntry[] = APP_OPTIONS.map((o) => ({ id: o.id, page: o.page, diff --git a/src/renderer/src/main.tsx b/src/renderer/src/main.tsx index 472a124..bd9b563 100644 --- a/src/renderer/src/main.tsx +++ b/src/renderer/src/main.tsx @@ -2,6 +2,7 @@ // graph is evaluated (see termHost.ts). import './termHost' import { StrictMode } from 'react' +import { startDiag } from '@core/renderer/lib/diag' import { createRoot } from 'react-dom/client' import App from './App' import { migrateOpacity } from './lib/opacityMigration' @@ -12,6 +13,11 @@ import './index.css' // is the window they get. migrateOpacity() +// THE PAGE'S HALF OF THE DIAGNOSTICS LOG (#140): long frames, errors, the +// heartbeat main watches, and the crumbs the app says. Before the first +// render, so a stall or an error while App mounts is caught too. +startDiag(window.prism) + createRoot(document.getElementById('root')!).render( diff --git a/tools/diag.mjs b/tools/diag.mjs new file mode 100644 index 0000000..be119a4 --- /dev/null +++ b/tools/diag.mjs @@ -0,0 +1,188 @@ +#!/usr/bin/env node +// READ THE DIAGNOSTICS LOG (#140): the newest problems (stalls, errors, slow +// calls, marks), each with the crumbs that came just before it, so "it +// stalled just now" is answered from the log rather than from memory. +// Schema and locations: docs/diagnostics.md. +// +// npm run diag newest problems in Prism Terminal's log +// npm run diag -- --app stable the stable copy's (PrismTerminalStable) +// npm run diag -- --app prism Prism's +// npm run diag -- --since 10m only the last ten minutes (s, m, h, d) +// npm run diag -- --all every line, not just the problems +// npm run diag -- --kinds page-stall,main-lag +// npm run diag -- --dir any folder holding a diag.jsonl +// npm run diag -- --n 50 how many problems (default 20) + +import { existsSync, readFileSync } from 'node:fs' +import { join } from 'node:path' + +const APPS = { pt: 'PrismTerminal', stable: 'PrismTerminalStable', prism: 'Prism' } +/** A problem is any of these, or an app's own `-slow` kind. */ +const PROBLEMS = new Set([ + 'main-lag', + 'fs-slow', + 'ipc-slow', + 'ipc-error', + 'page-stall', + 'page-stack', + 'page-error', + 'page-rejection', + 'main-error', + 'main-rejection', + 'gone', + 'unresponsive', + 'logger-error', + 'logger-dropped', + 'mark' +]) +const CRUMBS_BEFORE = 5 +/** A crumb older than this before a problem says nothing about it. */ +const CRUMB_WINDOW_MS = 120_000 + +function args(argv) { + const out = { app: 'pt', since: null, all: false, kinds: null, dir: null, n: 20 } + for (let i = 0; i < argv.length; i += 1) { + const a = argv[i] + const next = () => argv[++i] + if (a === '--app') out.app = next() + else if (a === '--since') out.since = next() + else if (a === '--all') out.all = true + else if (a === '--kinds') out.kinds = new Set(next().split(',')) + else if (a === '--dir') out.dir = next() + else if (a === '--n') out.n = Number(next()) || 20 + else if (a === '--help' || a === '-h') out.help = true + } + return out +} + +/** "10m" as ms; null for nothing or nonsense. */ +function duration(s) { + const m = /^(\d+(?:\.\d+)?)(ms|s|m|h|d)?$/.exec(s ?? '') + if (!m) return null + const unit = { ms: 1, s: 1000, m: 60_000, h: 3_600_000, d: 86_400_000 }[m[2] ?? 'm'] + return Number(m[1]) * unit +} + +function logDir(o) { + if (o.dir) return o.dir + const name = APPS[o.app] + if (!name) throw new Error(`--app is one of ${Object.keys(APPS).join(', ')}`) + const appData = process.env.APPDATA ?? join(process.env.USERPROFILE ?? '', 'AppData', 'Roaming') + return join(appData, name, 'logs') +} + +/** Every line of the live file and its rotations, oldest file first. */ +function readLines(dir) { + const files = ['diag.jsonl.4', 'diag.jsonl.3', 'diag.jsonl.2', 'diag.jsonl.1', 'diag.jsonl'].map((f) => join(dir, f)) + const lines = [] + for (const f of files) { + if (!existsSync(f)) continue + for (const raw of readFileSync(f, 'utf8').split('\n')) { + if (!raw.trim()) continue + try { + const l = JSON.parse(raw) + l._ms = Date.parse(l.t) + if (Number.isFinite(l._ms)) lines.push(l) + } catch { + /* a line cut by a crash */ + } + } + } + // A page's lines are written when their batch arrives, up to a few seconds + // after they happened: order by when they happened. + return lines.sort((a, b) => a._ms - b._ms) +} + +const isProblem = (l) => PROBLEMS.has(l.k) || /-slow$/.test(l.k) + +function clock(ms) { + const d = new Date(ms) + const p = (n, w = 2) => String(n).padStart(w, '0') + return `${d.getFullYear()}-${p(d.getMonth() + 1)}-${p(d.getDate())} ${p(d.getHours())}:${p(d.getMinutes())}:${p(d.getSeconds())}.${p(d.getMilliseconds(), 3)}` +} + +/** One line, said briefly: the fields that matter for its kind first. */ +function summary(l) { + const f = { ...l } + for (const k of ['t', 'up', 'src', 'k', '_ms']) delete f[k] + switch (l.k) { + case 'page-stall': { + const s = (l.scripts ?? []).map((x) => `${x.fn ?? '?'} in ${x.src ?? '?'} (${x.invoker ?? '?'}) ${x.ms}ms`).join('; ') + return `${l.ms}ms, blocking ${l.blocking}ms${s ? `: ${s}` : ''}` + } + case 'main-lag': { + const c = (l.inflight ?? []).map((x) => `${x.ch} ${x.ms}ms${x.done ? ' (ended)' : ''}`).join(', ') + return `${l.ms}ms${c ? `, calls: ${c}` : ', no IPC call around it'}` + } + case 'ipc-slow': + return `${l.ch} ${l.ms}ms${l.sync ? ' (sync)' : ''} args ${JSON.stringify(l.args)}` + case 'ipc-error': + return `${l.ch}: ${l.err}` + case 'page-stack': + return `${l.ms}ms without a heartbeat${l.unresponsive ? ', unresponsive' : ''}\n${indent(l.stack, 6)}` + case 'page-error': + case 'page-rejection': + case 'main-error': + case 'main-rejection': + return `${l.msg}${l.loc ? ` at ${l.loc}` : ''}${l.repeats ? ` (and ${l.repeats} more like it)` : ''}${l.stack ? `\n${indent(l.stack, 6)}` : ''}` + case 'mark': + return l.note ? `"${l.note}"` : '(no note)' + case 'crumb': { + const { a, ...rest } = f + return `${a} ${Object.keys(rest).length ? JSON.stringify(rest) : ''}`.trim() + } + default: + return JSON.stringify(f) + } +} + +function indent(text, n) { + return String(text ?? '') + .split('\n') + .filter((s) => s.trim()) + .map((s) => ' '.repeat(n) + s.trim()) + .join('\n') +} + +function main() { + const o = args(process.argv.slice(2)) + if (o.help) { + console.log(readFileSync(new URL(import.meta.url), 'utf8').split('\n').slice(1, 15).join('\n').replace(/^\/\/ ?/gm, '')) + return + } + const dir = logDir(o) + const all = readLines(dir) + if (all.length === 0) { + console.log(`No diagnostics log in ${dir}`) + return + } + const since = duration(o.since) + const from = since === null ? -Infinity : Date.now() - since + const lines = all.filter((l) => l._ms >= from) + const sessions = lines.filter((l) => l.k === 'session') + const last = [...all].reverse().find((l) => l.k === 'session') + console.log(`${dir}`) + if (last) console.log(`last session ${clock(last._ms)}: ${last.app} ${last.version}, pid ${last.pid}${last.verbose ? ', detailed' : ''}`) + console.log(`${lines.length} lines${since === null ? '' : ` in the last ${o.since}`}, ${sessions.length} session(s)\n`) + + if (o.all) { + for (const l of lines.filter((x) => !o.kinds || o.kinds.has(x.k))) + console.log(`${clock(l._ms)} ${String(l.src ?? '?').padEnd(4)} ${l.k.padEnd(14)} ${summary(l)}`) + return + } + + const problems = lines.filter((l) => (o.kinds ? o.kinds.has(l.k) : isProblem(l))).slice(-o.n) + if (problems.length === 0) { + console.log('No stalls, errors or slow calls.') + return + } + const crumbs = all.filter((l) => l.k === 'crumb') + for (const p of problems) { + console.log(`${clock(p._ms)} ${String(p.src ?? '?').padEnd(4)} ${p.k.padEnd(14)} ${summary(p)}`) + const before = crumbs.filter((c) => c._ms <= p._ms && c._ms >= p._ms - CRUMB_WINDOW_MS).slice(-CRUMBS_BEFORE) + for (const c of before) console.log(` ${((c._ms - p._ms) / 1000).toFixed(1).padStart(6)}s ${c.src} ${summary(c)}`) + console.log('') + } +} + +main() diff --git a/tools/e2e/run.mjs b/tools/e2e/run.mjs index fdfee10..b2260fb 100644 --- a/tools/e2e/run.mjs +++ b/tools/e2e/run.mjs @@ -176,6 +176,7 @@ const PREF_PAGE = { 'dictation-enabled': 'dictation', 'dictation-mode': 'dictation', 'dictation-hotkey': 'dictation', 'dictation-mic': 'dictation', 'dictation-language': 'dictation', 'dictation-pause-media': 'dictation', 'dictation-sounds': 'dictation', 'dictation-model': 'dictation', 'dictation-gpu': 'dictation', + 'diag-verbose': 'diagnostics', 'diag-folder': 'diagnostics', 'diag-mark': 'diagnostics', 'app-version': 'about' } @@ -2480,15 +2481,17 @@ const scenarios = { ...entries('core/renderer/settings/options.ts'), ...entries('core/renderer/settings/dictationOptions.ts', (row) => !row.includes('onlyWhere')), // Command help (#12) keeps a list of its own, as dictation does. - ...entries('core/renderer/settings/helpOptions.ts') + ...entries('core/renderer/settings/helpOptions.ts'), + // The diagnostics log (#140) too: its own list, read the same way. + ...entries('core/renderer/settings/diagnosticsOptions.ts') ] const wanted = core.map((e) => e.id).sort() - ok(wanted.length >= 18 && wanted.includes('help-enabled'), `the core lists the terminal, dictation and help options (${wanted.length})`) + ok(wanted.length >= 21 && wanted.includes('help-enabled') && wanted.includes('diag-verbose'), `the core lists the terminal, dictation, help and diagnostics options (${wanted.length})`) ok(core.every((e) => e.section), 'and every entry names its section') await page.locator('[data-title-settings]').click() const shown = new Set() const sections = [] - for (const tab of ['appearance', 'terminal', 'agents', 'dictation', 'about']) { + for (const tab of ['appearance', 'terminal', 'agents', 'dictation', 'diagnostics', 'about']) { await page.locator(`[data-settings-tab="${tab}"]`).click() // Default shell is drawn once main has listed the shells. if (tab === 'terminal') await page.locator('[data-pref="term-shell"]').waitFor({ timeout: 10000 }) @@ -2571,7 +2574,7 @@ const scenarios = { } }) const pages = {} - for (const tab of ['appearance', 'terminal', 'agents', 'dictation', 'about']) { + for (const tab of ['appearance', 'terminal', 'agents', 'dictation', 'diagnostics', 'about']) { await page.locator(`[data-settings-tab="${tab}"]`).click() if (tab === 'terminal') await page.locator('[data-pref="term-shell"]').waitFor({ timeout: 10000 }) await sleep(300) @@ -2590,6 +2593,151 @@ const scenarios = { await closeApp(app) }, + /** + * THE DIAGNOSTICS LOG (#140; owner, 2026-10-07: "robust logging and + * debugging ... especially to catch stalls"). Each problem is made on + * purpose and then found in \logs\diag.jsonl, the file the owner's + * "it stalled just now" is read from: a 2.5 s busy loop in the page (a + * page-stall naming the script, the crumbs before it, and the stack main + * took while it spun), a call main answers after 600 ms (`e2e:slow-ipc`, + * --e2e only), a thrown error and a rejected promise. Then the Diagnostics + * page: Open folder, Mark, and Detailed logging kept across a relaunch. + * And the quiet level is quiet: an idle 3 s writes nothing. + */ + async diagLog(ok) { + const w = world() + const file = join(w.profile, 'logs', 'diag.jsonl') + const read = () => { + try { + return readFileSync(file, 'utf8') + .split('\n') + .filter(Boolean) + .map((l) => { + try { + return JSON.parse(l) + } catch { + return { bad: l } + } + }) + } catch { + return [] + } + } + // Lines land in batches (the page's every 250 ms, the writer's every + // 250 ms), so every look waits for its line. + const has = (fn, ms = 10000) => until(() => read().find(fn) ?? false, ms, 100) + let { app, page } = await launch(w, { args: [w.alpha] }) + try { + await until(async () => (await tabLabels(page)).length === 1) + const session = await has((l) => l.k === 'session') + ok(!!session && session.src === 'main' && session.e2e === true && session.verbose === false && typeof session.version === 'string' && session.pid > 0, + `a session line opens the log (${JSON.stringify(session && { version: session.version, electron: session.electron, verbose: session.verbose })})`) + ok(!!(await has((l) => l.k === 'crumb' && l.a === 'shell-spawn' && l.src === 'main')), 'the restored tab\'s shell is a crumb, from main') + // A tab opened by the user (the launch's own tab is a restore). + await page.waitForFunction(() => /PS [^>]*>\s*$/.test((document.querySelector('.xterm .xterm-rows')?.textContent ?? '').trimEnd()), null, { timeout: 45000 }) + await page.keyboard.press('Control+t') + ok(!!(await until(async () => (await tabLabels(page)).length === 2)), 'Ctrl+T opens a second tab') + ok(!!(await has((l) => l.k === 'crumb' && l.a === 'tab-open' && l.src === 'page')), 'and the tab that opened is a crumb, from the page') + + // QUIET IS QUIET: once both shells are at their prompts, an idle 3 s + // writes nothing (no heartbeat, no canary, no timer is a line of its own). + await page.waitForFunction(() => { + const rows = [...document.querySelectorAll('.xterm .xterm-rows')] + return rows.length > 0 && rows.every((r) => /PS [^>]*>\s*$/.test((r.textContent ?? '').trimEnd())) + }, null, { timeout: 45000 }) + await sleep(1000) + const idleFrom = read().length + await sleep(3000) + const idle = read().slice(idleFrom) + ok(idle.length === 0, `an idle 3 s at the quiet level writes nothing (${JSON.stringify(idle.map((l) => l.k))})`) + + // A STALL: 2.5 s of the page's thread, started by a named timer. + await page.evaluate(() => { + setTimeout(function diagE2eBusy() { + const end = performance.now() + 2500 + while (performance.now() < end) { + /* spin */ + } + }, 0) + }) + const stall = await has((l) => l.k === 'page-stall' && l.ms >= 2000) + ok(!!stall && stall.src === 'page', `the busy loop is a page-stall (${stall?.ms} ms)`) + const scripts = Array.isArray(stall?.scripts) ? stall.scripts : [] + ok(scripts.some((x) => x && (x.fn === 'diagE2eBusy' || /setTimeout/i.test(x.invoker ?? ''))), + `with the script that ran named (${JSON.stringify(scripts)})`) + const crumbs = Array.isArray(stall?.crumbs) ? stall.crumbs : [] + ok(crumbs.some((c) => c && c.a === 'tab-open'), `and the crumbs said before it (${JSON.stringify(crumbs)})`) + // page-stack is kept (task 11, MEASURED): the stack main took while the + // page spun, written because a page-stall overlapping it arrived. + const stack = await has((l) => l.k === 'page-stack', 6000) + ok(!!stack && /diagE2eBusy/.test(stack.stack ?? '') && stack.ms >= 2000, `main took the spinning page's stack (${stack ? `${stack.ms} ms, ${String(stack.stack).split('\n')[1]?.trim()}` : 'none'})`) + + // A SLOW CALL: main answers after 600 ms. + ok((await page.evaluate(() => window.prism.e2eSlowIpc())) === true, 'the slow call answers') + const slow = await has((l) => l.k === 'ipc-slow' && l.ch === 'e2e:slow-ipc') + ok(!!slow && slow.ms >= 500 && slow.ok === true, `and is an ipc-slow line naming its channel (${slow?.ms} ms)`) + + // ERRORS: thrown in a timer, so it reaches the page's own handler (one + // thrown inside evaluate is Playwright's), and a rejection nobody holds. + await page.evaluate(() => { + setTimeout(() => { + throw new Error('diag-e2e-thrown') + }, 0) + void Promise.reject(new Error('diag-e2e-rejected')) + }) + const thrown = await has((l) => l.k === 'page-error' && /diag-e2e-thrown/.test(l.msg ?? '')) + ok(!!thrown && /diag-e2e-thrown/.test(thrown.stack ?? ''), 'a thrown error is a page-error, with its stack') + ok(!!(await has((l) => l.k === 'page-rejection' && /diag-e2e-rejected/.test(l.msg ?? ''))), 'a rejected promise is a page-rejection') + + // THE PAGE: the folder, Mark, Detailed logging. + const folderRow = await gotoPref(page, 'diag-folder') + ok(!!(await has((l) => l.k === 'crumb' && l.a === 'settings-page' && l.page === 'diagnostics')), 'opening the page is a crumb') + const shownDir = await until(async () => ((await folderRow.textContent()) ?? '').includes(join(w.profile, 'logs')), 5000, 100) + ok(!!shownDir, 'Log files shows the folder the log is in') + await folderRow.locator('button').click() + const opened = await until(() => app.evaluate(() => globalThis.__e2eOpenedPaths ?? []).then((x) => x.find((o) => o.abs === join(w.profile, 'logs')) ?? false), 4000, 100) + ok(!!opened, 'Open folder opens that folder (recorded under --e2e)') + // Its word sits in the middle of the button, as Open folder's does (the + // first shot of the page had it at the top: a grid button's row starts there). + const off = await page.evaluate(() => { + const b = document.querySelector('[data-diag-mark]') + // The TEXT's own box, through a Range: a stretched span is as tall as + // the button whatever line its word sits on. + const t = b?.querySelector('span')?.firstChild + if (!b || !t) return null + const r = document.createRange() + r.selectNodeContents(t) + const [bb, tb] = [b.getBoundingClientRect(), r.getBoundingClientRect()] + return Math.abs(bb.top + bb.height / 2 - (tb.top + tb.height / 2)) + }) + ok(off !== null && off <= 1, `Mark's word is centred in its button (${off?.toFixed(1)}px off)`) + const markAt = Date.now() + await page.locator('[data-diag-mark]').click() + ok(!!(await until(async () => (await page.locator('[data-diag-mark] span').last().isVisible()), 2000, 50)), 'Mark says Marked') + const mark = await has((l) => l.k === 'mark') + ok(!!mark && mark.src === 'page' && Math.abs(Date.parse(mark.t) - markAt) < 3000, `and stamps the moment in the log (${mark?.t})`) + const sw = page.locator('[data-pref="diag-verbose"] [role="switch"]') + ok((await sw.getAttribute('aria-checked')) === 'false', 'Detailed logging is off by default') + await sw.click() + ok(!!(await has((l) => l.k === 'verbose' && l.on === true)), 'switching it on is a line') + // The log's own diag: channels are never timed, so an app call. + await page.evaluate(() => window.prism.homeDir()) + ok(!!(await has((l) => l.k === 'ipc' && l.ch && !l.ch.startsWith('diag:'))), 'and every call is logged from then on') + await closeApp(app) + ok(read().at(-1)?.k === 'quit', `a quit is the session's last line (${read().at(-1)?.k})`) + + // KEPT ACROSS A RELAUNCH: main reads it from \diag.json. + ;({ app, page } = await launch(w, { args: [w.alpha] })) + const second = await has((l, i, all) => l.k === 'session' && all.slice(0, i).some((x) => x.k === 'session')) + ok(!!second && second.verbose === true, `the next session starts detailed (${second?.verbose})`) + await gotoPref(page, 'diag-verbose') + ok(!!(await until(async () => (await page.locator('[data-pref="diag-verbose"] [role="switch"]').getAttribute('aria-checked')) === 'true', 5000, 100)), 'and the switch says so') + ok(read().every((l) => !l.bad), 'every line in the file is one JSON object') + } finally { + await closeApp(app) + } + }, + /** * THE GROUPED CARDS LOOK RIGHT (2026-10-05; spec 1.2, 1.3 and #20: a page * that works is not a page that looks right). On a dark theme (Pitch), a @@ -2656,7 +2804,7 @@ const scenarios = { sideways: document.querySelector('[data-settings-page]').scrollWidth > document.querySelector('[data-settings-page]').clientWidth + 1 } }) - const pages = ['appearance', 'terminal', 'agents', 'dictation', 'about'] + const pages = ['appearance', 'terminal', 'agents', 'dictation', 'diagnostics', 'about'] try { await page.locator('[data-title-settings]').click() for (const [scheme, theme] of [['dark', 'pitch'], ['light', 'paper']]) { @@ -5061,6 +5209,61 @@ const scenarios = { } const table = [] +/** + * THE STALLS REPORT (#140): every scenario's app keeps the diagnostics log in + * its own profile, so before the profile goes its stall and error lines are + * kept for one table at the end of the run. A report only: the exit code is + * the scenarios' alone. The diagLog scenario makes some on purpose (the busy + * loop and its stack, the slow call, the two errors), and those rows say so; + * anything else it logged is as real as any other scenario's. + */ +const stalls = [] +const STALL_KINDS = new Set(['page-stall', 'page-stack', 'main-lag', 'fs-slow', 'ipc-slow', 'unresponsive']) +const ERROR_KINDS = new Set(['page-error', 'page-rejection', 'main-error', 'main-rejection', 'ipc-error', 'gone', 'logger-error']) +function stallDetail(l) { + const cut = (v) => String(v ?? '').replace(/\s+/g, ' ').slice(0, 70) + if (l.k === 'page-stall') { + const top = Array.isArray(l.scripts) ? l.scripts[0] : null + return cut(top ? [top.fn, top.src, top.invoker].filter(Boolean).join(' ') : `blocking ${l.blocking ?? '?'}`) + } + if (l.k === 'page-stack') return cut(String(l.stack ?? '').split('\n').find((x) => /^\s*at /.test(x))?.trim()) + if (l.k === 'main-lag') return cut((Array.isArray(l.inflight) ? l.inflight : []).map((c) => `${c.ch} ${c.ms}${c.done ? ' done' : ''}`).join(', ') || 'nothing in flight') + if (l.k === 'ipc-slow' || l.k === 'ipc-error') return cut(`${l.ch}${l.err ? ` ${l.err}` : ''}`) + if (l.k === 'gone') return cut(`${l.type} ${l.reason} ${l.exitCode}`) + return cut(l.msg ?? l.err ?? '') +} +function collectStalls(scenario) { + for (const base of worlds) { + const dir = join(base, 'profile', 'logs') + let files + try { + files = readdirSync(dir).filter((f) => f.startsWith('diag.jsonl')) + } catch { + continue + } + for (const f of files) { + let text + try { + text = readFileSync(join(dir, f), 'utf8') + } catch { + continue + } + for (const raw of text.split('\n')) { + if (!raw) continue + let l + try { + l = JSON.parse(raw) + } catch { + continue + } + const err = ERROR_KINDS.has(l.k) + if (!err && !(STALL_KINDS.has(l.k) && typeof l.ms === 'number' && l.ms >= 1000)) continue + const made = scenario === 'diagLog' && (['page-stall', 'page-stack', 'page-error', 'page-rejection'].includes(l.k) || l.ch === 'e2e:slow-ipc') + stalls.push({ scenario, kind: l.k, ms: typeof l.ms === 'number' ? l.ms : null, detail: stallDetail(l), expected: made }) + } + } + } +} /** Scenarios that honestly take longer than the default limit. */ const SLOW = { dictation: 360000, dictationParakeet: 360000, helpPanel: 300000, updateWindow: 300000 } reapStrays() @@ -5098,6 +5301,7 @@ for (const [name, run] of Object.entries(scenarios)) { over = true } const strays = reapStrays() + collectStalls(name) removeWorlds() table.push({ name, checks, fails, secs: ((Date.now() - t0) / 1000).toFixed(1), strays }) } @@ -5106,6 +5310,13 @@ console.log('\nscenario checks fails secs') for (const r of table) { console.log(`${r.name.padEnd(18)}${String(r.checks).padStart(6)}${String(r.fails).padStart(7)}${r.secs.padStart(6)}`) } +console.log('\nStalls (stalls of 1 s or more and errors, from each scenario\'s diagnostics log; a report, not a gate)') +if (!stalls.length) console.log(' none') +else { + console.log(` ${'scenario'.padEnd(18)}${'kind'.padEnd(16)}${'ms'.padStart(7)} detail`) + for (const r of stalls) + console.log(` ${r.scenario.padEnd(18)}${r.kind.padEnd(16)}${(r.ms === null ? '-' : String(r.ms)).padStart(7)} ${r.expected ? '(expected) ' : ''}${r.detail}`) +} const failed = table.filter((r) => r.fails > 0) console.log(failed.length ? `\n${failed.length} scenario(s) FAILED` : '\nall scenarios passed') process.exit(failed.length ? 1 : 0)