Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs
T
Joseph Doherty 727fa48cba feat(localdb): move site_events to application-minted GUID ids
Tasks 2 + 5a-writer + 5b of the LocalDb Phase 1 plan, landed together because
they are one indivisible change: the schema, the writer that fills it, and every
consumer that assumed the old id semantics.

WHY the id changes. Site pairs will replicate site_events with last-writer-wins on
the primary key. With INTEGER PRIMARY KEY AUTOINCREMENT both nodes independently
mint 1, 2, 3... for unrelated events, so sync would treat them as the same row and
silently overwrite. A GUID makes the event log a pure union across the pair.

Task 2 - schema extracted so the Host's AddZbLocalDb onReady can create the tables
before RegisterReplicated installs capture triggers (pre-registration rows are
never captured):
  - new OperationTrackingSchema.Apply / SiteEventLogSchema.Apply, plain
    Microsoft.Data.Sqlite, no LocalDb dependency
  - both stores delegate their InitializeSchema to them (idempotent, so a
    directly-constructed store still works)
  - OperationTracking is unchanged - it already had a TEXT PK and replicates as-is

Task 5a - SiteEventLogger mints Guid.NewGuid("N") per event and inserts it.

Task 5b - three consumers assumed a monotonic integer id. All three move to
timestamp ordering; leaving any one behind would be a live bug:
  - EventLogQueryService: "id > $afterId" would return an ARBITRARY subset of a
    GUID-keyed table and SILENTLY DROP ROWS from page-through. Now a composite
    (timestamp, id) keyset cursor with an opaque string token; timestamps are not
    unique, so id is the tie-break that guarantees exactly-once paging.
  - EventLogPurgeService: "ORDER BY id ASC LIMIT 1000" would delete a RANDOM batch
    instead of the oldest. Now orders by timestamp.
  - EventLogEntry.Id and both ContinuationTokens: long -> string.

WIRE COMPATIBILITY. Those DTOs cross the site<->central Akka boundary
(SiteCommunicationActor -> CommunicationService -> ManagementActor / CentralUI).
No rolling-upgrade shim is needed because both sides ship in the same deployable
and the rig redeploys as a unit. Checked: no Akka serializer binding pins these
types by name. A stale numeric token degrades to "start from the beginning"
(a visible repeat) rather than throwing or losing rows.

Tests: the two that encoded the old semantics were rewritten to guard the new
invariant rather than deleted - uniqueness instead of monotonicity, and
oldest-purged-first keyed on timestamp. That second test also exposed a latent
weakness: the bulk seed stamped every row with the same UtcNow, so "oldest" was
never actually well-defined; rows now get distinct increasing timestamps, kept
inside the retention window so the retention purge does not eat them first.

Verified:
  dotnet build ZB.MOM.WW.ScadaBridge.slnx -> 0 Error(s), 0 Warning(s)
  SiteEventLogging.Tests -> 70 passed (12 new schema tests, red-first)
  CentralUI.Tests        -> 925 passed
  Commons.Tests          -> 684 passed
  SiteRuntime.Tests      -> 529 passed, 1 pre-existing flaky failure
                            (InstanceActorChildAttributeRaceTests - passes 3/3 in
                            isolation with and without this change)

Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
2026-07-19 03:15:17 -04:00

420 lines
16 KiB
C#

