Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix logging of execution attempt #1341

Merged
merged 2 commits into from
Jun 22, 2023
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
51 changes: 51 additions & 0 deletions src/Polly.Extensions/Telemetry/Log.cs
Original file line number Diff line number Diff line change
@@ -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
}
Original file line number Diff line number Diff line change
@@ -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);
}
}
}
Original file line number Diff line number Diff line change
@@ -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)]
4 changes: 3 additions & 1 deletion test/Polly.TestUtils/FakeLogger.cs
Original file line number Diff line number Diff line change
@@ -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