fix: integrate centralized logger across services and hooks for improved logging consistency

This commit is contained in:
Alex Newman
2025-12-27 20:45:28 -05:00
parent 339e452bc0
commit 2ec9e58607
17 changed files with 67 additions and 56 deletions
+1
View File
@@ -10,6 +10,7 @@ import { stdin } from "process";
import { ensureWorkerRunning, getWorkerPort } from "../shared/worker-utils.js";
import { HOOK_TIMEOUTS } from "../shared/hook-constants.js";
import { getProjectName } from "../utils/project-name.js";
import { logger } from "../utils/logger.js";
export interface SessionStartInput {
session_id: string;
+1
View File
@@ -9,6 +9,7 @@
import { basename } from "path";
import { ensureWorkerRunning, getWorkerPort } from "../shared/worker-utils.js";
import { HOOK_EXIT_CODES } from "../shared/hook-constants.js";
import { logger } from "../utils/logger.js";
// Ensure worker is running
await ensureWorkerRunning();
+8 -4
View File
@@ -6,11 +6,16 @@
* Maintains MCP protocol handling and tool schemas
*/
// CRITICAL: Redirect console.log to stderr BEFORE any imports
// Import logger first
import { logger } from '../utils/logger.js';
// CRITICAL: Redirect console to stderr BEFORE other imports
// MCP uses stdio transport where stdout is reserved for JSON-RPC protocol messages.
// Any logs to stdout break the protocol (Claude Desktop parses "[2025..." as JSON array).
const _originalConsoleLog = console.log;
console.log = (...args: any[]) => console.error(...args);
const _originalLog = console['log'];
console['log'] = (...args: any[]) => {
logger.error('CONSOLE', 'Intercepted console output (MCP protocol protection)', undefined, { args });
};
import { Server } from '@modelcontextprotocol/sdk/server/index.js';
import { StdioServerTransport } from '@modelcontextprotocol/sdk/server/stdio.js';
@@ -18,7 +23,6 @@ import {
CallToolRequestSchema,
ListToolsRequestSchema,
} from '@modelcontextprotocol/sdk/types.js';
import { logger } from '../utils/logger.js';
import { getWorkerPort, getWorkerHost } from '../shared/worker-utils.js';
/**
+1 -1
View File
@@ -229,7 +229,7 @@ export async function generateContext(input?: ContextInput, useColors: boolean =
} catch (unlinkError) {
// Marker might not exist
}
console.error('Native module rebuild needed - restart Claude Code to auto-fix');
logger.error('SYSTEM', 'Native module rebuild needed - restart Claude Code to auto-fix');
return '';
}
throw error;
+3 -2
View File
@@ -1,5 +1,6 @@
import { Database } from 'bun:sqlite';
import { DATA_DIR, DB_PATH, ensureDir } from '../../shared/paths.js';
import { logger } from '../../utils/logger.js';
// SQLite configuration constants
const SQLITE_MMAP_SIZE_BYTES = 256 * 1024 * 1024; // 256MB
@@ -126,7 +127,7 @@ export class DatabaseManager {
for (const migration of this.migrations) {
if (migration.version > maxApplied) {
console.log(`Applying migration ${migration.version}...`);
logger.info('DB', `Applying migration ${migration.version}`);
const transaction = this.db.transaction(() => {
migration.up(this.db!);
@@ -136,7 +137,7 @@ export class DatabaseManager {
});
transaction();
console.log(`Migration ${migration.version} applied successfully`);
logger.info('DB', `Migration ${migration.version} applied successfully`);
}
}
}
@@ -1,5 +1,6 @@
import { Database } from './sqlite-compat.js';
import type { PendingMessage } from '../worker-types.js';
import { logger } from '../../utils/logger.js';
/**
* Persistent pending message record from database
+6 -8
View File
@@ -1,6 +1,7 @@
import { Database } from 'bun:sqlite';
import { TableNameRow } from '../../types/database.js';
import { DATA_DIR, DB_PATH, ensureDir } from '../../shared/paths.js';
import { logger } from '../../utils/logger.js';
import {
ObservationSearchResult,
SessionSummarySearchResult,
@@ -44,9 +45,6 @@ export class SessionSearch {
* - Tables maintained but search paths removed
* - Triggers still fire to keep tables synchronized
*
* Note: Using console.log for migration messages since they run during constructor
* before structured logger is available. Actual errors use console.error.
*
* TODO: Remove FTS5 infrastructure in future major version (v7.0.0)
*/
private ensureFTSTables(): void {
@@ -59,7 +57,7 @@ export class SessionSearch {
return;
}
console.log('[SessionSearch] Creating FTS5 tables...');
logger.info('DB', 'Creating FTS5 tables');
// Create observations_fts virtual table
this.db.run(`
@@ -143,7 +141,7 @@ export class SessionSearch {
END;
`);
console.log('[SessionSearch] FTS5 tables created successfully');
logger.info('DB', 'FTS5 tables created successfully');
}
@@ -270,7 +268,7 @@ export class SessionSearch {
// Vector search with query text should be handled by ChromaDB
// This method only supports filter-only queries (query=undefined)
console.warn('[SessionSearch] Text search not supported - use ChromaDB for vector search');
logger.warn('DB', 'Text search not supported - use ChromaDB for vector search');
return [];
}
@@ -309,7 +307,7 @@ export class SessionSearch {
// Vector search with query text should be handled by ChromaDB
// This method only supports filter-only queries (query=undefined)
console.warn('[SessionSearch] Text search not supported - use ChromaDB for vector search');
logger.warn('DB', 'Text search not supported - use ChromaDB for vector search');
return [];
}
@@ -495,7 +493,7 @@ export class SessionSearch {
// Vector search with query text should be handled by ChromaDB
// This method only supports filter-only queries (query=undefined)
console.warn('[SessionSearch] Text search not supported - use ChromaDB for vector search');
logger.warn('DB', 'Text search not supported - use ChromaDB for vector search');
return [];
}
+24 -27
View File
@@ -48,9 +48,6 @@ export class SessionStore {
/**
* Initialize database schema using migrations (migration004)
* This runs the core SDK tables migration if no tables exist
*
* Note: Using console.log for migration messages since they run during constructor
* before structured logger is available. Actual errors use console.error.
*/
private initializeSchema(): void {
try {
@@ -70,7 +67,7 @@ export class SessionStore {
// Only run migration004 if no migrations have been applied
// This creates the sdk_sessions, observations, and session_summaries tables
if (maxApplied === 0) {
console.log('[SessionStore] Initializing fresh database with migration004...');
logger.info('DB', 'Initializing fresh database with migration004');
// Migration004: SDK agent architecture tables
this.db.run(`
@@ -134,10 +131,10 @@ export class SessionStore {
// Record migration004 as applied
this.db.prepare('INSERT INTO schema_versions (version, applied_at) VALUES (?, ?)').run(4, new Date().toISOString());
console.log('[SessionStore] Migration004 applied successfully');
logger.info('DB', 'Migration004 applied successfully');
}
} catch (error: any) {
console.error('[SessionStore] Schema initialization error:', error.message);
logger.error('DB', 'Schema initialization error', undefined, error);
throw error;
}
}
@@ -156,7 +153,7 @@ export class SessionStore {
if (!hasWorkerPort) {
this.db.run('ALTER TABLE sdk_sessions ADD COLUMN worker_port INTEGER');
console.log('[SessionStore] Added worker_port column to sdk_sessions table');
logger.info('DB', 'Added worker_port column to sdk_sessions table');
}
// Record migration
@@ -177,7 +174,7 @@ export class SessionStore {
if (!hasPromptCounter) {
this.db.run('ALTER TABLE sdk_sessions ADD COLUMN prompt_counter INTEGER DEFAULT 0');
console.log('[SessionStore] Added prompt_counter column to sdk_sessions table');
logger.info('DB', 'Added prompt_counter column to sdk_sessions table');
}
// Check observations for prompt_number
@@ -186,7 +183,7 @@ export class SessionStore {
if (!obsHasPromptNumber) {
this.db.run('ALTER TABLE observations ADD COLUMN prompt_number INTEGER');
console.log('[SessionStore] Added prompt_number column to observations table');
logger.info('DB', 'Added prompt_number column to observations table');
}
// Check session_summaries for prompt_number
@@ -195,7 +192,7 @@ export class SessionStore {
if (!sumHasPromptNumber) {
this.db.run('ALTER TABLE session_summaries ADD COLUMN prompt_number INTEGER');
console.log('[SessionStore] Added prompt_number column to session_summaries table');
logger.info('DB', 'Added prompt_number column to session_summaries table');
}
// Record migration
@@ -220,7 +217,7 @@ export class SessionStore {
return;
}
console.log('[SessionStore] Removing UNIQUE constraint from session_summaries.sdk_session_id...');
logger.info('DB', 'Removing UNIQUE constraint from session_summaries.sdk_session_id');
// Begin transaction
this.db.run('BEGIN TRANSACTION');
@@ -275,7 +272,7 @@ export class SessionStore {
// Record migration
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(7, new Date().toISOString());
console.log('[SessionStore] Successfully removed UNIQUE constraint from session_summaries.sdk_session_id');
logger.info('DB', 'Successfully removed UNIQUE constraint from session_summaries.sdk_session_id');
} catch (error: any) {
// Rollback on error
this.db.run('ROLLBACK');
@@ -301,7 +298,7 @@ export class SessionStore {
return;
}
console.log('[SessionStore] Adding hierarchical fields to observations table...');
logger.info('DB', 'Adding hierarchical fields to observations table');
// Add new columns
this.db.run(`
@@ -317,7 +314,7 @@ export class SessionStore {
// Record migration
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(8, new Date().toISOString());
console.log('[SessionStore] Successfully added hierarchical fields to observations table');
logger.info('DB', 'Successfully added hierarchical fields to observations table');
}
/**
@@ -339,7 +336,7 @@ export class SessionStore {
return;
}
console.log('[SessionStore] Making observations.text nullable...');
logger.info('DB', 'Making observations.text nullable');
// Begin transaction
this.db.run('BEGIN TRANSACTION');
@@ -396,7 +393,7 @@ export class SessionStore {
// Record migration
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(9, new Date().toISOString());
console.log('[SessionStore] Successfully made observations.text nullable');
logger.info('DB', 'Successfully made observations.text nullable');
} catch (error: any) {
// Rollback on error
this.db.run('ROLLBACK');
@@ -420,7 +417,7 @@ export class SessionStore {
return;
}
console.log('[SessionStore] Creating user_prompts table with FTS5 support...');
logger.info('DB', 'Creating user_prompts table with FTS5 support');
// Begin transaction
this.db.run('BEGIN TRANSACTION');
@@ -479,7 +476,7 @@ export class SessionStore {
// Record migration
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(10, new Date().toISOString());
console.log('[SessionStore] Successfully created user_prompts table with FTS5 support');
logger.info('DB', 'Successfully created user_prompts table with FTS5 support');
} catch (error: any) {
// Rollback on error
this.db.run('ROLLBACK');
@@ -504,7 +501,7 @@ export class SessionStore {
if (!obsHasDiscoveryTokens) {
this.db.run('ALTER TABLE observations ADD COLUMN discovery_tokens INTEGER DEFAULT 0');
console.log('[SessionStore] Added discovery_tokens column to observations table');
logger.info('DB', 'Added discovery_tokens column to observations table');
}
// Check if discovery_tokens column exists in session_summaries table
@@ -513,13 +510,13 @@ export class SessionStore {
if (!sumHasDiscoveryTokens) {
this.db.run('ALTER TABLE session_summaries ADD COLUMN discovery_tokens INTEGER DEFAULT 0');
console.log('[SessionStore] Added discovery_tokens column to session_summaries table');
logger.info('DB', 'Added discovery_tokens column to session_summaries table');
}
// Record migration only after successful column verification/addition
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(11, new Date().toISOString());
} catch (error: any) {
console.error('[SessionStore] Discovery tokens migration error:', error.message);
logger.error('DB', 'Discovery tokens migration error', undefined, error);
throw error; // Re-throw to prevent silent failures
}
}
@@ -542,7 +539,7 @@ export class SessionStore {
return;
}
console.log('[SessionStore] Creating pending_messages table...');
logger.info('DB', 'Creating pending_messages table');
this.db.run(`
CREATE TABLE pending_messages (
@@ -572,9 +569,9 @@ export class SessionStore {
this.db.prepare('INSERT OR IGNORE INTO schema_versions (version, applied_at) VALUES (?, ?)').run(16, new Date().toISOString());
console.log('[SessionStore] pending_messages table created successfully');
logger.info('DB', 'pending_messages table created successfully');
} catch (error: any) {
console.error('[SessionStore] Pending messages table migration error:', error.message);
logger.error('DB', 'Pending messages table migration error', undefined, error);
throw error;
}
}
@@ -1387,7 +1384,7 @@ export class SessionStore {
startEpoch = beforeRecords.length > 0 ? beforeRecords[beforeRecords.length - 1].created_at_epoch : anchorEpoch;
endEpoch = afterRecords.length > 0 ? afterRecords[afterRecords.length - 1].created_at_epoch : anchorEpoch;
} catch (err: any) {
console.error('[SessionStore] Error getting boundary observations:', err.message, project ? `(project: ${project})` : '(all projects)');
logger.error('DB', 'Error getting boundary observations', undefined, { error: err, project });
return { observations: [], sessions: [], prompts: [] };
}
} else {
@@ -1419,7 +1416,7 @@ export class SessionStore {
startEpoch = beforeRecords.length > 0 ? beforeRecords[beforeRecords.length - 1].created_at_epoch : anchorEpoch;
endEpoch = afterRecords.length > 0 ? afterRecords[afterRecords.length - 1].created_at_epoch : anchorEpoch;
} catch (err: any) {
console.error('[SessionStore] Error getting boundary timestamps:', err.message, project ? `(project: ${project})` : '(all projects)');
logger.error('DB', 'Error getting boundary timestamps', undefined, { error: err, project });
return { observations: [], sessions: [], prompts: [] };
}
}
@@ -1475,7 +1472,7 @@ export class SessionStore {
}))
};
} catch (err: any) {
console.error('[SessionStore] Error querying timeline records:', err.message, project ? `(project: ${project})` : '(all projects)');
logger.error('DB', 'Error querying timeline records', undefined, { error: err, project });
return { observations: [], sessions: [], prompts: [] };
}
}
+14 -14
View File
@@ -965,13 +965,13 @@ async function main() {
logger.info('SYSTEM', 'Another session is spawning worker, waiting for health');
const healthy = await waitForHealth(port, getPlatformTimeout(30000));
if (healthy) {
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Worker healthy, returning success');
process.exit(0);
}
// Still not healthy after wait - try to acquire lock and spawn
const gotLock = await waitForLock('start', 5000);
if (!gotLock) {
console.error('Failed to acquire lock after timeout');
logger.error('SYSTEM', 'Failed to acquire lock after timeout');
process.exit(1);
}
}
@@ -980,7 +980,7 @@ async function main() {
// Re-check port AFTER acquiring lock
if (await isPortInUse(port)) {
releaseLock();
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Port already in use, worker already running');
process.exit(0);
}
@@ -994,7 +994,7 @@ async function main() {
if (child.pid === undefined) {
releaseLock();
console.error('Failed to spawn worker daemon');
logger.error('SYSTEM', 'Failed to spawn worker daemon');
process.exit(1);
}
@@ -1009,11 +1009,11 @@ async function main() {
if (!healthy) {
removePidFile();
console.error('Worker failed to start');
logger.error('SYSTEM', 'Worker failed to start');
process.exit(1);
}
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Worker started successfully');
process.exit(0);
} catch (error) {
releaseLock();
@@ -1033,7 +1033,7 @@ async function main() {
await waitForPortFree(port, getPlatformTimeout(15000));
removePidFile();
releaseLock();
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Worker stopped successfully');
process.exit(0);
} catch (error) {
releaseLock();
@@ -1048,10 +1048,10 @@ async function main() {
logger.info('SYSTEM', 'Another session is restarting worker, waiting');
const healthy = await waitForHealth(port, getPlatformTimeout(45000));
if (healthy) {
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Worker healthy after restart');
process.exit(0);
}
console.error('Worker failed to restart (concurrent operation)');
logger.error('SYSTEM', 'Worker failed to restart (concurrent operation)');
process.exit(1);
}
@@ -1069,7 +1069,7 @@ async function main() {
if (child.pid === undefined) {
releaseLock();
console.error('Failed to spawn worker daemon during restart');
logger.error('SYSTEM', 'Failed to spawn worker daemon during restart');
process.exit(1);
}
@@ -1081,10 +1081,10 @@ async function main() {
if (!healthy) {
removePidFile();
console.error('Worker failed to restart');
logger.error('SYSTEM', 'Worker failed to restart');
process.exit(1);
}
console.log(HOOK_RESPONSE);
logger.info('SYSTEM', 'Worker restarted successfully');
process.exit(0);
} catch (error) {
releaseLock();
@@ -1096,9 +1096,9 @@ async function main() {
const running = await isPortInUse(port);
const pidInfo = readPidFile();
if (running && pidInfo) {
console.log(`Worker running (PID: ${pidInfo.pid}, Port: ${pidInfo.port})`);
logger.info('SYSTEM', `Worker running (PID: ${pidInfo.pid}, Port: ${pidInfo.port})`);
} else {
console.log('Worker not running');
logger.info('SYSTEM', 'Worker not running');
}
process.exit(0);
}
+1
View File
@@ -5,6 +5,7 @@
import { ObservationSearchResult, SessionSummarySearchResult, UserPromptSearchResult } from '../sqlite/types.js';
import { ModeManager } from '../domain/ModeManager.js';
import { logger } from '../../utils/logger.js';
// Token estimation constant (matches context-generator)
const CHARS_PER_TOKEN_ESTIMATE = 4;
+1
View File
@@ -8,6 +8,7 @@
*/
import { DatabaseManager } from './DatabaseManager.js';
import { logger } from '../../utils/logger.js';
import type { PaginatedResult, Observation, Summary, UserPrompt } from '../worker-types.js';
export class PaginationHelper {
+1
View File
@@ -5,6 +5,7 @@
import { ObservationSearchResult, SessionSummarySearchResult, UserPromptSearchResult } from '../sqlite/types.js';
import { ModeManager } from '../domain/ModeManager.js';
import { logger } from '../../utils/logger.js';
/**
* Timeline item for unified chronological display
@@ -7,6 +7,7 @@
import { SSEBroadcaster } from '../SSEBroadcaster.js';
import type { WorkerService } from '../../worker-service.js';
import { logger } from '../../../utils/logger.js';
export class SessionEventBroadcaster {
constructor(
@@ -8,6 +8,7 @@
import express, { Request, Response } from 'express';
import path from 'path';
import { readFileSync, statSync, existsSync } from 'fs';
import { logger } from '../../../../utils/logger.js';
import { homedir } from 'os';
import { getPackageRoot } from '../../../../shared/paths.js';
import { getWorkerPort } from '../../../../shared/worker-utils.js';
@@ -8,6 +8,7 @@
import express, { Request, Response } from 'express';
import { SearchManager } from '../../SearchManager.js';
import { BaseRouteHandler } from '../BaseRouteHandler.js';
import { logger } from '../../../../utils/logger.js';
export class SearchRoutes extends BaseRouteHandler {
constructor(
@@ -8,6 +8,7 @@
import express, { Request, Response } from 'express';
import path from 'path';
import { readFileSync, existsSync } from 'fs';
import { logger } from '../../../../utils/logger.js';
import { getPackageRoot } from '../../../../shared/paths.js';
import { SSEBroadcaster } from '../../SSEBroadcaster.js';
import { DatabaseManager } from '../../DatabaseManager.js';
@@ -11,6 +11,7 @@
import { SessionManager } from '../SessionManager.js';
import { SessionEventBroadcaster } from '../events/SessionEventBroadcaster.js';
import { logger } from '../../../utils/logger.js';
export class SessionCompletionHandler {
constructor(