feat(logging): enhance SQLite logging and IPC handler management

- Add Winston-based structured logging system with:
  - Separate console and file output formats
  - Custom SQLite and migration loggers
  - Configurable log levels and verbosity
  - Log rotation and file management
  - Type-safe logger extensions

- Improve IPC handler management:
  - Add handler registration tracking
  - Implement proper cleanup before re-registration
  - Fix handler registration conflicts
  - Add better error handling for IPC operations

- Add migration logging controls:
  - Configurable via DEBUG_MIGRATIONS env var
  - Reduced console noise while maintaining file logs
  - Structured migration status reporting

Security:
- Add proper log file permissions (0o755)
- Implement log rotation to prevent disk space issues
- Add type safety for all logging operations
- Prevent handler registration conflicts

Dependencies:
- Add winston for enhanced logging
- Remove deprecated @types/winston

This change improves debugging capabilities while reducing console noise
and fixing IPC handler registration issues that could cause database
operation failures.
This commit is contained in:
Matthew Raymer
2025-06-03 13:05:40 +00:00
parent 5d97c98ae8
commit 340e718199
5 changed files with 578 additions and 287 deletions

View File

@@ -1,77 +1,140 @@
/**
* Structured logging system for TimeSafari
* Enhanced logging system for TimeSafari Electron
* Provides structured logging with proper levels and formatting
* Supports both console and file output with different verbosity levels
*
* Provides consistent logging across the application with:
* - Timestamp tracking
* - Log levels (debug, info, warn, error)
* - Structured data support
* - Component tagging
*
* @author Matthew Raymer <matthew.raymer@anomalistdesign.com>
* @version 1.0.0
* @since 2025-06-01
* @author Matthew Raymer
*/
// Log levels
export enum LogLevel {
DEBUG = 'DEBUG',
INFO = 'INFO',
WARN = 'WARN',
ERROR = 'ERROR'
}
import winston from 'winston';
import path from 'path';
import os from 'os';
import fs from 'fs';
// Log entry interface
interface LogEntry {
timestamp: string;
level: LogLevel;
component: string;
message: string;
data?: unknown;
}
// Format log entry
const formatLogEntry = (entry: LogEntry): string => {
const { timestamp, level, component, message, data } = entry;
const dataStr = data ? ` ${JSON.stringify(data, null, 2)}` : '';
return `[${timestamp}] [${level}] [${component}] ${message}${dataStr}`;
};
// Create logger for a specific component
export const createLogger = (component: string) => {
const log = (level: LogLevel, message: string, data?: unknown) => {
const entry: LogEntry = {
timestamp: new Date().toISOString(),
level,
component,
message,
data
// Extend Winston Logger type with our custom loggers
declare module 'winston' {
interface Logger {
sqlite: {
debug: (message: string, ...args: unknown[]) => void;
info: (message: string, ...args: unknown[]) => void;
warn: (message: string, ...args: unknown[]) => void;
error: (message: string, ...args: unknown[]) => void;
};
migration: {
debug: (message: string, ...args: unknown[]) => void;
info: (message: string, ...args: unknown[]) => void;
warn: (message: string, ...args: unknown[]) => void;
error: (message: string, ...args: unknown[]) => void;
};
}
}
const formatted = formatLogEntry(entry);
switch (level) {
case LogLevel.DEBUG:
console.debug(formatted);
break;
case LogLevel.INFO:
console.info(formatted);
break;
case LogLevel.WARN:
console.warn(formatted);
break;
case LogLevel.ERROR:
console.error(formatted);
break;
// Ensure log directory exists
const logDir = path.join(os.homedir(), 'Logs', 'TimeSafari');
if (!fs.existsSync(logDir)) {
fs.mkdirSync(logDir, { recursive: true, mode: 0o755 });
}
// Custom format for console output
const consoleFormat = winston.format.combine(
winston.format.timestamp(),
winston.format.colorize(),
winston.format.printf(({ level, message, timestamp, ...metadata }) => {
// Skip debug logs for migrations unless explicitly enabled
if (level === 'debug' &&
typeof message === 'string' &&
message.includes('Migration') &&
!process.env.DEBUG_MIGRATIONS) {
return '';
}
};
let msg = `${timestamp} [${level}] ${message}`;
if (Object.keys(metadata).length > 0) {
msg += ` ${JSON.stringify(metadata, null, 2)}`;
}
return msg;
})
);
return {
debug: (message: string, data?: unknown) => log(LogLevel.DEBUG, message, data),
info: (message: string, data?: unknown) => log(LogLevel.INFO, message, data),
warn: (message: string, data?: unknown) => log(LogLevel.WARN, message, data),
error: (message: string, data?: unknown) => log(LogLevel.ERROR, message, data)
// Custom format for file output
const fileFormat = winston.format.combine(
winston.format.timestamp(),
winston.format.json()
);
// Create logger instance
export const logger = winston.createLogger({
level: process.env.NODE_ENV === 'development' ? 'debug' : 'info',
format: fileFormat,
defaultMeta: { service: 'timesafari-electron' },
transports: [
// Console transport with custom format
new winston.transports.Console({
format: consoleFormat,
level: process.env.NODE_ENV === 'development' ? 'debug' : 'info'
}),
// File transport for all logs
new winston.transports.File({
filename: path.join(logDir, 'error.log'),
level: 'error',
maxsize: 5242880, // 5MB
maxFiles: 5
}),
// File transport for all logs including debug
new winston.transports.File({
filename: path.join(logDir, 'combined.log'),
maxsize: 5242880, // 5MB
maxFiles: 5
})
]
}) as winston.Logger & {
sqlite: {
debug: (message: string, ...args: unknown[]) => void;
info: (message: string, ...args: unknown[]) => void;
warn: (message: string, ...args: unknown[]) => void;
error: (message: string, ...args: unknown[]) => void;
};
migration: {
debug: (message: string, ...args: unknown[]) => void;
info: (message: string, ...args: unknown[]) => void;
warn: (message: string, ...args: unknown[]) => void;
error: (message: string, ...args: unknown[]) => void;
};
};
// Create default logger for SQLite operations
export const logger = createLogger('SQLite');
// Add SQLite specific logger
logger.sqlite = {
debug: (message: string, ...args: unknown[]) => {
logger.debug(`[SQLite] ${message}`, ...args);
},
info: (message: string, ...args: unknown[]) => {
logger.info(`[SQLite] ${message}`, ...args);
},
warn: (message: string, ...args: unknown[]) => {
logger.warn(`[SQLite] ${message}`, ...args);
},
error: (message: string, ...args: unknown[]) => {
logger.error(`[SQLite] ${message}`, ...args);
}
};
// Add migration specific logger
logger.migration = {
debug: (message: string, ...args: unknown[]) => {
if (process.env.DEBUG_MIGRATIONS) {
logger.debug(`[Migration] ${message}`, ...args);
}
},
info: (message: string, ...args: unknown[]) => {
logger.info(`[Migration] ${message}`, ...args);
},
warn: (message: string, ...args: unknown[]) => {
logger.warn(`[Migration] ${message}`, ...args);
},
error: (message: string, ...args: unknown[]) => {
logger.error(`[Migration] ${message}`, ...args);
}
};
// Export logger instance
export default logger;

View File

@@ -9,9 +9,9 @@
* - Plugin initialization and state verification
* - Connection lifecycle management
* - PRAGMA configuration for optimal performance
* - Migration system integration
* - Migration system integration with configurable logging
* - Error handling and recovery
* - IPC communication layer
* - IPC communication layer with proper cleanup
*
* Database Configuration:
* - Uses WAL journal mode for better concurrency
@@ -56,6 +56,7 @@ import path from 'path';
import os from 'os';
import { runMigrations } from './sqlite-migrations';
import { logger } from './logger';
import { startDatabaseOperation, endDatabaseOperation } from '../setup';
// Types for state management
interface PluginState {
@@ -597,255 +598,218 @@ export async function initializeSQLite(): Promise<void> {
}
}
// Add IPC handler tracking
const registeredHandlers = new Set<string>();
/**
* Removes all registered SQLite IPC handlers
* Called before re-registering handlers to prevent duplicates
*/
const cleanupSQLiteHandlers = (): void => {
logger.debug('Cleaning up SQLite IPC handlers');
for (const channel of registeredHandlers) {
try {
ipcMain.removeHandler(channel);
logger.debug(`Removed handler for channel: ${channel}`);
} catch (error) {
logger.warn(`Failed to remove handler for channel ${channel}:`, error);
}
}
registeredHandlers.clear();
};
/**
* Registers an IPC handler with tracking
* @param channel The IPC channel to register
* @param handler The handler function
*/
const registerHandler = (channel: string, handler: (...args: any[]) => Promise<any>): void => {
if (registeredHandlers.has(channel)) {
logger.debug(`Handler already registered for channel: ${channel}, removing first`);
ipcMain.removeHandler(channel);
}
ipcMain.handle(channel, handler);
registeredHandlers.add(channel);
logger.debug(`Registered handler for channel: ${channel}`);
};
/**
* Sets up IPC handlers for SQLite operations
* Registers handlers for all SQLite operations defined in VALID_CHANNELS.invoke
* Tracks database operations to prevent reloads during critical operations
* Implements proper handler cleanup to prevent duplicates
*
* Registers handlers for:
* - Plugin availability checks
* - Connection management
* - Query execution
* - Error retrieval
*
* Each handler includes:
* - State verification
* - Error handling
* - Detailed logging
* - Transaction safety
*
* Security:
* - Validates all incoming requests
* - Verifies plugin state
* - Maintains connection isolation
*
* @throws {Error} If handler registration fails
* @author Matthew Raymer
*/
export function setupSQLiteHandlers(): void {
// Remove existing handlers
const handlers = [
'sqlite-is-available',
'sqlite-echo',
'sqlite-create-connection',
'sqlite-execute',
'sqlite-query',
'sqlite-run',
'sqlite-close-connection',
'sqlite-get-error'
];
logger.info('Setting up SQLite IPC handlers');
handlers.forEach(handler => {
try {
ipcMain.removeHandler(handler);
} catch (error) {
logger.warn(`Error removing handler ${handler}:`, error);
}
});
// Register handlers
ipcMain.handle('sqlite-is-available', async () => {
// Clean up any existing handlers first
cleanupSQLiteHandlers();
// Handler for checking SQLite availability
registerHandler('sqlite-is-available', async () => {
logger.debug('Checking SQLite availability');
try {
startDatabaseOperation();
const isAvailable = await verifyPluginState();
logger.debug('Plugin availability check:', { isAvailable });
logger.debug('SQLite availability check:', { isAvailable });
return isAvailable;
} catch (error) {
logger.error('Error checking plugin availability:', error);
return false;
logger.error('SQLite availability check failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Enhanced sqlite-echo handler
ipcMain.handle('sqlite-echo', async (_event, options) => {
// Handler for echo test
registerHandler('sqlite-echo', async (_event, { value }) => {
logger.debug('SQLite echo test:', { value });
try {
if (!await verifyPluginState()) {
throw new SQLiteError(
'Plugin not available',
'sqlite-echo',
'SQLITE_PLUGIN_UNAVAILABLE',
null,
{ pluginState }
);
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-echo');
}
if (!options || typeof options !== 'object' || !('value' in options)) {
throw new SQLiteError(
'Invalid echo options',
'sqlite-echo',
'SQLITE_INVALID_OPTIONS',
null,
{ options }
);
}
const { value } = options as { value: unknown };
if (typeof value !== 'string') {
throw new SQLiteError(
'Echo value must be a string',
'sqlite-echo',
'SQLITE_INVALID_VALUE',
null,
{ value, type: typeof value }
);
}
logger.debug('Echo test:', { value, timestamp: new Date().toISOString() });
const result = await pluginState.instance.echo({ value });
if (!result || typeof result !== 'object' || !('value' in result)) {
throw new SQLiteError(
'Invalid echo result',
'sqlite-echo',
'SQLITE_INVALID_RESULT',
null,
{ result }
);
}
if (result.value !== value) {
throw new SQLiteError(
'Echo test failed - value mismatch',
'sqlite-echo',
'SQLITE_ECHO_MISMATCH',
null,
{ expected: value, received: result.value }
);
}
return result as SQLiteEchoResult;
logger.debug('SQLite echo result:', result);
return result;
} catch (error) {
throw handleError(error, 'sqlite-echo', { options });
logger.error('SQLite echo failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
ipcMain.handle('sqlite-get-error', async () => {
return pluginState.lastError ? {
message: pluginState.lastError.message,
stack: pluginState.lastError.stack,
name: pluginState.lastError.name,
context: (pluginState.lastError as SQLiteError).context
} : null;
});
// Add other handlers with proper state verification
ipcMain.handle('sqlite-create-connection', async (_event, options) => {
// Handler for creating database connection
registerHandler('sqlite-create-connection', async (_event, options: SQLiteConnectionOptions) => {
logger.debug('Creating SQLite connection:', options);
try {
if (!await verifyPluginState()) {
throw new SQLiteError('Plugin not available', 'sqlite-create-connection');
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-create-connection');
}
// ... rest of connection creation logic ...
const validatedOptions = validateConnectionOptions(options);
await pluginState.instance.createConnection(validatedOptions);
logger.debug('SQLite connection created successfully');
return true;
} catch (error) {
throw handleError(error, 'sqlite-create-connection');
logger.error('SQLite connection creation failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Enhanced sqlite-run handler
ipcMain.handle('sqlite-run', async (_event, options) => {
// Handler for executing SQL statements
registerHandler('sqlite-execute', async (_event, options: SQLiteExecuteOptions) => {
logger.debug('Executing SQL statements:', options);
try {
if (!await verifyPluginState()) {
throw new SQLiteError(
'Plugin not available',
'sqlite-run',
'SQLITE_PLUGIN_UNAVAILABLE',
null,
{ pluginState }
);
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-execute');
}
const runOptions = validateQueryOptions(options);
const runWithDb = {
database: 'timesafari',
...runOptions
};
logger.debug('Running SQL statement:', {
...runWithDb,
timestamp: new Date().toISOString()
});
const result = await pluginState.instance.run(runWithDb);
if (!result) {
throw new SQLiteError(
'Run operation returned no result',
'sqlite-run',
'SQLITE_NO_RESULT',
null,
{ run: runWithDb }
);
}
// Validate result structure
if (!('changes' in result)) {
throw new SQLiteError(
'Invalid run result structure',
'sqlite-run',
'SQLITE_INVALID_RESULT',
null,
{ result }
);
}
return result as SQLiteResult;
const result = await pluginState.instance.execute(options);
logger.debug('SQL execution result:', result);
return result;
} catch (error) {
throw handleError(error, 'sqlite-run', { options });
logger.error('SQL execution failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Enhanced sqlite-query handler
ipcMain.handle('sqlite-query', async (_event, options) => {
// Handler for querying data
registerHandler('sqlite-query', async (_event, options: SQLiteQueryOptions) => {
logger.debug('Querying SQLite:', options);
try {
if (!await verifyPluginState()) {
throw new SQLiteError(
'Plugin not available',
'sqlite-query',
'SQLITE_PLUGIN_UNAVAILABLE',
null,
{ pluginState }
);
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-query');
}
const queryOptions = validateQueryOptions(options);
const queryWithDb = {
database: 'timesafari',
...queryOptions
};
logger.debug('Executing SQL query:', {
...queryWithDb,
timestamp: new Date().toISOString()
});
const result = await pluginState.instance.query(queryWithDb);
if (!result) {
throw new SQLiteError(
'Query operation returned no result',
'sqlite-query',
'SQLITE_NO_RESULT',
null,
{ query: queryWithDb }
);
}
// Validate result structure
if (!('values' in result) && !('changes' in result)) {
throw new SQLiteError(
'Invalid query result structure',
'sqlite-query',
'SQLITE_INVALID_RESULT',
null,
{ result }
);
}
return result as SQLiteResult;
const result = await pluginState.instance.query(options);
logger.debug('SQL query result:', result);
return result;
} catch (error) {
throw handleError(error, 'sqlite-query', { options });
logger.error('SQL query failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
logger.info('SQLite IPC handlers registered successfully', {
handlers: handlers.join(', '),
timestamp: new Date().toISOString()
// Handler for running SQL statements
registerHandler('sqlite-run', async (_event, options: SQLiteQueryOptions) => {
logger.debug('Running SQL statement:', options);
try {
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-run');
}
const result = await pluginState.instance.run(options);
logger.debug('SQL run result:', result);
return result;
} catch (error) {
logger.error('SQL run failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Handler for closing database connection
registerHandler('sqlite-close-connection', async (_event, options: { database: string }) => {
logger.debug('Closing SQLite connection:', options);
try {
startDatabaseOperation();
if (!pluginState.instance) {
throw new SQLiteError('Plugin not initialized', 'sqlite-close-connection');
}
await pluginState.instance.closeConnection(options);
logger.debug('SQLite connection closed successfully');
return true;
} catch (error) {
logger.error('SQLite connection close failed:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Handler for getting database path
registerHandler('get-path', async () => {
logger.debug('Getting database path');
try {
startDatabaseOperation();
const dbDir = await initializeDatabasePaths();
const dbPath = path.join(dbDir, 'timesafariSQLite.db');
logger.debug('Database path:', dbPath);
return dbPath;
} catch (error) {
logger.error('Failed to get database path:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
// Handler for getting base path
registerHandler('get-base-path', async () => {
logger.debug('Getting base path');
try {
startDatabaseOperation();
const dbDir = await initializeDatabasePaths();
logger.debug('Base path:', dbDir);
return dbDir;
} catch (error) {
logger.error('Failed to get base path:', error);
throw error;
} finally {
endDatabaseOperation();
}
});
logger.info('SQLite IPC handlers setup complete');
}

View File

@@ -15,6 +15,7 @@ import { join } from 'path';
/**
* Reload watcher configuration and state management
* Prevents infinite reload loops and implements rate limiting
* Also prevents reloads during critical database operations
*
* @author Matthew Raymer
*/
@@ -22,7 +23,38 @@ const RELOAD_CONFIG = {
DEBOUNCE_MS: 1500,
COOLDOWN_MS: 5000,
MAX_RELOADS_PER_MINUTE: 10,
MAX_RELOADS_PER_SESSION: 100
MAX_RELOADS_PER_SESSION: 100,
DATABASE_OPERATION_TIMEOUT_MS: 10000 // 10 second timeout for database operations
};
// Track database operation state
let isDatabaseOperationInProgress = false;
let lastDatabaseOperationTime = 0;
/**
* Checks if a database operation is in progress or recently completed
* @returns {boolean} Whether a database operation is active
*/
const isDatabaseOperationActive = (): boolean => {
const now = Date.now();
return isDatabaseOperationInProgress ||
(now - lastDatabaseOperationTime < RELOAD_CONFIG.DATABASE_OPERATION_TIMEOUT_MS);
};
/**
* Marks the start of a database operation
*/
export const startDatabaseOperation = (): void => {
isDatabaseOperationInProgress = true;
lastDatabaseOperationTime = Date.now();
};
/**
* Marks the end of a database operation
*/
export const endDatabaseOperation = (): void => {
isDatabaseOperationInProgress = false;
lastDatabaseOperationTime = Date.now();
};
const reloadWatcher = {
@@ -45,12 +77,18 @@ const resetReloadCounter = () => {
};
/**
* Checks if a reload is allowed based on rate limits and cooldown
* Checks if a reload is allowed based on rate limits, cooldown, and database state
* @returns {boolean} Whether a reload is allowed
*/
const canReload = (): boolean => {
const now = Date.now();
// Check if database operation is active
if (isDatabaseOperationActive()) {
console.warn('[Reload Watcher] Skipping reload - database operation in progress');
return false;
}
// Check cooldown period
if (now - reloadWatcher.lastReloadTime < RELOAD_CONFIG.COOLDOWN_MS) {
console.warn('[Reload Watcher] Skipping reload - cooldown period active');
@@ -342,6 +380,14 @@ export class ElectronCapacitorApp {
if (!this.CapacitorFileConfig.electron?.hideMainWindowOnLaunch) {
this.MainWindow.show();
}
// Re-register SQLite handlers after reload
if (electronIsDev) {
console.log('[Electron Main Process] Re-registering SQLite handlers after reload');
const { setupSQLiteHandlers } = require('./rt/sqlite-init');
setupSQLiteHandlers();
}
setTimeout(() => {
if (electronIsDev) {
this.MainWindow.webContents.openDevTools();