Skip to content

Commit 5488560

Browse files
martintmkmartintmk
authored
Fix logging of execution attempt (#1341)
1 parent 2167ed3 commit 5488560

4 files changed

Lines changed: 164 additions & 10 deletions

File tree

‎src/Polly.Extensions/Telemetry/Log.cs‎

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,16 @@ internal static class Log
2727
"Strategy Key: '{StrategyKey}', " +
2828
"Result: '{Result}'";
2929

30+
private const string ExecutionAttemptMessage = "Execution attempt. " +
31+
"Builder Name: '{BuilderName}', " +
32+
"Strategy Name: '{StrategyName}', " +
33+
"Strategy Type: '{StrategyType}', " +
34+
"Strategy Key: '{StrategyKey}', " +
35+
"Result: '{Result}', " +
36+
"Handled: '{Handled}', " +
37+
"Attempt: '{Attempt}', " +
38+
"Execution Time: '{ExecutionTimeMs}'";
39+
3040
private const string StrategyExecutingMessage = "Resilience strategy executing. " +
3141
"Builder Name: '{BuilderName}', " +
3242
"Strategy Key: '{StrategyKey}', " +
@@ -122,4 +132,45 @@ public static void StrategyExecuted(
122132
}
123133
}
124134
#endif
135+
136+
#if NET6_0_OR_GREATER
137+
[LoggerMessage(EventId = 3, Message = ExecutionAttemptMessage, EventName = "ExecutionAttempt", SkipEnabledCheck = true)]
138+
public static partial void ExecutionAttempt(
139+
this ILogger logger,
140+
LogLevel level,
141+
string? builderName,
142+
string? strategyName,
143+
string strategyType,
144+
string? strategyKey,
145+
object? result,
146+
bool handled,
147+
int attempt,
148+
double executionTimeMs,
149+
Exception? exception);
150+
#else
151+
public static void ExecutionAttempt(
152+
this ILogger logger,
153+
LogLevel level,
154+
string? builderName,
155+
string? strategyName,
156+
string strategyType,
157+
string? strategyKey,
158+
object? result,
159+
bool handled,
160+
int attempt,
161+
double executionTimeMs,
162+
Exception? exception)
163+
{
164+
#pragma warning disable CA1848 // Use the LoggerMessage delegates
165+
if (exception is null)
166+
{
167+
logger.Log(level, new EventId(3, "ExecutionAttempt"), ExecutionAttemptMessage, builderName, strategyName, strategyType, strategyKey, result, handled, attempt, executionTimeMs);
168+
}
169+
else
170+
{
171+
logger.Log(level, new EventId(3, "ExecutionAttempt"), exception, ExecutionAttemptMessage, builderName, strategyName, strategyType, strategyKey, result, handled, attempt, executionTimeMs);
172+
}
173+
#pragma warning restore CA1848 // Use the LoggerMessage delegates
174+
}
175+
#endif
125176
}

‎src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs‎

Lines changed: 28 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -88,20 +88,39 @@ private void MeterEvent(TelemetryEventArguments args)
8888
private void LogEvent(TelemetryEventArguments args)
8989
{
9090
var strategyKey = args.Source.BuilderProperties.GetValue(TelemetryUtil.StrategyKey, null!);
91-
92-
if (args.Outcome?.Exception is Exception exception)
91+
var result = args.Outcome?.Result;
92+
if (result is not null)
9393
{
94-
Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, exception.Message, exception);
94+
result = _resultFormatter(args.Context, result);
9595
}
96-
else
96+
else if (args.Outcome?.Exception is Exception e)
97+
{
98+
result = e.Message;
99+
}
100+
101+
if (args.Arguments is ExecutionAttemptArguments executionAttempt)
97102
{
98-
var result = args.Outcome?.Result;
99-
if (result is not null)
103+
var level = executionAttempt.Handled ? LogLevel.Warning : LogLevel.Debug;
104+
105+
if (_logger.IsEnabled(level))
100106
{
101-
result = _resultFormatter(args.Context, result);
107+
Log.ExecutionAttempt(
108+
_logger,
109+
level,
110+
args.Source.BuilderName,
111+
args.Source.StrategyName,
112+
args.Source.StrategyType,
113+
strategyKey,
114+
result,
115+
executionAttempt.Handled,
116+
executionAttempt.Attempt,
117+
executionAttempt.ExecutionTime.TotalMilliseconds,
118+
args.Outcome?.Exception);
102119
}
103-
104-
Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, result, null);
120+
}
121+
else
122+
{
123+
Log.ResilienceEvent(_logger, args.EventName, args.Source.BuilderName, args.Source.StrategyName, args.Source.StrategyType, strategyKey, result, args.Outcome?.Exception);
105124
}
106125
}
107126
}

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

