lorentz/wulf-pulse
1
0
Fork 0
Code Issues 1 Pull requests Projects Releases Packages Wiki Activity Actions

feat: implement structured logging for sync operations

Browse source 
- 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.
This commit is contained in:
root 2026-01-23 08:02:02 -05:00
parent df333348f6
commit e25eb3fa5e
5 changed files with 1056 additions and 139 deletions
Download patch file Download diff file Expand all files Collapse all files

222
lib/services/entity-sync.ts
View file

@ -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<number>;
private cachedValidContactIds?: Set<number>;
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<string, any>[];
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<EntitySyncStats> {
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<EntitySyncStats> {
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<EntitySyncStats> {
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;
}
}

94
lib/services/sync-service.ts
View file

@ -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 });
}
}

257
lib/utils/sync-logger.ts Normal file
View file

@ -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();