diff --git a/README.md b/README.md index 1c91228..d946d9e 100644 --- a/README.md +++ b/README.md @@ -191,6 +191,22 @@ LOG_FILE=~/.agentboard/agentboard.log # default; set empty to disable file log Console output is pretty-printed in development, JSON in production (`NODE_ENV=production`). File output is always JSON. Set `LOG_FILE=` (empty) to disable file logging. +### Logging Quality Contract + +- Event names must be `snake_case` +- Catch blocks in server runtime paths must either: + - emit a structured log event, or + - be explicitly documented as intentional with `logging-audit:intentional` and a brief rationale +- `logger.warn` and `logger.error` used in catch paths must include useful error context fields (`error_message`, `error_name`, `error_stack`, `code`, etc.) + +Run the logging auditor: + +```bash +bun run audit:logging +``` + +The command fails if high-severity findings are present. + ## Troubleshooting ### "open terminal failed: not a terminal" errors diff --git a/docs/logging-audit.md b/docs/logging-audit.md new file mode 100644 index 0000000..54e78e4 --- /dev/null +++ b/docs/logging-audit.md @@ -0,0 +1,72 @@ +# Logging Quality Audit + +## Scope (Frozen) + +- Runtime server observability only: `src/server/**` +- Excluded: client/UI logs and all test files +- Priority remediation targets for this pass: + - API error paths in `src/server/index.ts` + - DB migration error paths in `src/server/db.ts` + - Intentional silent catches in `src/server/SessionManager.ts` + +## Quality Criteria + +- Event names are `snake_case` +- Catch blocks are either logged or explicitly marked intentional (`logging-audit:intentional`) +- `logger.warn` / `logger.error` in catch paths include error context (`error_message`, `error_name`, `error_stack`, `code`, etc.) + +## Auditor + +- Command: `bun run audit:logging` +- Implementation: + - `scripts/logging-audit.ts` + - `src/server/loggingAudit.ts` + +## Baseline Findings (Before Remediation) + +`bun run audit:logging` reported: + +- `high=10` +- `medium=97` +- `low=0` + +High-severity findings (all fixed in this task): + +1. `src/server/db.ts:414` `catch_without_logging` +2. `src/server/db.ts:581` `catch_without_logging` +3. `src/server/index.ts:830` `catch_without_logging` +4. `src/server/index.ts:882` `catch_without_logging` +5. `src/server/index.ts:916` `catch_without_logging` +6. `src/server/index.ts:978` `catch_without_logging` +7. `src/server/index.ts:1051` `catch_without_logging` +8. `src/server/index.ts:1073` `catch_without_logging` +9. `src/server/index.ts:1097` `catch_without_logging` +10. `src/server/index.ts:1130` `catch_without_logging` + +## Remediation Completed + +- `src/server/index.ts` + - Added structured warning logs for client-log ingestion failures. + - Added structured warning logs for session-preview read failures with session/log path context. + - Added structured warning logs for directory stat/read failures. + - Added structured warning logs for settings parsing failures and upload/clipboard failures. + - Added structured warning logs for websocket payload parse failures and session create/kill/rename/resume error paths. + - Replaced non-snake event `ssh_proxy_onExit` with `ssh_proxy_on_exit`. +- `src/server/db.ts` + - Added migration rollback/failure logging with migration IDs and error details before rethrow. + - Added debug logs for non-fatal data directory permission setup failures. +- `src/server/SessionManager.ts` + - Added debug logs for non-fatal tmux fallback/error paths. + - Marked high-frequency pane-capture silent catch as intentional with `logging-audit:intentional`. +- Supporting runtime modules + - Marked deliberate best-effort catch paths with `logging-audit:intentional` (log discovery/matcher, worker plumbing, and terminal proxies) so silent behavior is explicitly documented. + +## Current Status (After Remediation) + +`bun run audit:logging` now reports: + +- `high=0` +- `medium=0` +- `low=0` + +No outstanding findings in scope. diff --git a/package.json b/package.json index 2b54162..46eeb33 100644 --- a/package.json +++ b/package.json @@ -34,6 +34,7 @@ "lint": "oxlint .", "typecheck": "tsc --noEmit", "test": "bun scripts/test-runner.ts", + "audit:logging": "bun scripts/logging-audit.ts --fail-on=high", "test:coverage": "bun scripts/test-runner.ts --coverage --coverage-reporter=lcov --skip-isolated && bun run coverage:all", "coverage:all": "bun scripts/coverage-all.ts", "test:e2e": "playwright test", diff --git a/scripts/logging-audit.ts b/scripts/logging-audit.ts new file mode 100644 index 0000000..68d3a6f --- /dev/null +++ b/scripts/logging-audit.ts @@ -0,0 +1,78 @@ +import { + formatLoggingAuditReport, + runLoggingAudit, + type LoggingAuditSeverity, +} from '../src/server/loggingAudit' + +interface CliOptions { + failOn: LoggingAuditSeverity | 'none' + json: boolean +} + +const severityRank: Record = { + high: 0, + medium: 1, + low: 2, +} + +function parseArgs(argv: string[]): CliOptions { + let failOn: CliOptions['failOn'] = 'high' + let json = false + + for (const arg of argv) { + if (arg === '--json') { + json = true + continue + } + if (arg.startsWith('--fail-on=')) { + const value = arg.slice('--fail-on='.length) + if (value === 'none' || value === 'high' || value === 'medium' || value === 'low') { + failOn = value + } else { + throw new Error(`Invalid --fail-on value: ${value}`) + } + } + } + + return { failOn, json } +} + +function shouldFail( + highestSeverity: LoggingAuditSeverity | null, + failOn: CliOptions['failOn'] +): boolean { + if (failOn === 'none') { + return false + } + if (highestSeverity === null) { + return false + } + return severityRank[highestSeverity] <= severityRank[failOn] +} + +function findHighestSeverity( + counts: Record +): LoggingAuditSeverity | null { + if (counts.high > 0) return 'high' + if (counts.medium > 0) return 'medium' + if (counts.low > 0) return 'low' + return null +} + +async function main() { + const options = parseArgs(process.argv.slice(2)) + const report = await runLoggingAudit() + + if (options.json) { + console.log(JSON.stringify(report, null, 2)) + } else { + console.log(formatLoggingAuditReport(report)) + } + + const highestSeverity = findHighestSeverity(report.counts) + if (shouldFail(highestSeverity, options.failOn)) { + process.exitCode = 1 + } +} + +await main() diff --git a/src/server/SessionManager.ts b/src/server/SessionManager.ts index 63d0aa7..107e8b0 100644 --- a/src/server/SessionManager.ts +++ b/src/server/SessionManager.ts @@ -74,7 +74,11 @@ export class SessionManager { ensureSession(): void { try { this.runTmux(['has-session', '-t', this.sessionName]) - } catch { + } catch (error) { + logger.debug('tmux_session_missing_create', { + sessionName: this.sessionName, + ...toErrorLogFields(error), + }) this.runTmux(['new-session', '-d', '-s', this.sessionName]) } // Set mouse mode for scroll wheel support (SGR mouse sequences) @@ -98,7 +102,12 @@ export class SessionManager { 'mouse', enabled ? 'on' : 'off', ]) - } catch { + } catch (error) { + logger.debug('tmux_mouse_mode_apply_deferred', { + sessionName: this.sessionName, + enabled, + ...toErrorLogFields(error), + }) // Session doesn't exist yet, will be applied on next ensureSession } } @@ -305,7 +314,11 @@ export class SessionManager { .split('\n') .map((line) => line.trim()) .filter(Boolean) - } catch { + } catch (error) { + logger.debug('tmux_list_sessions_failed', { + sessionName: this.sessionName, + ...toErrorLogFields(error), + }) return [] } } @@ -358,6 +371,10 @@ export class SessionManager { if (!isTmuxFormatError(error)) { throw error } + logger.debug('tmux_window_list_format_fallback', { + sessionName, + ...toErrorLogFields(error), + }) } return this.runTmux([...args, WINDOW_LIST_FORMAT_FALLBACK]) @@ -409,7 +426,11 @@ export class SessionManager { try { const output = this.runTmux(['show-options', '-gv', 'base-index']) return Number.parseInt(output.trim(), 10) || 0 - } catch { + } catch (error) { + logger.debug('tmux_base_index_defaulted', { + sessionName: this.sessionName, + ...toErrorLogFields(error), + }) return 0 } } @@ -427,7 +448,11 @@ export class SessionManager { .split('\n') .map((line) => Number.parseInt(line.trim(), 10)) .filter((n) => !Number.isNaN(n)) - } catch { + } catch (error) { + logger.debug('tmux_window_indices_unavailable', { + sessionName: this.sessionName, + ...toErrorLogFields(error), + }) return [] } } @@ -572,9 +597,26 @@ function capturePaneWithDimensions(tmuxWindow: string): PaneCapture | null { const content = lines.slice(-30).join('\n') return { content, width, height } } catch { + // logging-audit:intentional Pane capture runs at poll cadence; transient + // failures are expected when panes close and logging each one would flood logs. return null } } // Re-export for external use export { detectsPermissionPrompt } from './statusInference' + +function toErrorLogFields(error: unknown): { + error_message: string + error_name?: string + error_stack?: string +} { + if (error instanceof Error) { + return { + error_message: error.message, + error_name: error.name, + error_stack: error.stack, + } + } + return { error_message: String(error) } +} diff --git a/src/server/__tests__/db.test.ts b/src/server/__tests__/db.test.ts index 651afea..3c0bedb 100644 --- a/src/server/__tests__/db.test.ts +++ b/src/server/__tests__/db.test.ts @@ -5,6 +5,7 @@ import fs from 'node:fs' import os from 'node:os' import path from 'node:path' import type { AgentType } from '../../shared/types' +import { logger } from '../logger' const now = new Date('2026-01-01T00:00:00.000Z').toISOString() @@ -190,6 +191,129 @@ describe('db', () => { fs.rmSync(tempDir, { recursive: true, force: true }) }) + test('logs migration failure details before rethrowing', () => { + const tempDir = fs.mkdtempSync(path.join(os.tmpdir(), 'agentboard-migrate-fail-')) + const dbPath = path.join(tempDir, 'agentboard.db') + const legacyDb = new SQLiteDatabase(dbPath) + + legacyDb.exec(` + CREATE TABLE agent_sessions ( + id INTEGER PRIMARY KEY AUTOINCREMENT, + session_id TEXT UNIQUE, + log_file_path TEXT NOT NULL UNIQUE, + project_path TEXT, + agent_type TEXT NOT NULL CHECK (agent_type IN ('claude', 'codex', 'invalid')), + display_name TEXT, + created_at TEXT NOT NULL, + last_activity_at TEXT NOT NULL, + current_window TEXT, + session_source TEXT NOT NULL CHECK (session_source IN ('log', 'synthetic')) + ); + `) + + // Invalid agent_type for the new schema forces migration INSERT failure. + legacyDb.exec(` + INSERT INTO agent_sessions ( + session_id, + log_file_path, + project_path, + agent_type, + display_name, + created_at, + last_activity_at, + current_window, + session_source + ) VALUES ( + 'session-invalid', + '/tmp/invalid.jsonl', + '/tmp/project', + 'invalid', + 'invalid', + '${now}', + '${now}', + NULL, + 'log' + ); + `) + legacyDb.close() + + const originalLoggerError = logger.error + const calls: Array<{ event: string; data?: Record }> = [] + logger.error = ((event: string, data?: Record) => { + calls.push({ event, data }) + }) as typeof logger.error + + try { + expect(() => initDatabase({ path: dbPath })).toThrow() + } finally { + logger.error = originalLoggerError + fs.rmSync(tempDir, { recursive: true, force: true }) + } + + const failureLog = calls.find( + (call) => + call.event === 'db_migration_failed' && + call.data?.migration === 'remove_session_source_column' + ) + expect(failureLog).toBeDefined() + expect(typeof failureLog?.data?.error_message).toBe('string') + }) + + test('logs non-fatal data-dir permission setup failures', () => { + const tempDir = fs.mkdtempSync(path.join(os.tmpdir(), 'agentboard-data-dir-')) + const dbPath = path.join(tempDir, 'nested', 'agentboard.db') + const dataDir = path.dirname(dbPath) + fs.mkdirSync(dataDir, { recursive: true }) + + const originalMkdirSync = fs.mkdirSync + const originalChmodSync = fs.chmodSync + const originalLoggerDebug = logger.debug + const calls: Array<{ event: string; data?: Record }> = [] + + fs.mkdirSync = ((dir: fs.PathLike, options?: fs.MakeDirectoryOptions) => { + if (String(dir) === dataDir) { + throw new Error('mkdir denied') + } + return originalMkdirSync(dir, options) + }) as typeof fs.mkdirSync + + fs.chmodSync = ((targetPath: fs.PathLike, mode: fs.Mode) => { + if (String(targetPath) === dataDir) { + throw new Error('chmod denied') + } + return originalChmodSync(targetPath, mode) + }) as typeof fs.chmodSync + + logger.debug = ((event: string, data?: Record) => { + calls.push({ event, data }) + }) as typeof logger.debug + + try { + const localDb = initDatabase({ path: dbPath }) + localDb.close() + } finally { + fs.mkdirSync = originalMkdirSync + fs.chmodSync = originalChmodSync + logger.debug = originalLoggerDebug + fs.rmSync(tempDir, { recursive: true, force: true }) + } + + expect( + calls.some((call) => + call.event === 'db_data_dir_create_failed' && + call.data?.dir === dataDir && + call.data?.error_message === 'mkdir denied' + ) + ).toBe(true) + expect( + calls.some((call) => + call.event === 'db_data_dir_chmod_failed' && + call.data?.dir === dataDir && + call.data?.error_message === 'chmod denied' + ) + ).toBe(true) + }) + test('app settings get/set', () => { // Initially null expect(db.getAppSetting('test_key')).toBeNull() diff --git a/src/server/__tests__/isolated/indexHandlers.test.ts b/src/server/__tests__/isolated/indexHandlers.test.ts index 77b1905..843e95d 100644 --- a/src/server/__tests__/isolated/indexHandlers.test.ts +++ b/src/server/__tests__/isolated/indexHandlers.test.ts @@ -31,6 +31,11 @@ let serveOptions: Parameters[0] | null = null let spawnSyncImpl: typeof Bun.spawnSync let writeImpl: typeof Bun.write let replaceSessionsCalls: Session[][] = [] +let loggerCalls: Array<{ + level: 'debug' | 'info' | 'warn' | 'error' + event: string + data?: Record +}> = [] let dbState: { records: Map nextId: number @@ -345,6 +350,25 @@ mock.module('../../SessionManager', () => ({ mock.module('../../SessionRegistry', () => ({ SessionRegistry: SessionRegistryMock, })) +mock.module('../../logger', () => ({ + logger: { + debug: (event: string, data?: Record) => { + loggerCalls.push({ level: 'debug', event, data }) + }, + info: (event: string, data?: Record) => { + loggerCalls.push({ level: 'info', event, data }) + }, + warn: (event: string, data?: Record) => { + loggerCalls.push({ level: 'warn', event, data }) + }, + error: (event: string, data?: Record) => { + loggerCalls.push({ level: 'error', event, data }) + }, + }, + logLevel: 'info', + flushLogger: () => {}, + closeLogger: () => {}, +})) class TerminalProxyErrorMock extends Error { code: string retryable: boolean @@ -417,6 +441,7 @@ async function loadIndex() { beforeEach(() => { serveOptions = null replaceSessionsCalls = [] + loggerCalls = [] TerminalProxyMock.instances = [] SessionManagerMock.instance = null SessionRegistryMock.instance = null @@ -553,6 +578,12 @@ describe('server message handlers', () => { type: 'error', message: 'Invalid message payload', }) + expect( + loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'ws_message_parse_failed' + ) + ).toBe(true) expect(sent[1]).toEqual({ type: 'error', message: 'Unknown message type' }) expect(sent[2]).toEqual({ type: 'terminal-error', @@ -617,6 +648,13 @@ describe('server message handlers', () => { type: 'error', message: 'explode', }) + expect( + loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'session_create_failed' && + call.data?.projectPath === '/tmp/new' + ) + ).toBe(true) }) test('returns errors for kill and rename when sessions are missing', async () => { @@ -724,6 +762,20 @@ describe('server message handlers', () => { expect(sent[sent.length - 2]).toEqual({ type: 'kill-failed', sessionId: baseSession.id, message: 'boom' }) expect(sent[sent.length - 1]).toEqual({ type: 'error', message: 'nope' }) + expect( + loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'session_kill_failed' && + call.data?.sessionId === baseSession.id + ) + ).toBe(true) + expect( + loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'session_rename_failed' && + call.data?.sessionId === baseSession.id + ) + ).toBe(true) }) test('blocks remote kill when remoteAllowControl is false', async () => { @@ -2113,6 +2165,47 @@ describe('server message handlers', () => { expect(registryInstance.sessions[0]?.id).toBe(createdSession.id) }) + test('logs warning when session resume creation fails', async () => { + const { serveOptions } = await loadIndex() + const { ws, sent } = createWs() + const websocket = serveOptions.websocket + if (!websocket) { + throw new Error('WebSocket handlers not configured') + } + + seedRecord( + makeRecord({ + sessionId: 'resume-fail', + displayName: 'resume-fail', + projectPath: '/tmp/resume-fail', + currentWindow: null, + }) + ) + + sessionManagerState.createWindow = () => { + throw new Error('resume exploded') + } + + websocket.message?.( + ws as never, + JSON.stringify({ type: 'session-resume', sessionId: 'resume-fail' }) + ) + + expect(sent[sent.length - 1]).toEqual({ + type: 'session-resume-result', + sessionId: 'resume-fail', + ok: false, + error: { code: 'RESUME_FAILED', message: 'resume exploded' }, + }) + expect( + loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'session_resume_failed' && + call.data?.sessionId === 'resume-fail' + ) + ).toBe(true) + }) + test('websocket close disposes all terminals', async () => { const { serveOptions } = await loadIndex() const websocket = serveOptions.websocket @@ -2468,6 +2561,11 @@ describe('server fetch handlers', () => { expect(response.status).toBe(404) const payload = (await response.json()) as { error: string } expect(payload.error).toBe('Log file not found') + expect(loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'session_preview_read_failed' && + call.data?.sessionId === 'missing-log' + )).toBe(true) }) }) @@ -2549,6 +2647,13 @@ describe('server startup side effects', () => { expect(response.status).toBe(200) const payload = (await response.json()) as { ok: boolean } expect(payload.ok).toBe(true) + const loggedClientEvent = loggerCalls.find( + (call) => + call.level === 'debug' && + call.event === 'client_log_event' + ) + expect(loggedClientEvent).toBeDefined() + expect(loggedClientEvent?.data?.client_event).toBe('test_event') }) test('/api/client-log handles malformed body gracefully', async () => { @@ -2576,6 +2681,10 @@ describe('server startup side effects', () => { expect(response.status).toBe(200) const payload = (await response.json()) as { ok: boolean } expect(payload.ok).toBe(true) + expect(loggerCalls.some((call) => + call.level === 'warn' && + call.event === 'client_log_ingest_failed' + )).toBe(true) }) test('does not run sync window verification before startup is ready', async () => { diff --git a/src/server/__tests__/loggingAudit.test.ts b/src/server/__tests__/loggingAudit.test.ts new file mode 100644 index 0000000..6c523cf --- /dev/null +++ b/src/server/__tests__/loggingAudit.test.ts @@ -0,0 +1,246 @@ +import { afterEach, describe, expect, test } from 'bun:test' +import fs from 'node:fs/promises' +import os from 'node:os' +import path from 'node:path' +import { + formatLoggingAuditReport, + runLoggingAudit, +} from '../loggingAudit' + +const tempDirs: string[] = [] + +afterEach(async () => { + for (const dir of tempDirs.splice(0)) { + await fs.rm(dir, { recursive: true, force: true }) + } +}) + +async function createServerFile( + rootDir: string, + relativePath: string, + content: string +): Promise { + const fullPath = path.join(rootDir, relativePath) + await fs.mkdir(path.dirname(fullPath), { recursive: true }) + await fs.writeFile(fullPath, content) +} + +async function createTempRoot(): Promise { + const rootDir = await fs.mkdtemp(path.join(os.tmpdir(), 'logging-audit-')) + tempDirs.push(rootDir) + return rootDir +} + +describe('loggingAudit', () => { + test('flags unlogged catch blocks in high-impact files', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/index.ts', + ` + const app = { get: (..._args: unknown[]) => {} } + + export function handler() { + app.get('/api/thing', async () => { + try { + throw new Error('boom') + } catch { + return 'x' + } + }) + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toContainEqual({ + severity: 'high', + rule: 'catch_without_logging', + file: 'src/server/index.ts', + line: 8, + message: 'catch block does not emit a structured logger event', + }) + }) + + test('supports intentional catch suppression markers', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/SessionManager.ts', + ` + export function syncState() { + try { + throw new Error('boom') + } catch { + /* logging-audit:intentional */ + return null + } + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toEqual([]) + }) + + test('flags non-snake events and missing catch error context', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/db.ts', + ` + import { logger } from './logger' + + export function migrate() { + try { + throw new Error('bad') + } catch (error) { + logger.warn('BadEventName', { detail: 'missing error fields' }) + } + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toEqual([ + { + severity: 'high', + rule: 'missing_error_context', + file: 'src/server/db.ts', + line: 8, + message: 'logger.warn("BadEventName") is missing error context fields', + }, + { + severity: 'medium', + rule: 'non_snake_case_event_name', + file: 'src/server/db.ts', + line: 8, + message: 'event "BadEventName" is not snake_case', + }, + ]) + + const output = formatLoggingAuditReport(report) + expect(output).toContain('HIGH missing_error_context src/server/db.ts:8') + expect(output).toContain('MEDIUM non_snake_case_event_name src/server/db.ts:8') + }) + + test('does not count logger calls inside nested functions as catch logging', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/index.ts', + ` + import { logger } from './logger' + const app = { get: (..._args: unknown[]) => {} } + + export function handler() { + app.get('/api/thing', async () => { + try { + throw new Error('boom') + } catch { + const deferred = () => { + logger.warn('deferred_error', { error_message: 'later' }) + } + return deferred + } + }) + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toContainEqual({ + severity: 'high', + rule: 'catch_without_logging', + file: 'src/server/index.ts', + line: 9, + message: 'catch block does not emit a structured logger event', + }) + }) + + test('does not treat suppression markers inside strings as intentional', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/SessionManager.ts', + ` + export function syncState() { + try { + throw new Error('boom') + } catch { + const note = 'logging-audit:intentional' + return note + } + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toContainEqual({ + severity: 'medium', + rule: 'catch_without_logging', + file: 'src/server/SessionManager.ts', + line: 5, + message: 'catch block does not emit a structured logger event', + }) + }) + + test('flags non-object logger context that lacks error signals', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/index.ts', + ` + import { logger } from './logger' + const app = { get: (..._args: unknown[]) => {} } + + export function handler() { + app.get('/api/thing', async () => { + try { + throw new Error('boom') + } catch (error) { + const details = { reason: 'none' } + logger.error('route_failed', details) + return error + } + }) + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toContainEqual({ + severity: 'high', + rule: 'missing_error_context', + file: 'src/server/index.ts', + line: 11, + message: 'logger.error("route_failed") is missing error context fields', + }) + }) + + test('supports logger bracket syntax in catch logging', async () => { + const rootDir = await createTempRoot() + await createServerFile( + rootDir, + 'src/server/index.ts', + ` + import { logger } from './logger' + const app = { get: (..._args: unknown[]) => {} } + + export function handler() { + app.get('/api/thing', async () => { + try { + throw new Error('boom') + } catch (error) { + logger['warn']('route_warned', { error_message: String(error) }) + return null + } + }) + } + ` + ) + + const report = await runLoggingAudit({ rootDir }) + expect(report.findings).toEqual([]) + }) +}) diff --git a/src/server/db.ts b/src/server/db.ts index d33ccea..ab30c24 100644 --- a/src/server/db.ts +++ b/src/server/db.ts @@ -2,6 +2,7 @@ import fs from 'node:fs' import path from 'node:path' import { Database as SQLiteDatabase } from 'bun:sqlite' import type { AgentType } from '../shared/types' +import { logger } from './logger' import { resolveProjectPath } from './paths' export interface AgentSessionRecord { @@ -328,14 +329,20 @@ function ensureDataDir(dbPath: string) { try { fs.mkdirSync(dir, { recursive: true, mode: 0o700 }) - } catch { - // Ignore mkdir failures; SQLite will surface errors when opening + } catch (error) { + logger.debug('db_data_dir_create_failed', { + dir, + ...toErrorLogFields(error), + }) } try { fs.chmodSync(dir, 0o700) - } catch { - // Ignore chmod failures + } catch (error) { + logger.debug('db_data_dir_chmod_failed', { + dir, + ...toErrorLogFields(error), + }) } } @@ -412,7 +419,7 @@ function migrateDatabase(db: SQLiteDatabase) { db.exec('DROP TABLE agent_sessions_old') db.exec('COMMIT') } catch (error) { - db.exec('ROLLBACK') + rollbackMigration(db, 'remove_session_source_column', error) throw error } } @@ -579,11 +586,47 @@ function migratePiAgentType(db: SQLiteDatabase) { db.exec('DROP TABLE agent_sessions_old_pi_migrate') db.exec('COMMIT') } catch (error) { - db.exec('ROLLBACK') + rollbackMigration(db, 'add_pi_agent_type_constraint', error) throw error } } +function rollbackMigration( + db: SQLiteDatabase, + migration: string, + originalError: unknown +) { + try { + db.exec('ROLLBACK') + } catch (rollbackError) { + logger.error('db_migration_rollback_failed', { + migration, + ...toErrorLogFields(rollbackError), + original_error_message: toErrorLogFields(originalError).error_message, + }) + } + + logger.error('db_migration_failed', { + migration, + ...toErrorLogFields(originalError), + }) +} + +function toErrorLogFields(error: unknown): { + error_message: string + error_name?: string + error_stack?: string +} { + if (error instanceof Error) { + return { + error_message: error.message, + error_name: error.name, + error_stack: error.stack, + } + } + return { error_message: String(error) } +} + function getColumnNames(db: SQLiteDatabase, tableName: string): string[] { const rows = db .prepare(`PRAGMA table_info(${tableName})`) diff --git a/src/server/index.ts b/src/server/index.ts index 134e6c8..d8249bc 100644 --- a/src/server/index.ts +++ b/src/server/index.ts @@ -60,7 +60,11 @@ function checkPortAvailable(port: number): void { stdout: 'pipe', stderr: 'pipe', }) - } catch { + } catch (error) { + logger.debug('port_check_failed', { + port, + ...toErrorLogFields(error), + }) return } const pids = result.stdout?.toString().trim() ?? '' @@ -75,7 +79,12 @@ function checkPortAvailable(port: number): void { stderr: 'pipe', }) processName = nameResult.stdout?.toString().trim() || 'unknown' - } catch { + } catch (error) { + logger.debug('port_process_lookup_failed', { + port, + pid, + ...toErrorLogFields(error), + }) } logger.error('port_in_use', { port, pid, processName }) process.exit(1) @@ -99,7 +108,11 @@ function getTailscaleIp(): string | null { const ip = result.stdout.toString().trim() if (ip) return ip } - } catch { + } catch (error) { + logger.debug('tailscale_ip_lookup_failed', { + path: tsPath, + ...toErrorLogFields(error), + }) // Try next path } } @@ -125,7 +138,11 @@ function pruneOrphanedWsSessions(): void { stderr: 'pipe', } ) - } catch { + } catch (error) { + logger.debug('ws_sessions_prune_list_failed', { + prefix, + ...toErrorLogFields(error), + }) return } @@ -155,7 +172,11 @@ function pruneOrphanedWsSessions(): void { if (killResult.exitCode === 0) { pruned += 1 } - } catch { + } catch (error) { + logger.debug('ws_sessions_prune_kill_failed', { + session: name, + ...toErrorLogFields(error), + }) // Ignore kill errors } } @@ -175,6 +196,33 @@ function createConnectionId(): string { return `${Date.now().toString(36)}-${Math.random().toString(36).slice(2, 8)}` } +function toErrorLogFields(error: unknown): { + error_message: string + error_name?: string + error_stack?: string +} { + if (error instanceof Error) { + return { + error_message: error.message, + error_name: error.name, + error_stack: error.stack, + } + } + return { error_message: String(error) } +} + +function normalizeClientEventName(rawEvent: unknown): string { + if (typeof rawEvent !== 'string') { + return 'unknown' + } + const normalized = rawEvent + .trim() + .toLowerCase() + .replace(/[^a-z0-9]+/g, '_') + .replace(/^_+|_+$/g, '') + return normalized || 'unknown' +} + checkPortAvailable(config.port) ensureTmux() pruneOrphanedWsSessions() @@ -534,7 +582,14 @@ function hydrateSessionsWithAgentSessions( }) // Kill any leftover dead window from remain-on-exit if (currentWindow) { - try { sessionManager.killWindow(currentWindow) } catch { /* may already be gone */ } + try { + sessionManager.killWindow(currentWindow) + } catch (error) { + logger.debug('orphan_window_cleanup_failed', { + tmuxWindow: currentWindow, + ...toErrorLogFields(error), + }) + } } const orphanedSession = db.orphanSession(agentSession.sessionId) if (orphanedSession) { @@ -824,11 +879,28 @@ registry.on('agent-sessions', ({ active, inactive }) => { app.post('/api/client-log', async (c) => { try { - const body = await c.req.json() as { level?: string; event: string; data?: Record } - const level = body.level === 'warn' || body.level === 'error' || body.level === 'info' ? body.level : 'debug' - logger[level]('client_' + body.event, body.data) - } catch { - // ignore malformed + const body = await c.req.json() as { + level?: string + event?: string + data?: Record + } + const level = body.level === 'warn' || body.level === 'error' || body.level === 'info' + ? body.level + : 'debug' + const normalizedEvent = normalizeClientEventName(body.event) + logger[level]('client_log_event', { + client_event: normalizedEvent, + client_event_raw: body.event, + path: c.req.path, + method: c.req.method, + data: body.data, + }) + } catch (error) { + logger.warn('client_log_ingest_failed', { + path: c.req.path, + method: c.req.method, + ...toErrorLogFields(error), + }) } return c.json({ ok: true }) }) @@ -881,6 +953,12 @@ app.get('/api/session-preview/:sessionId', async (c) => { }) } catch (error) { const err = error as NodeJS.ErrnoException + logger.warn('session_preview_read_failed', { + sessionId, + logPath, + code: err.code, + ...toErrorLogFields(error), + }) if (err.code === 'ENOENT') { return c.json({ error: 'Log file not found' }, 404) } @@ -915,6 +993,12 @@ app.get('/api/directories', async (c) => { stats = await fs.stat(resolved) } catch (error) { const err = error as NodeJS.ErrnoException + logger.warn('directories_stat_failed', { + requestedPath: trimmedPath, + resolvedPath: resolved, + code: err.code, + ...toErrorLogFields(error), + }) if (err.code === 'ENOENT' || err.code === 'ENOTDIR') { const payload: DirectoryErrorResponse = { error: 'not_found', @@ -977,6 +1061,12 @@ app.get('/api/directories', async (c) => { }) } catch (error) { const err = error as NodeJS.ErrnoException + logger.warn('directories_read_failed', { + requestedPath: trimmedPath, + resolvedPath: resolved, + code: err.code, + ...toErrorLogFields(error), + }) if (err.code === 'EACCES' || err.code === 'EPERM') { const payload: DirectoryErrorResponse = { error: 'forbidden', @@ -1048,7 +1138,12 @@ app.put('/api/settings/tmux-mouse-mode', async (c) => { db.setAppSetting(TMUX_MOUSE_MODE_KEY, String(body.enabled)) sessionManager.setMouseMode(body.enabled) return c.json({ enabled: body.enabled }) - } catch { + } catch (error) { + logger.warn('tmux_mouse_mode_update_failed', { + path: c.req.path, + method: c.req.method, + ...toErrorLogFields(error), + }) return c.json({ error: 'Invalid request body' }, 400) } }) @@ -1070,7 +1165,12 @@ app.put('/api/settings/inactive-max-age-hours', async (c) => { // Re-broadcast agent sessions with new max age updateAgentSessions() return c.json({ hours }) - } catch { + } catch (error) { + logger.warn('inactive_max_age_update_failed', { + path: c.req.path, + method: c.req.method, + ...toErrorLogFields(error), + }) return c.json({ error: 'Invalid request body' }, 400) } }) @@ -1095,6 +1195,11 @@ app.post('/api/paste-image', async (c) => { return c.json({ path: filepath }) } catch (error) { + logger.warn('paste_image_upload_failed', { + path: c.req.path, + method: c.req.method, + ...toErrorLogFields(error), + }) return c.json( { error: error instanceof Error ? error.message : 'Upload failed' }, 500 @@ -1127,7 +1232,12 @@ app.get('/api/clipboard-file-path', async (c) => { } } return c.json({ path: null }) - } catch { + } catch (error) { + logger.warn('clipboard_file_path_read_failed', { + path: c.req.path, + method: c.req.method, + ...toErrorLogFields(error), + }) return c.json({ path: null }) } }) @@ -1283,7 +1393,12 @@ function handleMessage( let message: ClientMessage try { message = JSON.parse(text) as ClientMessage - } catch { + } catch (error) { + logger.warn('ws_message_parse_failed', { + connectionId: ws.data.connectionId, + payload_bytes: text.length, + ...toErrorLogFields(error), + }) send(ws, { type: 'error', message: 'Invalid message payload' }) return } @@ -1311,6 +1426,12 @@ function handleMessage( refreshSessions() send(ws, { type: 'session-created', session: created }) } catch (error) { + logger.warn('session_create_failed', { + connectionId: ws.data.connectionId, + projectPath: message.projectPath, + requestedName: message.name, + ...toErrorLogFields(error), + }) send(ws, { type: 'error', message: @@ -1515,6 +1636,13 @@ async function handleRemoteCreate( registry.replaceSessions([createdSession, ...currentSessions]) send(ws, { type: 'session-created', session: createdSession }) } catch (error) { + logger.warn('remote_session_create_failed', { + host, + connectionId: ws.data.connectionId, + projectPath, + requestedName: name, + ...toErrorLogFields(error), + }) send(ws, { type: 'error', message: error instanceof Error ? error.message : 'Unable to create remote session', @@ -1539,7 +1667,14 @@ async function handleCancelCopyMode(sessionId: string, ws: ServerWebSocket) { const remaining = registry.getAll().filter((item) => item.id !== sessionId) registry.replaceSessions(remaining) } catch (error) { + logger.warn('remote_session_kill_failed', { + sessionId, + host: session.host, + tmuxWindow: session.tmuxWindow, + ...toErrorLogFields(error), + }) send(ws, { type: 'kill-failed', sessionId, @@ -1637,6 +1785,11 @@ async function handleKill(sessionId: string, ws: ServerWebSocket) { registry.replaceSessions(remaining) refreshSessions() } catch (error) { + logger.warn('session_kill_failed', { + sessionId, + tmuxWindow: session.tmuxWindow, + ...toErrorLogFields(error), + }) send(ws, { type: 'kill-failed', sessionId, @@ -1692,6 +1845,13 @@ async function handleRename( ) registry.replaceSessions(nextSessions) } catch (error) { + logger.warn('remote_session_rename_failed', { + sessionId, + host: session.host, + tmuxWindow: session.tmuxWindow, + requestedName: trimmed, + ...toErrorLogFields(error), + }) send(ws, { type: 'error', message: error instanceof Error ? error.message : 'Unable to rename remote session', @@ -1704,6 +1864,12 @@ async function handleRename( sessionManager.renameWindow(session.tmuxWindow, newName) refreshSessions() } catch (error) { + logger.warn('session_rename_failed', { + sessionId, + tmuxWindow: session.tmuxWindow, + requestedName: newName, + ...toErrorLogFields(error), + }) send(ws, { type: 'error', message: @@ -1819,7 +1985,13 @@ function resurrectPinnedSessions() { resurrectedSessionGrace.set(record.sessionId, Date.now()) try { sessionManager.setWindowOption(created.tmuxWindow, 'remain-on-exit', 'failed') - } catch { /* non-fatal — older tmux may not support 'failed' value */ } + } catch (error) { + logger.debug('remain_on_exit_set_failed', { + sessionId: record.sessionId, + tmuxWindow: created.tmuxWindow, + ...toErrorLogFields(error), + }) + } db.updateSession(record.sessionId, { currentWindow: created.tmuxWindow, displayName: created.name, @@ -1927,6 +2099,11 @@ function handleSessionResume( window: created.tmuxWindow, }) } catch (error) { + logger.warn('session_resume_failed', { + sessionId, + requestedName: message.name, + ...toErrorLogFields(error), + }) const err: ResumeError = { code: 'RESUME_FAILED', message: @@ -2023,6 +2200,7 @@ async function ensurePersistentTerminal( if (ws.data.terminal === terminal) { ws.data.terminal = null } + /* logging-audit:intentional Error is propagated to attach handler for contextual logging. */ throw error } } @@ -2057,6 +2235,7 @@ async function ensureCorrectProxyType( ws.data.terminal = null ws.data.terminalHost = null } + /* logging-audit:intentional Error is propagated to attach handler for contextual logging. */ throw error } } @@ -2113,7 +2292,7 @@ async function createAndStartSshProxy( // Guard: skip if this proxy was already replaced if (ws.data.terminal !== terminal) return const sessionId = ws.data.currentSessionId - logger.warn('ssh_proxy_onExit', { + logger.warn('ssh_proxy_on_exit', { sessionName, sessionId, host, @@ -2155,6 +2334,7 @@ async function createAndStartSshProxy( ws.data.terminal = null ws.data.terminalHost = null } + /* logging-audit:intentional Error is propagated to attach handler for contextual logging. */ throw error } } @@ -2207,6 +2387,7 @@ async function attachTerminalPersistent( terminal = await ensureCorrectProxyType(ws, session, attachSeq) if (!terminal) return } catch (error) { + /* logging-audit:intentional handleTerminalError sends structured failure telemetry for this path. */ if (sockets.has(ws) && isTerminalAttachCurrent(ws, attachSeq)) { handleTerminalError(ws, sessionId, error, 'ERR_TMUX_ATTACH_FAILED') } @@ -2295,6 +2476,7 @@ function captureTmuxHistory(target: string): string | null { } return output } catch { + /* logging-audit:intentional Scrollback capture is best-effort and silently degrades to live output only. */ return null } } @@ -2316,7 +2498,13 @@ async function runRemoteTmux(host: string, args: string[]): Promise<{ exitCode: const opts = sshOptionsForHost() const proc = Bun.spawn(['ssh', ...opts, host, remoteCmd], { stdout: 'pipe', stderr: 'pipe' }) - const timeout = setTimeout(() => { try { proc.kill() } catch {} }, 10_000) + const timeout = setTimeout(() => { + try { + proc.kill() + } catch { + /* logging-audit:intentional Process may already have exited before timeout cleanup. */ + } + }, 10_000) try { const [exitCode, stdout, stderr] = await Promise.all([ proc.exited, @@ -2333,7 +2521,13 @@ async function runRemoteSsh(host: string, remoteCmd: string): Promise<{ exitCode const opts = sshOptionsForHost() const proc = Bun.spawn(['ssh', ...opts, host, remoteCmd], { stdout: 'pipe', stderr: 'pipe' }) - const timeout = setTimeout(() => { try { proc.kill() } catch {} }, 10_000) + const timeout = setTimeout(() => { + try { + proc.kill() + } catch { + /* logging-audit:intentional Process may already have exited before timeout cleanup. */ + } + }, 10_000) try { const [exitCode, stdout, stderr] = await Promise.all([ proc.exited, @@ -2354,6 +2548,7 @@ async function captureTmuxHistoryRemote(target: string, host: string): Promise | null { if (!parsed || typeof parsed !== 'object') return null return parsed } catch { + /* logging-audit:intentional */ return null } } diff --git a/src/server/logMatchWorker.ts b/src/server/logMatchWorker.ts index 0b627f1..7a28af7 100644 --- a/src/server/logMatchWorker.ts +++ b/src/server/logMatchWorker.ts @@ -183,6 +183,7 @@ export function handleMatchWorkerRequest( profile, } } catch (error) { + /* logging-audit:intentional */ return { id: payload.id, type: 'error', diff --git a/src/server/logMatchWorkerClient.ts b/src/server/logMatchWorkerClient.ts index dd63d59..a2ffa08 100644 --- a/src/server/logMatchWorkerClient.ts +++ b/src/server/logMatchWorkerClient.ts @@ -47,6 +47,7 @@ export class LogMatchWorkerClient { try { await this.readyPromise } catch (error) { + /* logging-audit:intentional */ // Worker failed to initialize - restart and retry once if (error instanceof WorkerInitError) { if (this.disposed) { diff --git a/src/server/logMatcher.ts b/src/server/logMatcher.ts index 6ac8e98..0a1cfc9 100644 --- a/src/server/logMatcher.ts +++ b/src/server/logMatcher.ts @@ -271,6 +271,7 @@ export function hasMessageInValidUserContext( } continue } catch { + /* logging-audit:intentional */ // Fall back to regex matching for non-JSON lines. } @@ -400,6 +401,7 @@ function readLogTail(logPath: string, byteLimit = DEFAULT_LOG_TAIL_BYTES): strin fs.closeSync(fd) } } catch { + /* logging-audit:intentional */ return '' } } @@ -789,6 +791,7 @@ function parseRgMatchLines(output: string): number[] { try { entry = JSON.parse(trimmed) } catch { + /* logging-audit:intentional */ continue } const record = entry as { type?: string; data?: { line_number?: number } } @@ -1218,6 +1221,7 @@ export function readLogContent( return content } catch { + /* logging-audit:intentional */ return '' } } @@ -1242,6 +1246,7 @@ export function extractLogText( try { entry = JSON.parse(trimmed) } catch { + /* logging-audit:intentional */ continue } const extracted = extractTextFromEntry(entry, mode) @@ -1331,6 +1336,7 @@ function extractLastConversationFromLines(lines: string[]): ConversationPair { try { entry = JSON.parse(lines[i]) } catch { + /* logging-audit:intentional */ continue } const roleText = extractRoleTextFromEntry(entry) @@ -1423,6 +1429,7 @@ export function extractLastEntryTimestamp( } } } catch { + /* logging-audit:intentional */ // Skip malformed lines } } diff --git a/src/server/logWatcher.ts b/src/server/logWatcher.ts index 10916fc..9836705 100644 --- a/src/server/logWatcher.ts +++ b/src/server/logWatcher.ts @@ -72,6 +72,7 @@ export class LogWatcher { try { watcher.close() } catch { + /* logging-audit:intentional */ // Ignore close errors } } diff --git a/src/server/logger.ts b/src/server/logger.ts index 8734c72..1998f00 100644 --- a/src/server/logger.ts +++ b/src/server/logger.ts @@ -45,6 +45,7 @@ function hasPinoPretty(): boolean { require.resolve('pino-pretty') return true } catch { + /* logging-audit:intentional */ return false } } @@ -75,6 +76,7 @@ function createLogger(): pino.Logger { return pino({ level: logLevel, transport: { targets } }) } catch { + /* logging-audit:intentional */ // Fall through to production logger (compiled binary or missing pino-pretty) } } @@ -99,7 +101,10 @@ function createLogger(): pino.Logger { { level: logLevel, stream: fileDestination }, ] return pino(baseOptions, pino.multistream(streams)) - } catch { /* fall through */ } + } catch { + /* logging-audit:intentional */ + /* fall through */ + } } const streams: pino.StreamEntry[] = [ @@ -113,7 +118,10 @@ function createLogger(): pino.Logger { if (canPretty) { try { return pino(baseOptions, pino.transport({ target: 'pino-pretty', options: PRETTY_OPTIONS })) - } catch { /* fall through */ } + } catch { + /* logging-audit:intentional */ + /* fall through */ + } } return pino(baseOptions) } diff --git a/src/server/loggingAudit.ts b/src/server/loggingAudit.ts new file mode 100644 index 0000000..0d296e1 --- /dev/null +++ b/src/server/loggingAudit.ts @@ -0,0 +1,614 @@ +import fs from 'node:fs' +import fsp from 'node:fs/promises' +import path from 'node:path' +import ts from 'typescript' + +export type LoggingAuditSeverity = 'high' | 'medium' | 'low' + +export type LoggingAuditRule = + | 'catch_without_logging' + | 'non_snake_case_event_name' + | 'missing_error_context' + +export interface LoggingAuditFinding { + severity: LoggingAuditSeverity + rule: LoggingAuditRule + file: string + line: number + message: string +} + +export interface LoggingAuditReport { + scannedFiles: number + findings: LoggingAuditFinding[] + counts: Record +} + +export interface LoggingAuditOptions { + rootDir?: string + serverDir?: string + files?: string[] +} + +const SNAKE_CASE_EVENT = /^[a-z0-9]+(?:_[a-z0-9]+)*$/ +const LOGGER_LEVELS = new Set(['debug', 'info', 'warn', 'error'] as const) +const ERROR_CONTEXT_FIELDS = new Set([ + 'error', + 'error_name', + 'error_message', + 'error_stack', + 'message', + 'code', + 'cause', + 'stack', + 'name', +]) +const CATCH_SUPPRESSION_MARKER = /logging-audit:\s*(ignore|intentional)/i +const APP_ROUTE_METHODS = new Set(['get', 'post', 'put', 'patch', 'delete']) +const KNOWN_LOGGING_WRAPPERS = new Set(['rollbackMigration']) +const COMMENT_PATTERN = /\/\/[^\n]*|\/\*[\s\S]*?\*\//g +const ERROR_SIGNAL_PATTERN = /(error|err|exception|cause|stack|code|message)/i + +type LoggerLevel = 'debug' | 'info' | 'warn' | 'error' | 'unknown' + +interface LoggerCall { + level: LoggerLevel + eventArg: ts.Expression | undefined + dataArg: ts.Expression | undefined + node: ts.CallExpression +} + +const severityRank: Record = { + high: 0, + medium: 1, + low: 2, +} + +export async function runLoggingAudit( + options: LoggingAuditOptions = {} +): Promise { + const rootDir = path.resolve(options.rootDir ?? process.cwd()) + const serverDir = path.resolve(options.serverDir ?? path.join(rootDir, 'src/server')) + const files = options.files + ? options.files.map((file) => path.resolve(rootDir, file)).toSorted() + : await listServerFiles(serverDir) + + const findings: LoggingAuditFinding[] = [] + for (const filePath of files) { + findings.push(...auditFile(filePath, rootDir)) + } + findings.sort(compareFindings) + + return { + scannedFiles: files.length, + findings, + counts: countBySeverity(findings), + } +} + +export function formatLoggingAuditReport(report: LoggingAuditReport): string { + const lines = [ + `logging_audit scanned_files=${report.scannedFiles} high=${report.counts.high} medium=${report.counts.medium} low=${report.counts.low}`, + ] + + if (report.findings.length === 0) { + lines.push('logging_audit_result clean') + return lines.join('\n') + } + + for (const finding of report.findings) { + lines.push( + [ + finding.severity.toUpperCase(), + finding.rule, + `${finding.file}:${finding.line}`, + finding.message, + ].join(' ') + ) + } + + return lines.join('\n') +} + +function compareFindings(a: LoggingAuditFinding, b: LoggingAuditFinding): number { + if (severityRank[a.severity] !== severityRank[b.severity]) { + return severityRank[a.severity] - severityRank[b.severity] + } + if (a.file !== b.file) return a.file.localeCompare(b.file) + if (a.line !== b.line) return a.line - b.line + if (a.rule !== b.rule) return a.rule.localeCompare(b.rule) + return a.message.localeCompare(b.message) +} + +function countBySeverity(findings: LoggingAuditFinding[]) { + const counts: Record = { + high: 0, + medium: 0, + low: 0, + } + for (const finding of findings) { + counts[finding.severity] += 1 + } + return counts +} + +async function listServerFiles(serverDir: string): Promise { + const files: string[] = [] + await walk(serverDir, files) + return files.toSorted() +} + +async function walk(dir: string, files: string[]): Promise { + const entries = await fsp.readdir(dir, { withFileTypes: true }) + for (const entry of entries) { + if (entry.name === '__tests__') { + continue + } + const fullPath = path.join(dir, entry.name) + if (entry.isDirectory()) { + await walk(fullPath, files) + continue + } + if (!entry.isFile()) { + continue + } + if (!entry.name.endsWith('.ts')) { + continue + } + if (entry.name.endsWith('.test.ts')) { + continue + } + files.push(fullPath) + } +} + +function auditFile(filePath: string, rootDir: string): LoggingAuditFinding[] { + const sourceText = fs.readFileSync(filePath, 'utf8') + const sourceFile = ts.createSourceFile( + filePath, + sourceText, + ts.ScriptTarget.Latest, + true, + ts.ScriptKind.TS + ) + const relativeFile = toPosix(path.relative(rootDir, filePath)) + const findings: LoggingAuditFinding[] = [] + + const visit = (node: ts.Node): void => { + if (ts.isCatchClause(node)) { + auditCatchClause(node, sourceFile, relativeFile, findings) + ts.forEachChild(node.block, visit) + return + } + + if (ts.isCallExpression(node)) { + auditLoggerEventName(node, sourceFile, relativeFile, findings) + } + + ts.forEachChild(node, visit) + } + + visit(sourceFile) + return findings +} + +function auditLoggerEventName( + node: ts.CallExpression, + sourceFile: ts.SourceFile, + relativeFile: string, + findings: LoggingAuditFinding[] +): void { + const loggerCall = toLoggerCall(node) + if (!loggerCall) { + return + } + + const eventName = getStaticEventName(loggerCall.eventArg) + if (eventName !== null && !SNAKE_CASE_EVENT.test(eventName)) { + findings.push({ + severity: 'medium', + rule: 'non_snake_case_event_name', + file: relativeFile, + line: getLine(sourceFile, loggerCall.eventArg ?? loggerCall.node), + message: `event "${eventName}" is not snake_case`, + }) + } +} + +function auditCatchClause( + catchClause: ts.CatchClause, + sourceFile: ts.SourceFile, + relativeFile: string, + findings: LoggingAuditFinding[] +): void { + const loggerCalls = collectLoggerCalls(catchClause.block) + const hasLoggingWrapper = hasKnownLoggingWrapperCall(catchClause.block) + const suppressed = isCatchSuppressed(catchClause, sourceFile) + + if (loggerCalls.length === 0 && !hasLoggingWrapper && !suppressed) { + findings.push({ + severity: severityForCatch(relativeFile, catchClause), + rule: 'catch_without_logging', + file: relativeFile, + line: getLine(sourceFile, catchClause), + message: 'catch block does not emit a structured logger event', + }) + return + } + + for (const call of loggerCalls) { + if (call.level !== 'warn' && call.level !== 'error') { + continue + } + if (hasErrorContext(call.dataArg)) { + continue + } + const eventName = getStaticEventName(call.eventArg) + findings.push({ + severity: severityForCatch(relativeFile, catchClause), + rule: 'missing_error_context', + file: relativeFile, + line: getLine(sourceFile, call.node), + message: `logger.${call.level}(${eventName ? `"${eventName}"` : 'dynamic event'}) is missing error context fields`, + }) + } +} + +function collectLoggerCalls(node: ts.Node): LoggerCall[] { + const calls: LoggerCall[] = [] + + const walkNode = (next: ts.Node, isRoot = false): void => { + if (!isRoot && isNestedScopeBoundary(next)) { + return + } + + if (ts.isCallExpression(next)) { + const loggerCall = toLoggerCall(next) + if (loggerCall) { + calls.push(loggerCall) + } + } + ts.forEachChild(next, (child) => walkNode(child)) + } + + walkNode(node, true) + return calls +} + +function hasKnownLoggingWrapperCall(node: ts.Node): boolean { + let found = false + + const visit = (next: ts.Node, isRoot = false): void => { + if (found) { + return + } + if (!isRoot && isNestedScopeBoundary(next)) { + return + } + if ( + ts.isCallExpression(next) && + ts.isIdentifier(next.expression) && + KNOWN_LOGGING_WRAPPERS.has(next.expression.text) + ) { + found = true + return + } + ts.forEachChild(next, (child) => visit(child)) + } + + visit(node, true) + return found +} + +function isNestedScopeBoundary(node: ts.Node): boolean { + return ( + ts.isFunctionDeclaration(node) || + ts.isFunctionExpression(node) || + ts.isArrowFunction(node) || + ts.isMethodDeclaration(node) || + ts.isGetAccessorDeclaration(node) || + ts.isSetAccessorDeclaration(node) || + ts.isConstructorDeclaration(node) || + ts.isClassDeclaration(node) || + ts.isClassExpression(node) + ) +} + +function toLoggerCall(node: ts.CallExpression): LoggerCall | null { + const level = getLoggerLevel(node.expression) + if (!level) { + return null + } + + return { + level, + eventArg: node.arguments[0], + dataArg: node.arguments[1], + node, + } +} + +function getLoggerLevel(expression: ts.LeftHandSideExpression): LoggerLevel | null { + if (ts.isPropertyAccessExpression(expression)) { + if (!ts.isIdentifier(expression.expression) || expression.expression.text !== 'logger') { + return null + } + const level = expression.name.text + return LOGGER_LEVELS.has(level as Exclude) + ? (level as Exclude) + : null + } + + if (ts.isElementAccessExpression(expression)) { + if (!ts.isIdentifier(expression.expression) || expression.expression.text !== 'logger') { + return null + } + + const arg = expression.argumentExpression + if (!arg) { + return 'unknown' + } + + if (ts.isStringLiteral(arg) || ts.isNoSubstitutionTemplateLiteral(arg)) { + const level = arg.text + return LOGGER_LEVELS.has(level as Exclude) + ? (level as Exclude) + : 'unknown' + } + + return 'unknown' + } + + return null +} + +function getStaticEventName(node: ts.Expression | undefined): string | null { + if (!node) { + return null + } + if (ts.isStringLiteral(node) || ts.isNoSubstitutionTemplateLiteral(node)) { + return node.text + } + if (ts.isBinaryExpression(node) && node.operatorToken.kind === ts.SyntaxKind.PlusToken) { + const left = getStaticEventName(node.left) + const right = getStaticEventName(node.right) + if (left !== null && right !== null) { + return `${left}${right}` + } + } + return null +} + +function hasErrorContext(dataArg: ts.Expression | undefined): boolean { + if (!dataArg) { + return false + } + + if (!ts.isObjectLiteralExpression(dataArg)) { + return expressionHasErrorSignal(dataArg) + } + + for (const property of dataArg.properties) { + if (ts.isSpreadAssignment(property)) { + if (expressionHasErrorSignal(property.expression)) { + return true + } + continue + } + if (ts.isShorthandPropertyAssignment(property)) { + if ( + ERROR_CONTEXT_FIELDS.has(toSnakeCase(property.name.text)) || + expressionHasErrorSignal(property.name) + ) { + return true + } + continue + } + if (ts.isPropertyAssignment(property)) { + const propertyName = getPropertyName(property.name) + if (propertyName && ERROR_CONTEXT_FIELDS.has(toSnakeCase(propertyName))) { + return true + } + if (expressionHasErrorSignal(property.initializer)) { + return true + } + } + } + + return false +} + +function expressionHasErrorSignal(expression: ts.Expression): boolean { + if (ts.isIdentifier(expression)) { + return ERROR_SIGNAL_PATTERN.test(expression.text) + } + + if (ts.isPropertyAccessExpression(expression)) { + return ( + ERROR_SIGNAL_PATTERN.test(expression.name.text) || + expressionHasErrorSignal(expression.expression) + ) + } + + if (ts.isElementAccessExpression(expression)) { + if (expression.argumentExpression) { + if ( + ts.isStringLiteral(expression.argumentExpression) || + ts.isNoSubstitutionTemplateLiteral(expression.argumentExpression) + ) { + if (ERROR_SIGNAL_PATTERN.test(expression.argumentExpression.text)) { + return true + } + } else if (expressionHasErrorSignal(expression.argumentExpression)) { + return true + } + } + return expressionHasErrorSignal(expression.expression) + } + + if (ts.isCallExpression(expression)) { + if (expressionHasErrorSignal(expression.expression)) { + return true + } + return expression.arguments.some((arg) => expressionHasErrorSignal(arg)) + } + + if (ts.isObjectLiteralExpression(expression)) { + for (const property of expression.properties) { + if (ts.isSpreadAssignment(property) && expressionHasErrorSignal(property.expression)) { + return true + } + if (ts.isShorthandPropertyAssignment(property) && expressionHasErrorSignal(property.name)) { + return true + } + if (ts.isPropertyAssignment(property)) { + const propertyName = getPropertyName(property.name) + if (propertyName && ERROR_SIGNAL_PATTERN.test(propertyName)) { + return true + } + if (expressionHasErrorSignal(property.initializer)) { + return true + } + } + } + return false + } + + if (ts.isConditionalExpression(expression)) { + return ( + expressionHasErrorSignal(expression.whenTrue) || + expressionHasErrorSignal(expression.whenFalse) + ) + } + + if (ts.isBinaryExpression(expression)) { + return ( + expressionHasErrorSignal(expression.left) || + expressionHasErrorSignal(expression.right) + ) + } + + if (ts.isParenthesizedExpression(expression)) { + return expressionHasErrorSignal(expression.expression) + } + + if (ts.isAsExpression(expression)) { + return expressionHasErrorSignal(expression.expression) + } + + if (ts.isTypeAssertionExpression(expression)) { + return expressionHasErrorSignal(expression.expression) + } + + if (ts.isNonNullExpression(expression)) { + return expressionHasErrorSignal(expression.expression) + } + + return false +} + +function isCatchSuppressed(catchClause: ts.CatchClause, sourceFile: ts.SourceFile): boolean { + const sourceText = sourceFile.getFullText() + const ranges = [ + ...(ts.getLeadingCommentRanges(sourceText, catchClause.getFullStart()) ?? []), + ...(ts.getLeadingCommentRanges(sourceText, catchClause.block.getFullStart()) ?? []), + ] + + for (const range of ranges) { + const commentText = sourceText.slice(range.pos, range.end) + if (CATCH_SUPPRESSION_MARKER.test(commentText)) { + return true + } + } + + const blockText = sourceText.slice(catchClause.block.getFullStart(), catchClause.block.end) + for (const comment of blockText.match(COMMENT_PATTERN) ?? []) { + if (CATCH_SUPPRESSION_MARKER.test(comment)) { + return true + } + } + + return false +} + +function getPropertyName(name: ts.PropertyName): string | null { + if (ts.isIdentifier(name)) { + return name.text + } + if (ts.isStringLiteral(name) || ts.isNumericLiteral(name)) { + return name.text + } + return null +} + +function toSnakeCase(value: string): string { + return value + .replace(/([A-Z])/g, '_$1') + .replace(/[-\s]+/g, '_') + .toLowerCase() +} + +function severityForCatch( + relativeFile: string, + catchClause: ts.CatchClause +): LoggingAuditSeverity { + if (isApiRouteCatch(catchClause)) { + return 'high' + } + if (relativeFile === 'src/server/db.ts' && isMigrationCatch(catchClause)) { + return 'high' + } + return 'medium' +} + +function isApiRouteCatch(catchClause: ts.CatchClause): boolean { + let node: ts.Node | undefined = catchClause.parent + while (node) { + if (ts.isCallExpression(node)) { + if (!ts.isPropertyAccessExpression(node.expression)) { + node = node.parent + continue + } + const callee = node.expression + if (!ts.isIdentifier(callee.expression) || callee.expression.text !== 'app') { + node = node.parent + continue + } + if (!APP_ROUTE_METHODS.has(callee.name.text)) { + node = node.parent + continue + } + const routeArg = node.arguments[0] + return Boolean( + routeArg && + (ts.isStringLiteral(routeArg) || + ts.isNoSubstitutionTemplateLiteral(routeArg)) && + routeArg.text.startsWith('/api/') + ) + } + node = node.parent + } + return false +} + +function isMigrationCatch(catchClause: ts.CatchClause): boolean { + let node: ts.Node | undefined = catchClause.parent + while (node) { + if (ts.isFunctionDeclaration(node) && node.name) { + return node.name.text.startsWith('migrate') + } + node = node.parent + } + return false +} + +function getLine(sourceFile: ts.SourceFile, node: ts.Node): number { + const { line } = sourceFile.getLineAndCharacterOfPosition( + node.getStart(sourceFile) + ) + return line + 1 +} + +function toPosix(filePath: string): string { + return filePath.split(path.sep).join('/') +} diff --git a/src/server/prerequisites.ts b/src/server/prerequisites.ts index 5d5c7fa..9ad110e 100644 --- a/src/server/prerequisites.ts +++ b/src/server/prerequisites.ts @@ -9,6 +9,7 @@ export function ensureTmux(): void { throw new Error(result.stderr.toString() || 'tmux not found') } } catch (error) { + /* logging-audit:intentional */ const message = error instanceof Error ? error.message : 'tmux not found' throw new Error( diff --git a/src/server/remoteSessions.ts b/src/server/remoteSessions.ts index d8f39cf..145e399 100644 --- a/src/server/remoteSessions.ts +++ b/src/server/remoteSessions.ts @@ -282,6 +282,7 @@ async function captureRemotePaneStatus( try { proc.kill() } catch { + /* logging-audit:intentional */ // ignore } }, timeoutMs) @@ -327,6 +328,7 @@ async function pollHost( try { proc.kill() } catch { + /* logging-audit:intentional */ // ignore } }, timeoutMs) diff --git a/src/server/sessionRefreshWorker.ts b/src/server/sessionRefreshWorker.ts index 862e342..bf21a40 100644 --- a/src/server/sessionRefreshWorker.ts +++ b/src/server/sessionRefreshWorker.ts @@ -118,6 +118,7 @@ ctx.onmessage = (event: MessageEvent) => { } ctx.postMessage(response) } catch (error) { + /* logging-audit:intentional */ const response: RefreshWorkerResponse = { id: payload.id, kind: 'error', @@ -150,6 +151,7 @@ function listAllWindowData(): WindowData[] { try { output = runTmux(['list-windows', '-a', '-F', BATCH_WINDOW_FORMAT]) } catch (error) { + /* logging-audit:intentional */ if (!isTmuxFormatError(error)) { throw error } @@ -191,6 +193,7 @@ function capturePane(tmuxWindow: string): string | null { } return lines.slice(-30).join('\n') } catch { + /* logging-audit:intentional */ return null } } diff --git a/src/server/terminal/PipePaneTerminalProxy.ts b/src/server/terminal/PipePaneTerminalProxy.ts index 54b207b..8c3cb31 100644 --- a/src/server/terminal/PipePaneTerminalProxy.ts +++ b/src/server/terminal/PipePaneTerminalProxy.ts @@ -105,6 +105,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { this.runTmux(['send-keys', '-X', '-t', this.currentTarget, 'cancel']) } } catch { + /* logging-audit:intentional */ // Ignore errors checking scroll position } } @@ -131,6 +132,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { } } } catch { + /* logging-audit:intentional */ // Ignore write errors } } @@ -158,6 +160,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { await fs.rm(this.pipeRoot, { recursive: true, force: true }) } catch { + /* logging-audit:intentional */ // Ignore cleanup failures } @@ -185,6 +188,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { await this.ensurePipeRoot() } catch (error) { + /* logging-audit:intentional */ this.state = TerminalState.DEAD throw new TerminalProxyError( 'ERR_TMUX_ATTACH_FAILED', @@ -236,6 +240,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { onReady() } catch { + /* logging-audit:intentional */ // Ignore onReady failures } } @@ -254,6 +259,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { this.state = TerminalState.READY return true } catch (error) { + /* logging-audit:intentional */ this.outputSuppressed = false this.state = TerminalState.READY this.logEvent('terminal_switch_failure', { @@ -275,6 +281,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { await fs.chmod(this.pipeRoot, 0o700) } catch { + /* logging-audit:intentional */ // Ignore chmod failures } } @@ -285,6 +292,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { await fs.chmod(pipeFile, 0o600) } catch { + /* logging-audit:intentional */ // Ignore chmod failures } return pipeFile @@ -305,6 +313,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { stderr: 'pipe', }) } catch (error) { + /* logging-audit:intentional */ throw new TerminalProxyError( 'ERR_TMUX_ATTACH_FAILED', error instanceof Error ? error.message : 'Failed to start pipe tail', @@ -336,6 +345,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { this.options.onData(tail) } } catch { + /* logging-audit:intentional */ // Ignore tail read errors } } @@ -368,6 +378,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { this.tailProcess.kill() } catch { + /* logging-audit:intentional */ // Ignore kill failures } this.tailProcess = null @@ -394,6 +405,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { '#{pane_id}', ]) } catch { + /* logging-audit:intentional */ output = '' } if (output.trim()) { @@ -430,6 +442,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { this.runTmux(['pipe-pane', '-t', target]) } catch { + /* logging-audit:intentional */ // Ignore pipe stop failures } } @@ -438,6 +451,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { try { this.runTmux(['pipe-pane', '-t', target]) } catch { + /* logging-audit:intentional */ // Ignore pipe reset failures } } @@ -457,6 +471,7 @@ class PipePaneTerminalProxy extends TerminalProxyBase { rows.toString(), ]) } catch { + /* logging-audit:intentional */ // Ignore resize errors } } diff --git a/src/server/terminal/PtyTerminalProxy.ts b/src/server/terminal/PtyTerminalProxy.ts index c1d2e89..ba4e8b4 100644 --- a/src/server/terminal/PtyTerminalProxy.ts +++ b/src/server/terminal/PtyTerminalProxy.ts @@ -28,6 +28,7 @@ class PtyTerminalProxy extends TerminalProxyBase { try { this.process?.terminal?.resize(cols, rows) } catch { + /* logging-audit:intentional */ // Ignore resize errors } } @@ -44,6 +45,7 @@ class PtyTerminalProxy extends TerminalProxyBase { this.process.kill() this.process.terminal?.close() } catch { + /* logging-audit:intentional */ // Ignore if already exited } this.process = null @@ -55,6 +57,7 @@ class PtyTerminalProxy extends TerminalProxyBase { sessionName: this.options.sessionName, }) } catch { + /* logging-audit:intentional */ // Ignore cleanup failures } @@ -89,6 +92,7 @@ class PtyTerminalProxy extends TerminalProxyBase { this.options.sessionName, ]) } catch (error) { + /* logging-audit:intentional */ this.state = TerminalState.DEAD throw new TerminalProxyError( 'ERR_SESSION_CREATE_FAILED', @@ -131,6 +135,7 @@ class PtyTerminalProxy extends TerminalProxyBase { }, }) } catch (error) { + /* logging-audit:intentional */ this.state = TerminalState.DEAD throw new TerminalProxyError( 'ERR_TMUX_ATTACH_FAILED', @@ -144,6 +149,7 @@ class PtyTerminalProxy extends TerminalProxyBase { proc.kill() proc.terminal?.close() } catch { + /* logging-audit:intentional */ // Ignore if already exited } await this.dispose() @@ -179,6 +185,7 @@ class PtyTerminalProxy extends TerminalProxyBase { mode: this.getMode(), }) } catch (error) { + /* logging-audit:intentional */ this.state = TerminalState.DEAD await this.dispose() throw error @@ -211,6 +218,7 @@ class PtyTerminalProxy extends TerminalProxyBase { try { onReady() } catch { + /* logging-audit:intentional */ // Ignore onReady failures } } @@ -219,6 +227,7 @@ class PtyTerminalProxy extends TerminalProxyBase { try { this.runTmux(['refresh-client', '-t', this.clientTty]) } catch { + /* logging-audit:intentional */ // Ignore refresh failures } const durationMs = this.now() - startedAt @@ -232,6 +241,7 @@ class PtyTerminalProxy extends TerminalProxyBase { this.state = TerminalState.READY return true } catch (error) { + /* logging-audit:intentional */ this.outputSuppressed = false this.state = TerminalState.READY this.logEvent('terminal_switch_failure', { @@ -263,6 +273,7 @@ class PtyTerminalProxy extends TerminalProxyBase { '#{client_tty} #{client_pid}', ]) } catch { + /* logging-audit:intentional */ output = '' } for (const line of output.split('\n')) { diff --git a/src/server/terminal/SshTerminalProxy.ts b/src/server/terminal/SshTerminalProxy.ts index 142cd47..99ef2f7 100644 --- a/src/server/terminal/SshTerminalProxy.ts +++ b/src/server/terminal/SshTerminalProxy.ts @@ -49,6 +49,7 @@ class SshTerminalProxy extends TerminalProxyBase { try { this.process?.terminal?.resize(cols, rows) } catch { + /* logging-audit:intentional */ // Ignore resize errors } } @@ -65,6 +66,7 @@ class SshTerminalProxy extends TerminalProxyBase { this.process.kill() this.process.terminal?.close() } catch { + /* logging-audit:intentional */ // Ignore if already exited } this.process = null @@ -76,6 +78,7 @@ class SshTerminalProxy extends TerminalProxyBase { sessionName: this.options.sessionName, }) } catch { + /* logging-audit:intentional */ // Ignore cleanup failures } @@ -98,7 +101,11 @@ class SshTerminalProxy extends TerminalProxyBase { }) const timeout = setTimeout(() => { - try { proc.kill() } catch {} + try { + proc.kill() + } catch { + /* logging-audit:intentional */ + } }, this.commandTimeoutMs) let exitCode: number @@ -155,6 +162,7 @@ class SshTerminalProxy extends TerminalProxyBase { this.process.kill() this.process.terminal?.close() } catch { + /* logging-audit:intentional */ // Ignore if already exited } this.process = null @@ -201,6 +209,7 @@ class SshTerminalProxy extends TerminalProxyBase { this.options.sessionName, ]) } catch (error) { + /* logging-audit:intentional */ const message = error instanceof Error ? error.message : String(error) // Session name is per-WS-connection; if a previous proxy didn't clean up, // treat duplicate sessions as recoverable and try to proceed. @@ -298,6 +307,7 @@ class SshTerminalProxy extends TerminalProxyBase { proc.kill() proc.terminal?.close() } catch { + /* logging-audit:intentional */ // Ignore if already exited } await this.dispose() @@ -371,6 +381,7 @@ class SshTerminalProxy extends TerminalProxyBase { try { onReady() } catch { + /* logging-audit:intentional */ // Ignore onReady failures } } @@ -379,6 +390,7 @@ class SshTerminalProxy extends TerminalProxyBase { try { await this.runTmuxAsync(['refresh-client', '-t', this.clientTty]) } catch { + /* logging-audit:intentional */ // Ignore refresh failures } const durationMs = this.now() - startedAt @@ -392,6 +404,7 @@ class SshTerminalProxy extends TerminalProxyBase { this.state = TerminalState.READY return true } catch (error) { + /* logging-audit:intentional */ this.outputSuppressed = false this.state = TerminalState.READY this.logEvent('terminal_switch_failure', { @@ -425,6 +438,7 @@ class SshTerminalProxy extends TerminalProxyBase { '#{client_tty}', ]) } catch { + /* logging-audit:intentional */ output = '' } for (const line of output.split('\n')) { diff --git a/src/server/terminal/TerminalProxyBase.ts b/src/server/terminal/TerminalProxyBase.ts index 8f7cf52..940144a 100644 --- a/src/server/terminal/TerminalProxyBase.ts +++ b/src/server/terminal/TerminalProxyBase.ts @@ -119,6 +119,7 @@ abstract class TerminalProxyBase implements ITerminalProxy { const result = await this.doSwitch(target, onReady) resolvers.forEach((resolver) => resolver.resolve(result)) } catch (error) { + /* logging-audit:intentional */ resolvers.forEach((resolver) => resolver.reject(error)) } }