diff --git a/src/main/services/auth/auth-application-service.ts b/src/main/services/auth/auth-application-service.ts index 46c3d2b..8ac6df7 100644 --- a/src/main/services/auth/auth-application-service.ts +++ b/src/main/services/auth/auth-application-service.ts @@ -1,7 +1,7 @@ import { hostname } from 'os' import { SessionManager } from '../user/session-manager' import { UpdateService } from '../update/update-service' -import { createLogger } from '../logger' +import { createLogger, run, getRequestId, getContext } from '../logger' import { logAudit } from '../logger/audit-logger' import { ValidationError } from '../../types/errors' import type { UserInfo } from '../../types/user.types' @@ -23,120 +23,212 @@ export class AuthApplicationService { ) {} async getComputerName(): Promise { + const requestId = getRequestId() + if (requestId) { + log.debug('Get computer name', { requestId }) + } return hostname() } async silentLogin(): Promise { if (this.silentLoginPromise) { - log.debug('Reusing in-flight silent login request') + log.debug('Reusing in-flight silent login request', { requestId: getRequestId() }) return this.silentLoginPromise } - this.silentLoginPromise = this.performSilentLogin() - try { - return await this.silentLoginPromise - } finally { - this.silentLoginPromise = null - } - } + this.silentLoginPromise = run( + async (): Promise => { + const requestId = getRequestId() + const context = getContext() + const startTime = performance.now() - private async performSilentLogin(): Promise { - log.info('Attempting silent login') - const success = await this.sessionManager.loginByComputerName() - const userInfo = this.sessionManager.getUserInfo() + try { + log.info('Attempting silent login', { requestId, operation: context?.operation }) + const success = await this.sessionManager.loginByComputerName() + const userInfo = this.sessionManager.getUserInfo() - if (!success || !userInfo) { - await this.updateService.setUserContext(null) - throw new ValidationError('无感登录失败：未找到匹配用户', 'VAL_INVALID_INPUT') - } + if (!success || !userInfo) { + await this.updateService.setUserContext(null) + const error = new ValidationError('无感登录失败：未找到匹配用户', 'VAL_INVALID_INPUT') + log.error('Silent login failed - user not found', { + operation: 'silentLogin', + requestId, + userId: userInfo?.id, + username: userInfo?.username, + computerName: hostname(), + error + }) + throw error + } - await this.updateService.setUserContext(userInfo.userType) + await this.updateService.setUserContext(userInfo.userType) - const requiresUserSelection = userInfo.userType === 'Admin' - log.info('Silent login successful', { - username: userInfo.username, - userType: userInfo.userType, - requiresUserSelection - }) + const requiresUserSelection = userInfo.userType === 'Admin' + log.info('Silent login successful', { + requestId, + operation: context?.operation, + username: userInfo.username, + userType: userInfo.userType, + requiresUserSelection, + userId: userInfo.id + }) - this.writeAuditLog('LOGIN', String(userInfo.id), { - username: userInfo.username, - computerName: hostname(), - resource: 'ERP_SYSTEM', - status: 'success', - metadata: { loginType: 'silent', userType: userInfo.userType } - }) + this.writeAuditLog('LOGIN', String(userInfo.id), { + username: userInfo.username, + computerName: hostname(), + resource: 'ERP_SYSTEM', + status: 'success', + metadata: { loginType: 'silent', userType: userInfo.userType } + }) - return { - success: true, - userInfo, - requiresUserSelection - } + return { + success: true, + userInfo, + requiresUserSelection + } + } finally { + const durationMs = performance.now() - startTime + if (durationMs > 1000) { + log.warn(`Silent login took ${durationMs.toFixed(2)}ms (SLOW)`, { + operation: 'silentLogin', + requestId, + durationMs + }) + } else { + log.debug(`Silent login completed in ${durationMs.toFixed(2)}ms`, { + operation: 'silentLogin', + requestId, + durationMs + }) + } + } + }, + { operation: 'silentLogin' } + ) + return this.silentLoginPromise } async login(username: string, password: string): Promise { if (!username || !password) { - log.warn('Login attempt with missing credentials') + log.warn('Login attempt with missing credentials', { requestId: getRequestId() }) throw new ValidationError('请输入用户名和密码', 'VAL_MISSING_REQUIRED') } - log.info('Login attempt', { username }) - const success = await this.sessionManager.login(username, password) - const userInfo = this.sessionManager.getUserInfo() + return run( + async (): Promise => { + const requestId = getRequestId() + const context = getContext() - if (!success || !userInfo) { - this.writeAuditLog('LOGIN', '0', { - username, - computerName: hostname(), - resource: 'ERP_SYSTEM', - status: 'failure', - metadata: { loginType: 'credentials', reason: 'invalid_credentials' } - }) + const startTime = performance.now() - log.warn('Login failed - invalid credentials', { username }) - await this.updateService.setUserContext(null) - throw new ValidationError('用户名或密码错误', 'VAL_INVALID_INPUT') - } + try { + log.info('Login attempt', { username, requestId, operation: context?.operation }) + const success = await this.sessionManager.login(username, password) + const userInfo = this.sessionManager.getUserInfo() - log.info('Login successful', { username, userType: userInfo.userType }) - await this.updateService.setUserContext(userInfo.userType) + if (!success || !userInfo) { + this.writeAuditLog('LOGIN', '0', { + username, + computerName: hostname(), + resource: 'ERP_SYSTEM', + status: 'failure', + metadata: { loginType: 'credentials', reason: 'invalid_credentials' } + }) - this.writeAuditLog('LOGIN', String(userInfo.id), { - username: userInfo.username, - computerName: hostname(), - resource: 'ERP_SYSTEM', - status: 'success', - metadata: { loginType: 'credentials', userType: userInfo.userType } - }) + const error = new ValidationError('用户名或密码错误', 'VAL_INVALID_INPUT') + log.warn('Login failed - invalid credentials', { + username, + requestId, + operation: context?.operation, + error + }) + await this.updateService.setUserContext(null) + throw error + } - return { - success: true, - userInfo - } + log.info('Login successful', { + requestId, + operation: context?.operation, + username, + userType: userInfo.userType, + userId: userInfo.id + }) + await this.updateService.setUserContext(userInfo.userType) + + this.writeAuditLog('LOGIN', String(userInfo.id), { + username: userInfo.username, + computerName: hostname(), + resource: 'ERP_SYSTEM', + status: 'success', + metadata: { loginType: 'credentials', userType: userInfo.userType } + }) + + return { + success: true, + userInfo + } + } finally { + const durationMs = performance.now() - startTime + if (durationMs > 1000) { + log.warn(`Login took ${durationMs.toFixed(2)}ms (SLOW)`, { + operation: 'login', + requestId, + durationMs, + username + }) + } else { + log.debug(`Login completed in ${durationMs.toFixed(2)}ms`, { + operation: 'login', + requestId, + durationMs + }) + } + } + }, + { operation: 'login' } + ) } async logout(): Promise { - const userInfo = this.sessionManager.getUserInfo() - log.info('User logout', { username: userInfo?.username }) + return run( + async () => { + const requestId = getRequestId() + const context = getContext() + const userInfo = this.sessionManager.getUserInfo() - if (userInfo) { - this.writeAuditLog('LOGOUT', String(userInfo.id), { - username: userInfo.username, - computerName: hostname(), - resource: 'ERP_SYSTEM', - status: 'success', - metadata: { userType: userInfo.userType } - }) - } + log.info('User logout', { + requestId, + operation: context?.operation, + username: userInfo?.username, + userId: userInfo?.id + }) - this.sessionManager.logout() - await this.updateService.setUserContext(null) + if (userInfo) { + this.writeAuditLog('LOGOUT', String(userInfo.id), { + username: userInfo.username, + computerName: hostname(), + resource: 'ERP_SYSTEM', + status: 'success', + metadata: { userType: userInfo.userType } + }) + } + + this.sessionManager.logout() + await this.updateService.setUserContext(null) + }, + { operation: 'logout' } + ) } getCurrentUser(): CurrentUserResponse { + const requestId = getRequestId() const isAuthenticated = this.sessionManager.isAuthenticated() const userInfo = this.sessionManager.getUserInfo() + if (requestId) { + log.debug('Get current user', { requestId, isAuthenticated, userId: userInfo?.id }) + } + return { isAuthenticated, userInfo: userInfo ?? undefined @@ -144,27 +236,73 @@ export class AuthApplicationService { } async getAllUsers(): Promise { - log.debug('Fetching all users for admin selection') + const requestId = getRequestId() + log.debug('Fetching all users for admin selection', { requestId }) return this.sessionManager.getAllUsers() } async switchUser(userInfo: UserInfo): Promise { - log.info('User switch attempt', { targetUser: userInfo.username }) - const success = this.sessionManager.switchUser(userInfo) + return run( + async (): Promise => { + const requestId = getRequestId() + const context = getContext() + const startTime = performance.now() - if (!success) { - log.warn('User switch failed') - throw new ValidationError('用户切换失败', 'VAL_INVALID_INPUT') - } + try { + log.info('User switch attempt', { + requestId, + operation: context?.operation, + targetUser: userInfo.username, + targetUserId: userInfo.id + }) + const success = this.sessionManager.switchUser(userInfo) - const newUser = this.sessionManager.getUserInfo() - log.info('User switch successful', { newUsername: newUser?.username }) - await this.updateService.setUserContext(newUser?.userType ?? null) + if (!success) { + const error = new ValidationError('用户切换失败', 'VAL_INVALID_INPUT') + log.warn('User switch failed', { + requestId, + operation: context?.operation, + targetUser: userInfo.username, + targetUserId: userInfo.id, + error + }) + throw error + } - return { - success: true, - userInfo: newUser ?? undefined - } + const newUser = this.sessionManager.getUserInfo() + log.info('User switch successful', { + requestId, + operation: context?.operation, + newUsername: newUser?.username, + newUserId: newUser?.id, + newUserType: newUser?.userType + }) + await this.updateService.setUserContext(newUser?.userType ?? null) + + return { + success: true, + userInfo: newUser ?? undefined + } + } finally { + const durationMs = performance.now() - startTime + if (durationMs > 1000) { + log.warn(`User switch took ${durationMs.toFixed(2)}ms (SLOW)`, { + operation: 'switchUser', + requestId, + durationMs, + targetUser: userInfo.username + }) + } else { + log.debug(`User switch completed in ${durationMs.toFixed(2)}ms`, { + operation: 'switchUser', + requestId, + durationMs + }) + } + } + }, + { operation: 'switchUser', userId: String(userInfo.id) } + ) } isAdmin(): boolean { diff --git a/src/main/services/erp/cleaner.ts b/src/main/services/erp/cleaner.ts index 89fe04b..82f0fa5 100644 --- a/src/main/services/erp/cleaner.ts +++ b/src/main/services/erp/cleaner.ts @@ -3,7 +3,7 @@ import { ErpAuthService } from './erp-auth' import type { CleanerInput, CleanerResult, OrderCleanDetail } from '../../types/cleaner.types' import type { ErpSession } from '../../types/erp.types' import type { FrameLocator, Locator, Page } from 'playwright' -import { createLogger } from '../logger' +import { createLogger, run, trackDuration } from '../logger' const log = createLogger('CleanerService') @@ -173,6 +173,15 @@ export class CleanerService { } async clean(input: CleanerInput): Promise { + return run( + async () => { + return await this.performCleanup(input) + }, + { operation: 'cleaner' } + ) + } + + private async performCleanup(input: CleanerInput): Promise { const result: CleanerResult = { ordersProcessed: 0, materialsDeleted: 0, @@ -184,6 +193,7 @@ export class CleanerService { } const totalOrders = input.orderNumbers.length + const totalMaterials = input.materialCodes.length const dryRun = input.dryRun ?? this.dryRun const queryBatchSize = clampNumber( input.queryBatchSize, @@ -200,10 +210,12 @@ export class CleanerService { log.info('Starting cleaner', { totalOrders, - materialCount: input.materialCodes.length, + totalMaterials, dryRun, queryBatchSize, - processConcurrency + processConcurrency, + orderNumbers: input.orderNumbers, + materialCodes: input.materialCodes }) const deleteSet = new Set(input.materialCodes) @@ -231,56 +243,75 @@ export class CleanerService { log.info('Processing cleaner batch', { batchIndex: batchIndex + 1, totalBatches: orderBatches.length, - batchSize: batchOrders.length + batchSize: batchOrders.length, + totalOrders, + totalMaterials }) - await this.queryOrders(workFrame, batchOrders) - await this.waitForLoading(workFrame) + // Track batch processing duration with 5s slow threshold + await trackDuration( + async () => { + await this.queryOrders(workFrame, batchOrders) + await this.waitForLoading(workFrame) - const queriedRows = await this.collectQueryResultRows(workFrame) - const queriedOrderNumbersInBatch = new Set(queriedRows.map((row) => row.orderNumber)) + const queriedRows = await this.collectQueryResultRows(workFrame) + const queriedOrderNumbersInBatch = new Set(queriedRows.map((row) => row.orderNumber)) - await runWithConcurrency(queriedRows, processConcurrency, async (row) => { - const { rowIndex, orderNumber } = row - const openedDetailPage = await popupMutex.runExclusive(async () => { - return await this.openDetailPageFromRow(workFrame, popupPage!, rowIndex) - }) + await runWithConcurrency(queriedRows, processConcurrency, async (row) => { + const { rowIndex, orderNumber } = row + const openedDetailPage = await popupMutex.runExclusive(async () => { + return await this.openDetailPageFromRow(workFrame, popupPage!, rowIndex) + }) - let detail: OrderCleanDetail - try { - detail = await this.processDetailPage({ - detailPage: openedDetailPage, - deleteSet, - dryRun, - expectedOrderNumber: orderNumber, - progressState, - onProgress: input.onProgress + let detail: OrderCleanDetail + try { + detail = await this.processDetailPage({ + detailPage: openedDetailPage, + deleteSet, + dryRun, + expectedOrderNumber: orderNumber, + progressState, + onProgress: input.onProgress + }) + } catch (error) { + const message = error instanceof Error ? error.message : 'Unknown error' + detail = this.createErrorDetail(orderNumber, message) + } finally { + progressState.completedOrders += 1 + } + + result.details.push(detail) + + if (detail.errors.length > 0) { + result.errors.push(`Order ${detail.orderNumber}: ${detail.errors.join('; ')}`) + return + } + + result.ordersProcessed += 1 + result.materialsDeleted += detail.materialsDeleted + result.materialsSkipped += detail.materialsSkipped }) - } catch (error) { - const message = error instanceof Error ? error.message : 'Unknown error' - detail = this.createErrorDetail(orderNumber, message) - } finally { - progressState.completedOrders += 1 + + const missingOrders = getMissingOrders(batchOrders, queriedOrderNumbersInBatch) + for (const missingOrder of missingOrders) { + const missingMessage = '订单未出现在查询结果中' + result.errors.push(`Order ${missingOrder}: ${missingMessage}`) + result.details.push(this.createErrorDetail(missingOrder, missingMessage)) + } + }, + { + operationName: `batch-${batchIndex + 1}-${orderBatches[batchIndex].length}-orders`, + message: `Batch ${batchIndex + 1}/${orderBatches.length}`, + slowThresholdMs: 5000, + context: { + batchIndex: batchIndex + 1, + totalBatches: orderBatches.length, + batchSize: batchOrders.length, + totalOrders, + totalMaterials + } } - - result.details.push(detail) - - if (detail.errors.length > 0) { - result.errors.push(`Order ${detail.orderNumber}: ${detail.errors.join('; ')}`) - return - } - - result.ordersProcessed += 1 - result.materialsDeleted += detail.materialsDeleted - result.materialsSkipped += detail.materialsSkipped - }) - - const missingOrders = getMissingOrders(batchOrders, queriedOrderNumbersInBatch) - for (const missingOrder of missingOrders) { - const missingMessage = '订单未出现在查询结果中' - result.errors.push(`Order ${missingOrder}: ${missingMessage}`) - result.details.push(this.createErrorDetail(missingOrder, missingMessage)) - } + ) } const retryResult = await this.retryFailedOrders({ @@ -321,11 +352,21 @@ export class CleanerService { ordersProcessed: result.ordersProcessed, materialsDeleted: result.materialsDeleted, materialsSkipped: result.materialsSkipped, - errorCount: result.errors.length + errorCount: result.errors.length, + totalOrders, + totalMaterials, + dryRun }) } catch (error) { const message = error instanceof Error ? error.message : 'Unknown error' - log.error('Cleaner failed', { error: message }) + log.error('Cleaner failed', { + error: message, + totalOrders, + totalMaterials, + dryRun, + orderNumbers: input.orderNumbers, + materialCodes: input.materialCodes + }) result.errors.push(`Clean failed: ${message}`) } finally { if (popupPage) { @@ -780,86 +821,112 @@ export class CleanerService { return result } - log.info('Starting retry for failed orders', { count: failedDetails.length }) + log.info('Starting retry for failed orders', { + count: failedDetails.length, + totalOrders: params.failedDetails.length + }) const MAX_RETRIES = 2 - for (let detailIndex = 0; detailIndex < failedDetails.length; detailIndex++) { - const failedDetail = failedDetails[detailIndex] - const orderNumber = failedDetail.orderNumber - const retryAttempts: import('../../types/cleaner.types').RetryAttempt[] = [] + // Track overall retry process duration + const trackedResult = await trackDuration( + async () => { + const retryResult: RetryResult = { + retriedOrders: 0, + successfulRetries: 0, + updatedDetails: [] + } - for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { - try { - log.info(`Retrying order ${orderNumber} (attempt ${attempt}/${MAX_RETRIES})`) + for (let detailIndex = 0; detailIndex < failedDetails.length; detailIndex++) { + const failedDetail = failedDetails[detailIndex] + const orderNumber = failedDetail.orderNumber + const retryAttempts: import('../../types/cleaner.types').RetryAttempt[] = [] - await this.queryOrders(workFrame, [orderNumber]) - await this.waitForLoading(workFrame) + for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { + try { + log.info(`Retrying order ${orderNumber} (attempt ${attempt}/${MAX_RETRIES})`) - const rows = workFrame.locator('tbody tr') - const rowCount = await rows.count() - if (rowCount === 0) { - throw new Error('订单重试查询无结果') - } + await this.queryOrders(workFrame, [orderNumber]) + await this.waitForLoading(workFrame) - const detailPage = await this.openDetailPageFromCurrentQuery(workFrame, popupPage) - const retryDetail = await this.processDetailPage({ - detailPage, - deleteSet, - dryRun, - expectedOrderNumber: orderNumber, - progressState: { - completedOrders: detailIndex, - totalOrders: failedDetails.length - }, - onProgress: (message, progress, extra) => { - onProgress?.( - `[重试 ${attempt}/${MAX_RETRIES}] ${message}`, - progress, - extra ? { ...extra, phase: 'processing' as const } : undefined - ) + const rows = workFrame.locator('tbody tr') + const rowCount = await rows.count() + if (rowCount === 0) { + throw new Error('订单重试查询无结果') + } + + const detailPage = await this.openDetailPageFromCurrentQuery(workFrame, popupPage) + const retryDetail = await this.processDetailPage({ + detailPage, + deleteSet, + dryRun, + expectedOrderNumber: orderNumber, + progressState: { + completedOrders: detailIndex, + totalOrders: failedDetails.length + }, + onProgress: (message, progress, extra) => { + onProgress?.( + `[重试 ${attempt}/${MAX_RETRIES}] ${message}`, + progress, + extra ? { ...extra, phase: 'processing' as const } : undefined + ) + } + }) + + retryResult.successfulRetries += 1 + retryResult.updatedDetails.push({ + ...retryDetail, + retryCount: attempt, + retriedAt: Date.now(), + retrySuccess: true, + retryAttempts + }) + retryResult.retriedOrders += 1 + break + } catch (error) { + const message = error instanceof Error ? error.message : 'Unknown error' + log.warn(`Retry attempt ${attempt} failed for order ${orderNumber}: ${message}`) + + retryAttempts.push({ + attempt, + error: message, + timestamp: Date.now() + }) + + if (attempt === MAX_RETRIES) { + retryResult.updatedDetails.push({ + ...failedDetail, + retryCount: MAX_RETRIES, + retryAttempts, + retriedAt: Date.now(), + retrySuccess: false + }) + retryResult.retriedOrders += 1 + } } - }) - - result.successfulRetries += 1 - result.updatedDetails.push({ - ...retryDetail, - retryCount: attempt, - retriedAt: Date.now(), - retrySuccess: true, - retryAttempts - }) - result.retriedOrders += 1 - break - } catch (error) { - const message = error instanceof Error ? error.message : 'Unknown error' - log.warn(`Retry attempt ${attempt} failed for order ${orderNumber}: ${message}`) - - retryAttempts.push({ - attempt, - error: message, - timestamp: Date.now() - }) - - if (attempt === MAX_RETRIES) { - result.updatedDetails.push({ - ...failedDetail, - retryCount: MAX_RETRIES, - retryAttempts, - retriedAt: Date.now(), - retrySuccess: false - }) - result.retriedOrders += 1 } } + + log.info('Retry process completed', { + retriedOrders: retryResult.retriedOrders, + successfulRetries: retryResult.successfulRetries, + totalRetryOrders: failedDetails.length + }) + + return retryResult + }, + { + operationName: 'retry-failed-orders', + message: 'Retry failed orders', + slowThresholdMs: 5000, + context: { + totalRetryOrders: failedDetails.length, + dryRun + } } - } + ) - log.info('Retry process completed', { - retriedOrders: result.retriedOrders, - successfulRetries: result.successfulRetries - }) - - return result + return trackedResult.result } } diff --git a/src/main/services/erp/extractor.ts b/src/main/services/erp/extractor.ts index e8ca712..fb780d8 100644 --- a/src/main/services/erp/extractor.ts +++ b/src/main/services/erp/extractor.ts @@ -10,7 +10,8 @@ import type { LogLevel } from '../../types/extractor.types' import { DataImportService } from '../database/data-importer' -import { createLogger } from '../logger' +import { createLogger, withRequestContext, getRequestId } from '../logger' +import { trackDuration } from '../logger/performance-monitor' const log = createLogger('ExtractorService') @@ -50,70 +51,105 @@ export class ExtractorService { orderRecordCounts: [] } - try { - const session = this.authService.getSession() - - // Call ExtractorCore to execute web page operations - const core = new ExtractorCore() - const coreResult = await core.downloadAllBatches({ - session, - orderNumbers: input.orderNumbers, - downloadDir: this.downloadDir, - batchSize: input.batchSize || 100, - onProgress: input.onProgress - }) - - result.downloadedFiles = coreResult.downloadedFiles - result.errors = coreResult.errors - - // Merge downloaded files (original logic preserved) - if (result.downloadedFiles.length > 0) { - const totalBatches = result.downloadedFiles.length - const totalPoints = 1 + totalBatches + 2 - const progressPerPoint = 100 / totalPoints - const mergeProgress = (1 + totalBatches) * progressPerPoint - - input.onProgress?.('正在合并文件...', mergeProgress, { - phase: 'merging', - totalBatches + // Wrap entire extraction in request context for unified logging + return withRequestContext( + async () => { + const requestId = getRequestId() + log.info('Starting extraction', { + orderCount: input.orderNumbers.length, + batchSize: input.batchSize || 100, + downloadDir: this.downloadDir, + requestId }) - const mergeResult = await this.mergeFiles(result.downloadedFiles) - result.mergedFile = mergeResult.mergedFile - result.recordCount = mergeResult.recordCount - result.orderRecordCounts = mergeResult.orderRecordCounts - // Add merge error to result if any - if (mergeResult.error) { - result.errors.push(mergeResult.error) - } + try { + const session = this.authService.getSession() - // Always clean up temporary files regardless of merge success - await this.cleanupTempFiles(result.downloadedFiles) - - // Auto-import to database if merge was successful - if (result.mergedFile) { - const importProgress = (1 + totalBatches + 1) * progressPerPoint - input.onProgress?.('正在写入数据库...', importProgress, { - phase: 'importing', - totalBatches - }) - const importResult = await this.importToDatabaseWithLogging( - result.mergedFile, - input.onLog + // Call ExtractorCore to execute web page operations with timing + const core = new ExtractorCore() + const coreResult = await trackDuration( + async () => + core.downloadAllBatches({ + session, + orderNumbers: input.orderNumbers, + downloadDir: this.downloadDir, + batchSize: input.batchSize || 100, + onProgress: input.onProgress + }), + { + operationName: 'Batch Download', + context: { + orderCount: input.orderNumbers.length, + batchSize: input.batchSize || 100 + } + } ) - result.importResult = importResult - if (!importResult.success && importResult.errors.length > 0) { - result.errors.push(...importResult.errors) + result.downloadedFiles = coreResult.result.downloadedFiles + result.errors = coreResult.result.errors + + // Merge downloaded files (original logic preserved) + if (result.downloadedFiles.length > 0) { + const totalBatches = result.downloadedFiles.length + const totalPoints = 1 + totalBatches + 2 + const progressPerPoint = 100 / totalPoints + const mergeProgress = (1 + totalBatches) * progressPerPoint + + input.onProgress?.('正在合并文件...', mergeProgress, { + phase: 'merging', + totalBatches + }) + const mergeResult = await this.mergeFiles(result.downloadedFiles, input.orderNumbers) + result.mergedFile = mergeResult.mergedFile + result.recordCount = mergeResult.recordCount + result.orderRecordCounts = mergeResult.orderRecordCounts + + // Add merge error to result if any + if (mergeResult.error) { + result.errors.push(mergeResult.error) + } + + // Always clean up temporary files regardless of merge success + await this.cleanupTempFiles(result.downloadedFiles, input.orderNumbers) + + // Auto-import to database if merge was successful + if (result.mergedFile) { + const importProgress = (1 + totalBatches + 1) * progressPerPoint + input.onProgress?.('正在写入数据库...', importProgress, { + phase: 'importing', + totalBatches + }) + const importResult = await this.importToDatabaseWithLogging( + result.mergedFile, + input.onLog + ) + result.importResult = importResult + + if (!importResult.success && importResult.errors.length > 0) { + result.errors.push(...importResult.errors) + } + } } - } - } - } catch (error) { - const message = error instanceof Error ? error.message : 'Unknown error' - result.errors.push(`Extraction failed: ${message}`) - } - return result + log.info('Extraction completed successfully', { + recordCount: result.recordCount, + fileCount: result.downloadedFiles.length + }) + } catch (error) { + const message = error instanceof Error ? error.message : 'Unknown error' + log.error('Extraction failed', { + error: message, + orderNumbers: input.orderNumbers, + downloadDir: this.downloadDir, + requestId: getRequestId() + }) + result.errors.push(`Extraction failed: ${message}`) + } + + return result + }, + { operation: 'extract' } + ) } /** @@ -121,9 +157,13 @@ export class ExtractorService { * Uses ExcelParser to parse and combine all material plans * * @param filePaths - Array of downloaded Excel file paths + * @param orderNumbers - Order numbers for context logging * @returns Merged file path, total record count, and optional error message */ - private async mergeFiles(filePaths: string[]): Promise<{ + private async mergeFiles( + filePaths: string[], + orderNumbers: string[] + ): Promise<{ mergedFile: string | null recordCount: number error?: string @@ -133,75 +173,101 @@ export class ExtractorService { return { mergedFile: null, recordCount: 0, orderRecordCounts: [] } } - log.info('Starting merge', { fileCount: filePaths.length }) - const parser = new ExcelParser() + log.info('Starting merge', { fileCount: filePaths.length, orderCount: orderNumbers.length }) - // Collect all orders with full order info and materials - // Each order has: { orderInfo: OrderHeader, materials: MaterialRow[] } - const allOrders: Array<{ orderInfo: any; materials: any[] }> = [] + // Track merge operation duration and unwrap result + const trackedResult = await trackDuration( + async () => { + const parser = new ExcelParser() - // Parse each downloaded file and collect orders - for (const filePath of filePaths) { - try { - log.debug('Parsing file', { filePath }) - await parser.parse(filePath) - // After parse(), the parser store orders internally as lastOrders - const orders = (parser as any).lastOrders - log.debug('File parsed', { filePath, orderCount: orders?.length || 0 }) - if (orders && Array.isArray(orders)) { - allOrders.push(...orders) + // Collect all orders with full order info and materials + // Each order has: { orderInfo: OrderHeader, materials: MaterialRow[] } + const allOrders: Array<{ orderInfo: any; materials: any[] }> = [] + + // Parse each downloaded file and collect orders + for (const filePath of filePaths) { + try { + log.debug('Parsing file', { filePath }) + await parser.parse(filePath) + // After parse(), the parser store orders internally as lastOrders + const orders = (parser as any).lastOrders + log.debug('File parsed', { filePath, orderCount: orders?.length || 0 }) + if (orders && Array.isArray(orders)) { + allOrders.push(...orders) + } + } catch (error) { + const errorMsg = error instanceof Error ? error.message : String(error) + log.error('Failed to parse file', { + filePath, + error: errorMsg, + orderNumbers, + batchId: filePaths.indexOf(filePath) + }) + } + } + + // Calculate total record count (total material rows) + let recordCount = 0 + const orderRecordCounts: Array<{ orderNumber: string; recordCount: number }> = [] + for (const order of allOrders) { + const count = order.materials.length + recordCount += count + orderRecordCounts.push({ + orderNumber: order.orderInfo.productionOrder || '', + recordCount: count + }) + } + + log.info('Merge summary', { orderCount: allOrders.length, recordCount }) + + if (recordCount === 0) { + log.warn('No records found in any downloaded files', { orderNumbers }) + return { mergedFile: null, recordCount: 0, orderRecordCounts } + } + + // Generate output filename with timestamp + const timestamp = new Date() + .toISOString() + .replace(/[-:T]/g, '') + .replace(/\..+/, '') + .slice(0, 14) + const outputPath = path.join(this.downloadDir, `merged_${timestamp}.xlsx`) + + // Save with error handling + try { + log.info('Saving merged file', { outputPath }) + await this.saveMergedOrders(allOrders, outputPath) + log.info('Merged file saved successfully', { recordCount }) + return { mergedFile: outputPath, recordCount, orderRecordCounts } + } catch (error) { + const errorMsg = error instanceof Error ? error.message : String(error) + const errorStack = error instanceof Error ? error.stack : '' + log.error('Failed to save merged file', { + error: errorMsg, + stack: errorStack, + orderNumbers, + downloadDir: this.downloadDir + }) + // Return parsed record count and error info even if save fails + return { + mergedFile: null, + recordCount, + orderRecordCounts, + error: `保存合并文件失败：${errorMsg}` + } + } + }, + { + operationName: 'File Merge', + context: { + fileCount: filePaths.length, + orderCount: orderNumbers.length, + orderNumbers } - } catch (error) { - const errorMsg = error instanceof Error ? error.message : String(error) - log.error('Failed to parse file', { filePath, error: errorMsg }) } - } + ) - // Calculate total record count (total material rows) - let recordCount = 0 - const orderRecordCounts: Array<{ orderNumber: string; recordCount: number }> = [] - for (const order of allOrders) { - const count = order.materials.length - recordCount += count - orderRecordCounts.push({ - orderNumber: order.orderInfo.productionOrder || '', - recordCount: count - }) - } - - log.info('Merge summary', { orderCount: allOrders.length, recordCount }) - - if (recordCount === 0) { - log.warn('No records found in any downloaded files') - return { mergedFile: null, recordCount: 0, orderRecordCounts } - } - - // Generate output filename with timestamp - const timestamp = new Date() - .toISOString() - .replace(/[-:T]/g, '') - .replace(/\..+/, '') - .slice(0, 14) - const outputPath = path.join(this.downloadDir, `merged_${timestamp}.xlsx`) - - // Save with error handling - try { - log.info('Saving merged file', { outputPath }) - await this.saveMergedOrders(allOrders, outputPath) - log.info('Merged file saved successfully', { recordCount }) - return { mergedFile: outputPath, recordCount, orderRecordCounts } - } catch (error) { - const errorMsg = error instanceof Error ? error.message : String(error) - const errorStack = error instanceof Error ? error.stack : '' - log.error('Failed to save merged file', { error: errorMsg, stack: errorStack }) - // Return parsed record count and error info even if save fails - return { - mergedFile: null, - recordCount, - orderRecordCounts, - error: `保存合并文件失败：${errorMsg}` - } - } + return trackedResult.result } /** @@ -308,14 +374,19 @@ export class ExtractorService { * Clean up temporary batch files after merging * @param filePaths - Array of temporary file paths to delete */ - private async cleanupTempFiles(filePaths: string[]): Promise { + private async cleanupTempFiles(filePaths: string[], orderNumbers?: string[]): Promise { for (const filePath of filePaths) { try { await fs.unlink(filePath) log.debug('Deleted temporary file', { filePath }) } catch (error) { // Log error but don't fail the main process - log.error('Failed to delete temporary file', { filePath, error }) + log.error('Failed to delete temporary file', { + filePath, + error, + orderNumbers, + downloadDir: this.downloadDir + }) } } } @@ -333,41 +404,58 @@ export class ExtractorService { log.info('Starting database import', { filePath }) onLog?.('info', `开始导入数据到数据库...`) - const importService = new DataImportService() + // Track import operation duration and unwrap result + const trackedResult = await trackDuration( + async () => { + const importService = new DataImportService() - try { - const result = await importService.importFromExcel(filePath, 1000) + try { + const result = await importService.importFromExcel(filePath, 1000) - log.info('Import completed', { - success: result.success, - recordsRead: result.recordsRead, - recordsDeleted: result.recordsDeleted, - recordsImported: result.recordsImported - }) + log.info('Import completed', { + success: result.success, + recordsRead: result.recordsRead, + recordsDeleted: result.recordsDeleted, + recordsImported: result.recordsImported + }) - if (result.success) { - onLog?.( - 'success', - `导入完成：读取 ${result.recordsRead} 条，删除 ${result.recordsDeleted} 条，导入 ${result.recordsImported} 条` - ) - } else if (result.errors.length > 0) { - result.errors.forEach((err) => onLog?.('error', err)) + if (result.success) { + onLog?.( + 'success', + `导入完成：读取 ${result.recordsRead} 条，删除 ${result.recordsDeleted} 条，导入 ${result.recordsImported} 条` + ) + } else if (result.errors.length > 0) { + result.errors.forEach((err) => onLog?.('error', err)) + } + + return result + } catch (error) { + const errorMsg = error instanceof Error ? error.message : String(error) + log.error('Import failed', { + error: errorMsg, + filePath, + downloadDir: this.downloadDir + }) + onLog?.('error', `导入失败：${errorMsg}`) + + return { + success: false, + recordsRead: 0, + recordsDeleted: 0, + recordsImported: 0, + uniqueSourceNumbers: 0, + errors: [errorMsg] + } + } + }, + { + operationName: 'Database Import', + context: { + filePath + } } + ) - return result - } catch (error) { - const errorMsg = error instanceof Error ? error.message : String(error) - log.error('Import failed', { error: errorMsg }) - onLog?.('error', `导入失败：${errorMsg}`) - - return { - success: false, - recordsRead: 0, - recordsDeleted: 0, - recordsImported: 0, - uniqueSourceNumbers: 0, - errors: [errorMsg] - } - } + return trackedResult.result } } diff --git a/src/main/services/logger/error-utils.ts b/src/main/services/logger/error-utils.ts index e4c9694..d59d5c0 100644 --- a/src/main/services/logger/error-utils.ts +++ b/src/main/services/logger/error-utils.ts @@ -3,10 +3,13 @@ * * Provides comprehensive error serialization and formatting for logging. * Captures full error context including stack traces, causes, and custom properties. + * + * Enhanced with request context tracking for distributed tracing support. */ import type { ErrorLike, SerializedError } from '../../types/errors' import { isProduction } from './shared' +import { getRequestId } from './request-context' /** * Check if value is an Error or Error-like object @@ -152,6 +155,29 @@ export function extractErrorContext(error: SerializedError): { /** * Format error for console/file logging * Returns a formatted string with all error details + * + * @param error - The error to format (Error object or Error-like) + * @param context - Optional context for logging + * @param context.operation - Business operation being performed (e.g., 'extract', 'clean', 'validate') + * @param context.module - Module/Service name where error occurred + * @param context.userId - User ID performing the operation + * @param context.requestId - Request/trace ID for distributed tracing (auto-injected if not provided) + * @param context.batchId - Batch identifier for batch operations + * @param context.duration - Operation duration in milliseconds + * @param context.orderNumbers - Order numbers related to the operation + * @param context.materialCodes - Material codes related to the operation + * @returns Object with formatted message and metadata for logging + * + * @example + * ```typescript + * const { message, metadata } = formatErrorForLogging(error, { + * operation: 'extract', + * userId: 'user123', + * batchId: 'batch-001', + * duration: 1500 + * }) + * logger.error(message, metadata) + * ``` */ export function formatErrorForLogging( error: unknown, @@ -159,6 +185,11 @@ export function formatErrorForLogging( operation?: string module?: string userId?: string + requestId?: string + batchId?: string + duration?: number + orderNumbers?: string[] + materialCodes?: string[] [key: string]: unknown } ): { @@ -170,11 +201,27 @@ export function formatErrorForLogging( const errorToLog = isProd ? sanitizeError(serialized) : serialized const errorContext = extractErrorContext(errorToLog) + // Auto-inject requestId from async context if not explicitly provided + const autoRequestId = getRequestId() + const requestId = context?.requestId || autoRequestId + const metadata: Record = { error: errorToLog, + ...(requestId && { requestId }), ...context } + // Remove undefined context fields to keep logs clean + if (context) { + const cleanMetadata: Record = {} + for (const [key, value] of Object.entries(metadata)) { + if (value !== undefined) { + cleanMetadata[key] = value + } + } + Object.assign(metadata, cleanMetadata) + } + // Add error location context if available if (errorContext.fileName) { metadata.errorLocation = { @@ -202,6 +249,28 @@ export function formatErrorForLogging( /** * Log error with full context * Wrapper for logger.error that ensures complete error information is captured + * + * @param logger - Logger instance with error method + * @param error - The error to log (Error object or Error-like) + * @param options - Logging options + * @param options.message - Custom message to prepend to error message + * @param options.operation - Business operation being performed + * @param options.module - Module/Service name + * @param options.userId - User ID performing the operation + * @param options.requestId - Request/trace ID (auto-injected if not provided) + * @param options.batchId - Batch identifier for batch operations + * @param options.duration - Operation duration in milliseconds + * @param options.context - Additional custom context fields + * + * @example + * ```typescript + * logError(logger, error, { + * operation: 'extract', + * userId: 'user123', + * message: 'Failed to process order', + * duration: 1500 + * }) + * ``` */ export function logError( logger: { error: (message: string, meta?: Record) => void }, @@ -211,14 +280,29 @@ export function logError( operation?: string module?: string userId?: string + requestId?: string + batchId?: string + duration?: number context?: Record } = {} ): void { - const { message: customMessage, operation, module: moduleName, userId, context } = options + const { + message: customMessage, + operation, + module: moduleName, + userId, + requestId, + batchId, + duration, + context + } = options const { message, metadata } = formatErrorForLogging(error, { operation, module: moduleName, userId, + requestId, + batchId, + duration, ...context }) @@ -241,3 +325,77 @@ export function throwAfterLogging( logError(logger, error, options) throw error } + +/** + * Enhanced error logging helper with automatic context injection + * + * Simplifies error logging by automatically injecting requestId from async context + * and providing a concise API for common logging scenarios. + * + * @param logger - Logger instance with error method + * @param error - The error to log (Error object or Error-like) + * @param context - Business context for the error + * @param context.operation - Business operation (REQUIRED for enhanced logging) + * @param context.userId - User ID performing the operation + * @param context.batchId - Batch identifier for batch operations + * @param context.duration - Operation duration in milliseconds (e.g., from performance monitoring) + * @param context.orderNumbers - Order numbers related to the operation + * @param context.materialCodes - Material codes related to the operation + * @param context.module - Module/Service name (defaults to 'unknown' if not provided) + * @param customMessage - Optional custom message to prepend (if not provided, uses error message) + * + * @example + * ```typescript + * import { enhancedLogError } from './error-utils' + * + * // Simple usage with auto-injected requestId + * enhancedLogError(logger, error, { operation: 'extract', userId: 'user123' }) + * + * // With performance metrics + * const duration = Date.now() - startTime + * enhancedLogError(logger, error, { + * operation: 'clean', + * userId: 'user456', + * batchId: 'batch-001', + * duration, + * orderNumbers: ['ORD-123', 'ORD-124'] + * }) + * ``` + */ +export function enhancedLogError( + logger: { error: (message: string, meta?: Record) => void }, + error: unknown, + context: { + operation: string + userId?: string + batchId?: string + duration?: number + orderNumbers?: string[] + materialCodes?: string[] + module?: string + }, + customMessage?: string +): void { + const { + operation, + userId, + batchId, + duration, + orderNumbers, + materialCodes, + module: moduleName + } = context + + logError(logger, error, { + message: customMessage, + operation, + module: moduleName, + userId, + batchId, + duration, + context: { + ...(orderNumbers && { orderNumbers }), + ...(materialCodes && { materialCodes }) + } + }) +} diff --git a/src/main/services/logger/index.ts b/src/main/services/logger/index.ts index 18ec20b..8bd3ceb 100644 --- a/src/main/services/logger/index.ts +++ b/src/main/services/logger/index.ts @@ -15,6 +15,7 @@ import { BrowserWindow } from 'electron' import { serializeError, sanitizeError } from './error-utils' import { getLogDir, isProduction } from './shared' import { IPC_CHANNELS } from '../../../shared/ipc-channels' +import { getContext, run } from './request-context' // Cache isProduction() at module load — app.isPackaged never changes at runtime const IS_PROD = isProduction() @@ -37,50 +38,83 @@ function isSerializedError(value: unknown): boolean { const consoleFormat = winston.format.combine( winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }), winston.format.colorize(), - winston.format.printf(({ timestamp, level, message, context, error, ...meta }) => { - const contextStr = context ? `[${context}]` : '' - - // Format error with full stack trace - let errorStr = '' - if (error) { - // Skip re-serialization if already a serialized error object - const serialized: { stack?: string; message: string } = isSerializedError(error) - ? (error as { stack?: string; message: string }) - : IS_PROD - ? sanitizeError(serializeError(error)) - : serializeError(error) - if (serialized.stack) { - errorStr = `\n${serialized.stack}` - } else { - errorStr = ` ${serialized.message}` + // Auto-inject requestId from async context + winston.format((info) => { + const context = getContext() + if (context) { + info.requestId = context.requestId + if (context.userId) { + info.userId = context.userId + } + if (context.operation) { + info.operation = context.operation } } + return info + })(), + winston.format.printf( + ({ timestamp, level, message, context, error, requestId, userId, operation, ...meta }) => { + const contextStr = context ? `[${context}]` : '' + const requestIdStr = requestId ? ` [${requestId}]` : '' + const userStr = userId ? ` (user:${userId})` : '' + const opStr = operation ? ` op:${operation}` : '' - let metaStr = '' - if (Object.keys(meta).length > 0) { - try { - metaStr = ` ${JSON.stringify(meta, null, 2)}` - } catch { - // Fallback for circular references: stringify primitives, replace complex objects with placeholder - metaStr = ` ${JSON.stringify( - Object.fromEntries( - Object.entries(meta).map(([k, v]) => [ - k, - v !== null && typeof v === 'object' ? `[Object]` : v - ]) - ), - null, - 2 - )}` + // Format error with full stack trace + let errorStr = '' + if (error) { + // Skip re-serialization if already a serialized error object + const serialized: { stack?: string; message: string } = isSerializedError(error) + ? (error as { stack?: string; message: string }) + : IS_PROD + ? sanitizeError(serializeError(error)) + : serializeError(error) + if (serialized.stack) { + errorStr = `\n${serialized.stack}` + } else { + errorStr = ` ${serialized.message}` + } } + + let metaStr = '' + if (Object.keys(meta).length > 0) { + try { + metaStr = ` ${JSON.stringify(meta, null, 2)}` + } catch { + // Fallback for circular references: stringify primitives, replace complex objects with placeholder + metaStr = ` ${JSON.stringify( + Object.fromEntries( + Object.entries(meta).map(([k, v]) => [ + k, + v !== null && typeof v === 'object' ? `[Object]` : v + ]) + ), + null, + 2 + )}` + } + } + return `${timestamp} [${level}]${contextStr}${requestIdStr}${userStr}${opStr} ${message}${errorStr}${metaStr}` } - return `${timestamp} [${level}]${contextStr} ${message}${errorStr}${metaStr}` - }) + ) ) // Custom format for file output - JSON with full error details const fileFormat = winston.format.combine( winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }), + // Auto-inject requestId from async context for file logs + winston.format((info) => { + const context = getContext() + if (context) { + info.requestId = context.requestId + if (context.userId) { + info.userId = context.userId + } + if (context.operation) { + info.operation = context.operation + } + } + return info + })(), winston.format((info) => { // Serialize errors in metadata (skip if already serialized) if (info.error) { @@ -189,11 +223,48 @@ export function createLogger(context: string): winston.Logger { return logger.child({ context }) } +/** + * Execute a function with automatic request-scoped logging + * + * This wrapper ensures all logging within the function has access to the request context. + * It's a convenience wrapper around RequestContext.run() that also ensures the logger + * properly captures the context. + * + * @param fn - The async function to execute within the context + * @param context - Optional business context (userId, operation) + * @returns Promise resolving to the function's return value + * + * @example + * ```typescript + * await withRequestContext(async () => { + * logger.info('Processing order') // Will include requestId, userId, operation + * await processOrder() + * }, { userId: 'user123', operation: 'process-order' }) + * ``` + */ +export async function withRequestContext( + fn: () => Promise, + context?: { userId?: string; operation?: string } +): Promise { + return run(fn, context) +} + // Re-export error utilities for convenience export { logError, formatErrorForLogging, serializeError, extractErrorContext } from './error-utils' +// Export request context management for async-context logging +export { run, getRequestId, getContext, withContext, type LoggerContext } from './request-context' + // Export the main logger for direct use export default logger +// Export performance monitoring utilities +export { + trackDuration, + PerformanceTracker, + createPerformanceTracker, + DEFAULT_SLOW_THRESHOLD_MS +} from './performance-monitor' + // Export log level types for convenience export type LogLevel = 'error' | 'warn' | 'info' | 'debug' | 'verbose' diff --git a/src/main/services/logger/performance-monitor.ts b/src/main/services/logger/performance-monitor.ts new file mode 100644 index 0000000..9f81886 --- /dev/null +++ b/src/main/services/logger/performance-monitor.ts @@ -0,0 +1,340 @@ +/** + * Logger Performance Monitoring Utilities + * + * Provides performance tracking and timing utilities that integrate with the Winston logger. + * + * Features: + * - trackDuration: Wrap async functions and auto-log execution time + * - PerformanceTracker: Track multiple metrics over time + * - Slow operation detection with configurable thresholds + * - Performance warnings for operations exceeding thresholds + */ + +import type { Logger } from 'winston' +import logger from './index' + +/** + * Default threshold for slow operation warnings (in milliseconds) + */ +export const DEFAULT_SLOW_THRESHOLD_MS = 1000 + +/** + * Result of a tracked operation + */ +export interface TrackDurationResult { + /** The result value from the operation */ + result: T + /** Execution duration in milliseconds */ + durationMs: number + /** Whether the operation exceeded the slow threshold */ + isSlow: boolean +} + +/** + * Configuration for trackDuration + */ +export interface TrackDurationOptions { + /** Operation name for logging */ + operationName: string + /** Custom log message (optional) */ + message?: string + /** Slow threshold in ms (overrides default) */ + slowThresholdMs?: number + /** Log level for duration info (default: 'debug') */ + logLevel?: 'debug' | 'info' | 'verbose' + /** Additional context to include in logs */ + context?: Record +} + +/** + * Metrics tracked by PerformanceTracker + */ +export interface PerformanceMetrics { + /** Total number of operations tracked */ + count: number + /** Total duration of all operations in milliseconds */ + totalDurationMs: number + /** Minimum duration in milliseconds */ + minDurationMs: number + /** Maximum duration in milliseconds */ + maxDurationMs: number + /** Average duration in milliseconds */ + avgDurationMs: number + /** Number of operations exceeding slow threshold */ + slowOperationCount: number +} + +/** + * Track the duration of an async operation and log the result + * + * @param fn - The async function to track + * @param options - Configuration options including operation name and threshold + * @returns Promise resolving to TrackDurationResult with result, duration, and slow flag + * + * @example + * ```typescript + * const result = await trackDuration( + * async () => await someAsyncOperation(), + * { operationName: 'Database Query', slowThresholdMs: 500 } + * ); + * console.log(result.result, result.durationMs); + * ``` + */ +export async function trackDuration( + fn: () => Promise, + options: TrackDurationOptions +): Promise> { + const { + operationName, + message = `Operation "${operationName}"`, + slowThresholdMs = DEFAULT_SLOW_THRESHOLD_MS, + logLevel = 'debug', + context = {} + } = options + + const startTime = performance.now() + + try { + const result = await fn() + const durationMs = performance.now() - startTime + const isSlow = durationMs > slowThresholdMs + + // Log the result + const logMessage = `${message} completed in ${durationMs.toFixed(2)}ms` + if (isSlow) { + logger.warn(`${logMessage} (SLOW - exceeded ${slowThresholdMs}ms threshold)`, { + operation: operationName, + durationMs, + slowThresholdMs, + ...context + }) + } else { + logger[logLevel](logMessage, { + operation: operationName, + durationMs, + ...context + }) + } + + return { result, durationMs, isSlow } + } catch (error) { + const durationMs = performance.now() - startTime + const isSlow = durationMs > slowThresholdMs + + // Log the error with duration + logger.error(`${message} failed after ${durationMs.toFixed(2)}ms`, { + operation: operationName, + durationMs, + slowThresholdMs, + error, + ...context + }) + + throw error + } +} + +/** + * PerformanceTracker class for tracking multiple metrics over time + * + * Tracks operation counts, durations, and identifies slow operations. + * Useful for monitoring service-level performance and identifying bottlenecks. + * + * @example + * ```typescript + * const tracker = new PerformanceTracker('DataService', 500); + * + * // Track individual operations + * await tracker.track('fetchData', async () => fetchData()); + * await tracker.track('saveData', async () => saveData()); + * + * // Get metrics + * const metrics = tracker.getMetrics(); + * console.log(`Avg duration: ${metrics.avgDurationMs}ms`); + * + * // Log summary + * tracker.logSummary(); + * ``` + */ +export class PerformanceTracker { + private operationName: string + private slowThresholdMs: number + private durations: number[] = [] + private slowCount = 0 + private log: Logger + + /** + * Create a new PerformanceTracker + * + * @param operationName - Name of the operation/category being tracked + * @param slowThresholdMs - Custom slow threshold in ms (default: 1000) + * @param customLogger - Optional custom logger instance (default: main logger) + */ + constructor( + operationName: string, + slowThresholdMs: number = DEFAULT_SLOW_THRESHOLD_MS, + customLogger?: Logger + ) { + this.operationName = operationName + this.slowThresholdMs = slowThresholdMs + this.log = customLogger ?? logger + } + + /** + * Track an async operation and record its duration + * + * @param name - Specific name of this operation instance + * @param fn - The async function to track + * @param context - Optional context to log with the operation + * @returns Promise resolving to the function's result + * + * @example + * ```typescript + * const result = await tracker.track('getUserById', async () => getUserById(id), { + * userId: id + * }); + * ``` + */ + async track( + name: string, + fn: () => Promise, + context?: Record + ): Promise { + const startTime = performance.now() + + try { + const result = await fn() + const durationMs = performance.now() - startTime + + this.recordDuration(durationMs) + + if (durationMs > this.slowThresholdMs) { + this.log.warn(`[${this.operationName}] ${name} took ${durationMs.toFixed(2)}ms (SLOW)`, { + operation: name, + durationMs, + slowThresholdMs: this.slowThresholdMs, + ...context + }) + } else { + this.log.debug(`[${this.operationName}] ${name} completed in ${durationMs.toFixed(2)}ms`, { + operation: name, + durationMs, + ...context + }) + } + + return result + } catch (error) { + const durationMs = performance.now() - startTime + this.recordDuration(durationMs) + + this.log.error(`[${this.operationName}] ${name} failed after ${durationMs.toFixed(2)}ms`, { + operation: name, + durationMs, + error, + ...context + }) + + throw error + } + } + + /** + * Record a duration measurement (for manual tracking) + * + * @param durationMs - Duration in milliseconds + */ + recordDuration(durationMs: number): void { + this.durations.push(durationMs) + if (durationMs > this.slowThresholdMs) { + this.slowCount++ + } + } + + /** + * Get current performance metrics + * + * @returns PerformanceMetrics with aggregated statistics + */ + getMetrics(): PerformanceMetrics { + const count = this.durations.length + if (count === 0) { + return { + count: 0, + totalDurationMs: 0, + minDurationMs: 0, + maxDurationMs: 0, + avgDurationMs: 0, + slowOperationCount: 0 + } + } + + const totalDurationMs = this.durations.reduce((sum, d) => sum + d, 0) + const minDurationMs = Math.min(...this.durations) + const maxDurationMs = Math.max(...this.durations) + const avgDurationMs = totalDurationMs / count + + return { + count, + totalDurationMs, + minDurationMs, + maxDurationMs, + avgDurationMs, + slowOperationCount: this.slowCount + } + } + + /** + * Log a summary of performance metrics + * + * @param level - Log level for summary (default: 'info') + * @param message - Custom message prefix (optional) + */ + logSummary(level: 'info' | 'warn' | 'debug' = 'info', message?: string): void { + const metrics = this.getMetrics() + const summaryMessage = message || `[${this.operationName}] Performance Summary` + + this.log[level](summaryMessage, { + totalOperations: metrics.count, + avgDurationMs: `${metrics.avgDurationMs.toFixed(2)}ms`, + minDurationMs: `${metrics.minDurationMs.toFixed(2)}ms`, + maxDurationMs: `${metrics.maxDurationMs.toFixed(2)}ms`, + slowOperations: metrics.slowOperationCount, + slowPercentage: + metrics.count > 0 + ? ((metrics.slowOperationCount / metrics.count) * 100).toFixed(1) + '%' + : '0%', + totalDurationMs: `${metrics.totalDurationMs.toFixed(2)}ms` + }) + } + + /** + * Reset all tracked metrics + */ + reset(): void { + this.durations = [] + this.slowCount = 0 + } +} + +/** + * Create a performance tracker for a specific service or module + * + * Convenience function that returns a new PerformanceTracker instance. + * Useful for creating trackers with consistent naming conventions. + * + * @param context - Context/module name (e.g., 'DatabaseService', 'ERPExtractor') + * @param slowThresholdMs - Optional custom slow threshold + * @returns New PerformanceTracker instance + * + * @example + * ```typescript + * const dbTracker = createPerformanceTracker('DatabaseService', 200); + * ``` + */ +export function createPerformanceTracker( + context: string, + slowThresholdMs?: number +): PerformanceTracker { + return new PerformanceTracker(context, slowThresholdMs) +} diff --git a/src/main/services/logger/request-context.ts b/src/main/services/logger/request-context.ts new file mode 100644 index 0000000..9595f94 --- /dev/null +++ b/src/main/services/logger/request-context.ts @@ -0,0 +1,152 @@ +/** + * Request Context Management using AsyncLocalStorage + * + * Provides async-context propagation for request-scoped logging metadata. + * Uses Node.js AsyncLocalStorage to maintain isolated context across async/await boundaries. + * + * Features: + * - Automatic requestId generation with crypto.randomUUID() + * - Support for userId and operation tracking + * - Complete context isolation between concurrent requests + * - Backward compatible with non-request logging scenarios + * + * @example + * ```typescript + * import { run, getRequestId, getContext } from './request-context' + * + * await run(async () => { + * const requestId = getRequestId() // Available throughout async chain + * await someAsyncOperation() + * }, { userId: 'user123', operation: 'extract' }) + * ``` + */ + +import { AsyncLocalStorage } from 'async_hooks' +import { randomUUID } from 'crypto' + +/** + * Logger context structure containing request-scoped metadata + */ +export interface LoggerContext { + /** Unique identifier for this request (auto-generated UUID v4) */ + requestId: string + /** User ID performing the operation (optional, set by caller) */ + userId?: string + /** Operation being performed (optional, e.g., 'extract', 'clean', 'validate') */ + operation?: string +} + +/** + * AsyncLocalStorage instance for request context + * Each async execution scope has its own isolated context + */ +const storage = new AsyncLocalStorage() + +/** + * Execute a function within a request context scope + * + * Creates a new context with auto-generated requestId and optional business metadata. + * All async operations within the callback can access this context via getRequestId() or getContext(). + * + * @param fn - The async function to execute within the context + * @param context - Optional business context (userId, operation) + * @returns Promise resolving to the function's return value + * + * @example + * ```typescript + * await run(async () => { + * // requestId is available here and in all nested async calls + * const id = getRequestId() + * await processOrder() + * }, { userId: 'user123', operation: 'extract' }) + * ``` + */ +export function run( + fn: () => Promise, + context?: Omit +): Promise { + const fullContext: LoggerContext = { + requestId: randomUUID(), + userId: context?.userId, + operation: context?.operation + } + + return storage.run(fullContext, fn) +} + +/** + * Get the current request ID from the async context + * + * @returns The current requestId, or undefined if not in a request context + * + * @example + * ```typescript + * function logSomething() { + * const requestId = getRequestId() + * logger.info(`Processing...`, { requestId }) + * } + * ``` + */ +export function getRequestId(): string | undefined { + const context = storage.getStore() + return context?.requestId +} + +/** + * Get the full logger context from the current async scope + * + * @returns The complete LoggerContext, or undefined if not in a request context + * + * @example + * ```typescript + * const context = getContext() + * if (context) { + * logger.info('Operation', { + * requestId: context.requestId, + * userId: context.userId, + * operation: context.operation + * }) + * } + * ``` + */ +export function getContext(): LoggerContext | undefined { + return storage.getStore() +} + +/** + * Execute a function with a modified context + * + * Creates a new context scope based on the current context with selective overrides. + * Useful for nested operations that need to change specific context fields. + * + * @param fn - The async function to execute + * @param overrides - Context fields to override + * @returns Promise resolving to the function's return value + * + * @example + * ```typescript + * await run(async () => { + * // Outer context: operation='extract' + * await withContext(async () => { + * // Inner context: operation='validate-subtask' + * }, { operation: 'validate-subtask' }) + * }, { operation: 'extract' }) + * ``` + */ +export function withContext( + fn: () => Promise, + overrides: Partial> +): Promise { + const currentContext = storage.getStore() + const newContext: LoggerContext = currentContext + ? { + ...currentContext, + ...overrides + } + : { + requestId: randomUUID(), + ...overrides + } + + return storage.run(newContext, fn) +} diff --git a/src/main/types/logger.types.ts b/src/main/types/logger.types.ts new file mode 100644 index 0000000..264e628 --- /dev/null +++ b/src/main/types/logger.types.ts @@ -0,0 +1,244 @@ +/** + * Enhanced Logger Type Definitions + * + * Provides comprehensive type safety for the logging system, + * including request context, performance metrics, and structured log metadata. + * + * @packageDocumentation + */ + +import type { LogLevel } from '../../shared/ipc-channels' + +/** + * Core log context interface for request tracing + * + * This type is re-exported from the logger service but defined here + * for type sharing across the application without creating circular dependencies. + */ +export interface LogContext { + /** Unique identifier for the request/operation (UUID v4) */ + requestId: string + /** User ID performing the operation (optional) */ + userId?: string + /** Operation name being performed (e.g., 'extract', 'clean', 'validate') */ + operation?: string + /** Sub-operation or step within the main operation (optional) */ + subOperation?: string + /** Batch identifier for batch operations (optional) */ + batchId?: string +} + +/** + * Enhanced log metadata for structured logging + * + * Provides rich context for log entries, enabling better + * filtering, analysis, and debugging capabilities. + */ +export interface EnhancedLogMeta { + /** Request context for correlation */ + context?: LogContext + + /** Performance metrics (if applicable) */ + performance?: PerformanceMetrics + + /** Error information (if applicable) */ + error?: { + /** Error name/type */ + name: string + /** Error message */ + message: string + /** Error code for programmatic handling */ + code?: string + /** Stack trace (in development) */ + stack?: string + /** Serialized cause chain */ + cause?: string | Record + } + + /** Database query information (if applicable) */ + database?: { + /** Database type (mysql, sqlserver) */ + type: 'mysql' | 'sqlserver' + /** Query executed (sanitized in production) */ + query?: string + /** Execution time in milliseconds */ + duration: number + /** Number of rows affected/returned */ + rowsAffected?: number + } + + /** File operation information (if applicable) */ + file?: { + /** File path (sanitized in production) */ + path: string + /** Operation type (read, write, delete, exists) */ + operation: 'read' | 'write' | 'delete' | 'exists' | 'list' + /** File size in bytes (if applicable) */ + size?: number + /** Result of the operation */ + success: boolean + } + + /** HTTP/ERP API call information (if applicable) */ + http?: { + /** HTTP method used */ + method: 'GET' | 'POST' | 'PUT' | 'DELETE' | 'PATCH' + /** URL or endpoint called */ + url: string + /** HTTP status code received */ + statusCode: number + /** Request duration in milliseconds */ + duration: number + /** Request payload size in bytes */ + requestSize?: number + /** Response payload size in bytes */ + responseSize?: number + } + + /** Custom key-value pairs for additional metadata */ + custom?: Record +} + +/** + * Performance metrics for timing and resource tracking + * + * Captures timing information for operations, enabling + * performance monitoring and bottleneck identification. + */ +export interface PerformanceMetrics { + /** Operation start timestamp (ISO 8601 format or Date) */ + startTime: Date | string + + /** Operation end timestamp (ISO 8601 format or Date) */ + endTime?: Date | string + + /** Total duration in milliseconds */ + duration: number + + /** Breakdown of time spent in different phases (optional) */ + phases?: { + /** Phase name (e.g., 'connect', 'query', 'process', 'write') */ + [phaseName: string]: { + /** Duration of this phase in milliseconds */ + duration: number + /** Additional phase-specific metadata */ + meta?: Record + } + } + + /** Memory usage snapshot (optional, Node.js specific) */ + memory?: { + /** Heap used in bytes */ + heapUsed: number + /** Heap total in bytes */ + heapTotal: number + /** RSS (Resident Set Size) in bytes */ + rss: number + /** External memory in bytes */ + external: number + } + + /** CPU usage snapshot (optional) */ + cpu?: { + /** User CPU time in milliseconds */ + user: number + /** System CPU time in milliseconds */ + system: number + } +} + +/** + * Log entry structure for structured logging + * + * Represents a complete log entry with all metadata, + * suitable for JSON serialization and log aggregation systems. + */ +export interface StructuredLogEntry { + /** Log level */ + level: LogLevel + + /** Log message */ + message: string + + /** Timestamp (ISO 8601 format) */ + timestamp: string + + /** Service/application identifier */ + service: string + + /** Module or component context */ + context?: string + + /** Environment (development, production) */ + environment?: string + + /** Enhanced metadata */ + meta?: EnhancedLogMeta + + /** Process information */ + process?: { + /** Process ID */ + pid: number + /** Process uptime in seconds */ + uptime: number + } +} + +/** + * Logger configuration interface + * + * Used for type-safe configuration of the logging system. + */ +export interface LoggerConfig { + /** Log level threshold */ + level: LogLevel + + /** Number of days to retain application logs */ + appRetention: number + + /** Enable console output (default: true) */ + console?: boolean + + /** Enable file output (default: true in production) */ + file?: boolean + + /** Maximum log file size before rotation (e.g., '20m') */ + maxSize?: string + + /** Log format ('json' | 'pretty') */ + format?: 'json' | 'pretty' +} + +/** + * Result type for logger operations + * + * Provides type-safe error handling for logger methods. + */ +export interface LoggerOperationResult { + /** Whether the operation succeeded */ + success: boolean + /** Error message if operation failed */ + error?: string + /** Additional data from the operation */ + data?: Record +} + +/** + * Log transport configuration + */ +export interface LogTransportConfig { + /** Transport type */ + type: 'console' | 'file' | 'http' + + /** Transport-specific options */ + options?: { + /** Log level for this transport */ + level?: LogLevel + /** Maximum number of files to retain (for file transport) */ + maxFiles?: string + /** Maximum file size before rotation */ + maxSize?: string + /** Compression for old logs */ + zippedArchive?: boolean + } +} diff --git a/test-output.txt b/test-output.txt new file mode 100644 index 0000000..9f542d0 --- /dev/null +++ b/test-output.txt @@ -0,0 +1,72 @@ + +> erpauto@1.8.0 test:run +> vitest run cleaner + + + RUN  v4.0.18 D:/FileLib/Projects/CodeMigration/ERPAuto + +stdout | tests/unit/cleaner-handler.test.ts +Test suite starting... + +stdout | tests/unit/cleaner-helpers.test.ts +Test suite starting... + +stdout | tests/unit/cleaner-helpers.test.ts +Test suite completed. + + 鉁?[39m tests/unit/cleaner-helpers.test.ts (3 tests) 6ms +stdout | tests/unit/cleaner-handler.test.ts +Test suite completed. + + 鉁?[39m tests/unit/cleaner-handler.test.ts (2 tests) 120ms +stdout | tests/unit/cleaner.test.ts +Test suite starting... + +stdout | tests/unit/cleaner.test.ts +Test suite completed. + + 鉁?[39m tests/unit/cleaner.test.ts (8 tests) 64ms +stdout | tests/integration/cleaner.test.ts +Test suite starting... + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Dry-run mode > should initialize with dry-run mode +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Dry-run mode > should track materials to delete without actually deleting (dry-run) +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Order processing > should process single order and return details +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Order processing > should handle order with "瀹℃壒閫氳繃" status +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Order processing > should handle multiple orders with progress callback +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Error handling > should continue processing after order error +Skipping test: ERP credentials not configured + +stderr | tests/integration/cleaner.test.ts > Cleaner Service (Integration) > Navigation > should navigate to discrete production order maintenance page +Skipping test: ERP credentials not configured + +stdout | tests/integration/cleaner.test.ts +Test suite completed. + + 鉁?[39m tests/integration/cleaner.test.ts (7 tests) 10ms +stdout | tests/manual/cleaner-slow-motion.test.ts +Test suite starting... + +stderr | tests/manual/cleaner-slow-motion.test.ts > Cleaner Slow Motion Test > should run cleaner in slow motion mode +Please set ERP_URL, ERP_USERNAME, ERP_PASSWORD in .env file + +stdout | tests/manual/cleaner-slow-motion.test.ts +Test suite completed. + + 鉁?[39m tests/manual/cleaner-slow-motion.test.ts (1 test) 5ms + + Test Files  5 passed (5) + Tests  21 passed (21) + Start at  10:36:50 + Duration  1.50s (transform 729ms, setup 228ms, import 2.41s, tests 204ms, environment 1ms) + diff --git a/tests/integration/logger-performance.test.ts b/tests/integration/logger-performance.test.ts new file mode 100644 index 0000000..48d1efa --- /dev/null +++ b/tests/integration/logger-performance.test.ts @@ -0,0 +1,381 @@ +/** + * Performance Monitor Unit Tests + * + * Tests for trackDuration helper and PerformanceTracker class + */ + +import { describe, it, expect, vi, beforeEach, afterEach, type Mock } from 'vitest' +import { + trackDuration, + PerformanceTracker, + createPerformanceTracker, + DEFAULT_SLOW_THRESHOLD_MS, + type TrackDurationOptions +} from '../../src/main/services/logger/performance-monitor' +import logger from '../../src/main/services/logger/index' + +// Mock the logger to avoid noisy output during tests +vi.mock('../../src/main/services/logger/index', () => ({ + default: { + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + child: vi.fn().mockReturnThis() + } +})) + +describe('Performance Monitor', () => { + beforeEach(() => { + vi.clearAllMocks() + }) + + afterEach(() => { + vi.clearAllMocks() + }) + + describe('trackDuration', () => { + it('should track duration of successful async operation', async () => { + const mockFn = vi.fn().mockResolvedValue('test result') + + const result = await trackDuration(mockFn, { + operationName: 'TestOperation' + }) + + expect(result.result).toBe('test result') + expect(result.durationMs).toBeGreaterThanOrEqual(0) + expect(result.isSlow).toBe(false) + expect(mockFn).toHaveBeenCalledTimes(1) + }) + + it('should mark operation as slow when exceeding threshold', async () => { + const slowFn = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50))) + + const result = await trackDuration(slowFn, { + operationName: 'SlowOperation', + slowThresholdMs: 10 + }) + + expect(result.result).toBe('slow') + expect(result.durationMs).toBeGreaterThan(10) + expect(result.isSlow).toBe(true) + }) + + it('should log with custom log level', async () => { + const mockFn = vi.fn().mockResolvedValue('result') + + await trackDuration(mockFn, { + operationName: 'CustomLevelOp', + logLevel: 'info' + }) + + expect(logger.info).toHaveBeenCalled() + expect(logger.warn).not.toHaveBeenCalled() + }) + + it('should log warning for slow operations', async () => { + const slowFn = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100))) + + await trackDuration(slowFn, { + operationName: 'SlowOp', + slowThresholdMs: 50 + }) + + expect(logger.warn).toHaveBeenCalled() + const warnCall = (logger.warn as Mock).mock.calls[0][0] + expect(warnCall).toContain('SLOW') + expect(warnCall).toContain('50ms threshold') + }) + + it('should include context in logs', async () => { + const mockFn = vi.fn().mockResolvedValue('result') + + await trackDuration(mockFn, { + operationName: 'ContextOp', + context: { userId: 123, customField: 'test' } + }) + + expect(logger.debug).toHaveBeenCalled() + const contextCall = (logger.debug as Mock).mock.calls[0][1] + expect(contextCall).toMatchObject({ + operation: 'ContextOp', + userId: 123 + }) + // Also check the custom field is included + expect(contextCall.customField).toBe('test') + }) + + it('should log error and duration when operation fails', async () => { + const errorFn = vi.fn().mockRejectedValue(new Error('Test error')) + + await expect( + trackDuration(errorFn, { + operationName: 'ErrorOp' + }) + ).rejects.toThrow('Test error') + + expect(logger.error).toHaveBeenCalled() + const errorCall = (logger.error as Mock).mock.calls[0][0] + expect(errorCall).toContain('failed after') + expect(errorCall).toContain('ErrorOp') + }) + + it('should use custom message in logs', async () => { + const mockFn = vi.fn().mockResolvedValue('result') + + await trackDuration(mockFn, { + operationName: 'TestOp', + message: 'Custom message for this operation' + }) + + expect(logger.debug).toHaveBeenCalled() + const messageCall = (logger.debug as Mock).mock.calls[0][0] + expect(messageCall).toContain('Custom message for this operation') + }) + + it('should have default threshold of 1000ms', async () => { + const slowFn = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100))) + + const result = await trackDuration(slowFn, { + operationName: 'DefaultThresholdOp' + }) + + // 100ms should NOT be slow with default 1000ms threshold + expect(result.isSlow).toBe(false) + expect(result.durationMs).toBeLessThan(1000) + }) + }) + + describe('PerformanceTracker', () => { + it('should track multiple operations', async () => { + const tracker = new PerformanceTracker('TestService', 1000) + + const mockFn1 = vi.fn().mockResolvedValue('result1') + const mockFn2 = vi.fn().mockResolvedValue('result2') + + const result1 = await tracker.track('Operation1', mockFn1) + const result2 = await tracker.track('Operation2', mockFn2) + + expect(result1).toBe('result1') + expect(result2).toBe('result2') + + const metrics = tracker.getMetrics() + expect(metrics.count).toBe(2) + expect(metrics.minDurationMs).toBeGreaterThanOrEqual(0) + expect(metrics.maxDurationMs).toBeGreaterThanOrEqual(0) + }) + + it('should calculate correct metrics', async () => { + const tracker = new PerformanceTracker('TestService', 1000) + + // Track operations with known durations + tracker.recordDuration(100) + tracker.recordDuration(200) + tracker.recordDuration(300) + + const metrics = tracker.getMetrics() + + expect(metrics.count).toBe(3) + expect(metrics.totalDurationMs).toBe(600) + expect(metrics.minDurationMs).toBe(100) + expect(metrics.maxDurationMs).toBe(300) + expect(metrics.avgDurationMs).toBe(200) + }) + + it('should track slow operations count', async () => { + const tracker = new PerformanceTracker('TestService', 50) + + tracker.recordDuration(30) // Normal + tracker.recordDuration(100) // Slow + tracker.recordDuration(40) // Normal + tracker.recordDuration(150) // Slow + + const metrics = tracker.getMetrics() + expect(metrics.slowOperationCount).toBe(2) + }) + + it('should log warnings for slow operations', async () => { + const tracker = new PerformanceTracker('TestService', 10) + + const slowFn = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50))) + + await tracker.track('SlowOp', slowFn) + + expect(logger.warn).toHaveBeenCalled() + const warnCall = (logger.warn as Mock).mock.calls[0][0] + expect(warnCall).toContain('[TestService]') + expect(warnCall).toContain('SLOW') + }) + + it('should include context in operation logs', async () => { + const tracker = new PerformanceTracker('DatabaseService', 1000) + + const mockFn = vi.fn().mockResolvedValue('data') + + await tracker.track('getUser', mockFn, { userId: 456, table: 'users' }) + + expect(logger.debug).toHaveBeenCalled() + const contextCall = (logger.debug as Mock).mock.calls[0][1] + expect(contextCall).toMatchObject({ + operation: 'getUser', + userId: 456 + }) + }) + + it('should log summary with aggregated metrics', () => { + const tracker = new PerformanceTracker('TestService', 1000) + + tracker.recordDuration(100) + tracker.recordDuration(200) + tracker.recordDuration(300) + + tracker.logSummary('info', 'Test Summary') + + expect(logger.info).toHaveBeenCalled() + const summaryCall = (logger.info as Mock).mock.calls[0] + expect(summaryCall[0]).toContain('Test Summary') + expect(summaryCall[1]).toMatchObject({ + totalOperations: 3, + slowOperations: 0 + }) + }) + + it('should include slow percentage in summary', () => { + const tracker = new PerformanceTracker('TestService', 50) + + tracker.recordDuration(30) // Normal + tracker.recordDuration(100) // Slow + + tracker.logSummary() + + expect(logger.info).toHaveBeenCalled() + const summaryCall = (logger.info as Mock).mock.calls[0][1] + expect(summaryCall.slowPercentage).toContain('%') + }) + + it('should reset metrics when reset() is called', () => { + const tracker = new PerformanceTracker('TestService', 1000) + + tracker.recordDuration(100) + tracker.recordDuration(200) + + tracker.reset() + + const metrics = tracker.getMetrics() + expect(metrics.count).toBe(0) + expect(metrics.totalDurationMs).toBe(0) + expect(metrics.slowOperationCount).toBe(0) + }) + + it('should return zero metrics when no operations tracked', () => { + const tracker = new PerformanceTracker('EmptyService') + + const metrics = tracker.getMetrics() + + expect(metrics.count).toBe(0) + expect(metrics.totalDurationMs).toBe(0) + expect(metrics.minDurationMs).toBe(0) + expect(metrics.maxDurationMs).toBe(0) + expect(metrics.avgDurationMs).toBe(0) + expect(metrics.slowOperationCount).toBe(0) + }) + + it('should use custom logger if provided', () => { + const customLogger = { + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn() + } as unknown as typeof logger + + const tracker = new PerformanceTracker('TestService', 1000, customLogger) + tracker.recordDuration(100) + + // Should use custom logger + expect(customLogger.debug).not.toHaveBeenCalled() // We called recordDuration directly + tracker.logSummary() + expect(customLogger.info).toHaveBeenCalled() + }) + }) + + describe('createPerformanceTracker', () => { + it('should create a tracker with default threshold', () => { + const tracker = createPerformanceTracker('MyService') + + expect(tracker).toBeInstanceOf(PerformanceTracker) + const metrics = tracker.getMetrics() + expect(metrics.count).toBe(0) + }) + + it('should create a tracker with custom threshold', () => { + const tracker = createPerformanceTracker('FastService', 100) + + tracker.recordDuration(150) + + const metrics = tracker.getMetrics() + expect(metrics.slowOperationCount).toBe(1) // 150 > 100 + }) + + it('should use operation name in logs', async () => { + const tracker = createPerformanceTracker('MyCustomService', 1000) + + const mockFn = vi.fn().mockResolvedValue('result') + await tracker.track('TestOperation', mockFn) + + expect(logger.debug).toHaveBeenCalled() + const call = (logger.debug as Mock).mock.calls[0][0] + expect(call).toContain('[MyCustomService]') + expect(call).toContain('TestOperation') + }) + }) + + describe('Integration scenarios', () => { + it('should track a sequence of operations with varying speeds', async () => { + const tracker = new PerformanceTracker('DataPipeline', 100) + + const fastOp = vi.fn().mockResolvedValue('fast') + const mediumOp = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('medium'), 50))) + const slowOp = vi + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 200))) + + await tracker.track('FastExtract', fastOp) + await tracker.track('MediumTransform', mediumOp) + await tracker.track('SlowLoad', slowOp) + + const metrics = tracker.getMetrics() + expect(metrics.count).toBe(3) + expect(metrics.slowOperationCount).toBe(1) // Only SlowLoad > 100ms + expect(metrics.maxDurationMs).toBeGreaterThan(150) + }) + + it('should handle errors gracefully in tracker', async () => { + const tracker = new PerformanceTracker('ErrorProneService', 1000) + + const errorFn = vi.fn().mockRejectedValue(new Error('Expected error')) + + await expect(tracker.track('FailingOp', errorFn)).rejects.toThrow('Expected error') + + expect(logger.error).toHaveBeenCalled() + const errorCall = (logger.error as Mock).mock.calls[0][0] + expect(errorCall).toContain('[ErrorProneService]') + expect(errorCall).toContain('failed after') + }) + }) + + describe('Constants', () => { + it('should export DEFAULT_SLOW_THRESHOLD_MS as 1000', () => { + expect(DEFAULT_SLOW_THRESHOLD_MS).toBe(1000) + }) + }) +}) diff --git a/tests/unit/logger-integration.test.ts b/tests/unit/logger-integration.test.ts new file mode 100644 index 0000000..15563bc --- /dev/null +++ b/tests/unit/logger-integration.test.ts @@ -0,0 +1,54 @@ +/** + * Logger Integration Tests - RequestContext Integration + * Verifies RequestContext is properly integrated with Logger + */ + +import { describe, it, expect } from 'vitest' + +describe('Logger RequestContext Integration', () => { + it('should export run from request-context', async () => { + const { run } = await import('../../src/main/services/logger/index') + expect(run).toBeDefined() + expect(typeof run).toBe('function') + }) + + it('should export getRequestId from request-context', async () => { + const { getRequestId } = await import('../../src/main/services/logger/index') + expect(getRequestId).toBeDefined() + expect(typeof getRequestId).toBe('function') + }) + + it('should export getContext from request-context', async () => { + const { getContext } = await import('../../src/main/services/logger/index') + expect(getContext).toBeDefined() + expect(typeof getContext).toBe('function') + }) + + it('should export withContext from request-context', async () => { + const { withContext } = await import('../../src/main/services/logger/index') + expect(withContext).toBeDefined() + expect(typeof withContext).toBe('function') + }) + + it('should export withRequestContext wrapper', async () => { + const { withRequestContext } = await import('../../src/main/services/logger/index') + expect(withRequestContext).toBeDefined() + expect(typeof withRequestContext).toBe('function') + }) + + it('should export createLogger', async () => { + const { createLogger } = await import('../../src/main/services/logger/index') + expect(createLogger).toBeDefined() + expect(typeof createLogger).toBe('function') + }) + + it('should have all exports available from LoggerContext type', async () => { + const loggerModule = await import('../../src/main/services/logger/index') + expect(loggerModule.run).toBeDefined() + expect(loggerModule.getRequestId).toBeDefined() + expect(loggerModule.getContext).toBeDefined() + expect(loggerModule.withContext).toBeDefined() + expect(loggerModule.withRequestContext).toBeDefined() + expect(loggerModule.createLogger).toBeDefined() + }) +}) diff --git a/tests/unit/logger.test.ts b/tests/unit/logger.test.ts index 903942f..0d0dc21 100644 --- a/tests/unit/logger.test.ts +++ b/tests/unit/logger.test.ts @@ -48,34 +48,43 @@ vi.mock('winston', () => { }) } + const formatFn = vi.fn((fn: any) => fn && fn()) as any + formatFn.combine = vi.fn((...args) => args) + formatFn.timestamp = vi.fn(() => ({ type: 'timestamp' })) + formatFn.colorize = vi.fn(() => ({ type: 'colorize' })) + formatFn.printf = vi.fn((fn: any) => fn) + formatFn.json = vi.fn(() => ({ type: 'json' })) + return { default: { createLogger: vi.fn(() => createLoggerInstance), - format: { - combine: vi.fn((...args) => args), - timestamp: vi.fn(() => ({ type: 'timestamp' })), - colorize: vi.fn(() => ({ type: 'colorize' })), - printf: vi.fn((fn) => fn), - json: vi.fn(() => ({ type: 'json' })) - }, + format: formatFn, transports: { - Console: vi.fn() + Console: vi.fn() as any, + DailyRotateFile: vi.fn() as any } } } }) vi.mock('winston-daily-rotate-file', () => ({ - default: vi.fn() + default: vi.fn() as any })) -vi.mock('electron', () => ({ - app: { - isReady: vi.fn(() => false), - getPath: vi.fn(() => './logs'), - isPackaged: false - } -})) +vi.mock( + 'electron', + () => + ({ + BrowserWindow: { + getAllWindows: vi.fn(() => []) + }, + app: { + isReady: vi.fn(() => false), + getPath: vi.fn(() => './logs'), + isPackaged: false + } + }) as any +) describe('Logger', () => { beforeEach(() => { diff --git a/tests/unit/request-context.test.ts b/tests/unit/request-context.test.ts new file mode 100644 index 0000000..ea1e355 --- /dev/null +++ b/tests/unit/request-context.test.ts @@ -0,0 +1,432 @@ +/** + * RequestContext Unit Tests + * + * Tests for AsyncLocalStorage-based request context management: + * - Context propagation across async/await + * - Concurrent request isolation + * - Nested contexts + * - Non-request scenarios + * - userId and operation fields + */ + +import { describe, it, expect, beforeEach, afterEach } from 'vitest' +import { + run, + getRequestId, + getContext, + withContext, + LoggerContext +} from '../../src/main/services/logger/request-context' + +describe('RequestContext', () => { + beforeEach(() => { + // Clear any existing context before each test + }) + + afterEach(() => { + // Context is automatically cleaned up when async scope exits + }) + + describe('run()', () => { + it('should create context with auto-generated requestId', async () => { + let capturedRequestId: string | undefined + + await run(async () => { + capturedRequestId = getRequestId() + }) + + expect(capturedRequestId).toBeDefined() + expect(typeof capturedRequestId).toBe('string') + // UUID v4 format check (basic) + expect(capturedRequestId).toMatch( + /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i + ) + }) + + it('should include userId when provided', async () => { + let context: LoggerContext | undefined + + await run( + async () => { + context = getContext() + }, + { userId: 'user-123' } + ) + + expect(context).toBeDefined() + expect(context?.userId).toBe('user-123') + expect(context?.requestId).toBeDefined() + }) + + it('should include operation when provided', async () => { + let context: LoggerContext | undefined + + await run( + async () => { + context = getContext() + }, + { operation: 'extract' } + ) + + expect(context).toBeDefined() + expect(context?.operation).toBe('extract') + expect(context?.requestId).toBeDefined() + }) + + it('should include both userId and operation when provided', async () => { + let context: LoggerContext | undefined + + await run( + async () => { + context = getContext() + }, + { userId: 'user-456', operation: 'clean' } + ) + + expect(context).toBeDefined() + expect(context?.userId).toBe('user-456') + expect(context?.operation).toBe('clean') + expect(context?.requestId).toBeDefined() + }) + + it('should work without optional context', async () => { + let context: LoggerContext | undefined + + await run(async () => { + context = getContext() + }) + + expect(context).toBeDefined() + expect(context?.requestId).toBeDefined() + expect(context?.userId).toBeUndefined() + expect(context?.operation).toBeUndefined() + }) + }) + + describe('Context Propagation', () => { + it('should propagate context across async/await', async () => { + const requestIds: (string | undefined)[] = [] + + async function nestedOperation() { + requestIds.push(getRequestId()) + await Promise.resolve() // Simulate async operation + requestIds.push(getRequestId()) + } + + await run(async () => { + requestIds.push(getRequestId()) + await nestedOperation() + requestIds.push(getRequestId()) + }) + + // All should have the same requestId + expect(requestIds).toHaveLength(4) + expect(new Set(requestIds).size).toBe(1) + expect(requestIds[0]).toBeDefined() + }) + + it('should propagate context through Promise.all', async () => { + const requestIds: (string | undefined)[] = [] + + await run(async () => { + const outerId = getRequestId() + requestIds.push(outerId) + + await Promise.all([ + (async () => { + requestIds.push(getRequestId()) + await Promise.resolve() + requestIds.push(getRequestId()) + })(), + (async () => { + requestIds.push(getRequestId()) + await Promise.resolve() + requestIds.push(getRequestId()) + })() + ]) + + requestIds.push(getRequestId()) + }) + + // All should have the same requestId (6 total: 1 outer + 2 from each parallel + 1 final) + expect(requestIds).toHaveLength(6) + expect(new Set(requestIds).size).toBe(1) + }) + }) + + describe('Concurrent Request Isolation', () => { + it('should maintain separate contexts for concurrent requests', async () => { + const request1Ids: (string | undefined)[] = [] + const request2Ids: (string | undefined)[] = [] + + const promise1 = run( + async () => { + request1Ids.push(getRequestId()) + await new Promise((resolve) => setTimeout(resolve, 10)) + request1Ids.push(getRequestId()) + }, + { userId: 'user-1', operation: 'extract' } + ) + + const promise2 = run( + async () => { + request2Ids.push(getRequestId()) + await new Promise((resolve) => setTimeout(resolve, 5)) + request2Ids.push(getRequestId()) + }, + { userId: 'user-2', operation: 'clean' } + ) + + await Promise.all([promise1, promise2]) + + // Each request should have consistent internal context + expect(request1Ids).toHaveLength(2) + expect(request2Ids).toHaveLength(2) + + // promise1 should be consistent + expect(request1Ids[0]).toBe(request1Ids[1]) + // promise2 should be consistent + expect(request2Ids[0]).toBe(request2Ids[1]) + // Different requests should have different requestIds + expect(request1Ids[0]).not.toBe(request2Ids[0]) + }) + + it('should not leak context between sequential requests', async () => { + let firstRequestId: string | undefined + let secondRequestId: string | undefined + + // First request + await run( + async () => { + firstRequestId = getRequestId() + }, + { userId: 'first-user' } + ) + + // Second request (should have new context) + await run( + async () => { + secondRequestId = getRequestId() + }, + { userId: 'second-user' } + ) + + expect(firstRequestId).toBeDefined() + expect(secondRequestId).toBeDefined() + expect(firstRequestId).not.toBe(secondRequestId) + + // Outside any context, should be undefined + expect(getRequestId()).toBeUndefined() + }) + }) + + describe('Nested Contexts', () => { + it('should support nesting without affecting outer context', async () => { + const requestIds: { outer: string | undefined; inner: string | undefined } = { + outer: undefined, + inner: undefined + } + + await run( + async () => { + requestIds.outer = getRequestId() + + await run(async () => { + requestIds.inner = getRequestId() + }) + + // Outer context should be unchanged after nesting + expect(getRequestId()).toBe(requestIds.outer) + }, + { operation: 'outer' } + ) + + // Both should be defined but different + expect(requestIds.outer).toBeDefined() + expect(requestIds.inner).toBeDefined() + expect(requestIds.outer).not.toBe(requestIds.inner) + }) + + it('should restore outer context after nested context exits', async () => { + const capturedIds: (string | undefined)[] = [] + + await run(async () => { + capturedIds.push(getRequestId()) + + await run(async () => { + capturedIds.push(getRequestId()) + }) + + capturedIds.push(getRequestId()) + }) + + expect(capturedIds).toHaveLength(3) + expect(capturedIds[0]).toBe(capturedIds[2]) // Before and after should match + expect(capturedIds[0]).not.toBe(capturedIds[1]) // Inner should be different + }) + }) + + describe('Non-Request Scenarios', () => { + it('should return undefined requestId outside context', async () => { + const requestId = getRequestId() + expect(requestId).toBeUndefined() + }) + + it('should return undefined context outside context', async () => { + const context = getContext() + expect(context).toBeUndefined() + }) + + it('should work normally without RequestContext wrapper', async () => { + // This simulates existing code that doesn't use request context + expect(getRequestId()).toBeUndefined() + + const result = await Promise.resolve('test') + expect(result).toBe('test') + + // Still undefined after regular async operation + expect(getRequestId()).toBeUndefined() + }) + }) + + describe('withContext()', () => { + it('should override operation in nested context', async () => { + const operations: (string | undefined)[] = [] + + await run( + async () => { + operations.push(getContext()?.operation) + + await withContext( + async () => { + operations.push(getContext()?.operation) + }, + { operation: 'inner-operation' } + ) + + operations.push(getContext()?.operation) + }, + { operation: 'outer-operation' } + ) + + expect(operations).toHaveLength(3) + expect(operations[0]).toBe('outer-operation') + expect(operations[1]).toBe('inner-operation') + expect(operations[2]).toBe('outer-operation') + }) + + it('should override userId in nested context', async () => { + const userIds: (string | undefined)[] = [] + + await run( + async () => { + userIds.push(getContext()?.userId) + + await withContext( + async () => { + userIds.push(getContext()?.userId) + }, + { userId: 'inner-user' } + ) + + userIds.push(getContext()?.userId) + }, + { userId: 'outer-user' } + ) + + expect(userIds).toHaveLength(3) + expect(userIds[0]).toBe('outer-user') + expect(userIds[1]).toBe('inner-user') + expect(userIds[2]).toBe('outer-user') + }) + + it('should create new requestId if no outer context exists', async () => { + let requestIdInWith: string | undefined + + await withContext( + async () => { + requestIdInWith = getRequestId() + }, + { operation: 'standalone' } + ) + + expect(requestIdInWith).toBeDefined() + expect(getContext()).toBeUndefined() // Back to undefined after exiting + }) + + it('should preserve requestId when overriding other fields', async () => { + const requestIds: (string | undefined)[] = [] + + await run( + async () => { + requestIds.push(getRequestId()) + + await withContext( + async () => { + requestIds.push(getRequestId()) + }, + { operation: 'new-operation' } + ) + + requestIds.push(getRequestId()) + }, + { userId: 'test-user' } + ) + + // requestId should remain the same across all scopes + expect(requestIds).toHaveLength(3) + expect(new Set(requestIds).size).toBe(1) + }) + }) + + describe('Edge Cases', () => { + it('should handle errors within context gracefully', async () => { + let caughtRequestId: string | undefined + + try { + await run(async () => { + throw new Error('Test error') + }) + } catch (error) { + // Error caught, context should be cleaned up + caughtRequestId = getRequestId() + } + + expect(caughtRequestId).toBeUndefined() + }) + + it('should handle context in try-catch-finally', async () => { + const tryId: string | undefined = undefined + const finallyId: string | undefined = undefined + + await run(async () => { + try { + const id = getRequestId() + expect(id).toBeDefined() + throw new Error('Test') + } catch { + const id = getRequestId() + expect(id).toBeDefined() + } finally { + const id = getRequestId() + expect(id).toBeDefined() + } + }) + }) + + it('should handle empty string userId and operation', async () => { + let context: LoggerContext | undefined + + await run( + async () => { + context = getContext() + }, + { userId: '', operation: '' } + ) + + expect(context?.userId).toBe('') + expect(context?.operation).toBe('') + expect(context?.requestId).toBeDefined() + }) + }) +}) diff --git a/tests/unit/services/logger/error-utils.test.ts b/tests/unit/services/logger/error-utils.test.ts new file mode 100644 index 0000000..8222193 --- /dev/null +++ b/tests/unit/services/logger/error-utils.test.ts @@ -0,0 +1,561 @@ +/** + * Tests for Enhanced Error Logging Utilities + * + * Validates error serialization, formatting, and enhanced context support. + */ + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest' +import type { SerializedError } from '../../../../src/main/types/errors' +import { + isError, + serializeError, + sanitizeError, + extractErrorContext, + formatErrorForLogging, + logError, + enhancedLogError, + throwAfterLogging +} from '../../../../src/main/services/logger/error-utils' +import { run, getRequestId } from '../../../../src/main/services/logger/request-context' + +// Mock logger for testing +function createMockLogger() { + return { + error: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + debug: vi.fn() + } +} + +// Custom Error class for testing +class CustomError extends Error { + code: string + details?: Record + + constructor(message: string, code: string, details?: Record) { + super(message) + this.name = 'CustomError' + this.code = code + this.details = details + } +} + +describe('error-utils', () => { + describe('isError', () => { + it('should return true for Error instances', () => { + expect(isError(new Error('test'))).toBe(true) + expect(isError(new TypeError('test'))).toBe(true) + expect(isError(new CustomError('test', 'CODE'))).toBe(true) + }) + + it('should return true for Error-like objects', () => { + expect(isError({ name: 'Error', message: 'test' })).toBe(true) + expect(isError({ name: 'CustomError', message: 'test error' })).toBe(true) + }) + + it('should return false for non-error values', () => { + expect(isError('string')).toBe(false) + expect(isError(123)).toBe(false) + expect(isError(null)).toBe(false) + expect(isError(undefined)).toBe(false) + expect(isError({})).toBe(false) + expect(isError({ message: 'no name' })).toBe(false) + }) + }) + + describe('serializeError', () => { + it('should serialize standard Error with all properties', () => { + const error = new Error('Test error message') + const serialized = serializeError(error) + + expect(serialized).toEqual({ + name: 'Error', + message: 'Test error message', + stack: expect.any(String), + cause: undefined + }) + expect(serialized.stack).toContain('error-utils.test.ts') + }) + + it('should serialize custom Error with additional properties', () => { + const error = new CustomError('Custom error', 'CUSTOM_CODE', { userId: '123' }) + const serialized = serializeError(error) + + expect(serialized).toEqual({ + name: 'CustomError', + message: 'Custom error', + stack: expect.any(String), + cause: undefined, + code: 'CUSTOM_CODE', + details: { userId: '123' } + }) + }) + + it('should serialize error with cause', () => { + const cause = new Error('Root cause') + const error = new Error('Wrapped error') + ;(error as any).cause = cause + const serialized = serializeError(error) + + expect(serialized.cause).toEqual({ + name: 'Error', + message: 'Root cause', + stack: expect.any(String) + }) + }) + + it('should serialize Error-like objects', () => { + const errorLike = { name: 'APIError', message: 'API failed' } + const serialized = serializeError(errorLike) + + expect(serialized).toEqual({ + name: 'APIError', + message: 'API failed', + stack: undefined, + cause: undefined + }) + }) + + it('should serialize non-error values', () => { + const serialized1 = serializeError('String error' as any) + expect(serialized1).toEqual({ + name: 'UnknownError', + message: 'String error' + }) + + const serialized2 = serializeError({ code: 500 }) + expect(serialized2).toEqual({ + name: 'UnknownError', + message: '{"code":500}' + }) + }) + }) + + describe('sanitizeError', () => { + it('should sanitize sensitive fields in error message in production', () => { + const error: SerializedError = { + name: 'AuthError', + message: 'Invalid password provided', + stack: undefined + } + + // Note: sanitizeError uses isProduction() from shared module + // In test environment, NODE_ENV='test' which is not production + // So this test verifies the message is kept in tests/non-prod + const sanitized = sanitizeError(error) + + expect(sanitized.message).toBe('Invalid password provided') + expect(sanitized.name).toBe('AuthError') + }) + + it('should sanitize sensitive custom properties', () => { + const error: SerializedError = { + name: 'ConfigError', + message: 'Config failed', + apiKey: 'secret-key-123', + token: 'bearer-token' + } + + const sanitized = sanitizeError(error) + + // sanitizeError only sanitizes properties that contain sensitive key names + // It checks message content and property keys, but only for specific patterns + expect(sanitized.message).toBe('Config failed') + expect(sanitized.name).toBe('ConfigError') + // Note: apiKey and token are NOT sanitized by default - only 'password', 'secret', etc. + // The sanitization is based on key name matching, not automatic for all custom props + }) + + it('should sanitize custom properties by key name pattern', () => { + const error: SerializedError = { + name: 'ConfigError', + message: 'Config failed', + password: 'secret123', + secretKey: 'my-secret' + } + + const sanitized = sanitizeError(error) + + expect(sanitized.password).toBe('[REDACTED]') + expect(sanitized.secretKey).toBe('[REDACTED]') + }) + + it('should recursively sanitize cause', () => { + const error: SerializedError = { + name: 'ChainError', + message: 'Error chain', + cause: { + name: 'AuthError', + message: 'Invalid password', + password: 'secret123' + } as any + } + + const sanitized = sanitizeError(error) + + expect((sanitized.cause as any).password).toBe('[REDACTED]') + }) + }) + + describe('extractErrorContext', () => { + it('should extract file, line, column from stack trace', () => { + const error = new Error('Test') + const serialized = serializeError(error) + const context = extractErrorContext(serialized) + + expect(context.fileName).toBeDefined() + expect(context.lineNumber).toBeDefined() + expect(context.columnName).toBeDefined() + expect(context.fileName).toContain('error-utils.test.ts') + }) + + it('should return empty object when no stack trace', () => { + const serialized: SerializedError = { + name: 'Error', + message: 'Test', + stack: undefined + } + + const context = extractErrorContext(serialized) + expect(context).toEqual({}) + }) + }) + + describe('formatErrorForLogging', () => { + it('should format error with basic metadata', () => { + const error = new Error('Basic error') + const { message, metadata } = formatErrorForLogging(error) + + expect(message).toBe('[Error] Basic error') + expect(metadata.error).toBeDefined() + expect((metadata.error as SerializedError).name).toBe('Error') + }) + + it('should include context fields in metadata', () => { + const error = new Error('Context error') + const { metadata } = formatErrorForLogging(error, { + operation: 'extract', + userId: 'user123', + batchId: 'batch-001' + }) + + expect(metadata.operation).toBe('extract') + expect(metadata.userId).toBe('user123') + expect(metadata.batchId).toBe('batch-001') + }) + + it('should auto-inject requestId from async context', async () => { + await run( + async () => { + const requestId = getRequestId() + expect(requestId).toBeDefined() + + const error = new Error('Contextual error') + const { metadata } = formatErrorForLogging(error, { + operation: 'validate' + }) + + expect(metadata.requestId).toBe(requestId) + }, + { operation: 'validate' } + ) + }) + + it('should use explicit requestId if provided', async () => { + await run( + async () => { + const error = new Error('Test error') + const { metadata } = formatErrorForLogging(error, { + requestId: 'explicit-request-id', + operation: 'test' + }) + + expect(metadata.requestId).toBe('explicit-request-id') + }, + { operation: 'test' } + ) + }) + + it('should include duration when provided', () => { + const error = new Error('Slow operation') + const { metadata } = formatErrorForLogging(error, { + operation: 'extract', + duration: 2500 + }) + + expect(metadata.duration).toBe(2500) + }) + + it('should include orderNumbers and materialCodes when provided', () => { + const error = new Error('Processing error') + const { metadata } = formatErrorForLogging(error, { + operation: 'clean', + orderNumbers: ['ORD-001', 'ORD-002'], + materialCodes: ['MAT-100', 'MAT-101'] + }) + + expect(metadata.orderNumbers).toEqual(['ORD-001', 'ORD-002']) + expect(metadata.materialCodes).toEqual(['MAT-100', 'MAT-101']) + }) + + it('should handle environment-specific formatting', () => { + const error = new Error('Environment test') + const { metadata } = formatErrorForLogging(error) + + if (process.env.NODE_ENV === 'production') { + expect(metadata.environment).toBeUndefined() + } else { + expect(metadata.environment).toEqual({ + NODE_ENV: expect.any(String), + platform: expect.any(String), + nodeVersion: expect.any(String) + }) + } + }) + + it('should remove undefined fields from metadata', () => { + const error = new Error('Test') + const { metadata } = formatErrorForLogging(error, { + operation: 'test', + batchId: undefined as any + }) + + expect(metadata.batchId).toBeUndefined() + expect(metadata.operation).toBe('test') + }) + }) + + describe('logError', () => { + let logger: ReturnType + + beforeEach(() => { + logger = createMockLogger() + }) + + afterEach(() => { + vi.clearAllMocks() + }) + + it('should log error with message and metadata', () => { + const error = new Error('Log test') + logError(logger, error, { + message: 'Custom message', + operation: 'test' + }) + + expect(logger.error).toHaveBeenCalledWith( + 'Custom message', + expect.objectContaining({ + error: expect.any(Object), + operation: 'test' + }) + ) + }) + + it('should use error message if no custom message provided', () => { + const error = new Error('Auto message') + logError(logger, error, { operation: 'test' }) + + expect(logger.error).toHaveBeenCalledWith( + expect.stringContaining('[Error] Auto message'), + expect.any(Object) + ) + }) + + it('should log with all enhanced context fields', () => { + const error = new Error('Full context error') + logError(logger, error, { + operation: 'extract', + userId: 'user789', + batchId: 'batch-999', + duration: 3500, + module: 'ExtractorService' + }) + + const callArgs = logger.error.mock.calls[0] + expect(callArgs[1]).toEqual( + expect.objectContaining({ + operation: 'extract', + userId: 'user789', + batchId: 'batch-999', + duration: 3500, + module: 'ExtractorService' + }) + ) + }) + + it('should auto-inject requestId from context', async () => { + await run( + async () => { + const requestId = getRequestId() + expect(requestId).toBeDefined() + + const error = new Error('Contextual log') + const { metadata } = formatErrorForLogging(error, { operation: 'test' }) + + // The requestId should be auto-injected from async context + expect(metadata.requestId).toBe(requestId) + }, + { operation: 'test' } + ) + }) + }) + + describe('enhancedLogError', () => { + let logger: ReturnType + + beforeEach(() => { + logger = createMockLogger() + }) + + afterEach(() => { + vi.clearAllMocks() + }) + + it('should log error with required operation field', () => { + const error = new Error('Enhanced error') + enhancedLogError(logger, error, { + operation: 'validate' + }) + + expect(logger.error).toHaveBeenCalledWith( + expect.any(String), + expect.objectContaining({ + operation: 'validate' + }) + ) + }) + + it('should log with userId and batchId', () => { + const error = new Error('Batch error') + enhancedLogError(logger, error, { + operation: 'extract', + userId: 'user-enhanced', + batchId: 'batch-enhanced' + }) + + const callArgs = logger.error.mock.calls[0] + expect(callArgs[1]).toEqual( + expect.objectContaining({ + operation: 'extract', + userId: 'user-enhanced', + batchId: 'batch-enhanced' + }) + ) + }) + + it('should log with duration (performance metric)', () => { + const error = new Error('Slow error') + enhancedLogError(logger, error, { + operation: 'clean', + duration: 5000 + }) + + expect(logger.error).toHaveBeenCalledWith( + expect.any(String), + expect.objectContaining({ + operation: 'clean', + duration: 5000 + }) + ) + }) + + it('should log with orderNumbers and materialCodes', () => { + const error = new Error('Order error') + enhancedLogError(logger, error, { + operation: 'process', + orderNumbers: ['ORD-ENH-001'], + materialCodes: ['MAT-ENH-100'] + }) + + const callArgs = logger.error.mock.calls[0] + expect(callArgs[1]).toEqual( + expect.objectContaining({ + operation: 'process', + orderNumbers: ['ORD-ENH-001'], + materialCodes: ['MAT-ENH-100'] + }) + ) + }) + + it('should accept custom message', () => { + const error = new Error('Original message') + enhancedLogError( + logger, + error, + { + operation: 'test' + }, + 'Custom enhanced message' + ) + + expect(logger.error).toHaveBeenCalledWith('Custom enhanced message', expect.any(Object)) + }) + + it('should auto-inject requestId from async context', async () => { + await run( + async () => { + const requestId = getRequestId() + expect(requestId).toBeDefined() + + const error = new Error('Auto-inject test') + const { metadata } = formatErrorForLogging(error, { operation: 'auto-test' }) + + expect(metadata.requestId).toBe(requestId) + }, + { operation: 'auto-test' } + ) + }) + }) + + describe('throwAfterLogging', () => { + it('should log error and re-throw', () => { + const logger = createMockLogger() + const error = new Error('Re-throw test') + + expect(() => { + throwAfterLogging(logger, error, { + operation: 'throw-test' + }) + }).toThrow('Re-throw test') + + expect(logger.error).toHaveBeenCalled() + }) + }) + + describe('Backward Compatibility', () => { + it('should work without context parameter', () => { + const error = new Error('No context') + const { message, metadata } = formatErrorForLogging(error) + + expect(message).toBe('[Error] No context') + expect(metadata.error).toBeDefined() + }) + + it('should work with minimal context', () => { + const error = new Error('Minimal context') + const logger = createMockLogger() + logError(logger, error, { userId: 'minimal-user' }) + + expect(logger.error).toHaveBeenCalledWith( + expect.any(String), + expect.objectContaining({ + userId: 'minimal-user' + }) + ) + }) + + it('should not break existing error logging patterns', () => { + const error = new Error('Old pattern') + const { message, metadata } = formatErrorForLogging(error, { + operation: 'legacy', + module: 'LegacyModule' + }) + + expect(message).toContain('[Error] Old pattern') + expect(metadata.operation).toBe('legacy') + expect(metadata.module).toBe('LegacyModule') + }) + }) +})