Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs
T
Joseph Doherty 0d8a80aa27 feat(localdb): rewire SiteEventLogger onto the consolidated site database
Completes Task 5a of the LocalDb Phase 1 adoption plan. The GUID-id half landed
with Task 2 (727fa48c) because leaving it out would have committed a writer that
could not satisfy site_events.id NOT NULL; this is the connection half, which
was blocked on Task 3.

SiteEventLogger owned a SqliteConnection built from SiteEventLogOptions
.DatabasePath. It now takes ILocalDb and gets that connection from
CreateConnection() - already open, pragma-configured, and carrying the
zb_hlc_next() UDF that site_events' capture triggers call. It still owns and
disposes the connection; WithConnection's signature and locking semantics are
untouched, so EventLogQueryService and EventLogPurgeService are unaffected.

The connectionStringOverride seam is deleted rather than preserved. site_events
is a replicated table, so a raw connection lacks the UDF and fails closed on
every insert - an override could only produce a logger that cannot write. It had
no callers outside this class (the connectionStringOverride hits elsewhere in the
tree belong to SqliteAuditWriter, a different type).

Tests: a shared TestLocalDb helper gives each fixture a real ILocalDb over a temp
file. Real rather than stubbed on purpose - a stub handing back a bare
SqliteConnection would pass today and fail closed the moment the table is
registered, which is exactly the silent-wiring failure mode this family has hit
three times. ServiceWiringTests' DI path also needed AddZbLocalDb, mirroring
SiteServiceRegistration.

Verified: build 0 warnings; SiteEventLogging 70/70, Host 294/294,
SiteRuntime 530/530.

Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
2026-07-19 09:07:49 -04:00

425 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 TestLocalDb _localDb;
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
};
_localDb = TestLocalDb.Create(_dbPath);
_eventLogger = new SiteEventLogger(
Options.Create(_options),
NullLogger<SiteEventLogger>.Instance,
_localDb.Db);
}
public void Dispose()
{
_eventLogger.Dispose();
_localDb.Dispose();
TestLocalDb.DeleteFiles(_dbPath);
GC.SuppressFinalize(this);
}
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());
}
}