diff --git a/docs/advanced/telemetry.md b/docs/advanced/telemetry.md index ef6d2af8b5..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 @@ -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/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) ... diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs index 49a21a95e1..cc7746880b 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: {ExecutionTimeMs}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 @@ public static partial void ResilienceEvent( 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 @@ public static partial void PipelineExecuting( [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, @@ -55,18 +62,18 @@ public static partial void PipelineExecuted( string pipelineInstance, string? operationKey, object? result, - double executionTime, + double executionTimeMs, Exception? exception); [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: '{ExecutionTimeMs}'", + ExecutionTime, EventName = "ExecutionAttempt", SkipEnabledCheck = true)] public static partial void ExecutionAttempt( 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);