Testing Resilience4j retry logic

Question

I'm trying to test my retry logic, using Resilience4j, and I have the following.

In my test I'm having triggerFunc, throw an exception twice and then successfully execute on the 3rd attempt.

   @Test
   void testRetryLogic(){
      ServiceB spy = spy(serviceB);
      Object param = ...

      doThrow(new RuntimeException("Simulated exception"))
         .doThrow(new RuntimeException("Simulated exception"))
         .doCallRealMethod()
         .when(spy).triggerFunc(any());

      Object result = spy.funcHandler(param);
   }

Here is my retry logic. I'm using decorateRunnable as I'm calling on a void function.

//ServiceB
private Runnable executeFuncWithRetry(Object param, Object obj) {
    Retry retry = getRetryConfig(param.getName());

    return decorateRunnable(
      retry, () -> {
        log.debug("Successes: {}", retry.getMetrics().getNumberOfFailedCallsWithoutRetryAttempt());
        log.debug("Attempt #{} to read from {} ",
          retry.getMetrics().getNumberOfFailedCallsWithRetryAttempt(),
          param.getName());
        triggerFunc(obj);
    });
  }

Here is my output. I'm curious why when i log retry.getMetrics().getNumberOfFailedCallsWithRetryAttempt() my output always shows 0 instead of 2? Because, in my test I'm calling doThrow twice.

    2024-02-23 11:01:46,677 DEBUG [com...ServiceB] Fetching data for: test-table
Format: parquet
    2024-02-23 11:01:48,410 DEBUG [com...] Successes: 0
    2024-02-23 11:01:48,411 DEBUG [com...] Attempt #0 to read from test-table 
    2024-02-23 11:01:48,923 DEBUG [com...] Successes: 0
    2024-02-23 11:01:48,923 DEBUG [com...] Attempt #0 to read from test-table 
    2024-02-23 11:01:49,676 DEBUG [com...] Successes: 0
    2024-02-23 11:01:49,677 DEBUG [com...] Attempt #0 to read from test-table 

P.S. if there's a function you guys prefer over decorateRunnable for what im doing in here let me know.

For more context, here is the function i am invoking in my test that handles all this funcHandler

//ServiceB
public Object funcHandler(Object param) {
    try {
      log.debug("Fetching data for: {}", param.getName());
      Object object = serviceA.getObject(param);
      executeFuncWithRetry(param, object).run();
      return object;
    } catch (Throwable e) {
      return null;
    }
  }

Update 1

I discovered i was logging my retry metadata in the wrong place. I now see my desired logs. Although, now i can not see my successful retries. Any ideas?

public Runnable executeFuncWithRetry(Object param, Object obj) {
    Retry retry = getRetryConfig(param.getName());
    retry.getEventPublisher().onRetry( event -> {
      log.debug("event type: {}", event.getEventType());
      if(event.getEventType() == RetryEvent.Type.RETRY){
        log.debug("retry #{} for table: {}", event.getNumberOfRetryAttempts(), param.getName());
      }
      if(event.getEventType() == RetryEvent.Type.SUCCESS){
        log.debug("successfully fetched from table: {} - retries: {}", param.getName(), event.getNumberOfRetryAttempts());
      }
    });

    return decorateRunnable(
      retry, () -> triggerFunc(obj));
  }

Here is my output without the success being shown

2024-02-23 12:06:09,284 DEBUG [com...] Fetching data for Table: test-table
Format: parquet
2024-02-23 12:06:10,840 DEBUG [com...] event type: RETRY
2024-02-23 12:06:10,840 DEBUG [com...] retry #1 for table: test-table
2024-02-23 12:06:11,348 DEBUG [com...] event type: RETRY
2024-02-23 12:06:11,349 DEBUG [com...] retry #2 for table: test-table
2024-02-23 12:06:12,910 DEBUG [com...] Rows fetched: 1

Update 2

i need to slow down i think lol

I realized i was expecting too much from logging in retry.getEventPublisher().onRetry(...) obviously there is a onSuccess() that i can utilize

here's my updated code:

public Runnable executeFuncWithRetry(Object param, Object obj) {
    Retry retry = getRetryConfig(param.getName());

    retry.getEventPublisher()
      .onSuccess(event -> {
        log.debug("successfully fetched from table: {} - retries: {}", param.getName(), event.getNumberOfRetryAttempts());
      })
      .onRetry( event -> {
        log.debug("retry #{} for table: {}", event.getNumberOfRetryAttempts(), param.getName());
    });
    return decorateRunnable(
      retry, () -> triggerFunc(obj));
  }

Here's my desired output

2024-02-23 12:14:10,083 DEBUG [com...] retry #1 for table: test-table
2024-02-23 12:14:10,597 DEBUG [com...] retry #2 for table: test-table
2024-02-23 12:14:12,161 DEBUG [com...] Rows fetched: 1
2024-02-23 12:14:12,162 DEBUG [com...] successfully fetched from table: test-table - retries: 2