Merge pull request 'fix(common): classify request cancellation in profiler' (#2) from feature/profiler-request-cancellation into hrynco-common

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<Task> act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token);
+
+        var assertion = await act.Should().ThrowAsync<OperationCanceledException>();
+        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<Task> act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token);
+
+        var assertion = await act.Should().ThrowAsync<TaskCanceledException>();
+        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<Task> act = () => MeasureFailureAsync(profiler, actionOverload, exception, token);
+
+        var assertion = await act.Should().ThrowAsync<OperationCanceledException>();
+        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<Task> act = () => MeasureFailureAsync(profiler, actionOverload, exception, cancellation.Token);
+
+        var assertion = await act.Should().ThrowAsync<InvalidOperationException>();
+        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<Task> act = () => actionOverload
+            ? profiler.MeasureExecutionAsync(() => Task.FromException(exception), "LegacyBlock")
+            : profiler.MeasureExecutionAsync(() => Task.FromException<int>(exception), "LegacyBlock");
+
+        var assertion = await act.Should().ThrowAsync<OperationCanceledException>();
+        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<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName = "")
+        {
+            BlockName = blockName;
+            return function();
+        }
+
+        public Task MeasureExecutionAsync(Func<Task> 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<int>(exception), "CanceledBlock", cancellationToken);
+    }
+
     private sealed class CollectingSink : ILogEventSink
     {
         public ConcurrentQueue<LogEvent> Events { get; } = new();

HrynCo.Common/Profiler.cs

@@ -6,12 +6,26 @@ using Serilog;
 public interface IProfiler
 {
     Task<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName = "");
+    Task<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName, CancellationToken cancellationToken)
+    {
+        return MeasureExecutionAsync(function, blockName);
+    }
+
     Task MeasureExecutionAsync(Func<Task> action, string blockName = "");
+    Task MeasureExecutionAsync(Func<Task> action, string blockName, CancellationToken cancellationToken)
+    {
+        return MeasureExecutionAsync(action, blockName);
+    }
 }
 
 public class Profiler(ILogger logger) : IProfiler
 {
-    public async Task<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName = "")
+    public Task<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName = "")
+    {
+        return MeasureExecutionAsync(function, blockName, CancellationToken.None);
+    }
+
+    public async Task<T> MeasureExecutionAsync<T>(Func<Task<T>> 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<Task> action, string blockName = "")
+    public Task MeasureExecutionAsync(Func<Task> action, string blockName = "")
+    {
+        return MeasureExecutionAsync(action, blockName, CancellationToken.None);
+    }
+
+    public async Task MeasureExecutionAsync(Func<Task> action, string blockName, CancellationToken cancellationToken)
     {
         await MeasureExecutionAsync<object?>(async () =>
         {
             await action();
             return null;
-        }, blockName);
+        }, blockName, cancellationToken);
     }
 }

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.