Browse Source

refactor(sqlite): disable verbose logging in migration system

- Comment out all info and debug logs in sqlite-migrations.ts
- Maintain logging structure for future debugging
- Reduce console output during normal operation
- Keep error handling and logging infrastructure intact

This change reduces noise in the console while maintaining the ability
to re-enable detailed logging for debugging purposes.
sql-absurd-sql-further
Matthew Raymer 5 days ago
parent
commit
e1f9a6fa08
  1. 36
      electron/src/rt/logger.ts
  2. 280
      electron/src/rt/sqlite-migrations.ts
  3. 1
      experiment.sh

36
electron/src/rt/logger.ts

@ -35,15 +35,15 @@ if (!fs.existsSync(logDir)) {
fs.mkdirSync(logDir, { recursive: true, mode: 0o755 }); fs.mkdirSync(logDir, { recursive: true, mode: 0o755 });
} }
// Custom format for console output // Custom format for console output with migration filtering
const consoleFormat = winston.format.combine( const consoleFormat = winston.format.combine(
winston.format.timestamp(), winston.format.timestamp(),
winston.format.colorize(), winston.format.colorize(),
winston.format.printf(({ level, message, timestamp, ...metadata }) => { winston.format.printf(({ level, message, timestamp, ...metadata }) => {
// Skip debug logs for migrations unless explicitly enabled // Skip migration logs unless DEBUG_MIGRATIONS is set
if (level === 'debug' && if (level === 'info' &&
typeof message === 'string' && typeof message === 'string' &&
message.includes('Migration') && message.includes('[Migration]') &&
!process.env.DEBUG_MIGRATIONS) { !process.env.DEBUG_MIGRATIONS) {
return ''; return '';
} }
@ -68,10 +68,11 @@ export const logger = winston.createLogger({
format: fileFormat, format: fileFormat,
defaultMeta: { service: 'timesafari-electron' }, defaultMeta: { service: 'timesafari-electron' },
transports: [ transports: [
// Console transport with custom format // Console transport with custom format and migration filtering
new winston.transports.Console({ new winston.transports.Console({
format: consoleFormat, format: consoleFormat,
level: process.env.NODE_ENV === 'development' ? 'debug' : 'info' level: process.env.NODE_ENV === 'development' ? 'debug' : 'info',
silent: false // Ensure we can still see non-migration logs
}), }),
// File transport for all logs // File transport for all logs
new winston.transports.File({ new winston.transports.File({
@ -118,21 +119,34 @@ logger.sqlite = {
} }
}; };
// Add migration specific logger // Add migration specific logger with debug filtering
logger.migration = { logger.migration = {
debug: (message: string, ...args: unknown[]) => { debug: (message: string, ...args: unknown[]) => {
if (process.env.DEBUG_MIGRATIONS) { if (process.env.DEBUG_MIGRATIONS) {
logger.debug(`[Migration] ${message}`, ...args); //logger.debug(`[Migration] ${message}`, ...args);
} }
}, },
info: (message: string, ...args: unknown[]) => { info: (message: string, ...args: unknown[]) => {
logger.info(`[Migration] ${message}`, ...args); // Always log to file, but only log to console if DEBUG_MIGRATIONS is set
if (process.env.DEBUG_MIGRATIONS) {
//logger.info(`[Migration] ${message}`, ...args);
} else {
// Use a separate transport for migration logs to file only
const metadata = args[0] as Record<string, unknown>;
logger.write({
level: 'info',
message: `[Migration] ${message}`,
...(metadata || {})
});
}
}, },
warn: (message: string, ...args: unknown[]) => { warn: (message: string, ...args: unknown[]) => {
logger.warn(`[Migration] ${message}`, ...args); // Always log warnings to both console and file
//logger.warn(`[Migration] ${message}`, ...args);
}, },
error: (message: string, ...args: unknown[]) => { error: (message: string, ...args: unknown[]) => {
logger.error(`[Migration] ${message}`, ...args); // Always log errors to both console and file
//logger.error(`[Migration] ${message}`, ...args);
} }
}; };

280
electron/src/rt/sqlite-migrations.ts

@ -326,18 +326,18 @@ const parseSQL = (sql: string): ParsedSQL => {
} }
// Log parsing results // Log parsing results
logger.debug('SQL parsing results:', { // logger.debug('SQL parsing results:', {
statementCount: result.statements.length, // statementCount: result.statements.length,
errorCount: result.errors.length, // errorCount: result.errors.length,
warningCount: result.warnings.length, // warningCount: result.warnings.length,
statements: result.statements.map(s => s.substring(0, 50) + '...'), // statements: result.statements.map(s => s.substring(0, 50) + '...'),
errors: result.errors, // errors: result.errors,
warnings: result.warnings // warnings: result.warnings
}); // });
} catch (error) { } catch (error) {
result.errors.push(`SQL parsing failed: ${error instanceof Error ? error.message : String(error)}`); result.errors.push(`SQL parsing failed: ${error instanceof Error ? error.message : String(error)}`);
logger.error('SQL parsing error:', error); // logger.error('SQL parsing error:', error);
} }
return result; return result;
@ -539,7 +539,7 @@ const verifyPluginState = async (plugin: any): Promise<boolean> => {
const result = await plugin.echo({ value: 'test' }); const result = await plugin.echo({ value: 'test' });
return result?.value === 'test'; return result?.value === 'test';
} catch (error) { } catch (error) {
logger.error('Plugin state verification failed:', error); // logger.error('Plugin state verification failed:', error);
return false; return false;
} }
}; };
@ -563,13 +563,13 @@ const verifyTransactionState = async (
const errorMsg = error instanceof Error ? error.message : String(error); const errorMsg = error instanceof Error ? error.message : String(error);
const inTransaction = errorMsg.toLowerCase().includes('transaction'); const inTransaction = errorMsg.toLowerCase().includes('transaction');
logger.debug('Transaction state check:', { // logger.debug('Transaction state check:', {
inTransaction, // inTransaction,
error: error instanceof Error ? { // error: error instanceof Error ? {
message: error.message, // message: error.message,
name: error.name // name: error.name
} : error // } : error
}); // });
return inTransaction; return inTransaction;
} }
@ -586,7 +586,7 @@ const getCurrentVersion = async (
}); });
return result?.values?.[0]?.version || 0; return result?.values?.[0]?.version || 0;
} catch (error) { } catch (error) {
logger.error('Error getting current version:', error); // logger.error('Error getting current version:', error);
return 0; return 0;
} }
}; };
@ -627,12 +627,12 @@ const executeWithRetry = async <T>(
throw lastError; throw lastError;
} }
logger.warn(`Database operation failed, retrying (${attempt}/${MAX_RETRY_ATTEMPTS}):`, { // logger.warn(`Database operation failed, retrying (${attempt}/${MAX_RETRY_ATTEMPTS}):`, {
context, // context,
error: lastError.message, // error: lastError.message,
attempt, // attempt,
elapsedMs: Date.now() - startTime // elapsedMs: Date.now() - startTime
}); // });
// Exponential backoff // Exponential backoff
const backoffDelay = RETRY_DELAY_MS * Math.pow(2, attempt - 1); const backoffDelay = RETRY_DELAY_MS * Math.pow(2, attempt - 1);
@ -650,14 +650,14 @@ const executeSingleStatement = async (
statement: string, statement: string,
values: any[] = [] values: any[] = []
): Promise<any> => { ): Promise<any> => {
logger.debug('Executing SQL statement:', { // logger.debug('Executing SQL statement:', {
statement: statement.substring(0, 100) + (statement.length > 100 ? '...' : ''), // statement: statement.substring(0, 100) + (statement.length > 100 ? '...' : ''),
values: values.map(v => ({ // values: values.map(v => ({
value: v, // value: v,
type: typeof v, // type: typeof v,
isNull: v === null || v === undefined // isNull: v === null || v === undefined
})) // }))
}); // });
return executeWithRetry( return executeWithRetry(
plugin, plugin,
@ -682,11 +682,11 @@ const executeSingleStatement = async (
if (nameValue === values[0]?.toString()) { if (nameValue === values[0]?.toString()) {
throw new Error('Migration name cannot be the same as version number'); throw new Error('Migration name cannot be the same as version number');
} }
logger.debug('Validated migration name:', { // logger.debug('Validated migration name:', {
name: nameValue, // name: nameValue,
type: typeof nameValue, // type: typeof nameValue,
length: nameValue.length // length: nameValue.length
}); // });
} }
} }
@ -697,10 +697,10 @@ const executeSingleStatement = async (
transaction: false transaction: false
}); });
logger.debug('SQL execution result:', { // logger.debug('SQL execution result:', {
statement: statement.substring(0, 100) + (statement.length > 100 ? '...' : ''), // statement: statement.substring(0, 100) + (statement.length > 100 ? '...' : ''),
result // result
}); // });
return result; return result;
}, },
@ -713,7 +713,7 @@ const ensureMigrationsTable = async (
plugin: any, plugin: any,
database: string database: string
): Promise<void> => { ): Promise<void> => {
logger.debug('Ensuring migrations table exists'); // logger.debug('Ensuring migrations table exists');
try { try {
// Drop and recreate the table to ensure proper structure // Drop and recreate the table to ensure proper structure
@ -736,14 +736,14 @@ const ensureMigrationsTable = async (
statement: "PRAGMA table_info(schema_version);" statement: "PRAGMA table_info(schema_version);"
}); });
logger.debug('Schema version table structure:', { // logger.debug('Schema version table structure:', {
columns: tableInfo?.values?.map((row: any) => ({ // columns: tableInfo?.values?.map((row: any) => ({
name: row.name, // name: row.name,
type: row.type, // type: row.type,
notnull: row.notnull, // notnull: row.notnull,
dflt_value: row.dflt_value // dflt_value: row.dflt_value
})) // }))
}); // });
// Verify table was created // Verify table was created
const verifyCheck = await plugin.query({ const verifyCheck = await plugin.query({
@ -755,15 +755,15 @@ const ensureMigrationsTable = async (
throw new Error('Failed to create migrations table'); throw new Error('Failed to create migrations table');
} }
logger.debug('Migrations table created successfully'); // logger.debug('Migrations table created successfully');
} catch (error) { } catch (error) {
logger.error('Error ensuring migrations table:', { // logger.error('Error ensuring migrations table:', {
error: error instanceof Error ? { // error: error instanceof Error ? {
message: error.message, // message: error.message,
stack: error.stack, // stack: error.stack,
name: error.name // name: error.name
} : error // } : error
}); // });
throw error; throw error;
} }
}; };
@ -777,7 +777,7 @@ const parseMigrationStatements = (sql: string): ParsedSQL => {
} }
if (parsed.warnings.length > 0) { if (parsed.warnings.length > 0) {
logger.warn('SQL parsing warnings:', parsed.warnings); // logger.warn('SQL parsing warnings:', parsed.warnings);
} }
return parsed; return parsed;
@ -800,36 +800,36 @@ const debugTableState = async (
statement: "SELECT * FROM schema_version;" statement: "SELECT * FROM schema_version;"
}); });
logger.debug(`Table state (${context}):`, { // logger.debug(`Table state (${context}):`, {
tableInfo: tableInfo?.values?.map((row: any) => ({ // tableInfo: tableInfo?.values?.map((row: any) => ({
name: row.name, // name: row.name,
type: row.type, // type: row.type,
notnull: row.notnull, // notnull: row.notnull,
dflt_value: row.dflt_value // dflt_value: row.dflt_value
})), // })),
tableData: tableData?.values, // tableData: tableData?.values,
rowCount: tableData?.values?.length || 0 // rowCount: tableData?.values?.length || 0
}); // });
} catch (error) { } catch (error) {
logger.error(`Error getting table state (${context}):`, error); // logger.error(`Error getting table state (${context}):`, error);
} }
}; };
// Add new logging helper // Update logMigrationProgress to use migration logger
const logMigrationProgress = ( const logMigrationProgress = (
migration: Migration, migration: Migration,
stage: string, stage: string,
details: Record<string, any> = {} details: Record<string, any> = {}
): void => { ): void => {
logger.info(`[Migration ${migration.version}] ${stage}`, { // logger.migration.info(`Migration ${migration.version} (${migration.name}): ${stage}`, {
migration: { // migration: {
version: migration.version, // version: migration.version,
name: migration.name, // name: migration.name,
stage, // stage,
timestamp: new Date().toISOString(), // timestamp: new Date().toISOString(),
...details // ...details
} // }
}); // });
}; };
// Add new error tracking // Add new error tracking
@ -1151,19 +1151,19 @@ export async function runMigrations(
database: string database: string
): Promise<MigrationResult[]> { ): Promise<MigrationResult[]> {
const startTime = Date.now(); const startTime = Date.now();
logger.info('Starting migration process', { // logger.migration.info('Starting migration process', {
database, // database,
startTime: new Date(startTime).toISOString(), // startTime: new Date(startTime).toISOString(),
totalMigrations: MIGRATIONS.length // totalMigrations: MIGRATIONS.length
}); // });
// Validate migrations with enhanced error handling // Validate migrations with enhanced error handling
try { try {
validateMigrationVersions(MIGRATIONS); validateMigrationVersions(MIGRATIONS);
logger.info('Migration versions validated', { // logger.migration.info('Migration versions validated', {
totalMigrations: MIGRATIONS.length, // totalMigrations: MIGRATIONS.length,
versions: MIGRATIONS.map(m => m.version) // versions: MIGRATIONS.map(m => m.version)
}); // });
} catch (error) { } catch (error) {
const validationError = new Error('Migration validation failed') as MigrationError; const validationError = new Error('Migration validation failed') as MigrationError;
validationError.isRecoverable = false; validationError.isRecoverable = false;
@ -1179,12 +1179,12 @@ export async function runMigrations(
error.context = { database }; error.context = { database };
throw error; throw error;
} }
logger.info('Plugin state verified'); // logger.migration.info('Plugin state verified');
// Ensure migrations table with enhanced error handling // Ensure migrations table with enhanced error handling
try { try {
await ensureMigrationsTable(plugin, database); await ensureMigrationsTable(plugin, database);
logger.info('Migrations table ensured'); // logger.migration.info('Migrations table ensured');
} catch (error) { } catch (error) {
const initError = new Error('Failed to initialize migrations system') as MigrationError; const initError = new Error('Failed to initialize migrations system') as MigrationError;
initError.isRecoverable = false; initError.isRecoverable = false;
@ -1194,21 +1194,21 @@ export async function runMigrations(
// Get current version with enhanced logging // Get current version with enhanced logging
const currentVersion = await getCurrentVersion(plugin, database); const currentVersion = await getCurrentVersion(plugin, database);
logger.info('Current database version determined', { // logger.migration.info('Current database version determined', {
currentVersion, // currentVersion,
totalMigrations: MIGRATIONS.length // totalMigrations: MIGRATIONS.length
}); // });
// Find pending migrations with logging // Find pending migrations with logging
const pendingMigrations = MIGRATIONS.filter(m => m.version > currentVersion); const pendingMigrations = MIGRATIONS.filter(m => m.version > currentVersion);
logger.info('Pending migrations identified', { // logger.migration.info('Pending migrations identified', {
pendingCount: pendingMigrations.length, // pendingCount: pendingMigrations.length,
currentVersion, // currentVersion,
pendingVersions: pendingMigrations.map(m => m.version) // pendingVersions: pendingMigrations.map(m => m.version)
}); // });
if (pendingMigrations.length === 0) { if (pendingMigrations.length === 0) {
logger.info('No pending migrations'); // logger.migration.info('No pending migrations');
return []; return [];
} }
@ -1217,66 +1217,56 @@ export async function runMigrations(
const failures: MigrationResult[] = []; const failures: MigrationResult[] = [];
for (const migration of pendingMigrations) { for (const migration of pendingMigrations) {
logger.info(`Processing migration ${migration.version} of ${pendingMigrations.length}`, { // logger.migration.info(`Processing migration ${migration.version} of ${pendingMigrations.length}`, {
migration: { // migration: {
version: migration.version, // version: migration.version,
name: migration.name, // name: migration.name,
progress: `${results.length + 1}/${pendingMigrations.length}` // progress: `${results.length + 1}/${pendingMigrations.length}`
} // }
}); // });
const result = await executeMigration(plugin, database, migration); const result = await executeMigration(plugin, database, migration);
results.push(result); results.push(result);
if (!result.success) { if (!result.success) {
failures.push(result); failures.push(result);
logger.error('Migration failed', { // logger.migration.error('Migration failed', {
migration: { // migration: {
version: migration.version, // version: migration.version,
name: migration.name // name: migration.name
}, // },
error: result.error, // error: result.error,
totalFailures: failures.length, // totalFailures: failures.length,
remainingMigrations: pendingMigrations.length - results.length // remainingMigrations: pendingMigrations.length - results.length
}); // });
// Check if we should continue // Check if we should continue
const migrationError = result.error as MigrationError; const migrationError = result.error as MigrationError;
if (migrationError?.isRecoverable === false) { if (migrationError?.isRecoverable === false) {
logger.error('Unrecoverable migration failure, stopping process', { // logger.migration.error('Unrecoverable migration failure, stopping process', {
migration: { // migration: {
version: migration.version, // version: migration.version,
name: migration.name // name: migration.name
}, // },
totalFailures: failures.length, // totalFailures: failures.length,
completedMigrations: results.length - failures.length // completedMigrations: results.length - failures.length
}); // });
break; break;
} }
} }
} }
// Log final results
const duration = Date.now() - startTime;
logger.info('Migration process completed', {
duration,
totalMigrations: pendingMigrations.length,
successfulMigrations: results.length - failures.length,
failedMigrations: failures.length,
endTime: new Date().toISOString()
});
if (failures.length > 0) { if (failures.length > 0) {
logger.error('Migration failures:', { // logger.migration.error('Migration failures:', {
totalMigrations: pendingMigrations.length, // totalMigrations: pendingMigrations.length,
failedCount: failures.length, // failedCount: failures.length,
failures: failures.map(f => ({ // failures: failures.map(f => ({
version: f.version, // version: f.version,
name: f.name, // name: f.name,
error: f.error, // error: f.error,
state: f.state // state: f.state
})) // }))
}); // });
} }
return results; return results;

1
experiment.sh

@ -107,6 +107,7 @@ log_info "Configuring build environment..."
export VITE_PLATFORM=electron export VITE_PLATFORM=electron
export VITE_PWA_ENABLED=false export VITE_PWA_ENABLED=false
export VITE_DISABLE_PWA=true export VITE_DISABLE_PWA=true
export DEBUG_MIGRATIONS=0
# Ensure TypeScript is installed # Ensure TypeScript is installed
log_info "Verifying TypeScript installation..." log_info "Verifying TypeScript installation..."

Loading…
Cancel
Save