From 62752c26e05c4427a2f8373a062b237d0e13d012 Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:18:23 +0200 Subject: [PATCH 1/8] docs(diag): the diagnostics log design and plan (#140) Approved by the owner 2026-10-07 ("go ahead"). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- .../2026-10-07-diagnostics-log-design.md | 232 ++++++++++++++++++ 1 file changed, 232 insertions(+) create mode 100644 docs/superpowers/specs/2026-10-07-diagnostics-log-design.md 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..44ac7c1 --- /dev/null +++ b/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md @@ -0,0 +1,232 @@ +# 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). + +**After merge:** install both. The owner uses them, and the first "it stalled" is read with +`npm run diag`. From 83b217f4b4cdf3746c36f212842799c956d003f6 Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:25:44 +0200 Subject: [PATCH 2/8] feat(core): the diagnostics log's main half and bridge (#140) The writer (diag.jsonl, batched, rotated at 2 MB to .1-.4, flushed synchronously at quit, verbose kept in diag.json), IPC timing at the one ipcMain every channel passes, the stall watch (event loop lag, the fs canary, the page heartbeat and its stack), the crash hooks (observe only), the diag: channels with their preload half, and startDiagnostics to wire it in one call. A host without diagLogDir logs nothing. Core 0.27.0, app 0.34.0. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- core/main/crashHooks.test.ts | 95 +++++++++++++ core/main/crashHooks.ts | 87 ++++++++++++ core/main/diagIpc.test.ts | 144 +++++++++++++++++++ core/main/diagIpc.ts | 100 +++++++++++++ core/main/diagLog.test.ts | 136 ++++++++++++++++++ core/main/diagLog.ts | 259 ++++++++++++++++++++++++++++++++++ core/main/diagSummary.test.ts | 82 +++++++++++ core/main/diagSummary.ts | 100 +++++++++++++ core/main/diagnostics.test.ts | 58 ++++++++ core/main/diagnostics.ts | 105 ++++++++++++++ core/main/ipcTiming.test.ts | 211 +++++++++++++++++++++++++++ core/main/ipcTiming.ts | 204 ++++++++++++++++++++++++++ core/main/stallWatch.test.ts | 174 +++++++++++++++++++++++ core/main/stallWatch.ts | 165 ++++++++++++++++++++++ core/package.json | 2 +- core/preload/diagApi.ts | 42 ++++++ core/shared/channels.ts | 15 ++ package-lock.json | 4 +- package.json | 2 +- 19 files changed, 1981 insertions(+), 4 deletions(-) create mode 100644 core/main/crashHooks.test.ts create mode 100644 core/main/crashHooks.ts create mode 100644 core/main/diagIpc.test.ts create mode 100644 core/main/diagIpc.ts create mode 100644 core/main/diagLog.test.ts create mode 100644 core/main/diagLog.ts create mode 100644 core/main/diagSummary.test.ts create mode 100644 core/main/diagSummary.ts create mode 100644 core/main/diagnostics.test.ts create mode 100644 core/main/diagnostics.ts create mode 100644 core/main/ipcTiming.test.ts create mode 100644 core/main/ipcTiming.ts create mode 100644 core/main/stallWatch.test.ts create mode 100644 core/main/stallWatch.ts create mode 100644 core/preload/diagApi.ts diff --git a/core/main/crashHooks.test.ts b/core/main/crashHooks.test.ts new file mode 100644 index 0000000..50e75c0 --- /dev/null +++ b/core/main/crashHooks.test.ts @@ -0,0 +1,95 @@ +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('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..05d5aa2 --- /dev/null +++ b/core/main/crashHooks.ts @@ -0,0 +1,87 @@ +import { performance } from 'perf_hooks' +import type { DiagLog } from './diagLog' +import { errorFields } from './diagSummary' + +/** + * 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. + * + * Every line here is 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. + */ + +/* 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 +} + +/** Hooks the process and the app; returns the function that unhooks them. */ +export function hookCrashes({ log, process: proc, app }: 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 */ + } + } + const onError = (err: unknown, origin: unknown): void => + land('main-error', { ...errorFields(err), origin: typeof origin === 'string' ? origin : null }) + const onRejection = (reason: unknown): void => land('main-rejection', errorFields(reason)) + 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 () => { + 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..e100b5d --- /dev/null +++ b/core/main/diagLog.test.ts @@ -0,0 +1,136 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { existsSync, mkdirSync, mkdtempSync, readFileSync, 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('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('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..cd409cd --- /dev/null +++ b/core/main/diagLog.ts @@ -0,0 +1,259 @@ +import { appendFileSync, mkdirSync, readFileSync, renameSync, rmSync, statSync, writeFileSync } from 'fs' +import { appendFile, mkdir } 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. + */ + +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 + +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 + + 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() + } + return JSON.stringify({ t, up, src, k, ...cleanFields(fields ?? {}) }) + '\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 */ + } + } + + /** Rotation, synchronous: it happens once per 2 MB, and renames are fast. */ + const rotateIfFull = (incoming: number): void => { + if (size === 0 || size + incoming <= maxBytes) return + 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 + } + + const take = (): string | null => { + 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 + try { + await mkdir(dir, { recursive: true }) + const bytes = Buffer.byteLength(text) + rotateIfFull(bytes) + await appendFile(file, text) + size += bytes + } catch (err) { + fail(err) + } + }) + return chain + } + + const flushSync = (): void => { + if (timer) { + clearTimeout(timer) + timer = null + } + const text = take() + if (text === null) return + try { + mkdirSync(dir, { recursive: true }) + const bytes = Buffer.byteLength(text) + rotateIfFull(bytes) + appendFileSync(file, text) + size += bytes + } catch (err) { + 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) + queue.push(line(src, k, at, Math.max(0, uptime() - age), fields)) + if (queue.length > 2000) queue.splice(0, queue.length - 2000) + 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..047bb55 --- /dev/null +++ b/core/main/diagnostics.ts @@ -0,0 +1,105 @@ +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 slice of a BrowserWindow the watch needs. */ +export interface DiagWindow extends EmitterLike { + isDestroyed?(): boolean + webContents: { mainFrame?: { collectJavaScriptCallStack?(): 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) + 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 + return frame?.collectJavaScriptCallStack ? await frame.collectJavaScriptCallStack() : null + } + }) + const unhook = hookCrashes({ log, process: deps.process, app: deps.app }) + registerDiagIpc({ ipcMain: deps.ipcMain, log, watch, openFolder: deps.openFolder }) + + return { + log, + watchWindow: (w) => { + win = w + watchWindowHealth(w, log, watch) + }, + stop: () => { + watch.stop() + 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..7719711 --- /dev/null +++ b/core/main/ipcTiming.test.ts @@ -0,0 +1,211 @@ +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('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..19da6f5 --- /dev/null +++ b/core/main/ipcTiming.ts @@ -0,0 +1,204 @@ +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 +} + +export interface IpcTiming { + /** Calls running now, longest first, at most eight. */ + inflight(): 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 +} + +/** 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:') + +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)) + + let nextId = 0 + const running = new Map() + 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 ms = Math.round(now() - start) + if (!ok) log.write('main', 'ipc-error', { ch, ms, ...renameMsg(errorFields(err)) }) + if (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++ + 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: () => { + const t = now() + return [...running.values()] + .map((r) => ({ ch: r.ch, ms: Math.round(t - r.start) })) + .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..ecb04ee --- /dev/null +++ b/core/main/stallWatch.test.ts @@ -0,0 +1,174 @@ +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 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('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..d51aa2f --- /dev/null +++ b/core/main/stallWatch.ts @@ -0,0 +1,165 @@ +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(): 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 + 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 + + 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 + if (late >= lagMs) log.write('main', 'main-lag', { ms: late, inflight: deps.inflight() }) + 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 done = (): void => { + canaryBusy = false + 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 })) + }), + stop: () => { + clearInterval(tick) + clearInterval(canary) + } + } +} diff --git a/core/package.json b/core/package.json index c94510a..ad9bde4 100644 --- a/core/package.json +++ b/core/package.json @@ -1,6 +1,6 @@ { "name": "prism-term-core", - "version": "0.25.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/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/package-lock.json b/package-lock.json index cb3f087..265e25e 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "prism-terminal", - "version": "0.32.0", + "version": "0.34.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "prism-terminal", - "version": "0.32.0", + "version": "0.34.0", "license": "MIT", "dependencies": { "@xterm/addon-fit": "^0.11.0", diff --git a/package.json b/package.json index 31c65bd..8df46f7 100644 --- a/package.json +++ b/package.json @@ -1,7 +1,7 @@ { "name": "prism-terminal", "productName": "Prism Terminal", - "version": "0.32.0", + "version": "0.34.0", "description": "A tabbed Windows terminal for AI CLIs.", "main": "./out/main/index.js", "author": "Max", From 3622bb150de1912c21114d68e603ed1f8ca87cde Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:32:38 +0200 Subject: [PATCH 3/8] feat(core): the page's half of the diagnostics log and its Settings page (#140) diag.ts: long-animation-frame stalls of 200 ms with their scripts and the last five crumbs, long tasks (detailed only), page errors and rejections, the heartbeat, a 50 crumb ring and a 250 ms batch; crumb() and time() for either app. The Diagnostics page (Detailed logging, Log files, Mark a problem) takes its bridge as props; its rows are a list of their own. Crumbs at the shared sites: shell spawn and exit in main, the update window and install, dictation's phases. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- core/main/diagnostics.ts | 5 +- core/main/terminal.ts | 22 +- core/renderer/lib/diag.test.ts | 182 +++++++++++++ core/renderer/lib/diag.ts | 242 ++++++++++++++++++ core/renderer/lib/dictation.ts | 4 + core/renderer/lib/useUpdateFlow.ts | 7 +- core/renderer/settings/coreIndex.ts | 9 +- core/renderer/settings/diagnosticsOptions.ts | 28 ++ core/renderer/settings/layout/icons.ts | 5 + core/renderer/settings/options.test.ts | 17 +- core/renderer/settings/sectionIds.ts | 6 +- .../settings/sections/DiagnosticsPage.tsx | 88 +++++++ core/renderer/settings/sections/opts.ts | 5 +- core/shared/settingsCopy.test.ts | 2 +- 14 files changed, 606 insertions(+), 16 deletions(-) create mode 100644 core/renderer/lib/diag.test.ts create mode 100644 core/renderer/lib/diag.ts create mode 100644 core/renderer/settings/diagnosticsOptions.ts create mode 100644 core/renderer/settings/sections/DiagnosticsPage.tsx diff --git a/core/main/diagnostics.ts b/core/main/diagnostics.ts index 047bb55..a244158 100644 --- a/core/main/diagnostics.ts +++ b/core/main/diagnostics.ts @@ -37,7 +37,7 @@ export interface DiagnosticsDeps { /** The slice of a BrowserWindow the watch needs. */ export interface DiagWindow extends EmitterLike { isDestroyed?(): boolean - webContents: { mainFrame?: { collectJavaScriptCallStack?(): Promise } | null } + webContents: { mainFrame?: { collectJavaScriptCallStack?(): Promise | Promise } | null } } export interface Diagnostics { @@ -82,7 +82,8 @@ export function startDiagnostics(deps: DiagnosticsDeps): Diagnostics { collectStack: async () => { if (!win || win.isDestroyed?.()) return null const frame = win.webContents.mainFrame - return frame?.collectJavaScriptCallStack ? await frame.collectJavaScriptCallStack() : null + const stack = frame?.collectJavaScriptCallStack ? await frame.collectJavaScriptCallStack() : null + return typeof stack === 'string' ? stack : null } }) const unhook = hookCrashes({ log, process: deps.process, app: deps.app }) 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/renderer/lib/diag.test.ts b/core/renderer/lib/diag.test.ts new file mode 100644 index 0000000..04eb1f4 --- /dev/null +++ b/core/renderer/lib/diag.test.ts @@ -0,0 +1,182 @@ +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', + src: '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('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..f667428 --- /dev/null +++ b/core/renderer/lib/diag.ts @@ -0,0 +1,242 @@ +import type { DiagApi, DiagPageLine } from '../../preload/diagApi' + +/** + * 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 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 src = ev.filename ? `${shortSrc(ev.filename)}:${ev.lineno ?? 0}:${ev.colno ?? 0}` : null + return { k, at: Date.now(), msg, stack, src } +} + +function enqueue(line: DiagPageLine): void { + if (!api) return + queue.push(line) + if (queue.length > QUEUE_MAX) queue.splice(0, queue.length - QUEUE_MAX) +} + +function send(): void { + if (!api || 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 => enqueue(errorLine('page-error', ev)) + const onRejection = (ev: never): void => enqueue(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 = [] +} 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..f6d4917 --- /dev/null +++ b/core/renderer/settings/sections/DiagnosticsPage.tsx @@ -0,0 +1,88 @@ +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. */} + + + + ) +} 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/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[] = [] From b8a3676ac6cc286927a52f813e9c0af16255556c Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:35:44 +0200 Subject: [PATCH 4/8] fix(core): what the first run of the built app showed the log getting wrong (#140) MEASURED in the built app with --e2e: a page error's script location, named src, overwrote the line's own src (it read null), so the writer now keeps t, up, src and k whatever the fields say, and the location is loc. And a 1630 ms main-lag listed nothing in flight beside an 1837 ms term:spawn that had settled a millisecond before the tick could run, so main-lag now names the calls that ended inside the lag as well (done). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- core/main/diagLog.test.ts | 8 ++++++++ core/main/diagLog.ts | 8 +++++++- core/main/ipcTiming.test.ts | 13 +++++++++++++ core/main/ipcTiming.ts | 35 ++++++++++++++++++++++++++-------- core/main/stallWatch.ts | 6 ++++-- core/renderer/lib/diag.test.ts | 2 +- core/renderer/lib/diag.ts | 4 ++-- 7 files changed, 62 insertions(+), 14 deletions(-) diff --git a/core/main/diagLog.test.ts b/core/main/diagLog.test.ts index e100b5d..ea851aa 100644 --- a/core/main/diagLog.test.ts +++ b/core/main/diagLog.test.ts @@ -113,6 +113,14 @@ describe('createDiagLog', () => { 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 }) diff --git a/core/main/diagLog.ts b/core/main/diagLog.ts index cd409cd..ff48cbc 100644 --- a/core/main/diagLog.ts +++ b/core/main/diagLog.ts @@ -62,6 +62,8 @@ 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 export function createDiagLog(opts: DiagLogOptions): DiagLog { const dir = opts.dir @@ -88,7 +90,11 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { } catch { t = new Date(now()).toISOString() } - return JSON.stringify({ t, up, src, k, ...cleanFields(fields ?? {}) }) + '\n' + // 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 => { diff --git a/core/main/ipcTiming.test.ts b/core/main/ipcTiming.test.ts index 7719711..71fe74a 100644 --- a/core/main/ipcTiming.test.ts +++ b/core/main/ipcTiming.test.ts @@ -199,6 +199,19 @@ describe('timeIpcMain', () => { 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('logs only the sizes of an opaque channel', async () => { const ipc = new FakeIpcMain() const log = fakeLog() diff --git a/core/main/ipcTiming.ts b/core/main/ipcTiming.ts index 19da6f5..f78fb54 100644 --- a/core/main/ipcTiming.ts +++ b/core/main/ipcTiming.ts @@ -38,11 +38,20 @@ export interface IpcMainPatchable { 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, longest first, at most eight. */ - inflight(): InflightCall[] + /** + * 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 { @@ -59,6 +68,7 @@ export interface IpcTimingOptions { * 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()) @@ -68,6 +78,8 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi 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 => { @@ -84,7 +96,10 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi const ended = (ch: string, start: number, args: unknown[], ok: boolean, sync: boolean, err?: unknown): void => { try { - const ms = Math.round(now() - start) + const end = now() + const ms = Math.round(end - start) + 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 (ms >= (sync ? syncSlowMs : slowMs)) log.write('main', 'ipc-slow', { ch, ms, args: summariseArgs(args, opaque(ch)), ok, ...(sync ? { sync: true } : {}) }) @@ -188,12 +203,16 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi } return { - inflight: () => { + inflight: (windowMs = 0) => { const t = now() - return [...running.values()] - .map((r) => ({ ch: r.ch, ms: Math.round(t - r.start) })) - .sort((a, b) => b.ms - a.ms) - .slice(0, 8) + 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) } } } diff --git a/core/main/stallWatch.ts b/core/main/stallWatch.ts index d51aa2f..01a8423 100644 --- a/core/main/stallWatch.ts +++ b/core/main/stallWatch.ts @@ -29,7 +29,7 @@ import type { InflightCall } from './ipcTiming' export interface StallWatchDeps { log: DiagLog - inflight(): InflightCall[] + 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. */ @@ -105,7 +105,9 @@ export function startStallWatch(deps: StallWatchDeps): StallWatch { const n = now() const late = Math.round(n - last - tickMs) last = n - if (late >= lagMs) log.write('main', 'main-lag', { ms: late, inflight: deps.inflight() }) + // 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) }) if (lastBeat !== null && !askedThisGap && n - lastBeat >= beatGapMs) { askedThisGap = true void askStack(n - lastBeat) diff --git a/core/renderer/lib/diag.test.ts b/core/renderer/lib/diag.test.ts index 04eb1f4..63281a0 100644 --- a/core/renderer/lib/diag.test.ts +++ b/core/renderer/lib/diag.test.ts @@ -99,7 +99,7 @@ describe('errorLine', () => { 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', - src: 'assets/index.js:3:9' + loc: 'assets/index.js:3:9' }) expect(errorLine('page-rejection', { reason: 'plain' })).toMatchObject({ k: 'page-rejection', msg: 'plain' }) }) diff --git a/core/renderer/lib/diag.ts b/core/renderer/lib/diag.ts index f667428..1f75cd6 100644 --- a/core/renderer/lib/diag.ts +++ b/core/renderer/lib/diag.ts @@ -102,8 +102,8 @@ export function errorLine( 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 src = ev.filename ? `${shortSrc(ev.filename)}:${ev.lineno ?? 0}:${ev.colno ?? 0}` : null - return { k, at: Date.now(), msg, stack, src } + const loc = ev.filename ? `${shortSrc(ev.filename)}:${ev.lineno ?? 0}:${ev.colno ?? 0}` : null + return { k, at: Date.now(), msg, stack, loc } } function enqueue(line: DiagPageLine): void { From 4278d85efee51750a5f207569ced9bb7bb290135 Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:35:45 +0200 Subject: [PATCH 5/8] feat(diag): Prism Terminal keeps a diagnostics log, with a Diagnostics page (#140) Main starts the core's diagnostics in the instance holding the lock, before any IPC is registered, at %APPDATA%\PrismTerminal\logs (the stable copy's profile gets its own); it hands over the window and stops at the quit. Documents are served with the Document-Policy that lets main read the page's stack: MEASURED, a 3 s busy loop's stack came back in the built app and in the dev server's page. The preload carries the diag bridge, the page starts its half before the first render, App says tab open, close and switch and the Settings page as crumbs, and Settings has a Diagnostics page above About. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- src/main/index.ts | 42 ++++++++++++++++++- src/preload/index.ts | 3 ++ src/renderer/src/App.tsx | 12 ++++++ .../src/components/settings/Settings.tsx | 3 ++ .../components/settings/appOptions.test.ts | 4 +- .../src/components/settings/appOptions.ts | 2 +- .../src/components/settings/settingsIndex.ts | 8 +++- src/renderer/src/main.tsx | 6 +++ 8 files changed, 75 insertions(+), 5 deletions(-) diff --git a/src/main/index.ts b/src/main/index.ts index 81cdf60..e36f09f 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -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. @@ -718,6 +725,22 @@ 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) + }) 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 +786,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 +820,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..aaffd71 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 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( From fa9b7a66521df1108ec56b2b88f5d32b4ff45f5e Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 15:38:31 +0200 Subject: [PATCH 6/8] docs(diag): how to read the diagnostics log, npm run diag, privacy (#140) docs/diagnostics.md holds the schema, every kind and crumb, the folders (PrismTerminal, PrismTerminalStable, Prism) and how to read a stall. tools/diag.mjs (npm run diag) prints the newest stalls, errors, slow calls and marks with the crumbs before each (--app pt|stable|prism, --since 10m, --all, --kinds, --dir). CLAUDE.md points at it, PRIVACY.md says the log is local and never sent, the core README states the diagLogDir contract, and the spec records what was measured: the page stack works once the document opts in, so page-stack is kept. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- CLAUDE.md | 7 + PRIVACY.md | 14 +- core/README.md | 15 ++ docs/diagnostics.md | 123 ++++++++++++ .../2026-10-07-diagnostics-log-design.md | 37 ++++ package.json | 1 + tools/diag.mjs | 187 ++++++++++++++++++ 7 files changed, 382 insertions(+), 2 deletions(-) create mode 100644 docs/diagnostics.md create mode 100644 tools/diag.mjs diff --git a/CLAUDE.md b/CLAUDE.md index ea99d39..2caaee9 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -846,6 +846,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..a67b560 100644 --- a/core/README.md +++ b/core/README.md @@ -183,6 +183,21 @@ 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). 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/docs/diagnostics.md b/docs/diagnostics.md new file mode 100644 index 0000000..e588e11 --- /dev/null +++ b/docs/diagnostics.md @@ -0,0 +1,123 @@ +# 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 | | +| `main-lag` | main | main's 50 ms tick came 100 ms or more late | `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 | `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) | +| `main-error` / `main-rejection` | main | `uncaughtExceptionMonitor`, `unhandledRejection` (observed only) | `msg`, `stack`, `origin` | +| `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 (once a session) | `msg` | +| `-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`). + +## 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 })`, 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. +- `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 index 44ac7c1..b854b3b 100644 --- a/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md +++ b/docs/superpowers/specs/2026-10-07-diagnostics-log-design.md @@ -228,5 +228,42 @@ merges. It also folds in the auto bump. - 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.json b/package.json index 8df46f7..9f09cc1 100644 --- a/package.json +++ b/package.json @@ -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/tools/diag.mjs b/tools/diag.mjs new file mode 100644 index 0000000..c0b37fc --- /dev/null +++ b/tools/diag.mjs @@ -0,0 +1,187 @@ +#!/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', + '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.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() From de49ceb7b2e51de6cf954469348edcb0b93e3c63 Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 16:03:00 +0200 Subject: [PATCH 7/8] test(e2e): the diagLog scenario, Diagnostics in options, and a Stalls report (#140) - diagLog makes each problem on purpose and finds it in \logs\diag.jsonl: a 2.5 s busy loop (page-stall naming its timer, the crumbs before it, and page-stack with the busy function), a call main answers after 600 ms (e2e:slow-ipc, --e2e only: ipc-slow with its channel), a thrown error and a rejected promise. Then the page: Open folder (recorded), Mark, Detailed logging kept across a relaunch, the quit line, and an idle 3 s at the quiet level that writes nothing. - options reads diagnosticsOptions.ts into its wanted list and walks the Diagnostics page; settingsLook measures and shoots it in both schemes. - The runner keeps every scenario's stall lines of 1 s or more and every error line before its profile goes, and prints them in a closing Stalls table. A report only: the exit code is unchanged. diagLog's own deliberate lines are marked (expected). - The shots showed Mark's word 6 px above its button's middle (a grid button stretches its one row from the top); centred, and diagLog measures it. Full e2e twice: 50 scenarios, 0 fails. The Stalls table names the first term:spawn of every launch (1.4 to 3.1 s of main), already noted for its own issue. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- .../settings/sections/DiagnosticsPage.tsx | 6 +- src/main/index.ts | 3 + src/preload/index.ts | 4 +- tools/e2e/run.mjs | 221 +++++++++++++++++- 4 files changed, 226 insertions(+), 8 deletions(-) diff --git a/core/renderer/settings/sections/DiagnosticsPage.tsx b/core/renderer/settings/sections/DiagnosticsPage.tsx index f6d4917..216eb1b 100644 --- a/core/renderer/settings/sections/DiagnosticsPage.tsx +++ b/core/renderer/settings/sections/DiagnosticsPage.tsx @@ -77,8 +77,10 @@ export function DiagnosticsPage({ api }: { api: DiagSettingsBridge }): JSX.Eleme {/* Both words in one cell, only one visible: the button never - changes width as it answers. */} - diff --git a/src/main/index.ts b/src/main/index.ts index e36f09f..a4dbcda 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -683,6 +683,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. diff --git a/src/preload/index.ts b/src/preload/index.ts index aaffd71..7a5245e 100644 --- a/src/preload/index.ts +++ b/src/preload/index.ts @@ -135,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/tools/e2e/run.mjs b/tools/e2e/run.mjs index df996e8..0ba656c 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']]) { @@ -5030,6 +5178,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() @@ -5067,6 +5270,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 }) } @@ -5075,6 +5279,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) From ed96010240548515d47b91980489284cab2fc52b Mon Sep 17 00:00:00 2001 From: Max <112043822+Maxaubert@users.noreply.github.com> Date: Wed, 7 Oct 2026 16:26:38 +0200 Subject: [PATCH 8/8] fix(core): what the two reviews of the diagnostics log found (#140) - A failed rotation (the full file held open without share-delete) no longer silences the log: the batch is appended to the live file, the logger-error line lands, and the rotation is tried again 30 s later. - flushSync writes a batch the async path has taken and not yet written, ahead of the quit lines. The async write is now open-then-write, so a flushSync during the open skips it (MEASURED in the unit test: with appendFile the batch came after the quit line, then again). - The log folder is made once (and again after a failed write), not with an mkdir on the fs threadpool every flush. - The writer and the page drop the NEWEST lines when full, and count them (logger-dropped, a diag-dropped crumb). - Errors are gated (core/shared/diagGate): the same error once per 10 s with a repeats count, at most 10 lines per kind per 10 s. A rejection goes in the batch, not a sync write on main's thread. - A main-process block no longer reads as a page freeze: main's lateness is taken off the beat gap. - A sleep is not a lag: powerMonitor suspend/resume pause the watch. - Calls that wait on the user or a download (folder picker, update install, dictation download) are never ipc-slow and stay out of inflight. - PT writes the log out at a Windows shutdown or logoff (session-end). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01FHHaWKR4M5QtW7Wecyuk4t --- core/README.md | 5 +- core/main/crashHooks.test.ts | 21 ++++++ core/main/crashHooks.ts | 42 ++++++++++-- core/main/diagLog.test.ts | 55 ++++++++++++++- core/main/diagLog.ts | 122 +++++++++++++++++++++++++++------ core/main/diagnostics.ts | 25 ++++++- core/main/ipcTiming.test.ts | 19 +++++ core/main/ipcTiming.ts | 25 +++++-- core/main/stallWatch.test.ts | 49 +++++++++++++ core/main/stallWatch.ts | 35 +++++++++- core/renderer/lib/diag.test.ts | 25 +++++++ core/renderer/lib/diag.ts | 32 +++++++-- core/shared/diagGate.test.ts | 35 ++++++++++ core/shared/diagGate.ts | 81 ++++++++++++++++++++++ docs/diagnostics.md | 26 +++++-- src/main/index.ts | 17 +++-- tools/diag.mjs | 3 +- 17 files changed, 567 insertions(+), 50 deletions(-) create mode 100644 core/shared/diagGate.test.ts create mode 100644 core/shared/diagGate.ts diff --git a/core/README.md b/core/README.md index a67b560..54d2e6f 100644 --- a/core/README.md +++ b/core/README.md @@ -191,7 +191,10 @@ 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). The bridge is `DGCH` in +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 diff --git a/core/main/crashHooks.test.ts b/core/main/crashHooks.test.ts index 50e75c0..6854e58 100644 --- a/core/main/crashHooks.test.ts +++ b/core/main/crashHooks.test.ts @@ -52,6 +52,27 @@ describe('hookCrashes', () => { 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() diff --git a/core/main/crashHooks.ts b/core/main/crashHooks.ts index 05d5aa2..4669fd4 100644 --- a/core/main/crashHooks.ts +++ b/core/main/crashHooks.ts @@ -1,6 +1,7 @@ import { performance } from 'perf_hooks' import type { DiagLog } from './diagLog' import { errorFields } from './diagSummary' +import { createDiagGate } from '../shared/diagGate' /** * ERRORS AND CRASHES, OBSERVED (#140). @@ -13,9 +14,9 @@ import { errorFields } from './diagSummary' * warning and the app ran on, with or without a listener, so the listener * costs the console warning and nothing else. * - * Every line here is 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. + * 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 */ @@ -31,10 +32,12 @@ export interface CrashHookDeps { 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 }: CrashHookDeps): () => void { +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) @@ -43,9 +46,35 @@ export function hookCrashes({ log, process: proc, app }: CrashHookDeps): () => v /* 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 => - land('main-error', { ...errorFields(err), origin: typeof origin === 'string' ? origin : null }) - const onRejection = (reason: unknown): void => land('main-rejection', errorFields(reason)) + 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 => @@ -56,6 +85,7 @@ export function hookCrashes({ log, process: proc, app }: CrashHookDeps): () => v 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) diff --git a/core/main/diagLog.test.ts b/core/main/diagLog.test.ts index ea851aa..e19bf1d 100644 --- a/core/main/diagLog.test.ts +++ b/core/main/diagLog.test.ts @@ -1,5 +1,5 @@ import { afterEach, describe, expect, it, vi } from 'vitest' -import { existsSync, mkdirSync, mkdtempSync, readFileSync, writeFileSync } from 'fs' +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' @@ -69,6 +69,59 @@ describe('createDiagLog', () => { 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 }) diff --git a/core/main/diagLog.ts b/core/main/diagLog.ts index ff48cbc..6948921 100644 --- a/core/main/diagLog.ts +++ b/core/main/diagLog.ts @@ -1,5 +1,5 @@ import { appendFileSync, mkdirSync, readFileSync, renameSync, rmSync, statSync, writeFileSync } from 'fs' -import { appendFile, mkdir } from 'fs/promises' +import { open } from 'fs/promises' import { dirname, join } from 'path' import { performance } from 'perf_hooks' import { cleanFields, errorFields } from './diagSummary' @@ -20,6 +20,13 @@ import { cleanFields, errorFields } from './diagSummary' * 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' @@ -64,6 +71,11 @@ export const DIAG_MAX_BYTES = 2 * 1024 * 1024 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 @@ -82,6 +94,16 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { 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 @@ -118,22 +140,52 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { } } - /** Rotation, synchronous: it happens once per 2 MB, and renames are fast. */ + /** 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 - 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 */ + 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) } - renameSync(file, `${file}.1`) - size = 0 } + /** 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 = [] @@ -148,14 +200,31 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { chain = chain.then(async () => { const text = take() if (text === null) return + const batch = { text, bytes: Buffer.byteLength(text), done: false } try { - await mkdir(dir, { recursive: true }) - const bytes = Buffer.byteLength(text) - rotateIfFull(bytes) - await appendFile(file, text) - size += bytes + 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) { - fail(err) + if (!batch.done) { + dirReady = false + fail(err) + } + } finally { + batch.done = true + if (inflightBatch === batch) inflightBatch = null } }) return chain @@ -166,15 +235,25 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { clearTimeout(timer) timer = null } - const text = take() - if (text === null) return + 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 { - mkdirSync(dir, { recursive: true }) + ensureDir() const bytes = Buffer.byteLength(text) rotateIfFull(bytes) appendFileSync(file, text) size += bytes } catch (err) { + dirReady = false fail(err) } } @@ -184,8 +263,11 @@ export function createDiagLog(opts: DiagLogOptions): DiagLog { 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)) - if (queue.length > 2000) queue.splice(0, queue.length - 2000) schedule() } catch (err) { fail(err) diff --git a/core/main/diagnostics.ts b/core/main/diagnostics.ts index a244158..3440547 100644 --- a/core/main/diagnostics.ts +++ b/core/main/diagnostics.ts @@ -32,6 +32,13 @@ export interface DiagnosticsDeps { 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. */ @@ -72,7 +79,7 @@ export function startDiagnostics(deps: DiagnosticsDeps): Diagnostics { ...(deps.appInfo.e2e ? { e2e: true } : {}) }) - const timing = timeIpcMain(deps.ipcMain, log) + const timing = timeIpcMain(deps.ipcMain, log, { longWait: deps.longWaitChannels }) let win: DiagWindow | null = null const watch: StallWatch = startStallWatch({ log, @@ -89,14 +96,30 @@ export function startDiagnostics(deps: DiagnosticsDeps): Diagnostics { 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() diff --git a/core/main/ipcTiming.test.ts b/core/main/ipcTiming.test.ts index 71fe74a..a51169f 100644 --- a/core/main/ipcTiming.test.ts +++ b/core/main/ipcTiming.test.ts @@ -212,6 +212,25 @@ describe('timeIpcMain', () => { 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() diff --git a/core/main/ipcTiming.ts b/core/main/ipcTiming.ts index f78fb54..b1d874d 100644 --- a/core/main/ipcTiming.ts +++ b/core/main/ipcTiming.ts @@ -62,8 +62,21 @@ export interface IpcTimingOptions { 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]) @@ -75,6 +88,7 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi 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() @@ -98,10 +112,13 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi try { const end = now() const ms = Math.round(end - start) - recent.push({ ch, start, end }) - if (recent.length > RECENT_MAX) recent.shift() + 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 (ms >= (sync ? syncSlowMs : slowMs)) + 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 { @@ -114,7 +131,7 @@ export function timeIpcMain(ipcMain: IpcMainPatchable, log: DiagLog, opts: IpcTi return (event, ...args) => { const start = now() const id = nextId++ - running.set(id, { ch, start }) + if (!longWait.has(ch)) running.set(id, { ch, start }) let result: unknown try { result = fn(event, ...args) diff --git a/core/main/stallWatch.test.ts b/core/main/stallWatch.test.ts index ecb04ee..39a35ba 100644 --- a/core/main/stallWatch.test.ts +++ b/core/main/stallWatch.test.ts @@ -156,6 +156,22 @@ describe('the page heartbeat', () => { 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 }) @@ -164,6 +180,39 @@ describe('the page heartbeat', () => { }) }) +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() diff --git a/core/main/stallWatch.ts b/core/main/stallWatch.ts index 01a8423..93a644d 100644 --- a/core/main/stallWatch.ts +++ b/core/main/stallWatch.ts @@ -54,6 +54,14 @@ export interface StallWatch { 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 } @@ -80,6 +88,9 @@ export function startStallWatch(deps: StallWatchDeps): StallWatch { 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 { @@ -105,9 +116,19 @@ export function startStallWatch(deps: StallWatchDeps): StallWatch { 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) }) + 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) @@ -121,8 +142,10 @@ export function startStallWatch(deps: StallWatchDeps): StallWatch { 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 }) @@ -159,6 +182,16 @@ export function startStallWatch(deps: StallWatchDeps): StallWatch { // 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/renderer/lib/diag.test.ts b/core/renderer/lib/diag.test.ts index 63281a0..33ae2bf 100644 --- a/core/renderer/lib/diag.test.ts +++ b/core/renderer/lib/diag.test.ts @@ -156,6 +156,31 @@ describe('startDiag', () => { }) }) +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() diff --git a/core/renderer/lib/diag.ts b/core/renderer/lib/diag.ts index 1f75cd6..65e04a0 100644 --- a/core/renderer/lib/diag.ts +++ b/core/renderer/lib/diag.ts @@ -1,4 +1,5 @@ import type { DiagApi, DiagPageLine } from '../../preload/diagApi' +import { createDiagGate } from '../../shared/diagGate' /** * THE PAGE'S HALF OF THE DIAGNOSTICS LOG (#140), for both hosts. @@ -35,6 +36,8 @@ 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. */ @@ -106,14 +109,33 @@ export function errorLine( 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) - if (queue.length > QUEUE_MAX) queue.splice(0, queue.length - QUEUE_MAX) +} + +/** 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 || queue.length === 0) return + 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 { @@ -209,8 +231,8 @@ export function startDiag(bridge: DiagApi, target: PageTarget = globalThis as un observers.push(o) } - const onError = (ev: never): void => enqueue(errorLine('page-error', ev)) - const onRejection = (ev: never): void => enqueue(errorLine('page-rejection', ev)) + 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) @@ -239,4 +261,6 @@ export function resetDiag(): void { verbose = false ring = [] queue = [] + dropped = 0 + errorGate = createDiagGate() } 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/docs/diagnostics.md b/docs/diagnostics.md index e588e11..87dda12 100644 --- a/docs/diagnostics.md +++ b/docs/diagnostics.md @@ -73,25 +73,34 @@ Quiet level, always on: | --- | --- | --- | --- | | `session` | main | start | `app`, `version`, `electron`, `chrome`, `windows`, `pid`, `verbose`, `cpus`, `cpu`, `ramGb`, `e2e` | | `quit` | main | the quit, last line | | -| `main-lag` | main | main's 50 ms tick came 100 ms or more late | `ms`, `inflight` (`ch`, `ms`, `done`) | +| `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 | `ch`, `ms`, `args`, `ok`, `sync` | +| `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) | -| `main-error` / `main-rejection` | main | `uncaughtExceptionMonitor`, `unhandledRejection` (observed only) | `msg`, `stack`, `origin` | +| `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 (once a session) | `msg` | +| `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: @@ -115,8 +124,11 @@ second passes `{ often: true }`. ## Wiring (a host) - Main, before any IPC is registered: `startDiagnostics({ diagLogDir, ipcMain, process, app, - appInfo, openFolder })`, 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. + 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. diff --git a/src/main/index.ts b/src/main/index.ts index a4dbcda..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' @@ -343,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) @@ -742,7 +748,10 @@ if (!app.requestSingleInstanceLock()) { 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) + 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). diff --git a/tools/diag.mjs b/tools/diag.mjs index c0b37fc..be119a4 100644 --- a/tools/diag.mjs +++ b/tools/diag.mjs @@ -32,6 +32,7 @@ const PROBLEMS = new Set([ 'gone', 'unresponsive', 'logger-error', + 'logger-dropped', 'mark' ]) const CRUMBS_BEFORE = 5 @@ -123,7 +124,7 @@ function summary(l) { case 'page-rejection': case 'main-error': case 'main-rejection': - return `${l.msg}${l.loc ? ` at ${l.loc}` : ''}${l.stack ? `\n${indent(l.stack, 6)}` : ''}` + 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': {