From 7dc06c051e24528c4192a735e0a14b77650752a6 Mon Sep 17 00:00:00 2001 From: martintmk <103487740+martintmk@users.noreply.github.com> Date: Wed, 26 Jul 2023 15:53:43 +0200 Subject: [PATCH] Improve logging messages (#1436) --- src/Polly.Extensions/Telemetry/Log.cs | 26 +++++++++---------- .../ResilienceTelemetryDiagnosticSource.cs | 12 ++++----- .../Telemetry/TelemetryResilienceStrategy.cs | 8 +++--- .../Telemetry/TelemetryUtil.cs | 2 ++ ...esilienceTelemetryDiagnosticSourceTests.cs | 16 ++++++------ .../TelemetryResilienceStrategyTests.cs | 8 +++--- .../Utils/TelemetryUtilTests.cs | 7 +++++ 7 files changed, 44 insertions(+), 35 deletions(-) diff --git a/src/Polly.Extensions/Telemetry/Log.cs b/src/Polly.Extensions/Telemetry/Log.cs index 3ca6726db82..0765a6081cd 100644 --- a/src/Polly.Extensions/Telemetry/Log.cs +++ b/src/Polly.Extensions/Telemetry/Log.cs @@ -12,7 +12,7 @@ internal static partial class Log EventId = 0, Message = "Resilience event occurred. " + "EventName: '{EventName}', " + - "Source: '{BuilderName}[{BuilderInstance}]/{StrategyName}', " + + "Source: '{BuilderName}/{BuilderInstance}/{StrategyName}', " + "Operation Key: '{OperationKey}', " + "Result: '{Result}'", EventName = "ResilienceEvent")] @@ -20,8 +20,8 @@ public static partial void ResilienceEvent( this ILogger logger, LogLevel logLevel, string eventName, - string? builderName, - string? builderInstance, + string builderName, + string builderInstance, string? strategyName, string? operationKey, object? result, @@ -31,21 +31,21 @@ public static partial void ResilienceEvent( 1, LogLevel.Debug, "Resilience strategy executing. " + - "Source: '{BuilderName}[{BuilderInstance}]', " + + "Source: '{BuilderName}/{BuilderInstance}', " + "Operation Key: '{OperationKey}', " + "Result Type: '{ResultType}'", EventName = "StrategyExecuting")] public static partial void ExecutingStrategy( this ILogger logger, - string? builderName, - string? builderInstance, + string builderName, + string builderInstance, string? operationKey, string resultType); [LoggerMessage( EventId = 2, Message = "Resilience strategy executed. " + - "Source: '{BuilderName}[{BuilderInstance}]', " + + "Source: '{BuilderName}/{BuilderInstance}', " + "Operation Key: '{OperationKey}', " + "Result Type: '{ResultType}', " + "Result: '{Result}', " + @@ -55,8 +55,8 @@ public static partial void ExecutingStrategy( public static partial void StrategyExecuted( this ILogger logger, LogLevel logLevel, - string? builderName, - string? builderInstance, + string builderName, + string builderInstance, string? operationKey, string resultType, object? result, @@ -67,7 +67,7 @@ public static partial void StrategyExecuted( [LoggerMessage( EventId = 3, Message = "Execution attempt. " + - "Source: '{BuilderName}[{BuilderInstance}]/{StrategyName}', " + + "Source: '{BuilderName}/{BuilderInstance}/{StrategyName}', " + "Operation Key: '{OperationKey}', " + "Result: '{Result}', " + "Handled: '{Handled}', " + @@ -78,9 +78,9 @@ public static partial void StrategyExecuted( public static partial void ExecutionAttempt( this ILogger logger, LogLevel level, - string? builderName, - string? builderInstance, - string? strategyName, + string builderName, + string builderInstance, + string strategyName, string? operationKey, object? result, bool handled, diff --git a/src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs b/src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs index b33b45a1f01..5965a1b9ef1 100644 --- a/src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs +++ b/src/Polly.Extensions/Telemetry/ResilienceTelemetryDiagnosticSource.cs @@ -115,9 +115,9 @@ private void LogEvent(TelemetryEventArguments args) Log.ExecutionAttempt( _logger, level, - args.Source.BuilderName, - args.Source.BuilderInstanceName, - args.Source.StrategyName, + args.Source.BuilderName.GetValueOrPlaceholder(), + args.Source.BuilderInstanceName.GetValueOrPlaceholder(), + args.Source.StrategyName.GetValueOrPlaceholder(), args.Context.OperationKey, result, executionAttempt.Handled, @@ -132,9 +132,9 @@ private void LogEvent(TelemetryEventArguments args) _logger, level, args.Event.EventName, - args.Source.BuilderName, - args.Source.BuilderInstanceName, - args.Source.StrategyName, + args.Source.BuilderName.GetValueOrPlaceholder(), + args.Source.BuilderInstanceName.GetValueOrPlaceholder(), + args.Source.StrategyName.GetValueOrPlaceholder(), args.Context.OperationKey, result, args.Outcome?.Exception); diff --git a/src/Polly.Extensions/Telemetry/TelemetryResilienceStrategy.cs b/src/Polly.Extensions/Telemetry/TelemetryResilienceStrategy.cs index 3cac7fc2bb8..0fc6f8d3ca9 100644 --- a/src/Polly.Extensions/Telemetry/TelemetryResilienceStrategy.cs +++ b/src/Polly.Extensions/Telemetry/TelemetryResilienceStrategy.cs @@ -6,8 +6,8 @@ namespace Polly.Extensions.Telemetry; internal sealed class TelemetryResilienceStrategy : ResilienceStrategy { private readonly TimeProvider _timeProvider; - private readonly string? _builderName; - private readonly string? _builderInstance; + private readonly string _builderName; + private readonly string _builderInstance; private readonly List> _enrichers; private readonly ILogger _logger; private readonly Func _resultFormatter; @@ -32,8 +32,8 @@ public TelemetryResilienceStrategy( List> enrichers) { _timeProvider = timeProvider; - _builderName = builderName; - _builderInstance = builderInstance; + _builderName = builderName.GetValueOrPlaceholder(); + _builderInstance = builderInstance.GetValueOrPlaceholder(); _resultFormatter = resultFormatter; _enrichers = enrichers; _logger = loggerFactory.CreateLogger(TelemetryUtil.PollyDiagnosticSource); diff --git a/src/Polly.Extensions/Telemetry/TelemetryUtil.cs b/src/Polly.Extensions/Telemetry/TelemetryUtil.cs index 167a628a0a3..0c53049adf1 100644 --- a/src/Polly.Extensions/Telemetry/TelemetryUtil.cs +++ b/src/Polly.Extensions/Telemetry/TelemetryUtil.cs @@ -15,6 +15,8 @@ internal static class TelemetryUtil internal const string PollyDiagnosticSource = "Polly"; + public static string GetValueOrPlaceholder(this string? value) => value ?? "(null)"; + public static object AsBoxedBool(this bool value) => value switch { true => True, diff --git a/test/Polly.Extensions.Tests/Telemetry/ResilienceTelemetryDiagnosticSourceTests.cs b/test/Polly.Extensions.Tests/Telemetry/ResilienceTelemetryDiagnosticSourceTests.cs index 111da9d94dd..5df7c1bd9d3 100644 --- a/test/Polly.Extensions.Tests/Telemetry/ResilienceTelemetryDiagnosticSourceTests.cs +++ b/test/Polly.Extensions.Tests/Telemetry/ResilienceTelemetryDiagnosticSourceTests.cs @@ -72,11 +72,11 @@ public void WriteEvent_LoggingWithOutcome_Ok(bool noOutcome) if (noOutcome) { - messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: ''"); + messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: ''"); } else { - messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: '200'"); + messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: '200'"); } } @@ -99,11 +99,11 @@ public void WriteEvent_LoggingWithException_Ok(bool noOutcome) if (noOutcome) { - messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: ''"); + messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: ''"); } else { - messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.'"); + messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.'"); } } @@ -115,7 +115,7 @@ public void WriteEvent_LoggingWithoutInstanceName_Ok() var messages = _logger.GetRecords(new EventId(0, "ResilienceEvent")).ToList(); - messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder[]/my-strategy', Operation Key: 'op-key', Result: ''"); + messages[0].Message.Should().Be("Resilience event occurred. EventName: 'my-event', Source: 'my-builder/(null)/my-strategy', Operation Key: 'op-key', Result: ''"); } [InlineData(ResilienceEventSeverity.Error, LogLevel.Error)] @@ -150,7 +150,7 @@ public void WriteExecutionAttempt_LoggingWithException_Ok() var messages = _logger.GetRecords(new EventId(3, "ExecutionAttempt")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Be("Execution attempt. Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be("Execution attempt. Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: 'Dummy message.', Handled: 'True', Attempt: '4', Execution Time: '123'"); } [InlineData(true, true)] @@ -170,11 +170,11 @@ public void WriteExecutionAttempt_LoggingWithOutcome_Ok(bool noOutcome, bool han if (noOutcome) { string resultString = string.Empty; - messages[0].Message.Should().Be($"Execution attempt. Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be($"Execution attempt. Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: '{resultString}', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); } else { - messages[0].Message.Should().Be($"Execution attempt. Source: 'my-builder[builder-instance]/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); + messages[0].Message.Should().Be($"Execution attempt. Source: 'my-builder/builder-instance/my-strategy', Operation Key: 'op-key', Result: '200', Handled: '{handled}', Attempt: '4', Execution Time: '123'"); } messages[0].LogLevel.Should().Be(LogLevel.Warning); diff --git a/test/Polly.Extensions.Tests/Telemetry/TelemetryResilienceStrategyTests.cs b/test/Polly.Extensions.Tests/Telemetry/TelemetryResilienceStrategyTests.cs index f268075abb4..1f83d8c6095 100644 --- a/test/Polly.Extensions.Tests/Telemetry/TelemetryResilienceStrategyTests.cs +++ b/test/Polly.Extensions.Tests/Telemetry/TelemetryResilienceStrategyTests.cs @@ -50,10 +50,10 @@ public void Execute_EnsureLogged(bool healthy) var messages = _logger.GetRecords(new EventId(1, "StrategyExecuting")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Be("Resilience strategy executing. Source: 'my-builder[my-instance]', Operation Key: 'op-key', Result Type: 'void'"); + messages[0].Message.Should().Be("Resilience strategy executing. Source: 'my-builder/my-instance', Operation Key: 'op-key', Result Type: 'void'"); messages = _logger.GetRecords(new EventId(2, "StrategyExecuted")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Match($"Resilience strategy executed. Source: 'my-builder[my-instance]', Operation Key: 'op-key', Result Type: 'void', Result: 'void', Execution Health: '{healthString}', Execution Time: *ms"); + messages[0].Message.Should().Match($"Resilience strategy executed. Source: 'my-builder/my-instance', Operation Key: 'op-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 @@ -78,11 +78,11 @@ public void Execute_WithException_EnsureLogged() var messages = _logger.GetRecords(new EventId(1, "StrategyExecuting")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Be("Resilience strategy executing. Source: 'my-builder[my-instance]', Operation Key: 'op-key', Result Type: 'void'"); + messages[0].Message.Should().Be("Resilience strategy executing. Source: 'my-builder/my-instance', Operation Key: 'op-key', Result Type: 'void'"); messages = _logger.GetRecords(new EventId(2, "StrategyExecuted")).ToList(); messages.Should().HaveCount(1); - messages[0].Message.Should().Match($"Resilience strategy executed. Source: 'my-builder[my-instance]', Operation Key: 'op-key', Result Type: 'void', Result: 'Dummy message.', Execution Health: 'Healthy', Execution Time: *ms"); + messages[0].Message.Should().Match($"Resilience strategy executed. Source: 'my-builder/my-instance', Operation Key: 'op-key', Result Type: 'void', Result: 'Dummy message.', Execution Health: 'Healthy', Execution Time: *ms"); messages[0].Exception.Should().BeOfType(); } diff --git a/test/Polly.Extensions.Tests/Utils/TelemetryUtilTests.cs b/test/Polly.Extensions.Tests/Utils/TelemetryUtilTests.cs index 23ea7f45c3c..328f9f83431 100644 --- a/test/Polly.Extensions.Tests/Utils/TelemetryUtilTests.cs +++ b/test/Polly.Extensions.Tests/Utils/TelemetryUtilTests.cs @@ -25,4 +25,11 @@ public void AsBoxedInt_Ok() (-1).AsBoxedInt().Should().NotBeSameAs((-1).AsBoxedInt()); 100.AsBoxedInt().Should().NotBeSameAs(100.AsBoxedInt()); } + + [Fact] + public void GetValueOrPlaceholder_Ok() + { + TelemetryUtil.GetValueOrPlaceholder("dummy").Should().Be("dummy"); + TelemetryUtil.GetValueOrPlaceholder(null).Should().Be("(null)"); + } }