Fix logging of execution attempt (#1341)

src/Polly.Extensions/Telemetry/Log.cs

@@ -27,6 +27,16 @@ internal static class Log
                 "Strategy Key: '{StrategyKey}', " +
                 "Result: '{Result}'";
 
+    private const string ExecutionAttemptMessage = "Execution attempt. " +
+                "Builder Name: '{BuilderName}', " +
+                "Strategy Name: '{StrategyName}', " +
+                "Strategy Type: '{StrategyType}', " +
+                "Strategy Key: '{StrategyKey}', " +
+                "Result: '{Result}', " +
+                "Handled: '{Handled}', " +
+                "Attempt: '{Attempt}', " +
+                "Execution Time: '{ExecutionTimeMs}'";
+
     private const string StrategyExecutingMessage = "Resilience strategy executing. " +
             "Builder Name: '{BuilderName}', " +
             "Strategy Key: '{StrategyKey}', " +
@@ -122,4 +132,45 @@ public static void StrategyExecuted(
         }
     }
 #endif
+
+#if NET6_0_OR_GREATER
+    [LoggerMessage(EventId = 3, Message = ExecutionAttemptMessage, EventName = "ExecutionAttempt", SkipEnabledCheck = true)]
+    public static partial void ExecutionAttempt(
+        this ILogger logger,
+        LogLevel level,
+        string? builderName,
+        string? strategyName,
+        string strategyType,
+        string? strategyKey,
+        object? result,
+        bool handled,
+        int attempt,
+        double executionTimeMs,
+        Exception? exception);
+#else
+    public static void ExecutionAttempt(
+        this ILogger logger,
+        LogLevel level,
+        string? builderName,
+        string? strategyName,
+        string strategyType,
+        string? strategyKey,
+        object? result,
+        bool handled,
+        int attempt,
+        double executionTimeMs,
+        Exception? exception)
+    {
+#pragma warning disable CA1848 // Use the LoggerMessage delegates
+        if (exception is null)
+        {
+            logger.Log(level, new EventId(3, "ExecutionAttempt"), ExecutionAttemptMessage, builderName, strategyName, strategyType, strategyKey, result, handled, attempt, executionTimeMs);
+        }
+        else
+        {
+            logger.Log(level, new EventId(3, "ExecutionAttempt"), exception, ExecutionAttemptMessage, builderName, strategyName, strategyType, strategyKey, result, handled, attempt, executionTimeMs);
+        }
+#pragma warning restore CA1848 // Use the LoggerMessage delegates
+    }
+#endif
 }

src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs

@@ -88,20 +88,39 @@ private void MeterEvent(TelemetryEventArguments args)
     private void LogEvent(TelemetryEventArguments args)
     {
         var strategyKey = args.Source.BuilderProperties.GetValue(TelemetryUtil.StrategyKey, null!);
-
-        if (args.Outcome?.Exception is Exception exception)
+        var result = args.Outcome?.Result;
+        if (result is not null)
         {
-            Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, exception.Message, exception);
+            result = _resultFormatter(args.Context, result);
         }
-        else
+        else if (args.Outcome?.Exception is Exception e)
+        {
+            result = e.Message;
+        }
+
+        if (args.Arguments is ExecutionAttemptArguments executionAttempt)
         {
-            var result = args.Outcome?.Result;
-            if (result is not null)
+            var level = executionAttempt.Handled ? LogLevel.Warning : LogLevel.Debug;
+
+            if (_logger.IsEnabled(level))
             {
-                result = _resultFormatter(args.Context, result);
+                Log.ExecutionAttempt(
+                    _logger,
+                    level,
+                    args.Source.BuilderName,
+                    args.Source.StrategyName,
+                    args.Source.StrategyType,
+                    strategyKey,
+                    result,
+                    executionAttempt.Handled,
+                    executionAttempt.Attempt,
+                    executionAttempt.ExecutionTime.TotalMilliseconds,
+                    args.Outcome?.Exception);
             }
-
-            Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, result, null);
+        }
+        else
+        {
+            Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, result, args.Outcome?.Exception);
         }
     }
 }

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

