From 7425a8e19dc1cba95f342939ed3976694467317e Mon Sep 17 00:00:00 2001 From: Ned Twigg Date: Sun, 6 Sep 2026 14:29:03 -0700 Subject: [PATCH 1/5] Log local speech volume and alert lifecycle diagnostics --- .gitignore | 1 + docs/specs/alert.md | 14 ++- docs/specs/alert.rationale.md | 6 ++ docs/specs/security-local.md | 4 + docs/specs/standalone.md | 2 + docs/specs/transport.md | 1 + docs/specs/vscode.md | 6 ++ lib/src/host/alert-journal.test.ts | 94 ++++++++++++++++ lib/src/host/alert-journal.ts | 119 +++++++++++++++++++++ lib/src/lib/alert-diagnostics.test.ts | 80 ++++++++++++++ lib/src/lib/alert-diagnostics.ts | 70 ++++++++++++ lib/src/lib/alert-manager.ts | 63 ++++++++++- lib/src/lib/alert-ring-watch.ts | 36 +++++-- lib/src/lib/alert-settings.ts | 3 + lib/src/lib/alert-speech.test.ts | 72 ++++++++++++- lib/src/lib/alert-speech.ts | 75 +++++++------ lib/src/lib/platform/index.ts | 16 ++- lib/src/lib/platform/types.ts | 3 + lib/src/lib/platform/vscode-adapter.ts | 5 + lib/src/lib/quiesce-detector.ts | 40 +++++-- lib/src/lib/session-activity-store.ts | 3 + package.json | 2 +- scripts/spec-word-budgets.json | 8 +- scripts/summarize-alert-log.mjs | 72 +++++++++++++ scripts/summarize-alert-log.test.mjs | 27 +++++ standalone/scripts/build-sidecar-proxy.mjs | 1 + standalone/sidecar/main.js | 4 + standalone/src-tauri/src/lib.rs | 8 ++ standalone/src/tauri-adapter.ts | 5 + vscode-ext/src/alert-journal.ts | 12 +++ vscode-ext/src/extension.ts | 8 ++ vscode-ext/src/message-router.ts | 4 + vscode-ext/src/message-types.ts | 1 + 33 files changed, 805 insertions(+), 60 deletions(-) create mode 100644 lib/src/host/alert-journal.test.ts create mode 100644 lib/src/host/alert-journal.ts create mode 100644 lib/src/lib/alert-diagnostics.test.ts create mode 100644 lib/src/lib/alert-diagnostics.ts create mode 100644 scripts/summarize-alert-log.mjs create mode 100644 scripts/summarize-alert-log.test.mjs create mode 100644 vscode-ext/src/alert-journal.ts diff --git a/.gitignore b/.gitignore index fbc49a524..90c178302 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/specs/alert.md b/docs/specs/alert.md index 3ac64d266..2260214f4 100644 --- a/docs/specs/alert.md +++ b/docs/specs/alert.md @@ -289,10 +289,22 @@ 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 journal desktop alert decisions and local speech attempts without changing delivery behavior.** 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 manager publications, suppression reasons, semantic event kinds, dismissal/attention actions, detector changes, deferred delivery, timer deadlines/lateness, renderer snapshots, and focus/visibility transitions. 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. 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 ec9bb99c7..b1e6af2f1 100644 --- a/docs/specs/alert.rationale.md +++ b/docs/specs/alert.rationale.md @@ -80,6 +80,12 @@ 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 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 58407e0bd..b6eb69f6e 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 6ea823831..9d94ced6e 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 bb00c2b30..204b6df05 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 6797f7ae8..64215cce0 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. 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 000000000..06a20539f --- /dev/null +++ b/lib/src/host/alert-journal.test.ts @@ -0,0 +1,94 @@ +import { afterEach, 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 } from './alert-journal'; +import type { AlertDiagnostic } from '../lib/alert-diagnostics'; + +const dirs: string[] = []; +const journals: ReturnType[] = []; +afterEach(async () => { + await Promise.all(journals.splice(0).map((j) => j.close())); + 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); +}); +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]); +}); diff --git a/lib/src/host/alert-journal.ts b/lib/src/host/alert-journal.ts new file mode 100644 index 000000000..2c89e3a1a --- /dev/null +++ b/lib/src/host/alert-journal.ts @@ -0,0 +1,119 @@ +import { mkdir, open, readdir, stat, unlink, chmod } from 'node:fs/promises'; +import { join } from 'node:path'; +import { randomUUID } from 'node:crypto'; +import type { AlertDiagnostic } 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[] = []; + let draining: Promise | undefined; + let file: Awaited> | undefined; + let bytes = 0; + let openedAt = 0; + let dropped = 0; + let closed = false; + let warned = false; + + 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({ version: 1, event: 'journal.dropped', at: Date.now(), fields: { 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(); + }); + } + + return { + directory, + append(value: unknown): void { + if (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(); + }, + 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.test.ts b/lib/src/lib/alert-diagnostics.test.ts new file mode 100644 index 000000000..8e969e9fc --- /dev/null +++ b/lib/src/lib/alert-diagnostics.test.ts @@ -0,0 +1,80 @@ +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(() => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date', 'performance'] }); + records = []; + configureAlertDiagnostics('test', (record) => records.push(record)); + manager = new AlertManager(); +}); +afterEach(() => { + manager.dispose(); + configureAlertDiagnostics('off'); + 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'); +}); diff --git a/lib/src/lib/alert-diagnostics.ts b/lib/src/lib/alert-diagnostics.ts new file mode 100644 index 000000000..db3558d8f --- /dev/null +++ b/lib/src/lib/alert-diagnostics.ts @@ -0,0 +1,70 @@ +/** 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 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 = write; + 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 (!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 (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 af4fe9ead..1f308b8b6 100644 --- a/lib/src/lib/alert-manager.ts +++ b/lib/src/lib/alert-manager.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic, 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,28 @@ 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 trace(event: string, id?: string, fields: DiagnosticFields = {}): void { + const entry = id === undefined ? undefined : this.entries.get(id); + alertDiagnostic(event, { + 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, + } : {}), ...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 +267,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 +279,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 +317,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 +328,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 +389,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,7 +446,18 @@ 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)); + this.trace('manager.completion', id, { + kind: event.kind, claimed, + reason: claimed ? 'claimed' : this.hasAttention(id) ? 'attended' + : event.kind === 'settled' && !this.isWatching(entry) ? 'not-watched' + : event.kind === 'commandFinished' && !event.armed ? 'not-armed' + : event.kind === 'commandFinished' && event.ranMs < this.inactivityTimeoutMs ? 'short-command' + : 'eligible', + ...(event.kind === 'commandFinished' ? { ranMs: event.ranMs, armed: event.armed, exitCode: event.exitCode ?? null } : {}), + ...(event.kind === 'notification' ? { notificationSource: event.notification.source } : {}), + }); + if (claimed) return true; switch (event.kind) { case 'settled': @@ -738,6 +778,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 +925,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 +949,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 +962,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 +1051,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 +1074,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 +1088,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 +1099,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 +1116,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 +1126,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 +1136,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 +1173,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 +1200,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 +1219,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 +1301,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 18c77965d..caedb1153 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 46d4cd374..1688ddefb 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 ca5666890..be35f1f64 100644 --- a/lib/src/lib/alert-speech.test.ts +++ b/lib/src/lib/alert-speech.test.ts @@ -4,7 +4,8 @@ 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 +16,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; @@ -83,6 +85,8 @@ function ringTwoWithFirstSpeaking(): void { beforeEach(() => { vi.useFakeTimers(); stubSpeechSynthesis(); + records = []; + configureAlertDiagnostics('test', (record) => records.push(record)); clearTerminalActivity(); applyAlertSettingsFromHost({ ...DEFAULT_ALERT_SETTINGS, speakEnabled: true, speakDelayMs: SPEAK_DELAY_MS }); }); @@ -93,6 +97,7 @@ afterEach(() => { for (const id of ['osc0-title', 'osc2-title', 'osc9-title']) removeTerminalPaneState(id); clearTerminalActivity(); applyAlertSettingsFromHost(DEFAULT_ALERT_SETTINGS); + configureAlertDiagnostics('off'); vi.useRealTimers(); vi.unstubAllGlobals(); }); @@ -484,3 +489,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 8752d6e50..ba97d72ae 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 14b56a946..f5c5ab61e 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 9476be67e..4881d4b9f 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 00fbf0318..dbc5cebbd 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 b6f215686..95759baf0 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 5b1a8d865..e8287847d 100644 --- a/lib/src/lib/session-activity-store.ts +++ b/lib/src/lib/session-activity-store.ts @@ -1,3 +1,4 @@ +import { alertDiagnostic } 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,7 @@ 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 { + alertDiagnostic('renderer.snapshot', { sessionId: id, previousStatus: terminalActivity.get(id)?.state.status ?? null, previousRingSeq: terminalActivity.get(id)?.state.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 +94,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 904f8071d..857d0e7fa 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 2c3ccbe5a..14d64ed5e 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": 7000, "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 000000000..72e9f316c --- /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 (record.source) 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 000000000..e134e203c --- /dev/null +++ b/scripts/summarize-alert-log.test.mjs @@ -0,0 +1,27 @@ +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('diagnostics.dropped', null, { count: 4 }), + ].map(JSON.stringify).join('\n') + '\n{"truncated":'); + const summary = await summarizeAlertLogs(dir); + assert.equal(summary.droppedRecords, 4); + 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 8b86f2b4e..65480c213 100644 --- a/standalone/scripts/build-sidecar-proxy.mjs +++ b/standalone/scripts/build-sidecar-proxy.mjs @@ -24,6 +24,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 3fa735078..bcd0326cd 100644 --- a/standalone/sidecar/main.js +++ b/standalone/sidecar/main.js @@ -1,3 +1,5 @@ +const { createAlertJournal } = require('./alert-journal.cjs'); +const alertJournal = createAlertJournal(process.env.DORMOUSE_STATE_DIR || ''); /** * Tauri sidecar entry point — stdio JSON-lines transport over pty-core. * @@ -139,6 +141,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. @@ -232,6 +235,7 @@ async function shutdown() { dorControl?.close(); burrow.dispose(); mgr.killAll(); + 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 83a4e2ee4..98b326da4 100644 --- a/standalone/src-tauri/src/lib.rs +++ b/standalone/src-tauri/src/lib.rs @@ -427,6 +427,13 @@ fn pty_request_init(state: tauri::State<'_, SidecarState>) { // service share a contract (lib/src/host/remote/service-protocol.ts) that Rust // has no reason to know, so the payload rides through opaquely. Replies come // back on the sidecar's own stdout events, not from this invoke. +#[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 burrow_command(state: tauri::State<'_, SidecarState>, payload: JsonValue) { let msg = serde_json::json!({ @@ -1897,6 +1904,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 0a051c231..f736abcff 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 000000000..52230b026 --- /dev/null +++ b/vscode-ext/src/alert-journal.ts @@ -0,0 +1,12 @@ +import { createAlertJournal } from '../../lib/src/host/alert-journal'; +import { configureAlertDiagnostics } from '../../lib/src/lib/alert-diagnostics'; +import { log } from './log'; + +let journal: ReturnType | undefined; +export function initAlertJournal(stateDir: string): void { + 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 c743d5053..7c2d2e2e5 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,8 @@ export async function deactivate() { const t0 = Date.now(); const step = (name: string) => log.info(`[deactivate] ${name} (+${Date.now() - t0}ms)`); step('starting'); + alertDiagnostic('host.stop'); + void closeAlertJournal(); // 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 diff --git a/vscode-ext/src/message-router.ts b/vscode-ext/src/message-router.ts index 50d0ab206..61d0fe36f 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 305e62931..a8e7841c9 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 } From aa93d197e27ee3aec540a98c127f68d6ca6a7954 Mon Sep 17 00:00:00 2001 From: Ned Twigg Date: Sun, 6 Sep 2026 14:41:14 -0700 Subject: [PATCH 2/5] Preserve shutdown diagnostics and align logging with alert decisions --- docs/specs/vscode.md | 2 +- lib/src/host/alert-journal.test.ts | 3 ++- lib/src/host/alert-journal.ts | 4 +++- lib/src/lib/alert-diagnostics.test.ts | 13 ++++++++++++ lib/src/lib/alert-diagnostics.ts | 2 ++ lib/src/lib/alert-manager.ts | 24 ++++++++++++---------- lib/src/lib/session-activity-store.ts | 10 +++++++-- standalone/scripts/build-sidecar-proxy.mjs | 1 + standalone/sidecar/main.js | 7 +++++-- standalone/src-tauri/src/lib.rs | 15 +++++++------- vscode-ext/src/extension.ts | 9 ++++++-- 11 files changed, 63 insertions(+), 27 deletions(-) diff --git a/docs/specs/vscode.md b/docs/specs/vscode.md index 64215cce0..35b0761ab 100644 --- a/docs/specs/vscode.md +++ b/docs/specs/vscode.md @@ -8,7 +8,7 @@ ## 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. Never put these records in Settings Sync or restorable Session state. Behavior: `docs/specs/alert.md` → 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`. diff --git a/lib/src/host/alert-journal.test.ts b/lib/src/host/alert-journal.test.ts index 06a20539f..b1e8ee18c 100644 --- a/lib/src/host/alert-journal.test.ts +++ b/lib/src/host/alert-journal.test.ts @@ -2,7 +2,7 @@ import { afterEach, 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 } from './alert-journal'; +import { createAlertJournal, isAlertDiagnostic } from './alert-journal'; import type { AlertDiagnostic } from '../lib/alert-diagnostics'; const dirs: string[] = []; @@ -43,6 +43,7 @@ it('bounds an overloaded queue and writes a loss marker', async () => { 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(); diff --git a/lib/src/host/alert-journal.ts b/lib/src/host/alert-journal.ts index 2c89e3a1a..44cd96611 100644 --- a/lib/src/host/alert-journal.ts +++ b/lib/src/host/alert-journal.ts @@ -14,6 +14,8 @@ const FILE_PATTERN = /^alerts-[\d-]+-[0-9a-f-]+\.jsonl$/; 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; @@ -45,7 +47,7 @@ export function createAlertJournal(stateDir: string, warn: (message: string) => while (queue.length || dropped) { const lost = dropped; const line = lost - ? JSON.stringify({ version: 1, event: 'journal.dropped', at: Date.now(), fields: { count: lost } }) + '\n' + ? JSON.stringify({ version: 1, source, seq: ++seq, monotonicMs: performance.now(), event: 'journal.dropped', at: Date.now(), fields: { count: lost } }) + '\n' : queue[0]; const lineBytes = Buffer.byteLength(line); // Another window may prune an idle writer's file. Reopen instead of diff --git a/lib/src/lib/alert-diagnostics.test.ts b/lib/src/lib/alert-diagnostics.test.ts index 8e969e9fc..a8faf7dcb 100644 --- a/lib/src/lib/alert-diagnostics.test.ts +++ b/lib/src/lib/alert-diagnostics.test.ts @@ -78,3 +78,16 @@ it('keeps alert delivery working when the diagnostic sink throws', () => { 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'); +}); diff --git a/lib/src/lib/alert-diagnostics.ts b/lib/src/lib/alert-diagnostics.ts index db3558d8f..e43bc5da4 100644 --- a/lib/src/lib/alert-diagnostics.ts +++ b/lib/src/lib/alert-diagnostics.ts @@ -17,6 +17,8 @@ let windowAt = 0; let windowCount = 0; let dropped = 0; +export function alertDiagnosticsEnabled(): boolean { return sink !== undefined; } + export function diagnosticId(): string { return globalThis.crypto?.randomUUID?.() ?? `${Date.now()}-${Math.random().toString(36).slice(2)}`; } diff --git a/lib/src/lib/alert-manager.ts b/lib/src/lib/alert-manager.ts index 1f308b8b6..f78dedec9 100644 --- a/lib/src/lib/alert-manager.ts +++ b/lib/src/lib/alert-manager.ts @@ -1,4 +1,4 @@ -import { alertDiagnostic, diagnosticId, type DiagnosticFields } from './alert-diagnostics'; +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'; @@ -214,6 +214,7 @@ export class AlertManager { private lastAttentionAt: number | null = null; private trace(event: string, id?: string, fields: DiagnosticFields = {}): void { + if (!alertDiagnosticsEnabled()) return; const entry = id === undefined ? undefined : this.entries.get(id); alertDiagnostic(event, { manager: this.diagnosticManager, sessionId: id ?? null, @@ -447,31 +448,30 @@ export class AlertManager { // being offered this very event. const claimants = [...(this.claimants.get(id) ?? [])]; const claimed = claimants.some((claimant) => claimant(event)); - this.trace('manager.completion', id, { - kind: event.kind, claimed, - reason: claimed ? 'claimed' : this.hasAttention(id) ? 'attended' - : event.kind === 'settled' && !this.isWatching(entry) ? 'not-watched' - : event.kind === 'commandFinished' && !event.armed ? 'not-armed' - : event.kind === 'commandFinished' && event.ranMs < this.inactivityTimeoutMs ? 'short-command' - : 'eligible', + const traceDecision = (reason: string): void => this.trace('manager.completion', id, { + 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) return true; + 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); @@ -482,6 +482,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); @@ -490,6 +491,7 @@ export class AlertManager { this.deferOrDeliverNotification(id, entry, event.notification); break; } + traceDecision(reason); return false; } diff --git a/lib/src/lib/session-activity-store.ts b/lib/src/lib/session-activity-store.ts index e8287847d..cd9901acd 100644 --- a/lib/src/lib/session-activity-store.ts +++ b/lib/src/lib/session-activity-store.ts @@ -1,4 +1,4 @@ -import { alertDiagnostic } from './alert-diagnostics'; +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'; @@ -83,7 +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 { - alertDiagnostic('renderer.snapshot', { sessionId: id, previousStatus: terminalActivity.get(id)?.state.status ?? null, previousRingSeq: terminalActivity.get(id)?.state.ringSeq ?? null, status: state.status ?? null, ringSeq: state.ringSeq ?? null }); + 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 }, diff --git a/standalone/scripts/build-sidecar-proxy.mjs b/standalone/scripts/build-sidecar-proxy.mjs index 65480c213..dfab95e13 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 diff --git a/standalone/sidecar/main.js b/standalone/sidecar/main.js index bcd0326cd..56aa8173c 100644 --- a/standalone/sidecar/main.js +++ b/standalone/sidecar/main.js @@ -1,5 +1,3 @@ -const { createAlertJournal } = require('./alert-journal.cjs'); -const alertJournal = createAlertJournal(process.env.DORMOUSE_STATE_DIR || ''); /** * Tauri sidecar entry point — stdio JSON-lines transport over pty-core. * @@ -25,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), diff --git a/standalone/src-tauri/src/lib.rs b/standalone/src-tauri/src/lib.rs index 98b326da4..197e27117 100644 --- a/standalone/src-tauri/src/lib.rs +++ b/standalone/src-tauri/src/lib.rs @@ -427,13 +427,6 @@ fn pty_request_init(state: tauri::State<'_, SidecarState>) { // service share a contract (lib/src/host/remote/service-protocol.ts) that Rust // has no reason to know, so the payload rides through opaquely. Replies come // back on the sidecar's own stdout events, not from this invoke. -#[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 burrow_command(state: tauri::State<'_, SidecarState>, payload: JsonValue) { let msg = serde_json::json!({ @@ -443,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!({ diff --git a/vscode-ext/src/extension.ts b/vscode-ext/src/extension.ts index 7c2d2e2e5..05beaaa74 100644 --- a/vscode-ext/src/extension.ts +++ b/vscode-ext/src/extension.ts @@ -243,8 +243,6 @@ export async function deactivate() { const t0 = Date.now(); const step = (name: string) => log.info(`[deactivate] ${name} (+${Date.now() - t0}ms)`); step('starting'); - alertDiagnostic('host.stop'); - void closeAlertJournal(); // 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 @@ -302,5 +300,12 @@ export async function deactivate() { step('graceful kill'); await ptyManager.gracefulKillAll(2000); ptyManager.killAll(); + alertDiagnostic('host.stop'); + let journalDeadline: ReturnType | undefined; + await Promise.race([ + closeAlertJournal(), + new Promise((resolve) => { journalDeadline = setTimeout(resolve, 250); }), + ]); + clearTimeout(journalDeadline); step('done'); } From 4f49e385e18ad7304aba3192566d96d142db2449 Mon Sep 17 00:00:00 2001 From: Ned Twigg Date: Sun, 6 Sep 2026 14:51:00 -0700 Subject: [PATCH 3/5] Capture decision inputs and both shutdown lifecycle boundaries --- docs/specs/alert.md | 4 ++-- lib/src/host/alert-journal.test.ts | 11 +++++++++++ lib/src/host/alert-journal.ts | 27 +++++++++++++++++---------- lib/src/lib/alert-diagnostics.test.ts | 20 ++++++++++++++++++++ lib/src/lib/alert-manager.ts | 21 ++++++++++++++------- scripts/summarize-alert-log.mjs | 2 +- scripts/summarize-alert-log.test.mjs | 3 ++- standalone/sidecar/main.js | 2 ++ vscode-ext/src/extension.ts | 3 ++- 9 files changed, 71 insertions(+), 22 deletions(-) diff --git a/docs/specs/alert.md b/docs/specs/alert.md index 2260214f4..ca8c87982 100644 --- a/docs/specs/alert.md +++ b/docs/specs/alert.md @@ -297,11 +297,11 @@ Source of truth: `toSpokenText` in `lib/src/lib/alert-speech.ts`, armed by `lib/ - **Must journal desktop alert decisions and local speech attempts without changing delivery behavior.** 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 manager publications, suppression reasons, semantic event kinds, dismissal/attention actions, detector changes, deferred delivery, timer deadlines/lateness, renderer snapshots, and focus/visibility transitions. 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 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. 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. +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. 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`. diff --git a/lib/src/host/alert-journal.test.ts b/lib/src/host/alert-journal.test.ts index b1e8ee18c..4ee69e77b 100644 --- a/lib/src/host/alert-journal.test.ts +++ b/lib/src/host/alert-journal.test.ts @@ -93,3 +93,14 @@ it('reopens a file pruned by another host writer', async () => { 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 index 44cd96611..f9991da74 100644 --- a/lib/src/host/alert-journal.ts +++ b/lib/src/host/alert-journal.ts @@ -1,7 +1,7 @@ import { mkdir, open, readdir, stat, unlink, chmod } from 'node:fs/promises'; import { join } from 'node:path'; import { randomUUID } from 'node:crypto'; -import type { AlertDiagnostic } from '../lib/alert-diagnostics'; +import type { AlertDiagnostic, DiagnosticFields } from '../lib/alert-diagnostics'; const FILE_BYTES = 4 * 1024 * 1024; const TOTAL_BYTES = 64 * 1024 * 1024; @@ -24,6 +24,10 @@ export function createAlertJournal(stateDir: string, warn: (message: string) => 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) => { @@ -47,7 +51,7 @@ export function createAlertJournal(stateDir: string, warn: (message: string) => while (queue.length || dropped) { const lost = dropped; const line = lost - ? JSON.stringify({ version: 1, source, seq: ++seq, monotonicMs: performance.now(), event: 'journal.dropped', at: Date.now(), fields: { count: lost } }) + '\n' + ? 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 @@ -86,16 +90,19 @@ export function createAlertJournal(stateDir: string, warn: (message: string) => }); } + function append(value: unknown): void { + if (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(value: unknown): void { - if (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(); - }, + append, + recordLifecycle(event: 'host.stopping' | 'host.stopped'): void { append(writerRecord(event)); }, async flush(): Promise { while (draining) await draining; }, async close(): Promise { closed = true; diff --git a/lib/src/lib/alert-diagnostics.test.ts b/lib/src/lib/alert-diagnostics.test.ts index a8faf7dcb..68d41073b 100644 --- a/lib/src/lib/alert-diagnostics.test.ts +++ b/lib/src/lib/alert-diagnostics.test.ts @@ -91,3 +91,23 @@ it('reports the suppression branch actually taken when conditions overlap', () = }); 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-manager.ts b/lib/src/lib/alert-manager.ts index f78dedec9..c5e559a76 100644 --- a/lib/src/lib/alert-manager.ts +++ b/lib/src/lib/alert-manager.ts @@ -213,10 +213,10 @@ export class AlertManager { private readonly diagnosticManager = diagnosticId(); private lastAttentionAt: number | null = null; - private trace(event: string, id?: string, fields: DiagnosticFields = {}): void { - if (!alertDiagnosticsEnabled()) return; + private traceFields(id?: string): DiagnosticFields { + if (!alertDiagnosticsEnabled()) return {}; const entry = id === undefined ? undefined : this.entries.get(id); - alertDiagnostic(event, { + return { manager: this.diagnosticManager, sessionId: id ?? null, attentionId: this.attentionId, lastAttentionAt: this.lastAttentionAt, inactivityTimeoutMs: this.inactivityTimeoutMs, deferAlertsUntilQuiet: this.deferAlertsUntilQuiet, @@ -229,8 +229,13 @@ export class AlertManager { commandSeenAt: entry.commandExitWatch?.seenWithAttentionAt ?? null, pendingNotification: entry.deferredNotification?.source ?? null, todo: entry.todo, attentionDismissedRing: entry.attentionDismissedRing, - } : {}), ...fields, - }); + } : {}), + }; + } + + private trace(event: string, id?: string, fields: DiagnosticFields = {}): void { + if (!alertDiagnosticsEnabled()) return; + alertDiagnostic(event, { ...this.traceFields(id), ...fields }); } private entries = new Map(); @@ -448,8 +453,10 @@ export class AlertManager { // being offered this very event. const claimants = [...(this.claimants.get(id) ?? [])]; const claimed = claimants.some((claimant) => claimant(event)); - const traceDecision = (reason: string): void => this.trace('manager.completion', id, { - kind: event.kind, claimed, reason, + // 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 } : {}), }); diff --git a/scripts/summarize-alert-log.mjs b/scripts/summarize-alert-log.mjs index 72e9f316c..11921338f 100644 --- a/scripts/summarize-alert-log.mjs +++ b/scripts/summarize-alert-log.mjs @@ -23,7 +23,7 @@ export async function summarizeAlertLogs(directory) { || !record.fields || typeof record.fields !== 'object') { malformedLines++; continue; } firstAt = Math.min(firstAt, record.at); lastAt = Math.max(lastAt, record.at); - if (record.source) sources.add(record.source); + 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}`; diff --git a/scripts/summarize-alert-log.test.mjs b/scripts/summarize-alert-log.test.mjs index e134e203c..d941791a8 100644 --- a/scripts/summarize-alert-log.test.mjs +++ b/scripts/summarize-alert-log.test.mjs @@ -15,10 +15,11 @@ test('separates initial speech, retries, tests, outcomes, and incomplete data', event('speech.request', '2', { reason: 'requeue', characters: 12 }), event('speech.request', '3', { reason: 'test', characters: 19 }), event('speech.unavailable', '3'), - event('diagnostics.dropped', null, { count: 4 }), + { ...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, diff --git a/standalone/sidecar/main.js b/standalone/sidecar/main.js index 56aa8173c..fa6dce1ba 100644 --- a/standalone/sidecar/main.js +++ b/standalone/sidecar/main.js @@ -226,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(). @@ -238,6 +239,7 @@ 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/vscode-ext/src/extension.ts b/vscode-ext/src/extension.ts index 05beaaa74..ccb2d8656 100644 --- a/vscode-ext/src/extension.ts +++ b/vscode-ext/src/extension.ts @@ -243,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 @@ -300,7 +301,7 @@ export async function deactivate() { step('graceful kill'); await ptyManager.gracefulKillAll(2000); ptyManager.killAll(); - alertDiagnostic('host.stop'); + alertDiagnostic('host.stopped'); let journalDeadline: ReturnType | undefined; await Promise.race([ closeAlertJournal(), From 8f1438ad23dfd4f2aafa4924dee6c4b6b3b7ad8f Mon Sep 17 00:00:00 2001 From: Ned Twigg Date: Sun, 6 Sep 2026 14:59:46 -0700 Subject: [PATCH 4/5] Clarify diagnostic source counting across desktop hosts --- docs/specs/alert.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/specs/alert.md b/docs/specs/alert.md index ca8c87982..4c9e9a670 100644 --- a/docs/specs/alert.md +++ b/docs/specs/alert.md @@ -301,7 +301,7 @@ Source of truth: `toSpokenText` in `lib/src/lib/alert-speech.ts`, armed by `lib/ - **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. 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. +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`. From 34bbd09180030530d36703ae5b607d7967ae727c Mon Sep 17 00:00:00 2001 From: Ned Twigg Date: Sun, 6 Sep 2026 17:57:07 -0700 Subject: [PATCH 5/5] Default temporary alert diagnostics off behind a shared flag --- docs/alert-diagnostics-removal.md | 13 +++++ docs/specs/alert.md | 3 +- docs/specs/alert.rationale.md | 2 + lib/src/host/alert-journal.test.ts | 5 +- lib/src/host/alert-journal.ts | 3 +- lib/src/lib/alert-diagnostics-config.ts | 4 ++ lib/src/lib/alert-diagnostics-gate.test.ts | 55 ++++++++++++++++++++++ lib/src/lib/alert-diagnostics.test.ts | 3 ++ lib/src/lib/alert-diagnostics.ts | 10 ++-- lib/src/lib/alert-speech.test.ts | 3 ++ scripts/spec-word-budgets.json | 2 +- vscode-ext/src/alert-journal.ts | 2 + 12 files changed, 97 insertions(+), 8 deletions(-) create mode 100644 docs/alert-diagnostics-removal.md create mode 100644 lib/src/lib/alert-diagnostics-config.ts create mode 100644 lib/src/lib/alert-diagnostics-gate.test.ts diff --git a/docs/alert-diagnostics-removal.md b/docs/alert-diagnostics-removal.md new file mode 100644 index 000000000..8f82c67f0 --- /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 4c9e9a670..3bc846eb3 100644 --- a/docs/specs/alert.md +++ b/docs/specs/alert.md @@ -295,7 +295,8 @@ Source of truth: `toSpokenText` in `lib/src/lib/alert-speech.ts`, armed by `lib/ ### Local alert diagnostics -- **Must journal desktop alert decisions and local speech attempts without changing delivery behavior.** Logging failure never blocks an alert; diagnostics never hydrate alert state. Pocket and the website demo have no journal port (rationale). +- **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. diff --git a/docs/specs/alert.rationale.md b/docs/specs/alert.rationale.md index b1e6af2f1..665695e24 100644 --- a/docs/specs/alert.rationale.md +++ b/docs/specs/alert.rationale.md @@ -82,6 +82,8 @@ Guarding only completion leaves a stale `start` free to replace the active utter ## 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. diff --git a/lib/src/host/alert-journal.test.ts b/lib/src/host/alert-journal.test.ts index 4ee69e77b..1bf36c832 100644 --- a/lib/src/host/alert-journal.test.ts +++ b/lib/src/host/alert-journal.test.ts @@ -1,4 +1,5 @@ -import { afterEach, expect, it, vi } from 'vitest'; +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'; @@ -7,8 +8,10 @@ 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() { diff --git a/lib/src/host/alert-journal.ts b/lib/src/host/alert-journal.ts index f9991da74..76b689427 100644 --- a/lib/src/host/alert-journal.ts +++ b/lib/src/host/alert-journal.ts @@ -1,6 +1,7 @@ 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; @@ -91,7 +92,7 @@ export function createAlertJournal(stateDir: string, warn: (message: string) => } function append(value: unknown): void { - if (closed || !stateDir || !isAlertDiagnostic(value)) return; + 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; } diff --git a/lib/src/lib/alert-diagnostics-config.ts b/lib/src/lib/alert-diagnostics-config.ts new file mode 100644 index 000000000..38e248ec2 --- /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 000000000..ec91635a5 --- /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 index 68d41073b..7b573c11f 100644 --- a/lib/src/lib/alert-diagnostics.test.ts +++ b/lib/src/lib/alert-diagnostics.test.ts @@ -1,3 +1,4 @@ +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'; @@ -5,6 +6,7 @@ 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)); @@ -13,6 +15,7 @@ beforeEach(() => { afterEach(() => { manager.dispose(); configureAlertDiagnostics('off'); + alertDiagnosticsConfig.enabled = false; vi.useRealTimers(); }); diff --git a/lib/src/lib/alert-diagnostics.ts b/lib/src/lib/alert-diagnostics.ts index e43bc5da4..51af32d01 100644 --- a/lib/src/lib/alert-diagnostics.ts +++ b/lib/src/lib/alert-diagnostics.ts @@ -1,3 +1,5 @@ +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; + /** Local observability only: never use these records to drive alert state. */ export type DiagnosticFields = Record; export interface AlertDiagnostic { @@ -17,14 +19,14 @@ let windowAt = 0; let windowCount = 0; let dropped = 0; -export function alertDiagnosticsEnabled(): boolean { return sink !== undefined; } +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 = write; + sink = alertDiagnosticsConfig.enabled ? write : undefined; source = `${label}:${diagnosticId()}`; seq = windowCount = dropped = 0; windowAt = performance.now(); @@ -34,7 +36,7 @@ export function configureAlertDiagnostics(label: string, write?: (record: AlertD /** 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 (!sink) return; + if (!alertDiagnosticsEnabled() || !sink) return; try { const monotonicMs = performance.now(); const record = (name: string, data: DiagnosticFields): AlertDiagnostic => ({ @@ -57,7 +59,7 @@ export function alertDiagnostic(event: string, fields: DiagnosticFields = {}): v } export function observeAlertFocus(): () => void { - if (typeof window === 'undefined') return () => {}; + if (!alertDiagnosticsEnabled() || typeof window === 'undefined') return () => {}; const record = (event: Event): void => alertDiagnostic('renderer.focus', { trigger: event.type, focused: document.hasFocus(), visibility: document.visibilityState, }); diff --git a/lib/src/lib/alert-speech.test.ts b/lib/src/lib/alert-speech.test.ts index be35f1f64..071baa14e 100644 --- a/lib/src/lib/alert-speech.test.ts +++ b/lib/src/lib/alert-speech.test.ts @@ -1,3 +1,4 @@ +import { alertDiagnosticsConfig } from './alert-diagnostics-config'; import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; vi.mock('./platform', () => ({ @@ -83,6 +84,7 @@ function ringTwoWithFirstSpeaking(): void { } beforeEach(() => { + alertDiagnosticsConfig.enabled = true; vi.useFakeTimers(); stubSpeechSynthesis(); records = []; @@ -98,6 +100,7 @@ afterEach(() => { clearTerminalActivity(); applyAlertSettingsFromHost(DEFAULT_ALERT_SETTINGS); configureAlertDiagnostics('off'); + alertDiagnosticsConfig.enabled = false; vi.useRealTimers(); vi.unstubAllGlobals(); }); diff --git a/scripts/spec-word-budgets.json b/scripts/spec-word-budgets.json index 14d64ed5e..cf6411652 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": 7000, + "docs/specs/alert.md": 7100, "docs/specs/auto-update.md": 1000, "docs/specs/deploy.md": 1900, "docs/specs/dor-browser.md": 4500, diff --git a/vscode-ext/src/alert-journal.ts b/vscode-ext/src/alert-journal.ts index 52230b026..92f6c8d2a 100644 --- a/vscode-ext/src/alert-journal.ts +++ b/vscode-ext/src/alert-journal.ts @@ -1,9 +1,11 @@ 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}`);