feat: add retry information display with exponential backoff in task logs (#533)

jumski · web-flow · commit 622cf2e2da0b · 2025-12-10T10:47:24.000+01:00
# Enhanced Retry Information Display in Edge Worker Logs

This PR adds improved retry information to the Edge Worker logs when a task fails but has retries remaining. The changes include:

- Added `baseDelay` parameter to the task context to support exponential backoff calculations
- Enhanced the `FancyFormatter` to display retry information with a visual indicator (↻) showing:
  - Current retry attempt number
  - Maximum retries allowed
  - Calculated delay before the next retry attempt
- Updated the `SimpleFormatter` to include retry information in key-value format for structured logging
- Implemented exponential backoff calculation: `baseDelay * 2^(attempt-1)`
- Added comprehensive unit tests for both formatters to verify retry information display

These changes make it easier to understand retry behavior when tasks fail, providing clear visibility into when a task will be retried and with what delay.
diff --git a/pkgs/edge-worker/src/flow/StepTaskExecutor.ts b/pkgs/edge-worker/src/flow/StepTaskExecutor.ts
@@ -61,6 +61,8 @@ export class StepTaskExecutor<TFlow extends AnyFlow, TContext extends StepTaskHa
     const stepDef = this.flow.getStepDefinition(this.stepTask.step_slug);
     // maxAttempts includes the initial attempt, so maxRetries = maxAttempts - 1
     const maxRetries = stepDef?.options?.maxAttempts ? stepDef.options.maxAttempts - 1 : undefined;
+    // baseDelay from step options for retry delay calculation
+    const baseDelay = stepDef?.options?.baseDelay;
 
     return {
       flowSlug: this.stepTask.flow_slug,
@@ -73,6 +75,7 @@ export class StepTaskExecutor<TFlow extends AnyFlow, TContext extends StepTaskHa
       queueName: this.workerIdentity.queueName,
       retryAttempt,
       maxRetries,
+      baseDelay,
     };
   }
 
diff --git a/pkgs/edge-worker/src/platform/logging.ts b/pkgs/edge-worker/src/platform/logging.ts
@@ -108,6 +108,22 @@ class FancyFormatter {
     let result = `${prefix} ${icon} ${path}`;
     if (ids) result += `  ${ids}`;
     result += `\n${prefix}   ${errorMsg}`;
+
+    // Show retry info if there are retries remaining
+    // retryAttempt = read_ct from pgmq (1-indexed: read_ct=1 is first attempt, read_ct=2 is first retry)
+    // maxRetries = maxAttempts - 1 (e.g., maxAttempts=4 means 3 retries allowed)
+    // Show retry pending when: retryAttempt <= maxRetries (still have retries left)
+    if (ctx.retryAttempt !== undefined && ctx.maxRetries !== undefined && ctx.retryAttempt <= ctx.maxRetries) {
+      const retryIcon = colorize('↻', ANSI.yellow, this.colorsEnabled);
+      // Exponential backoff: baseDelay * 2^(attempt-1)
+      // Example with baseDelay=5: attempt 1 -> 5s, attempt 2 -> 10s, attempt 3 -> 20s
+      // Default 5s matches pgflow SQL default in create_flow/add_step
+      const baseDelay = ctx.baseDelay ?? 5;
+      const delay = baseDelay * Math.pow(2, ctx.retryAttempt - 1);
+      const retryInfo = colorize(`retry ${ctx.retryAttempt}/${ctx.maxRetries} in ${delay}s`, ANSI.yellow, this.colorsEnabled);
+      result += `\n${prefix}   ${retryIcon} ${retryInfo}`;
+    }
+
     return result;
   }
 
