Skip to content

Commit

Permalink
Report last attempt as error if it would be handled (#2291)
Browse files Browse the repository at this point in the history
Report last attempt as error if it would be handled.
Resolves #2162.
  • Loading branch information
peter-csala authored Sep 18, 2024
1 parent 7d0c672 commit 1c6f3aa
Show file tree
Hide file tree
Showing 7 changed files with 151 additions and 19 deletions.
4 changes: 2 additions & 2 deletions docs/advanced/telemetry.md
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,7 @@ telemetryOptions.MeteringEnrichers.Add(new MyMeteringEnricher());
// Configure telemetry listeners
telemetryOptions.TelemetryListeners.Add(new MyTelemetryListener());

var builder = new ResiliencePipelineBuilder()
var pipeline = new ResiliencePipelineBuilder()
.AddTimeout(TimeSpan.FromSeconds(1))
.ConfigureTelemetry(telemetryOptions) // This method enables telemetry in the builder
.Build();
Expand Down Expand Up @@ -223,7 +223,7 @@ var telemetryOptions = new TelemetryOptions();
// Register custom enricher
telemetryOptions.MeteringEnrichers.Add(new CustomMeteringEnricher());

var builder = new ResiliencePipelineBuilder()
var pipeline = new ResiliencePipelineBuilder()
.AddRetry(new RetryStrategyOptions())
.ConfigureTelemetry(telemetryOptions) // This method enables telemetry in the builder
.Build();
Expand Down
12 changes: 7 additions & 5 deletions docs/strategies/retry.md
Original file line number Diff line number Diff line change
Expand Up @@ -115,10 +115,10 @@ new ResiliencePipelineBuilder<HttpResponseMessage>().AddRetry(optionsExtractDela

The retry strategy reports the following telemetry events:

| Event Name | Event Severity | When? |
|--------------------|---------------------------|-------------------------------------------------------|
| `ExecutionAttempt` | `Information` / `Warning` | Just before the strategy calculates the next delay |
| `OnRetry` | `Warning` | Just before the strategy calls the `OnRetry` delegate |
| Event Name | Event Severity | When? |
|--------------------|-------------------------------------|-------------------------------------------------------|
| `ExecutionAttempt` | `Information` / `Warning` / `Error` | Just before the strategy calculates the next delay |
| `OnRetry` | `Warning` | Just before the strategy calls the `OnRetry` delegate |

Here are some sample events:

Expand All @@ -138,7 +138,7 @@ Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Oper

### Handled case

If the retry strategy performs some retries then the reported telemetry events' severity will be `Warning`:
If the retry strategy performs some retries then the reported telemetry events' severity will be `Warning`. If the retry strategy runs out of retry attempts then the last event's severity will be `Error`:

```none
Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '0', Execution Time: 5.0397ms
Expand Down Expand Up @@ -167,6 +167,8 @@ Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Oper
> On the other hand the `Execution attempt` event will be **always** reported regardless whether the strategy has to perform any retries.
>
> Also remember that `Attempt: '0'` relates to the original execution attempt.
>
> Only the last error event will have `Error` severity if it was unsuccessful.
For further information please check out the [telemetry page](../advanced/telemetry.md).

Expand Down
12 changes: 10 additions & 2 deletions src/Polly.Core/Retry/RetryResilienceStrategy.cs
Original file line number Diff line number Diff line change
Expand Up @@ -57,9 +57,17 @@ protected internal override async ValueTask<Outcome<T>> ExecuteCore<TState>(Func
var handle = await ShouldHandle(shouldRetryArgs).ConfigureAwait(context.ContinueOnCapturedContext);
var executionTime = _timeProvider.GetElapsedTime(startTimestamp);

TelemetryUtil.ReportExecutionAttempt(_telemetry, context, outcome, attempt, executionTime, handle);
var isLastAttempt = IsLastAttempt(attempt, out bool incrementAttempts);
if (isLastAttempt)
{
TelemetryUtil.ReportFinalExecutionAttempt(_telemetry, context, outcome, attempt, executionTime, handle);
}
else
{
TelemetryUtil.ReportExecutionAttempt(_telemetry, context, outcome, attempt, executionTime, handle);
}

if (context.CancellationToken.IsCancellationRequested || IsLastAttempt(attempt, out bool incrementAttempts) || !handle)
if (context.CancellationToken.IsCancellationRequested || isLastAttempt || !handle)
{
return outcome;
}
Expand Down
37 changes: 32 additions & 5 deletions src/Polly.Core/Telemetry/TelemetryUtil.cs
Original file line number Diff line number Diff line change
Expand Up @@ -17,16 +17,43 @@ public static void ReportExecutionAttempt<TResult>(
int attempt,
TimeSpan executionTime,
bool handled)
{
ReportAttempt(
telemetry,
new(handled ? ResilienceEventSeverity.Warning : ResilienceEventSeverity.Information, ExecutionAttempt),
context,
outcome,
new ExecutionAttemptArguments(attempt, executionTime, handled));
}

public static void ReportFinalExecutionAttempt<TResult>(
ResilienceStrategyTelemetry telemetry,
ResilienceContext context,
Outcome<TResult> outcome,
int attempt,
TimeSpan executionTime,
bool handled)
{
ReportAttempt(
telemetry,
new(handled ? ResilienceEventSeverity.Error : ResilienceEventSeverity.Information, ExecutionAttempt),
context,
outcome,
new ExecutionAttemptArguments(attempt, executionTime, handled));
}

private static void ReportAttempt<TResult>(
ResilienceStrategyTelemetry telemetry,
ResilienceEvent resilienceEvent,
ResilienceContext context,
Outcome<TResult> outcome,
ExecutionAttemptArguments args)
{
if (!telemetry.Enabled)
{
return;
}

telemetry.Report(
new(handled ? ResilienceEventSeverity.Warning : ResilienceEventSeverity.Information, ExecutionAttempt),
context,
outcome,
new ExecutionAttemptArguments(attempt, executionTime, handled));
telemetry.Report<ExecutionAttemptArguments, TResult>(resilienceEvent, context, outcome, args);
}
}
4 changes: 2 additions & 2 deletions src/Snippets/Docs/Telemetry.cs
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ public static void ConfigureTelemetry()
// Configure telemetry listeners
telemetryOptions.TelemetryListeners.Add(new MyTelemetryListener());

var builder = new ResiliencePipelineBuilder()
var pipeline = new ResiliencePipelineBuilder()
.AddTimeout(TimeSpan.FromSeconds(1))
.ConfigureTelemetry(telemetryOptions) // This method enables telemetry in the builder
.Build();
Expand Down Expand Up @@ -109,7 +109,7 @@ public static void MeteringEnricherRegistration()
// Register custom enricher
telemetryOptions.MeteringEnrichers.Add(new CustomMeteringEnricher());

var builder = new ResiliencePipelineBuilder()
var pipeline = new ResiliencePipelineBuilder()
.AddRetry(new RetryStrategyOptions())
.ConfigureTelemetry(telemetryOptions) // This method enables telemetry in the builder
.Build();
Expand Down
84 changes: 82 additions & 2 deletions test/Polly.Core.Tests/Retry/RetryResilienceStrategyTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -292,13 +292,13 @@ await sut.ExecuteAsync(_ =>
}

[Fact]
public void Execute_EnsureAttemptReported()
public void Execute_NotHandledOriginalAttempt_EnsureAttemptReported()
{
var called = false;
_telemetry = TestUtilities.CreateResilienceTelemetry(args =>
{
var attempt = args.Arguments.Should().BeOfType<ExecutionAttemptArguments>().Subject;
args.Event.Severity.Should().Be(ResilienceEventSeverity.Information);
attempt.Handled.Should().BeFalse();
attempt.AttemptNumber.Should().Be(0);
attempt.Duration.Should().Be(TimeSpan.FromSeconds(1));
Expand All @@ -316,6 +316,86 @@ public void Execute_EnsureAttemptReported()
called.Should().BeTrue();
}

[Fact]
public void Execute_NotHandledFinalAttempt_EnsureAttemptReported()
{
_options.MaxRetryAttempts = 1;
_options.Delay = TimeSpan.Zero;

// original attempt is handled, retried attempt is not handled
_options.ShouldHandle = args => new ValueTask<bool>(args.AttemptNumber == 0);
var called = false;
_telemetry = TestUtilities.CreateResilienceTelemetry(args =>
{
// ignore OnRetry event
if (args.Arguments is OnRetryArguments<object>)
{
return;
}
var attempt = args.Arguments.Should().BeOfType<ExecutionAttemptArguments>().Subject;
if (attempt.AttemptNumber == 0)
{
args.Event.Severity.Should().Be(ResilienceEventSeverity.Warning);
}
else
{
args.Event.Severity.Should().Be(ResilienceEventSeverity.Information);
}
called = true;
});

var sut = CreateSut();

sut.Execute(() =>
{
_timeProvider.Advance(TimeSpan.FromSeconds(1));
return 0;
});

called.Should().BeTrue();
}

[Fact]
public void Execute_HandledFinalAttempt_EnsureAttemptReported()
{
_options.MaxRetryAttempts = 1;
_options.Delay = TimeSpan.Zero;
_options.ShouldHandle = _ => new ValueTask<bool>(true);
var called = false;
_telemetry = TestUtilities.CreateResilienceTelemetry(args =>
{
// ignore OnRetry event
if (args.Arguments is OnRetryArguments<object>)
{
return;
}
var attempt = args.Arguments.Should().BeOfType<ExecutionAttemptArguments>().Subject;
if (attempt.AttemptNumber == 0)
{
args.Event.Severity.Should().Be(ResilienceEventSeverity.Warning);
}
else
{
args.Event.Severity.Should().Be(ResilienceEventSeverity.Error);
}
called = true;
});

var sut = CreateSut();

sut.Execute(() =>
{
_timeProvider.Advance(TimeSpan.FromSeconds(1));
return 0;
});

called.Should().BeTrue();
}

[Fact]
public async Task OnRetry_EnsureTelemetry()
{
Expand Down
17 changes: 16 additions & 1 deletion test/Polly.Core.Tests/Telemetry/TelemetryUtilTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,6 @@ public class TelemetryUtilTests
public void ReportExecutionAttempt_Ok(bool handled, ResilienceEventSeverity severity)
{
var asserted = false;
var props = new ResilienceProperties();
var listener = TestUtilities.CreateResilienceTelemetry(args =>
{
args.Event.Severity.Should().Be(severity);
Expand All @@ -20,4 +19,20 @@ public void ReportExecutionAttempt_Ok(bool handled, ResilienceEventSeverity seve
TelemetryUtil.ReportExecutionAttempt(listener, ResilienceContextPool.Shared.Get(), Outcome.FromResult("dummy"), 0, TimeSpan.Zero, handled);
asserted.Should().BeTrue();
}

[InlineData(true, ResilienceEventSeverity.Error)]
[InlineData(false, ResilienceEventSeverity.Information)]
[Theory]
public void ReportFinalExecutionAttempt_Ok(bool handled, ResilienceEventSeverity severity)
{
var asserted = false;
var listener = TestUtilities.CreateResilienceTelemetry(args =>
{
args.Event.Severity.Should().Be(severity);
asserted = true;
});

TelemetryUtil.ReportFinalExecutionAttempt(listener, ResilienceContextPool.Shared.Get(), Outcome.FromResult("dummy"), 1, TimeSpan.Zero, handled);
asserted.Should().BeTrue();
}
}

0 comments on commit 1c6f3aa

Please sign in to comment.