@@ -117,6 +117,88 @@ public void WriteEvent_LoggingWithoutStrategyKey_Ok()
         messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Builder Name: 'my-builder', Strategy Name: 'my-strategy', Strategy Type: 'my-strategy-type', Strategy Key: '(null)', Result: '(null)'");
     }
 
+    [Fact]
+    public void WriteExecutionAttempt_LoggingWithException_Ok()
+    {
+        var telemetry = Create();
+        using var response = new HttpResponseMessage(System.Net.HttpStatusCode.OK);
+        ReportEvent(telemetry, Outcome.FromException<object>(new InvalidOperationException("Dummy message.")), arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), true));
+
+        var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
+        messages.Should().HaveCount(1);
+
+        messages[0].Message.Should().Be("Execution attempt. Builder Name: 'my-builder', Strategy Name: 'my-strategy', Strategy Type: 'my-strategy-type', Strategy Key: 'my-strategy-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: '123'");
+    }
+
+    [InlineData(true, true)]
+    [InlineData(false, true)]
+    [InlineData(true, false)]
+    [InlineData(false, false)]
+    [Theory]
+    public void WriteExecutionAttempt_LoggingWithOutcome_Ok(bool noOutcome, bool handled)
+    {
+        var telemetry = Create();
+        using var response = new HttpResponseMessage(System.Net.HttpStatusCode.OK);
+        ReportEvent(telemetry, noOutcome ? null : Outcome.FromResult<object>(response), arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), handled));
+
+        var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
+        messages.Should().HaveCount(1);
+
+        if (noOutcome)
+        {
+#if NET6_0_OR_GREATER
+            string resultString = string.Empty;
+#else
+            string resultString = "(null)";
+#endif
+
+            messages[0].Message.Should().Be($"Execution attempt. Builder Name: 'my-builder', Strategy Name: 'my-strategy', Strategy Type: 'my-strategy-type', Strategy Key: 'my-strategy-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: '123'");
+        }
+        else
+        {
+            messages[0].Message.Should().Be($"Execution attempt. Builder Name: 'my-builder', Strategy Name: 'my-strategy', Strategy Type: 'my-strategy-type', Strategy Key: 'my-strategy-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: '123'");
+        }
+
+        if (handled)
+        {
+            messages[0].LogLevel.Should().Be(LogLevel.Warning);
+        }
+        else
+        {
+            messages[0].LogLevel.Should().Be(LogLevel.Debug);
+        }
+
+#if NET6_0_OR_GREATER
+        // verify reported state
+        var coll = messages[0].State.Should().BeAssignableTo<IReadOnlyList<KeyValuePair<string, object>>>().Subject;
+        coll.Count.Should().Be(9);
+        coll.AsEnumerable().Should().HaveCount(9);
+        (coll as IEnumerable).GetEnumerator().Should().NotBeNull();
+
+        for (int i = 0; i < coll.Count; i++)
+        {
+            if (!noOutcome)
+            {
+                coll[i].Value.Should().NotBeNull();
+            }
+        }
+
+        coll.Invoking(c => c[coll.Count + 1]).Should().Throw<IndexOutOfRangeException>();
+#endif
+    }
+
+    [Fact]
+    public void WriteExecutionAttempt_NotEnabled_EnsureNotLogged()
+    {
+        var telemetry = Create();
+        _logger.Enabled = false;
+
+        ReportEvent(telemetry, null, arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), true));
+
+        var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
+        messages.Should().HaveCount(0);
+    }
+
     [InlineData(true, false)]
     [InlineData(false, false)]
     [InlineData(true, true)]

test/Polly.TestUtils/FakeLogger.cs

@@ -8,14 +8,16 @@ public class FakeLogger : ILogger
 {
     private readonly List<LogRecord> _records = new();
 
+    public bool Enabled { get; set; } = true;
+
     public IEnumerable<LogRecord> GetRecords() => _records;
 
     public IEnumerable<LogRecord> GetRecords(EventId eventId) => GetRecords().Where(v => v.EventId.Id == eventId.Id && v.EventId.Name == eventId.Name);
 
     public IDisposable BeginScope<TState>(TState state)
         where TState : notnull => null!;
 
-    public bool IsEnabled(LogLevel logLevel) => true;
+    public bool IsEnabled(LogLevel logLevel) => Enabled;
 
     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
          where TState : notnull