diff --git a/src/cli/extract-command.ts b/src/cli/extract-command.ts index 8a5d5da..4dec233 100644 --- a/src/cli/extract-command.ts +++ b/src/cli/extract-command.ts @@ -21,6 +21,10 @@ import { ArtifactStore } from '../clients/artifact-store.js'; import { IArtifactStore } from '../clients/iartifact-store.js'; import { getCloudConfig, buildArmBaseUrl } from '../lib/cloud-config.js'; import { EXIT_FATAL, EXIT_SUCCESS } from '../lib/exit-codes.js'; +import { getResourceTier, TIER_LABELS } from '../lib/dependency-graph.js'; +import { formatDuration } from '../lib/format-duration.js'; +import { ResourceType } from '../models/resource-types.js'; +import { getNamePart } from '../lib/resource-path.js'; /** * Interface for extract command options (from CLI flags). @@ -135,6 +139,7 @@ export async function executeExtract( await fs.mkdir(outputParent, { recursive: true }); const stagingDir = await fs.mkdtemp(stagingPrefix); + const startedAt = Date.now(); let result: ExtractionResult; try { const extractConfig: ExtractConfig = { @@ -159,11 +164,13 @@ export async function executeExtract( await fs.rm(stagingDir, { recursive: true, force: true }); } + const elapsedMs = Date.now() - startedAt; + // Output results if (globalOpts.format === 'json') { - outputJson(result); + outputJson(result, elapsedMs); } else { - outputText(result); + outputText(result, elapsedMs); } dependencies.exit(result.exitCode); @@ -180,13 +187,14 @@ export function shouldRemoveStaleArtifacts( * JSON output mode for extract. * Machine-readable JSON to stdout with resource counts and file paths. */ -function outputJson(result: ExtractionResult): void { +function outputJson(result: ExtractionResult, elapsedMs: number): void { const output = { status: result.exitCode === 0 ? 'success' : result.exitCode === 1 ? 'partial' : 'error', exitCode: result.exitCode, summary: { totalExtracted: result.totalExtracted, totalErrors: result.totalErrors, + elapsedMs, typeBreakdown: result.typeResults.map((tr) => ({ type: tr.type, extracted: tr.extracted.filter((r) => r.status === 'success').length, @@ -216,30 +224,72 @@ function outputJson(result: ExtractionResult): void { process.stdout.write(JSON.stringify(output, null, 2) + '\n'); } + +function tierOf(type: ResourceType): number { + try { + return getResourceTier(type); + } catch { + return Number.MAX_SAFE_INTEGER; + } +} + /** * Text output mode (default) — per-resource status lines. */ -function outputText(result: ExtractionResult): void { - // Per-type summary +export function outputText(result: ExtractionResult, elapsedMs: number): void { + // Per-type summary, grouped by dependency tier + const linesByTier = new Map(); for (const tr of result.typeResults) { + const lines: string[] = []; const successCount = tr.extracted.filter((r) => r.status === 'success').length; if (successCount > 0) { - process.stdout.write(`Extracted ${successCount} ${tr.type}(s)\n`); + lines.push(` Extracted ${successCount} ${tr.type}(s)`); } if (tr.errorCount > 0) { - process.stdout.write(`Failed ${tr.errorCount} ${tr.type}(s)\n`); + lines.push(` Failed ${tr.errorCount} ${tr.type}(s)`); + } + if (lines.length === 0) continue; + + const tier = tierOf(tr.type); + const tierLines = linesByTier.get(tier) ?? []; + tierLines.push(...lines); + linesByTier.set(tier, tierLines); + } + + for (const tier of [...linesByTier.keys()].sort((a, b) => a - b)) { + const label = TIER_LABELS[tier]; + process.stdout.write(label ? `Tier ${tier}: ${label}\n` : 'Other resources\n'); + process.stdout.write(`${linesByTier.get(tier)!.join('\n')}\n\n`); + } + + // API details — list every extracted API, even those without sub-resources + // or whose sub-resource extraction failed + const apiDetails = new Map(result.apiResults.map((ar) => [ar.apiName, ar])); + const apiNames = new Set(); + for (const tr of result.typeResults) { + if (tr.type !== ResourceType.Api) continue; + for (const r of tr.extracted) { + if (r.status === 'success') apiNames.add(getNamePart(r.descriptor.nameParts, 0)); } } + for (const name of apiDetails.keys()) apiNames.add(name); - // API details - for (const ar of result.apiResults) { - const details: string[] = []; - if (ar.specification) details.push('spec'); - if (ar.operations.length > 0) details.push(`${ar.operations.length} ops`); - if (ar.revisions.length > 0) details.push(`${ar.revisions.length} revisions`); - if (details.length > 0) { - process.stdout.write(` API "${ar.apiName}": ${details.join(', ')}\n`); + if (apiNames.size > 0) { + process.stdout.write('APIs:\n'); + } + for (const name of apiNames) { + const ar = apiDetails.get(name); + let summary: string; + if (!ar) { + summary = 'sub-resource extraction failed'; + } else { + const details: string[] = []; + if (ar.specification) details.push('spec'); + if (ar.operations.length > 0) details.push(`${ar.operations.length} ops`); + if (ar.revisions.length > 0) details.push(`${ar.revisions.length} revisions`); + summary = details.length > 0 ? details.join(', ') : 'definition only'; } + process.stdout.write(` API "${name}": ${summary}\n`); } // Workspace details @@ -249,6 +299,7 @@ function outputText(result: ExtractionResult): void { // Summary process.stdout.write( - `\nTotal: ${result.totalExtracted} resources extracted, ${result.totalErrors} errors\n` + `\nTotal: ${result.totalExtracted} resources extracted, ${result.totalErrors} errors ` + + `in ${formatDuration(elapsedMs)}\n` ); } diff --git a/src/cli/publish-command.ts b/src/cli/publish-command.ts index 7caf3ab..16a94ab 100644 --- a/src/cli/publish-command.ts +++ b/src/cli/publish-command.ts @@ -16,6 +16,7 @@ import { logger, parseLogLevel } from '../lib/logger.js'; import { ApimClient } from '../clients/apim-client.js'; import { ArtifactStore } from '../clients/artifact-store.js'; import { getCloudConfig, buildArmBaseUrl } from '../lib/cloud-config.js'; +import { formatDuration } from '../lib/format-duration.js'; /** * Interface for publish command options (from CLI flags). @@ -158,6 +159,7 @@ async function executePublish( deleteUnmatched: options.deleteUnmatched, commitId, logLevel: parseLogLevel(globalOpts.logLevel ?? 'info'), + outputFormat: globalOpts.format === 'json' ? 'json' : 'text', }; // Create client and store @@ -202,6 +204,9 @@ function outputJson(result: PublishResult): void { totalDeletes: number; totalErrors: number; totalSkipped: number; + totalRetries: number; + retriedResources: number; + elapsedMs?: number; }; actions: Array<{ action: string; @@ -209,6 +214,7 @@ function outputJson(result: PublishResult): void { nameParts: string[]; status: string; error?: string; + retries?: number; }>; dryRun?: { actions: Array<{ @@ -238,6 +244,9 @@ function outputJson(result: PublishResult): void { totalDeletes: result.totalDeletes, totalErrors: result.totalErrors, totalSkipped: result.totalSkipped, + totalRetries: result.totalRetries ?? 0, + retriedResources: result.retriedResources ?? 0, + elapsedMs: result.elapsedMs, }, actions: result.actions.map((action) => ({ action: action.action, @@ -245,6 +254,7 @@ function outputJson(result: PublishResult): void { nameParts: action.descriptor.nameParts, status: action.status, error: action.error?.message, + retries: action.retries, })), }; @@ -268,7 +278,7 @@ function outputJson(result: PublishResult): void { /** * Text output mode (default) — per-resource status lines and summary. */ -function outputText(result: PublishResult, dryRun: boolean): void { +export function outputText(result: PublishResult, dryRun: boolean): void { // Per-resource status lines are already output by publish-service // Just output the summary here @@ -300,5 +310,18 @@ function outputText(result: PublishResult, dryRun: boolean): void { if (result.totalErrors > 0) { process.stdout.write(`${result.totalErrors} errors\n`); } + + const totalRetries = result.totalRetries ?? 0; + if (totalRetries > 0) { + const retriedResources = result.retriedResources ?? 0; + process.stdout.write( + `${totalRetries} ${totalRetries === 1 ? 'retry' : 'retries'} across ` + + `${retriedResources} ${retriedResources === 1 ? 'resource' : 'resources'}\n` + ); + } + } + + if (result.elapsedMs !== undefined) { + process.stdout.write(`Completed in ${formatDuration(result.elapsedMs)}\n`); } } diff --git a/src/clients/apim-client.ts b/src/clients/apim-client.ts index d840bf0..06adbf5 100644 --- a/src/clients/apim-client.ts +++ b/src/clients/apim-client.ts @@ -11,10 +11,12 @@ import { IApimClient, ApiSpecDialect } from './iapim-client.js'; import { ApimServiceContext, ResourceDescriptor } from '../models/types.js'; import { RESOURCE_TYPE_METADATA, ResourceType } from '../models/resource-types.js'; import { buildArmUri, buildResourceLabel } from '../lib/resource-uri.js'; -import { deriveListPaths } from '../lib/resource-path.js'; +import { deriveListPaths, getResourceDescriptorKey } from '../lib/resource-path.js'; import { logger } from '../lib/logger.js'; import { isWorkspaceScope } from '../lib/workspace-link.js'; import { USER_AGENT } from '../lib/user-agent.js'; +import { formatDuration } from '../lib/format-duration.js'; +import { recordRetry, withRetryResource } from '../lib/retry-tracker.js'; /** * Structured HTTP error that carries the response status code. @@ -76,6 +78,38 @@ export function stripSourceArmId( return rest; } +/** + * Build a short, human-readable description of a request URL for log output. + * ARM URLs are reduced to the path below the APIM service (e.g. + * `apis/echo/operations/get`); other URLs keep host and path only. + * Query strings are always dropped. + */ +export function describeRequestTarget(url: string): string { + let pathname: string; + let host = ''; + try { + const parsed = new URL(url); + pathname = parsed.pathname; + host = parsed.host; + } catch { + pathname = url.split('?')[0] ?? url; + } + + const match = /\/providers\/Microsoft\.ApiManagement\/service\/[^/]+\/?(.*)$/i.exec(pathname); + if (match) { + return safeDecode(match[1] || 'service'); + } + return safeDecode(`${host}${pathname}`); +} + +function safeDecode(value: string): string { + try { + return decodeURIComponent(value); + } catch { + return value; + } +} + export class ApimClient implements IApimClient { private credential: DefaultAzureCredential; private readonly authScope: string; @@ -173,20 +207,28 @@ export class ApimClient implements IApimClient { let attempt = 0; // For SAS blob URLs the query string contains the sig token — strip it before logging. const logUrl = skipAuth ? url.split('?')[0] : url; + const method = options.method ?? 'GET'; + const target = `${method} ${describeRequestTarget(logUrl)}`; + const maxAttempts = ApimClient.MAX_RETRIES + 1; while (attempt <= ApimClient.MAX_RETRIES) { try { - logger.debug(`HTTP ${options.method ?? 'GET'} ${logUrl}`); + logger.debug(`HTTP ${method} ${logUrl}`); const response = await fetch(url, { ...options, headers }); // Handle rate limiting (429) if (response.status === 429) { const retryAfter = response.headers.get('Retry-After'); - const delaySeconds = retryAfter ? parseInt(retryAfter, 10) : Math.pow(2, attempt); - logger.warn(`Rate limited (429), retrying after ${delaySeconds}s`); - await this.delay(delaySeconds * 1000); - attempt++; - continue; + if (attempt < ApimClient.MAX_RETRIES) { + const delaySeconds = retryAfter ? parseInt(retryAfter, 10) : Math.pow(2, attempt); + this.logRetry( + `Rate limited (429) on ${target} (attempt ${attempt + 1}/${maxAttempts}), ` + + `retrying in ${formatDuration(delaySeconds * 1000)}` + ); + await this.delay(delaySeconds * 1000); + attempt++; + continue; + } } // Handle transient errors (5xx) @@ -199,7 +241,10 @@ export class ApimClient implements IApimClient { } if (attempt < ApimClient.MAX_RETRIES) { const delayMs = this.exponentialBackoffWithJitter(attempt); - logger.warn(`Server error ${response.status}, retrying after ${delayMs}ms`); + this.logRetry( + `Server error ${response.status} on ${target} (attempt ${attempt + 1}/${maxAttempts}), ` + + `retrying in ${formatDuration(delayMs)}` + ); await this.delay(delayMs); attempt++; continue; @@ -261,7 +306,10 @@ export class ApimClient implements IApimClient { throw error; } const delayMs = this.exponentialBackoffWithJitter(attempt); - logger.warn(`Request failed: ${(error as Error).message}, retrying after ${delayMs}ms`); + this.logRetry( + `Request failed on ${target} (attempt ${attempt + 1}/${maxAttempts}): ` + + `${(error as Error).message}, retrying in ${formatDuration(delayMs)}` + ); await this.delay(delayMs); attempt++; } @@ -270,6 +318,20 @@ export class ApimClient implements IApimClient { throw new Error('Max retries exceeded'); } + /** + * Log an intermediate retry. When the retry is attributed to an active + * tracking scope (e.g. a publish operation that reports its retry count on + * the final status line), the message is demoted to debug to keep normal + * output free of interleaved retry noise. + */ + private logRetry(message: string): void { + if (recordRetry()) { + logger.debug(message); + } else { + logger.warn(message); + } + } + private exponentialBackoffWithJitter(attempt: number): number { const exponentialDelay = Math.min( ApimClient.BASE_DELAY_MS * Math.pow(2, attempt), @@ -372,6 +434,14 @@ export class ApimClient implements IApimClient { async getResource( context: ApimServiceContext, descriptor: ResourceDescriptor + ): Promise | undefined> { + return withRetryResource(getResourceDescriptorKey(descriptor), () => + this.getResourceInternal(context, descriptor)); + } + + private async getResourceInternal( + context: ApimServiceContext, + descriptor: ResourceDescriptor ): Promise | undefined> { // Some association resources (ProductGroup, ProductApi, GatewayApi) only // support PUT/DELETE. Short-circuit before making a network call. @@ -424,6 +494,15 @@ export class ApimClient implements IApimClient { context: ApimServiceContext, descriptor: ResourceDescriptor, payload: Record + ): Promise> { + return withRetryResource(getResourceDescriptorKey(descriptor), () => + this.putResourceInternal(context, descriptor, payload)); + } + + private async putResourceInternal( + context: ApimServiceContext, + descriptor: ResourceDescriptor, + payload: Record ): Promise> { const url = buildArmUri(context, descriptor); @@ -475,6 +554,15 @@ export class ApimClient implements IApimClient { context: ApimServiceContext, descriptor: ResourceDescriptor, payload: Record + ): Promise> { + return withRetryResource(getResourceDescriptorKey(descriptor), () => + this.patchResourceInternal(context, descriptor, payload)); + } + + private async patchResourceInternal( + context: ApimServiceContext, + descriptor: ResourceDescriptor, + payload: Record ): Promise> { const url = buildArmUri(context, descriptor); @@ -498,6 +586,14 @@ export class ApimClient implements IApimClient { async deleteResource( context: ApimServiceContext, descriptor: ResourceDescriptor + ): Promise { + return withRetryResource(getResourceDescriptorKey(descriptor), () => + this.deleteResourceInternal(context, descriptor)); + } + + private async deleteResourceInternal( + context: ApimServiceContext, + descriptor: ResourceDescriptor ): Promise { let url = buildArmUri(context, descriptor); @@ -544,11 +640,12 @@ export class ApimClient implements IApimClient { error instanceof HttpError && (error.status === 412 || error.code === 'PreconditionFailed'); if (isConflict && attempt < ApimClient.DELETE_CONFLICT_RETRIES) { - logger.warn( + const delayMs = ApimClient.DELETE_CONFLICT_RETRY_DELAY_MS * attempt; + this.logRetry( `Delete conflict for ${buildResourceLabel(descriptor)} ` + - `(attempt ${attempt}/${ApimClient.DELETE_CONFLICT_RETRIES}), retrying...` + `(attempt ${attempt}/${ApimClient.DELETE_CONFLICT_RETRIES}), retrying in ${formatDuration(delayMs)}` ); - await this.delay(ApimClient.DELETE_CONFLICT_RETRY_DELAY_MS * attempt); + await this.delay(delayMs); continue; } throw error; diff --git a/src/lib/dependency-graph.ts b/src/lib/dependency-graph.ts index 482b55a..ac91230 100644 --- a/src/lib/dependency-graph.ts +++ b/src/lib/dependency-graph.ts @@ -109,6 +109,16 @@ export const TIER_4_RESOURCES: ResourceType[] = [ ResourceType.GraphQLResolverPolicy, ]; +/** + * Human-readable labels for each dependency tier, used to group CLI output. + */ +export const TIER_LABELS: Readonly> = { + 1: 'Independent resources', + 2: 'Resources with dependencies', + 3: 'Child resources', + 4: 'Nested child resources', +}; + /** * Returns all resource types in topological order (dependencies first). * This is the order in which resources should be extracted and published. diff --git a/src/lib/format-duration.ts b/src/lib/format-duration.ts new file mode 100644 index 0000000..22a9960 --- /dev/null +++ b/src/lib/format-duration.ts @@ -0,0 +1,20 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. +/** + * Human-readable duration formatting for CLI output. + */ + +/** + * Format a duration in milliseconds as a short human-readable string, + * e.g. `0.4s`, `12.3s`, `2m 5.0s`. + */ +export function formatDuration(ms: number): string { + const safeMs = Number.isFinite(ms) && ms > 0 ? ms : 0; + const totalSeconds = Math.round(safeMs / 100) / 10; + if (totalSeconds < 60) { + return `${totalSeconds.toFixed(1)}s`; + } + const minutes = Math.floor(totalSeconds / 60); + const seconds = totalSeconds - minutes * 60; + return `${minutes}m ${seconds.toFixed(1)}s`; +} diff --git a/src/lib/retry-tracker.ts b/src/lib/retry-tracker.ts new file mode 100644 index 0000000..678cdbb --- /dev/null +++ b/src/lib/retry-tracker.ts @@ -0,0 +1,73 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. +/** + * Per-operation retry tracking. + * + * Callers wrap a unit of work (e.g. publishing a single resource) in + * `trackRetries()`. HTTP retries performed anywhere inside that async call + * chain are attributed to the enclosing scope via `recordRetry()`, even when + * many operations run concurrently against a shared client. + * + * Work that targets one specific resource (e.g. a single client request) can + * additionally wrap itself in `withRetryResource()` so retries are attributed + * to that resource rather than to the whole scope. This matters when a task + * publishes child resources (e.g. an API and its operations) and each result + * must report the retries it actually incurred. + */ + +import { AsyncLocalStorage } from 'node:async_hooks'; + +interface RetryScope { + count: number; + byResource: Map; +} + +/** Retries recorded during one tracking scope. */ +export interface RetryCounts { + /** Total retries recorded in the scope. */ + total: number; + /** Retries attributed to a specific resource key. */ + byResource: Map; +} + +const retryScopes = new AsyncLocalStorage(); +const retryResources = new AsyncLocalStorage(); + +/** + * Run `fn` inside a retry-tracking scope and return its value together with + * the retries recorded while it executed. + */ +export async function trackRetries( + fn: () => Promise +): Promise<{ value: T; retries: RetryCounts }> { + const scope: RetryScope = { count: 0, byResource: new Map() }; + const value = await retryScopes.run(scope, fn); + return { value, retries: { total: scope.count, byResource: scope.byResource } }; +} + +/** + * Run `fn` with retries attributed to `resourceKey` within the active + * tracking scope. + */ +export function withRetryResource(resourceKey: string, fn: () => Promise): Promise { + return retryResources.run(resourceKey, fn); +} + +/** + * Record a retry against the current tracking scope, and against the current + * resource when one is active. + * @returns true when a tracking scope is active (the retry will be reported + * by the caller of `trackRetries`), false otherwise. + */ +export function recordRetry(): boolean { + const scope = retryScopes.getStore(); + if (!scope) { + return false; + } + scope.count++; + const resourceKey = retryResources.getStore(); + if (resourceKey !== undefined) { + scope.byResource.set(resourceKey, (scope.byResource.get(resourceKey) ?? 0) + 1); + } + return true; +} diff --git a/src/models/config.ts b/src/models/config.ts index 6c5085f..1498eef 100644 --- a/src/models/config.ts +++ b/src/models/config.ts @@ -108,6 +108,13 @@ export interface PublishConfig { deleteUnmatched: boolean; commitId?: string; logLevel: LogLevel; + /** + * Output mode selected on the command line. When 'json', service-level + * human-readable text (tier headers/footers, per-resource status lines) is + * suppressed so stdout carries only the JSON document. + * Defaults to 'text' when omitted. + */ + outputFormat?: 'text' | 'json'; } /** diff --git a/src/services/publish-service.ts b/src/services/publish-service.ts index 517667a..c9feffe 100644 --- a/src/services/publish-service.ts +++ b/src/services/publish-service.ts @@ -11,12 +11,14 @@ import { IArtifactStore } from '../clients/iartifact-store.js'; import { FilterConfig, PublishConfig, OverrideConfig } from '../models/config.js'; import { ApimServiceContext, ResourceDescriptor } from '../models/types.js'; import { ResourceType } from '../models/resource-types.js'; -import { getResourceTier } from '../lib/dependency-graph.js'; +import { getResourceTier, TIER_LABELS } from '../lib/dependency-graph.js'; import { runParallel } from '../lib/parallel-runner.js'; import { logger } from '../lib/logger.js'; import { isAutoGeneratedId } from '../lib/auto-generated.js'; import { EXIT_SUCCESS, EXIT_PARTIAL, EXIT_FATAL } from '../lib/exit-codes.js'; import { buildResourceLabel } from '../lib/resource-uri.js'; +import { formatDuration } from '../lib/format-duration.js'; +import { RetryCounts, trackRetries } from '../lib/retry-tracker.js'; import { getApiRootName, getNamePart, @@ -66,6 +68,8 @@ export interface PublishActionResult { action: 'put' | 'patch' | 'delete' | 'noop'; status: 'success' | 'failed' | 'skipped'; error?: Error; + /** Number of HTTP retries performed while processing this resource. */ + retries?: number; } export interface PublishResult { @@ -77,6 +81,12 @@ export interface PublishResult { exitCode: number; // 0=success, 1=partial failure, 2=fatal actions: PublishActionResult[]; dryRunReport?: DryRunReport; + /** Wall-clock duration of the publish run in milliseconds. */ + elapsedMs?: number; + /** Total HTTP retries performed across all resources. */ + totalRetries?: number; + /** Number of resources that required at least one retry. */ + retriedResources?: number; } interface PublishTargets { @@ -86,12 +96,29 @@ interface PublishTargets { /** * Main publish orchestration function. - * Coordinates PUT/DELETE operations across dependency tiers. + * Coordinates PUT/DELETE operations across dependency tiers and reports + * elapsed time and retry statistics. */ export async function runPublish( client: IApimClient, store: IArtifactStore, config: PublishConfig +): Promise { + const startedAt = Date.now(); + const result = await runPublishPipeline(client, store, config); + const retriedActions = result.actions.filter((action) => (action.retries ?? 0) > 0); + return { + ...result, + elapsedMs: Date.now() - startedAt, + totalRetries: retriedActions.reduce((sum, action) => sum + (action.retries ?? 0), 0), + retriedResources: retriedActions.length, + }; +} + +async function runPublishPipeline( + client: IApimClient, + store: IArtifactStore, + config: PublishConfig ): Promise { try { // Step 0: Pre-flight validation — ensure the resource group and APIM service exist @@ -460,9 +487,14 @@ async function executePuts( if (descriptors.length === 0) continue; logger.debug(`Publishing tier ${tier}: ${descriptors.length} resources`); + const tierStartedAt = Date.now(); if (tier === 1) { const { workspaces, nonWorkspaceTier1 } = splitWorkspaces(descriptors); + const { namedValues, otherTier1 } = splitNamedValues(nonWorkspaceTier1, config.overrides); + const tierCount = workspaces.length + namedValues.length + otherTier1.length; + if (tierCount === 0) continue; + writeTierHeader(config, tier, tierCount); if (workspaces.length > 0) { logger.debug(`Publishing ${workspaces.length} workspace container(s) first (wave 0 of tier 1)`); @@ -485,8 +517,6 @@ async function executePuts( // Pool backends reference individual Backend resources and must be // published after the backends they aggregate (see pool backend // ordering comments in splitPoolBackends). - const { namedValues, otherTier1 } = splitNamedValues(nonWorkspaceTier1, config.overrides); - if (namedValues.length > 0) { logger.debug(`Publishing ${namedValues.length} named value(s) first (wave 1 of tier 1)`); await publishAndOutput(client, store, context, config, namedValues, targetDescriptors, results); @@ -514,6 +544,8 @@ async function executePuts( } } else if (tier === 2) { const tier2Descriptors = filterApiRevisionsHandledByRootApis(descriptors); + if (tier2Descriptors.length === 0) continue; + writeTierHeader(config, tier, tier2Descriptors.length); const apiDescriptors = tier2Descriptors.filter((d) => d.type === ResourceType.Api); const nonApiDescriptors = tier2Descriptors.filter((d) => d.type !== ResourceType.Api); @@ -523,7 +555,7 @@ async function executePuts( apiDescriptors ); - await publishAndOutput(client, store, context, config, regularApis, targetDescriptors, results); + await publishAndOutput(client, store, context, config, regularApis, targetDescriptors, results); if (mcpApis.length > 0) { logger.debug(`Publishing ${mcpApis.length} MCP API resource(s) after regular tier 2 resources`); @@ -556,13 +588,54 @@ async function executePuts( } + if (tierDescriptors.length === 0) continue; + writeTierHeader(config, tier, tierDescriptors.length); await publishAndOutput(client, store, context, config, tierDescriptors, targetDescriptors, results); } + + writeTierFooter(config, tier, Date.now() - tierStartedAt); } return results; } +/** + * True when human-readable text may be written to stdout. + * In `--format json` mode stdout must carry only the JSON document, so all + * service-level text output is suppressed. + */ +function isTextOutput(config: PublishConfig): boolean { + return config.outputFormat !== 'json'; +} + +/** + * Write a tier header line to stdout, e.g. + * `── Tier 1: Independent resources (16) ──`. + */ +function writeTierHeader( + config: PublishConfig, + tier: number, + count: number, + prefix = 'Tier' +): void { + if (!isTextOutput(config)) return; + const label = TIER_LABELS[tier] ?? 'Resources'; + process.stdout.write(`\n── ${prefix} ${tier}: ${label} (${count}) ──\n`); +} + +/** + * Write the per-tier completion line with elapsed time to stdout. + */ +function writeTierFooter( + config: PublishConfig, + tier: number, + elapsedMs: number, + prefix = 'Tier' +): void { + if (!isTextOutput(config)) return; + process.stdout.write(`${prefix} ${tier} completed in ${formatDuration(elapsedMs)}\n`); +} + function parentScopeKey(descriptor: ResourceDescriptor): string { return `${descriptor.workspace ?? ''}:${getNamePart(descriptor.nameParts, 0)}`.toLowerCase(); } @@ -638,7 +711,7 @@ async function publishAndOutput( const tierResults = await publishTier(client, store, context, config, descriptors, targetDescriptors); results.push(...tierResults); for (const result of tierResults) { - outputActionStatus(result); + outputActionStatus(config, result); } } @@ -749,7 +822,7 @@ async function publishTier( descriptors: ResourceDescriptor[], allTargetDescriptors: ResourceDescriptor[] ): Promise { - const tasks = descriptors.map((descriptor) => async () => { + const publishDescriptor = async (descriptor: ResourceDescriptor): Promise => { try { let publishResult: ResourcePublishResult; const apiName = descriptor.type === ResourceType.Api @@ -798,6 +871,11 @@ async function publishTier( error: error instanceof Error ? error : new Error(String(error)), }]; } + }; + + const tasks = descriptors.map((descriptor) => async () => { + const { value, retries } = await trackRetries(() => publishDescriptor(descriptor)); + return attachRetries(value, retries); }); const taskResults = await runParallel(tasks, 5); @@ -928,6 +1006,8 @@ async function executeDeletesForDescriptors( if (descriptors.length === 0) continue; logger.debug(`Deleting tier ${tier}: ${descriptors.length} resources`); + const tierStartedAt = Date.now(); + writeTierHeader(config, tier, descriptors.length, 'Delete tier'); const tierResults = await deleteTier( client, @@ -941,8 +1021,9 @@ async function executeDeletesForDescriptors( // Output per-resource status lines for (const result of tierResults) { - outputActionStatus(result); + outputActionStatus(config, result); } + writeTierFooter(config, tier, Date.now() - tierStartedAt, 'Delete tier'); } return results; @@ -958,7 +1039,7 @@ async function deleteTier( config: PublishConfig, descriptorsAreDeployed: boolean ): Promise { - const tasks = descriptors.map((descriptor) => async () => { + const deleteDescriptor = async (descriptor: ResourceDescriptor): Promise => { try { const deployedDescriptor = config.envMapping && !descriptorsAreDeployed ? mapDescriptor(descriptor, config.envMapping) @@ -994,6 +1075,11 @@ async function deleteTier( error: error instanceof Error ? error : new Error(String(error)), }; } + }; + + const tasks = descriptors.map((descriptor) => async () => { + const { value, retries } = await trackRetries(() => deleteDescriptor(descriptor)); + return attachRetries([value], retries)[0] ?? value; }); const taskResults = await runParallel(tasks, 5); @@ -1030,19 +1116,59 @@ function convertToActionResult( }; } +/** + * Attribute the retries recorded for one publish task to the results that + * incurred them. Retries the client attributed to a specific resource are + * assigned to the matching result (e.g. an operation published as part of its + * API); any remaining retries are assigned to the primary (first) result. + */ +function attachRetries( + results: PublishActionResult[], + retries: RetryCounts +): PublishActionResult[] { + if (retries.total === 0 || results.length === 0) { + return results; + } + + const unassigned = new Map(retries.byResource); + let assignedTotal = 0; + const attributed = results.map((result) => { + const key = getResourceDescriptorKey(result.descriptor); + const count = unassigned.get(key); + if (count === undefined) { + return result; + } + unassigned.delete(key); + assignedTotal += count; + return { ...result, retries: count }; + }); + + const remainder = retries.total - assignedTotal; + if (remainder > 0) { + const primary = attributed[0]; + if (primary) { + attributed[0] = { ...primary, retries: (primary.retries ?? 0) + remainder }; + } + } + + return attributed; +} + /** * Output per-resource status line to stdout. */ -function outputActionStatus(result: PublishActionResult): void { +function outputActionStatus(config: PublishConfig, result: PublishActionResult): void { const verb = result.action.toUpperCase(); const path = buildResourcePath(result.descriptor); + const retries = result.retries ?? 0; + const retrySuffix = retries > 0 ? ` (${retries} ${retries === 1 ? 'retry' : 'retries'})` : ''; if (result.status === 'success') { - process.stdout.write(`${verb} ${path}\n`); + if (isTextOutput(config)) process.stdout.write(`${verb} ${path}${retrySuffix}\n`); } else if (result.status === 'skipped') { - process.stdout.write(`SKIP ${path}\n`); + if (isTextOutput(config)) process.stdout.write(`SKIP ${path}${retrySuffix}\n`); } else if (result.status === 'failed') { - process.stderr.write(`ERROR ${verb} ${path}: ${result.error?.message}\n`); + process.stderr.write(`ERROR ${verb} ${path}${retrySuffix}: ${result.error?.message}\n`); } } diff --git a/tests/unit/cli/extract-command.test.ts b/tests/unit/cli/extract-command.test.ts index 4ac3822..de66f58 100644 --- a/tests/unit/cli/extract-command.test.ts +++ b/tests/unit/cli/extract-command.test.ts @@ -8,11 +8,15 @@ import { describe, it, expect, vi } from 'vitest'; import { createExtractCommand, executeExtract, + outputText, shouldRemoveStaleArtifacts, } from '../../../src/cli/extract-command.js'; import { ExtractionResult } from '../../../src/services/extract-service.js'; import { ApimClient } from '../../../src/clients/apim-client.js'; import { IArtifactStore } from '../../../src/clients/iartifact-store.js'; +import { ResourceType } from '../../../src/models/resource-types.js'; +import { ApiExtractionResult } from '../../../src/services/api-extractor.js'; +import { TypeExtractionResult } from '../../../src/services/resource-extractor.js'; describe('extract-command', () => { describe('createExtractCommand', () => { @@ -139,4 +143,136 @@ describe('extract-command', () => { } }); }); + + describe('outputText', () => { + function typeResult(type: ResourceType, successCount: number, errorCount = 0): TypeExtractionResult { + return { + type, + extracted: Array.from({ length: successCount }, (_, i) => ({ + descriptor: { type, nameParts: [`${type}-${i}`] }, + json: {}, + status: 'success' as const, + })), + totalCount: successCount + errorCount, + errorCount, + }; + } + + function apiResult(apiName: string, overrides: Partial = {}): ApiExtractionResult { + return { + apiName, + errorCount: 0, + revisions: [], + specification: false, + operations: [], + operationPolicies: [], + tags: [], + diagnostics: [], + schemas: [], + releases: [], + tagDescriptions: [], + wiki: false, + mcpServer: false, + resolvers: [], + resolverPolicies: [], + policies: [], + ...overrides, + }; + } + + function render(result: ExtractionResult, elapsedMs: number): string { + const stdout = vi.spyOn(process.stdout, 'write').mockImplementation(() => true); + try { + outputText(result, elapsedMs); + return stdout.mock.calls.map((call) => String(call[0])).join(''); + } finally { + stdout.mockRestore(); + } + } + + const baseResult: ExtractionResult = { + totalExtracted: 0, + totalErrors: 0, + typeResults: [], + apiResults: [], + productResults: [], + workspaceResults: [], + extractedDescriptors: [], + collectedPolicies: new Map(), + exitCode: 0, + }; + + it('groups extracted types by dependency tier', () => { + const output = render( + { + ...baseResult, + typeResults: [ + typeResult(ResourceType.NamedValue, 2), + typeResult(ResourceType.Api, 1), + typeResult(ResourceType.Subscription, 3, 1), + typeResult(ResourceType.Tag, 1), + ], + }, + 0 + ); + + expect(output).toContain( + 'Tier 1: Independent resources\n Extracted 2 NamedValue(s)\n Extracted 1 Tag(s)\n\n' + ); + expect(output).toContain('Tier 2: Resources with dependencies\n Extracted 1 Api(s)\n\n'); + expect(output).toContain( + 'Tier 3: Child resources\n Extracted 3 Subscription(s)\n Failed 1 Subscription(s)\n\n' + ); + expect(output.indexOf('Tier 1:')).toBeLessThan(output.indexOf('Tier 2:')); + expect(output.indexOf('Tier 2:')).toBeLessThan(output.indexOf('Tier 3:')); + }); + + it('lists every API, including those without sub-resources', () => { + const output = render( + { + ...baseResult, + apiResults: [ + apiResult('echo', { + specification: true, + operations: [{ descriptor: { type: ResourceType.ApiOperation, nameParts: ['echo', 'get'] }, json: {}, status: 'success' }], + }), + apiResult('src-graphql-synthetic'), + ], + }, + 0 + ); + + expect(output).toContain(' API "echo": spec, 1 ops\n'); + expect(output).toContain(' API "src-graphql-synthetic": definition only\n'); + }); + + it('lists extracted APIs whose sub-resource extraction failed', () => { + const output = render( + { + ...baseResult, + typeResults: [ + { + type: ResourceType.Api, + extracted: [ + { descriptor: { type: ResourceType.Api, nameParts: ['echo'] }, json: {}, status: 'success' }, + { descriptor: { type: ResourceType.Api, nameParts: ['broken'] }, json: {}, status: 'success' }, + ], + totalCount: 2, + errorCount: 0, + }, + ], + apiResults: [apiResult('echo', { specification: true })], + }, + 0 + ); + + expect(output).toContain('APIs:\n API "echo": spec\n API "broken": sub-resource extraction failed\n'); + }); + + it('includes elapsed time on the Total line', () => { + const output = render({ ...baseResult, totalExtracted: 96 }, 12_345); + + expect(output).toContain('Total: 96 resources extracted, 0 errors in 12.3s\n'); + }); + }); }); diff --git a/tests/unit/cli/publish-command.test.ts b/tests/unit/cli/publish-command.test.ts index 7af2763..67d5527 100644 --- a/tests/unit/cli/publish-command.test.ts +++ b/tests/unit/cli/publish-command.test.ts @@ -4,11 +4,13 @@ * Unit tests for Publish command CLI registration */ -import { describe, it, expect } from 'vitest'; +import { describe, it, expect, vi } from 'vitest'; import { createPublishCommand, hasMutuallyExclusivePublishOptions, + outputText, } from '../../../src/cli/publish-command.js'; +import { PublishResult } from '../../../src/services/publish-service.js'; describe('publish-command', () => { describe('createPublishCommand', () => { @@ -158,4 +160,52 @@ describe('publish-command', () => { expect(hasMutuallyExclusivePublishOptions(false, undefined, true)).toBe(false); }); }); + + describe('outputText', () => { + const baseResult: PublishResult = { + totalPuts: 41, + totalPatches: 0, + totalDeletes: 0, + totalErrors: 0, + totalSkipped: 1, + exitCode: 0, + actions: [], + }; + + function render(result: PublishResult, dryRun = false): string { + const stdout = vi.spyOn(process.stdout, 'write').mockImplementation(() => true); + try { + outputText(result, dryRun); + return stdout.mock.calls.map((call) => String(call[0])).join(''); + } finally { + stdout.mockRestore(); + } + } + + it('includes retry counts and elapsed time in the summary', () => { + const output = render({ + ...baseResult, + elapsedMs: 12_345, + totalRetries: 6, + retriedResources: 2, + }); + + expect(output).toContain('41 creates/updates, 0 patches, 0 deletes, 1 skipped\n'); + expect(output).toContain('6 retries across 2 resources\n'); + expect(output).toContain('Completed in 12.3s\n'); + }); + + it('omits the retry line when no retries occurred', () => { + const output = render({ ...baseResult, elapsedMs: 500, totalRetries: 0, retriedResources: 0 }); + + expect(output).not.toContain('retr'); + expect(output).toContain('Completed in 0.5s\n'); + }); + + it('uses singular wording for a single retry', () => { + const output = render({ ...baseResult, totalRetries: 1, retriedResources: 1 }); + + expect(output).toContain('1 retry across 1 resource\n'); + }); + }); }); diff --git a/tests/unit/clients/apim-client.test.ts b/tests/unit/clients/apim-client.test.ts index 26560b9..d09cb2b 100644 --- a/tests/unit/clients/apim-client.test.ts +++ b/tests/unit/clients/apim-client.test.ts @@ -6,10 +6,13 @@ */ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; -import { ApimClient, HttpError } from '../../../src/clients/apim-client.js'; +import { ApimClient, HttpError, describeRequestTarget } from '../../../src/clients/apim-client.js'; import { ResourceType } from '../../../src/models/resource-types.js'; import { ApimServiceContext } from '../../../src/models/types.js'; import { buildArmBaseUrl } from '../../../src/lib/cloud-config.js'; +import { logger } from '../../../src/lib/logger.js'; +import { trackRetries } from '../../../src/lib/retry-tracker.js'; +import { getResourceDescriptorKey } from '../../../src/lib/resource-path.js'; const testContext: ApimServiceContext = { subscriptionId: 'sub-1', @@ -1670,3 +1673,90 @@ describe('User-Agent header', () => { expect(blobHeaders.get('Authorization')).toBeNull(); }); }); + +describe('describeRequestTarget', () => { + it('reduces ARM URLs to the path below the APIM service', () => { + expect( + describeRequestTarget(`${testContext.baseUrl}/namedValues/nv%201?api-version=2024-05-01`) + ).toBe('namedValues/nv 1'); + }); + + it('describes the service itself when no sub-path is present', () => { + expect(describeRequestTarget(`${testContext.baseUrl}?api-version=2024-05-01`)).toBe('service'); + }); + + it('keeps host and path for non-ARM URLs and drops the query string', () => { + expect(describeRequestTarget('https://blob.example.net/container/spec.json?sig=secret')).toBe( + 'blob.example.net/container/spec.json' + ); + }); +}); + +describe('ApimClient retry logging', () => { + let client: ApimClient; + let fetchSpy: ReturnType; + + beforeEach(() => { + client = new ApimClient(); + fetchSpy = vi.fn(); + vi.stubGlobal('fetch', fetchSpy); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + vi.spyOn(client as any, 'getToken').mockResolvedValue('fake-token'); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + vi.spyOn(client as any, 'delay').mockResolvedValue(undefined); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + vi.spyOn(client as any, 'exponentialBackoffWithJitter').mockReturnValue(1175.1730686888397); + }); + + afterEach(() => { + vi.restoreAllMocks(); + vi.unstubAllGlobals(); + }); + + const descriptor = { type: ResourceType.NamedValue, nameParts: ['nv-1'] }; + + function queueServerErrorThenSuccess(): void { + fetchSpy + .mockResolvedValueOnce(new Response('error', { status: 503, headers: { 'Content-Type': 'text/plain' } })) + .mockResolvedValueOnce(makeResponse(200, { name: 'nv-1' })); + } + + it('warns with resource context, attempt number, and a rounded delay', async () => { + const warnSpy = vi.spyOn(logger, 'warn').mockImplementation(() => undefined); + queueServerErrorThenSuccess(); + + await client.getResource(testContext, descriptor); + + expect(warnSpy).toHaveBeenCalledWith( + 'Server error 503 on GET namedValues/nv-1 (attempt 1/4), retrying in 1.2s' + ); + }); + + it('includes resource context and attempt number for rate limiting', async () => { + const warnSpy = vi.spyOn(logger, 'warn').mockImplementation(() => undefined); + fetchSpy + .mockResolvedValueOnce(new Response('', { status: 429, headers: { 'Retry-After': '3' } })) + .mockResolvedValueOnce(makeResponse(200, { name: 'nv-1' })); + + await client.getResource(testContext, descriptor); + + expect(warnSpy).toHaveBeenCalledWith( + 'Rate limited (429) on GET namedValues/nv-1 (attempt 1/4), retrying in 3.0s' + ); + }); + + it('demotes retry messages to debug and counts them inside a tracking scope', async () => { + const warnSpy = vi.spyOn(logger, 'warn').mockImplementation(() => undefined); + const debugSpy = vi.spyOn(logger, 'debug').mockImplementation(() => undefined); + queueServerErrorThenSuccess(); + + const { retries } = await trackRetries(() => client.getResource(testContext, descriptor)); + + expect(retries.total).toBe(1); + expect(retries.byResource.get(getResourceDescriptorKey(descriptor))).toBe(1); + expect(warnSpy).not.toHaveBeenCalled(); + expect(debugSpy).toHaveBeenCalledWith( + 'Server error 503 on GET namedValues/nv-1 (attempt 1/4), retrying in 1.2s' + ); + }); +}); diff --git a/tests/unit/lib/format-duration.test.ts b/tests/unit/lib/format-duration.test.ts new file mode 100644 index 0000000..a982cd8 --- /dev/null +++ b/tests/unit/lib/format-duration.test.ts @@ -0,0 +1,24 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. +/** + * Unit tests for formatDuration + */ + +import { describe, it, expect } from 'vitest'; +import { formatDuration } from '../../../src/lib/format-duration.js'; + +describe('formatDuration', () => { + it.each([ + [0, '0.0s'], + [49, '0.0s'], + [1175.1730686888397, '1.2s'], + [12_345, '12.3s'], + [59_949, '59.9s'], + [59_950, '1m 0.0s'], + [125_000, '2m 5.0s'], + [-5, '0.0s'], + [Number.NaN, '0.0s'], + ])('formats %s ms as %s', (ms, expected) => { + expect(formatDuration(ms)).toBe(expected); + }); +}); diff --git a/tests/unit/lib/retry-tracker.test.ts b/tests/unit/lib/retry-tracker.test.ts new file mode 100644 index 0000000..1588e72 --- /dev/null +++ b/tests/unit/lib/retry-tracker.test.ts @@ -0,0 +1,58 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT license. +/** + * Unit tests for retry tracking scopes + */ + +import { describe, it, expect } from 'vitest'; +import { recordRetry, trackRetries, withRetryResource } from '../../../src/lib/retry-tracker.js'; + +describe('retry-tracker', () => { + it('returns false when no tracking scope is active', () => { + expect(recordRetry()).toBe(false); + }); + + it('counts retries recorded within the scope', async () => { + const { value, retries } = await trackRetries(async () => { + expect(recordRetry()).toBe(true); + await Promise.resolve(); + recordRetry(); + return 'done'; + }); + + expect(value).toBe('done'); + expect(retries.total).toBe(2); + }); + + it('attributes retries to the correct scope under concurrency', async () => { + const work = (count: number, delayMs: number) => + trackRetries(async () => { + for (let i = 0; i < count; i++) { + await new Promise((resolve) => setTimeout(resolve, delayMs)); + recordRetry(); + } + }); + + const [a, b] = await Promise.all([work(3, 1), work(1, 2)]); + + expect(a.retries.total).toBe(3); + expect(b.retries.total).toBe(1); + }); + + it('attributes retries to the resource scope that recorded them', async () => { + const { retries } = await trackRetries(async () => { + await withRetryResource('api:child-a', async () => { + recordRetry(); + recordRetry(); + }); + await withRetryResource('api:child-b', async () => { + recordRetry(); + }); + recordRetry(); + }); + + expect(retries.total).toBe(4); + expect(retries.byResource.get('api:child-a')).toBe(2); + expect(retries.byResource.get('api:child-b')).toBe(1); + }); +}); diff --git a/tests/unit/services/publish-service.test.ts b/tests/unit/services/publish-service.test.ts index 503c3be..d829b9a 100644 --- a/tests/unit/services/publish-service.test.ts +++ b/tests/unit/services/publish-service.test.ts @@ -9,6 +9,8 @@ import { ResourceType } from '../../../src/models/resource-types.js'; import { ResourceDescriptor, ApimServiceContext } from '../../../src/models/types.js'; import { PublishConfig } from '../../../src/models/config.js'; import { LogLevel } from '../../../src/lib/logger.js'; +import { recordRetry, withRetryResource } from '../../../src/lib/retry-tracker.js'; +import { getResourceDescriptorKey } from '../../../src/lib/resource-path.js'; // Mock service dependencies vi.mock('../../../src/services/git-diff-service.js'); @@ -123,6 +125,32 @@ describe('publish-service', () => { expect(result.exitCode).toBe(0); }); + it('should not write text output to stdout in json format mode', async () => { + const resources = [ + { type: ResourceType.NamedValue, nameParts: ['nv1'] }, + { type: ResourceType.Api, nameParts: ['api1'] }, + ]; + + const client = createMockClient(); + const store = createMockStore(resources); + const writeSpy = vi.spyOn(process.stdout, 'write').mockReturnValue(true); + + try { + await runPublish(client, store, { + service: testContext, + sourceDir: '/source', + dryRun: false, + deleteUnmatched: false, + logLevel: LogLevel.INFO, + outputFormat: 'json', + }); + } finally { + writeSpy.mockRestore(); + } + + expect(writeSpy).not.toHaveBeenCalled(); + }); + it('should return exit code 0 when all succeed', async () => { const resources = [ { type: ResourceType.Tag, nameParts: ['tag1'] }, @@ -2090,4 +2118,121 @@ describe('publish-service', () => { expect(putNames).toContain(autoGenId); }); }); + + describe('publish output readability', () => { + const baseConfig: PublishConfig = { + service: testContext, + sourceDir: '/source', + dryRun: false, + deleteUnmatched: false, + logLevel: LogLevel.INFO, + }; + + function captureStdout(): { lines: () => string; restore: () => void } { + const spy = vi.spyOn(process.stdout, 'write').mockImplementation(() => true); + return { + lines: () => spy.mock.calls.map((call) => String(call[0])).join(''), + restore: () => spy.mockRestore(), + }; + } + + it('writes tier headers with counts and per-tier timing', async () => { + const resources = [ + { type: ResourceType.NamedValue, nameParts: ['nv1'] }, + { type: ResourceType.Tag, nameParts: ['tag1'] }, + { type: ResourceType.Api, nameParts: ['api1'] }, + ]; + const stdout = captureStdout(); + + try { + await runPublish(createMockClient(), createMockStore(resources), baseConfig); + const output = stdout.lines(); + + expect(output).toContain('── Tier 1: Independent resources (2) ──'); + expect(output).toContain('── Tier 2: Resources with dependencies (1) ──'); + expect(output).not.toContain('── Tier 3'); + expect(output).toMatch(/Tier 1 completed in \d+\.\ds/); + expect(output).toMatch(/Tier 2 completed in \d+\.\ds/); + expect(output.indexOf('Tier 1:')).toBeLessThan(output.indexOf('PUT namedvalue/nv1')); + expect(output.indexOf('PUT namedvalue/nv1')).toBeLessThan(output.indexOf('Tier 2:')); + } finally { + stdout.restore(); + } + }); + + it('reports retries per resource and in the result totals', async () => { + const resources = [ + { type: ResourceType.NamedValue, nameParts: ['nv1'] }, + { type: ResourceType.Tag, nameParts: ['tag1'] }, + ]; + const client = createMockClient(); + client.putResource.mockImplementation(async (_ctx: ApimServiceContext, descriptor: ResourceDescriptor) => { + if (descriptor.nameParts[0] === 'nv1') { + recordRetry(); + recordRetry(); + } + return undefined; + }); + const stdout = captureStdout(); + + try { + const result = await runPublish(client, createMockStore(resources), baseConfig); + const output = stdout.lines(); + + expect(output).toContain('PUT namedvalue/nv1 (2 retries)\n'); + expect(output).toContain('PUT tag/tag1\n'); + expect(result.totalRetries).toBe(2); + expect(result.retriedResources).toBe(1); + expect(result.actions.find((a) => a.descriptor.nameParts[0] === 'nv1')?.retries).toBe(2); + expect(result.elapsedMs).toBeGreaterThanOrEqual(0); + } finally { + stdout.restore(); + } + }); + + it('attributes retries to the related resource that incurred them', async () => { + const apiDescriptor = { type: ResourceType.Api, nameParts: ['api1'] }; + const operationDescriptor = { + type: ResourceType.ApiOperation, + nameParts: ['api1', 'get-items'], + }; + vi.mocked(publishApi).mockImplementation(async () => { + await withRetryResource(getResourceDescriptorKey(operationDescriptor), async () => { + recordRetry(); + recordRetry(); + }); + return { + descriptor: apiDescriptor, + status: 'success', + action: 'put', + relatedResults: [{ + descriptor: operationDescriptor, + status: 'success', + action: 'put', + }], + }; + }); + const stdout = captureStdout(); + + try { + const result = await runPublish( + createMockClient(), + createMockStore([apiDescriptor]), + baseConfig + ); + const output = stdout.lines(); + + expect(output).toContain('PUT api/api1\n'); + expect(output).toContain('PUT apioperation/api1/get-items (2 retries)\n'); + expect(result.actions.find((a) => a.descriptor.type === ResourceType.Api)?.retries) + .toBeUndefined(); + expect(result.actions.find((a) => a.descriptor.type === ResourceType.ApiOperation)?.retries) + .toBe(2); + expect(result.totalRetries).toBe(2); + expect(result.retriedResources).toBe(1); + } finally { + stdout.restore(); + } + }); + }); });