fix(common): classify request cancellation in profiler #2

Merged
agrynco merged 1 commits from feature/profiler-request-cancellation into hrynco-common 2026-10-11 17:51:30 +03:00
3 changed files with 239 additions and 4 deletions
+195
View File
@@ -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();
+30 -4
View File
@@ -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);
}
}
}
+14
View File
@@ -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.