How to institute logging from Poly ResiliencePipeline for success after failure

In C# I'm using Polly Version=8.4.1 and a reusable retry ResiliencePipeline via ResiliencePipelineBuilder.

    return new ResiliencePipelineBuilder()
        .AddRetry(new RetryStrategyOptions
        {
            MaxRetryAttempts = 5,
            DelayGenerator = {blah(blah, blah);},
            ShouldHandle = args => { blahblah(blah); }
        }).Build();

I want to be able to add logging for when the operation initially fails but subsequently succeeds. Something like:

{operations} recovered after 3 tries, in 22 seconds

I believe in older versions of Polly this would be accomplished by injecting handling via the OnSuccess operation.

How is this done in v8.x?

Solution

On way to solve this problem is by introducing a custom ResilienceStrategy. This strategy wraps your retry strategy and captures the execution time via a simple Stopwatch. It also retrieves the attempt count via the usage of ResilienceContext.

Here you can find a working example: https://dotnetfiddle.net/9uEFbl.

The custom strategy

public sealed class RetryReporterStrategy: ResilienceStrategy
{
    private readonly ResiliencePropertyKey<int> _attemptCount;
    public RetryReporterStrategy(ResiliencePropertyKey<int> attemptCount)
    {
        _attemptCount = attemptCount;
    }

    protected override async ValueTask<Outcome<TResult>> ExecuteCore<TResult, TState>(
        Func<ResilienceContext, TState, ValueTask<Outcome<TResult>>> callback,
        ResilienceContext context,
        TState state)
    {
        var watch = Stopwatch.StartNew();
        var result = await callback(context, state).ConfigureAwait(context.ContinueOnCapturedContext);
        watch.Stop();

        context.Properties.TryGetValue(_attemptCount, out var attempts);
        if (result.Exception is not null)
            Console.WriteLine($"The operation failed after {attempts+1} tries, in {watch.Elapsed.TotalSeconds} seconds");
        else
            Console.WriteLine($"The operation succeeded after {attempts+1} tries, in {watch.Elapsed.TotalSeconds} seconds");

        return result;
    }
}

The strategy receives a ResiliencePropertyKey which is used to set & get the attempt number on the context
- The attempt number for the retry strategy starts from 0 because the original user function's execution does not count as retry
The ExecuteCore starts the stopwatch, executes the wrapped strategy (var result = await callback(...)` and stops the stopwatch
Then it fetches the attempt count
- Please bear in mind that this code demonstrates the basic idea WITHOUT any proper error handling
- In your production code please make sure that TryGetValue returns true before you start using the attempts variable
Before the function returns the result it performs some logging
- This branching logic is meant only for demonstration
- In your production code it could be more sophisticated

Let's wire up

public static class RetryExtensions
{ 
    public static ResiliencePipelineBuilder AddFancyRetry(this ResiliencePipelineBuilder builder, RetryStrategyOptions options)
    {
        ResiliencePropertyKey<int> attemptCountKey = new(nameof(attemptCountKey));
        return builder
        .AddStrategy(context => new RetryReporterStrategy(attemptCountKey), options)
        .AddRetry(new() {
            BackoffType = options.BackoffType,
            Delay = options.Delay,
            DelayGenerator = options.DelayGenerator,
            MaxDelay = options.MaxDelay,
            MaxRetryAttempts = options.MaxRetryAttempts,
            Name = options.Name,
            Randomizer = options.Randomizer,
            OnRetry = args =>
            {
                args.Context.Properties.Set(attemptCountKey, args.AttemptNumber);
                return options.OnRetry?.Invoke(args) ?? default;
            },
            ShouldHandle = options.ShouldHandle,
            UseJitter = options.UseJitter
        });
    }
}

An extension method is defined against ResiliencePipelineBuilder to ease the usage
- In your production code you might need to introduce a generic variant as well against the ResiliencePipelineBuilder<TResult> type
First the function defines a ResiliencePropertyKey which is used for communication (via the context) between our custom strategy and the retry
It registers our RetryReporterStrategy first as the outer strategy into the pipeline (.AddStrategy)
Then it adds a retry as the inner strategy (.AddRetry)
- It basically copies blindly all values from the options parameter, except for OnRetry
  - First it sets the attempt number on the context
  - Then it performs the OnRetry delegate if it was provided

Usage samples

A happy path

var pipeline = new ResiliencePipelineBuilder()
    .AddFancyRetry(new () {
        ShouldHandle = args => PredicateResult.True(),
        MaxRetryAttempts = 3,
        Delay = TimeSpan.FromSeconds(1),
    })
    .Build();

await pipeline.ExecuteAsync(async ct => await Task.Delay(100, ct), CancellationToken.None);

The output

The operation succeeded after 3 tries, in 3.4203751 seconds

The Task.Delay have been executed four times >> 0.4s
- Four times: the original attempt + three retry attempts
Before each retry attempt the strategy waited a second >> 3.0s
and finally there is a negligible Polly pipeline overhead >> 0.02s

An unhappy path

pipeline = new ResiliencePipelineBuilder()
    .AddFancyRetry(new () {
        ShouldHandle = new PredicateBuilder().Handle<Exception>(),
        MaxRetryAttempts = 5,
        Delay = TimeSpan.FromMilliseconds(500),
        OnRetry = static args => 
        {
            Console.WriteLine("OnRetry");
            return default;
        }
    })
    .Build();

await pipeline.ExecuteAsync(async ct => 
{ 
    await Task.Delay(100, ct); 
    throw new Exception(); 
}, CancellationToken.None);

The output

OnRetry
OnRetry
OnRetry
OnRetry
OnRetry
The operation failed after 5 tries, in 3.1136394 seconds
Unhandled exception. System.Exception: Exception of type 'System.Exception' was thrown.

In this scenario we had

6 execution attempts >> 0.6s
5 half second delays >> 2.5s
and the Polly overhead >> 0.01s