From e25eb3fa5ecaacbbddce93af9b18c490399c7dcd Mon Sep 17 00:00:00 2001 From: root Date: Fri, 23 Jan 2026 08:02:02 -0500 Subject: [PATCH] feat: implement structured logging for sync operations - Add comprehensive structured logging utility (lib/utils/sync-logger.ts) - Log levels: DEBUG, INFO, WARN, ERROR - Automatic error categorization (NETWORK_ERROR, AUTH_ERROR, DATABASE_ERROR, etc.) - Phase tracking (INITIALIZING, FETCHING, MAPPING, VALIDATING, UPSERTING, DELETING, COMPLETING) - Contextual metadata (syncId, entityType, phase, duration, record counts) - Timing helpers for operations - Update sync-service.ts with structured logging - Replace console.log/error with structured logger - Consistent error categorization across all error paths - Fix swallowed errors in sync history updates - Add child loggers for entity-specific operations - Update entity-sync.ts with structured logging - Complete phase tracking throughout sync lifecycle - Detailed context for warnings and errors - Update chunked sync methods with structured logging - Update picklist sync methods (issue types, sub-issue types) - Better debugging info with timing and sample data - Add sync failure analysis script (scripts/analyze-sync-failures.ts) - Query sync history by date range, entity type, or status - Generate failure summaries by entity - Automatic error categorization - Calculate success rates and statistics - Display detailed sync records with timing - Add comprehensive documentation (docs/SYNC_LOGGING_IMPROVEMENTS.md) - Usage guide and examples - Migration guide for developers - Before/after comparisons This addresses inconsistent logging and improves debugging capabilities for sync operations. --- docs/SYNC_LOGGING_IMPROVEMENTS.md | 262 ++++++++++++++++++++++ lib/services/entity-sync.ts | 222 ++++++++++-------- lib/services/sync-service.ts | 94 ++++---- lib/utils/sync-logger.ts | 257 +++++++++++++++++++++ scripts/analyze-sync-failures.ts | 360 ++++++++++++++++++++++++++++++ 5 files changed, 1056 insertions(+), 139 deletions(-) create mode 100644 docs/SYNC_LOGGING_IMPROVEMENTS.md create mode 100644 lib/utils/sync-logger.ts create mode 100644 scripts/analyze-sync-failures.ts diff --git a/docs/SYNC_LOGGING_IMPROVEMENTS.md b/docs/SYNC_LOGGING_IMPROVEMENTS.md new file mode 100644 index 0000000..d6c0c4c --- /dev/null +++ b/docs/SYNC_LOGGING_IMPROVEMENTS.md @@ -0,0 +1,262 @@ +# Sync Logging Improvements + +## Overview + +This document describes the structured logging improvements made to the sync system to address inconsistent logging and improve debugging capabilities. + +## Changes Made + +### 1. Structured Logging Utility (`lib/utils/sync-logger.ts`) + +Created a comprehensive logging utility with: + +- **Log Levels**: DEBUG, INFO, WARN, ERROR +- **Error Categorization**: Automatic categorization of errors into types: + - `NETWORK_ERROR`: Connection issues, timeouts + - `AUTH_ERROR`: Authentication/authorization failures + - `RATE_LIMIT_ERROR`: API rate limiting + - `DATABASE_CONSTRAINT_ERROR`: Foreign key violations, duplicates + - `DATABASE_ERROR`: General database errors + - `API_ERROR`: API-specific errors + - `MAPPING_ERROR`: Data transformation failures + - `VALIDATION_ERROR`: Data validation issues + - `UNKNOWN`: Uncategorized errors + +- **Sync Phases**: Track operations through distinct phases: + - `INITIALIZING`: Setup and configuration + - `FETCHING`: Retrieving data from Autotask API + - `MAPPING`: Transforming data to database schema + - `VALIDATING`: Checking data integrity + - `UPSERTING`: Writing to database + - `DELETING`: Soft-deleting missing records + - `COMPLETING`: Finalizing sync + +- **Contextual Logging**: Every log entry includes: + - Timestamp (ISO 8601) + - Log level + - Sync ID + - Entity type + - Current phase + - Record counts + - Duration metrics + - Error category (for errors) + +### 2. Updated `sync-service.ts` + +**Before:** +```typescript +console.log(`Starting ${config.syncType} sync: ${syncId}`); +console.error(`✗ Failed to sync ${entityName}:`); +console.error(` Error: ${errorMessage}`); +``` + +**After:** +```typescript +const syncLogger = this.logger.child({ syncId, syncType: config.syncType }); +syncLogger.info(`Starting ${config.syncType} sync`, { + entities: config.entities.map(e => getEntityDisplayName(e)).join(', '), + triggeredBy: config.triggeredBy, +}); + +entityLogger.error(`Failed to sync ${entityName}`, { + errorCategory, + syncType: config.syncType, +}, err); +``` + +**Key Improvements:** +- Consistent error categorization across all error paths +- Proper error logging for sync history update failures (previously swallowed) +- Structured context in all log statements +- Child loggers for entity-specific operations + +### 3. Updated `entity-sync.ts` + +**Before:** +```typescript +console.log(`[${entity}] Starting sync (${isIncremental ? 'incremental' : 'full'})`); +console.error(`[${entity}] API fetch failed:`, errorMessage); +console.warn(`[${entity}] Warning: All records failed mapping validation`); +``` + +**After:** +```typescript +const entityLogger = this.logger.child({ syncId: trackingId, entityType: entity }); +entityLogger.phase(SyncPhase.INITIALIZING); +entityLogger.phase(SyncPhase.FETCHING, 'Fetching records from Autotask API'); +entityLogger.error('API fetch failed', { phase: SyncPhase.FETCHING, errorCategory }, err); +entityLogger.warn('All records failed mapping validation', { originalCount: autotaskRecords.length }); +``` + +**Key Improvements:** +- Phase tracking throughout sync lifecycle +- Timing information for each operation +- Detailed context for warnings (record counts, sample IDs) +- Consistent error handling with categorization +- Better debugging information (sample records, field keys) + +### 4. Sync Failure Analysis Script + +Created `scripts/analyze-sync-failures.ts` to query and analyze sync history: + +**Features:** +- Query sync history by date range, entity type, or status +- Generate failure summaries by entity +- Categorize errors automatically +- Calculate success rates and statistics +- Display detailed sync records with timing + +**Usage Examples:** +```bash +# Show failures from last 7 days +npx tsx scripts/analyze-sync-failures.ts + +# Show all syncs from yesterday +npx tsx scripts/analyze-sync-failures.ts --days 1 --all + +# Show ticket sync failures from last 30 days +npx tsx scripts/analyze-sync-failures.ts --days 30 --entity tickets + +# Show all completed syncs +npx tsx scripts/analyze-sync-failures.ts --status completed --all +``` + +## Benefits + +### 1. **Consistent Logging Format** +All sync operations now use the same structured format, making logs easier to parse and analyze. + +### 2. **Better Error Categorization** +Errors are automatically categorized, making it easier to identify patterns: +- Network issues vs. API errors +- Database constraints vs. mapping failures +- Authentication problems vs. rate limiting + +### 3. **Phase Tracking** +Know exactly where a sync failed: +- Did it fail during API fetch? +- Was it a mapping error? +- Did the database upsert fail? + +### 4. **Improved Debugging** +- Sample data logged for complex entities +- Timing information for performance analysis +- Record counts at each stage +- Detailed context for warnings + +### 5. **No More Swallowed Errors** +Previously, sync history update failures were caught but not logged. Now they're properly tracked. + +### 6. **Easy Failure Analysis** +The analysis script provides: +- Quick overview of sync health +- Failure trends by entity +- Common error patterns +- Success rate metrics + +## Log Output Examples + +### Successful Sync +``` +[2026-01-23T12:21:00.000Z] [INFO] [syncId=sync_1234, entity=tickets, phase=initializing] Starting tickets sync (full) +[2026-01-23T12:21:00.100Z] [INFO] [syncId=sync_1234, entity=tickets, phase=fetching] Fetching records from Autotask API +[2026-01-23T12:21:05.200Z] [INFO] [syncId=sync_1234, entity=tickets, records=150] Fetched records from Autotask +[2026-01-23T12:21:05.300Z] [INFO] [syncId=sync_1234, entity=tickets, phase=mapping] Mapping 150 records to database schema +[2026-01-23T12:21:05.500Z] [INFO] [syncId=sync_1234, entity=tickets, mappedCount=148] Successfully mapped records +[2026-01-23T12:21:05.600Z] [INFO] [syncId=sync_1234, entity=tickets, phase=upserting] Upserting records to PostgreSQL +[2026-01-23T12:21:06.800Z] [INFO] [syncId=sync_1234, entity=tickets, upsertedCount=148] Upserted records to PostgreSQL +[2026-01-23T12:21:06.900Z] [INFO] [syncId=sync_1234, entity=tickets, duration=6900ms] Completed tickets sync +``` + +### Failed Sync with Error Details +``` +[2026-01-23T12:25:00.000Z] [INFO] [syncId=sync_5678, entity=contacts, phase=initializing] Starting contacts sync (full) +[2026-01-23T12:25:00.100Z] [INFO] [syncId=sync_5678, entity=contacts, phase=fetching] Fetching records from Autotask API +[2026-01-23T12:25:10.200Z] [ERROR] [syncId=sync_5678, entity=contacts, phase=fetching, errorCategory=NETWORK_ERROR] API fetch failed + Error: ETIMEDOUT: Connection timed out + Category: NETWORK_ERROR + Stack: Error: ETIMEDOUT... +[2026-01-23T12:25:10.300Z] [ERROR] [syncId=sync_5678, entity=contacts, duration=10300ms, errorCategory=NETWORK_ERROR] Failed contacts sync +``` + +## Migration Guide + +### For Developers + +If you're adding new sync operations or modifying existing ones: + +1. **Import the logger:** + ```typescript + import { createSyncLogger, SyncPhase, categorizeError } from '../utils/sync-logger'; + ``` + +2. **Create a logger instance:** + ```typescript + const logger = createSyncLogger({ component: 'MyComponent' }); + ``` + +3. **Use child loggers for operations:** + ```typescript + const operationLogger = logger.child({ syncId, entityType }); + ``` + +4. **Track phases:** + ```typescript + operationLogger.phase(SyncPhase.FETCHING, 'Fetching data'); + ``` + +5. **Log with context:** + ```typescript + operationLogger.info('Operation completed', { recordCount: 100 }); + operationLogger.error('Operation failed', { phase: SyncPhase.MAPPING }, error); + ``` + +6. **Use timing helpers:** + ```typescript + const startTime = logger.start('My operation'); + // ... do work ... + logger.complete('My operation', startTime, { recordCount: 100 }); + // or on error: + logger.fail('My operation', startTime, error); + ``` + +## Analyzing Yesterday's Sync + +To investigate the sync issues from yesterday: + +```bash +# Show all failures from yesterday +npx tsx scripts/analyze-sync-failures.ts --days 1 + +# Show all syncs (including successful) from yesterday +npx tsx scripts/analyze-sync-failures.ts --days 1 --all + +# Check specific entity +npx tsx scripts/analyze-sync-failures.ts --days 1 --entity tickets +``` + +The script will show: +- Which entities failed +- Error categories +- Timing information +- Success rates +- Common error patterns + +## Future Enhancements + +Potential improvements for consideration: + +1. **Log Aggregation**: Send logs to a centralized logging service (e.g., Datadog, CloudWatch) +2. **Alerting**: Automatic alerts on consecutive failures +3. **Metrics Dashboard**: Real-time sync health monitoring +4. **Log Rotation**: Automatic cleanup of old logs +5. **JSON Output**: Option for machine-readable JSON logs +6. **Performance Profiling**: Detailed timing breakdown for optimization + +## Related Files + +- `lib/utils/sync-logger.ts` - Structured logging utility +- `lib/services/sync-service.ts` - Main sync orchestration +- `lib/services/entity-sync.ts` - Entity-specific sync logic +- `scripts/analyze-sync-failures.ts` - Failure analysis tool +- `lib/types/sync.ts` - Sync type definitions diff --git a/lib/services/entity-sync.ts b/lib/services/entity-sync.ts index 0f36a40..ac38e5c 100644 --- a/lib/services/entity-sync.ts +++ b/lib/services/entity-sync.ts @@ -20,6 +20,7 @@ import { buildTimeEntriesFilter, getTableName } from '../utils/sync-helpers'; +import { createSyncLogger, SyncPhase, categorizeError } from '../utils/sync-logger'; /** * Entity Sync Result @@ -37,6 +38,7 @@ export class EntitySyncService { private autotaskClient: AutotaskClient; private cachedValidResourceIds?: Set; private cachedValidContactIds?: Set; + private logger = createSyncLogger({ component: 'EntitySyncService' }); constructor(autotaskClient: AutotaskClient) { this.autotaskClient = autotaskClient; @@ -63,13 +65,13 @@ export class EntitySyncService { return await this.syncSubIssueTypes(isIncremental); } - const syncStartTime = Date.now(); const trackingId = syncId || `${entity}_${Date.now()}`; + const entityLogger = this.logger.child({ syncId: trackingId, entityType: entity }); + const syncStartTime = entityLogger.start(`${entity} sync (${isIncremental ? 'incremental' : 'full'})`); // Start progress tracking syncProgressTracker.startSync(trackingId, entity); - - console.log(`[${entity}] Starting sync (${isIncremental ? 'incremental' : 'full'})`); + entityLogger.phase(SyncPhase.INITIALIZING); try { const autotaskEntityName = getAutotaskEntityName(entity); @@ -81,13 +83,14 @@ export class EntitySyncService { const lastSyncTime = await getLastSyncTime(entity); if (lastSyncTime) { params.filter = buildIncrementalFilter(entity, lastSyncTime); - console.log(`[${entity}] Incremental sync from ${lastSyncTime.toISOString()}`); + entityLogger.info(`Incremental sync from ${lastSyncTime.toISOString()}`); } else { - console.log(`[${entity}] No previous sync found, performing full sync`); + entityLogger.info('No previous sync found, performing full sync'); } } catch (error) { - console.error(`[${entity}] Failed to get last sync time:`, error); - throw new Error(`Failed to determine sync time: ${error instanceof Error ? error.message : String(error)}`); + const err = error instanceof Error ? error : new Error(String(error)); + entityLogger.error('Failed to get last sync time', {}, err); + throw new Error(`Failed to determine sync time: ${err.message}`); } } else { // For full sync, build filters @@ -96,26 +99,26 @@ export class EntitySyncService { // Special handling for entities that require filters if (entity === EntityType.CONTRACTS) { filters.push(...buildContractsFilter()); - console.log(`[${entity}] Full sync with status filter for active contracts`); + entityLogger.info('Full sync with status filter for active contracts'); } else if (entity === EntityType.PROJECTS) { filters.push(...buildProjectsFilter()); - console.log(`[${entity}] Full sync with status filter for non-completed projects`); + entityLogger.info('Full sync with status filter for non-completed projects'); } else if (entity === EntityType.TIME_ENTRIES) { filters.push(...buildTimeEntriesFilter(yearsBack)); - console.log(`[${entity}] Full sync with dateWorked filter for last ${yearsBack} years`); + entityLogger.info(`Full sync with dateWorked filter for last ${yearsBack} years`); } else { // Add active filter if applicable const activeFilter = buildActiveFilter(entity); if (activeFilter) { filters.push(...activeFilter); - console.log(`[${entity}] Full sync with active filter`); + entityLogger.info('Full sync with active filter'); } // Add date range filter for time-based entities (tickets, tasks, etc.) const dateRangeFilter = buildDateRangeFilter(entity, yearsBack); if (dateRangeFilter) { filters.push(...dateRangeFilter); - console.log(`[${entity}] Full sync limited to last ${yearsBack} years`); + entityLogger.info(`Full sync limited to last ${yearsBack} years`); } } @@ -125,71 +128,81 @@ export class EntitySyncService { } // Fetch data from Autotask with pagination - console.log(`[${entity}] Fetching records from Autotask API...`); + entityLogger.phase(SyncPhase.FETCHING, 'Fetching records from Autotask API'); syncProgressTracker.updateProgress(trackingId, { phase: 'fetching' }); let autotaskRecords: any[]; + const fetchStartTime = Date.now(); try { autotaskRecords = await this.autotaskClient.queryEntityPaginated( autotaskEntityName, params, 500 // Page size ); + entityLogger.debug('API fetch completed', { duration: Date.now() - fetchStartTime }); } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] API fetch failed:`, errorMessage); - throw new Error(`Autotask API error: ${errorMessage}`); + const err = error instanceof Error ? error : new Error(String(error)); + const errorCategory = categorizeError(err); + entityLogger.error('API fetch failed', { phase: SyncPhase.FETCHING, errorCategory }, err); + throw new Error(`Autotask API error: ${err.message}`); } - console.log(`[${entity}] Fetched ${autotaskRecords.length} records from Autotask`); + entityLogger.info('Fetched records from Autotask', { recordCount: autotaskRecords.length }); syncProgressTracker.updateProgress(trackingId, { totalRecords: autotaskRecords.length, phase: 'mapping' }); if (autotaskRecords.length === 0) { - console.log(`[${entity}] No records to sync`); + entityLogger.info('No records to sync'); syncProgressTracker.completeSync(trackingId, 0); return { recordsAdded: 0, recordsUpdated: 0, recordsDeleted: 0 }; } // Map Autotask data to PostgreSQL schema - console.log(`[${entity}] Mapping ${autotaskRecords.length} records to database schema...`); + entityLogger.phase(SyncPhase.MAPPING, `Mapping ${autotaskRecords.length} records to database schema`); // DEBUG: Log first record to see actual field names from Autotask if (autotaskRecords.length > 0 && (entity === EntityType.TICKETS || entity === EntityType.TIME_ENTRIES)) { - console.log(`[${entity}] DEBUG - Sample raw Autotask record keys:`, Object.keys(autotaskRecords[0])); + entityLogger.debug('Sample raw Autotask record keys', { keys: Object.keys(autotaskRecords[0]) }); if (entity === EntityType.TIME_ENTRIES) { - console.log(`[${entity}] DEBUG - Sample time entry:`, JSON.stringify(autotaskRecords[0], null, 2)); + entityLogger.debug('Sample time entry', { sample: JSON.stringify(autotaskRecords[0], null, 2) }); } } let mappedRecords: Record[]; + const mapStartTime = Date.now(); try { mappedRecords = mapAutotaskBatch(entity, autotaskRecords); + entityLogger.debug('Mapping completed', { duration: Date.now() - mapStartTime }); } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Mapping failed:`, errorMessage); - throw new Error(`Data mapping error: ${errorMessage}`); + const err = error instanceof Error ? error : new Error(String(error)); + const errorCategory = categorizeError(err); + entityLogger.error('Mapping failed', { phase: SyncPhase.MAPPING, errorCategory }, err); + throw new Error(`Data mapping error: ${err.message}`); } if (mappedRecords.length === 0) { - console.warn(`[${entity}] Warning: All records failed mapping validation`); + entityLogger.warn('All records failed mapping validation', { originalCount: autotaskRecords.length }); return { recordsAdded: 0, recordsUpdated: 0, recordsDeleted: 0 }; } // Check for records with missing company_id (for entities that require it) // Note: TIME_ENTRIES removed from this check because company_id is nullable for time entries + entityLogger.phase(SyncPhase.VALIDATING, 'Validating records'); if (entity === EntityType.TICKETS || entity === EntityType.PROJECTS || entity === EntityType.CONFIGURATION_ITEMS || entity === EntityType.CONTACTS || entity === EntityType.CONTRACTS || entity === EntityType.BILLING_ITEMS) { const recordsWithoutCompany = mappedRecords.filter(r => !r.company_id); if (recordsWithoutCompany.length > 0) { - console.warn(`[${entity}] Found ${recordsWithoutCompany.length} records without company_id (out of ${mappedRecords.length} total)`); - console.warn(`[${entity}] Sample IDs without company_id:`, recordsWithoutCompany.slice(0, 5).map(r => r.id)); + entityLogger.warn('Found records without company_id', { + missingCount: recordsWithoutCompany.length, + totalCount: mappedRecords.length, + sampleIds: recordsWithoutCompany.slice(0, 5).map(r => r.id), + }); // Filter out records without company_id to prevent constraint violation mappedRecords = mappedRecords.filter(r => r.company_id); - console.log(`[${entity}] Filtered to ${mappedRecords.length} records with valid company_id`); + entityLogger.info('Filtered to records with valid company_id', { validCount: mappedRecords.length }); } } @@ -204,7 +217,10 @@ export class EntitySyncService { mappedRecords = mappedRecords.map(ticket => { // Set invalid resource IDs to null instead of filtering out the entire ticket if (ticket.assigned_resource_id && !validResourceIds.has(ticket.assigned_resource_id)) { - console.warn(`[${entity}] Ticket ${ticket.id}: Invalid assigned_resource_id ${ticket.assigned_resource_id}, setting to null`); + entityLogger.debug(`Invalid assigned_resource_id, setting to null`, { + ticketId: ticket.id, + invalidResourceId: ticket.assigned_resource_id, + }); ticket.assigned_resource_id = null; } if (ticket.first_response_assigned_resource_id && !validResourceIds.has(ticket.first_response_assigned_resource_id)) { @@ -218,7 +234,7 @@ export class EntitySyncService { const nullifiedCount = initialCount - mappedRecords.filter(t => t.assigned_resource_id).length; if (nullifiedCount > 0) { - console.warn(`[${entity}] Nullified ${nullifiedCount} invalid resource references`); + entityLogger.warn('Nullified invalid resource references', { nullifiedCount }); } } @@ -233,7 +249,10 @@ export class EntitySyncService { mappedRecords = mappedRecords.map(item => { // Set invalid contact IDs to null instead of filtering out the entire item if (item.contact_id && !validContactIds.has(item.contact_id)) { - console.warn(`[${entity}] Configuration Item ${item.id}: Invalid contact_id ${item.contact_id}, setting to null`); + entityLogger.debug(`Invalid contact_id, setting to null`, { + itemId: item.id, + invalidContactId: item.contact_id, + }); item.contact_id = null; } return item; @@ -241,26 +260,29 @@ export class EntitySyncService { const nullifiedCount = initialCount - mappedRecords.filter(i => i.contact_id).length; if (nullifiedCount > 0) { - console.warn(`[${entity}] Nullified ${nullifiedCount} invalid contact references`); + entityLogger.warn('Nullified invalid contact references', { nullifiedCount }); } } - console.log(`[${entity}] Successfully mapped ${mappedRecords.length} records`); + entityLogger.info('Successfully mapped records', { mappedCount: mappedRecords.length }); // Bulk upsert to PostgreSQL - console.log(`[${entity}] Upserting records to PostgreSQL...`); + entityLogger.phase(SyncPhase.UPSERTING, 'Upserting records to PostgreSQL'); syncProgressTracker.updateProgress(trackingId, { phase: 'upserting' }); let upsertedCount: number; + const upsertStartTime = Date.now(); try { upsertedCount = await bulkUpsertRecords(entity, mappedRecords, 100); + entityLogger.debug('Upsert completed', { duration: Date.now() - upsertStartTime }); } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Database upsert failed:`, errorMessage); - throw new Error(`Database error: ${errorMessage}`); + const err = error instanceof Error ? error : new Error(String(error)); + const errorCategory = categorizeError(err); + entityLogger.error('Database upsert failed', { phase: SyncPhase.UPSERTING, errorCategory }, err); + throw new Error(`Database error: ${err.message}`); } - console.log(`[${entity}] Upserted ${upsertedCount} records to PostgreSQL`); + entityLogger.info('Upserted records to PostgreSQL', { upsertedCount }); // For full sync, soft delete records not in the fetched set // IMPORTANT: Only delete for entities without date filters to avoid deleting records outside sync window @@ -272,32 +294,34 @@ export class EntitySyncService { entity === EntityType.CONTRACTS; if (!isIncremental && !hasDateFilter) { - console.log(`[${entity}] Checking for records to soft delete...`); + entityLogger.phase(SyncPhase.DELETING, 'Checking for records to soft delete'); syncProgressTracker.updateProgress(trackingId, { phase: 'deleting' }); try { const activeIds = mappedRecords.map(r => r.id); deletedCount = await softDeleteMissingRecords(entity, activeIds); - console.log(`[${entity}] Soft deleted ${deletedCount} missing records`); + entityLogger.info('Soft deleted missing records', { deletedCount }); } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Soft delete failed:`, errorMessage); + const err = error instanceof Error ? error : new Error(String(error)); + entityLogger.warn('Soft delete failed, continuing sync', {}, err); // Don't throw - soft delete failure shouldn't fail the entire sync - console.warn(`[${entity}] Continuing despite soft delete failure`); } } else if (!isIncremental && hasDateFilter) { - console.log(`[${entity}] Skipping soft-delete for date-filtered sync (would delete records outside sync window)`); + entityLogger.info('Skipping soft-delete for date-filtered sync (would delete records outside sync window)'); } // Calculate added vs updated (simplified - actual count would require tracking) const recordsAdded = Math.floor(upsertedCount * 0.1); // Estimate 10% new const recordsUpdated = upsertedCount - recordsAdded; - const duration = Date.now() - syncStartTime; - console.log(`[${entity}] Sync completed in ${duration}ms`); - // Mark sync as completed + entityLogger.phase(SyncPhase.COMPLETING); syncProgressTracker.completeSync(trackingId, mappedRecords.length); + entityLogger.complete(`${entity} sync`, syncStartTime, { + recordsAdded, + recordsUpdated, + recordsDeleted: deletedCount, + }); return { recordsAdded, @@ -305,12 +329,11 @@ export class EntitySyncService { recordsDeleted: deletedCount, }; } catch (error) { - const duration = Date.now() - syncStartTime; - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Sync failed after ${duration}ms:`, errorMessage); + const err = error instanceof Error ? error : new Error(String(error)); // Mark sync as failed - syncProgressTracker.failSync(trackingId, errorMessage); + syncProgressTracker.failSync(trackingId, err.message); + entityLogger.fail(`${entity} sync`, syncStartTime, err); throw error; } @@ -341,14 +364,14 @@ export class EntitySyncService { yearsBack: number = 2, onChunkProgress?: (chunk: { index: number; total: number; description: string; recordsProcessed: number }) => void ): Promise { - const syncStartTime = Date.now(); const entity = EntityType.TICKETS; - console.log(`[${entity}] Starting chunked sync for last ${yearsBack} years`); + const chunkLogger = this.logger.child({ entityType: entity, syncType: 'chunked' }); + const syncStartTime = chunkLogger.start(`Chunked sync for last ${yearsBack} years`); try { // Calculate date chunks (monthly) const chunks = this.calculateMonthlyChunks(yearsBack); - console.log(`[${entity}] Split into ${chunks.length} monthly chunks`); + chunkLogger.info('Split into monthly chunks', { chunkCount: chunks.length, yearsBack }); let totalRecordsAdded = 0; let totalRecordsUpdated = 0; @@ -360,7 +383,7 @@ export class EntitySyncService { const chunk = chunks[i]; const chunkDescription = `${chunk.startDate.toLocaleDateString('en-US', { month: 'short', year: 'numeric' })}`; - console.log(`[${entity}] Processing chunk ${i + 1}/${chunks.length}: ${chunkDescription}`); + chunkLogger.info(`Processing chunk ${i + 1}/${chunks.length}`, { chunkDescription }); // Notify progress if (onChunkProgress) { @@ -380,7 +403,11 @@ export class EntitySyncService { { field: 'createDate', op: 'lt' as const, value: chunk.endDate.toISOString() }, ]; - console.log(`[${entity}] Fetching records from ${chunk.startDate.toISOString()} to ${chunk.endDate.toISOString()}`); + chunkLogger.debug('Fetching records for chunk', { + chunkIndex: i + 1, + startDate: chunk.startDate.toISOString(), + endDate: chunk.endDate.toISOString(), + }); const autotaskRecords = await this.autotaskClient.queryEntityPaginated( autotaskEntityName, @@ -388,23 +415,26 @@ export class EntitySyncService { 500 ); - console.log(`[${entity}] Chunk ${i + 1}: Fetched ${autotaskRecords.length} records`); + chunkLogger.info(`Chunk ${i + 1}: Fetched records`, { recordCount: autotaskRecords.length }); if (autotaskRecords.length > 0) { // Map and upsert records let mappedRecords = mapAutotaskBatch(entity, autotaskRecords); // Filter out records without company_id + const beforeFilter = mappedRecords.length; mappedRecords = mappedRecords.filter(r => r.company_id); - if (mappedRecords.length < autotaskRecords.length) { - console.warn(`[${entity}] Chunk ${i + 1}: Filtered out ${autotaskRecords.length - mappedRecords.length} records without company_id`); + if (mappedRecords.length < beforeFilter) { + chunkLogger.warn(`Chunk ${i + 1}: Filtered out records without company_id`, { + filteredCount: beforeFilter - mappedRecords.length, + }); } // Validate resource foreign keys (fetch once per sync, not per chunk) if (i === 0) { // Cache valid resource IDs for all chunks this.cachedValidResourceIds = await this.getValidResourceIds(); - console.log(`[${entity}] Cached ${this.cachedValidResourceIds.size} valid resource IDs`); + chunkLogger.info('Cached valid resource IDs', { cacheSize: this.cachedValidResourceIds.size }); } // Nullify invalid resource references @@ -431,24 +461,37 @@ export class EntitySyncService { totalRecordsAdded += recordsAdded; totalRecordsUpdated += recordsUpdated; - console.log(`[${entity}] Chunk ${i + 1}: Upserted ${upsertedCount} records (+${recordsAdded} ~${recordsUpdated})`); + chunkLogger.info(`Chunk ${i + 1}: Upserted records`, { + upsertedCount, + recordsAdded, + recordsUpdated, + }); } } } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Chunk ${i + 1} (${chunkDescription}) failed:`, errorMessage); - failedChunks.push(`${chunkDescription}: ${errorMessage}`); + const err = error instanceof Error ? error : new Error(String(error)); + const errorCategory = categorizeError(err); + chunkLogger.error(`Chunk ${i + 1} (${chunkDescription}) failed`, { + chunkIndex: i + 1, + chunkDescription, + errorCategory, + }, err); + failedChunks.push(`${chunkDescription}: ${err.message}`); // Continue with next chunk instead of failing entire sync } } - const duration = Date.now() - syncStartTime; - console.log(`[${entity}] Chunked sync completed in ${duration}ms`); - console.log(`[${entity}] Total: +${totalRecordsAdded} ~${totalRecordsUpdated} -${totalRecordsDeleted}`); + chunkLogger.complete('Chunked sync', syncStartTime, { + totalRecordsAdded, + totalRecordsUpdated, + totalRecordsDeleted, + totalChunks: chunks.length, + failedChunks: failedChunks.length, + }); if (failedChunks.length > 0) { - console.warn(`[${entity}] ${failedChunks.length} chunks failed:`, failedChunks); + chunkLogger.warn('Some chunks failed', { failedChunks }); } return { @@ -457,9 +500,8 @@ export class EntitySyncService { recordsDeleted: totalRecordsDeleted, }; } catch (error) { - const duration = Date.now() - syncStartTime; - const errorMessage = error instanceof Error ? error.message : String(error); - console.error(`[${entity}] Chunked sync failed after ${duration}ms:`, errorMessage); + const err = error instanceof Error ? error : new Error(String(error)); + chunkLogger.fail('Chunked sync', syncStartTime, err); throw error; } } @@ -475,7 +517,8 @@ export class EntitySyncService { const result = await postgresClient.query<{ id: number }>(query); return new Set(result.rows.map(row => row.id)); } catch (error) { - console.error('Failed to fetch valid resource IDs:', error); + const err = error instanceof Error ? error : new Error(String(error)); + this.logger.error('Failed to fetch valid resource IDs', {}, err); // Return empty set on error - will cause all resource IDs to be nullified return new Set(); } @@ -491,7 +534,8 @@ export class EntitySyncService { const result = await postgresClient.query<{ id: number }>(query); return new Set(result.rows.map(row => row.id)); } catch (error) { - console.error('Failed to fetch valid contact IDs:', error); + const err = error instanceof Error ? error : new Error(String(error)); + this.logger.error('Failed to fetch valid contact IDs', {}, err); // Return empty set on error - will cause all contact IDs to be nullified return new Set(); } @@ -594,8 +638,8 @@ export class EntitySyncService { * Sync Issue Types (Picklist from Ticket field) */ async syncIssueTypes(isIncremental: boolean = false): Promise { - const syncStartTime = Date.now(); - console.log(`[issue_types] Starting picklist sync`); + const picklistLogger = this.logger.child({ entityType: EntityType.ISSUE_TYPES, syncType: 'picklist' }); + const syncStartTime = picklistLogger.start('Picklist sync'); try { // Get issue type picklist values from Tickets entity @@ -610,7 +654,7 @@ export class EntitySyncService { synced_at: new Date(), })); - console.log(`[issue_types] Found ${records.length} picklist values`); + picklistLogger.info('Found picklist values', { recordCount: records.length }); // Upsert to database const tableName = getTableName(EntityType.ISSUE_TYPES); @@ -622,13 +666,15 @@ export class EntitySyncService { recordsDeleted: 0, }; - const duration = Date.now() - syncStartTime; - console.log(`[issue_types] Sync completed in ${duration}ms: +${stats.recordsAdded} ~${stats.recordsUpdated}`); + picklistLogger.complete('Picklist sync', syncStartTime, { + recordsAdded: stats.recordsAdded, + recordsUpdated: stats.recordsUpdated, + }); return stats; } catch (error) { - const duration = Date.now() - syncStartTime; - console.error(`[issue_types] Sync failed after ${duration}ms:`, error); + const err = error instanceof Error ? error : new Error(String(error)); + picklistLogger.fail('Picklist sync', syncStartTime, err); throw error; } } @@ -637,8 +683,8 @@ export class EntitySyncService { * Sync Sub-Issue Types (Picklist from Ticket field) */ async syncSubIssueTypes(isIncremental: boolean = false): Promise { - const syncStartTime = Date.now(); - console.log(`[sub_issue_types] Starting picklist sync`); + const picklistLogger = this.logger.child({ entityType: EntityType.SUB_ISSUE_TYPES, syncType: 'picklist' }); + const syncStartTime = picklistLogger.start('Picklist sync'); try { // Get sub-issue type picklist values from Tickets entity @@ -670,7 +716,7 @@ export class EntitySyncService { synced_at: new Date(), })); - console.log(`[sub_issue_types] Found ${records.length} picklist values`); + picklistLogger.info('Found picklist values', { recordCount: records.length }); // Upsert to database const tableName = getTableName(EntityType.SUB_ISSUE_TYPES); @@ -682,13 +728,15 @@ export class EntitySyncService { recordsDeleted: 0, }; - const duration = Date.now() - syncStartTime; - console.log(`[sub_issue_types] Sync completed in ${duration}ms: +${stats.recordsAdded} ~${stats.recordsUpdated}`); + picklistLogger.complete('Picklist sync', syncStartTime, { + recordsAdded: stats.recordsAdded, + recordsUpdated: stats.recordsUpdated, + }); return stats; } catch (error) { - const duration = Date.now() - syncStartTime; - console.error(`[sub_issue_types] Sync failed after ${duration}ms:`, error); + const err = error instanceof Error ? error : new Error(String(error)); + picklistLogger.fail('Picklist sync', syncStartTime, err); throw error; } } diff --git a/lib/services/sync-service.ts b/lib/services/sync-service.ts index fa4ffc9..ddca271 100644 --- a/lib/services/sync-service.ts +++ b/lib/services/sync-service.ts @@ -24,6 +24,7 @@ import { getEntityDisplayName } from '../utils/sync-helpers'; import { getLastSyncTime } from '../utils/db-helpers'; +import { createSyncLogger, SyncPhase, categorizeError } from '../utils/sync-logger'; /** * Main Sync Service Class @@ -33,6 +34,7 @@ export class SyncService { private isSyncing = false; private autotaskClient: AutotaskClient; private entitySyncService: EntitySyncService; + private logger = createSyncLogger({ component: 'SyncService' }); constructor(autotaskClient: AutotaskClient) { this.autotaskClient = autotaskClient; @@ -116,15 +118,18 @@ export class SyncService { const errors: string[] = []; try { - console.log(`Starting ${config.syncType} sync: ${syncId}`); - console.log(`Entities to sync: ${config.entities.map(e => getEntityDisplayName(e)).join(', ')}`); + const syncLogger = this.logger.child({ syncId, syncType: config.syncType }); + syncLogger.info(`Starting ${config.syncType} sync`, { + entities: config.entities.map(e => getEntityDisplayName(e)).join(', '), + triggeredBy: config.triggeredBy, + yearsBack: config.yearsBack, + }); // Sync each entity in order for (const entity of config.entities) { try { - const entityStartTime = Date.now(); - - console.log(`Syncing ${getEntityDisplayName(entity)}...`); + const entityLogger = syncLogger.child({ entityType: entity }); + const entityStartTime = entityLogger.start(`Syncing ${getEntityDisplayName(entity)}`); // Create sync history record const historyId = await this.createSyncHistory( @@ -168,41 +173,24 @@ export class SyncService { duration, }); - console.log( - `✓ ${getEntityDisplayName(entity)} synced: +${recordsAdded} ~${recordsUpdated} -${recordsDeleted} (${duration}ms)` - ); + entityLogger.complete(`Syncing ${getEntityDisplayName(entity)}`, entityStartTime, { + recordsAdded, + recordsUpdated, + recordsDeleted, + }); } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - const errorStack = error instanceof Error ? error.stack : undefined; + const err = error instanceof Error ? error : new Error(String(error)); + const entityLogger = syncLogger.child({ entityType: entity }); const entityName = getEntityDisplayName(entity); + const errorCategory = categorizeError(err); // Log detailed error information - console.error(`✗ Failed to sync ${entityName}:`); - console.error(` Error: ${errorMessage}`); - if (errorStack) { - console.error(` Stack: ${errorStack}`); - } - console.error(` Entity: ${entity}`); - console.error(` Sync Type: ${config.syncType}`); - console.error(` Sync ID: ${syncId}`); + entityLogger.error(`Failed to sync ${entityName}`, { + errorCategory, + syncType: config.syncType, + }, err); - // Categorize error type - let errorCategory = 'UNKNOWN'; - if (errorMessage.includes('ECONNREFUSED') || errorMessage.includes('ETIMEDOUT')) { - errorCategory = 'NETWORK_ERROR'; - } else if (errorMessage.includes('401') || errorMessage.includes('403')) { - errorCategory = 'AUTH_ERROR'; - } else if (errorMessage.includes('429')) { - errorCategory = 'RATE_LIMIT_ERROR'; - } else if (errorMessage.includes('constraint') || errorMessage.includes('duplicate')) { - errorCategory = 'DATABASE_CONSTRAINT_ERROR'; - } else if (errorMessage.includes('query') || errorMessage.includes('SQL')) { - errorCategory = 'DATABASE_ERROR'; - } else if (errorMessage.includes('API')) { - errorCategory = 'API_ERROR'; - } - - const fullErrorMessage = `[${errorCategory}] ${errorMessage}`; + const fullErrorMessage = `[${errorCategory}] ${err.message}`; errors.push(`${entityName}: ${fullErrorMessage}`); // Try to update sync history with error @@ -221,7 +209,8 @@ export class SyncService { fullErrorMessage ); } catch (historyError) { - console.error('Failed to update sync history with error:', historyError); + const histErr = historyError instanceof Error ? historyError : new Error(String(historyError)); + entityLogger.error('Failed to update sync history with error', {}, histErr); } entityResults.push({ @@ -253,25 +242,25 @@ export class SyncService { errors, }; - console.log(`Sync ${syncId} completed in ${totalDuration}ms`); - console.log(`Total: +${result.totalRecordsAdded} ~${result.totalRecordsUpdated} -${result.totalRecordsDeleted}`); + syncLogger.info(`Sync completed`, { + duration: totalDuration, + status: result.status, + recordsAdded: result.totalRecordsAdded, + recordsUpdated: result.totalRecordsUpdated, + recordsDeleted: result.totalRecordsDeleted, + errorCount: errors.length, + }); return result; } catch (error) { - const errorMessage = error instanceof Error ? error.message : String(error); - const errorStack = error instanceof Error ? error.stack : undefined; + const err = error instanceof Error ? error : new Error(String(error)); + const syncLogger = this.logger.child({ syncId, syncType: config.syncType }); - console.error('=== SYNC OPERATION FAILED ==='); - console.error(`Sync ID: ${syncId}`); - console.error(`Sync Type: ${config.syncType}`); - console.error(`Error: ${errorMessage}`); - if (errorStack) { - console.error(`Stack Trace:\n${errorStack}`); - } - console.error(`Entities Attempted: ${config.entities.join(', ')}`); - console.error(`Successful Entities: ${entityResults.filter(r => r.success).length}`); - console.error(`Failed Entities: ${entityResults.filter(r => !r.success).length}`); - console.error('============================'); + syncLogger.error('Sync operation failed', { + entitiesAttempted: config.entities.join(', '), + successfulEntities: entityResults.filter(r => r.success).length, + failedEntities: entityResults.filter(r => !r.success).length, + }, err); throw error; } finally { @@ -440,9 +429,10 @@ export class SyncService { // TODO: Implement graceful cancellation this.isSyncing = false; + const cancelledSyncId = this.currentSyncId || 'unknown'; this.currentSyncId = null; - console.log('Sync operation cancelled'); + this.logger.warn('Sync operation cancelled', { syncId: cancelledSyncId }); } } diff --git a/lib/utils/sync-logger.ts b/lib/utils/sync-logger.ts new file mode 100644 index 0000000..1731450 --- /dev/null +++ b/lib/utils/sync-logger.ts @@ -0,0 +1,257 @@ +/** + * Structured Logging Utility for Sync Operations + * Provides consistent, categorized logging with context + */ + +export enum LogLevel { + DEBUG = 'DEBUG', + INFO = 'INFO', + WARN = 'WARN', + ERROR = 'ERROR', +} + +export enum ErrorCategory { + NETWORK_ERROR = 'NETWORK_ERROR', + AUTH_ERROR = 'AUTH_ERROR', + RATE_LIMIT_ERROR = 'RATE_LIMIT_ERROR', + DATABASE_CONSTRAINT_ERROR = 'DATABASE_CONSTRAINT_ERROR', + DATABASE_ERROR = 'DATABASE_ERROR', + API_ERROR = 'API_ERROR', + MAPPING_ERROR = 'MAPPING_ERROR', + VALIDATION_ERROR = 'VALIDATION_ERROR', + UNKNOWN = 'UNKNOWN', +} + +export enum SyncPhase { + INITIALIZING = 'initializing', + FETCHING = 'fetching', + MAPPING = 'mapping', + VALIDATING = 'validating', + UPSERTING = 'upserting', + DELETING = 'deleting', + COMPLETING = 'completing', +} + +export interface LogContext { + syncId?: string; + entityType?: string; + phase?: SyncPhase; + recordCount?: number; + duration?: number; + errorCategory?: ErrorCategory; + [key: string]: any; +} + +export interface LogEntry { + timestamp: string; + level: LogLevel; + message: string; + context?: LogContext; + error?: { + message: string; + stack?: string; + category?: ErrorCategory; + }; +} + +/** + * Categorize error based on error message + */ +export function categorizeError(error: Error | string): ErrorCategory { + const errorMessage = typeof error === 'string' ? error : error.message; + + if (errorMessage.includes('ECONNREFUSED') || errorMessage.includes('ETIMEDOUT') || errorMessage.includes('ENOTFOUND')) { + return ErrorCategory.NETWORK_ERROR; + } else if (errorMessage.includes('401') || errorMessage.includes('403') || errorMessage.includes('Unauthorized')) { + return ErrorCategory.AUTH_ERROR; + } else if (errorMessage.includes('429') || errorMessage.includes('rate limit')) { + return ErrorCategory.RATE_LIMIT_ERROR; + } else if (errorMessage.includes('constraint') || errorMessage.includes('duplicate') || errorMessage.includes('foreign key')) { + return ErrorCategory.DATABASE_CONSTRAINT_ERROR; + } else if (errorMessage.includes('query') || errorMessage.includes('SQL') || errorMessage.includes('database')) { + return ErrorCategory.DATABASE_ERROR; + } else if (errorMessage.includes('API') || errorMessage.includes('endpoint')) { + return ErrorCategory.API_ERROR; + } else if (errorMessage.includes('mapping') || errorMessage.includes('transform')) { + return ErrorCategory.MAPPING_ERROR; + } else if (errorMessage.includes('validation') || errorMessage.includes('invalid')) { + return ErrorCategory.VALIDATION_ERROR; + } + + return ErrorCategory.UNKNOWN; +} + +/** + * Structured Logger Class + */ +export class SyncLogger { + private context: LogContext; + + constructor(context: LogContext = {}) { + this.context = context; + } + + /** + * Create a child logger with additional context + */ + child(additionalContext: LogContext): SyncLogger { + return new SyncLogger({ ...this.context, ...additionalContext }); + } + + /** + * Update logger context + */ + updateContext(updates: LogContext): void { + this.context = { ...this.context, ...updates }; + } + + /** + * Format log entry + */ + private formatLog(level: LogLevel, message: string, context?: LogContext, error?: Error): LogEntry { + const entry: LogEntry = { + timestamp: new Date().toISOString(), + level, + message, + context: { ...this.context, ...context }, + }; + + if (error) { + entry.error = { + message: error.message, + stack: error.stack, + category: categorizeError(error), + }; + } + + return entry; + } + + /** + * Output log entry + */ + private output(entry: LogEntry): void { + const prefix = `[${entry.timestamp}] [${entry.level}]`; + const contextStr = entry.context ? ` [${this.formatContext(entry.context)}]` : ''; + const fullMessage = `${prefix}${contextStr} ${entry.message}`; + + switch (entry.level) { + case LogLevel.DEBUG: + console.log(fullMessage); + break; + case LogLevel.INFO: + console.log(fullMessage); + break; + case LogLevel.WARN: + console.warn(fullMessage); + if (entry.error) { + console.warn(` Error: ${entry.error.message}`); + console.warn(` Category: ${entry.error.category}`); + } + break; + case LogLevel.ERROR: + console.error(fullMessage); + if (entry.error) { + console.error(` Error: ${entry.error.message}`); + console.error(` Category: ${entry.error.category}`); + if (entry.error.stack) { + console.error(` Stack: ${entry.error.stack}`); + } + } + break; + } + } + + /** + * Format context for display + */ + private formatContext(context: LogContext): string { + const parts: string[] = []; + + if (context.syncId) parts.push(`syncId=${context.syncId}`); + if (context.entityType) parts.push(`entity=${context.entityType}`); + if (context.phase) parts.push(`phase=${context.phase}`); + if (context.recordCount !== undefined) parts.push(`records=${context.recordCount}`); + if (context.duration !== undefined) parts.push(`duration=${context.duration}ms`); + if (context.errorCategory) parts.push(`errorCategory=${context.errorCategory}`); + + return parts.join(', '); + } + + /** + * Debug level logging + */ + debug(message: string, context?: LogContext): void { + const entry = this.formatLog(LogLevel.DEBUG, message, context); + this.output(entry); + } + + /** + * Info level logging + */ + info(message: string, context?: LogContext): void { + const entry = this.formatLog(LogLevel.INFO, message, context); + this.output(entry); + } + + /** + * Warning level logging + */ + warn(message: string, context?: LogContext, error?: Error): void { + const entry = this.formatLog(LogLevel.WARN, message, context, error); + this.output(entry); + } + + /** + * Error level logging + */ + error(message: string, context?: LogContext, error?: Error): void { + const entry = this.formatLog(LogLevel.ERROR, message, context, error); + this.output(entry); + } + + /** + * Log phase transition + */ + phase(phase: SyncPhase, message?: string): void { + this.updateContext({ phase }); + this.info(message || `Entering phase: ${phase}`, { phase }); + } + + /** + * Log operation start + */ + start(operation: string, context?: LogContext): number { + this.info(`Starting ${operation}`, context); + return Date.now(); + } + + /** + * Log operation completion + */ + complete(operation: string, startTime: number, context?: LogContext): void { + const duration = Date.now() - startTime; + this.info(`Completed ${operation}`, { ...context, duration }); + } + + /** + * Log operation failure + */ + fail(operation: string, startTime: number, error: Error, context?: LogContext): void { + const duration = Date.now() - startTime; + const errorCategory = categorizeError(error); + this.error(`Failed ${operation}`, { ...context, duration, errorCategory }, error); + } +} + +/** + * Create a new sync logger instance + */ +export function createSyncLogger(context?: LogContext): SyncLogger { + return new SyncLogger(context); +} + +/** + * Default logger instance + */ +export const defaultLogger = new SyncLogger(); diff --git a/scripts/analyze-sync-failures.ts b/scripts/analyze-sync-failures.ts new file mode 100644 index 0000000..0c69627 --- /dev/null +++ b/scripts/analyze-sync-failures.ts @@ -0,0 +1,360 @@ +/** + * Sync Failure Analysis Script + * Query and analyze sync_history for failures and patterns + * Run with: npx tsx scripts/analyze-sync-failures.ts [options] + */ + +import { config } from 'dotenv'; +import { resolve } from 'path'; +import postgresClient from '../lib/services/postgres-client'; + +// Load environment variables +config({ path: resolve(__dirname, '../.env.local') }); + +interface SyncHistoryRecord { + id: number; + entity_type: string; + sync_type: string; + status: string; + started_at: Date; + completed_at: Date | null; + records_added: number; + records_updated: number; + records_deleted: number; + error_message: string | null; + triggered_by: string; +} + +interface FailureSummary { + entity_type: string; + failure_count: number; + last_failure: Date; + common_errors: string[]; +} + +/** + * Parse command line arguments + */ +function parseArgs(): { + days: number; + entity?: string; + status?: string; + showAll: boolean; +} { + const args = process.argv.slice(2); + const options = { + days: 7, + entity: undefined as string | undefined, + status: undefined as string | undefined, + showAll: false, + }; + + for (let i = 0; i < args.length; i++) { + const arg = args[i]; + if (arg === '--days' || arg === '-d') { + options.days = parseInt(args[++i]); + } else if (arg === '--entity' || arg === '-e') { + options.entity = args[++i]; + } else if (arg === '--status' || arg === '-s') { + options.status = args[++i]; + } else if (arg === '--all' || arg === '-a') { + options.showAll = true; + } else if (arg === '--help' || arg === '-h') { + console.log(` +Sync Failure Analysis Script + +Usage: npx tsx scripts/analyze-sync-failures.ts [options] + +Options: + -d, --days Number of days to look back (default: 7) + -e, --entity Filter by entity type + -s, --status Filter by status (failed, completed, started) + -a, --all Show all records, not just failures + -h, --help Show this help message + +Examples: + # Show failures from last 7 days + npx tsx scripts/analyze-sync-failures.ts + + # Show all syncs from yesterday + npx tsx scripts/analyze-sync-failures.ts --days 1 --all + + # Show ticket sync failures from last 30 days + npx tsx scripts/analyze-sync-failures.ts --days 30 --entity tickets + + # Show all completed syncs + npx tsx scripts/analyze-sync-failures.ts --status completed --all + `); + process.exit(0); + } + } + + return options; +} + +/** + * Query sync history + */ +async function querySyncHistory( + days: number, + entity?: string, + status?: string +): Promise { + const params: any[] = []; + let query = ` + SELECT + id, + entity_type, + sync_type, + status, + started_at, + completed_at, + records_added, + records_updated, + records_deleted, + error_message, + triggered_by + FROM sync_history + WHERE started_at >= NOW() - INTERVAL '${days} days' + `; + + if (entity) { + params.push(entity); + query += ` AND entity_type = $${params.length}`; + } + + if (status) { + params.push(status); + query += ` AND status = $${params.length}`; + } + + query += ' ORDER BY started_at DESC'; + + const result = await postgresClient.query(query, params); + return result.rows; +} + +/** + * Get failure summary by entity + */ +async function getFailureSummary(days: number): Promise { + const query = ` + SELECT + entity_type, + COUNT(*) as failure_count, + MAX(started_at) as last_failure, + ARRAY_AGG(DISTINCT SUBSTRING(error_message, 1, 100)) as common_errors + FROM sync_history + WHERE status = 'failed' + AND started_at >= NOW() - INTERVAL '${days} days' + GROUP BY entity_type + ORDER BY failure_count DESC, last_failure DESC + `; + + const result = await postgresClient.query(query); + return result.rows.map(row => ({ + entity_type: row.entity_type, + failure_count: parseInt(row.failure_count), + last_failure: row.last_failure, + common_errors: row.common_errors.filter((e: string | null) => e !== null), + })); +} + +/** + * Categorize error message + */ +function categorizeError(errorMessage: string | null): string { + if (!errorMessage) return 'UNKNOWN'; + + if (errorMessage.includes('NETWORK_ERROR')) return 'NETWORK'; + if (errorMessage.includes('AUTH_ERROR')) return 'AUTH'; + if (errorMessage.includes('RATE_LIMIT_ERROR')) return 'RATE_LIMIT'; + if (errorMessage.includes('DATABASE_CONSTRAINT_ERROR')) return 'DB_CONSTRAINT'; + if (errorMessage.includes('DATABASE_ERROR')) return 'DATABASE'; + if (errorMessage.includes('API_ERROR')) return 'API'; + if (errorMessage.includes('MAPPING_ERROR')) return 'MAPPING'; + if (errorMessage.includes('VALIDATION_ERROR')) return 'VALIDATION'; + + return 'OTHER'; +} + +/** + * Format duration + */ +function formatDuration(startedAt: Date, completedAt: Date | null): string { + if (!completedAt) return 'N/A'; + const duration = new Date(completedAt).getTime() - new Date(startedAt).getTime(); + const seconds = Math.floor(duration / 1000); + const minutes = Math.floor(seconds / 60); + + if (minutes > 0) { + return `${minutes}m ${seconds % 60}s`; + } + return `${seconds}s`; +} + +/** + * Main analysis function + */ +async function analyzeSyncFailures() { + console.log('🔍 Sync Failure Analysis\n'); + console.log('═══════════════════════════════════════════════════════════\n'); + + const options = parseArgs(); + + try { + // Test database connection + const isConnected = await postgresClient.testConnection(); + if (!isConnected) { + console.error('❌ Database connection failed'); + process.exit(1); + } + + // Get sync history + const records = await querySyncHistory( + options.days, + options.entity, + options.status || (options.showAll ? undefined : 'failed') + ); + + console.log(`📊 Analysis Period: Last ${options.days} day(s)`); + if (options.entity) { + console.log(`🎯 Entity Filter: ${options.entity}`); + } + if (options.status) { + console.log(`📌 Status Filter: ${options.status}`); + } + console.log(`📝 Total Records: ${records.length}\n`); + + if (records.length === 0) { + console.log('✅ No sync records found for the specified criteria.\n'); + process.exit(0); + } + + // Display failure summary + if (!options.entity && !options.showAll) { + console.log('═══════════════════════════════════════════════════════════'); + console.log('📈 FAILURE SUMMARY BY ENTITY'); + console.log('═══════════════════════════════════════════════════════════\n'); + + const summary = await getFailureSummary(options.days); + + if (summary.length === 0) { + console.log('✅ No failures found in the specified period!\n'); + } else { + summary.forEach(item => { + console.log(`Entity: ${item.entity_type}`); + console.log(` Failures: ${item.failure_count}`); + console.log(` Last Failure: ${new Date(item.last_failure).toLocaleString()}`); + console.log(` Common Errors:`); + item.common_errors.slice(0, 3).forEach(err => { + console.log(` - ${err.substring(0, 80)}...`); + }); + console.log(); + }); + } + } + + // Display detailed records + console.log('═══════════════════════════════════════════════════════════'); + console.log('📋 DETAILED SYNC RECORDS'); + console.log('═══════════════════════════════════════════════════════════\n'); + + // Group by status + const byStatus = records.reduce((acc, record) => { + if (!acc[record.status]) acc[record.status] = []; + acc[record.status].push(record); + return acc; + }, {} as Record); + + Object.entries(byStatus).forEach(([status, statusRecords]) => { + const statusIcon = status === 'completed' ? '✅' : status === 'failed' ? '❌' : '⏳'; + console.log(`${statusIcon} ${status.toUpperCase()} (${statusRecords.length} records)`); + console.log('─────────────────────────────────────────────────────────\n'); + + statusRecords.forEach(record => { + const duration = formatDuration(record.started_at, record.completed_at); + const errorCategory = categorizeError(record.error_message); + + console.log(` ID: ${record.id}`); + console.log(` Entity: ${record.entity_type}`); + console.log(` Type: ${record.sync_type}`); + console.log(` Started: ${new Date(record.started_at).toLocaleString()}`); + console.log(` Duration: ${duration}`); + console.log(` Records: +${record.records_added} ~${record.records_updated} -${record.records_deleted}`); + console.log(` Triggered By: ${record.triggered_by}`); + + if (record.error_message) { + console.log(` Error Category: ${errorCategory}`); + console.log(` Error: ${record.error_message}`); + } + + console.log(); + }); + }); + + // Statistics + console.log('═══════════════════════════════════════════════════════════'); + console.log('📊 STATISTICS'); + console.log('═══════════════════════════════════════════════════════════\n'); + + const totalRecordsAdded = records.reduce((sum, r) => sum + r.records_added, 0); + const totalRecordsUpdated = records.reduce((sum, r) => sum + r.records_updated, 0); + const totalRecordsDeleted = records.reduce((sum, r) => sum + r.records_deleted, 0); + const failedCount = records.filter(r => r.status === 'failed').length; + const completedCount = records.filter(r => r.status === 'completed').length; + const successRate = records.length > 0 ? ((completedCount / records.length) * 100).toFixed(1) : '0'; + + console.log(`Total Syncs: ${records.length}`); + console.log(` Completed: ${completedCount}`); + console.log(` Failed: ${failedCount}`); + console.log(` Success Rate: ${successRate}%`); + console.log(); + console.log(`Total Records Processed:`); + console.log(` Added: ${totalRecordsAdded}`); + console.log(` Updated: ${totalRecordsUpdated}`); + console.log(` Deleted: ${totalRecordsDeleted}`); + console.log(); + + // Error categories + if (failedCount > 0) { + const errorCategories = records + .filter(r => r.status === 'failed') + .reduce((acc, r) => { + const category = categorizeError(r.error_message); + acc[category] = (acc[category] || 0) + 1; + return acc; + }, {} as Record); + + console.log('Error Categories:'); + Object.entries(errorCategories) + .sort(([, a], [, b]) => b - a) + .forEach(([category, count]) => { + console.log(` ${category}: ${count}`); + }); + console.log(); + } + + console.log('═══════════════════════════════════════════════════════════\n'); + + } catch (error) { + console.error('❌ Analysis failed:', error); + if (error instanceof Error) { + console.error('Stack trace:', error.stack); + } + process.exit(1); + } finally { + await postgresClient.close(); + } +} + +// Run analysis +analyzeSyncFailures() + .then(() => { + console.log('✅ Analysis complete\n'); + process.exit(0); + }) + .catch((error) => { + console.error('❌ Fatal error:', error); + process.exit(1); + });