Lines changed: 82 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -117,6 +117,88 @@ public void WriteEvent_LoggingWithoutStrategyKey_Ok()
117117
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)'");
118118
}
119119

120+
[Fact]
121+
public void WriteExecutionAttempt_LoggingWithException_Ok()
122+
{
123+
var telemetry = Create();
124+
using var response = new HttpResponseMessage(System.Net.HttpStatusCode.OK);
125+
ReportEvent(telemetry, Outcome.FromException<object>(new InvalidOperationException("Dummy message.")), arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), true));
126+
127+
var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
128+
messages.Should().HaveCount(1);
129+
130+
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'");
131+
}
132+
133+
[InlineData(true, true)]
134+
[InlineData(false, true)]
135+
[InlineData(true, false)]
136+
[InlineData(false, false)]
137+
[Theory]
138+
public void WriteExecutionAttempt_LoggingWithOutcome_Ok(bool noOutcome, bool handled)
139+
{
140+
var telemetry = Create();
141+
using var response = new HttpResponseMessage(System.Net.HttpStatusCode.OK);
142+
ReportEvent(telemetry, noOutcome ? null : Outcome.FromResult<object>(response), arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), handled));
143+
144+
var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
145+
messages.Should().HaveCount(1);
146+
147+
if (noOutcome)
148+
{
149+
#if NET6_0_OR_GREATER
150+
string resultString = string.Empty;
151+
#else
152+
string resultString = "(null)";
153+
#endif
154+
155+
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'");
156+
}
157+
else
158+
{
159+
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'");
160+
}
161+
162+
if (handled)
163+
{
164+
messages[0].LogLevel.Should().Be(LogLevel.Warning);
165+
}
166+
else
167+
{
168+
messages[0].LogLevel.Should().Be(LogLevel.Debug);
169+
}
170+
171+
#if NET6_0_OR_GREATER
172+
// verify reported state
173+
var coll = messages[0].State.Should().BeAssignableTo<IReadOnlyList<KeyValuePair<string, object>>>().Subject;
174+
coll.Count.Should().Be(9);
175+
coll.AsEnumerable().Should().HaveCount(9);
176+
(coll as IEnumerable).GetEnumerator().Should().NotBeNull();
177+
178+
for (int i = 0; i < coll.Count; i++)
179+
{
180+
if (!noOutcome)
181+
{
182+
coll[i].Value.Should().NotBeNull();
183+
}
184+
}
185+
186+
coll.Invoking(c => c[coll.Count + 1]).Should().Throw<IndexOutOfRangeException>();
187+
#endif
188+
}
189+
190+
[Fact]
191+
public void WriteExecutionAttempt_NotEnabled_EnsureNotLogged()
192+
{
193+
var telemetry = Create();
194+
_logger.Enabled = false;
195+
196+
ReportEvent(telemetry, null, arg: new ExecutionAttemptArguments(4, TimeSpan.FromMilliseconds(123), true));
197+
198+
var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList();
199+
messages.Should().HaveCount(0);
200+
}
201+
120202
[InlineData(true, false)]
121203
[InlineData(false, false)]
122204
[InlineData(true, true)]

‎test/Polly.TestUtils/FakeLogger.cs‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,14 +8,16 @@ public class FakeLogger : ILogger
88
{
99
private readonly List<LogRecord> _records = new();
1010

11+
public bool Enabled { get; set; } = true;
12+
1113
public IEnumerable<LogRecord> GetRecords() => _records;
1214

1315
public IEnumerable<LogRecord> GetRecords(EventId eventId) => GetRecords().Where(v => v.EventId.Id == eventId.Id && v.EventId.Name == eventId.Name);
1416

1517
public IDisposable BeginScope<TState>(TState state)
1618
where TState : notnull => null!;
1719

18-
public bool IsEnabled(LogLevel logLevel) => true;
20+
public bool IsEnabled(LogLevel logLevel) => Enabled;
1921

2022
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
2123
where TState : notnull

0 commit comments

Comments
 (0)