Respect override for PipelineExecuting and PipelineExecuted (#2752)

Resolves #2750.

Author: peter-csala

docs/advanced/telemetry.md

@@ -283,3 +283,19 @@ services.AddResiliencePipeline("my-strategy", (builder, context) =>
 });
 ```
 <!-- endSnippet -->
+
+There are telemetry events which are specific to strategies. Like the above overrides are specific to Retry (and partially to Hedging).
+
+> [!TIP]
+> If you want to define *X* severity for the `ExecutionAttempt` event of Retry and *Y* severity for the `ExecutionAttempt` event of Hedging
+> then use the `args.Source.StrategyName` information as well inside the switch expression.
+
+There are also pipeline specific telemetry events
+
+- `PipelineExecuting`: by default reported at `Debug` level
+- `PipelineExecuted`: by default reported at `Information` level
+
+In general the suggestion is to use `SeverityProvider` to override strategy specific telemetry events' severity.
+
+> [!TIP]
+> If you want to suppress the specific event completely then use `ResilienceEventSeverity.None`.

src/Polly.Extensions/Telemetry/Log.cs

@@ -35,14 +35,14 @@ public static partial void ResilienceEvent(
         Exception? exception);
 
     [LoggerMessage(
-        1,
-        LogLevel.Debug,
-        "Resilience pipeline executing. " +
+        EventId = 1,
+        Message = "Resilience pipeline executing. " +
         SourceWithoutStrategy + Separator +
         OperationKey,
         EventName = "StrategyExecuting")]
     public static partial void PipelineExecuting(
         this ILogger logger,
+        LogLevel logLevel,
         string pipelineName,
         string pipelineInstance,
         string? operationKey);
@@ -74,8 +74,7 @@ public static partial void PipelineExecuted(
                 "Handled: '{Handled}', " +
                 "Attempt: '{Attempt}', " +
                 ExecutionTime,
-        EventName = "ExecutionAttempt",
-        SkipEnabledCheck = true)]
+        EventName = "ExecutionAttempt")]
     public static partial void ExecutionAttempt(
         this ILogger logger,
         LogLevel level,

src/Polly.Extensions/Telemetry/TelemetryListenerImpl.cs

@@ -54,12 +54,9 @@ public override void Write<TResult, TArgs>(in TelemetryEventArguments<TResult, T
             }
         }
 
-        var severity = args.Event.Severity;
-
-        if (_severityProvider is { } provider)
-        {
-            severity = provider(new SeverityProviderArguments(args.Source, args.Event, args.Context));
-        }
+        var severity = _severityProvider is { } provider
+            ? provider(new SeverityProviderArguments(args.Source, args.Event, args.Context))
+            : args.Event.Severity;
 
         LogEvent(in args, severity);
         MeterEvent(in args, severity);
@@ -166,53 +163,56 @@ private void LogEvent<TResult, TArgs>(in TelemetryEventArguments<TResult, TArgs>
     {
         var result = GetResult(args.Context, args.Outcome);
         var level = severity.AsLogLevel();
+        var pipelineName = args.Source.PipelineName.GetValueOrPlaceholder();
+        var pipelineInstanceName = args.Source.PipelineInstanceName.GetValueOrPlaceholder();
+        var strategyName = args.Source.StrategyName.GetValueOrPlaceholder();
+        var operationKey = args.Context.OperationKey;
+        var exception = args.Outcome?.Exception;
 
         if (GetArgs<TArgs, PipelineExecutingArguments>(args.Arguments, out _))
         {
             _logger.PipelineExecuting(
-                args.Source.PipelineName.GetValueOrPlaceholder(),
-                args.Source.PipelineInstanceName.GetValueOrPlaceholder(),
-                args.Context.OperationKey);
+                level,
+                pipelineName,
+                pipelineInstanceName,
+                operationKey);
         }
         else if (GetArgs<TArgs, PipelineExecutedArguments>(args.Arguments, out var pipelineExecuted))
         {
             _logger.PipelineExecuted(
-                LogLevel.Debug,
-                args.Source.PipelineName.GetValueOrPlaceholder(),
-                args.Source.PipelineInstanceName.GetValueOrPlaceholder(),
-                args.Context.OperationKey,
-                GetResult(args.Context, args.Outcome),
+                level,
+                pipelineName,
+                pipelineInstanceName,
+                operationKey,
+                result,
                 pipelineExecuted.Duration.TotalMilliseconds,
-                args.Outcome?.Exception);
+                exception);
         }
         else if (GetArgs<TArgs, ExecutionAttemptArguments>(args.Arguments, out var executionAttempt))
         {
-            if (_logger.IsEnabled(level))
-            {
-                _logger.ExecutionAttempt(
-                    level,
-                    args.Source.PipelineName.GetValueOrPlaceholder(),
-                    args.Source.PipelineInstanceName.GetValueOrPlaceholder(),
-                    args.Source.StrategyName.GetValueOrPlaceholder(),
-                    args.Context.OperationKey,
-                    result,
-                    executionAttempt.Handled,
-                    executionAttempt.AttemptNumber,
-                    executionAttempt.Duration.TotalMilliseconds,
-                    args.Outcome?.Exception);
-            }
+            _logger.ExecutionAttempt(
+                level,
+                pipelineName,
+                pipelineInstanceName,
+                strategyName,
+                operationKey,
+                result,
+                executionAttempt.Handled,
+                executionAttempt.AttemptNumber,
+                executionAttempt.Duration.TotalMilliseconds,
+                exception);
         }
         else
         {
             _logger.ResilienceEvent(
                 level,
                 args.Event.EventName,
-                args.Source.PipelineName.GetValueOrPlaceholder(),
-                args.Source.PipelineInstanceName.GetValueOrPlaceholder(),
-                args.Source.StrategyName.GetValueOrPlaceholder(),
-                args.Context.OperationKey,
+                pipelineName,
+                pipelineInstanceName,
+                strategyName,
+                operationKey,
                 result,
-                args.Outcome?.Exception);
+                exception);
         }
     }
 

test/Polly.Extensions.Tests/Telemetry/TelemetryListenerImplTests.cs

@@ -291,8 +291,8 @@ public void WriteEvent_MeteringWithEnrichers_Ok(int count)
 
         const int DefaultDimensions = 6;
 
-        var telemetry = Create(new[]
-        {
+        var telemetry = Create(
+        [
             new CallbackEnricher(context =>
             {
                 for (int i = 0; i < count; i++)
@@ -305,7 +305,7 @@ public void WriteEvent_MeteringWithEnrichers_Ok(int count)
             {
                 context.Tags.Add(new KeyValuePair<string, object?>("other", "other-value"));
             })
-        });
+        ]);
 
         ReportEvent(telemetry, Outcome.FromResult<object>(true));
 
@@ -357,16 +357,17 @@ public void PipelineExecution_Logged(bool exception)
         var outcome = exception ? Outcome.FromException<object>(new InvalidOperationException("dummy message")) : Outcome.FromResult((object)10);
         var result = exception ? "dummy message" : "10";
 
-        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutingArguments), context: context);
-        ReportEvent(telemetry, outcome: outcome, arg: new PipelineExecutedArguments(TimeSpan.FromSeconds(10)), context: context);
+        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutingArguments), context: context, severity: ResilienceEventSeverity.Debug);
+        ReportEvent(telemetry, outcome: outcome, arg: new PipelineExecutedArguments(TimeSpan.FromSeconds(10)), context: context, severity: ResilienceEventSeverity.Information);
 
         var messages = _logger.GetRecords(new EventId(1, "StrategyExecuting")).ToList();
         messages.Count.ShouldBe(1);
         messages[0].Message.ShouldBe("Resilience pipeline executing. Source: 'my-pipeline/my-instance', Operation Key: 'op-key'");
+        messages[0].LogLevel.ShouldBe(LogLevel.Debug);
         messages = [.. _logger.GetRecords(new EventId(2, "StrategyExecuted"))];
         messages.Count.ShouldBe(1);
         messages[0].Message.ShouldMatch($"Resilience pipeline executed. Source: 'my-pipeline/my-instance', Operation Key: 'op-key', Result: '{result}', Execution Time: 10000ms");
-        messages[0].LogLevel.ShouldBe(LogLevel.Debug);
+        messages[0].LogLevel.ShouldBe(LogLevel.Information);
     }
 
     [Fact]
@@ -404,8 +405,8 @@ public void PipelineExecution_Metered(bool exception)
         var outcome = exception ? Outcome.FromException<object>(new InvalidOperationException("dummy message")) : Outcome.FromResult((object)10);
         var result = exception ? "dummy message" : "10";
 
-        var telemetry = Create(new[]
-        {
+        var telemetry = Create(
+        [
             new CallbackEnricher(context =>
             {
                 if (exception)
@@ -415,7 +416,7 @@ public void PipelineExecution_Metered(bool exception)
 
                 context.Tags.Add(new("custom-tag", "custom-tag-value"));
             })
-        });
+        ]);
 
         ReportEvent(telemetry, outcome: outcome, arg: new PipelineExecutedArguments(TimeSpan.FromSeconds(10)), context: context);
 
@@ -489,6 +490,59 @@ public void SeverityProvider_EnsureRespected()
         called.ShouldBeTrue();
     }
 
+    [Fact]
+    public void SeverityProvider_EnsureRespected_For_PipelineEvents()
+    {
+        var context = ResilienceContextPool.Shared.Get("op-key", TestCancellation.Token).WithResultType<int>();
+        var outcome = Outcome.FromException<object>(new InvalidOperationException("dummy message"));
+
+        var severity = ResilienceEventSeverity.Critical;
+        var expectedLogLevel = LogLevel.Critical;
+
+        const string PipelineExecuting = nameof(PipelineExecuting);
+        const string PipelineExecuted = nameof(PipelineExecuted);
+
+        var telemetry = Create(configure: options =>
+        {
+            options.SeverityProvider = args =>
+            {
+                return args.Event.EventName switch
+                {
+                    PipelineExecuting => severity,
+                    PipelineExecuted => severity,
+                    _ => ResilienceEventSeverity.None
+                };
+            };
+        });
+
+        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutingArguments), context: context, eventName: PipelineExecuting);
+        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutedArguments), context: context, eventName: PipelineExecuted);
+
+        _logger.GetRecords(new EventId(1, "StrategyExecuting")).Single().LogLevel.ShouldBe(expectedLogLevel);
+        _logger.GetRecords(new EventId(2, "StrategyExecuted")).Single().LogLevel.ShouldBe(expectedLogLevel);
+    }
+
+    [InlineData((ResilienceEventSeverity)(-1))]
+    [InlineData((ResilienceEventSeverity)6)]
+    [Theory]
+    public void SeverityProvider_EnsureLogLevelChecked(ResilienceEventSeverity severity)
+    {
+        var context = ResilienceContextPool.Shared.Get("op-key", TestCancellation.Token).WithResultType<int>();
+        var outcome = Outcome.FromException<object>(new InvalidOperationException("dummy message"));
+        var telemetry = Create(configure: options => options.SeverityProvider = args => severity);
+
+        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutingArguments), context: context, eventName: "PipelineExecuting");
+        ReportEvent(telemetry, outcome: outcome, arg: default(ExecutionAttemptArguments), context: context, eventName: "ExecutionAttempt");
+        ReportEvent(telemetry, outcome: outcome, arg: default(Retry.OnRetryArguments<object>), context: context, eventName: "OnRetry");
+        ReportEvent(telemetry, outcome: outcome, arg: default(PipelineExecutedArguments), context: context, eventName: "PipelineExecuted");
+
+        var expectedLogLevel = LogLevel.None;
+        _logger.GetRecords(new EventId(0, "ResilienceEvent")).Single().LogLevel.ShouldBe(expectedLogLevel);
+        _logger.GetRecords(new EventId(1, "StrategyExecuting")).Single().LogLevel.ShouldBe(expectedLogLevel);
+        _logger.GetRecords(new EventId(2, "StrategyExecuted")).Single().LogLevel.ShouldBe(expectedLogLevel);
+        _logger.GetRecords(new EventId(3, "ExecutionAttempt")).Single().LogLevel.ShouldBe(expectedLogLevel);
+    }
+
     private List<Dictionary<string, object?>> GetEvents(string eventName) => [.. _events.Where(e => e.Name == eventName).Select(v => v.Tags)];
 
     private TelemetryListenerImpl Create(IEnumerable<MeteringEnricher>? enrichers = null, Action<TelemetryOptions>? configure = null)
@@ -522,19 +576,22 @@ private static void ReportEvent(
         string? instanceName = "my-instance",
         ResilienceContext? context = null,
         TestArguments? arg = null,
-        ResilienceEventSeverity severity = ResilienceEventSeverity.Warning) => ReportEvent<TestArguments>(telemetry, outcome, instanceName, context, arg!, severity);
+        ResilienceEventSeverity severity = ResilienceEventSeverity.Warning,
+        string eventName = "my-event")
+        => ReportEvent<TestArguments>(telemetry, outcome, instanceName, context, arg!, severity, eventName);
 
     private static void ReportEvent<TArgs>(
         TelemetryListenerImpl telemetry,
         Outcome<object>? outcome,
         string? instanceName = "my-instance",
         ResilienceContext? context = null,
         TArgs arg = default!,
-        ResilienceEventSeverity severity = ResilienceEventSeverity.Warning) =>
+        ResilienceEventSeverity severity = ResilienceEventSeverity.Warning,
+        string eventName = "my-event") =>
         telemetry.Write(
             new TelemetryEventArguments<object, TArgs>(
                 new ResilienceTelemetrySource("my-pipeline", instanceName, "my-strategy"),
-                new ResilienceEvent(severity, "my-event"),
+                new ResilienceEvent(severity, eventName),
                 context ?? ResilienceContextPool.Shared.Get("op-key"),
                 arg!,
                 outcome));