@@ -186,7 +202,17 @@ class SimpleFormatter {
 
   taskFailed(ctx: TaskLogContext, error: Error): string {
     // Phase 3b: worker=X queue=Y flow=Z step=W format
-    return `[VERBOSE] worker=${ctx.workerName} queue=${ctx.queueName} flow=${ctx.flowSlug} step=${ctx.stepSlug} status=failed error="${error.message}" run_id=${ctx.runId} msg_id=${ctx.msgId} worker_id=${ctx.workerId}`;
+    let result = `[VERBOSE] worker=${ctx.workerName} queue=${ctx.queueName} flow=${ctx.flowSlug} step=${ctx.stepSlug} status=failed error="${error.message}" run_id=${ctx.runId} msg_id=${ctx.msgId} worker_id=${ctx.workerId}`;
+
+    // Add retry info if there are retries remaining (see FancyFormatter for detailed comments)
+    // Default 5s matches pgflow SQL default in create_flow/add_step
+    if (ctx.retryAttempt !== undefined && ctx.maxRetries !== undefined && ctx.retryAttempt <= ctx.maxRetries) {
+      const baseDelay = ctx.baseDelay ?? 5;
+      const delay = baseDelay * Math.pow(2, ctx.retryAttempt - 1);
+      result += ` retry=${ctx.retryAttempt}/${ctx.maxRetries} retry_delay_s=${delay}`;
+    }
+
+    return result;
   }
 
   polling(): string {
diff --git a/pkgs/edge-worker/src/platform/types.ts b/pkgs/edge-worker/src/platform/types.ts
@@ -13,6 +13,8 @@ export interface TaskLogContext {
   queueName: string;
   retryAttempt?: number;
   maxRetries?: number;
+  /** Base delay in seconds for retry calculation (from step options) */
+  baseDelay?: number;
 }
 
 /**
diff --git a/pkgs/edge-worker/tests/unit/platform/formatters.test.ts b/pkgs/edge-worker/tests/unit/platform/formatters.test.ts
@@ -17,6 +17,7 @@ interface TaskLogContext {
   queueName: string;
   retryAttempt?: number;
   maxRetries?: number;
+  baseDelay?: number;
 }
 
 interface StartupContext {
@@ -615,3 +616,189 @@ Deno.test('FancyFormatter - taskFailed at DEBUG level includes identifiers', ()
     restore();
   }
 });
+
+// ============================================================
+// Phase 5: Retry Information Display Tests
+// ============================================================
+
+Deno.test('FancyFormatter - taskFailed shows retry pending info when retries remaining', () => {
+  const consoleSpy = spy(console, 'log');
+
+  try {
+    const factory = createLoggingFactory({
+      SUPABASE_ANON_KEY: 'eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZS1kZW1vIiwicm9sZSI6ImFub24iLCJleHAiOjE5ODM4MTI5OTZ9.CRXP1A7WOeoJeXxjNni43kdQwgnWNReilDMblYTn_I0',
+    });
+    const logger = factory.createLogger('test');
+
+    const ctx: TaskLogContext = {
+      flowSlug: 'greetUser',
+      stepSlug: 'sendEmail',
+      msgId: '1044',
+      runId: 'run-123',
+      workerId: 'worker-1',
+      workerName: 'greet-user-worker',
+      queueName: 'orders',
+      retryAttempt: 1,  // First attempt (read_ct=1)
+      maxRetries: 3,    // 3 retries allowed
+      baseDelay: 5,     // 5 second base delay
+    };
+
+    const error = new Error('Request failed');
+    logger.taskFailed(ctx, error);
+
+    assertSpyCalls(consoleSpy, 1);
+    const output = consoleSpy.calls[0].args[0] as string;
+
+    // Should contain retry icon and info
+    assertStringIncludes(output, '↻');
+    assertStringIncludes(output, 'retry 1/3');
+    assertStringIncludes(output, '5s');  // baseDelay * 2^0 = 5s for first attempt
+  } finally {
+    restore();
+  }
+});
+
+Deno.test('FancyFormatter - taskFailed calculates exponential backoff delay correctly', () => {
+  const consoleSpy = spy(console, 'log');
+
+  try {
+    const factory = createLoggingFactory({
+      SUPABASE_ANON_KEY: 'eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZS1kZW1vIiwicm9sZSI6ImFub24iLCJleHAiOjE5ODM4MTI5OTZ9.CRXP1A7WOeoJeXxjNni43kdQwgnWNReilDMblYTn_I0',
+    });
+    const logger = factory.createLogger('test');
+
+    const ctx: TaskLogContext = {
+      flowSlug: 'greetUser',
+      stepSlug: 'sendEmail',
+      msgId: '1044',
+      runId: 'run-123',
+      workerId: 'worker-1',
+      workerName: 'greet-user-worker',
+      queueName: 'orders',
+      retryAttempt: 2,  // Second attempt (first retry)
+      maxRetries: 3,
+      baseDelay: 5,     // 5 second base delay
+    };
+
+    const error = new Error('Request failed');
+    logger.taskFailed(ctx, error);
+
+    assertSpyCalls(consoleSpy, 1);
+    const output = consoleSpy.calls[0].args[0] as string;
+
+    // Should show retry 2/3 with 10s delay (5 * 2^1 = 10)
+    assertStringIncludes(output, 'retry 2/3');
+    assertStringIncludes(output, '10s');
+  } finally {
+    restore();
+  }
+});
+
+Deno.test('FancyFormatter - taskFailed does NOT show retry info when no retries remaining', () => {
+  const consoleSpy = spy(console, 'log');
+
+  try {
+    const factory = createLoggingFactory({
+      SUPABASE_ANON_KEY: 'eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZS1kZW1vIiwicm9sZSI6ImFub24iLCJleHAiOjE5ODM4MTI5OTZ9.CRXP1A7WOeoJeXxjNni43kdQwgnWNReilDMblYTn_I0',
+    });
+    const logger = factory.createLogger('test');
+
+    const ctx: TaskLogContext = {
+      flowSlug: 'greetUser',
+      stepSlug: 'sendEmail',
+      msgId: '1044',
+      runId: 'run-123',
+      workerId: 'worker-1',
+      workerName: 'greet-user-worker',
+      queueName: 'orders',
+      retryAttempt: 4,  // 4th attempt, exceeds maxRetries
+      maxRetries: 3,    // Only 3 retries allowed
+      baseDelay: 5,
+    };
+
+    const error = new Error('Request failed');
+    logger.taskFailed(ctx, error);
+
+    assertSpyCalls(consoleSpy, 1);
+    const output = consoleSpy.calls[0].args[0] as string;
+
+    // Should NOT contain retry icon when no retries remaining
+    assertEquals(output.includes('↻'), false);
+  } finally {
+    restore();
+  }
+});
+
+Deno.test('SimpleFormatter - taskFailed shows retry info in key=value format', () => {
+  const consoleSpy = spy(console, 'log');
+
+  try {
+    const factory = createLoggingFactory({
+      SUPABASE_ANON_KEY: 'some-production-key',
+      EDGE_WORKER_LOG_LEVEL: 'verbose',
+    });
+    const logger = factory.createLogger('test');
+
+    const ctx: TaskLogContext = {
+      flowSlug: 'greetUser',
+      stepSlug: 'sendEmail',
+      msgId: '1044',
+      runId: 'run-123',
+      workerId: 'worker-1',
+      workerName: 'greet-user-worker',
+      queueName: 'orders',
+      retryAttempt: 1,
+      maxRetries: 3,
+      baseDelay: 5,
+    };
+
+    const error = new Error('Request failed');
+    logger.taskFailed(ctx, error);
+
+    assertSpyCalls(consoleSpy, 1);
+    const output = consoleSpy.calls[0].args[0] as string;
+
+    // Should contain retry info in key=value format
+    assertStringIncludes(output, 'retry=1/3');
+    assertStringIncludes(output, 'retry_delay_s=5');
+  } finally {
+    restore();
+  }
+});
+
+Deno.test('SimpleFormatter - taskFailed does NOT show retry info when no retries remaining', () => {
+  const consoleSpy = spy(console, 'log');
+
+  try {
+    const factory = createLoggingFactory({
+      SUPABASE_ANON_KEY: 'some-production-key',
+      EDGE_WORKER_LOG_LEVEL: 'verbose',
+    });
+    const logger = factory.createLogger('test');
+
+    const ctx: TaskLogContext = {
+      flowSlug: 'greetUser',
+      stepSlug: 'sendEmail',
+      msgId: '1044',
+      runId: 'run-123',
+      workerId: 'worker-1',
+      workerName: 'greet-user-worker',
+      queueName: 'orders',
+      retryAttempt: 4,  // Exceeds maxRetries
+      maxRetries: 3,
+      baseDelay: 5,
+    };
+
+    const error = new Error('Request failed');
+    logger.taskFailed(ctx, error);
+
+    assertSpyCalls(consoleSpy, 1);
+    const output = consoleSpy.calls[0].args[0] as string;
+
+    // Should NOT contain retry info when no retries remaining
+    assertEquals(output.includes('retry='), false);
+    assertEquals(output.includes('retry_delay_s='), false);
+  } finally {
+    restore();
+  }
+});

Original file line number	Diff line number	Diff line change
`@@ -13,6 +13,8 @@ export interface TaskLogContext {`
`13`	`13`	`queueName: string;`
`14`	`14`	`retryAttempt?: number;`
`15`	`15`	`maxRetries?: number;`
	`16`	`+ /** Base delay in seconds for retry calculation (from step options) */`
	`17`	`+ baseDelay?: number;`
`16`	`18`	`}`
`17`	`19`
`18`	`20`	`/**`