Log unhealthy executions with warning level (#1306)

Author: martintmk

src/Polly.Extensions/Telemetry/Log.cs

@@ -83,9 +83,10 @@ public static void ExecutingStrategy(
 #endif
 
 #if NET6_0_OR_GREATER
-    [LoggerMessage(2, LogLevel.Debug, StrategyExecutedMessage, EventName = "StrategyExecuted")]
+    [LoggerMessage(EventId = 2, Message = StrategyExecutedMessage, EventName = "StrategyExecuted")]
     public static partial void StrategyExecuted(
         this ILogger logger,
+        LogLevel logLevel,
         string? builderName,
         string? strategyKey,
         string resultType,
@@ -94,11 +95,15 @@ public static partial void StrategyExecuted(
         double executionTime,
         Exception? exception);
 #else
-    private static readonly Action<ILogger, string?, string?, string, object?, string, double, Exception?> StrategyExecutedAction =
+    private static readonly Action<ILogger, string?, string?, string, object?, string, double, Exception?> StrategyExecutedActionDebug =
         LoggerMessage.Define<string?, string?, string, object?, string, double>(LogLevel.Debug, new EventId(2, "StrategyExecuted"), StrategyExecutedMessage);
 
+    private static readonly Action<ILogger, string?, string?, string, object?, string, double, Exception?> StrategyExecutedActionWarning =
+        LoggerMessage.Define<string?, string?, string, object?, string, double>(LogLevel.Warning, new EventId(2, "StrategyExecuted"), StrategyExecutedMessage);
+
     public static void StrategyExecuted(
         this ILogger logger,
+        LogLevel logLevel,
         string? builderName,
         string? strategyKey,
         string resultType,
@@ -107,7 +112,14 @@ public static void StrategyExecuted(
         double executionTime,
         Exception? exception)
     {
-        StrategyExecutedAction(logger, builderName, strategyKey, resultType, result, executionHealth, executionTime, exception);
+        if (logLevel == LogLevel.Warning)
+        {
+            StrategyExecutedActionWarning(logger, builderName, strategyKey, resultType, result, executionHealth, executionTime, exception);
+        }
+        else
+        {
+            StrategyExecutedActionDebug(logger, builderName, strategyKey, resultType, result, executionHealth, executionTime, exception);
+        }
     }
 #endif
 }

src/Polly.Extensions/Telemetry/ResilienceContextExtensions.cs

@@ -4,13 +4,9 @@ namespace Polly.Extensions.Telemetry;
 
 internal static class ResilienceContextExtensions
 {
-    public static string GetResultType(this ResilienceContext context)
-    {
-        return context.IsVoid ? "void" : context.ResultType.Name.ToString(CultureInfo.InvariantCulture);
-    }
+    public static string GetResultType(this ResilienceContext context) => context.IsVoid ? "void" : context.ResultType.Name.ToString(CultureInfo.InvariantCulture);
 
-    public static string GetExecutionHealth(this ResilienceContext context)
-    {
-        return context.ResilienceEvents.Count == 0 ? "Healthy" : "Unhealthy";
-    }
+    public static string GetExecutionHealth(this ResilienceContext context) => context.IsExecutionHealthy() ? "Healthy" : "Unhealthy";
+
+    public static bool IsExecutionHealthy(this ResilienceContext context) => context.ResilienceEvents.Count == 0;
 }

src/Polly.Extensions/Telemetry/TelemetryResilienceStrategy.cs

@@ -58,8 +58,11 @@ protected override async ValueTask<Outcome<TResult>> ExecuteCoreAsync<TResult, T
         var outcome = await callback(context, state).ConfigureAwait(context.ContinueOnCapturedContext);
 
         var duration = _timeProvider.GetElapsedTime(stamp);
+        var logLevel = context.IsExecutionHealthy() ? LogLevel.Debug : LogLevel.Warning;
+
         Log.StrategyExecuted(
             _logger,
+            logLevel,
             _builderName,
             _strategyKey,
             context.GetResultType(),

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

@@ -1,3 +1,5 @@
+using System.Collections.Generic;
+using FluentAssertions;
 using Microsoft.Extensions.Logging;
 using Polly.Extensions.Telemetry;
 using Polly.Telemetry;
@@ -54,6 +56,20 @@ public void Execute_EnsureLogged(bool healthy)
         messages = _logger.GetRecords(new EventId(2, "StrategyExecuted")).ToList();
         messages.Should().HaveCount(1);
         messages[0].Message.Should().Match($"Resilience strategy executed. Builder Name: 'my-builder', Strategy Key: 'my-key', Result Type: 'void', Result: 'void', Execution Health: '{healthString}', Execution Time: *ms");
+        messages[0].LogLevel.Should().Be(healthy ? LogLevel.Debug : LogLevel.Warning);
+
+        // verify reported state
+        var coll = messages[0].State.Should().BeAssignableTo<IReadOnlyList<KeyValuePair<string, object>>>().Subject;
+        coll.Count.Should().Be(7);
+        coll.AsEnumerable().Should().HaveCount(7);
+        (coll as IEnumerable).GetEnumerator().Should().NotBeNull();
+
+        for (int i = 0; i < coll.Count; i++)
+        {
+            coll[i].Value.Should().NotBeNull();
+        }
+
+        coll.Invoking(c => c[coll.Count + 1]).Should().Throw<IndexOutOfRangeException>();
     }
 
     [Fact]

test/Polly.TestUtils/FakeLogger.cs

@@ -20,6 +20,6 @@ public IDisposable BeginScope<TState>(TState state)
     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
          where TState : notnull
     {
-        _records.Add(new LogRecord(eventId, formatter(state, exception), exception));
+        _records.Add(new LogRecord(logLevel, eventId, formatter(state, exception), exception, state));
     }
 }

test/Polly.TestUtils/LogRecord.cs

@@ -3,4 +3,4 @@
 namespace Polly.TestUtils;
 #pragma warning disable CS8633 // Nullability in constraints for type parameter doesn't match the constraints for type parameter in implicitly implemented interface method'.
 
-public record class LogRecord(EventId EventId, string Message, Exception? Exception);
+public record class LogRecord(LogLevel LogLevel, EventId EventId, string Message, Exception? Exception, object State);