fix(auditlog): do not log a graceful-stop OperationCanceledException at Error in the telemetry drains (review 2026-10-21 06/COR-2)

This commit is contained in:
Joseph Doherty
2026-10-22 06:18:50 -04:00
parent 15496575bc
commit 268b55e350
2 changed files with 55 additions and 2 deletions
@@ -163,8 +163,8 @@ public class SiteAuditTelemetryActor : ReceiveActor
// Route every async dependency call through the
// per-actor lifecycle token so PostStop cancellation actually
// propagates into the queue read, the gRPC push, and the
// mark-forwarded write. OperationCanceledException is swallowed by
// the catch-all below.
// mark-forwarded write. A shutdown-driven OperationCanceledException is
// swallowed silently by the dedicated catch below.
var ct = _lifecycleCts.Token;
try
{
@@ -204,6 +204,12 @@ public class SiteAuditTelemetryActor : ReceiveActor
.ConfigureAwait(false);
}
}
catch (OperationCanceledException) when (ct.IsCancellationRequested)
{
// Graceful stop: PostStop cancelled the lifecycle token while the drain
// was awaiting the queue / gRPC push. Expected on every orderly shutdown or
// failover — not an error (review 2026-10-21 06/COR-2).
}
catch (Exception ex)
{
// Catch-all so a SQLite hiccup or mapper bug never crashes the
@@ -382,6 +388,10 @@ public class SiteAuditTelemetryActor : ReceiveActor
.ConfigureAwait(false);
}
}
catch (OperationCanceledException) when (ct.IsCancellationRequested)
{
// Graceful stop mid-drain — see OnDrainAsync (review 2026-10-21 06/COR-2).
}
catch (Exception ex)
{
_logger.LogError(ex,
@@ -717,4 +717,47 @@ public class SiteAuditTelemetryActorTests : TestKit
}, TimeSpan.FromSeconds(10));
});
}
/// <summary>
/// Review 2026-10-21 06/COR-2: a graceful stop while a drain is parked on its
/// queue read surfaces as an <see cref="OperationCanceledException"/>; it must not
/// be logged at Error ("Unexpected error during ... drain") on every orderly shutdown.
/// </summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task GracefulStop_MidDrain_DoesNotLogError()
{
var reads = new System.Collections.Concurrent.ConcurrentQueue<int>();
async Task<IReadOnlyList<AuditEvent>> Parked(CancellationToken ct)
{
reads.Enqueue(1);
await Task.Delay(Timeout.Infinite, ct).ConfigureAwait(false);
return Array.Empty<AuditEvent>();
}
_queue.ReadPendingAsync(Arg.Any<int>(), Arg.Any<CancellationToken>())
.Returns(c => Parked(c.Arg<CancellationToken>()));
_queue.ReadPendingCachedTelemetryAsync(Arg.Any<int>(), Arg.Any<CancellationToken>())
.Returns(c => Parked(c.Arg<CancellationToken>()));
var logger = new CapturingLogger<SiteAuditTelemetryActor>();
var actor = Sys.ActorOf(Props.Create(() => new SiteAuditTelemetryActor(
_queue, _client, Opts(), logger, (IOperationTrackingStore?)_trackingStore)));
await AwaitConditionAsync(() => Task.FromResult(reads.Count >= 1), TimeSpan.FromSeconds(10));
Watch(actor);
Sys.Stop(actor);
await ExpectTerminatedAsync(actor);
await Task.Delay(300);
Assert.DoesNotContain(logger.Levels, l => l >= Microsoft.Extensions.Logging.LogLevel.Error);
}
private sealed class CapturingLogger<T> : Microsoft.Extensions.Logging.ILogger<T>
{
public System.Collections.Concurrent.ConcurrentQueue<Microsoft.Extensions.Logging.LogLevel> Levels { get; } = new();
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) => true;
public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId,
TState state, Exception? exception, Func<TState, Exception?, string> formatter) => Levels.Enqueue(logLevel);
}
}