diff --git a/.gitignore b/.gitignore index fbc49a52..90c17830 100644 --- a/.gitignore +++ b/.gitignore @@ -32,6 +32,7 @@ standalone/src-tauri/binaries/ standalone/src-tauri/gen/ standalone/dist/ standalone/sidecar/dor-cli/ +standalone/sidecar/alert-journal.cjs standalone/sidecar/iframe-proxy.cjs standalone/sidecar/agent-browser-host.cjs standalone/sidecar/burrow.cjs diff --git a/docs/alert-diagnostics-removal.md b/docs/alert-diagnostics-removal.md new file mode 100644 index 00000000..8f82c67f --- /dev/null +++ b/docs/alert-diagnostics-removal.md @@ -0,0 +1,13 @@ +# Removing temporary alert diagnostics + +The feature gate and current logging contract are owned by `docs/specs/alert.md` → Local alert diagnostics. + +Use this checklist when the usage sample and alert investigation are finished: + +1. Remove `lib/src/lib/alert-diagnostics-config.ts`, `lib/src/lib/alert-diagnostics.ts`, and `lib/src/host/alert-journal.ts`, their dedicated tests, and `vscode-ext/src/alert-journal.ts`. +2. Remove diagnostic imports and calls from the alert manager, detector, ring watcher, speech, settings, activity store, and platform initialization. Remove diagnostic-only snapshots, counters, timer wrappers, and attempt metadata. Keep the existing ring/attention decisions, speech callbacks, and high-entropy redaction. +3. Remove `recordAlertDiagnostic` from the platform port and desktop adapters; remove `alert:diagnostic` / `alert_diagnostic` from the VS Code message types/router, Tauri command registration, and sidecar dispatch. Remove journal initialization/shutdown hooks, the sidecar bundle entry, and its `.gitignore` entry. +4. Remove `scripts/summarize-alert-log.mjs`, its test and root test-script entry. Remove diagnostic-only assertions from mixed test files, the owning spec section/rationale, this checklist, and pointers in the transport, desktop-host, and local-security specs. Ratchet changed spec budgets. +5. Search for leftovers with `rg -n 'alert-diagnostic|alert-journal|alertDiagnostic|AlertDiagnostic|recordLifecycle|diagnosticSnapshot|summarize-alert-log' lib standalone vscode-ext scripts docs .gitignore package.json`. Run `pnpm test` and build both desktop hosts. + +Disabling or removing the feature leaves existing `alert-logs` directories intact. Delete those saved samples separately if they are no longer needed. diff --git a/docs/specs/alert.md b/docs/specs/alert.md index 3ac64d26..3bc846eb 100644 --- a/docs/specs/alert.md +++ b/docs/specs/alert.md @@ -289,10 +289,23 @@ Source of truth: `AlertSettings` in `lib/src/lib/alert-settings.ts` (renderer mi - Web Speech has no per-utterance stop, so `cancel()` empties the whole queue. **Re-dispatch every still-ringing Session whose current-ring utterance was accepted but never started**, because attending one Pane must not silence another's alarm, and hold each re-dispatch to the same gates as the first (attended meanwhile, or the setting switched off, drops out). **Prune a queued entry as soon as its ring resolves**, so a later unrelated `cancel()` cannot re-dispatch a stale one, bypass the new ring's delay, and speak twice. **Never cut a Session that is only queued** — cutting it would take the Pane that *is* talking with it. - **Teardown must `cancel()` the engine, not just detach the callbacks** — a webview that unmounts mid-alarm would otherwise keep reading Pane names aloud with no UI left to stop it. - **In-flight tracking is bounded.** The utterance set and queued index evict their oldest entry past a shared cap. Delivery identities retain one token per ringing Session until the ring resolves. An evicted utterance that still fires settles normally; it is no longer eligible for collateral re-dispatch. -- `speaking` / `spoken` remains only while the originating Session is still `ALERT_RINGING`: any action that resolves the ring (Clearing And TODO) clears it, killing the Session included, while visibility, hover, and command-mode selection do not. **Never persist it or send it to the host**, so restore/reconnect cannot recreate it. +- `speaking` / `spoken` remains only while the originating Session is still `ALERT_RINGING`: any action that resolves the ring (Clearing And TODO) clears it, killing the Session included, while visibility, hover, and command-mode selection do not. **Never persist it as restorable state or send it as host alert state**, so restore/reconnect cannot recreate it. Diagnostic events follow Local alert diagnostics. Source of truth: `toSpokenText` in `lib/src/lib/alert-speech.ts`, armed by `lib/src/components/wall/use-alert-speech.ts`; `redactHighEntropyTokens` in `lib/src/lib/redact-high-entropy.ts`; label derivation in `lib/src/lib/session-label.ts`; `AlertSpeechState` in `lib/src/lib/alert-speech-state.ts`. +### Local alert diagnostics + +- **Must default temporary diagnostics off**, through `alertDiagnosticsConfig.enabled` in `lib/src/lib/alert-diagnostics-config.ts`. Disabled builds emit no diagnostic IPC, install no diagnostic focus listeners, and write or prune no journal files, including direct host/lifecycle records. Set the flag to `true`, rebuild the desktop frontend and host/sidecar bundles, and restart to collect a sample; this is a source switch, not a persisted setting. Existing logs remain untouched. Removal checklist: `docs/alert-diagnostics-removal.md`. Pinned by `lib/src/lib/alert-diagnostics-gate.test.ts`. +- **Must journal desktop alert decisions and local speech attempts without changing delivery behavior when diagnostics are enabled.** Logging failure never blocks an alert; diagnostics never hydrate alert state. Pocket and the website demo have no journal port (rationale). +- **Must record only the final `toSpokenText` payload as speech content**, with code-point and UTF-16 counts, a distinct attempt id, Session id and ring sequence, and a reason separating fresh rings, queue redispatch, and settings tests. Record unavailable/refused dispatch, queue admission, engine start/end/error, and global cancellation. A callback includes the current ring state and time since request; absence of callbacks is unknown delivery, not silence. +- **Must correlate decisions with source-instance ids, source sequence numbers, wall time, and process-local monotonic time.** Record decision inputs before ring mutations, manager publications, suppression reasons, semantic event kinds, dismissal/attention actions, detector changes, deferred delivery, timer deadlines/lateness, renderer snapshots, focus/visibility transitions, and host shutdown start/completion. Sample output through cumulative received/resize-ignored chunk counts and last-output timestamps at those events; never log PTY bytes, raw commands, or notification bodies. +- **Must bound logging before IPC and disk.** The emitter admits 100 events per monotonic second, with speech allowed through a 200-event total; the writer accepts at most 512 queued records of 8 KiB each. Loss is reported on subsequent successful writes. IPC loss, abrupt shutdown, and retention can leave incomplete traces. Never infer exact provider billing from them. +- **Must rotate JSONL files at 4 MiB or 24 hours of writing**, pruning on rotation/startup by a 30-day age and a 64 MiB directory budget with one file's headroom. Concurrent writers make the size budget approximate. Files are local to the host's app storage; access controls are described in `docs/specs/security-local.md` → Persisted state. + +Run `node scripts/summarize-alert-log.mjs ` for UTC daily character totals separated into fresh rings, redispatch, and tests, plus observed outcomes and loss markers. The source count excludes journal-writer identities, including standalone's writer-owned shutdown markers; standalone counts its renderer, while VS Code counts renderer and extension-host emitters. Files and first/last record times describe the available sample, not continuous uptime. Multiply the relevant character volume by the eventual provider/model rate; no ElevenLabs client or pricing is built here. + +Source of truth: `alertDiagnostic` in `lib/src/lib/alert-diagnostics.ts`; `trace` in `lib/src/lib/alert-manager.ts`; `speak` in `lib/src/lib/alert-speech.ts`; `watchUnattendedRings` in `lib/src/lib/alert-ring-watch.ts`; `createAlertJournal` in `lib/src/host/alert-journal.ts`; `summarizeAlertLogs` in `scripts/summarize-alert-log.mjs`. Pinned by `lib/src/lib/alert-diagnostics.test.ts`, `lib/src/lib/alert-speech.test.ts`, `lib/src/host/alert-journal.test.ts`, and `scripts/summarize-alert-log.test.mjs`. + ### Push notifications **The two halves run in different processes.** Ring *detection* is webview state, so `watchPushRings` stays in the webview and fires one `push { sessionId, title }` command at the Burrow service. *Delivery* needs the enrollment and the ACL, which only the Burrow holds, so `sendPush` runs in the service's process and touches no DOM or store. **A webview cannot choose recipients:** it names the Session and what to call it; the service reads its own active ACL at send time. **Arm watching only while the service reports an enrollment** (`enrolled-gate.ts`), so an un-enrolled machine pays no activity-store subscription; a `push` arriving with no Burrow running is not sent. **Keep both halves under `remote/burrow/`**, inside the lazily-imported `RemotePairingModalHost` chunk, so a host without `enableBurrow` never fetches it (rationale). diff --git a/docs/specs/alert.rationale.md b/docs/specs/alert.rationale.md index ec9bb99c..665695e2 100644 --- a/docs/specs/alert.rationale.md +++ b/docs/specs/alert.rationale.md @@ -80,6 +80,14 @@ Guarding only completion leaves a stale `start` free to replace the active utterance's token. Queue-admission identity also covers old rings, collateral redispatch, and evicted callbacks after teardown; it retains one token per ringing Session without retaining each engine utterance. +## Local alert diagnostics + +A source switch keeps this temporary investigation out of persisted alarm settings. Gating both the emitter and journal covers renderer IPC and the sidecar’s direct lifecycle path; either gate alone would leave part of the feature active. + +A spoken alert after focus returns can be a newly latched ring, a replayed host snapshot, a throttled renderer timer, or an engine queue entry that starts late. Logging only speech text cannot distinguish these. The VS Code manager survives in the extension host while its renderer is hidden; standalone's manager lives in the renderer. Recording both layers, their separate source lifetimes, and the last accepted output connects a dismissal to the later decision without storing terminal content. Monotonic clocks are comparable only within one source; wall-clock deadlines expose delayed timers but can also move when the system clock changes. + +Post-sanitization counts measure the text a future speech provider would receive. Redispatch is separate because the future remote queue and browser fallback need not retry identically. Local request volume is a planning sample, not a billing ledger. Best-effort bounded writing keeps observability off the alert's critical path. + ## Push notifications **Why both halves live under `remote/burrow/`.** The sink rides the lazily-imported `RemotePairingModalHost` chunk; the shared ring machine and the device store stay in the common bundle instead, since speech and the settings dialog need them everywhere. diff --git a/docs/specs/security-local.md b/docs/specs/security-local.md index 58407e0b..b6eb69f6 100644 --- a/docs/specs/security-local.md +++ b/docs/specs/security-local.md @@ -166,6 +166,10 @@ invocation per Surface, no buffer, unlinked as it is read with `wx`, its socket directory re-checked on every contention round. **Neither control does anything on Windows** (rationale). +**Must keep alert journals in host app storage, separate from the standalone debug log.** `/alert-logs/` (standalone) and `context.globalStorageUri/alert-logs/` (VS Code) contain post-redaction spoken text and diagnostic metadata. Redaction is a heuristic; spoken text can still contain sensitive words. The writer creates/tightens its directory to `0700` and exclusively creates files at `0600` on Unix; Windows uses inherited host-storage ACLs, including standalone's `burrow_state_dir` restriction. No upload or Settings Sync is involved. Content and retention: `docs/specs/alert.md` → Local alert diagnostics. + +Source of truth: `createAlertJournal` in `lib/src/host/alert-journal.ts`, pinned by `lib/src/host/alert-journal.test.ts`. + **The standalone log is unprotected and names the control socket.** `$DORMOUSE_LOG_FILE`, else `%LOCALAPPDATA%\Dormouse Terminal\dormouse.log`, else `/dormouse.log`, created and appended with no mode and no ACL, so it diff --git a/docs/specs/standalone.md b/docs/specs/standalone.md index 6ea82383..9d94ced6 100644 --- a/docs/specs/standalone.md +++ b/docs/specs/standalone.md @@ -502,6 +502,8 @@ native handler never fires. Behavior and status: ## Logging +Local alert diagnostics (`docs/specs/alert.md` → Local alert diagnostics) live in `/alert-logs/`, written by the Node sidecar through `alert_diagnostic`. The sidecar bundles `createAlertJournal` from `lib/src/host/alert-journal.ts` and gives its close at most 250ms during shutdown. The browser-dev harness has no persistent journal. + Windows release builds use the GUI subsystem, so nothing streams to a launching terminal. The Rust backend appends sidecar stderr, malformed stdout diagnostics, and its own diagnostics to a log file: `%LOCALAPPDATA%\Dormouse Terminal\dormouse.log` on diff --git a/docs/specs/transport.md b/docs/specs/transport.md index bb00c2b3..204b6df0 100644 --- a/docs/specs/transport.md +++ b/docs/specs/transport.md @@ -122,6 +122,7 @@ Transport constraints: | Direction | Message | Contract | | --- | --- | --- | +| Webview → host | `alert:diagnostic` (VS Code) / `alert_diagnostic` → sidecar `alert:diagnostic` (Tauri) | One local journal record through the optional `recordAlertDiagnostic` adapter port. No reply, broadcast, or Relay forwarding. **Must validate the bounded primitive record before retaining it**; `isAlertDiagnostic` in `lib/src/host/alert-journal.ts`. Behavior: `docs/specs/alert.md` → Local alert diagnostics. | | Webview → host | `dormouse:openExternal` | Open a user-confirmed external URI from an OSC 8 hyperlink. **Hosts must revalidate**, rejecting malformed, control-character-bearing, or blocked pseudo-scheme targets (`javascript:`, `data:`, `blob:`, `about:` — `lib/src/lib/external-links.ts`). | | Webview → host | `pty:getOpenPorts` | TCP listening ports of a PTY's shell **and all of its descendant subprocesses**, resolved from the root pid, answered with `pty:openPorts`. `getOpenPortsForPid()` in `standalone/sidecar/pty-core.js` (VS Code loads it through the `lib/pty-core.cjs` shim). | | Host → webview | `pty:openPorts` | `ports: OpenPort[]` (`{ protocol, family, address, port, pid, processName }`), de-duplicated by `(family, address, port)`, sorted by port then address. Empty when the PTY is gone or enumeration fails. | diff --git a/docs/specs/vscode.md b/docs/specs/vscode.md index 6797f7ae..35b0761a 100644 --- a/docs/specs/vscode.md +++ b/docs/specs/vscode.md @@ -6,6 +6,12 @@ > > Defers to `docs/specs/transport.md` — PTY lifecycle, buffering, reconnection, the message protocol, persisted-session types, and every adapter-agnostic invariant — for all sections below. +## Local alert diagnostics + +**Must append host decisions and renderer diagnostic messages to the same local journal**, under `context.globalStorageUri/alert-logs/`. The Dormouse output channel reports the directory. **Must keep the journal open through PTY teardown**, then give closing writes at most 250ms. Never put these records in Settings Sync or restorable Session state. Behavior: `docs/specs/alert.md` → Local alert diagnostics. + +Source of truth: `initAlertJournal` in `vscode-ext/src/alert-journal.ts`; `attachRouter` in `vscode-ext/src/message-router.ts`. + ## Code Map Start on the side of the webview boundary involved, then follow imports: diff --git a/lib/src/host/alert-journal.test.ts b/lib/src/host/alert-journal.test.ts new file mode 100644 index 00000000..1bf36c83 --- /dev/null +++ b/lib/src/host/alert-journal.test.ts @@ -0,0 +1,109 @@ +import { alertDiagnosticsConfig } from '../lib/alert-diagnostics-config'; +import { afterEach, beforeEach, expect, it, vi } from 'vitest'; +import { mkdtemp, mkdir, readdir, readFile, rm, stat, writeFile, utimes } from 'node:fs/promises'; +import { join } from 'node:path'; +import { tmpdir } from 'node:os'; +import { createAlertJournal, isAlertDiagnostic } from './alert-journal'; +import type { AlertDiagnostic } from '../lib/alert-diagnostics'; + +const dirs: string[] = []; +const journals: ReturnType[] = []; +beforeEach(() => { alertDiagnosticsConfig.enabled = true; }); +afterEach(async () => { + await Promise.all(journals.splice(0).map((j) => j.close())); + alertDiagnosticsConfig.enabled = false; + await Promise.all(dirs.splice(0).map((d) => rm(d, { recursive: true, force: true }))); +}); +async function setup() { + const dir = await mkdtemp(join(tmpdir(), 'alert-journal-')); + dirs.push(dir); + const journal = createAlertJournal(dir); + journals.push(journal); + return { dir, journal }; +} +const record = (seq: number): AlertDiagnostic => ({ version: 1, source: 'test', seq, at: Date.now(), monotonicMs: seq, event: 'speech.request', fields: { text: 'hello', characters: 5, attempt: String(seq), reason: 'ring' } }); +async function records(directory: string) { + return (await Promise.all((await readdir(directory)).map((f) => readFile(join(directory, f), 'utf8')))) + .join('').trim().split('\n').map((s) => JSON.parse(s)); +} +it('writes private JSONL, strips extra envelope fields, and rejects oversized data', async () => { + const { journal } = await setup(); + const first = record(1); + journal.append({ ...first, unexpected: 'do not persist' }); + journal.append({ ...record(2), fields: { text: 'x'.repeat(513) } }); + await journal.flush(); + expect(await records(journal.directory)).toEqual([first]); + if (process.platform !== 'win32') { + expect((await stat(journal.directory)).mode & 0o777).toBe(0o700); + const [name] = await readdir(journal.directory); + expect((await stat(join(journal.directory, name))).mode & 0o777).toBe(0o600); + } +}); +it('bounds an overloaded queue and writes a loss marker', async () => { + const { journal } = await setup(); + for (let seq = 1; seq <= 1000; seq++) journal.append(record(seq)); + await journal.flush(); + const all = await records(journal.directory); + expect(all.filter((r) => r.event === 'speech.request')).toHaveLength(512); + expect(all.find((r) => r.event === 'journal.dropped')?.fields.count).toBe(488); + expect(all.every(isAlertDiagnostic)).toBe(true); +}); +it('prunes only its own expired files', async () => { + const { journal } = await setup(); + await mkdir(journal.directory); + const old = join(journal.directory, 'alerts-1-00000000-0000-0000-0000-000000000000.jsonl'); + await writeFile(old, 'old'); + await utimes(old, new Date(0), new Date(0)); + await writeFile(join(journal.directory, 'unrelated.txt'), 'keep'); + journal.append(record(1)); + await journal.flush(); + expect(await readdir(journal.directory)).toContain('unrelated.txt'); + await expect(stat(old)).rejects.toThrow(); +}); +it('absorbs filesystem failure without leaking record contents in warnings', async () => { + const { dir } = await setup(); + const warn = vi.fn(); + const file = join(dir, 'not-a-directory'); + await writeFile(file, 'x'); + const journal = createAlertJournal(file, warn); + journals.push(journal); + journal.append(record(1)); + await expect(journal.flush()).resolves.toBeUndefined(); + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls.flat().join('')).not.toContain('hello'); +}); + +it('rotates before exceeding the file size budget', async () => { + const { journal } = await setup(); + const fields = Object.fromEntries(Array.from({ length: 14 }, (_, i) => [`value${i}`, 'x'.repeat(500)])); + for (let batch = 0; batch < 2; batch++) { + for (let i = 0; i < 350; i++) journal.append({ ...record(batch * 350 + i + 1), fields }); + await journal.flush(); + } + const files = await readdir(journal.directory); + expect(files).toHaveLength(2); + for (const name of files) expect((await stat(join(journal.directory, name))).size).toBeLessThanOrEqual(4 * 1024 * 1024); + expect(await records(journal.directory)).toHaveLength(700); +}); + +it('reopens a file pruned by another host writer', async () => { + const { journal } = await setup(); + journal.append(record(1)); + await journal.flush(); + const [file] = await readdir(journal.directory); + await rm(join(journal.directory, file)); + journal.append(record(2)); + await journal.flush(); + expect((await records(journal.directory)).map((r) => r.seq)).toEqual([2]); +}); + +it('keeps accepting teardown records between shutdown lifecycle markers', async () => { + const { journal } = await setup(); + journal.recordLifecycle('host.stopping'); + journal.append({ ...record(1), event: 'manager.onExit', fields: { sessionId: 's' } }); + journal.recordLifecycle('host.stopped'); + await journal.close(); + const all = await records(journal.directory); + expect(all.map((r) => r.event)).toEqual(['host.stopping', 'manager.onExit', 'host.stopped']); + expect(all.every(isAlertDiagnostic)).toBe(true); +}); diff --git a/lib/src/host/alert-journal.ts b/lib/src/host/alert-journal.ts new file mode 100644 index 00000000..76b68942 --- /dev/null +++ b/lib/src/host/alert-journal.ts @@ -0,0 +1,129 @@ +import { mkdir, open, readdir, stat, unlink, chmod } from 'node:fs/promises'; +import { join } from 'node:path'; +import { randomUUID } from 'node:crypto'; +import { alertDiagnosticsConfig } from '../lib/alert-diagnostics-config'; +import type { AlertDiagnostic, DiagnosticFields } from '../lib/alert-diagnostics'; + +const FILE_BYTES = 4 * 1024 * 1024; +const TOTAL_BYTES = 64 * 1024 * 1024; +const RETENTION_MS = 30 * 24 * 60 * 60 * 1000; +const MAX_QUEUED = 512; +const FILE_PATTERN = /^alerts-[\d-]+-[0-9a-f-]+\.jsonl$/; + +/** Bounded, best-effort private JSONL journal, shared by the two desktop hosts. + * Each writer owns unique files. Never fall back to the public diagnostic log. */ +export function createAlertJournal(stateDir: string, warn: (message: string) => void = console.warn) { + const directory = join(stateDir, 'alert-logs'); + const queue: string[] = []; + const source = `journal:${randomUUID()}`; + let seq = 0; + let draining: Promise | undefined; + let file: Awaited> | undefined; + let bytes = 0; + let openedAt = 0; + let dropped = 0; + let closed = false; + let warned = false; + + function writerRecord(event: string, fields: DiagnosticFields = {}): AlertDiagnostic { + return { version: 1, source, seq: ++seq, at: Date.now(), monotonicMs: performance.now(), event, fields }; + } + + async function prune(): Promise { + const names = (await readdir(directory)).filter((name) => FILE_PATTERN.test(name)); + const files = await Promise.all(names.map(async (name) => { + const path = join(directory, name); + return { path, ...await stat(path).catch(() => ({ size: 0, mtimeMs: 0 })) }; + })); + files.sort((a, b) => b.mtimeMs - a.mtimeMs); + let total = 0; + for (const entry of files) { + total += entry.size; + if (Date.now() - entry.mtimeMs > RETENTION_MS || total > TOTAL_BYTES - FILE_BYTES) { + await unlink(entry.path).catch(() => {}); + } + } + } + + async function drain(): Promise { + try { + await mkdir(directory, { recursive: true, mode: 0o700 }); + await chmod(directory, 0o700); + while (queue.length || dropped) { + const lost = dropped; + const line = lost + ? JSON.stringify(writerRecord('journal.dropped', { count: lost })) + '\n' + : queue[0]; + const lineBytes = Buffer.byteLength(line); + // Another window may prune an idle writer's file. Reopen instead of + // continuing to append invisibly to an unlinked inode. + if (file && (await file.stat()).nlink === 0) { await file.close(); file = undefined; } + if (!file || bytes + lineBytes > FILE_BYTES || Date.now() - openedAt >= 86_400_000) { + await file?.close(); + file = undefined; + await prune(); + file = await open(join(directory, `alerts-${Date.now()}-${randomUUID()}.jsonl`), 'wx', 0o600); + bytes = 0; + openedAt = Date.now(); + } + await file.writeFile(line); + if (lost) dropped -= lost; + else queue.shift(); + bytes += lineBytes; + } + } catch { + dropped += queue.length; + queue.length = 0; + await file?.close().catch(() => {}); + file = undefined; + if (!warned) { + warned = true; + try { warn('[alerts] Local alert journal unavailable; some diagnostics were lost.'); } catch {} + } + } + } + + function pump(): void { + if (draining) return; + draining = drain().finally(() => { + draining = undefined; + if (queue.length) pump(); + }); + } + + function append(value: unknown): void { + if (!alertDiagnosticsConfig.enabled || closed || !stateDir || !isAlertDiagnostic(value)) return; + const { version, source, seq, at, monotonicMs, event, fields } = value; + const line = JSON.stringify({ version, source, seq, at, monotonicMs, event, fields }) + '\n'; + if (Buffer.byteLength(line) > 8192 || queue.length >= MAX_QUEUED) { dropped++; return; } + queue.push(line); + pump(); + } + + return { + directory, + append, + recordLifecycle(event: 'host.stopping' | 'host.stopped'): void { append(writerRecord(event)); }, + async flush(): Promise { while (draining) await draining; }, + async close(): Promise { + closed = true; + while (draining) await draining; + await file?.close().catch(() => {}); + file = undefined; + }, + }; +} + +/** Limit untrusted renderer payloads before retaining them in the host queue. */ +export function isAlertDiagnostic(value: unknown): value is AlertDiagnostic { + if (!value || typeof value !== 'object') return false; + const r = value as AlertDiagnostic; + if (r.version !== 1 || typeof r.source !== 'string' || r.source.length > 100 + || !Number.isSafeInteger(r.seq) || r.seq < 1 || !Number.isFinite(r.at) || !Number.isFinite(r.monotonicMs) + || typeof r.event !== 'string' || !/^[a-zA-Z.]+$/.test(r.event) || r.event.length > 80 + || !r.fields || typeof r.fields !== 'object' || Array.isArray(r.fields)) return false; + const fields = Object.entries(r.fields); + return fields.length <= 64 && fields.every(([key, v]) => key.length <= 80 + && (v === null || typeof v === 'boolean' || (typeof v === 'number' && Number.isFinite(v)) + || (typeof v === 'string' && v.length <= 512))); +} diff --git a/lib/src/lib/alert-diagnostics-config.ts b/lib/src/lib/alert-diagnostics-config.ts new file mode 100644 index 00000000..38e248ec --- /dev/null +++ b/lib/src/lib/alert-diagnostics-config.ts @@ -0,0 +1,4 @@ +/** Temporary instrumentation. Flip to true, rebuild both desktop bundles, and + * restart to collect a sample. Removal checklist: docs/alert-diagnostics-removal.md. + * Shared by the renderer, VS Code extension host, and bundled Node sidecar. */ +export const alertDiagnosticsConfig = { enabled: false }; diff --git a/lib/src/lib/alert-diagnostics-gate.test.ts b/lib/src/lib/alert-diagnostics-gate.test.ts new file mode 100644 index 00000000..ec91635a --- /dev/null +++ b/lib/src/lib/alert-diagnostics-gate.test.ts @@ -0,0 +1,55 @@ +// @vitest-environment jsdom +import { afterEach, expect, it, vi } from 'vitest'; +import { mkdtemp, rm, stat } from 'node:fs/promises'; +import { join } from 'node:path'; +import { tmpdir } from 'node:os'; +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; +import { alertDiagnostic, alertDiagnosticsEnabled, configureAlertDiagnostics, observeAlertFocus } from './alert-diagnostics'; +import { createAlertJournal } from '../host/alert-journal'; +import { speakTestUtterance } from './alert-speech'; + +afterEach(() => { + configureAlertDiagnostics('off'); + vi.restoreAllMocks(); + vi.unstubAllGlobals(); +}); + +it('defaults off even when a sink is supplied, while speech still works', () => { + expect(alertDiagnosticsConfig.enabled).toBe(false); + const sink = vi.fn(); + configureAlertDiagnostics('renderer', sink); + const speak = vi.fn(); + vi.stubGlobal('speechSynthesis', { speak }); + vi.stubGlobal('SpeechSynthesisUtterance', class { + constructor(readonly text: string) {} + }); + expect(speakTestUtterance()).toBe(true); + expect(speak).toHaveBeenCalledOnce(); + alertDiagnostic('host.stopping'); + expect(alertDiagnosticsEnabled()).toBe(false); + expect(sink).not.toHaveBeenCalled(); +}); + +it('does not install diagnostic focus listeners while disabled', () => { + const windowListener = vi.spyOn(window, 'addEventListener'); + const documentListener = vi.spyOn(document, 'addEventListener'); + observeAlertFocus()(); + expect(windowListener).not.toHaveBeenCalled(); + expect(documentListener).not.toHaveBeenCalled(); +}); + +it('does not create log storage for direct host or lifecycle records while disabled', async () => { + const directory = await mkdtemp(join(tmpdir(), 'alert-gate-')); + const journal = createAlertJournal(directory); + try { + journal.append({ version: 1, source: 'renderer', seq: 1, at: Date.now(), monotonicMs: 1, + event: 'speech.request', fields: { text: 'Dormouse alarm test' } }); + journal.recordLifecycle('host.stopping'); + journal.recordLifecycle('host.stopped'); + await journal.close(); + await expect(stat(journal.directory)).rejects.toMatchObject({ code: 'ENOENT' }); + } finally { + await journal.close(); + await rm(directory, { recursive: true, force: true }); + } +}); diff --git a/lib/src/lib/alert-diagnostics.test.ts b/lib/src/lib/alert-diagnostics.test.ts new file mode 100644 index 00000000..7b573c11 --- /dev/null +++ b/lib/src/lib/alert-diagnostics.test.ts @@ -0,0 +1,116 @@ +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; +import { afterEach, beforeEach, expect, it, vi } from 'vitest'; +import { alertDiagnostic, configureAlertDiagnostics, type AlertDiagnostic } from './alert-diagnostics'; +import { AlertManager } from './alert-manager'; + +let records: AlertDiagnostic[]; +let manager: AlertManager; +beforeEach(() => { + alertDiagnosticsConfig.enabled = true; + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date', 'performance'] }); + records = []; + configureAlertDiagnostics('test', (record) => records.push(record)); + manager = new AlertManager(); +}); +afterEach(() => { + manager.dispose(); + configureAlertDiagnostics('off'); + alertDiagnosticsConfig.enabled = false; + vi.useRealTimers(); +}); + +it('preserves dismissal and last output evidence across an hour away', () => { + manager.onData('s'); + manager.notifyFromProtocol('s', { source: 'OSC 9', title: 'secret raw title', body: 'raw body' }); + manager.dismissAlert('s'); + manager.clearAttention(); + vi.advanceTimersByTime(3_600_000); + manager.attend('s'); + const dismissal = records.find((r) => r.event === 'manager.dismissAlert')!; + expect(dismissal.fields).toMatchObject({ sessionId: 's', ringSeq: 1, status: 'ALERT_RINGING', outputChunks: 1 }); + const attention = records.findLast((r) => r.event === 'manager.attention')!; + expect(attention.fields).toMatchObject({ ringSeq: 1, outputChunks: 1, status: 'WATCHING_DISABLED' }); + expect(attention.at - dismissal.at).toBe(3_600_000); + expect(JSON.stringify(records)).not.toContain('raw'); +}); + +it('explains rearmed animation deferral after output and a detector reset', () => { + manager.setDeferAlertsUntilQuiet(true); + manager.onData('s'); + vi.advanceTimersByTime(500); + manager.onData('s'); + vi.advanceTimersByTime(1100); + manager.onData('s'); + manager.notifyFromProtocol('s', { source: 'OSC 9', title: 'private title', body: null }); + expect(records.some((r) => r.event === 'manager.defer')).toBe(true); + vi.advanceTimersByTime(1000); + manager.onData('s'); + manager.applyTerminalSemanticEvents('s', [{ type: 'promptStart' }]); + vi.advanceTimersByTime(4000); + const wake = records.find((r) => r.event === 'manager.deferTimer')!; + expect(wake.fields).toMatchObject({ outputChunks: 4, pendingNotification: 'OSC 9' }); + expect(wake.fields.quietDueAt).toBeGreaterThan(wake.at); + expect(records.filter((r) => r.event === 'manager.deferScheduled')).toHaveLength(2); + manager.dismissAlert('s'); + vi.advanceTimersByTime(3_600_000); + expect(records.some((r) => r.event === 'manager.deferFlush')).toBe(false); + expect(JSON.stringify(records)).not.toContain('private title'); +}); + +it('reports output ignored during resize without recording PTY bytes', () => { + manager.onResize('s'); + manager.onData('s'); + manager.dismissAlert('s'); + expect(records.find((r) => r.event === 'manager.dismissAlert')?.fields).toMatchObject({ + outputChunks: 1, ignoredResizeChunks: 1, lastAcceptedOutputAt: null, resizeGrace: true, + }); +}); + +it('bounds storms, reserves room for speech, and reports dropped events', () => { + for (let i = 0; i < 500; i++) alertDiagnostic('manager.publish'); + alertDiagnostic('speech.request'); + expect(records.filter((r) => r.event === 'speech.request')).toHaveLength(1); + expect(records).toHaveLength(101); + vi.advanceTimersByTime(1000); + alertDiagnostic('manager.publish'); + expect(records.find((r) => r.event === 'diagnostics.dropped')?.fields.count).toBe(401); +}); + +it('keeps alert delivery working when the diagnostic sink throws', () => { + configureAlertDiagnostics('broken', () => { throw new Error('disk unavailable'); }); + expect(() => manager.notifyFromProtocol('s', { source: 'OSC 9', title: 'done', body: null })).not.toThrow(); + expect(manager.getState('s').status).toBe('ALERT_RINGING'); +}); + +it('reports the suppression branch actually taken when conditions overlap', () => { + manager.attend('s'); + manager.applyTerminalSemanticEvents('s', [ + { type: 'commandLine', commandLine: 'private command' }, + { type: 'commandStart', source: 'osc633_E', startedAt: Date.now() }, + { type: 'commandFinish', exitCode: 0 }, + ]); + expect(records.find((r) => r.event === 'manager.completion')?.fields).toMatchObject({ + kind: 'commandFinished', reason: 'not-armed', armed: false, ranMs: 0, + }); + expect(JSON.stringify(records)).not.toContain('private command'); +}); + +it('preserves pending notification inputs before a command exit flushes and rings', () => { + manager.setInactivityTimeoutMs(100); + manager.setDeferAlertsUntilQuiet(true); + manager.applyTerminalSemanticEvents('s', [ + { type: 'commandStart', source: 'osc633_E', startedAt: Date.now() }, + ]); + manager.attend('s'); + manager.onData('s'); + vi.advanceTimersByTime(500); + manager.onData('s'); + vi.advanceTimersByTime(1100); + manager.onData('s'); + manager.notifyFromProtocol('s', { source: 'OSC 9', title: 'done', body: null }); + manager.applyTerminalSemanticEvents('s', [{ type: 'commandFinish', exitCode: 0 }]); + const decision = records.find((r) => r.event === 'manager.completion' && r.fields.kind === 'commandFinished')!; + const publication = records.findLast((r) => r.event === 'manager.publish')!; + expect(decision.fields).toMatchObject({ reason: 'eligible', ringSeq: 0, pendingNotification: 'OSC 9', todo: false }); + expect(publication.fields).toMatchObject({ status: 'ALERT_RINGING', pendingNotification: null, todo: true }); +}); diff --git a/lib/src/lib/alert-diagnostics.ts b/lib/src/lib/alert-diagnostics.ts new file mode 100644 index 00000000..51af32d0 --- /dev/null +++ b/lib/src/lib/alert-diagnostics.ts @@ -0,0 +1,74 @@ +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; + +/** Local observability only: never use these records to drive alert state. */ +export type DiagnosticFields = Record; +export interface AlertDiagnostic { + version: 1; + source: string; + seq: number; + at: number; + monotonicMs: number; + event: string; + fields: DiagnosticFields; +} + +let sink: ((record: AlertDiagnostic) => void) | undefined; +let source = ''; +let seq = 0; +let windowAt = 0; +let windowCount = 0; +let dropped = 0; + +export function alertDiagnosticsEnabled(): boolean { return alertDiagnosticsConfig.enabled && sink !== undefined; } + +export function diagnosticId(): string { + return globalThis.crypto?.randomUUID?.() ?? `${Date.now()}-${Math.random().toString(36).slice(2)}`; +} + +export function configureAlertDiagnostics(label: string, write?: (record: AlertDiagnostic) => void): void { + sink = alertDiagnosticsConfig.enabled ? write : undefined; + source = `${label}:${diagnosticId()}`; + seq = windowCount = dropped = 0; + windowAt = performance.now(); + alertDiagnostic('source.start', { label }); +} + +/** Callers pass metadata only; speech.request alone carries sanitized spoken text. + * Bound event storms before IPC and signal loss. Disk/IPC failure cannot affect alerts. */ +export function alertDiagnostic(event: string, fields: DiagnosticFields = {}): void { + if (!alertDiagnosticsEnabled() || !sink) return; + try { + const monotonicMs = performance.now(); + const record = (name: string, data: DiagnosticFields): AlertDiagnostic => ({ + version: 1, source, seq: ++seq, at: Date.now(), monotonicMs, event: name, fields: data, + }); + if (monotonicMs - windowAt >= 1000) { + windowAt = monotonicMs; + windowCount = 0; + if (dropped) { + const count = dropped; + dropped = 0; + sink(record('diagnostics.dropped', { count })); + } + } + // Speech requests/outcomes get priority over noisy state transitions. + if (windowCount >= (event.startsWith('speech.') ? 200 : 100)) { dropped++; return; } + windowCount++; + sink(record(event, fields)); + } catch { dropped++; /* Observability must never interrupt delivery. */ } +} + +export function observeAlertFocus(): () => void { + if (!alertDiagnosticsEnabled() || typeof window === 'undefined') return () => {}; + const record = (event: Event): void => alertDiagnostic('renderer.focus', { + trigger: event.type, focused: document.hasFocus(), visibility: document.visibilityState, + }); + const events = ['focus', 'blur', 'pageshow', 'pagehide'] as const; + for (const name of events) window.addEventListener(name, record); + document.addEventListener('visibilitychange', record); + record(new Event('initial')); + return () => { + for (const name of events) window.removeEventListener(name, record); + document.removeEventListener('visibilitychange', record); + }; +} diff --git a/lib/src/lib/alert-manager.ts b/lib/src/lib/alert-manager.ts index af4fe9ea..c5e559a7 100644 --- a/lib/src/lib/alert-manager.ts +++ b/lib/src/lib/alert-manager.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic, alertDiagnosticsEnabled, diagnosticId, type DiagnosticFields } from './alert-diagnostics'; import { QuiesceDetector, type QuiesceStatus } from './quiesce-detector'; import type { AlertSettings } from './alert-settings'; import { cfg } from '../cfg'; @@ -209,6 +210,34 @@ interface AlertEntry { /** Portable Session Activity manager. `dispatchCompletion` is the single * observe→claim→ring seam, so await can claim completions before suppression. */ export class AlertManager { + private readonly diagnosticManager = diagnosticId(); + private lastAttentionAt: number | null = null; + + private traceFields(id?: string): DiagnosticFields { + if (!alertDiagnosticsEnabled()) return {}; + const entry = id === undefined ? undefined : this.entries.get(id); + return { + manager: this.diagnosticManager, sessionId: id ?? null, + attentionId: this.attentionId, lastAttentionAt: this.lastAttentionAt, + inactivityTimeoutMs: this.inactivityTimeoutMs, deferAlertsUntilQuiet: this.deferAlertsUntilQuiet, + ...(entry ? { + ...entry.detector.diagnosticSnapshot(), ringSeq: entry.ringSeq, + status: this.getProjectedStatus(entry), watching: this.isWatching(entry), + watchingRing: entry.watchingRingingCommand !== null, outputSinceWatchingRing: entry.outputSinceWatchingRing, + protocol: entry.protocolStatus, commandExit: entry.commandExitStatus, + commandStartedAt: entry.commandExitWatch?.startedAt ?? null, + commandSeenAt: entry.commandExitWatch?.seenWithAttentionAt ?? null, + pendingNotification: entry.deferredNotification?.source ?? null, + todo: entry.todo, attentionDismissedRing: entry.attentionDismissedRing, + } : {}), + }; + } + + private trace(event: string, id?: string, fields: DiagnosticFields = {}): void { + if (!alertDiagnosticsEnabled()) return; + alertDiagnostic(event, { ...this.traceFields(id), ...fields }); + } + private entries = new Map(); /** Blocks late output/resize from recreating a removed entry. Only a semantic * or protocol event proves a reused id belongs to a live replacement. */ @@ -244,6 +273,7 @@ export class AlertManager { setInactivityTimeoutMs(ms: number): void { if (!Number.isFinite(ms) || ms <= 0 || ms === this.inactivityTimeoutMs) return; this.inactivityTimeoutMs = ms; + this.trace('manager.settings'); // Re-arm from now so a shortened window takes effect immediately instead of // waiting out the window that was already running. if (this.attentionTimer !== null && this.attentionId !== null) { @@ -255,6 +285,7 @@ export class AlertManager { setDeferAlertsUntilQuiet(enabled: boolean): void { if (enabled === this.deferAlertsUntilQuiet) return; this.deferAlertsUntilQuiet = enabled; + this.trace('manager.settings'); if (enabled) return; // Turning the gate off releases news it was holding; dropping it would turn @@ -292,6 +323,7 @@ export class AlertManager { } onExit(id: string, exitCode?: number): void { + this.trace('manager.onExit', id); if (this.helpers.has(id)) return; const entry = this.entries.get(id); if (entry && this.finishCommandExitWatch(id, entry, exitCode)) this.notify(id); @@ -302,6 +334,7 @@ export class AlertManager { } onResize(id: string): void { + this.trace('manager.onResize', id); if (this.helpers.has(id)) return; // Same reasoning as `onData`: the resize grace window is part of the // always-on detector, and a Pane's first fit usually beats any PTY event. @@ -362,9 +395,11 @@ export class AlertManager { private createDetector(id: string): QuiesceDetector { return new QuiesceDetector({ + diagnostic: (event, fields) => this.trace(event, id, fields), // Detector state is public only while WATCHING, so only then can a // transition change the projection. onChange: () => { + this.trace('detector.state', id); const entry = this.entries.get(id); if (entry && this.isWatching(entry)) this.notify(id); }, @@ -417,21 +452,33 @@ export class AlertManager { // Snapshot: a claimant may unregister itself (or register another) while // being offered this very event. const claimants = [...(this.claimants.get(id) ?? [])]; - if (claimants.some((claimant) => claimant(event))) return true; + const claimed = claimants.some((claimant) => claimant(event)); + // Decision records carry inputs; manager.publish records the resulting state. + const atDecision = this.traceFields(id); + const traceDecision = (reason: string): void => alertDiagnostic('manager.completion', { + ...atDecision, kind: event.kind, claimed, reason, + ...(event.kind === 'commandFinished' ? { ranMs: event.ranMs, armed: event.armed, exitCode: event.exitCode ?? null } : {}), + ...(event.kind === 'notification' ? { notificationSource: event.notification.source } : {}), + }); + if (claimed) { traceDecision('claimed'); return true; } + let reason = 'eligible'; switch (event.kind) { case 'settled': // Only a watched command rings, and only if the user is not looking at // it right now. The originating command key latches here so the ring // outlives the command that raised it. - if (!this.isWatching(entry) || this.hasAttention(id)) break; + if (!this.isWatching(entry)) { reason = 'not-watched'; break; } + if (this.hasAttention(id)) { reason = 'attended'; break; } this.latchRing(entry, entry.watchingRingingCommand !== null); entry.watchingRingingCommand = entry.commandExitWatch?.argv0 ?? null; entry.outputSinceWatchingRing = false; this.notify(id); break; case 'commandFinished': - if (!event.armed || this.hasAttention(id) || event.ranMs < this.inactivityTimeoutMs) break; + if (!event.armed) { reason = 'not-armed'; break; } + if (this.hasAttention(id)) { reason = 'attended'; break; } + if (event.ranMs < this.inactivityTimeoutMs) { reason = 'short-command'; break; } // A shell-reported exit is authoritative, so recent animation never // delays it. The detector only gates in-band terminal notifications. this.applyCommandExitRinging(entry, event.displayCommand, event.exitCode); @@ -442,6 +489,7 @@ export class AlertManager { break; case 'notification': if (this.hasAttention(id)) { + reason = 'attended'; // A progress cycle was already cleared before dispatch, so publish // that; a plain direct notification changes nothing and dedupes away. this.notify(id); @@ -450,6 +498,7 @@ export class AlertManager { this.deferOrDeliverNotification(id, entry, event.notification); break; } + traceDecision(reason); return false; } @@ -738,6 +787,7 @@ export class AlertManager { applyTerminalSemanticEvents(id: string, events: TerminalSemanticEvent[]): void { if (events.length === 0 || this.helpers.has(id)) return; + for (const event of events) this.trace('manager.semantic', id, { kind: event.type }); const entry = this.reportedEntry(id); let changed = false; @@ -884,12 +934,14 @@ export class AlertManager { && (entry.deferredNotification !== null || entry.detector.isConfirmedBusy()) ) { // Latest wins, matching repeated notifications on an already-ringing track. + this.trace('manager.defer', id, { notificationSource: notification.source }); entry.deferredNotification = notification; this.scheduleDeferredNotification(id, entry); } else { // An existing ring means this is enrichment, not a fresh summons. Cancel // any older pending detail so it cannot overwrite this notification later. this.clearDeferredNotification(entry); + this.trace('manager.deliver', id, { notificationSource: notification.source }); this.applyProtocolRinging(entry, notification); } // The caller may have cleared a publicly visible cycle and delegated the @@ -906,7 +958,10 @@ export class AlertManager { */ private scheduleDeferredNotification(id: string, entry: AlertEntry): void { if (entry.deferredNotificationTimer !== null) clearTimeout(entry.deferredNotificationTimer); + const dueAt = Math.max(Date.now(), entry.detector.quietAt()); + this.trace('manager.deferScheduled', id, { dueAt }); entry.deferredNotificationTimer = setTimeout(() => { + this.trace('manager.deferTimer', id, { dueAt, lateByMs: Date.now() - dueAt }); entry.deferredNotificationTimer = null; if (entry.detector.quietAt() > Date.now()) this.scheduleDeferredNotification(id, entry); else this.flushDeferredNotification(id, entry); @@ -916,6 +971,7 @@ export class AlertManager { private flushDeferredNotification(id: string, entry: AlertEntry): void { const notification = entry.deferredNotification; if (notification === null) return; + this.trace('manager.deferFlush', id, { reason: this.hasAttention(id) ? 'attended' : 'deliver' }); this.clearDeferredNotification(entry); // Attending the Session clears this eagerly too; retain the recheck as the @@ -1004,12 +1060,16 @@ export class AlertManager { private setAttention(id: string): void { const previousAttentionId = this.attentionId; + if (previousAttentionId !== id) this.trace('manager.attention', id, { reason: 'gain' }); + this.lastAttentionAt = Date.now(); if (previousAttentionId && previousAttentionId !== id && this.armCommandExitOnAttentionLoss(previousAttentionId)) { this.notify(previousAttentionId); } this.attentionId = id; this.clearAttentionTimer(); + const dueAt = Date.now() + this.inactivityTimeoutMs; this.attentionTimer = setTimeout(() => { + this.trace('manager.attentionTimer', id, { dueAt, lateByMs: Date.now() - dueAt }); if (this.attentionId === id) { this.attentionId = null; if (this.armCommandExitOnAttentionLoss(id)) { @@ -1023,6 +1083,7 @@ export class AlertManager { attend(id: string): void { if (this.helpers.has(id)) return; const entry = this.getOrCreateEntry(id); + if (this.hasActiveRing(entry) || entry.deferredNotification !== null) this.trace('manager.attend', id); this.setAttention(id); if (this.clearAllRingsIfActive(entry)) { @@ -1036,6 +1097,7 @@ export class AlertManager { clearAttention(id?: string): void { if (id !== undefined && (this.attentionId !== id || this.helpers.has(id))) return; const lostAttentionId = this.attentionId; + this.trace('manager.attention', lostAttentionId ?? undefined, { reason: 'clear', requestedId: id ?? null }); this.attentionId = null; this.clearAttentionTimer(); if (lostAttentionId && this.armCommandExitOnAttentionLoss(lostAttentionId)) { @@ -1046,6 +1108,7 @@ export class AlertManager { // --- Alert controls --- dismissAlert(id: string): void { + this.trace('manager.dismissAlert', id); const entry = this.entries.get(id); if (!entry) return; @@ -1062,6 +1125,7 @@ export class AlertManager { // --- Todo controls --- toggleTodo(id: string): void { + this.trace('manager.toggleTodo', id); if (this.helpers.has(id)) return; const entry = this.getOrCreateEntry(id); entry.todo = !entry.todo; @@ -1071,6 +1135,7 @@ export class AlertManager { } markTodo(id: string): void { + this.trace('manager.markTodo', id); if (this.helpers.has(id)) return; const entry = this.getOrCreateEntry(id); const cleared = this.clearAllRingsIfActive(entry); @@ -1080,6 +1145,7 @@ export class AlertManager { } clearTodo(id: string): void { + this.trace('manager.clearTodo', id); if (this.helpers.has(id)) return; const entry = this.getOrCreateEntry(id); entry.todo = false; @@ -1116,6 +1182,7 @@ export class AlertManager { /** Completely remove alert state for a PTY (used when PTY is destroyed) */ remove(id: string): void { + this.trace('manager.remove', id); this.helpers.delete(id); this.removed.add(id); // Nobody parked here has anything left to wait for. @@ -1142,6 +1209,7 @@ export class AlertManager { * never resurrect a ring or an in-flight progress cycle. */ seed(id: string, state: { todo: unknown; notification?: unknown }): void { + this.trace('manager.seed', id); if (this.helpers.has(id)) return; const entry = this.getOrCreateEntry(id); entry.todo = state.todo === true; @@ -1160,6 +1228,7 @@ export class AlertManager { } dispose(): void { + this.trace('manager.dispose'); // Settled first, while listeners are still attached: a parked caller that // never hears an outcome absorbed a completion it never delivered. for (const id of [...this.awaits.keys()]) this.settleWaiters(id, 'cancelled'); @@ -1241,6 +1310,7 @@ export class AlertManager { const state = this.getState(id); const last = this.lastEmitted.get(id); if (last && alertStatesEqual(last, state)) return; + this.trace('manager.publish', id, { previousStatus: last?.status ?? null, previousRingSeq: last?.ringSeq ?? null }); if (this.entries.has(id)) { this.lastEmitted.set(id, state); } else { diff --git a/lib/src/lib/alert-ring-watch.ts b/lib/src/lib/alert-ring-watch.ts index 18c77965..caedb115 100644 --- a/lib/src/lib/alert-ring-watch.ts +++ b/lib/src/lib/alert-ring-watch.ts @@ -1,7 +1,9 @@ +import { alertDiagnostic, diagnosticId } from './alert-diagnostics'; import { getActivity, getActivitySnapshot, subscribeToActivity } from './session-activity-store'; /** Shared renderer-side fresh-ring→delay→recheck machine for alarm sinks. */ export interface UnattendedRingWatch { + readonly diagnosticSink?: 'speech' | 'push'; /** * Whether this sink is switched on. Read when a ring is scheduled *and* * again when the timer fires, so toggling the setting mid-delay drops the @@ -19,14 +21,20 @@ export interface UnattendedRingWatch { * that cancels everything pending. */ export function watchUnattendedRings(watch: UnattendedRingWatch): () => void { + const watcher = diagnosticId(); + const trace = (event: string, id?: string, extra = {}): void => alertDiagnostic(event, { + watcher, sink: watch.diagnosticSink ?? 'push', sessionId: id ?? null, ...extra, + }); + trace('watch.start', undefined, { enabled: watch.enabled(), delayMs: watch.delayMs() }); // Absence means never observed, so restore/reconnect cannot turn an existing // ring into a fresh transition. const lastStatus = new Map(); const pending = new Map>(); - const cancel = (id: string): void => { + const cancel = (id: string, reason: string): void => { const timer = pending.get(id); if (timer === undefined) return; + trace('watch.cancel', id, { reason }); clearTimeout(timer); pending.delete(id); }; @@ -40,29 +48,38 @@ export function watchUnattendedRings(watch: UnattendedRingWatch): () => void { if (state.status !== 'ALERT_RINGING') { // Attended, dismissed, or never ringing — either way nothing to do. - cancel(id); + cancel(id, 'resolved'); continue; } // Already ringing, or seen for the first time already ringing. - if (previous === 'ALERT_RINGING' || previous === undefined) continue; + if (previous === 'ALERT_RINGING' || previous === undefined) { + if (previous === undefined) trace('watch.skip', id, { reason: 'existing-ring', ringSeq: state.ringSeq }); + continue; + } - if (!watch.enabled()) continue; + if (!watch.enabled()) { trace('watch.skip', id, { reason: 'disabled', ringSeq: state.ringSeq }); continue; } + const delayMs = watch.delayMs(); + const dueAt = Date.now() + delayMs; + trace('watch.schedule', id, { dueAt, delayMs, ringSeq: state.ringSeq }); pending.set(id, setTimeout(() => { pending.delete(id); // Re-read rather than trusting the closure: the user may have attended // or dismissed during the delay, and the setting may have been toggled. - if (getActivity(id).status !== 'ALERT_RINGING') return; - if (!watch.enabled()) return; + const status = getActivity(id).status; + const enabled = watch.enabled(); + trace('watch.timer', id, { dueAt, lateByMs: Date.now() - dueAt, status, enabled, ringSeq: getActivity(id).ringSeq, scheduledRingSeq: state.ringSeq }); + if (status !== 'ALERT_RINGING') return; + if (!enabled) return; watch.fire(id); - }, watch.delayMs())); + }, delayMs)); } // A Session that left the store entirely (pane killed) must not fire. for (const id of [...lastStatus.keys()]) { if (snapshot.has(id)) continue; lastStatus.delete(id); - cancel(id); + cancel(id, 'removed'); } }; @@ -72,7 +89,8 @@ export function watchUnattendedRings(watch: UnattendedRingWatch): () => void { return () => { unsubscribe(); - for (const timer of pending.values()) clearTimeout(timer); + trace('watch.stop'); + for (const id of pending.keys()) cancel(id, 'dispose'); pending.clear(); lastStatus.clear(); }; diff --git a/lib/src/lib/alert-settings.ts b/lib/src/lib/alert-settings.ts index 46d4cd37..1688ddef 100644 --- a/lib/src/lib/alert-settings.ts +++ b/lib/src/lib/alert-settings.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic } from './alert-diagnostics'; import { cfg } from '../cfg'; import { loadJson, saveJson } from './local-json-store'; import { getPlatform } from './platform'; @@ -104,6 +105,7 @@ export function updateAlertSettings(patch: Partial): void { const next = normalizeAlertSettings({ ...settings, ...patch }); if (alertSettingsEqual(next, settings)) return; settings = next; + alertDiagnostic('renderer.settings', { speakEnabled: settings.speakEnabled, speakDelayMs: settings.speakDelayMs, deferAlertsUntilQuiet: settings.deferAlertsUntilQuiet, inactivityTimeoutMs: settings.inactivityTimeoutMs }); saveJson(STORAGE_KEY, settings); getPlatform().alertPublishSettings(settings, { seed: false }); listeners.forEach((listener) => listener()); @@ -114,6 +116,7 @@ export function applyAlertSettingsFromHost(value: unknown): void { const next = normalizeAlertSettings(value); if (alertSettingsEqual(next, settings)) return; settings = next; + alertDiagnostic('renderer.settings', { speakEnabled: settings.speakEnabled, speakDelayMs: settings.speakDelayMs, deferAlertsUntilQuiet: settings.deferAlertsUntilQuiet, inactivityTimeoutMs: settings.inactivityTimeoutMs }); saveJson(STORAGE_KEY, settings); listeners.forEach((listener) => listener()); } diff --git a/lib/src/lib/alert-speech.test.ts b/lib/src/lib/alert-speech.test.ts index ca566689..071baa14 100644 --- a/lib/src/lib/alert-speech.test.ts +++ b/lib/src/lib/alert-speech.test.ts @@ -1,10 +1,12 @@ +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; vi.mock('./platform', () => ({ getPlatform: () => ({ alertPublishSettings: vi.fn() }), })); -import { startAlertSpeech, toSpokenText } from './alert-speech'; +import { configureAlertDiagnostics, type AlertDiagnostic } from './alert-diagnostics'; +import { startAlertSpeech, speakTestUtterance, toSpokenText } from './alert-speech'; import { getAlertSpeechState } from './alert-speech-state'; import { applyAlertSettingsFromHost, DEFAULT_ALERT_SETTINGS } from './alert-settings'; import { clearTerminalActivity, setTerminalActivity } from './session-activity-store'; @@ -15,6 +17,7 @@ import type { TerminalTitleSource } from './terminal-state'; const SPEAK_DELAY_MS = 10_000; /** Utterances passed to the stubbed Web Speech API, in order. */ +let records: AlertDiagnostic[]; let spoken: string[]; let utterances: StubUtterance[]; let cancelCount: number; @@ -81,8 +84,11 @@ function ringTwoWithFirstSpeaking(): void { } beforeEach(() => { + alertDiagnosticsConfig.enabled = true; vi.useFakeTimers(); stubSpeechSynthesis(); + records = []; + configureAlertDiagnostics('test', (record) => records.push(record)); clearTerminalActivity(); applyAlertSettingsFromHost({ ...DEFAULT_ALERT_SETTINGS, speakEnabled: true, speakDelayMs: SPEAK_DELAY_MS }); }); @@ -93,6 +99,8 @@ afterEach(() => { for (const id of ['osc0-title', 'osc2-title', 'osc9-title']) removeTerminalPaneState(id); clearTerminalActivity(); applyAlertSettingsFromHost(DEFAULT_ALERT_SETTINGS); + configureAlertDiagnostics('off'); + alertDiagnosticsConfig.enabled = false; vi.useRealTimers(); vi.unstubAllGlobals(); }); @@ -484,3 +492,68 @@ describe('spoken alarms', () => { expect(spoken).toHaveLength(20 + 7); }); }); + + +describe('speech diagnostics', () => { + it('records exactly the sanitized payload and counts at the synthesis boundary', () => { + resetTerminalPaneState('osc0-title', { + activity: { kind: 'running' }, + currentCommand: { id: 'cmd', rawCommandLine: 'sleep 60', displayCommand: 'sleep 60', cwdAtStart: null, startedAt: 10, source: 'osc133_boundaries' }, + titleCandidates: { osc0: { title: 'Done 0123456789abcdef0123456789abcdef', source: 'osc0', updatedAt: 20 } }, + }); + start(); + ring('osc0-title'); + vi.advanceTimersByTime(SPEAK_DELAY_MS); + const request = records.find((r) => r.event === 'speech.request')!; + expect(request.fields.text).toBe('Done REDACTED'); + expect(request.fields.text).toBe(spoken[0]); + expect(request.fields.characters).toBe(Array.from(spoken[0]).length); + expect(JSON.stringify(records)).not.toContain('0123456789abcdef'); + }); + + it('distinguishes an old engine queue entry starting after dismissal from a new ring', () => { + start(); + ring('pty-1'); + vi.advanceTimersByTime(SPEAK_DELAY_MS); + setStatus('pty-1', 'NOTHING_TO_SHOW'); + vi.advanceTimersByTime(3_600_000); + utterances[0].onstart?.(); + const requests = records.filter((r) => r.event === 'speech.request'); + const started = records.find((r) => r.event === 'speech.start')!; + expect(requests).toHaveLength(1); + expect(started.fields).toMatchObject({ + attempt: requests[0].fields.attempt, sinceRequestMs: 3_600_000, liveStatus: 'NOTHING_TO_SHOW', + }); + }); + + it('gives queue retries distinct attempts and a separate reason', () => { + ringTwoWithFirstSpeaking(); + setStatus('pty-1', 'NOTHING_TO_SHOW'); + const requests = records.filter((r) => r.event === 'speech.request'); + expect(requests.map((r) => r.fields.reason)).toEqual(['ring', 'ring', 'requeue']); + expect(new Set(requests.map((r) => r.fields.attempt)).size).toBe(3); + expect(records.find((r) => r.event === 'speech.cancel')?.fields.reason).toBe('resolved-speaking-ring'); + }); + + it('records a suspended ring timer deadline separately from the speech queue', () => { + start(); + const timers = vi.spyOn(globalThis, 'setTimeout'); + try { + ring('pty-1'); + const callback = timers.mock.calls.at(-1)![0] as () => void; + const scheduledAt = Date.now(); + vi.setSystemTime(scheduledAt + 3_600_000); + callback(); + const fired = records.find((r) => r.event === 'watch.timer')!; + expect(fired.fields).toMatchObject({ dueAt: scheduledAt + SPEAK_DELAY_MS, lateByMs: 3_600_000 - SPEAK_DELAY_MS }); + expect(records.find((r) => r.event === 'speech.request')?.fields.sinceRequestMs).toBe(0); + } finally { timers.mockRestore(); } + }); + + it('counts test requests even when the backend is unavailable', () => { + vi.stubGlobal('speechSynthesis', undefined); + expect(speakTestUtterance()).toBe(false); + expect(records.find((r) => r.event === 'speech.request')?.fields).toMatchObject({ reason: 'test', characters: 19 }); + expect(records.some((r) => r.event === 'speech.unavailable')).toBe(true); + }); +}); diff --git a/lib/src/lib/alert-speech.ts b/lib/src/lib/alert-speech.ts index 8752d6e5..ba97d72a 100644 --- a/lib/src/lib/alert-speech.ts +++ b/lib/src/lib/alert-speech.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic, diagnosticId, type DiagnosticFields } from './alert-diagnostics'; import { getAlertSettings } from './alert-settings'; import { watchUnattendedRings } from './alert-ring-watch'; import { @@ -51,34 +52,58 @@ interface SpeechLifecycle { /** Dispatch after tracking is installed; engines may synchronously start and * settle inside `synth.speak()`. */ -function speak(text: string, lifecycle: SpeechLifecycle): void { +function speak(text: string, lifecycle: SpeechLifecycle | undefined, context: DiagnosticFields): boolean { + const spokenText = toSpokenText(text); + const attempt = diagnosticId(); + const requestedAt = Date.now(); + const trace = (event: string, extra: DiagnosticFields = {}): void => alertDiagnostic(event, { + ...context, attempt, sinceRequestMs: Date.now() - requestedAt, + ...(typeof context.sessionId === 'string' ? { + liveStatus: getActivity(context.sessionId).status, + liveRingSeq: getActivity(context.sessionId).ringSeq, + } : {}), + ...extra, + }); + trace('speech.request', { text: spokenText, characters: Array.from(spokenText).length, utf16Units: spokenText.length }); const synth = globalThis.speechSynthesis; // Absent in jsdom and in webviews with no speech backend — staying silent is // the correct degradation, not an error. - if (!synth || typeof globalThis.SpeechSynthesisUtterance !== 'function') return; + if (!synth || typeof globalThis.SpeechSynthesisUtterance !== 'function') { + trace('speech.unavailable'); + return false; + } let utterance: SpeechSynthesisUtterance; try { - utterance = new globalThis.SpeechSynthesisUtterance(toSpokenText(text)); + utterance = new globalThis.SpeechSynthesisUtterance(spokenText); } catch { // A speech engine that refuses the utterance must never break the alert path. - return; + trace('speech.refused', { stage: 'construct' }); + return false; } - utterance.onstart = () => lifecycle.onStart(utterance); - utterance.onend = () => lifecycle.onSettle(utterance); - utterance.onerror = () => lifecycle.onSettle(utterance); - lifecycle.onQueued(utterance); + utterance.onstart = () => { trace('speech.start'); lifecycle?.onStart(utterance); }; + utterance.onend = () => { trace('speech.end'); lifecycle?.onSettle(utterance); }; + utterance.onerror = (event) => { + trace('speech.error', { error: event?.error ?? 'unknown' }); + lifecycle?.onSettle(utterance); + }; + trace('speech.queue'); + lifecycle?.onQueued(utterance); try { synth.speak(utterance); } catch { // Settle a refused dispatch rather than leaving the Session pinned at // `speaking` behind an utterance no callback will ever retire. - lifecycle.onSettle(utterance); + trace('speech.refused', { stage: 'dispatch' }); + lifecycle?.onSettle(utterance); + return false; } + return true; } /** Silence the engine, dropping everything it is holding. */ -function cancelSpeech(): void { +function cancelSpeech(reason: string): void { + alertDiagnostic('speech.cancel', { reason, scope: 'engine-queue' }); globalThis.speechSynthesis?.cancel(); } @@ -88,23 +113,7 @@ const TEST_UTTERANCE = 'Dormouse alarm test'; /** Play the Settings test without publishing Session delivery state; false means * this webview has no speech backend. */ export function speakTestUtterance(): boolean { - const synth = globalThis.speechSynthesis; - if (!synth || typeof globalThis.SpeechSynthesisUtterance !== 'function') return false; - - let utterance: SpeechSynthesisUtterance; - try { - utterance = new globalThis.SpeechSynthesisUtterance(toSpokenText(TEST_UTTERANCE)); - } catch { - return false; - } - try { - // Do not cancel the shared engine queue: only `interrupt` can re-dispatch - // queued real alarms whose callbacks cancellation may drop. - synth.speak(utterance); - } catch { - return false; - } - return true; + return speak(TEST_UTTERANCE, undefined, { reason: 'test', sessionId: null, ringSeq: null }); } /** @@ -113,6 +122,7 @@ export function speakTestUtterance(): boolean { * detaches delivery callbacks from utterances already handed to it. */ export function startAlertSpeech(): () => void { + alertDiagnostic('speech.mount'); // A callback from an old or already-attended utterance must not overwrite the // state of a newer ring for the same Session. The opaque token makes every // utterance generation distinct without exposing engine objects to the store. @@ -176,7 +186,7 @@ export function startAlertSpeech(): () => void { } }; - const fireSpeech = (sessionId: string): void => { + const fireSpeech = (sessionId: string, reason = 'ring'): void => { const token = {}; speak(deriveSessionLabel(sessionId), { onQueued: (utterance) => { @@ -198,7 +208,7 @@ export function startAlertSpeech(): () => void { setAlertSpeechState(sessionId, 'speaking'); }, onSettle: (utterance) => settle(sessionId, token, utterance), - }); + }, { sessionId, ringSeq: getActivity(sessionId).ringSeq, reason }); }; /** Stop resolved speech. Web Speech cancels the whole queue, so re-dispatch @@ -217,11 +227,12 @@ export function startAlertSpeech(): () => void { if (speakable && activity.get(sessionId)?.status === 'ALERT_RINGING') requeue.push(sessionId); } queued.clear(); - cancelSpeech(); - for (const sessionId of requeue) fireSpeech(sessionId); + cancelSpeech('resolved-speaking-ring'); + for (const sessionId of requeue) fireSpeech(sessionId, 'requeue'); }; const stopRingWatch = watchUnattendedRings({ + diagnosticSink: 'speech', enabled: () => getAlertSettings().speakEnabled, delayMs: () => getAlertSettings().speakDelayMs, fire: fireSpeech, @@ -279,7 +290,7 @@ export function startAlertSpeech(): () => void { // teardown; the engine still owns its queue. Without this, a webview that // unmounts mid-alarm keeps reading Pane names aloud with no visible source // and no UI left to stop it. - cancelSpeech(); + cancelSpeech('dispose'); clearAllAlertSpeechStates(); }; } diff --git a/lib/src/lib/platform/index.ts b/lib/src/lib/platform/index.ts index 14b56a94..f5c5ab61 100644 --- a/lib/src/lib/platform/index.ts +++ b/lib/src/lib/platform/index.ts @@ -1,3 +1,4 @@ +import { configureAlertDiagnostics, observeAlertFocus } from '../alert-diagnostics'; import type { PlatformAdapter } from './types'; import { VSCodeAdapter } from './vscode-adapter'; import { FakePtyAdapter } from './fake-adapter'; @@ -40,10 +41,14 @@ export const IS_MAC: boolean = /Mac|iPhone|iPad/i.test(PLATFORM_STRING); export const IS_WINDOWS: boolean = /Win/i.test(PLATFORM_STRING); let adapter: PlatformAdapter | null = null; +let stopFocusDiagnostics: (() => void) | undefined; /** Set an externally-created platform adapter (e.g. TauriAdapter from standalone). */ export function setPlatform(a: PlatformAdapter): void { + stopFocusDiagnostics?.(); adapter = a; + configureAlertDiagnostics('renderer', a.recordAlertDiagnostic?.bind(a)); + stopFocusDiagnostics = a.recordAlertDiagnostic ? observeAlertFocus() : undefined; } export function getPlatform(): PlatformAdapter { @@ -63,13 +68,14 @@ export function initPlatform(): PlatformAdapter; export function initPlatform(override?: 'fake'): PlatformAdapter { if (adapter) return adapter as PlatformAdapter; if (override === 'fake') { - adapter = new FakePtyAdapter(); - return adapter; + const fake = new FakePtyAdapter(); + setPlatform(fake); + return fake; } if (typeof acquireVsCodeApi === 'function') { - adapter = new VSCodeAdapter(); + setPlatform(new VSCodeAdapter()); } else { - adapter = new FakePtyAdapter(); + setPlatform(new FakePtyAdapter()); } - return adapter; + return adapter!; } diff --git a/lib/src/lib/platform/types.ts b/lib/src/lib/platform/types.ts index 9476be67..4881d4b9 100644 --- a/lib/src/lib/platform/types.ts +++ b/lib/src/lib/platform/types.ts @@ -1,3 +1,4 @@ +import type { AlertDiagnostic } from '../alert-diagnostics'; import type { HelperIdentity, TerminalContextRequest, TerminalContextInfo } from '../terminal-context-types'; import type { AlertState, AwaitHandle, AwaitOptions } from '../alert-manager'; import type { AlertSettings } from '../alert-settings'; @@ -174,6 +175,8 @@ export interface PtyDataDetail { } export interface PlatformAdapter { + /** Desktop-only local diagnostic journal; absent on Pocket and the demo. */ + recordAlertDiagnostic?(record: AlertDiagnostic): void; // Lifecycle init(): Promise; shutdown(): void; diff --git a/lib/src/lib/platform/vscode-adapter.ts b/lib/src/lib/platform/vscode-adapter.ts index 00fbf031..dbc5cebb 100644 --- a/lib/src/lib/platform/vscode-adapter.ts +++ b/lib/src/lib/platform/vscode-adapter.ts @@ -1,3 +1,4 @@ +import type { AlertDiagnostic } from '../alert-diagnostics'; import type { HelperIdentity, TerminalContextRequest, TerminalContextInfo } from '../terminal-context-types'; import type { AgentBrowserCommandResult, AgentBrowserEditOp, AgentBrowserEditResult, AgentBrowserOpenResult, AgentBrowserPopResult, AgentBrowserScreenshotResult, AgentBrowserStreamStatusResult, AlertStateDetail, IframeProxyResult, OpenPort, PlatformAdapter, PtyDataDetail, PtyInfo, BurrowLink } from './types'; import { OPEN_PORT_TIMEOUT_MS } from './types'; @@ -115,6 +116,10 @@ export class VSCodeAdapter implements PlatformAdapter { }, }; + recordAlertDiagnostic(record: AlertDiagnostic): void { + this.vscode.postMessage({ type: 'alert:diagnostic', record }); + } + constructor() { this.vscode = acquireVsCodeApi(); diff --git a/lib/src/lib/quiesce-detector.ts b/lib/src/lib/quiesce-detector.ts index b6f21568..95759baf 100644 --- a/lib/src/lib/quiesce-detector.ts +++ b/lib/src/lib/quiesce-detector.ts @@ -1,3 +1,4 @@ +import type { DiagnosticFields } from './alert-diagnostics'; import { cfg } from '../cfg'; /** @@ -11,6 +12,7 @@ export type QuiesceStatus = | 'MIGHT_NEED_ATTENTION'; export interface QuiesceDetectorOptions { + diagnostic?: (event: string, fields: DiagnosticFields) => void; onChange?: (status: QuiesceStatus) => void; /** * A busy Session stayed quiet long enough to look finished. Fired once per @@ -38,6 +40,10 @@ const QUIESCE_AFTER_OUTPUT_MS = T_MIGHT_NEED_ATTENTION + T_SETTLED_CONFIRM; * `onSettled` and the detector immediately starts over. */ export class QuiesceDetector { + private outputChunks = 0; + private ignoredResizeChunks = 0; + private lastReceivedOutputAt: number | null = null; + private readonly diagnostic?: QuiesceDetectorOptions['diagnostic']; private status: QuiesceStatus = 'NOTHING_TO_SHOW'; private resizeGrace = false; private busyCandidateTimer: ReturnType | null = null; @@ -60,10 +66,28 @@ export class QuiesceDetector { private readonly onSettled: (() => void) | null; constructor(options?: QuiesceDetectorOptions) { + this.diagnostic = options?.diagnostic; this.onChange = options?.onChange ?? null; this.onSettled = options?.onSettled ?? null; } + diagnosticSnapshot(): DiagnosticFields { + return { + detector: this.status, outputChunks: this.outputChunks, + ignoredResizeChunks: this.ignoredResizeChunks, lastReceivedOutputAt: this.lastReceivedOutputAt, + lastAcceptedOutputAt: this.lastAcceptedOutputAt, resizeGrace: this.resizeGrace, + quietDueAt: this.lastAcceptedOutputAt === null ? null : this.quietAt(), + }; + } + + private timer(name: string, callback: () => void, delay: number): ReturnType { + const dueAt = Date.now() + delay; + return setTimeout(() => { + this.diagnostic?.('detector.timer', { timer: name, dueAt, lateByMs: Date.now() - dueAt }); + callback(); + }, delay); + } + getStatus(): QuiesceStatus { return this.status; } @@ -86,13 +110,17 @@ export class QuiesceDetector { * history. The `quietAt` clock is not history and survives (see above). */ reset(): void { if (this.disposed) return; + this.diagnostic?.('detector.reset', this.diagnosticSnapshot()); this.clearActivityTimers(); this.resetOutputTracking(); this.setStatus('NOTHING_TO_SHOW'); } onData(): void { - if (this.disposed || this.resizeGrace) return; + if (this.disposed) return; + this.outputChunks++; + this.lastReceivedOutputAt = Date.now(); + if (this.resizeGrace) { this.ignoredResizeChunks++; return; } const now = Date.now(); this.lastOutputAt = now; @@ -118,7 +146,7 @@ export class QuiesceDetector { if (this.disposed) return; this.resizeGrace = true; if (this.resizeTimer !== null) clearTimeout(this.resizeTimer); - this.resizeTimer = setTimeout(() => { + this.resizeTimer = this.timer('resize', () => { this.resizeGrace = false; this.resizeTimer = null; }, T_RESIZE_DEBOUNCE); @@ -151,7 +179,7 @@ export class QuiesceDetector { private enterMightBeBusy(): void { this.clearActivityTimers(); this.setStatus('MIGHT_BE_BUSY'); - this.busyConfirmTimer = setTimeout(() => { + this.busyConfirmTimer = this.timer('busyConfirm', () => { this.busyConfirmTimer = null; if (this.status !== 'MIGHT_BE_BUSY') return; this.seedFromLatestOutput(); @@ -168,7 +196,7 @@ export class QuiesceDetector { private startBusyCandidateTimer(): void { if (this.busyCandidateTimer !== null) return; - this.busyCandidateTimer = setTimeout(() => { + this.busyCandidateTimer = this.timer('busyCandidate', () => { this.busyCandidateTimer = null; if (this.status !== 'NOTHING_TO_SHOW') return; if (this.outputCountSinceReset >= 2) { @@ -181,7 +209,7 @@ export class QuiesceDetector { if (this.mightNeedAttentionTimer !== null) { clearTimeout(this.mightNeedAttentionTimer); } - this.mightNeedAttentionTimer = setTimeout(() => { + this.mightNeedAttentionTimer = this.timer('mightNeedAttention', () => { this.mightNeedAttentionTimer = null; if (this.status !== 'BUSY') return; this.setStatus('MIGHT_NEED_ATTENTION'); @@ -190,7 +218,7 @@ export class QuiesceDetector { } private startSettledConfirmTimer(): void { - this.settledConfirmTimer = setTimeout(() => { + this.settledConfirmTimer = this.timer('settledConfirm', () => { this.settledConfirmTimer = null; if (this.status !== 'MIGHT_NEED_ATTENTION') return; this.resetOutputTracking(); diff --git a/lib/src/lib/session-activity-store.ts b/lib/src/lib/session-activity-store.ts index 5b1a8d86..cd9901ac 100644 --- a/lib/src/lib/session-activity-store.ts +++ b/lib/src/lib/session-activity-store.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic, alertDiagnosticsEnabled } from './alert-diagnostics'; import type { AlertState, SessionStatus } from './alert-manager'; import type { AlertStateDetail } from './platform/types'; import { applyAlertSettingsFromHost, publishAlertSettings } from './alert-settings'; @@ -82,6 +83,13 @@ export function getLivePersistedAlertState(id: string): PersistedAlertState | nu /** Install a host snapshot, including one received before xterm initialization. */ export function setTerminalActivity(id: string, state: Partial): void { + if (alertDiagnosticsEnabled()) { + const previous = terminalActivity.get(id)?.state; + alertDiagnostic('renderer.snapshot', { + sessionId: id, previousStatus: previous?.status ?? null, previousRingSeq: previous?.ringSeq ?? null, + status: state.status ?? null, ringSeq: state.ringSeq ?? null, + }); + } const { attentionDismissedRing = false, ...activity } = state; terminalActivity.set(id, { state: { ...DEFAULT_ACTIVITY_STATE, ...activity }, @@ -92,6 +100,7 @@ export function setTerminalActivity(id: string, state: Partial): voi /** Called after registry removal, or without an id to reset the terminal cache. */ export function clearTerminalActivity(id?: string): void { + alertDiagnostic('renderer.clear', { sessionId: id ?? null }); if (id === undefined) { if (terminalActivity.size === 0) return; terminalActivity.clear(); diff --git a/package.json b/package.json index 904f8071..857d0e7f 100644 --- a/package.json +++ b/package.json @@ -12,7 +12,7 @@ }, "scripts": { "build": "pnpm run build:vscode && pnpm --filter dormouse-lib build:pocket && pnpm --filter dormouse-website build", - "test": "node scripts/spec-lint.mjs && node scripts/spec-lint-selftest.mjs && node scripts/public-docs-lint.mjs && node scripts/xterm-lint.mjs && node --test scripts/xterm-bump.test.mjs && node scripts/loopback-lint.mjs && node scripts/loopback-lint-selftest.mjs && node scripts/deploy-lint.mjs && node scripts/deploy-lint-selftest.mjs && node scripts/installer-verify-test.mjs && node scripts/ps1-cmdlet-lint.mjs && node scripts/ps1-cmdlet-lint-selftest.mjs && node scripts/e2e-lint.mjs && node scripts/e2e-lint-selftest.mjs && node scripts/clamp-issue-body-selftest.mjs && node --test scripts/sign-and-deploy.test.mjs && node --test scripts/workflow-audit.test.mjs && node --test scripts/security-audit.test.mjs && pnpm -r run test", + "test": "node scripts/spec-lint.mjs && node scripts/spec-lint-selftest.mjs && node scripts/public-docs-lint.mjs && node scripts/xterm-lint.mjs && node --test scripts/summarize-alert-log.test.mjs scripts/xterm-bump.test.mjs && node scripts/loopback-lint.mjs && node scripts/loopback-lint-selftest.mjs && node scripts/deploy-lint.mjs && node scripts/deploy-lint-selftest.mjs && node scripts/installer-verify-test.mjs && node scripts/ps1-cmdlet-lint.mjs && node scripts/ps1-cmdlet-lint-selftest.mjs && node scripts/e2e-lint.mjs && node scripts/e2e-lint-selftest.mjs && node scripts/clamp-issue-body-selftest.mjs && node --test scripts/sign-and-deploy.test.mjs && node --test scripts/workflow-audit.test.mjs && node --test scripts/security-audit.test.mjs && pnpm -r run test", "lint:specs": "node scripts/spec-lint.mjs && node scripts/spec-lint-selftest.mjs", "lint:public-docs": "node scripts/public-docs-lint.mjs", "audit:prose": "node scripts/prose-audit.mjs", diff --git a/scripts/spec-word-budgets.json b/scripts/spec-word-budgets.json index 2c3ccbe5..cf641165 100644 --- a/scripts/spec-word-budgets.json +++ b/scripts/spec-word-budgets.json @@ -2,7 +2,7 @@ "AGENTS.md": 3250, "SECURITY.md": 200, "SELF_HOST.md": 6000, - "docs/specs/alert.md": 6600, + "docs/specs/alert.md": 7100, "docs/specs/auto-update.md": 1000, "docs/specs/deploy.md": 1900, "docs/specs/dor-browser.md": 4500, @@ -19,12 +19,12 @@ "docs/specs/remote-security-model.md": 4200, "docs/specs/security-audit.md": 1750, "docs/specs/security-ci.md": 2500, - "docs/specs/security-local.md": 2550, + "docs/specs/security-local.md": 2600, "docs/specs/security-remote.md": 4900, "docs/specs/security-supply-chain.md": 1150, "docs/specs/security.md": 1900, "docs/specs/shortcuts.md": 1000, - "docs/specs/standalone.md": 4300, + "docs/specs/standalone.md": 4350, "docs/specs/terminal-context.md": 900, "docs/specs/terminal-escapes.md": 3750, "docs/specs/terminal-state.md": 2300, @@ -32,7 +32,7 @@ "docs/specs/tiling-engine.md": 4500, "docs/specs/transport.md": 4350, "docs/specs/tutorial.md": 1900, - "docs/specs/vscode.md": 7350, + "docs/specs/vscode.md": 7400, "docs/specs/webgl-text.md": 1200, "docs/specs/website-docs.md": 5050 } diff --git a/scripts/summarize-alert-log.mjs b/scripts/summarize-alert-log.mjs new file mode 100644 index 00000000..11921338 --- /dev/null +++ b/scripts/summarize-alert-log.mjs @@ -0,0 +1,72 @@ +#!/usr/bin/env node +// Usage: node scripts/summarize-alert-log.mjs +import { createReadStream } from 'node:fs'; +import { readdir } from 'node:fs/promises'; +import { join, resolve } from 'node:path'; +import { createInterface } from 'node:readline'; +import { pathToFileURL } from 'node:url'; + +export async function summarizeAlertLogs(directory) { + const attempts = new Map(); + const sources = new Set(); + let firstAt = Infinity; + let lastAt = -Infinity; + let droppedRecords = 0; + let malformedLines = 0; + const files = (await readdir(directory)).filter((name) => /^alerts-.*\.jsonl$/.test(name)).sort(); + for (const name of files) { + const lines = createInterface({ input: createReadStream(join(directory, name)), crlfDelay: Infinity }); + for await (const line of lines) { + let record; + try { record = JSON.parse(line); } catch { malformedLines++; continue; } + if (!record || record.version !== 1 || !Number.isFinite(record.at) || typeof record.event !== 'string' + || !record.fields || typeof record.fields !== 'object') { malformedLines++; continue; } + firstAt = Math.min(firstAt, record.at); + lastAt = Math.max(lastAt, record.at); + if (typeof record.source === 'string' && !record.source.startsWith('journal:')) sources.add(record.source); + if (record.event.endsWith('.dropped')) droppedRecords += record.fields.count || 0; + if (!record.event.startsWith('speech.') || !record.fields.attempt || !record.source) continue; + const key = `${record.source}/${record.fields.attempt}`; + const attempt = attempts.get(key) ?? { events: new Set() }; + attempt.events.add(record.event); + if (record.event === 'speech.request') attempt.request = record; + attempts.set(key, attempt); + } + } + const days = new Map(); + for (const { request, events } of attempts.values()) { + if (!request) continue; // Request may have aged out of retention. + const date = new Date(request.at).toISOString().slice(0, 10); + const day = days.get(date) ?? { + date, ringRequests: 0, ringCharacters: 0, requeues: 0, requeueCharacters: 0, + tests: 0, testCharacters: 0, started: 0, ended: 0, failed: 0, withoutOutcome: 0, + }; + const { reason, characters } = request.fields; + if (!Number.isSafeInteger(characters) || characters < 0) { malformedLines++; continue; } + if (reason === 'ring') { day.ringRequests++; day.ringCharacters += characters; } + if (reason === 'requeue') { day.requeues++; day.requeueCharacters += characters; } + if (reason === 'test') { day.tests++; day.testCharacters += characters; } + if (events.has('speech.start')) day.started++; + if (events.has('speech.end')) day.ended++; + const failed = ['speech.error', 'speech.refused', 'speech.unavailable'].some((event) => events.has(event)); + if (failed) day.failed++; + if (!failed && !events.has('speech.end')) day.withoutOutcome++; + days.set(date, day); + } + return { + note: 'Observed local requests, not billable ElevenLabs usage. Missing callbacks do not prove silence. Retention, shutdown, and dropped records can make totals incomplete.', + files: files.length, sources: sources.size, droppedRecords, malformedLines, + firstRecordAt: Number.isFinite(firstAt) ? new Date(firstAt).toISOString() : null, + lastRecordAt: Number.isFinite(lastAt) ? new Date(lastAt).toISOString() : null, + days: [...days.values()].sort((a, b) => a.date.localeCompare(b.date)), + }; +} + +if (process.argv[1] && import.meta.url === pathToFileURL(resolve(process.argv[1])).href) { + if (!process.argv[2]) { + console.error('Usage: node scripts/summarize-alert-log.mjs '); + process.exitCode = 1; + } else { + console.log(JSON.stringify(await summarizeAlertLogs(process.argv[2]), null, 2)); + } +} diff --git a/scripts/summarize-alert-log.test.mjs b/scripts/summarize-alert-log.test.mjs new file mode 100644 index 00000000..d941791a --- /dev/null +++ b/scripts/summarize-alert-log.test.mjs @@ -0,0 +1,28 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { mkdtemp, rm, writeFile } from 'node:fs/promises'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { summarizeAlertLogs } from './summarize-alert-log.mjs'; + +test('separates initial speech, retries, tests, outcomes, and incomplete data', async () => { + const dir = await mkdtemp(join(tmpdir(), 'alert-summary-')); + const event = (event, attempt, extra = {}) => ({ version: 1, at: Date.UTC(2026, 8, 6), source: 'a', event, fields: { attempt, ...extra } }); + try { + await writeFile(join(dir, 'alerts-1.jsonl'), [ + event('speech.request', '1', { reason: 'ring', characters: 12 }), + event('speech.start', '1'), event('speech.end', '1'), + event('speech.request', '2', { reason: 'requeue', characters: 12 }), + event('speech.request', '3', { reason: 'test', characters: 19 }), + event('speech.unavailable', '3'), + { ...event('journal.dropped', null, { count: 4 }), source: 'journal:writer' }, + ].map(JSON.stringify).join('\n') + '\n{"truncated":'); + const summary = await summarizeAlertLogs(dir); + assert.equal(summary.droppedRecords, 4); + assert.equal(summary.sources, 1); + assert.equal(summary.malformedLines, 1); + assert.deepEqual(summary.days, [{ date: '2026-09-06', ringRequests: 1, ringCharacters: 12, + requeues: 1, requeueCharacters: 12, tests: 1, testCharacters: 19, + started: 1, ended: 1, failed: 1, withoutOutcome: 1 }]); + } finally { await rm(dir, { recursive: true, force: true }); } +}); diff --git a/standalone/scripts/build-sidecar-proxy.mjs b/standalone/scripts/build-sidecar-proxy.mjs index 8b86f2b4..dfab95e1 100644 --- a/standalone/scripts/build-sidecar-proxy.mjs +++ b/standalone/scripts/build-sidecar-proxy.mjs @@ -1,6 +1,7 @@ // Bundle the host-agnostic host modules (shared with the VS Code extension host) // into CommonJS files the Node sidecar can require. Keeps each as a single // TypeScript source while the sidecar itself stays plain CJS. +// - lib/src/host/alert-journal.ts → sidecar/alert-journal.cjs // - lib/src/host/iframe-proxy.ts → sidecar/iframe-proxy.cjs // - lib/src/host/agent-browser-host.ts → sidecar/agent-browser-host.cjs // - lib/src/host/remote/sidecar-entry.ts → sidecar/burrow.cjs @@ -24,6 +25,7 @@ const sidecar = path.resolve(here, '../sidecar'); const remoteSrc = resolveRemoteConnectSrc(process.env, 'sidecar'); const bundles = [ + { entry: 'alert-journal.ts', out: 'alert-journal.cjs' }, { entry: 'iframe-proxy.ts', out: 'iframe-proxy.cjs' }, { entry: 'agent-browser-host.ts', out: 'agent-browser-host.cjs' }, { diff --git a/standalone/sidecar/main.js b/standalone/sidecar/main.js index 3fa73507..fa6dce1b 100644 --- a/standalone/sidecar/main.js +++ b/standalone/sidecar/main.js @@ -23,6 +23,11 @@ const { createAgentBrowserHost } = require('./agent-browser-host.cjs'); // the PTYs it serves. See docs/specs/remote-api.md. const { createSidecarBurrow } = require('./burrow.cjs'); +// Built from lib/src/host/alert-journal.ts (shared with the VS Code host) by +// scripts/build-sidecar-proxy.mjs. See docs/specs/alert.md → Local alert diagnostics. +const { createAlertJournal } = require('./alert-journal.cjs'); +const alertJournal = createAlertJournal(process.env.DORMOUSE_STATE_DIR || ''); + const agentBrowser = createAgentBrowserHost({ writeClipboardText: (text) => clipboard.writeClipboardText(text), log: (m) => console.error(m), @@ -139,6 +144,7 @@ function handleLine(line) { case 'pty:themeColors': burrow.setThemeColors(data); break; case 'sidecar:shutdown': shutdown(); break; case 'dor:controlResponse': dorControl?.respond(data); break; + case 'alert:diagnostic': alertJournal.append(data); break; case 'burrow:command': burrow.handleCommand(data); break; case 'iframe:createProxyUrl': // Log to stderr — stdout is the JSON-lines protocol channel. @@ -220,6 +226,7 @@ let shuttingDown = false; async function shutdown() { if (shuttingDown) return; shuttingDown = true; + alertJournal.recordLifecycle('host.stopping'); // Close any headed pop-out windows so quitting never orphans a real Chrome // window (spec → "Pop-Out" lifecycle). Bounded so a hung agent-browser // can't wedge the exit; mirrors the VS Code host's deactivate(). @@ -232,6 +239,8 @@ async function shutdown() { dorControl?.close(); burrow.dispose(); mgr.killAll(); + alertJournal.recordLifecycle('host.stopped'); + await Promise.race([alertJournal.close(), new Promise((resolve) => setTimeout(resolve, 250))]); process.exit(0); } diff --git a/standalone/src-tauri/src/lib.rs b/standalone/src-tauri/src/lib.rs index 83a4e2ee..197e2711 100644 --- a/standalone/src-tauri/src/lib.rs +++ b/standalone/src-tauri/src/lib.rs @@ -436,6 +436,14 @@ fn burrow_command(state: tauri::State<'_, SidecarState>, payload: JsonValue) { send_to_sidecar(&state, msg.to_string()); } +// Local alert diagnostics: one record forwarded to the sidecar journal. +#[tauri::command] +fn alert_diagnostic(state: tauri::State<'_, SidecarState>, record: JsonValue) { + send_to_sidecar(&state, serde_json::json!({ + "event": "alert:diagnostic", "data": record, + }).to_string()); +} + #[tauri::command] fn dor_control_response(state: tauri::State<'_, SidecarState>, response: DorControlResponse) { let msg = serde_json::json!({ @@ -1897,6 +1905,7 @@ pub fn run() { pty_request_init, dor_control_response, burrow_command, + alert_diagnostic, kill_sidecar_now, quit_ack, quit_progress, diff --git a/standalone/src/tauri-adapter.ts b/standalone/src/tauri-adapter.ts index 0a051c23..f736abcf 100644 --- a/standalone/src/tauri-adapter.ts +++ b/standalone/src/tauri-adapter.ts @@ -1,3 +1,4 @@ +import type { AlertDiagnostic } from 'dormouse-lib/lib/alert-diagnostics'; import type { HelperIdentity, TerminalContextRequest, TerminalContextInfo } from '../../lib/src/lib/terminal-context-types'; import { invoke as rawInvoke } from "@tauri-apps/api/core"; import { listen } from "@tauri-apps/api/event"; @@ -83,6 +84,10 @@ const errMessage = (err: unknown): string => * Shell processes */ export class TauriAdapter implements PlatformAdapter { + recordAlertDiagnostic(record: AlertDiagnostic): void { + invoke('alert_diagnostic', { record }); + } + private dataHandlers = new Set<(detail: PtyDataDetail) => void>(); private exitHandlers = new Set<(detail: { id: string; exitCode: number }) => void>(); private listHandlers = new Set<(detail: { ptys: PtyInfo[] }) => void>(); diff --git a/vscode-ext/src/alert-journal.ts b/vscode-ext/src/alert-journal.ts new file mode 100644 index 00000000..92f6c8d2 --- /dev/null +++ b/vscode-ext/src/alert-journal.ts @@ -0,0 +1,14 @@ +import { createAlertJournal } from '../../lib/src/host/alert-journal'; +import { configureAlertDiagnostics } from '../../lib/src/lib/alert-diagnostics'; +import { alertDiagnosticsConfig } from '../../lib/src/lib/alert-diagnostics-config'; +import { log } from './log'; + +let journal: ReturnType | undefined; +export function initAlertJournal(stateDir: string): void { + if (!alertDiagnosticsConfig.enabled) return; + journal = createAlertJournal(stateDir, (message) => log.info(message)); + configureAlertDiagnostics('vscode-host', (record) => journal?.append(record)); + log.info(`[alerts] Local journal: ${journal.directory}`); +} +export function appendAlertDiagnostic(record: unknown): void { journal?.append(record); } +export async function closeAlertJournal(): Promise { await journal?.close(); } diff --git a/vscode-ext/src/extension.ts b/vscode-ext/src/extension.ts index c743d505..ccb2d865 100644 --- a/vscode-ext/src/extension.ts +++ b/vscode-ext/src/extension.ts @@ -1,3 +1,5 @@ +import { initAlertJournal, closeAlertJournal } from './alert-journal'; +import { alertDiagnostic } from '../../lib/src/lib/alert-diagnostics'; import * as vscode from 'vscode'; import * as path from 'path'; import * as ptyManager from './pty-manager'; @@ -92,6 +94,10 @@ export function activate(context: vscode.ExtensionContext) { // whichever window wins the bind (burrow.ts). context.subscriptions.push(initBurrow(context)); log.init(); + initAlertJournal(context.globalStorageUri.fsPath); + context.subscriptions.push(vscode.window.onDidChangeWindowState((state) => { + alertDiagnostic('host.focus', { focused: state.focused }); + })); extensionContext = context; ptyManager.setExtensionPath(context.extensionPath); @@ -237,6 +243,7 @@ export async function deactivate() { const t0 = Date.now(); const step = (name: string) => log.info(`[deactivate] ${name} (+${Date.now() - t0}ms)`); step('starting'); + alertDiagnostic('host.stopping'); // Recovery gets the budget FIRST, and this ordering is load-bearing rather than // tidy. `[deactivate] done` has never once been reached in a real shutdown — VS // Code kills the extension host on a budget we do not control — so the single @@ -294,5 +301,12 @@ export async function deactivate() { step('graceful kill'); await ptyManager.gracefulKillAll(2000); ptyManager.killAll(); + alertDiagnostic('host.stopped'); + let journalDeadline: ReturnType | undefined; + await Promise.race([ + closeAlertJournal(), + new Promise((resolve) => { journalDeadline = setTimeout(resolve, 250); }), + ]); + clearTimeout(journalDeadline); step('done'); } diff --git a/vscode-ext/src/message-router.ts b/vscode-ext/src/message-router.ts index 50d0ab20..61d0fe36 100644 --- a/vscode-ext/src/message-router.ts +++ b/vscode-ext/src/message-router.ts @@ -1,3 +1,4 @@ +import { appendAlertDiagnostic } from './alert-journal'; import * as vscode from 'vscode'; import * as ptyManager from './pty-manager'; import { AlertManager, type AwaitHandle, type AwaitOutcome } from '../../lib/src/lib/alert-manager'; @@ -910,6 +911,9 @@ export function attachRouter( break; // Alert actions — proxy to the shared alert manager + case 'alert:diagnostic': + appendAlertDiagnostic(msg.record); + break; case 'alert:remove': alertManager.remove(msg.id); break; diff --git a/vscode-ext/src/message-types.ts b/vscode-ext/src/message-types.ts index 305e6293..a8e7841c 100644 --- a/vscode-ext/src/message-types.ts +++ b/vscode-ext/src/message-types.ts @@ -14,6 +14,7 @@ import type { VolatileNotepadSnapshot } from '../../lib/src/lib/notepad/types'; // Messages from webview → extension host export type WebviewMessage = + | { type: 'alert:diagnostic'; record: unknown } | { type: 'pty:context'; request: TerminalContextRequest; requestId: string } | { type: 'pty:spawn'; id: string; options?: { cols?: number; rows?: number; cwd?: string; shell?: string; args?: string[]; helper?: HelperIdentity } } | { type: 'pty:input'; id: string; data: string }