2 Commits

Author SHA1 Message Date
agrynco 30538b7262 fix(common): classify request cancellation in profiler
Preserve legacy profiler contracts and record expected cancellation below error level.
2026-10-11 17:50:19 +03:00
agrynco df91901e00 Merge pull request 'chore: preserve current configuration and documentation' (#1) from feature/hrynco-service-hosts into hrynco-common 2026-10-03 00:59:43 +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)); && 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 private sealed class CollectingSink : ILogEventSink
{ {
public ConcurrentQueue<LogEvent> Events { get; } = new(); public ConcurrentQueue<LogEvent> Events { get; } = new();
+30 -4
View File
@@ -6,12 +6,26 @@ using Serilog;
public interface IProfiler public interface IProfiler
{ {
Task<T> MeasureExecutionAsync<T>(Func<Task<T>> function, string blockName = ""); 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 = "");
Task MeasureExecutionAsync(Func<Task> action, string blockName, CancellationToken cancellationToken)
{
return MeasureExecutionAsync(action, blockName);
}
} }
public class Profiler(ILogger logger) : IProfiler 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); logger.ForContext("PerformanceLog", true).Information("{BlockName} - Start", blockName);
@@ -42,6 +56,13 @@ public class Profiler(ILogger logger) : IProfiler
return result; return result;
} }
catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested)
{
logger
.ForContext("PerformanceLog", true)
.Debug("{BlockName} - Canceled", blockName);
throw;
}
catch (Exception ex) // NOSONAR catch (Exception ex) // NOSONAR
{ {
logger 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 MeasureExecutionAsync<object?>(async () =>
{ {
await action(); await action();
return null; return null;
}, blockName); }, blockName, cancellationToken);
} }
} }
+14
View File
@@ -11,6 +11,20 @@ Shared common utilities for HrynCo applications.
- Tree traversal helpers - Tree traversal helpers
- Time and profiling 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 ## Packaging
This package is intended for reuse through NuGet. The test project is excluded from packing. This package is intended for reuse through NuGet. The test project is excluded from packing.