0d8a80aa27
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
425 lines
16 KiB
C#
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());
|
|
}
|
|
}
|