Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Integration/NotifyDispatcherAuditTrailTests.cs
T
Joseph Doherty da23f2dcae test(mssql): close register row 82 — throttle cross-process create+migrate, stop leaked test actors
AuditLog.Tests flaked under parallel full-solution runs. Three distinct
mechanisms, all load-sensitive and all green in isolation.

1. MsSqlMigrationFixture create+migrate saturation (the register's headline).
   Database NAMING was already isolated (a guid per fixture), but nothing
   bounded how many fixtures ran CREATE DATABASE + the ~100-migration chain at
   once. xunit parallelises processor-count collections PER PROCESS, and a
   solution-level `dotnet test` starts several MSSQL-backed processes together,
   so the dev container saw dozens of simultaneous fresh-database migrations.
   That is resource saturation, not object-level locking, and it pushed
   individual DDL statements past EF's default 30s command timeout — every
   failure had the identical fingerprint the register recorded:
   MsSqlMigrationFixture..ctor -> Migrator.MigrateAsync -> SqlException
   "Execution Timeout Expired" (error 258), which xunit surfaces as
   "Class fixture type ... threw in its constructor" against every test in the
   class.

   Fix: a machine-wide counting semaphore over the create+migrate window, built
   from sp_getapplock on master (ScadaBridgeTestMigrate/0..N-1, default 4 slots,
   SCADABRIDGE_MSSQL_TEST_MIGRATE_SLOTS to override). An xunit collection cannot
   do this — the contention is cross-PROCESS, so the arbiter has to live on the
   shared server. The gate connection is unpooled (a pooled connection defers the
   implicit release of a session-scoped app lock until reuse) and releases
   explicitly; a crashed process drops its connection and SQL releases the lock,
   so the gate cannot wedge the suite, and a deadline miss proceeds ungated
   rather than failing. Migration commands also get a 300s timeout and
   CREATE/DROP DATABASE 120s: under a bounded queue the server is busy but
   progressing, so waiting is the correct response. Plus a once-per-process
   best-effort sweep of ScadaBridgeAuditMigTest_* databases older than 2h so a
   killed run does not leave strays, and the connectivity probe now retries
   (3 attempts) — a busy server misread as an absent one would silently turn
   every MSSQL test into a Skip, which reads green and is worse than a red.

2. PartitionPurgeTests leaked AuditLogPurgeActors. Each ticks every 100ms and
   switches out the Jan-2026 partition; they were only stopped implicitly by
   TestKit Dispose -> Shutdown, which is timeout-bounded and does not fail when
   it expires. Under load a previous test's actor was still ticking against the
   shared per-class fixture DB, so PerChannelOverride_... found its seeded
   Jan-15-2026 row already gone (Expected: 1, Actual: 0).

3. NotifyDispatcherAuditTrailTests leaked NotificationOutboxActors, same shape.
   The dispatcher claims EVERY due row, not just the test's siteId, so a leaked
   actor delivered the next test's notification through its own exhausted
   QueuedOutcomeAdapter — a transient outcome, leaving the row in Retrying
   (Expected: Delivered, Actual: Retrying) and audit counts short.

   Both fixed by stopping the actor inside the test that created it
   (Watch/Stop/ExpectTerminated), removing the dependency on shutdown timing.

Evidence. Reproducer: 10 concurrent ConfigurationDatabase.Tests processes
against the one dev SQL Server — before, 10/10 processes failed (17-77 failures
each, 100% the ctor->MigrateAsync timeout); after, 3 consecutive runs 10/10
green, 395/395 each. Realistic shape (3x AuditLog.Tests + 1x
ConfigurationDatabase.Tests concurrent): first post-fix run still showed the
NotifyDispatcher leak, then 3 consecutive clean runs. Standalone: AuditLog.Tests
383/383, ConfigurationDatabase.Tests 395/395 (12s, unchanged from baseline),
SiteCallAudit.Tests 66/66. No orphan databases or stuck app locks left behind.

docs/test_infra/test_infra_db.md documents the ephemeral per-test-class
databases, the throttle and its env override, the timeouts, and the stray sweep.
2026-08-17 04:08:45 -04:00

407 lines
18 KiB
C#

using Akka.Actor;
using Akka.TestKit.Xunit2;
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging.Abstractions;
using ZB.MOM.WW.ScadaBridge.AuditLog.Central;
using ZB.MOM.WW.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Entities.Notifications;
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Repositories;
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase;
using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase.Repositories;
using ZB.MOM.WW.ScadaBridge.ConfigurationDatabase.Tests.Migrations;
using ZB.MOM.WW.ScadaBridge.NotificationOutbox;
using ZB.MOM.WW.ScadaBridge.NotificationOutbox.Delivery;
using ZB.MOM.WW.ScadaBridge.NotificationOutbox.Messages;
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Tests.Integration;
/// <summary>
/// Audit Log #23 — M4 Bundle E (Task E2): end-to-end audit trail produced by
/// the central <see cref="NotificationOutboxActor"/> dispatcher loop. Wires
/// the production <see cref="CentralAuditWriter"/> onto the real
/// <see cref="AuditLogRepository"/> against the per-class
/// <see cref="MsSqlMigrationFixture"/> MSSQL database, drives the dispatcher
/// with a stub <see cref="INotificationDeliveryAdapter"/> that yields a
/// transient-then-success sequence, and asserts the resulting
/// <see cref="AuditChannel.Notification"/>/<see cref="AuditKind.NotifyDeliver"/>
/// rows materialise with the expected Attempted/Delivered shape.
/// </summary>
/// <remarks>
/// <para>
/// The Submit row is normally produced by the site-side <c>Notify.Send</c>
/// wrapper (Bundle C); for this E2E we pre-insert a single AuditLog Submit row
/// via <see cref="IAuditLogRepository"/> alongside the seeded
/// <see cref="Notification"/> row so the assertions can confirm the dispatcher
/// emissions slot in alongside it. This keeps the test focused on the
/// dispatcher's emission shape without depending on the upstream site path.
/// </para>
/// <para>
/// Each test uses a unique notification id + source-site id so concurrent
/// tests sharing the MSSQL fixture don't interfere. The dispatcher is driven
/// deterministically via the internal
/// <c>InternalMessages.DispatchTick.Instance</c> sentinel (same pattern the
/// existing NotificationOutbox.Tests use).
/// </para>
/// </remarks>
public class NotifyDispatcherAuditTrailTests : TestKit, IClassFixture<MsSqlMigrationFixture>
{
private readonly MsSqlMigrationFixture _fixture;
public NotifyDispatcherAuditTrailTests(MsSqlMigrationFixture fixture)
{
_fixture = fixture;
}
private static string NewSiteId() =>
"test-e2-notify-" + Guid.NewGuid().ToString("N").Substring(0, 8);
private ScadaBridgeDbContext CreateContext()
{
var options = new DbContextOptionsBuilder<ScadaBridgeDbContext>()
.UseSqlServer(_fixture.ConnectionString)
.ConfigureWarnings(w => w.Ignore(
Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId.PendingModelChangesWarning))
.Options;
return new ScadaBridgeDbContext(options);
}
/// <summary>
/// Builds a DI provider that mirrors the production wiring expected by
/// <see cref="NotificationOutboxActor"/>: scoped EF-backed
/// <see cref="INotificationOutboxRepository"/> + <see cref="INotificationRepository"/>
/// + the supplied <see cref="INotificationDeliveryAdapter"/>. The
/// <see cref="IAuditLogRepository"/> registration powers the
/// <see cref="CentralAuditWriter"/> the actor will emit through.
/// </summary>
private IServiceProvider BuildServiceProvider(INotificationDeliveryAdapter adapter)
{
var services = new ServiceCollection();
services.AddDbContext<ScadaBridgeDbContext>(opts =>
opts.UseSqlServer(_fixture.ConnectionString)
.ConfigureWarnings(w => w.Ignore(
Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId.PendingModelChangesWarning)));
services.AddScoped<INotificationOutboxRepository>(sp =>
new NotificationOutboxRepository(sp.GetRequiredService<ScadaBridgeDbContext>()));
services.AddScoped<INotificationRepository>(sp =>
new NotificationRepository(sp.GetRequiredService<ScadaBridgeDbContext>()));
services.AddScoped<IAuditLogRepository>(sp =>
new AuditLogRepository(sp.GetRequiredService<ScadaBridgeDbContext>()));
services.AddScoped<INotificationDeliveryAdapter>(_ => adapter);
return services.BuildServiceProvider();
}
/// <summary>
/// Stub adapter that yields the next outcome from a configurable queue per
/// call. Lets a single dispatch sweep exercise the transient-then-success
/// transition by alternating <see cref="DeliveryResult.TransientFailure"/>
/// and <see cref="DeliveryResult.Success"/>.
/// </summary>
private sealed class QueuedOutcomeAdapter : INotificationDeliveryAdapter
{
private readonly Queue<DeliveryOutcome> _outcomes;
public int CallCount;
public QueuedOutcomeAdapter(params DeliveryOutcome[] outcomes)
{
_outcomes = new Queue<DeliveryOutcome>(outcomes);
}
public NotificationType Type => NotificationType.Email;
public Task<DeliveryOutcome> DeliverAsync(
Notification notification, CancellationToken cancellationToken = default)
{
Interlocked.Increment(ref CallCount);
// Defensive — if a test under-supplies outcomes we surface the
// problem as an explicit transient failure rather than throwing
// (the dispatcher would log + skip the notification but the audit
// assertions would be misleading).
var outcome = _outcomes.Count > 0
? _outcomes.Dequeue()
: DeliveryOutcome.Transient("test stub out of outcomes");
return Task.FromResult(outcome);
}
}
/// <summary>
/// Inserts a single SMTP configuration row so the dispatcher's
/// <c>ResolveRetryPolicyAsync</c> sees a real (maxRetries, retryDelay)
/// pair rather than the conservative fallback. A tiny positive RetryDelay
/// means a transient outcome's <c>NextAttemptAt</c> is immediately due —
/// useful so the SECOND DispatchTick re-claims the row without waiting.
/// NO-002: the dispatcher now clamps a non-positive RetryDelay to the
/// 1-minute fallback to avoid burn-looping on transient failures, so this
/// must be a strictly positive value (1 ms is fine for tests).
/// </summary>
private async Task SeedSmtpConfigAsync(int maxRetries = 5)
{
await using var ctx = CreateContext();
ctx.SmtpConfigurations.Add(new SmtpConfiguration(
"smtp.example.com", "Basic", "noreply@example.com")
{
MaxRetries = maxRetries,
RetryDelay = TimeSpan.FromMilliseconds(1),
});
await ctx.SaveChangesAsync();
}
/// <summary>
/// Seeds the Pending outbox row the dispatcher will claim. Using a fixed
/// caller-supplied <c>notificationId</c> so the test can later query the
/// AuditLog by <see cref="AuditEvent.CorrelationId"/> = notificationId.
/// </summary>
private async Task<Notification> SeedNotificationAsync(
Guid notificationId, string siteId, string listName = "ops-team")
{
await using var ctx = CreateContext();
var n = new Notification(
notificationId.ToString("D"),
NotificationType.Email,
listName,
"Tank overflow",
"Tank 3 level critical",
siteId)
{
SourceInstanceId = "Plant.Pump42",
SourceScript = "AlarmScript",
CreatedAt = DateTimeOffset.UtcNow.AddMinutes(-1),
};
ctx.Notifications.Add(n);
await ctx.SaveChangesAsync();
return n;
}
/// <summary>
/// Pre-inserts the Submit AuditLog row that the site-side Notify.Send
/// wrapper would have emitted (Bundle C). Keeps the assertions on the
/// dispatcher emissions intact without depending on the upstream site
/// path.
/// </summary>
private async Task SeedSubmitAuditRowAsync(Guid notificationId, string siteId)
{
await using var ctx = CreateContext();
var repo = new AuditLogRepository(ctx);
var submitEvt = ScadaBridgeAuditEventFactory.Create(
eventId: Guid.NewGuid(),
occurredAtUtc: DateTime.UtcNow.AddMinutes(-1),
channel: AuditChannel.Notification,
kind: AuditKind.NotifySend,
correlationId: notificationId,
sourceSiteId: siteId,
sourceInstanceId: "Plant.Pump42",
sourceScript: "AlarmScript",
target: "ops-team",
status: AuditStatus.Submitted,
ingestedAtUtc: new DateTimeOffset(DateTime.UtcNow.AddMinutes(-1)));
await repo.InsertIfNotExistsAsync(submitEvt);
}
/// <summary>
/// Stops a dispatcher actor and blocks until it is actually dead.
/// </summary>
/// <remarks>
/// <para>
/// Deferred-work register row 82. The dispatcher claims <b>every</b> due row in the
/// Notifications table — it is not scoped to the per-test <c>siteId</c> — and the
/// tests in this class share one <see cref="MsSqlMigrationFixture"/> database. The
/// actors were only ever stopped implicitly, by <see cref="TestKit"/>'s
/// <c>Dispose</c> → <c>Shutdown</c>, which is bounded by a timeout and does not fail
/// when that timeout expires. On a loaded machine an earlier test's dispatcher was
/// therefore still alive when the next test seeded its notification, claimed that
/// row, and delivered it through its OWN exhausted
/// <see cref="QueuedOutcomeAdapter"/> — which returns a transient outcome, leaving
/// the row in <c>Retrying</c> (observed: <c>Expected: Delivered, Actual: Retrying</c>)
/// and the audit-row counts short (<c>Range: (3 - 4), Actual: 2</c>).
/// </para>
/// <para>
/// Stopping the actor inside the test that created it removes the dependency on
/// ActorSystem-shutdown timing, so no dispatcher outlives the rows it is allowed to
/// touch.
/// </para>
/// </remarks>
private void StopDispatcher(IActorRef actor)
{
Watch(actor);
Sys.Stop(actor);
// A stop is processed after the in-flight tick completes, so this also
// guarantees no delivery is still running against the fixture DB.
ExpectTerminated(actor, TimeSpan.FromSeconds(30));
Unwatch(actor);
}
private static NotificationOutboxOptions LongDispatchOptions() =>
// 1h dispatch + 24h purge so PreStart's timers never fire during the
// test; the test drives the dispatcher with explicit DispatchTick.
new()
{
DispatchInterval = TimeSpan.FromHours(1),
PurgeInterval = TimeSpan.FromDays(1),
};
[SkippableFact]
public async Task NotifyDispatcher_FailThenSuccess_Emits_TwoAttempts_OneDelivered_Terminal()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = NewSiteId();
var notificationId = Guid.NewGuid();
await SeedSmtpConfigAsync(maxRetries: 5);
await SeedNotificationAsync(notificationId, siteId);
await SeedSubmitAuditRowAsync(notificationId, siteId);
var adapter = new QueuedOutcomeAdapter(
DeliveryOutcome.Transient("smtp 421 try again"),
DeliveryOutcome.Success("ops@example.com"));
var serviceProvider = BuildServiceProvider(adapter);
var auditWriter = new CentralAuditWriter(
serviceProvider,
NullLogger<CentralAuditWriter>.Instance);
var actor = Sys.ActorOf(Props.Create(() => new NotificationOutboxActor(
serviceProvider,
LongDispatchOptions(),
(ICentralAuditWriter)auditWriter,
NullLogger<NotificationOutboxActor>.Instance)));
// First tick: transient failure → one Attempted row, no terminal row.
actor.Tell(InternalMessages.DispatchTick.Instance);
await AwaitAssertAsync(async () =>
{
await using var ctx = CreateContext();
var repo = new AuditLogRepository(ctx);
var rows = await repo.QueryAsync(
new AuditLogQueryFilter(SourceSiteIds: new[] { siteId }),
new AuditLogPaging(PageSize: 50));
// 1 Submit + 1 Attempted = 2 rows so far.
Assert.Equal(2, rows.Count);
Assert.Single(rows, r => r.AsRow().Kind == AuditKind.NotifyDeliver
&& r.AsRow().Status == AuditStatus.Attempted);
Assert.Single(rows, r => r.AsRow().Kind == AuditKind.NotifySend);
}, TimeSpan.FromSeconds(15));
// Second tick: success → second Attempted + one Delivered terminal.
actor.Tell(InternalMessages.DispatchTick.Instance);
await AwaitAssertAsync(async () =>
{
await using var ctx = CreateContext();
var repo = new AuditLogRepository(ctx);
var rows = await repo.QueryAsync(
new AuditLogQueryFilter(SourceSiteIds: new[] { siteId }),
new AuditLogPaging(PageSize: 50));
// 1 Submit + 2 Attempted + 1 Delivered terminal = 4 rows.
Assert.InRange(rows.Count, 3, 4);
var notifyDeliverRows = rows
.Where(r => r.AsRow().Kind == AuditKind.NotifyDeliver)
.ToList();
Assert.Equal(2, notifyDeliverRows.Count(r => r.AsRow().Status == AuditStatus.Attempted));
var terminal = Assert.Single(notifyDeliverRows, r => r.AsRow().Status == AuditStatus.Delivered);
// All NotifyDeliver rows correlate to the original notification id.
Assert.All(notifyDeliverRows, r => Assert.Equal(notificationId, r.CorrelationId));
Assert.Equal("ops-team", terminal.Target);
}, TimeSpan.FromSeconds(15));
// Operational Notifications table mirrors the audit outcome.
await AwaitAssertAsync(async () =>
{
await using var ctx = CreateContext();
var n = await ctx.Notifications.SingleAsync(
row => row.NotificationId == notificationId.ToString("D"));
Assert.Equal(NotificationStatus.Delivered, n.Status);
Assert.NotNull(n.DeliveredAt);
}, TimeSpan.FromSeconds(15));
// The dispatcher claims every due row, not just this test's — it must not
// outlive the test (register row 82).
StopDispatcher(actor);
}
[SkippableFact]
public async Task NotifyDispatcher_AuditWriter_Throws_DeliveryStillSucceeds()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = NewSiteId();
var notificationId = Guid.NewGuid();
await SeedSmtpConfigAsync(maxRetries: 5);
await SeedNotificationAsync(notificationId, siteId);
var adapter = new QueuedOutcomeAdapter(
DeliveryOutcome.Success("ops@example.com"));
var serviceProvider = BuildServiceProvider(adapter);
// ALWAYS-throw writer wired in place of the production
// CentralAuditWriter. The dispatcher MUST still deliver the
// notification and persist the terminal Delivered transition
// regardless of the audit subsystem being down (alog.md §13).
var throwingWriter = new ThrowingCentralAuditWriter();
var actor = Sys.ActorOf(Props.Create(() => new NotificationOutboxActor(
serviceProvider,
LongDispatchOptions(),
(ICentralAuditWriter)throwingWriter,
NullLogger<NotificationOutboxActor>.Instance)));
actor.Tell(InternalMessages.DispatchTick.Instance);
// The Notifications table is the operational source of truth — assert
// it transitions to Delivered even though every audit write threw.
await AwaitAssertAsync(async () =>
{
await using var ctx = CreateContext();
var n = await ctx.Notifications.SingleAsync(
row => row.NotificationId == notificationId.ToString("D"));
Assert.Equal(NotificationStatus.Delivered, n.Status);
Assert.NotNull(n.DeliveredAt);
}, TimeSpan.FromSeconds(15));
// The writer was attempted (at least once for the Attempted row, plus
// once for the Delivered terminal) — proves the dispatcher tried to
// emit and absorbed the throws rather than aborting the action.
//
// AwaitAssert, not a bare Assert: the dispatcher deliberately persists
// the delivery state BEFORE emitting either audit row (DeliverOneAsync
// writes the row, then Attempted, then the terminal), so observing
// Delivered above establishes NO happens-before edge with the audit
// writes — under a loaded parallel run the continuation after the DB
// write can be scheduled after the poll that saw Delivered, yielding a
// spurious "saw 0". The bounded wait removes the ordering assumption
// without weakening the claim: the writer must genuinely be invoked at
// least twice inside the timeout or the test still fails.
await AwaitAssertAsync(
() =>
{
Assert.True(throwingWriter.AttemptCount >= 2,
$"Expected the dispatcher to attempt audit writes; saw {throwingWriter.AttemptCount}");
return Task.CompletedTask;
},
TimeSpan.FromSeconds(15));
// The dispatcher claims every due row, not just this test's — it must not
// outlive the test (register row 82).
StopDispatcher(actor);
}
/// <summary>
/// Test-only <see cref="ICentralAuditWriter"/> that ALWAYS throws on
/// <see cref="WriteAsync"/>. Used to verify the dispatcher's defensive
/// try/catch contract (alog.md §13) — audit failures must NEVER abort
/// the user-facing notification delivery.
/// </summary>
private sealed class ThrowingCentralAuditWriter : ICentralAuditWriter
{
private int _attemptCount;
public int AttemptCount => Volatile.Read(ref _attemptCount);
public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
{
Interlocked.Increment(ref _attemptCount);
throw new InvalidOperationException(
"test-only ThrowingCentralAuditWriter — audit subsystem unavailable");
}
}
}