using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;
namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests;
public class EventLogPurgeServiceTests : IDisposable
{
private readonly SiteEventLogger _eventLogger;
private readonly string _dbPath;
private readonly SiteEventLogOptions _options;
/// <summary>
/// SiteEventLogging-023: stop flag for the concurrent stress test. Declared as
/// a <c>volatile</c> field so every writer thread observes the main thread's
/// `_stop = true` write without depending on JIT/runtime quirks. A plain
/// <c>bool</c> local would be legal-cached in a register inside the tight
/// <c>while (!_stop)</c> loop under release-mode optimisation.
/// </summary>
private volatile bool _stop;
public EventLogPurgeServiceTests()
{
_dbPath = Path.Combine(Path.GetTempPath(), $"test_purge_{Guid.NewGuid()}.db");
_options = new SiteEventLogOptions
{
DatabasePath = _dbPath,
RetentionDays = 30,
MaxStorageMb = 1024
};
_eventLogger = new SiteEventLogger(
Options.Create(_options),
NullLogger<SiteEventLogger>.Instance);
}
public void Dispose()
{
_eventLogger.Dispose();
if (File.Exists(_dbPath)) File.Delete(_dbPath);
}
private EventLogPurgeService CreatePurgeService(
SiteEventLogOptions? optionsOverride = null,
SiteEventLogActiveNodeCheck? isActiveNode = null)
{
var opts = optionsOverride ?? _options;
return new EventLogPurgeService(
_eventLogger,
Options.Create(opts),
NullLogger<EventLogPurgeService>.Instance,
isActiveNode);
}
private void InsertEventWithTimestamp(DateTimeOffset timestamp)
{
_eventLogger.WithConnection(connection =>
{
using var cmd = connection.CreateCommand();
cmd.CommandText = """
INSERT INTO site_events (id, timestamp, event_type, severity, source, message)
VALUES ($id, $ts, 'script', 'Info', 'Test', 'Test message')
""";
cmd.Parameters.AddWithValue("$id", Guid.NewGuid().ToString("N"));
cmd.Parameters.AddWithValue("$ts", timestamp.ToString("o"));
cmd.ExecuteNonQuery();
});
}
private long GetEventCount()
{
return _eventLogger.WithConnection(connection =>
{
using var cmd = connection.CreateCommand();
cmd.CommandText = "SELECT COUNT(*) FROM site_events";
return (long)cmd.ExecuteScalar()!;
});
}
[Fact]
public void PurgeByRetention_DeletesOldEvents()
{
// Insert an old event (31 days ago) and a recent one
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
var purge = CreatePurgeService();
purge.RunPurge();
Assert.Equal(1, GetEventCount());
}
[Fact]
public void PurgeByRetention_KeepsRecentEvents()
{
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-29));
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-1));
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
var purge = CreatePurgeService();
purge.RunPurge();
Assert.Equal(3, GetEventCount());
}
[Fact]
public void PurgeByStorageCap_DeletesOldestWhenOverCap()
{
// Insert enough events to have some data
for (int i = 0; i < 100; i++)
{
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
}
// Set an artificially small cap to trigger purge
var smallCapOptions = new SiteEventLogOptions
{
DatabasePath = _dbPath,
RetentionDays = 30,
MaxStorageMb = 0 // 0 MB cap forces purge
};
var purge = CreatePurgeService(smallCapOptions);
purge.RunPurge();
// All events should be purged since cap is 0
Assert.Equal(0, GetEventCount());
}
[Fact]
public void GetDatabaseSizeBytes_ReturnsPositiveValue()
{
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
var purge = CreatePurgeService();
var size = purge.GetDatabaseSizeBytes();
Assert.True(size > 0);
}
/// <summary>
/// Base instant for bulk-seeded events: one day ago, evaluated once so a run is
/// self-consistent.
/// <para>
/// Must stay INSIDE the retention window (<c>RetentionDays</c>, default 30).
/// <see cref="EventLogPurgeService.RunPurge"/> applies the retention purge before
/// the storage-cap purge, so a fixed calendar date in the past would be deleted
/// wholesale as stale and the storage-cap assertions would silently test an empty
/// table rather than cap-trimming behaviour.
/// </para>
/// </summary>
private static readonly DateTimeOffset BulkSeedStart =
DateTimeOffset.UtcNow.AddDays(-1);
/// <summary>
/// Timestamp of the i-th bulk-seeded event. Each row is one second newer than the
/// last, so "oldest" is unambiguous — the storage-cap purge orders by timestamp,
/// and previously every bulk row shared the same <c>UtcNow</c>, which left the
/// oldest-first guarantee untestable.
/// </summary>
private static DateTimeOffset BulkSeedTimestamp(int index) =>
BulkSeedStart.AddSeconds(index);
private void InsertBulkEvents(int count)
{
// Each event carries a sizeable details payload so the database grows
// measurably and the storage cap can be exercised against a realistic file.
var details = new string('x', 2000);
_eventLogger.WithConnection(connection =>
{
for (int i = 0; i < count; i++)
{
using var cmd = connection.CreateCommand();
cmd.CommandText = """
INSERT INTO site_events (id, timestamp, event_type, severity, source, message, details)
VALUES ($id, $ts, 'script', 'Info', 'Test', 'Bulk event', $details)
""";
cmd.Parameters.AddWithValue("$id", Guid.NewGuid().ToString("N"));
cmd.Parameters.AddWithValue("$ts", BulkSeedTimestamp(i).ToString("o"));
cmd.Parameters.AddWithValue("$details", details);
cmd.ExecuteNonQuery();
}
});
}
/// <summary>
/// Oldest surviving event timestamp. Replaces the former <c>MIN(id)</c> probe:
/// ids are GUIDs since LocalDb Phase 1 and carry no ordering, so age is measured
/// on the timestamp column the purge itself orders by.
/// </summary>
private string MinEventTimestamp()
{
return _eventLogger.WithConnection(connection =>
{
using var cmd = connection.CreateCommand();
cmd.CommandText = "SELECT MIN(timestamp) FROM site_events";
var result = cmd.ExecuteScalar();
return result as string ?? "";
});
}
[Fact]
public void PurgeByStorageCap_StopsWhenUnderCap_DoesNotEmptyTable()
{
// Regression test for SiteEventLogging-001 / -002:
// a realistic non-zero cap must trim the oldest events to the budget,
// not delete the entire table.
InsertBulkEvents(3000);
var purge = CreatePurgeService();
var totalSize = purge.GetDatabaseSizeBytes();
// Cap at roughly half the current database size — purge must keep some rows.
var capBytes = totalSize / 2;
var capOptions = new SiteEventLogOptions
{
DatabasePath = _dbPath,
RetentionDays = 30,
MaxStorageMb = (int)Math.Max(1, capBytes / (1024 * 1024))
};
var cappedPurge = CreatePurgeService(capOptions);
cappedPurge.RunPurge();
var remaining = GetEventCount();
Assert.True(remaining > 0, "Storage-cap purge must not delete the entire table.");
Assert.True(remaining < 3000, "Storage-cap purge must remove some events when over cap.");
// The database must actually be back under the cap after purge.
var finalSize = cappedPurge.GetDatabaseSizeBytes();
var finalCapBytes = (long)capOptions.MaxStorageMb * 1024 * 1024;
Assert.True(finalSize <= finalCapBytes,
$"Database size {finalSize} must be at or below cap {finalCapBytes} after purge.");
}
[Fact]
public void PurgeByStorageCap_RemovesOldestEventsFirst()
{
// Regression test for SiteEventLogging-002: only the oldest events should be
// removed when trimming to the cap.
//
// "Oldest" used to mean "lowest autoincrement id". Since LocalDb Phase 1 the id
// is a GUID with no ordering, so both the purge and this test key on timestamp.
// Ordering by id here would delete an arbitrary batch, which is precisely the
// regression this test now guards.
const int eventCount = 3000;
InsertBulkEvents(eventCount);
var purge = CreatePurgeService();
var totalSize = purge.GetDatabaseSizeBytes();
var capOptions = new SiteEventLogOptions
{
DatabasePath = _dbPath,
RetentionDays = 30,
MaxStorageMb = (int)Math.Max(1, (totalSize / 2) / (1024 * 1024))
};
var oldestBefore = MinEventTimestamp();
var cappedPurge = CreatePurgeService(capOptions);
cappedPurge.RunPurge();
var oldestAfter = MinEventTimestamp();
// The surviving rows must be the newest ones — the oldest timestamp advanced.
Assert.True(
string.CompareOrdinal(oldestAfter, oldestBefore) > 0,
$"Oldest events must be purged first; oldest went from '{oldestBefore}' to '{oldestAfter}'.");
// The newest event must still be present.
var newestTimestamp = BulkSeedTimestamp(eventCount - 1).ToString("o");
var newestPresent = _eventLogger.WithConnection(connection =>
{
using var cmd = connection.CreateCommand();
cmd.CommandText = "SELECT COUNT(*) FROM site_events WHERE timestamp = $ts";
cmd.Parameters.AddWithValue("$ts", newestTimestamp);
return (long)cmd.ExecuteScalar()!;
});
Assert.Equal(1L, newestPresent);
}
[Fact]
public async Task StartAsync_DoesNotBlock_OnTheInitialPurge()
{
// SiteEventLogging-014 (re-triaged): on .NET 8+ BackgroundService runs
// ExecuteAsync on a thread-pool thread — the synchronous prelude (the
// initial RunPurge()) does NOT execute on the host startup thread, so
// StartAsync returns promptly and host startup / the /health/ready gate is
// not blocked even by a large initial purge. This test pins that behaviour:
// StartAsync returns fast, and the initial purge still happens shortly
// afterwards on the background scheduler.
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
Assert.Equal(1, GetEventCount());
var purge = CreatePurgeService();
using var cts = new CancellationTokenSource();
var sw = System.Diagnostics.Stopwatch.StartNew();
await purge.StartAsync(cts.Token);
sw.Stop();
Assert.True(sw.ElapsedMilliseconds < 1000,
$"StartAsync blocked for {sw.ElapsedMilliseconds} ms — the initial purge " +
"must not run on the host startup thread.");
// The initial purge still runs on the background scheduler.
var deadline = DateTime.UtcNow.AddSeconds(5);
while (GetEventCount() != 0 && DateTime.UtcNow < deadline)
{
await Task.Delay(25);
}
Assert.Equal(0, GetEventCount());
await cts.CancelAsync();
await purge.StopAsync(CancellationToken.None);
}
[Fact]
public async Task PurgeByStorageCap_ConcurrentWritesDoNotCorruptConnection()
{
// Regression test for SiteEventLogging-003: purge running on a background
// thread while events are recorded on other threads must not throw
// "DataReader already open" / "connection busy" from a shared connection.
InsertBulkEvents(2000);
var purge = CreatePurgeService();
var totalSize = purge.GetDatabaseSizeBytes();
var capOptions = new SiteEventLogOptions
{
DatabasePath = _dbPath,
RetentionDays = 30,
MaxStorageMb = (int)Math.Max(1, (totalSize / 2) / (1024 * 1024))
};
var exceptions = new System.Collections.Concurrent.ConcurrentBag<Exception>();
// SiteEventLogging-023: must be volatile so the writer threads observe the
// main thread's `stop = true` flip after the purge task completes. Without
// it, a release-mode JIT is permitted to cache the `stop = false` read in
// a register inside the tight `while (!stop)` loop and never see the flip,
// causing the writer tasks to hang past xUnit's per-test timeout instead
// of asserting `Empty(exceptions)`.
_stop = false;
var purgeTask = Task.Run(() =>
{
try
{
var p = CreatePurgeService(capOptions);
for (int i = 0; i < 20; i++) p.RunPurge();
}
catch (Exception ex) { exceptions.Add(ex); }
});
var writeTasks = Enumerable.Range(0, 4).Select(_ => Task.Run(async () =>
{
try
{
while (!_stop)
{
await _eventLogger.LogEventAsync("script", "Info", null, "Concurrent", "Concurrent write");
}
}
catch (Exception ex) { exceptions.Add(ex); }
})).ToArray();
await purgeTask;
_stop = true;
await Task.WhenAll(writeTasks);
Assert.Empty(exceptions);
}
// ── SiteEventLogging-019: purge runs only on the active node ──
[Fact]
public void RunPurge_OnStandbyNode_SkipsAllWork()
{
// SiteEventLogging-019: per design, the daily purge runs on the active
// node only. The standby's local SQLite receives no writes, so purging
// there is unnecessary; we gate the purge tick on the injected
// active-node check and early-exit when it returns false. The row
// inserted here is well past retention, so a real purge would delete
// it — the standby gate must leave it intact.
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
Assert.Equal(1, GetEventCount());
var purge = CreatePurgeService(isActiveNode: () => false);
purge.RunPurge();
Assert.Equal(1, GetEventCount());
}
[Fact]
public void RunPurge_OnActiveNode_RunsTheRetentionPurge()
{
// SiteEventLogging-019: when the active-node check returns true the
// service runs the purge as before. Pinned alongside the standby case
// so a future regression that inverts the gate is caught.
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
var purge = CreatePurgeService(isActiveNode: () => true);
purge.RunPurge();
Assert.Equal(1, GetEventCount());
}
[Fact]
public void RunPurge_WithNullCheck_FallsBackToRunning()
{
// SiteEventLogging-019: when no active-node check is supplied (the
// default for non-clustered hosts and pre-existing tests), the service
// preserves the pre-fix "run on every tick" behaviour rather than
// silently skipping every tick. Backward compatibility guard.
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
var purge = CreatePurgeService(isActiveNode: null);
purge.RunPurge();
Assert.Equal(0, GetEventCount());
}
}