From 4f3af2e9c3aef47b5a5b09ae918f2ceb92e998f1 Mon Sep 17 00:00:00 2001 From: Misaka Date: Sat, 4 Apr 2026 18:09:50 +0800 Subject: [PATCH] feat(logging): enhance CleanerService logging granularity for better debugging - Add detailed step-by-step logging in navigation phase with elapsed time tracking - Enhance query interface setup with individual step logging and timing - Improve order query and result collection with validation logging - Add comprehensive processDetailPage logging with 8 tracked steps - Detail material processing loop with decision tracking (delete/skip reasons) - Enhance retry mechanism with per-attempt logging and success rate tracking - Add performance monitoring with slow operation detection (isSlow flags) - All logs use consistent Chinese labeling with [Phase] prefix format Total: +437 lines of logging instrumentation across cleaner.ts --- src/main/services/erp/cleaner.ts | 477 +++++++++++++++++++-- src/main/services/rustfs/rustfs-service.ts | 2 +- src/main/services/update/update-service.ts | 2 +- 3 files changed, 440 insertions(+), 41 deletions(-) diff --git a/src/main/services/erp/cleaner.ts b/src/main/services/erp/cleaner.ts index bb293be..3c00700 100644 --- a/src/main/services/erp/cleaner.ts +++ b/src/main/services/erp/cleaner.ts @@ -387,66 +387,172 @@ export class CleanerService { session: ErpSession ): Promise<{ popupPage: Page; workFrame: FrameLocator }> { const { page, mainFrame } = session + const navStartTime = Date.now() + log.info('开始导航到清理页面', { + sessionAvailable: !!session, + hasPage: !!page, + hasMainFrame: !!mainFrame + }) + + // Step 1: Click menu icon + log.debug('[导航 Step 1] 准备点击菜单图标') await mainFrame.locator('i').first().click() - log.debug('导航: 已点击菜单图标') + log.debug('[导航 Step 1 完成] 菜单图标已点击', { elapsedMs: Date.now() - navStartTime }) + // Step 2: Wait for popup and click menu item + log.debug('[导航 Step 2] 等待弹出窗口并点击菜单项') const popupPromise = page.waitForEvent('popup') await mainFrame.getByTitle('离散生产订单维护', { exact: true }).first().click() const popupPage = await popupPromise - log.debug('导航: 弹出窗口已打开') + log.debug('[导航 Step 2 完成] 弹出窗口已打开', { + elapsedMs: Date.now() - navStartTime, + popupOpened: !!popupPage + }) + // Step 3: Get forward frame + log.debug('[导航 Step 3] 获取 forwardFrame 框架') const forwardFrameLocator = popupPage.locator('#forwardFrame') const fFrame = forwardFrameLocator.contentFrame() - log.debug('导航: 已获取 forwardFrame') + log.debug('[导航 Step 3 完成] forwardFrame 已获取', { + elapsedMs: Date.now() - navStartTime, + frameExists: !!fFrame + }) + if (!fFrame) { + log.error('[导航失败] forwardFrame 为空', { + elapsedMs: Date.now() - navStartTime, + pageUrl: popupPage.url(), + contextData: await capturePageContext(popupPage, undefined, 'nav.forwardFrame') + }) + throw new Error('无法访问弹出窗口的 forwardFrame') + } + + // Step 4: Get inner work frame + log.debug('[导航 Step 4] 等待并获取 mainiframe 内部框架', { timeout: 30000 }) const innerFrameLocator = fFrame.locator('#mainiframe') await innerFrameLocator.waitFor({ state: 'visible', timeout: 30000 }) const workFrame = innerFrameLocator.contentFrame() - log.debug('导航: 已获取内部工作框架') + log.debug('[导航 Step 4 完成] 内部工作框架已获取', { + elapsedMs: Date.now() - navStartTime, + frameExists: !!workFrame + }) + if (!workFrame) { + log.error('[导航失败] workFrame 为空', { + elapsedMs: Date.now() - navStartTime, + pageUrl: popupPage.url(), + contextData: await capturePageContext(popupPage, undefined, 'nav.workFrame') + }) + throw new Error('无法访问内部工作框架') + } + + // Step 5: Wait for page ready + log.debug('[导航 Step 5] 等待页面就绪标志', { selector: '#hot-key-head_list', timeout: 30000 }) await workFrame.locator('#hot-key-head_list').waitFor({ state: 'visible', timeout: 30000 }) - log.info('已导航到清理页面') + const totalNavTime = Date.now() - navStartTime + log.info('[导航完成] 已导航到清理页面', { + totalNavTimeMs: totalNavTime, + isSlow: totalNavTime > 5000 + }) return { popupPage, workFrame } } private async setupQueryInterface(innerFrame: FrameLocator): Promise { - await innerFrame.locator('.search-name-wrapper > .iconfont').click() - log.debug('查询界面: 已点击搜索图标') - await innerFrame.getByText('订单号查询').click() - log.debug('查询界面: 已点击订单号查询') - await innerFrame.getByRole('tab', { name: '全部' }).click() - log.debug('查询界面: 已切换到全部标签页') + const setupStartTime = Date.now() + log.debug('[查询界面设置开始] 准备配置查询界面') + // Step 1: Click search icon + log.debug('[查询设置 Step 1] 点击搜索图标') + await innerFrame.locator('.search-name-wrapper > .iconfont').click() + log.debug('[查询设置 Step 1 完成] 搜索图标已点击', { elapsedMs: Date.now() - setupStartTime }) + + // Step 2: Select order number query mode + log.debug('[查询设置 Step 2] 选择订单号查询模式') + await innerFrame.getByText('订单号查询').click() + log.debug('[查询设置 Step 2 完成] 已切换到订单号查询', { + elapsedMs: Date.now() - setupStartTime + }) + + // Step 3: Switch to "All" tab + log.debug('[查询设置 Step 3] 切换到全部标签页') + await innerFrame.getByRole('tab', { name: '全部' }).click() + log.debug('[查询设置 Step 3 完成] 已全部标签页激活', { elapsedMs: Date.now() - setupStartTime }) + + // Step 4: Set query limit to 5000 + log.debug('[查询设置 Step 4] 设置查询数量限制为 5000') const inputEl = innerFrame.locator('#rc_select_0') await inputEl.fill('5000') await inputEl.press('Enter') - log.debug('查询界面: 已设置查询限制为5000') + const totalSetupTime = Date.now() - setupStartTime + log.debug('[查询设置完成] 查询界面配置完毕', { + totalSetupTimeMs: totalSetupTime, + queryLimit: 5000, + isSlow: totalSetupTime > 2000 + }) } private async queryOrders(workFrame: FrameLocator, orderNumbers: string[]): Promise { - log.debug('开始查询订单', { orderCount: orderNumbers.length }) + const queryStartTime = Date.now() + log.debug('[订单查询开始]', { + orderCount: orderNumbers.length, + orderNumbers: orderNumbers + .slice(0, 5) + .concat(orderNumbers.length > 5 ? [`... (${orderNumbers.length - 5} more)`] : []), + isPreview: orderNumbers.length > 5 + }) + const textbox = workFrame.getByRole('textbox', { name: '生产订单号' }) + log.debug('[订单查询] 准备填入订单号') await textbox.fill(orderNumbers.join(',')) + log.debug('[订单查询] 订单号已填入', { + elapsedMs: Date.now() - queryStartTime, + charCount: orderNumbers.join(',').length + }) + + log.debug('[订单查询] 点击搜索按钮') await workFrame.locator('.search-component-searchBtn').click() + log.info('[订单查询完成] 查询请求已发送', { + elapsedMs: Date.now() - queryStartTime, + orderCount: orderNumbers.length + }) } private async collectQueryResultRows(workFrame: FrameLocator): Promise { + const collectStartTime = Date.now() + log.debug('[查询结果收集开始] 准备读取查询结果表格') + const rows = workFrame.locator('tbody tr') const rowCount = await rows.count() + log.debug('[查询结果收集] 检测到表格行数', { rowCount }) + const result: QueryResultRow[] = [] + let validOrderCount = 0 + let invalidOrderCount = 0 for (let rowIndex = 0; rowIndex < rowCount; rowIndex++) { const row = rows.nth(rowIndex) const orderNumber = await this.extractOrderNumberFromQueryRow(row) if (!this.isOrderNumber(orderNumber)) { + invalidOrderCount++ + if (invalidOrderCount <= 3) { + log.warn('[查询结果] 跳过无效订单号行', { rowIndex, extractedValue: orderNumber }) + } continue } + validOrderCount++ result.push({ rowIndex, orderNumber }) } - log.debug('查询结果收集完成', { rowCount: result.length }) + const totalCollectTime = Date.now() - collectStartTime + log.info('[查询结果收集完成]', { + totalRowsScanned: rowCount, + validOrderCount, + invalidOrderCount, + elapsedMs: totalCollectTime, + isSlow: totalCollectTime > 3000 + }) return result } @@ -455,12 +561,31 @@ export class CleanerService { try { const cell = row.locator('td[colkey="vbillcode"]') const codeLink = cell.locator('.code-detail-link').first() - const rawValue = - (await codeLink.count()) > 0 ? await codeLink.innerText() : await cell.innerText() + const linkCount = await codeLink.count() + + log.verbose('[提取订单号] 尝试从行提取订单号', { + hasLink: linkCount > 0, + extractionMethod: linkCount > 0 ? 'link' : 'cellText' + }) + + const rawValue = linkCount > 0 ? await codeLink.innerText() : await cell.innerText() const value = rawValue.trim() const match = value.match(/SC\d{14}/) - return match ? match[0] : value - } catch { + const extracted = match ? match[0] : value + + log.verbose('[提取订单号完成]', { + rawValue, + extracted, + matched: !!match + }) + + return extracted + } catch (error) { + const message = error instanceof Error ? error.message : 'Unknown error' + log.warn('[提取订单号失败] 提取过程发生错误', { + error: message, + fallback: 'empty string' + }) return '' } } @@ -538,35 +663,79 @@ export class CleanerService { ) => void }): Promise { const { detailPage, deleteSet, dryRun, progressState, expectedOrderNumber, onProgress } = params + const processStartTime = Date.now() + + log.info('[订单详情处理开始]', { + expectedOrderNumber, + dryRun, + deleteSetSize: deleteSet.size, + completedOrders: progressState.completedOrders, + totalOrders: progressState.totalOrders + }) try { + // Step 1: Access forward frame + log.debug('[详情页面 Step 1] 准备访问 forwardFrame') const detailMainFrame = detailPage.locator('#forwardFrame') const dFrame = await detailMainFrame.contentFrame() if (!dFrame) { - log.error('Failed to access detail page forward frame', { - ...(await capturePageContext(detailPage)) + const errorMsg = '无法访问详情页面的 forwardFrame' + log.error('[详情页面失败] forwardFrame 访问失败', { + elapsedMs: Date.now() - processStartTime, + pageUrl: detailPage.url(), + contextData: await capturePageContext(detailPage) }) - throw new Error('Failed to access detail page forward frame') + throw new Error(errorMsg) } + log.debug('[详情页面 Step 1 完成] forwardFrame 已获取', { + elapsedMs: Date.now() - processStartTime + }) + // Step 2: Access inner frame + log.debug('[详情页面 Step 2] 等待并获取 mainiframe 内部框架', { timeout: 30000 }) const detailInnerLocator = dFrame.locator('#mainiframe') await detailInnerLocator.waitFor({ state: 'visible', timeout: 30000 }) const detailInnerFrame = await detailInnerLocator.contentFrame() if (!detailInnerFrame) { - log.error('Failed to access detail inner frame', { - ...(await capturePageContext(detailPage, undefined, 'processDetail.detailInnerFrame')) + const errorMsg = '无法访问详情页面的内部框架' + log.error('[详情页面失败] 内部框架访问失败', { + elapsedMs: Date.now() - processStartTime, + pageUrl: detailPage.url(), + contextData: await capturePageContext( + detailPage, + undefined, + 'processDetail.detailInnerFrame' + ) }) - throw new Error('Failed to access detail inner frame') + throw new Error(errorMsg) } + log.debug('[详情页面 Step 2 完成] 内部框架已获取', { + elapsedMs: Date.now() - processStartTime + }) + // Step 3: Wait for page header + log.debug('[详情页面 Step 3] 等待页面标题显示', { + selector: '离散备料计划维护', + timeout: 30000 + }) await detailInnerFrame .getByText(/^离散备料计划维护：/) .waitFor({ state: 'visible', timeout: 30000 }) + log.debug('[详情页面 Step 3 完成] 页面标题已显示', { + elapsedMs: Date.now() - processStartTime + }) + // Step 4: Extract order number + log.debug('[详情页面 Step 4] 提取源订单号') const sourceOrderNumber = await this.extractSourceOrderNumber(detailInnerFrame) const orderNumber = sourceOrderNumber || expectedOrderNumber || 'UNKNOWN_ORDER' + log.debug('[详情页面 Step 4 完成] 订单号已确认', { + extractedOrderNumber: orderNumber, + sourceOrderNumber, + usedFallback: !sourceOrderNumber && !!expectedOrderNumber + }) const detail: OrderCleanDetail = { orderNumber, @@ -580,6 +749,8 @@ export class CleanerService { retrySuccess: false } + // Step 5: Get material counts and status + log.debug('[详情页面 Step 5] 读取物料数量和状态') const detailCountText = await detailInnerFrame.getByText(/^详细信息 \(\d+\)$/).innerText() const detailCountMatch = detailCountText.match(/\((\d+)\)/) const detailCount = detailCountMatch ? parseInt(detailCountMatch[1], 10) : 0 @@ -588,8 +759,15 @@ export class CleanerService { const statusMatch = statusText.replace(/\n/g, '').match(/备料状态:(.+)$/) const detailStatus = statusMatch ? statusMatch[1].trim() : '' + log.info('[详情页面] 订单状态已读取', { + orderNumber, + detailStatus, + totalMaterials: detailCount, + elapsedMs: Date.now() - processStartTime + }) + onProgress?.( - `开始处理订单: ${orderNumber}`, + `开始处理订单：${orderNumber}`, this.calculateProgress( progressState.completedOrders, 0, @@ -605,13 +783,26 @@ export class CleanerService { } ) + // Step 6: Process materials if status is "审批通过" if (detailStatus === '审批通过' && detailCount > 0) { + log.debug('[详情页面 Step 6] 订单状态为"审批通过"，开始修改流程', { + materialCount: detailCount + }) await detailInnerFrame.getByRole('button', { name: '修改' }).click() + log.debug('[详情页面 Step 6.1] 已点击"修改"按钮', { + elapsedMs: Date.now() - processStartTime + }) const saveButtonLocator = detailInnerFrame.getByRole('button', { name: '保存' }) await saveButtonLocator.waitFor({ state: 'visible', timeout: 30000 }) + log.debug('[详情页面 Step 6.2] "保存"按钮已就绪', { + elapsedMs: Date.now() - processStartTime + }) await detailInnerFrame.getByText('展开').first().click() + log.debug('[详情页面 Step 6.3] 已展开明细卡片', { + elapsedMs: Date.now() - processStartTime + }) const childForm = detailInnerFrame.locator('.card-table-side-box') const buttonWrapper = childForm.locator('.button-wrapper') @@ -621,14 +812,28 @@ export class CleanerService { let lastRowNumber = '' let materialIdx = 0 + const processingStartTime = Date.now() + + log.info('[物料循环开始] 准备遍历物料明细', { + orderNumber, + totalMaterials: detailCount, + deleteSetSize: deleteSet.size + }) while (true) { materialIdx += 1 + const materialStartTime = Date.now() const currentRow = await this.getInputValue(childForm, /^行号$/) const rowNumInt = parseInt(currentRow, 10) if (currentRow === lastRowNumber) { + log.debug('[物料循环] 检测到重复行号，等待 500ms', { + orderNumber, + materialIdx, + rowNumber: currentRow, + elapsedMs: Date.now() - processingStartTime + }) await this.delay(500) } @@ -656,6 +861,16 @@ export class CleanerService { ) if (deleteSet.has(materialCode)) { + log.debug('[物料判断] 物料在删除清单中，进行评估', { + orderNumber, + materialIdx, + materialCode, + materialName, + rowNumber: rowNumInt, + pendingQty: pendingQty || '(empty)', + deleteSetSize: deleteSet.size + }) + const shouldDelete = this.shouldDeleteMaterial({ rowNumber: rowNumInt, pendingQty, @@ -664,14 +879,35 @@ export class CleanerService { }) if (shouldDelete && !dryRun) { + log.info('[物料操作] 执行删除操作', { + orderNumber, + materialIdx, + materialCode, + materialName, + rowNumber: currentRow, + dryRun: false + }) const oldRowNumber = currentRow await deleteRowBtn.click() const deleteSuccess = await this.waitForRowChange(childForm, oldRowNumber, 10000) + const deleteElapsed = Date.now() - materialStartTime if (deleteSuccess) { detail.materialsDeleted += 1 - log.debug('物料已删除', { orderNumber, materialCode, rowNumber: currentRow }) + log.info('[物料操作完成] 物料已成功删除', { + orderNumber, + materialCode, + rowNumber: currentRow, + elapsedMs: deleteElapsed + }) + } else { + log.warn('[物料操作警告] 删除操作后行号未改变', { + orderNumber, + materialCode, + rowNumber: currentRow, + elapsedMs: deleteElapsed + }) } continue } @@ -684,7 +920,15 @@ export class CleanerService { materialCode, deleteSet }) - log.debug('物料已跳过', { orderNumber, materialCode, reason }) + log.debug('[物料跳过] 物料不满足删除条件', { + orderNumber, + materialIdx, + materialCode, + materialName, + rowNumber: rowNumInt, + reason, + elapsedMs: Date.now() - materialStartTime + }) detail.skippedMaterials.push({ materialCode, materialName, @@ -692,29 +936,93 @@ export class CleanerService { reason }) } + } else { + log.verbose('[物料判断] 物料不在删除清单中，跳过', { + orderNumber, + materialIdx, + materialCode, + materialName + }) } const isNextEnabled = await this.isButtonEnabled(nextBtn) if (isNextEnabled) { lastRowNumber = currentRow + log.verbose('[物料循环] 点击"下一行"按钮', { + orderNumber, + materialIdx, + currentRow, + hasNext: true + }) await nextBtn.click() } else { + log.info('[物料循环结束] 已到达最后一行', { + orderNumber, + totalMaterials: materialIdx, + deleted: detail.materialsDeleted, + skipped: detail.materialsSkipped, + elapsedMs: Date.now() - processingStartTime + }) break } } + log.debug('[详情页面 Step 7] 折叠明细卡片') await collapseBtn.click() if (!dryRun && detail.materialsDeleted > 0) { + log.info('[详情页面 Step 8] 保存订单修改', { + orderNumber, + materialsDeleted: detail.materialsDeleted, + materialsSkipped: detail.materialsSkipped + }) await saveButtonLocator.click() await saveButtonLocator.waitFor({ state: 'hidden', timeout: 60000 }) - log.info('订单修改已保存', { orderNumber, materialsDeleted: detail.materialsDeleted }) + log.info('[详情页面保存完成] 订单修改已保存', { + orderNumber, + materialsDeleted: detail.materialsDeleted, + elapsedMs: Date.now() - processStartTime + }) + } else if (dryRun) { + log.info('[详情页面干运行] 模拟模式下不保存修改', { + orderNumber, + wouldDeleteMaterials: detail.materialsDeleted + }) } + } else { + log.info('[详情页面跳过] 订单状态不是"审批通过"或无物料', { + orderNumber, + detailStatus, + detailCount, + reason: detailStatus !== '审批通过' ? '状态不符' : '无物料明细' + }) } + const totalProcessTime = Date.now() - processStartTime + log.info('[详情页面处理完成]', { + orderNumber, + totalMaterials: detailCount, + deleted: detail.materialsDeleted, + skipped: detail.materialsSkipped, + elapsedMs: totalProcessTime, + isSlow: totalProcessTime > 30000, + dryRun + }) + return detail + } catch (error) { + const message = error instanceof Error ? error.message : 'Unknown error' + log.error('[详情页面处理失败]', { + orderNumber: expectedOrderNumber || 'UNKNOWN', + error: message, + elapsedMs: Date.now() - processStartTime, + contextData: await capturePageContext(detailPage, undefined, 'processDetail.error') + }) + throw error } finally { + log.debug('[详情页面清理] 准备关闭详情页面', { pageUrl: detailPage.url() }) await detailPage.close() + log.debug('[详情页面清理完成] 详情页已关闭') } } @@ -844,12 +1152,17 @@ export class CleanerService { } if (failedDetails.length === 0) { + log.info('[重试机制] 没有需要重试的订单', { checkedCount: failedDetails.length }) return result } - log.info('Starting retry for failed orders', { - count: failedDetails.length, - totalOrders: params.failedDetails.length + const retryStartTime = Date.now() + log.info('[重试机制开始] 准备重试失败的订单', { + totalFailures: failedDetails.length, + failedOrders: failedDetails + .map((d) => d.orderNumber) + .slice(0, 5) + .concat(failedDetails.length > 5 ? [`... (${failedDetails.length - 5} more)`] : []) }) const MAX_RETRIES = 2 @@ -867,22 +1180,62 @@ export class CleanerService { const failedDetail = failedDetails[detailIndex] const orderNumber = failedDetail.orderNumber const retryAttempts: import('../../types/cleaner.types').RetryAttempt[] = [] + const retryLoopStartTime = Date.now() + + log.info('[重试订单] 开始处理失败订单的重试', { + orderNumber, + failureReason: failedDetail.errors.join('; '), + index: detailIndex + 1, + total: failedDetails.length + }) for (let attempt = 1; attempt <= MAX_RETRIES; attempt++) { - try { - log.info(`Retrying order ${orderNumber} (attempt ${attempt}/${MAX_RETRIES})`) + const attemptStartTime = Date.now() + log.info('[重试尝试] 开始第 {attempt} 次重试', { + orderNumber, + attempt, + maxRetries: MAX_RETRIES, + elapsedMs: attemptStartTime - retryLoopStartTime, + interpolatedAttempt: attempt + }) + try { + // Step 1: Re-query order + log.debug('[重试查询] 重新查询订单', { orderNumber, attempt }) await this.queryOrders(workFrame, [orderNumber]) await this.waitForLoading(workFrame) + log.debug('[重试查询完成] 查询加载完成', { + orderNumber, + attempt, + elapsedMs: Date.now() - attemptStartTime + }) + // Step 2: Check query results const rows = workFrame.locator('tbody tr') const rowCount = await rows.count() if (rowCount === 0) { - log.error('Retry query returned no results', { orderNumber, rowCount }) - throw new Error('订单重试查询无结果') + const errorMsg = '订单重试查询无结果' + log.error('[重试失败] 重试查询返回空结果', { + orderNumber, + attempt, + rowCount, + elapsedMs: Date.now() - attemptStartTime + }) + throw new Error(errorMsg) } + log.debug('[重试查询] 查询到 {rowCount} 行结果', { orderNumber, attempt, rowCount }) + // Step 3: Open detail page + log.debug('[重试详情] 打开订单详情页', { orderNumber, attempt }) const detailPage = await this.openDetailPageFromCurrentQuery(workFrame, popupPage) + log.debug('[重试详情] 详情页已打开', { + orderNumber, + attempt, + elapsedMs: Date.now() - attemptStartTime + }) + + // Step 4: Process detail page + log.debug('[重试处理] 开始处理详情页', { orderNumber, attempt }) const retryDetail = await this.processDetailPage({ detailPage, deleteSet, @@ -900,7 +1253,15 @@ export class CleanerService { ) } }) + log.info('[重试处理完成] 详情页处理完毕', { + orderNumber, + attempt, + deleted: retryDetail.materialsDeleted, + skipped: retryDetail.materialsSkipped, + elapsedMs: Date.now() - attemptStartTime + }) + // Success - update counters retryResult.successfulRetries += 1 retryResult.updatedDetails.push({ ...retryDetail, @@ -910,10 +1271,28 @@ export class CleanerService { retryAttempts }) retryResult.retriedOrders += 1 + + log.info('[重试成功] 订单重试成功', { + orderNumber, + attempt, + cumulativeSuccesses: retryResult.successfulRetries, + cumulativeRetried: retryResult.retriedOrders, + deletedMaterials: retryDetail.materialsDeleted, + elapsedMs: Date.now() - retryLoopStartTime + }) break } catch (error) { const message = error instanceof Error ? error.message : 'Unknown error' - log.warn(`Retry attempt ${attempt} failed for order ${orderNumber}: ${message}`) + const attemptElapsed = Date.now() - attemptStartTime + + log.warn('[重试失败] 当前重试尝试失败', { + orderNumber, + attempt, + maxRetries: MAX_RETRIES, + error: message, + elapsedMs: attemptElapsed, + remainingAttempts: MAX_RETRIES - attempt + }) retryAttempts.push({ attempt, @@ -922,6 +1301,15 @@ export class CleanerService { }) if (attempt === MAX_RETRIES) { + log.error('[重试彻底失败] 所有重试均已失败', { + orderNumber, + totalAttempts: MAX_RETRIES, + errors: retryAttempts.map((a) => a.error), + elapsedMs: Date.now() - retryLoopStartTime, + finalOutcome: 'exhausted_all_retries', + successRate: `${((retryResult.successfulRetries / (detailIndex + 1)) * 100).toFixed(1)}%` + }) + retryResult.updatedDetails.push({ ...failedDetail, retryCount: MAX_RETRIES, @@ -935,10 +1323,21 @@ export class CleanerService { } } - log.info('Retry process completed', { - retriedOrders: retryResult.retriedOrders, + const totalRetryTime = Date.now() - retryStartTime + const finalSuccessRate = + failedDetails.length > 0 + ? ((retryResult.successfulRetries / failedDetails.length) * 100).toFixed(1) + '%' + : 'N/A' + const avgTimePerRetry = totalRetryTime / (failedDetails.length || 1) + + log.info('[重试机制完成] 所有重试订单处理完毕', { + totalRetryOrders: failedDetails.length, successfulRetries: retryResult.successfulRetries, - totalRetryOrders: failedDetails.length + failedRetries: failedDetails.length - retryResult.successfulRetries, + successRate: finalSuccessRate, + totalElapsedTimeMs: totalRetryTime, + avgTimePerRetry, + isSlow: totalRetryTime > 30000 }) return retryResult diff --git a/src/main/services/rustfs/rustfs-service.ts b/src/main/services/rustfs/rustfs-service.ts index 68ca4e1..bd5938a 100644 --- a/src/main/services/rustfs/rustfs-service.ts +++ b/src/main/services/rustfs/rustfs-service.ts @@ -15,7 +15,7 @@ import { type GetObjectCommandInput, type DeleteObjectCommandInput } from '@aws-sdk/client-s3' -import { createLogger, run, trackDuration } from '../logger' +import { createLogger, run, trackDuration, PerformanceTracker } from '../logger' import type { RustfsConfig } from '../../types/config.schema' import * as fs from 'fs' import * as path from 'path' diff --git a/src/main/services/update/update-service.ts b/src/main/services/update/update-service.ts index 9d2bb34..461c6df 100644 --- a/src/main/services/update/update-service.ts +++ b/src/main/services/update/update-service.ts @@ -1,6 +1,6 @@ import * as fs from 'fs' import { ConfigManager } from '../config/config-manager' -import { createLogger, run, trackDuration } from '../logger' +import { createLogger, run, trackDuration, PerformanceTracker } from '../logger' import type { UpdateConfig } from '../../types/config.schema' import type { UserType } from '../../types/user.types' import type {