fix(audit-log): explicit long CommandTimeout on partition-switch and per-channel purge maintenance paths

This commit is contained in:
Joseph Doherty
2026-07-09 06:43:23 -04:00
parent 1b6b0aab2a
commit b59aa2d717
11 changed files with 231 additions and 17 deletions
@@ -182,7 +182,7 @@ public class AuditLogPurgeActor : ReceiveActor
try
{
var rowsDeleted = await repository
.SwitchOutPartitionAsync(boundary)
.SwitchOutPartitionAsync(boundary, _purgeOptions.ResolvedMaintenanceCommandTimeout)
.ConfigureAwait(false);
sw.Stop();
@@ -250,7 +250,11 @@ public class AuditLogPurgeActor : ReceiveActor
try
{
var rowsDeleted = await repository
.PurgeChannelOlderThanAsync(channel, channelThreshold, _purgeOptions.ChannelPurgeBatchSize)
.PurgeChannelOlderThanAsync(
channel,
channelThreshold,
_purgeOptions.ChannelPurgeBatchSize,
_purgeOptions.ResolvedMaintenanceCommandTimeout)
.ConfigureAwait(false);
sw.Stop();
@@ -56,6 +56,30 @@ public sealed class AuditLogPurgeOptions
/// </summary>
public int ChannelPurgeBatchSize => ChannelPurgeBatchSizeConfigured < 1 ? 1 : ChannelPurgeBatchSizeConfigured;
/// <summary>
/// Per-command timeout (in minutes) for the maintenance SQL the purge tick issues —
/// both the partition switch-out drop-and-rebuild dance
/// (<see cref="ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Repositories.IAuditLogRepository.SwitchOutPartitionAsync"/>)
/// and each per-channel <c>DELETE TOP</c> batch. Default 30 minutes.
/// </summary>
/// <remarks>
/// The ADO.NET default command timeout is ~30 seconds. On a large or contended partition the
/// SWITCH dance (which briefly drops <c>UX_AuditLog_EventId</c>) can exceed that and abort
/// mid-flight — leaving the live table without its idempotency-supporting unique index until a
/// later tick's CATCH branch rebuilds it (arch-review 04, S2). A generous maintenance timeout
/// lets the metadata-only switch complete rather than self-locking. Resolved via
/// <see cref="ResolvedMaintenanceCommandTimeout"/>, clamped to a 1-minute floor.
/// </remarks>
public int MaintenanceCommandTimeoutMinutes { get; set; } = 30;
/// <summary>
/// Resolves the effective maintenance command timeout, clamped to at least 1 minute so a
/// misconfigured <c>0</c>/negative value cannot yield a zero/negative timeout (which ADO.NET
/// interprets as "no timeout" for <c>0</c> and rejects for negatives).
/// </summary>
public TimeSpan ResolvedMaintenanceCommandTimeout =>
TimeSpan.FromMinutes(MaintenanceCommandTimeoutMinutes < 1 ? 1 : MaintenanceCommandTimeoutMinutes);
/// <summary>
/// Test-only override for finer control over the tick cadence than
/// whole-hour resolution allows. When non-null, takes precedence over
@@ -83,9 +83,17 @@ public interface IAuditLogRepository
/// </para>
/// </remarks>
/// <param name="monthBoundary">Lower-bound datetime of the monthly partition to switch out.</param>
/// <param name="commandTimeout">
/// Optional per-command timeout for the maintenance SQL (the row-count sample plus the
/// drop-and-rebuild dance). When null the provider default applies. The purge actor passes
/// <see cref="ZB.MOM.WW.ScadaBridge.AuditLog.Central.AuditLogPurgeOptions.ResolvedMaintenanceCommandTimeout"/>
/// (default 30 min) because the ~30s ADO.NET default can abort the switch mid-dance on a large
/// or contended partition, leaving the table without <c>UX_AuditLog_EventId</c> until the next
/// tick recovers (arch-review 04, S2).
/// </param>
/// <param name="ct">Cancellation token.</param>
/// <returns>A task that resolves to the approximate number of rows discarded by the partition switch.</returns>
Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default);
Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default);
/// <summary>
/// Per-channel retention override purge. Deletes <c>AuditLog</c> rows for a
@@ -115,12 +123,20 @@ public interface IAuditLogRepository
/// <param name="channel">Canonical channel name (the <c>Category</c> column value, e.g. <c>ApiOutbound</c>).</param>
/// <param name="threshold">Rows with <c>OccurredAtUtc</c> strictly older than this UTC datetime are deleted.</param>
/// <param name="batchSize">Maximum rows deleted per batch; must be &gt; 0.</param>
/// <param name="commandTimeout">
/// Optional per-batch <c>DELETE TOP</c> command timeout. When null the provider default applies.
/// The purge actor passes the same
/// <see cref="ZB.MOM.WW.ScadaBridge.AuditLog.Central.AuditLogPurgeOptions.ResolvedMaintenanceCommandTimeout"/>
/// it uses for the partition switch so a large single batch under lock contention is not aborted
/// by the ~30s ADO.NET default (arch-review 04, S2).
/// </param>
/// <param name="ct">Cancellation token.</param>
/// <returns>A task that resolves to the total number of rows deleted across all batches.</returns>
Task<long> PurgeChannelOlderThanAsync(
string channel,
DateTime threshold,
int batchSize,
TimeSpan? commandTimeout = null,
CancellationToken ct = default);
/// <summary>
@@ -227,8 +227,13 @@ VALUES
};
/// <inheritdoc />
public async Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default)
public async Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default)
{
// Maintenance timeout in whole seconds (ADO.NET CommandTimeout unit). Null leaves the
// provider default in place. See AuditLogPurgeOptions.MaintenanceCommandTimeoutMinutes /
// arch-review 04 S2 for why the ~30s default is unsafe for the switch-out dance.
var commandTimeoutSeconds = commandTimeout is { } ct2 ? (int)ct2.TotalSeconds : (int?)null;
// GUID-suffixed staging name: prevents collision with any concurrent
// purge attempt and avoids polluting the AuditLog object namespace with
// a predictable identifier.
@@ -351,6 +356,10 @@ VALUES
await using (var sampleCmd = conn.CreateCommand())
{
sampleCmd.CommandText = sampleSql;
if (commandTimeoutSeconds is { } sampleTimeout)
{
sampleCmd.CommandTimeout = sampleTimeout;
}
var sampleResult = await sampleCmd.ExecuteScalarAsync(ct).ConfigureAwait(false);
if (sampleResult is not null && sampleResult is not DBNull)
{
@@ -366,7 +375,27 @@ VALUES
}
}
await _context.Database.ExecuteSqlRawAsync(sql, ct);
// Apply the maintenance timeout to the drop-and-rebuild dance. The context is scoped per
// purge tick (see AuditLogPurgeActor.OnTickAsync's CreateAsyncScope), so a restore is not
// strictly required — but we restore the previous value in a finally for hygiene in case a
// future caller reuses the context for other work after the switch-out.
var previousTimeout = _context.Database.GetCommandTimeout();
if (commandTimeout is { } maintenanceTimeout)
{
_context.Database.SetCommandTimeout(maintenanceTimeout);
}
try
{
await _context.Database.ExecuteSqlRawAsync(sql, ct);
}
finally
{
if (commandTimeout is not null)
{
_context.Database.SetCommandTimeout(previousTimeout);
}
}
return rowsDeleted;
}
@@ -375,6 +404,7 @@ VALUES
string channel,
DateTime threshold,
int batchSize,
TimeSpan? commandTimeout = null,
CancellationToken ct = default)
{
if (string.IsNullOrWhiteSpace(channel))
@@ -389,6 +419,9 @@ VALUES
var thresholdUtc = DateTime.SpecifyKind(threshold.ToUniversalTime(), DateTimeKind.Utc);
// Maintenance timeout in whole seconds; null leaves the provider default (arch-review 04 S2).
var commandTimeoutSeconds = commandTimeout is { } cto ? (int)cto.TotalSeconds : (int?)null;
// Per-channel retention override purge. This is the ONLY DELETE
// against dbo.AuditLog in the codebase and it runs on the purge/maintenance
// path, NOT the append-only writer role (which has INSERT + SELECT only — see
@@ -427,6 +460,10 @@ VALUES
await using var cmd = conn.CreateCommand();
cmd.CommandText = deleteBatchSql;
if (commandTimeoutSeconds is { } batchTimeout)
{
cmd.CommandTimeout = batchTimeout;
}
var pBatch = cmd.CreateParameter();
pBatch.ParameterName = "@batch";
@@ -259,12 +259,12 @@ public class AuditLogIngestActorTests : TestKit, IClassFixture<MsSqlMigrationFix
AuditLogQueryFilter filter, AuditLogPaging paging, CancellationToken ct = default) =>
_inner.QueryAsync(filter, paging, ct);
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default) =>
_inner.SwitchOutPartitionAsync(monthBoundary, ct);
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
_inner.SwitchOutPartitionAsync(monthBoundary, commandTimeout, ct);
public Task<long> PurgeChannelOlderThanAsync(
string channel, DateTime threshold, int batchSize, CancellationToken ct = default) =>
_inner.PurgeChannelOlderThanAsync(channel, threshold, batchSize, ct);
string channel, DateTime threshold, int batchSize, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
_inner.PurgeChannelOlderThanAsync(channel, threshold, batchSize, commandTimeout, ct);
public Task<long> BackfillSourceNodeAsync(
string sentinel, DateTime before, int batchSize, CancellationToken ct = default) =>
@@ -51,6 +51,11 @@ public class AuditLogPurgeActorTests : TestKit, IClassFixture<MsSqlMigrationFixt
public DateTime? ThrowOnBoundary { get; set; }
public Exception? BoundaryException { get; set; }
// Task 4: captures the maintenance command timeout the actor threads through to the
// switch-out + per-channel purge, so tests can assert the options value reaches the repo.
public List<TimeSpan?> SwitchTimeouts { get; } = new();
public List<TimeSpan?> ChannelTimeouts { get; } = new();
// M5.5 (T3): records every per-channel purge call as
// (channel, threshold, batchSize) so tests can assert which channels the
// actor chose to purge and with what window.
@@ -69,8 +74,9 @@ public class AuditLogPurgeActorTests : TestKit, IClassFixture<MsSqlMigrationFixt
AuditLogQueryFilter filter, AuditLogPaging paging, CancellationToken ct = default) =>
Task.FromResult<IReadOnlyList<AuditEvent>>(Array.Empty<AuditEvent>());
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default)
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default)
{
SwitchTimeouts.Add(commandTimeout);
if (ThrowOnBoundary.HasValue && monthBoundary == ThrowOnBoundary.Value)
{
throw BoundaryException ?? new InvalidOperationException("simulated switch failure");
@@ -87,9 +93,10 @@ public class AuditLogPurgeActorTests : TestKit, IClassFixture<MsSqlMigrationFixt
}
public Task<long> PurgeChannelOlderThanAsync(
string channel, DateTime threshold, int batchSize, CancellationToken ct = default)
string channel, DateTime threshold, int batchSize, TimeSpan? commandTimeout = null, CancellationToken ct = default)
{
ChannelPurges.Add((channel, threshold, batchSize));
ChannelTimeouts.Add(commandTimeout);
return Task.FromResult(RowsPerChannel(channel));
}
@@ -491,4 +498,49 @@ public class AuditLogPurgeActorTests : TestKit, IClassFixture<MsSqlMigrationFixt
Assert.Empty(repo.ChannelPurges);
}
// ---------------------------------------------------------------------
// 10. PurgeTick_Passes_MaintenanceCommandTimeout_To_Repository (Task 4)
// ---------------------------------------------------------------------
[Fact]
public void PurgeTick_Passes_MaintenanceCommandTimeout_To_Repository()
{
// The actor must thread AuditLogPurgeOptions.ResolvedMaintenanceCommandTimeout through to
// BOTH the partition switch-out and each per-channel purge, so the ~30s ADO.NET default
// cannot self-lock the drop-and-rebuild dance (arch-review 04, S2).
var boundary = new DateTime(2025, 5, 1, 0, 0, 0, DateTimeKind.Utc);
var repo = new RecordingRepo
{
Boundaries = new List<DateTime> { boundary },
RowsPerBoundary = _ => 7L,
};
var purgeOptions = FastTickOptions();
purgeOptions.MaintenanceCommandTimeoutMinutes = 45;
// A per-channel override shorter than the global window so the channel purge also fires.
var auditOptions = Options.Create(new AuditLogOptions
{
RetentionDays = 365,
PerChannelRetentionDays = new Dictionary<string, int> { ["ApiOutbound"] = 30 },
});
var sp = BuildScopedProvider(repo);
Sys.ActorOf(Props.Create(() => new AuditLogPurgeActor(
sp,
Options.Create(purgeOptions),
auditOptions,
NullLogger<AuditLogPurgeActor>.Instance)));
var expected = TimeSpan.FromMinutes(45);
AwaitAssert(
() =>
{
Assert.Contains(expected, repo.SwitchTimeouts);
Assert.Contains(expected, repo.ChannelTimeouts);
},
duration: TimeSpan.FromSeconds(3),
interval: TimeSpan.FromMilliseconds(50));
}
}
@@ -0,0 +1,31 @@
using ZB.MOM.WW.ScadaBridge.AuditLog.Central;
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Tests.Central;
/// <summary>
/// Task 4 tests for <see cref="AuditLogPurgeOptions.MaintenanceCommandTimeoutMinutes"/> /
/// <see cref="AuditLogPurgeOptions.ResolvedMaintenanceCommandTimeout"/>: the maintenance timeout
/// defaults to 30 minutes and is clamped to a 1-minute floor so a misconfigured 0/negative value
/// cannot yield a zero/negative ADO.NET command timeout (arch-review 04, S2).
/// </summary>
public class AuditLogPurgeOptionsTests
{
[Fact]
public void MaintenanceCommandTimeout_Defaults_To_30_Minutes()
{
var options = new AuditLogPurgeOptions();
Assert.Equal(30, options.MaintenanceCommandTimeoutMinutes);
Assert.Equal(TimeSpan.FromMinutes(30), options.ResolvedMaintenanceCommandTimeout);
}
[Theory]
[InlineData(0, 1)] // clamp floor — a zero config value cannot become a zero timeout
[InlineData(-5, 1)] // clamp floor — negatives are rejected by ADO.NET
[InlineData(1, 1)] // boundary passthrough
[InlineData(45, 45)] // ordinary passthrough
public void ResolvedMaintenanceCommandTimeout_Clamps_To_MinimumOneMinute(int configured, int expectedMinutes)
{
var options = new AuditLogPurgeOptions { MaintenanceCommandTimeoutMinutes = configured };
Assert.Equal(TimeSpan.FromMinutes(expectedMinutes), options.ResolvedMaintenanceCommandTimeout);
}
}
@@ -42,10 +42,10 @@ public class CentralAuditWriteFailuresTests : TestKit
public Task<IReadOnlyList<AuditEvent>> QueryAsync(
AuditLogQueryFilter filter, AuditLogPaging paging, CancellationToken ct = default) =>
Task.FromResult<IReadOnlyList<AuditEvent>>(Array.Empty<AuditEvent>());
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default) =>
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
Task.FromResult(0L);
public Task<long> PurgeChannelOlderThanAsync(
string channel, DateTime threshold, int batchSize, CancellationToken ct = default) =>
string channel, DateTime threshold, int batchSize, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
Task.FromResult(0L);
public Task<long> BackfillSourceNodeAsync(
string sentinel, DateTime before, int batchSize, CancellationToken ct = default) =>
@@ -86,11 +86,11 @@ public class SiteAuditReconciliationActorTests : TestKit, IClassFixture<MsSqlMig
AuditLogQueryFilter filter, AuditLogPaging paging, CancellationToken ct = default) =>
Task.FromResult<IReadOnlyList<AuditEvent>>(Inserted);
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default) =>
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
Task.FromResult(0L);
public Task<long> PurgeChannelOlderThanAsync(
string channel, DateTime threshold, int batchSize, CancellationToken ct = default) =>
string channel, DateTime threshold, int batchSize, TimeSpan? commandTimeout = null, CancellationToken ct = default) =>
Task.FromResult(0L);
public Task<long> BackfillSourceNodeAsync(
@@ -474,4 +474,54 @@ WHERE name = 'UX_AuditLog_EventId'
Assert.Contains(rows, r => r.EventId == dbOldId);
Assert.Contains(rows, r => r.EventId == dbRecentId);
}
// ---------------------------------------------------------------------
// 5. SwitchOut_WithExplicitCommandTimeout_Succeeds (Task 4)
// ---------------------------------------------------------------------
/// <summary>
/// Task 4 (arch-review 04, S2): proves the explicit-<see cref="TimeSpan"/> maintenance-timeout
/// overload of <see cref="IAuditLogRepository.SwitchOutPartitionAsync"/> runs the real
/// drop-and-rebuild dance to completion against SQL Server — the old row is purged, the kept row
/// survives, and the returned sampled row-count reflects the switched partition. Exercising the
/// timeout path end-to-end guards against a regression that only sets the timeout on the sample
/// command and forgets the DDL batch (or vice versa).
/// </summary>
[SkippableFact]
public async Task SwitchOut_WithExplicitCommandTimeout_Succeeds()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = "switch-timeout-" + Guid.NewGuid().ToString("N").Substring(0, 8);
var oldEventId = Guid.NewGuid();
var keptEventId = Guid.NewGuid();
var (oldOccurred, keptOccurred, _, _) = SeedOccurredAt();
await using (var seedConn = _fixture.OpenConnection())
{
await DirectInsertAsync(seedConn, oldEventId, oldOccurred, siteId);
await DirectInsertAsync(seedConn, keptEventId, keptOccurred, siteId);
}
var janBoundary = new DateTime(2026, 1, 1, 0, 0, 0, DateTimeKind.Utc);
await using (var ctx = CreateContext())
{
var repo = new AuditLogRepository(ctx);
var rowsDeleted = await repo.SwitchOutPartitionAsync(janBoundary, TimeSpan.FromMinutes(30));
Assert.True(rowsDeleted >= 1,
$"Expected the Jan-2026 partition switch-out to report >= 1 sampled row; got {rowsDeleted}.");
}
await using var verify = CreateContext();
var rows = await verify.Set<AuditLogRow>()
.Where(e => e.SourceSiteId == siteId)
.ToListAsync();
Assert.DoesNotContain(rows, r => r.EventId == oldEventId);
Assert.Contains(rows, r => r.EventId == keptEventId);
// The dance must leave the idempotency-supporting unique index rebuilt.
await using var check = _fixture.OpenConnection();
await AssertUxIndexExistsAsync(check);
}
}
@@ -86,11 +86,11 @@ public class SiteAuditPushFlowTests : TestKit
AuditLogQueryFilter filter, AuditLogPaging paging, CancellationToken ct = default)
=> throw new NotSupportedException();
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, CancellationToken ct = default)
public Task<long> SwitchOutPartitionAsync(DateTime monthBoundary, TimeSpan? commandTimeout = null, CancellationToken ct = default)
=> throw new NotSupportedException();
public Task<long> PurgeChannelOlderThanAsync(
string channel, DateTime threshold, int batchSize, CancellationToken ct = default)
string channel, DateTime threshold, int batchSize, TimeSpan? commandTimeout = null, CancellationToken ct = default)
=> throw new NotSupportedException();
public Task<long> BackfillSourceNodeAsync(