From 1c6f3aaa4019a4c4ee9b16446ff8af5f31be4540 Mon Sep 17 00:00:00 2001 From: peter-csala <57183693+peter-csala@users.noreply.github.com> Date: Wed, 18 Sep 2024 10:40:36 +0200 Subject: [PATCH] Report last attempt as error if it would be handled (#2291) Report last attempt as error if it would be handled. Resolves #2162. --- docs/advanced/telemetry.md | 4 +- docs/strategies/retry.md | 12 +-- .../Retry/RetryResilienceStrategy.cs | 12 ++- src/Polly.Core/Telemetry/TelemetryUtil.cs | 37 ++++++-- src/Snippets/Docs/Telemetry.cs | 4 +- .../Retry/RetryResilienceStrategyTests.cs | 84 ++++++++++++++++++- .../Telemetry/TelemetryUtilTests.cs | 17 +++- 7 files changed, 151 insertions(+), 19 deletions(-) diff --git a/docs/advanced/telemetry.md b/docs/advanced/telemetry.md index 46ece083b3c..45057d5a1dc 100644 --- a/docs/advanced/telemetry.md +++ b/docs/advanced/telemetry.md @@ -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(); @@ -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(); diff --git a/docs/strategies/retry.md b/docs/strategies/retry.md index 4b4bc349fa3..885cb65a649 100644 --- a/docs/strategies/retry.md +++ b/docs/strategies/retry.md @@ -115,10 +115,10 @@ new ResiliencePipelineBuilder().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: @@ -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 @@ -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). diff --git a/src/Polly.Core/Retry/RetryResilienceStrategy.cs b/src/Polly.Core/Retry/RetryResilienceStrategy.cs index 484b78d48cf..6402875d69b 100644 --- a/src/Polly.Core/Retry/RetryResilienceStrategy.cs +++ b/src/Polly.Core/Retry/RetryResilienceStrategy.cs @@ -57,9 +57,17 @@ protected internal override async ValueTask> ExecuteCore(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; } diff --git a/src/Polly.Core/Telemetry/TelemetryUtil.cs b/src/Polly.Core/Telemetry/TelemetryUtil.cs index 1bf6661bdd1..18d83777064 100644 --- a/src/Polly.Core/Telemetry/TelemetryUtil.cs +++ b/src/Polly.Core/Telemetry/TelemetryUtil.cs @@ -17,16 +17,43 @@ public static void ReportExecutionAttempt( 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( + ResilienceStrategyTelemetry telemetry, + ResilienceContext context, + Outcome 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( + ResilienceStrategyTelemetry telemetry, + ResilienceEvent resilienceEvent, + ResilienceContext context, + Outcome 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(resilienceEvent, context, outcome, args); } } diff --git a/src/Snippets/Docs/Telemetry.cs b/src/Snippets/Docs/Telemetry.cs index 2d94357b433..b18c5acb45e 100644 --- a/src/Snippets/Docs/Telemetry.cs +++ b/src/Snippets/Docs/Telemetry.cs @@ -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(); @@ -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(); diff --git a/test/Polly.Core.Tests/Retry/RetryResilienceStrategyTests.cs b/test/Polly.Core.Tests/Retry/RetryResilienceStrategyTests.cs index 16aa1188d85..c389351329b 100644 --- a/test/Polly.Core.Tests/Retry/RetryResilienceStrategyTests.cs +++ b/test/Polly.Core.Tests/Retry/RetryResilienceStrategyTests.cs @@ -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().Subject; - + args.Event.Severity.Should().Be(ResilienceEventSeverity.Information); attempt.Handled.Should().BeFalse(); attempt.AttemptNumber.Should().Be(0); attempt.Duration.Should().Be(TimeSpan.FromSeconds(1)); @@ -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(args.AttemptNumber == 0); + var called = false; + _telemetry = TestUtilities.CreateResilienceTelemetry(args => + { + // ignore OnRetry event + if (args.Arguments is OnRetryArguments) + { + return; + } + + var attempt = args.Arguments.Should().BeOfType().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(true); + var called = false; + _telemetry = TestUtilities.CreateResilienceTelemetry(args => + { + // ignore OnRetry event + if (args.Arguments is OnRetryArguments) + { + return; + } + + var attempt = args.Arguments.Should().BeOfType().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() { diff --git a/test/Polly.Core.Tests/Telemetry/TelemetryUtilTests.cs b/test/Polly.Core.Tests/Telemetry/TelemetryUtilTests.cs index 0e837506901..d43fc891443 100644 --- a/test/Polly.Core.Tests/Telemetry/TelemetryUtilTests.cs +++ b/test/Polly.Core.Tests/Telemetry/TelemetryUtilTests.cs @@ -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); @@ -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(); + } }