From fc7f583a555392e54c5035ab0cc591ffd63e2b98 Mon Sep 17 00:00:00 2001 From: peter-csala Date: Mon, 22 Apr 2024 12:54:52 +0200 Subject: [PATCH 1/4] Add unit to execution time in telemetry event --- docs/advanced/telemetry.md | 2 +- src/Polly.Extensions/Telemetry/Log.cs | 4 ++-- .../Telemetry/TelemetryListenerImplTests.cs | 6 +++--- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/docs/advanced/telemetry.md b/docs/advanced/telemetry.md index ef6d2af8b5..538b693c75 100644 --- a/docs/advanced/telemetry.md +++ b/docs/advanced/telemetry.md @@ -241,7 +241,7 @@ Resilience pipeline executing. Source: '{PipelineName}/{PipelineInstance}', Oper Resilience pipeline executed. Source: '{PipelineName}/{PipelineInstance}', Operation Key: '{OperationKey}', Result: '{Result}', Execution Health: '{ExecutionHealth}', Execution Time: {ExecutionTime}ms // This log is recorded upon the completion of every execution attempt. EventId = 3 -Execution attempt. Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', Operation Key: '{OperationKey}', Result: '{Result}', Handled: '{Handled}', Attempt: '{Attempt}', Execution Time: '{ExecutionTimeMs}' +Execution attempt. Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', Operation Key: '{OperationKey}', Result: '{Result}', Handled: '{Handled}', Attempt: '{Attempt}', Execution Time: '{ExecutionTime}ms' ``` ## Emitting telemetry events diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs index 49a21a95e1..f3591169fd 100644 --- a/src/Polly.Extensions/Telemetry/Log.cs +++ b/src/Polly.Extensions/Telemetry/Log.cs @@ -66,7 +66,7 @@ internal static partial class Log "Result: '{Result}', " + "Handled: '{Handled}', " + "Attempt: '{Attempt}', " + - "Execution Time: '{ExecutionTimeMs}'", + "Execution Time: {ExecutionTime}ms", EventName = "ExecutionAttempt", SkipEnabledCheck = true)] public static partial void ExecutionAttempt( @@ -79,6 +79,6 @@ internal static partial class Log object? result, bool handled, int attempt, - double executionTimeMs, + double executionTime, Exception? exception); } diff --git a/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs b/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs index 200f492957..22c1040752 100644 --- a/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs +++ b/test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs @@ -128,7 +128,7 @@ public void WriteExecutionAttempt_LoggingWithException_Ok() var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Be("Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be("Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: 123ms"); } [InlineData(true, true)] @@ -148,11 +148,11 @@ public void WriteExecutionAttempt_LoggingWithOutcome_Ok(bool noOutcome, bool han if (noOutcome) { string resultString = string.Empty; - messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: 123ms"); } else { - messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be($"Execution attempt. Source: 'my-pipeline/my-instance/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: 123ms"); } messages[0].LogLevel.Should().Be(LogLevel.Warning); From bd44d939c04d56eea7d9ba4f5e082cac6a55702f Mon Sep 17 00:00:00 2001 From: peter-csala Date: Mon, 22 Apr 2024 13:08:39 +0200 Subject: [PATCH 2/4] Use constants to reduce repetitive message format fragments --- src/Polly.Extensions/Telemetry/Log.cs | 33 ++++++++++++++++----------- 1 file changed, 20 insertions(+), 13 deletions(-) diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs index f3591169fd..ecf9b47173 100644 --- a/src/Polly.Extensions/Telemetry/Log.cs +++ b/src/Polly.Extensions/Telemetry/Log.cs @@ -8,13 +8,20 @@ namespace Polly.Telemetry; [ExcludeFromCodeCoverage] internal static partial class Log { + internal const string Separator = ", "; + internal const string SourceWithStrategy = "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}'"; + internal const string SourceWithoutStrategy = "Source: '{PipelineName}/{PipelineInstance}'"; + internal const string OperationKey = "Operation Key: '{OperationKey}'"; + internal const string Result = "Result: '{Result}'"; + internal const string ExecutionTime = "Execution Time: {ExecutionTime}ms"; + [LoggerMessage( EventId = 0, Message = "Resilience event occurred. " + "EventName: '{EventName}', " + - "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', " + - "Operation Key: '{OperationKey}', " + - "Result: '{Result}'", + SourceWithStrategy + Separator + + OperationKey + Separator + + Result, EventName = "ResilienceEvent")] public static partial void ResilienceEvent( this ILogger logger, @@ -31,8 +38,8 @@ internal static partial class Log 1, LogLevel.Debug, "Resilience pipeline executing. " + - "Source: '{PipelineName}/{PipelineInstance}', " + - "Operation Key: '{OperationKey}'", + SourceWithoutStrategy + Separator + + OperationKey, EventName = "StrategyExecuting")] public static partial void PipelineExecuting( this ILogger logger, @@ -43,10 +50,10 @@ internal static partial class Log [LoggerMessage( EventId = 2, Message = "Resilience pipeline executed. " + - "Source: '{PipelineName}/{PipelineInstance}', " + - "Operation Key: '{OperationKey}', " + - "Result: '{Result}', " + - "Execution Time: {ExecutionTime}ms", + SourceWithoutStrategy + Separator + + OperationKey + Separator + + Result + Separator + + ExecutionTime, EventName = "StrategyExecuted")] public static partial void PipelineExecuted( this ILogger logger, @@ -61,12 +68,12 @@ internal static partial class Log [LoggerMessage( EventId = 3, Message = "Execution attempt. " + - "Source: '{PipelineName}/{PipelineInstance}/{StrategyName}', " + - "Operation Key: '{OperationKey}', " + - "Result: '{Result}', " + + SourceWithStrategy + Separator + + OperationKey + Separator + + Result + Separator + "Handled: '{Handled}', " + "Attempt: '{Attempt}', " + - "Execution Time: {ExecutionTime}ms", + ExecutionTime, EventName = "ExecutionAttempt", SkipEnabledCheck = true)] public static partial void ExecutionAttempt( From 98c6ef533a5c60bca429d0b83348df20f21bb50e Mon Sep 17 00:00:00 2001 From: peter-csala Date: Mon, 22 Apr 2024 13:13:47 +0200 Subject: [PATCH 3/4] Update documentation --- docs/advanced/telemetry.md | 62 +++++++++++++++++++------------------- docs/strategies/hedging.md | 4 +-- docs/strategies/retry.md | 8 ++--- 3 files changed, 37 insertions(+), 37 deletions(-) diff --git a/docs/advanced/telemetry.md b/docs/advanced/telemetry.md index 538b693c75..18b7da1ab1 100644 --- a/docs/advanced/telemetry.md +++ b/docs/advanced/telemetry.md @@ -77,12 +77,12 @@ var serviceCollection = new ServiceCollection() The metrics are emitted under the `Polly` meter name. The subsequent sections provide insights into the metrics produced by Polly. Please note that any custom enriched tags are not depicted in the following tables. -Every telemetry event has the following tags: +Every telemetry event has the following optional tags: -- `pipeline.name`: Optional, comes from `ResiliencePipelineBuilder.Name`. -- `pipeline.instance`: Optional, comes from `ResiliencePipelineBuilder.InstanceName`. -- `strategy.name`: Optional, comes from `RetryStrategyOptions.Name`. -- `operation.key`: Optional, comes from `ResilienceContext.OperationKey`. +- `pipeline.name`: comes from `ResiliencePipelineBuilder.Name`. +- `pipeline.instance`: comes from `ResiliencePipelineBuilder.InstanceName`. +- `strategy.name`: comes from `RetryStrategyOptions.Name`. +- `operation.key`: comes from `ResilienceContext.OperationKey`. The sample below demonstrates how to assign these tags: @@ -126,15 +126,15 @@ These values are subsequently reflected in the following metering instruments ex Tags: -|Name|Description| -|---| ---| -|`event.name`| The name of the emitted event.| -|`event.severity`| The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).| -|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.| -|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.| -|`strategy.name`| The name of the strategy generating this event.| -|`operation.key`| The operation key associated with the call site. | -|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | +| Name | Description | +|---------------------|-------------------------------------------------------------------------------------------------------| +| `event.name` | The name of the emitted event. | +| `event.severity` | The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`). | +| `pipeline.name` | The name of the pipeline corresponding to the resilience pipeline. | +| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline. | +| `strategy.name` | The name of the strategy generating this event. | +| `operation.key` | The operation key associated with the call site. | +| `exception.type` | The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | #### Event names @@ -158,17 +158,17 @@ The `event.name` tag is reported by individual resilience strategies. The built- Tags: -|Name|Description| -|---| ---| -|`event.name`| The name of the emitted event. Currently, the event name is always `ExecutionAttempt`. | -|`event.severity`| The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`).| -|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.| -|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.| -|`strategy.name`| The name of the strategy generating this event.| -|`operation.key`| The operation key associated with the call site. | -|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | -|`attempt.number`| The execution attempt number, starting at 0 (0, 1, 2, etc.). | -|`attempt.handled`| Indicates if the execution outcome was handled. A handled outcome indicates execution failure and the need for retry (`true`, `false`). | +| Name | Description | +|---------------------|-----------------------------------------------------------------------------------------------------------------------------------------| +| `event.name` | The name of the emitted event. Currently, the event name is always `ExecutionAttempt`. | +| `event.severity` | The severity of the event (`Debug`, `Information`, `Warning`, `Error`, `Critical`). | +| `pipeline.name` | The name of the pipeline corresponding to the resilience pipeline. | +| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline. | +| `strategy.name` | The name of the strategy generating this event. | +| `operation.key` | The operation key associated with the call site. | +| `exception.type` | The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | +| `attempt.number` | The execution attempt number, starting at 0 (0, 1, 2, etc.). | +| `attempt.handled` | Indicates if the execution outcome was handled. A handled outcome indicates execution failure and the need for retry (`true`, `false`). | ### Instrument: `resilience.polly.pipeline.duration` @@ -179,12 +179,12 @@ Tags: Tags: -|Name|Description| -|---| ---| -|`pipeline.name`| The name of the pipeline corresponding to the resilience pipeline.| -|`pipeline.instance`| The instance name of the pipeline corresponding to the resilience pipeline.| -|`operation.key`| The operation key associated with the call site. | -|`exception.type`| The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | +| Name | Description | +|---------------------|-------------------------------------------------------------------------------------------------------| +| `pipeline.name` | The name of the pipeline corresponding to the resilience pipeline. | +| `pipeline.instance` | The instance name of the pipeline corresponding to the resilience pipeline. | +| `operation.key` | The operation key associated with the call site. | +| `exception.type` | The full name of the exception assigned to the execution result (`System.InvalidOperationException`). | ### Metering enrichment diff --git a/docs/strategies/hedging.md b/docs/strategies/hedging.md index c5af808899..4ed172c4ec 100644 --- a/docs/strategies/hedging.md +++ b/docs/strategies/hedging.md @@ -97,9 +97,9 @@ The reported `Execution Attempt` telemetry events' severity depends on the actio ```none Resilience event occurred. EventName: 'OnHedging', Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: '' -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: '1505.3839' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: 1505.3839ms -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: 'Exception of type 'CustomException' was thrown.', Handled: 'True', Attempt: '1', Execution Time: '1525.2899' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/Hedging', Operation Key: 'MyHedgingOperation', Result: 'Exception of type 'CustomException' was thrown.', Handled: 'True', Attempt: '1', Execution Time: 1525.2899ms CustomException: Exception of type 'CustomException' was thrown. at Program.<>c.<
b__0_2>d.MoveNext() ... diff --git a/docs/strategies/retry.md b/docs/strategies/retry.md index 7cfddc9e5b..08b6f9cc98 100644 --- a/docs/strategies/retry.md +++ b/docs/strategies/retry.md @@ -127,9 +127,9 @@ Here are some sample events: If the retry strategy does not perform any retries then the reported telemetry events' severity will be `Information`: ```none -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: '110.952' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: '1', Handled: 'False', Attempt: '0', Execution Time: 110.952ms -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'False', Attempt: '0', Execution Time: '5.2194' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'False', Attempt: '0', Execution Time: 5.2194ms System.Exception: Failed at Program.<>c.
b__0_1(ResilienceContext ctx) ... @@ -141,7 +141,7 @@ Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Oper If the retry strategy performs some retries then the reported telemetry events' severity will be `Warning`: ```none -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '0', Execution Time: '5.0397' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '0', Execution Time: 5.0397ms System.Exception: Failed at Program.<>c.
b__0_1(ResilienceContext ctx) ... @@ -154,7 +154,7 @@ Resilience event occurred. EventName: 'OnRetry', Source: 'MyPipeline/MyPipelineI at Polly.ResiliencePipeline.<>c.<b__1_0>d.MoveNext() in /_/src/Polly.Core/ResiliencePipeline.Async.cs:line 67 -Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '1', Execution Time: '0.1159' +Execution attempt. Source: 'MyPipeline/MyPipelineInstance/MyRetryStrategy', Operation Key: 'MyRetryableOperation', Result: 'Failed', Handled: 'True', Attempt: '1', Execution Time: 0.1159ms System.Exception: Failed at Program.<>c.
b__0_1(ResilienceContext ctx) ... From 00ea17c19c9864285e2f7af57bba3312c05657ac Mon Sep 17 00:00:00 2001 From: peter-csala Date: Mon, 22 Apr 2024 15:31:04 +0200 Subject: [PATCH 4/4] Rename executionTime to executionTimeMs --- src/Polly.Extensions/Telemetry/Log.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs index ecf9b47173..cc7746880b 100644 --- a/src/Polly.Extensions/Telemetry/Log.cs +++ b/src/Polly.Extensions/Telemetry/Log.cs @@ -13,7 +13,7 @@ internal static partial class Log internal const string SourceWithoutStrategy = "Source: '{PipelineName}/{PipelineInstance}'"; internal const string OperationKey = "Operation Key: '{OperationKey}'"; internal const string Result = "Result: '{Result}'"; - internal const string ExecutionTime = "Execution Time: {ExecutionTime}ms"; + internal const string ExecutionTime = "Execution Time: {ExecutionTimeMs}ms"; [LoggerMessage( EventId = 0, @@ -62,7 +62,7 @@ internal static partial class Log string pipelineInstance, string? operationKey, object? result, - double executionTime, + double executionTimeMs, Exception? exception); [LoggerMessage( @@ -86,6 +86,6 @@ internal static partial class Log object? result, bool handled, int attempt, - double executionTime, + double executionTimeMs, Exception? exception); }