diff --git a/docs/activity-trace.md b/docs/activity-trace.md index 09b114e9..873f5651 100644 --- a/docs/activity-trace.md +++ b/docs/activity-trace.md @@ -307,10 +307,13 @@ checks are scans: every call to `trace`, `codePoints`, `controlOffset`, and the probe categories are named so a probe deleted in a refactor fails the suite instead of quietly reducing a count. -One call is exempt and pinned by its exact text: the OSC 0 `log.debug` line -renders a code point into a template literal on every title, whatever the trace -is doing. It predates this feature (c07ab13, 2026-03) and is on `main`; the -exemption exists so that it stays the only one. +One call is exempt from that guard and pinned by its exact text: the OSC 0 +`log.debug` line renders a code point into a template literal, and it carries +the debug-log guard `if (LOG_DEBUG_ON)` rather than `if (TRACE.on)` — a +packaged build logs at `info`, so the line and its code point are inert there. +`test/osc-debug-log-guards.test.js` pins that guard, and every other debug line +on the PTY data path with it. The exemption above exists so that this stays the +only one. This matters because of [ADR 0002](decisions/0002-discrete-steps-sidebar-animations.md) — the diff --git a/main.js b/main.js index 772da514..ee0cb94b 100644 --- a/main.js +++ b/main.js @@ -30,6 +30,7 @@ if (process.env.SWITCHBOARD_DATA_DIR) { log.transports.file.level = app.isPackaged ? 'info' : 'debug'; log.transports.console.level = app.isPackaged ? 'info' : 'debug'; +const LOG_DEBUG_ON = log.transports.file.level === 'debug' || log.transports.console.level === 'debug'; // Opt-in activity trace — see docs/activity-trace.md. const activityTrace = require('./activity-trace'); @@ -2170,12 +2171,12 @@ function wireSessionPty(session, sessionId, ptyProcess) { // Detect Claude CLI busy state from the OSC 0 title — see .ai/contexts/ipc-bridge.md if (code === '0') { const { busy: isBusy, idle: isIdle, via } = classifyTitleActivity(payload, { allowFallback: !session.isPlainTerminal }); - log.debug(`[OSC 0] session=${currentId} cp=${codePoints(payload, 1)} rule=${via} busy=${isBusy} idle=${isIdle} wasBusy=${!!session._cliBusy}`); + if (LOG_DEBUG_ON) log.debug(`[OSC 0] session=${currentId} cp=${codePoints(payload, 1)} rule=${via} busy=${isBusy} idle=${isIdle} wasBusy=${!!session._cliBusy}`); if (TRACE.on) trace('osc.title', currentId, { cp: codePoints(payload, 3), title: payload.slice(0, 60), busy: isBusy, idle: isIdle, rule: via, was: !!session._cliBusy, decision: busyDecision(isBusy, isIdle, !!session._cliBusy) }); if (isBusy && !session._cliBusy) { session._cliBusy = true; session._oscIdle = false; - log.debug(`[OSC 0] session=${currentId} → BUSY`); + if (LOG_DEBUG_ON) log.debug(`[OSC 0] session=${currentId} → BUSY`); if (TRACE.on) trace('busy.emit', currentId, { busy: true, via: 'osc0', sent: !!(mainWindow && !mainWindow.isDestroyed()) }); if (mainWindow && !mainWindow.isDestroyed()) { mainWindow.webContents.send('cli-busy-state', currentId, true); @@ -2183,7 +2184,7 @@ function wireSessionPty(session, sessionId, ptyProcess) { } else if (isIdle && session._cliBusy) { session._cliBusy = false; session._oscIdle = true; - log.debug(`[OSC 0] session=${currentId} → IDLE`); + if (LOG_DEBUG_ON) log.debug(`[OSC 0] session=${currentId} → IDLE`); if (TRACE.on) trace('busy.emit', currentId, { busy: false, via: 'osc0', sent: !!(mainWindow && !mainWindow.isDestroyed()) }); if (mainWindow && !mainWindow.isDestroyed()) { mainWindow.webContents.send('cli-busy-state', currentId, false); @@ -2199,12 +2200,12 @@ function wireSessionPty(session, sessionId, ptyProcess) { if (payload.startsWith('4;')) { const level = payload.split(';')[1]; if (level === '0') continue; // 4;0 is also used for clearing, making it unreliable as an idle signal - log.debug(`[OSC 9;4] session=${currentId} level=${level} payload="${payload}" wasBusy=${!!session._cliBusy}`); + if (LOG_DEBUG_ON) log.debug(`[OSC 9;4] session=${currentId} level=${level} payload="${payload}" wasBusy=${!!session._cliBusy}`); if (TRACE.on) trace('osc.progress', currentId, { level, payload: payload.slice(0, 60), was: !!session._cliBusy, decision: progressDecision(level, !!session._cliBusy) }); if ((level === '1' || level === '2' || level === '3') && !session._cliBusy) { session._cliBusy = true; session._oscIdle = false; - log.debug(`[OSC 9;4] session=${currentId} → BUSY`); + if (LOG_DEBUG_ON) log.debug(`[OSC 9;4] session=${currentId} → BUSY`); if (TRACE.on) trace('busy.emit', currentId, { busy: true, via: 'osc9.4', sent: !!(mainWindow && !mainWindow.isDestroyed()) }); if (mainWindow && !mainWindow.isDestroyed()) { mainWindow.webContents.send('cli-busy-state', currentId, true); diff --git a/test/activity-trace-probe-guards.test.js b/test/activity-trace-probe-guards.test.js index 080476f5..4b85affc 100644 --- a/test/activity-trace-probe-guards.test.js +++ b/test/activity-trace-probe-guards.test.js @@ -132,13 +132,12 @@ test('every trace() call in main.js is guarded, except the IPC forwarder', () => assert.equal(looseTrace.length, 1, 'the renderer forwarder is the only unguarded call'); }); -// One call predates the trace: the OSC 0 debug log renders a code point into a -// template literal on every title, whatever the trace is doing. It is a real -// cost on a hot path and it is not this feature's to remove — it came in with -// c07ab13 (2026-03) and is on main. Pinned by its exact text so that it stays -// the *only* exception: anything new fails the assertion below. +// One call renders a code point outside the trace's guard: the OSC 0 debug log +// sits under `if (LOG_DEBUG_ON)` instead, the debug-log guard, which +// test/osc-debug-log-guards.test.js pins. Its exact text is pinned here so +// that it stays the *only* exception: anything new fails the assertion below. const KNOWN_UNGUARDED_HELPERS = [ - 'log.debug(`[OSC 0] session=${currentId} cp=${codePoints(payload, 1)} rule=${via} busy=${isBusy} idle=${isIdle} wasBusy=${!!session._cliBusy}`);', + 'if (LOG_DEBUG_ON) log.debug(`[OSC 0] session=${currentId} cp=${codePoints(payload, 1)} rule=${via} busy=${isBusy} idle=${isIdle} wasBusy=${!!session._cliBusy}`);', ]; test('no trace payload helper is called outside a guard', () => { diff --git a/test/osc-debug-log-guards.test.js b/test/osc-debug-log-guards.test.js new file mode 100644 index 00000000..ed2182db --- /dev/null +++ b/test/osc-debug-log-guards.test.js @@ -0,0 +1,62 @@ +// The debug lines on the PTY data path must cost nothing when debug logging +// is off. +// +// `log.debug` decides at the transport whether to write, but its argument is +// built by the caller either way: a template literal interpolating +// `codePoints(payload, 1)` is rendered, handed to electron-log, walked through +// the transports and dropped. A packaged build sets both transports to `info` +// (main.js), so every one of these lines is discarded work there, and the CLI +// emits an OSC title per spinner frame. `LOG_DEBUG_ON` is the guard, the same +// shape as the `if (TRACE.on)` guard the probes on those lines already carry. +// +// This is a source scan, the house pattern for main.js (see +// read-file-for-panel-bounds.test.js): main.js needs an Electron host, so the +// only thing standing between the codebase and an unguarded hot-path debug +// line is a read of the text. + +'use strict'; +const test = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('node:fs'); +const path = require('node:path'); + +// Normalised: core.autocrlf=true and no .gitattributes means a fresh clone can +// hand these tests CRLF while CI stays LF. +const MAIN = fs.readFileSync(path.join(__dirname, '..', 'main.js'), 'utf8').replace(/\r\n/g, '\n'); + +function ptyDataHandler() { + const start = MAIN.indexOf('function wireSessionPty('); + assert.notEqual(start, -1, 'wireSessionPty not found in main.js'); + const end = MAIN.indexOf('\n}\n', start); + assert.notEqual(end, -1, 'end of wireSessionPty not found'); + return MAIN.slice(start, end); +} + +test('LOG_DEBUG_ON follows the transports rather than restating their condition', () => { + const m = MAIN.match(/^const LOG_DEBUG_ON = (.+);$/m); + assert.ok(m, 'LOG_DEBUG_ON must be declared'); + assert.match(m[1], /transports\.file\.level/); + assert.match(m[1], /transports\.console\.level/); + assert.ok( + MAIN.indexOf('const LOG_DEBUG_ON') > MAIN.indexOf('log.transports.console.level ='), + 'the flag must be read after the levels are set', + ); +}); + +test('every debug line on the PTY data path is guarded', () => { + const lines = ptyDataHandler().split('\n'); + const calls = lines.filter(l => l.includes('log.debug(')); + assert.ok(calls.length >= 5, `expected the OSC debug lines to still be there, found ${calls.length}`); + for (const line of calls) { + assert.match( + line.trim(), /^if \(LOG_DEBUG_ON\) log\.debug\(/, + `an unguarded log.debug on the PTY data path builds its message on every frame: ${line.trim()}`, + ); + } +}); + +test('the OSC 0 title line renders code points only under the guard', () => { + const line = ptyDataHandler().split('\n').find(l => l.includes('codePoints(payload, 1)')); + assert.ok(line, 'the OSC 0 debug line must still report the title code point'); + assert.match(line.trim(), /^if \(LOG_DEBUG_ON\) log\.debug\(/); +});