diff --git a/HrynCo.Common.Tests/ProfilerTests.cs b/HrynCo.Common.Tests/ProfilerTests.cs index a69df2e..377656f 100644 --- a/HrynCo.Common.Tests/ProfilerTests.cs +++ b/HrynCo.Common.Tests/ProfilerTests.cs @@ -82,6 +82,201 @@ public sealed class ProfilerTests && e.MessageTemplate.Text.Contains("An error occurred", StringComparison.Ordinal)); } + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithCanceledToken_ShouldLogCancellationWithoutExceptionAndRethrow(bool actionOverload) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + var exception = new OperationCanceledException(cancellation.Token); + + Func act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token); + + var assertion = await act.Should().ThrowAsync(); + assertion.Which.Should().BeSameAs(exception); + sink.Events.Should().ContainSingle(e => + e.Level == LogEventLevel.Debug + && e.Exception == null + && e.MessageTemplate.Text == "{BlockName} - Canceled" + && e.Properties["BlockName"].ToString() == "\"CanceledBlock\"" + && e.Properties["PerformanceLog"].ToString() == "True"); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error || e.Properties.ContainsKey("Measurements")); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithCanceledToken_ShouldRecognizeTaskCanceledException(bool actionOverload) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + var exception = new TaskCanceledException(); + + Func act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token); + + var assertion = await act.Should().ThrowAsync(); + assertion.Which.Should().BeSameAs(exception); + sink.Events.Should().ContainSingle(e => e.Level == LogEventLevel.Debug && e.Exception == null); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error || e.Properties.ContainsKey("Measurements")); + } + + [Theory] + [InlineData(false, false)] + [InlineData(false, true)] + [InlineData(true, false)] + [InlineData(true, true)] + public async Task MeasureExecutionAsync_WithUncanceledToken_ShouldLogOperationCanceledExceptionAsError(bool actionOverload, bool tokenCanBeCanceled) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + CancellationToken token = tokenCanBeCanceled ? cancellation.Token : CancellationToken.None; + var exception = new OperationCanceledException(); + + Func act = () => MeasureFailureAsync(profiler, actionOverload, exception, token); + + var assertion = await act.Should().ThrowAsync(); + assertion.Which.Should().BeSameAs(exception); + sink.Events.Should().ContainSingle(e => e.Level == LogEventLevel.Error && ReferenceEquals(e.Exception, exception)); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Debug || e.Properties.ContainsKey("Measurements")); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithCanceledToken_ShouldKeepOtherExceptionsAsErrors(bool actionOverload) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + var exception = new InvalidOperationException("boom"); + + Func act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token); + + var assertion = await act.Should().ThrowAsync(); + assertion.Which.Should().BeSameAs(exception); + sink.Events.Should().ContainSingle(e => e.Level == LogEventLevel.Error && ReferenceEquals(e.Exception, exception)); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Debug || e.Properties.ContainsKey("Measurements")); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithoutToken_ShouldKeepCancellationAsError(bool actionOverload) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + var exception = new OperationCanceledException(cancellation.Token); + + Func act = () => actionOverload + ? profiler.MeasureExecutionAsync(() => Task.FromException(exception), "LegacyBlock") + : profiler.MeasureExecutionAsync(() => Task.FromException(exception), "LegacyBlock"); + + var assertion = await act.Should().ThrowAsync(); + assertion.Which.Should().BeSameAs(exception); + sink.Events.Should().ContainSingle(e => e.Level == LogEventLevel.Error && ReferenceEquals(e.Exception, exception)); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Debug || e.Properties.ContainsKey("Measurements")); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithCanceledToken_ShouldAllowSuccessfulWork(bool actionOverload) + { + var sink = new CollectingSink(); + IProfiler profiler = CreateProfiler(sink); + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + bool invoked = false; + + if (actionOverload) + { + await profiler.MeasureExecutionAsync(() => + { + invoked = true; + return Task.CompletedTask; + }, "SuccessBlock", cancellation.Token); + invoked.Should().BeTrue(); + } + else + { + int result = await profiler.MeasureExecutionAsync(() => Task.FromResult(42), "SuccessBlock", cancellation.Token); + result.Should().Be(42); + } + + sink.Events.Should().ContainSingle(e => e.Level == LogEventLevel.Information && e.Properties.ContainsKey("Measurements")); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error || e.Level == LogEventLevel.Debug); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task MeasureExecutionAsync_WithToken_ShouldSupportLegacyInterfaceImplementations(bool actionOverload) + { + var legacyProfiler = new LegacyProfiler(); + IProfiler profiler = legacyProfiler; + using var cancellation = new CancellationTokenSource(); + cancellation.Cancel(); + bool invoked = false; + + if (actionOverload) + { + await profiler.MeasureExecutionAsync(() => + { + invoked = true; + return Task.CompletedTask; + }, "LegacyBlock", cancellation.Token); + invoked.Should().BeTrue(); + } + else + { + int result = await profiler.MeasureExecutionAsync(() => Task.FromResult(42), "LegacyBlock", cancellation.Token); + result.Should().Be(42); + } + + legacyProfiler.BlockName.Should().Be("LegacyBlock"); + } + + private sealed class LegacyProfiler : IProfiler + { + public string? BlockName { get; private set; } + + public Task MeasureExecutionAsync(Func> function, string blockName = "") + { + BlockName = blockName; + return function(); + } + + public Task MeasureExecutionAsync(Func action, string blockName = "") + { + BlockName = blockName; + return action(); + } + } + + private static IProfiler CreateProfiler(CollectingSink sink) + { + return new Profiler(new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(sink) + .CreateLogger()); + } + + private static Task MeasureFailureAsync(IProfiler profiler, bool actionOverload, Exception exception, CancellationToken cancellationToken) + { + return actionOverload + ? profiler.MeasureExecutionAsync(() => Task.FromException(exception), "CanceledBlock", cancellationToken) + : profiler.MeasureExecutionAsync(() => Task.FromException(exception), "CanceledBlock", cancellationToken); + } + private sealed class CollectingSink : ILogEventSink { public ConcurrentQueue Events { get; } = new(); diff --git a/HrynCo.Common/Profiler.cs b/HrynCo.Common/Profiler.cs index a3639b7..6838b6d 100644 --- a/HrynCo.Common/Profiler.cs +++ b/HrynCo.Common/Profiler.cs @@ -6,12 +6,26 @@ using Serilog; public interface IProfiler { Task MeasureExecutionAsync(Func> function, string blockName = ""); + Task MeasureExecutionAsync(Func> function, string blockName, CancellationToken cancellationToken) + { + return MeasureExecutionAsync(function, blockName); + } + Task MeasureExecutionAsync(Func action, string blockName = ""); + Task MeasureExecutionAsync(Func action, string blockName, CancellationToken cancellationToken) + { + return MeasureExecutionAsync(action, blockName); + } } public class Profiler(ILogger logger) : IProfiler { - public async Task MeasureExecutionAsync(Func> function, string blockName = "") + public Task MeasureExecutionAsync(Func> function, string blockName = "") + { + return MeasureExecutionAsync(function, blockName, CancellationToken.None); + } + + public async Task MeasureExecutionAsync(Func> function, string blockName, CancellationToken cancellationToken) { logger.ForContext("PerformanceLog", true).Information("{BlockName} - Start", blockName); @@ -42,6 +56,13 @@ public class Profiler(ILogger logger) : IProfiler return result; } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + logger + .ForContext("PerformanceLog", true) + .Debug("{BlockName} - Canceled", blockName); + throw; + } catch (Exception ex) // NOSONAR { logger @@ -51,12 +72,17 @@ public class Profiler(ILogger logger) : IProfiler } } - public async Task MeasureExecutionAsync(Func action, string blockName = "") + public Task MeasureExecutionAsync(Func action, string blockName = "") + { + return MeasureExecutionAsync(action, blockName, CancellationToken.None); + } + + public async Task MeasureExecutionAsync(Func action, string blockName, CancellationToken cancellationToken) { await MeasureExecutionAsync(async () => { await action(); return null; - }, blockName); + }, blockName, cancellationToken); } -} \ No newline at end of file +} diff --git a/HrynCo.Common/README.md b/HrynCo.Common/README.md index 06e6ec8..683900b 100644 --- a/HrynCo.Common/README.md +++ b/HrynCo.Common/README.md @@ -11,6 +11,20 @@ Shared common utilities for HrynCo applications. - Tree traversal helpers - Time and profiling helpers +## Profiling and cancellation + +`IProfiler.MeasureExecutionAsync` supports both result-returning and action delegates. Existing overloads keep their original behavior. Pass a cancellation token as the third argument when profiling work associated with a request: + +```csharp +await profiler.MeasureExecutionAsync(() => LoadItemsAsync(cancellationToken), "LoadItems", cancellationToken); +``` + +If the delegate throws `OperationCanceledException` (including `TaskCanceledException`) and the supplied token is canceled, the profiler writes a Debug cancellation event with `PerformanceLog = true` and no attached exception, then rethrows the original exception. An `OperationCanceledException` with an uncanceled or absent token, and any other exception even with a canceled token, remain Error events with the exception attached. Failed or canceled operations do not write a successful End measurement. + +The supplied token controls log classification; the caller must pass it to the operation itself. The profiler does not cancel the delegate or reject successful work when the token is canceled. + +Custom implementations of `IProfiler` that implement only the original overloads remain compatible. The new interface overloads default to the original methods; custom implementations must override them to add token-aware log classification. + ## Packaging This package is intended for reuse through NuGet. The test project is excluded from packing.