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.
This commit is contained in:
Joseph Doherty
2026-08-17 04:08:45 -04:00
parent 07220bc655
commit da23f2dcae
4 changed files with 538 additions and 69 deletions
@@ -200,6 +200,39 @@ public class NotifyDispatcherAuditTrailTests : TestKit, IClassFixture<MsSqlMigra
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.
@@ -280,6 +313,10 @@ public class NotifyDispatcherAuditTrailTests : TestKit, IClassFixture<MsSqlMigra
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]
@@ -342,6 +379,10 @@ public class NotifyDispatcherAuditTrailTests : TestKit, IClassFixture<MsSqlMigra
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>
@@ -156,6 +156,41 @@ SELECT
NullLogger<AuditLogPurgeActor>.Instance)));
}
/// <summary>
/// Stops a purge actor and blocks until it is actually dead, then disposes the
/// service provider that backed it.
/// </summary>
/// <remarks>
/// <para>
/// Deferred-work register row 82. Every actor these tests create ticks every
/// <c>100 ms</c> (<see cref="AuditLogPurgeOptions.IntervalOverride"/>) and switches
/// out the Jan-2026 partition each time it finds one eligible. The tests relied on
/// <see cref="TestKit"/>'s <c>Dispose</c> → <c>Shutdown</c> to stop them between
/// test methods, but that shutdown is bounded by a timeout and does NOT fail when
/// it expires — so on a loaded machine a previous test's actor was still ticking
/// against the (per-class, shared) fixture database while the next test ran.
/// </para>
/// <para>
/// That is what made <c>PerChannelOverride_DeletesOnlyOverriddenChannelsOldRows</c>
/// flake under a parallel full-solution run: it seeds a Jan-15-2026 row and expects
/// its own per-channel DELETE to remove exactly one row, but a leaked actor could
/// switch the whole Jan-2026 partition out first, leaving nothing to delete
/// (observed: <c>Assert.Equal() Failure … Expected: 1, Actual: 0</c>). Stopping the
/// actor inside the test that created it removes the dependency on shutdown timing
/// altogether.
/// </para>
/// </remarks>
private void StopPurgeActor(IActorRef actor, ServiceProvider sp)
{
Watch(actor);
Sys.Stop(actor);
// A stop is processed after the in-flight tick completes, so this also
// guarantees no partition switch is still running against the fixture DB.
ExpectTerminated(actor, TimeSpan.FromSeconds(30));
Unwatch(actor);
sp.Dispose();
}
/// <summary>
/// Returns three seed timestamps and a computed <c>RetentionDays</c> value that
/// keep the purge-intent date-independent regardless of when the test runs.
@@ -246,7 +281,7 @@ SELECT
};
var auditOptions = new AuditLogOptions { RetentionDays = retentionDays };
CreateActor(sp, purgeOptions, auditOptions);
var actor = CreateActor(sp, purgeOptions, auditOptions);
// The Jan-2026 partition boundary is the only eligible one in this fixture DB.
var janBoundary = new DateTime(2026, 1, 1, 0, 0, 0, DateTimeKind.Utc);
@@ -256,6 +291,10 @@ SELECT
Assert.True(matched.RowsDeleted >= 1,
$"Expected RowsDeleted >= 1 for Jan-2026 boundary; got {matched.RowsDeleted}.");
// Stop the actor before verifying: its 100ms tick must not outlive this test
// and start purging the next one's seed rows (register row 82).
StopPurgeActor(actor, sp);
// Allow a brief settle in case the actor re-enumerates quickly.
await Task.Delay(TimeSpan.FromMilliseconds(500));
@@ -303,7 +342,7 @@ SELECT
var probe = CreateTestProbe();
Sys.EventStream.Subscribe(probe.Ref, typeof(AuditLogPurgedEvent));
CreateActor(
var actor = CreateActor(
sp,
new AuditLogPurgeOptions
{
@@ -317,6 +356,10 @@ SELECT
isMessage: m => m.MonthBoundary == janBoundary,
max: TimeSpan.FromSeconds(30));
// Stop the actor before verifying: its 100ms tick must not outlive this test
// and start purging the next one's seed rows (register row 82).
StopPurgeActor(actor, sp);
// Open a fresh connection (the actor's pool is owned by EF) and
// assert the index is present post-purge.
await using var check = _fixture.OpenConnection();
@@ -357,7 +400,7 @@ SELECT
var probe = CreateTestProbe();
Sys.EventStream.Subscribe(probe.Ref, typeof(AuditLogPurgedEvent));
CreateActor(
var actor = CreateActor(
sp,
new AuditLogPurgeOptions
{
@@ -371,6 +414,10 @@ SELECT
isMessage: m => m.MonthBoundary == janBoundary,
max: TimeSpan.FromSeconds(30));
// Stop the actor before verifying: its 100ms tick must not outlive this test
// and start purging the next one's seed rows (register row 82).
StopPurgeActor(actor, sp);
// Settle then exercise InsertIfNotExistsAsync twice for the same
// EventId. The repository's idempotency relies on the aligned clustered
// PK (EventId, OccurredAtUtc) being intact so the IF NOT EXISTS … INSERT