ddb3c32e06
Row 81 — the cap could not be enforced on a replicated node. MaxStorageMb was compared against page_count-freelist_count over the WHOLE consolidated LocalDb file, which since Phase 1/2 holds ten tables plus __localdb_oplog / __localdb_row_version / __localdb_snapshot_state. Every 1000-row trim batch freed ~390 KB of site_events pages and added ~1000 oplog rows + ~1000 tombstones to the same file, so the measured size did not fall, the "size did not decrease" guard fired, and the trim stopped 2.5x over a 64 MB cap with 226 k rows still present. A node whose peer was down could not enforce its cap at all, and the event log's budget was in practice shared with bookkeeping it does not own. The cap now measures site_events AND ITS FOUR INDEXES only, so replication bookkeeping can neither consume nor block the budget — and the cap stops being a function of the peer's health, which was the wrong direction of coupling: an inflated oplog is a replication fault, and letting it drive event deletion would destroy operational history in response to one. dbstat — the exact per-table measurement the register proposed — is NOT usable here, verified before implementing. It is a compile-time option and the bundled SQLitePCLRaw.lib.e_sqlite3 (SQLite 3.53.3) does not enable it: PRAGMA compile_options lists no ENABLE_DBSTAT_VTAB, pragma_module_list returns ten modules with neither dbstat nor sqlite_dbpage, and selecting from dbstat fails with "no such table". Switching SQLite builds was rejected — the provider is shared with ZB.MOM.WW.LocalDb and every other consumer, so it trades cap accuracy for fleet-wide version skew. The footprint is therefore modelled from sampled row width (500 rows each end, octet_length so multi-byte UTF-8 is not under-counted) through a page-layout model; whole pages rather than a flat rate, because page fill collapses once rows approach half a page and a linear model underestimates that by ~40%. Clamped by whole-file logical size, a true upper bound that can only correct an over-estimate and never binds on a replicated node. Index pages count against the cap deliberately: measured at ~34% of the table's footprint, and the 1 GB default was sized against a 393 B/row figure that already included them. Guard semantics restated — two backstops replace the single on-disk check: (1) row width unsampleable => refuse to trim (checked before the cap comparison, since a zero width makes "over cap" unanswerable rather than false; the old loop's answer to an unanswerable cap was to keep deleting); (2) estimated size not falling across a batch => stop. (2) is the old guard re-based onto the table-scoped metric, so it can no longer be tripped by replication bookkeeping and now means exactly one thing: events are arriving as fast as the trim removes them. For that to be observable the loop re-reads the row count each batch, while bytes-per-row is sampled once per tick and held fixed — re-sampling per batch would jitter the estimate as the trim eats the head of the table and could stall the loop through guard (2), the same self-defeating measurement as row 81 itself. Row 84 — LogReplicationBacklogNote moved from per-phase to once per tick, driven by the shared PurgeBudget. A tick where retention AND the cap trim both deleted used to emit two identical Information notes; the tick total is also the more useful number beside an oplog spike. Measured model error: -0.8% / +8.4% / +12.8% across representative workloads, biased high on purpose (an early cap forfeits budget; a low one fails at its only job). Independently cross-checks row 34's harness at 397.2 vs 393 B/row. Fail-before: reverting the estimator to whole-file semantics fails 5 of the new tests and reproduces the original signature exactly (remaining=2000 estimate=21725184 cap=11534336 — rows destroyed, cap still unmet); restoring per-phase notes fails the row-84 test with "collection contained 2 matching items". No config keys added or renamed, so no rig/deploy changes. Decision record: docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md Tests: SiteEventLogging 104/104 (was 93), Host 520/520, solution build clean.
366 lines
16 KiB
C#
366 lines
16 KiB
C#
using Microsoft.Data.Sqlite;
|
|
using Microsoft.Extensions.Logging;
|
|
using Microsoft.Extensions.Logging.Abstractions;
|
|
using Microsoft.Extensions.Options;
|
|
using Xunit.Abstractions;
|
|
|
|
namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests;
|
|
|
|
/// <summary>
|
|
/// Register row 81 — the storage cap measures <c>site_events</c>' own pages, not the whole
|
|
/// consolidated LocalDb file.
|
|
/// </summary>
|
|
/// <remarks>
|
|
/// <para>
|
|
/// The defect these tests close: <c>site_events</c> shares one SQLite file with nine other
|
|
/// tables plus LocalDb's <c>__localdb_oplog</c> / <c>__localdb_row_version</c> bookkeeping, and
|
|
/// the cap used to compare <c>MaxStorageMb</c> against <c>page_count - freelist_count</c> over
|
|
/// that whole file. On a replication-enabled node the trim therefore fought itself — each
|
|
/// 1000-row delete freed ~390 KB of event pages while adding ~1000 oplog rows and ~1000
|
|
/// tombstones to the same file — and stopped 2.5x over a 64 MB cap with 226 k rows still
|
|
/// present (<c>docs/plans/2026-08-15-site-events-purge-burst-measurement.md</c> §5).
|
|
/// </para>
|
|
/// <para>
|
|
/// A real replication pair is not needed to pin the semantics: what matters is that OTHER pages
|
|
/// in the same file neither consume nor block the event log's budget. A plain ballast table
|
|
/// stands in for the oplog, tombstones and the other nine tables alike.
|
|
/// </para>
|
|
/// </remarks>
|
|
public class EventLogStorageCapScopeTests : IDisposable
|
|
{
|
|
private readonly ITestOutputHelper _output;
|
|
private readonly SiteEventLogger _eventLogger;
|
|
private readonly TestLocalDb _localDb;
|
|
private readonly string _dbPath;
|
|
|
|
public EventLogStorageCapScopeTests(ITestOutputHelper output)
|
|
{
|
|
_output = output;
|
|
_dbPath = Path.Combine(Path.GetTempPath(), $"test_capscope_{Guid.NewGuid()}.db");
|
|
_localDb = TestLocalDb.Create(_dbPath);
|
|
_eventLogger = new SiteEventLogger(
|
|
Options.Create(new SiteEventLogOptions { DatabasePath = _dbPath }),
|
|
NullLogger<SiteEventLogger>.Instance,
|
|
_localDb.Db);
|
|
}
|
|
|
|
public void Dispose()
|
|
{
|
|
_eventLogger.Dispose();
|
|
_localDb.Dispose();
|
|
TestLocalDb.DeleteFiles(_dbPath);
|
|
GC.SuppressFinalize(this);
|
|
}
|
|
|
|
private EventLogPurgeService CreatePurgeService(SiteEventLogOptions options, ILogger<EventLogPurgeService>? logger = null) =>
|
|
new(_eventLogger, Options.Create(options), logger ?? NullLogger<EventLogPurgeService>.Instance);
|
|
|
|
private SiteEventLogOptions CapOptions(int maxStorageMb) => new()
|
|
{
|
|
DatabasePath = _dbPath,
|
|
// Far enough in the past that the retention purge never fires — these tests are about
|
|
// the cap trim in isolation, and a shared tick budget would otherwise blur the two.
|
|
RetentionDays = 3650,
|
|
MaxStorageMb = maxStorageMb,
|
|
};
|
|
|
|
/// <summary>Seeds <paramref name="count"/> events, each ~256 bytes of payload.</summary>
|
|
private void SeedEvents(int count)
|
|
{
|
|
var details = new string('x', 200);
|
|
_eventLogger.WithConnection(connection =>
|
|
{
|
|
using var tx = connection.BeginTransaction();
|
|
using var cmd = connection.CreateCommand();
|
|
cmd.Transaction = tx;
|
|
cmd.CommandText = """
|
|
INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details)
|
|
VALUES ($id, $ts, 'script', 'Info', $inst, 'SiteRuntime', 'Bulk event', $details)
|
|
""";
|
|
var id = cmd.Parameters.Add("$id", SqliteType.Text);
|
|
var ts = cmd.Parameters.Add("$ts", SqliteType.Text);
|
|
var inst = cmd.Parameters.Add("$inst", SqliteType.Text);
|
|
var det = cmd.Parameters.Add("$details", SqliteType.Text);
|
|
var start = new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero);
|
|
for (var i = 0; i < count; i++)
|
|
{
|
|
id.Value = Guid.NewGuid().ToString("N");
|
|
ts.Value = start.AddSeconds(i).ToString("o");
|
|
inst.Value = i % 3 == 0 ? DBNull.Value : Guid.NewGuid().ToString();
|
|
det.Value = details;
|
|
cmd.ExecuteNonQuery();
|
|
}
|
|
tx.Commit();
|
|
});
|
|
}
|
|
|
|
/// <summary>
|
|
/// Fills a non-event table in the SAME file, standing in for LocalDb's oplog and
|
|
/// row-version tables and the nine other consolidated tables.
|
|
/// </summary>
|
|
private void SeedBallast(int rows, int bytesPerRow)
|
|
{
|
|
var payload = new string('b', bytesPerRow);
|
|
_eventLogger.WithConnection(connection =>
|
|
{
|
|
using var create = connection.CreateCommand();
|
|
create.CommandText = "CREATE TABLE IF NOT EXISTS test_ballast (seq INTEGER PRIMARY KEY, row_json TEXT)";
|
|
create.ExecuteNonQuery();
|
|
|
|
using var tx = connection.BeginTransaction();
|
|
using var cmd = connection.CreateCommand();
|
|
cmd.Transaction = tx;
|
|
cmd.CommandText = "INSERT INTO test_ballast (row_json) VALUES ($p)";
|
|
var p = cmd.Parameters.Add("$p", SqliteType.Text);
|
|
for (var i = 0; i < rows; i++)
|
|
{
|
|
p.Value = payload;
|
|
cmd.ExecuteNonQuery();
|
|
}
|
|
tx.Commit();
|
|
});
|
|
}
|
|
|
|
private long EventCount() => _eventLogger.WithConnection(connection =>
|
|
{
|
|
using var cmd = connection.CreateCommand();
|
|
cmd.CommandText = "SELECT COUNT(*) FROM site_events";
|
|
return (long)cmd.ExecuteScalar()!;
|
|
});
|
|
|
|
[Fact]
|
|
public void EstimatedSize_ExcludesOtherTablesInTheSameFile()
|
|
{
|
|
// A small ballast is seeded up front so the whole-file clamp inside the estimator is
|
|
// slack in BOTH readings — otherwise the first would be pinned to the file size and the
|
|
// comparison would be measuring the clamp rather than the model.
|
|
SeedBallast(rows: 4_000, bytesPerRow: 400);
|
|
SeedEvents(4000);
|
|
|
|
var purge = CreatePurgeService(CapOptions(1024));
|
|
var eventsOnly = purge.EstimateSiteEventsSize().EstimatedBytes;
|
|
var fileBefore = purge.GetDatabaseSizeBytes();
|
|
|
|
SeedBallast(rows: 40_000, bytesPerRow: 500);
|
|
|
|
var eventsAfterBallast = purge.EstimateSiteEventsSize().EstimatedBytes;
|
|
var fileAfter = purge.GetDatabaseSizeBytes();
|
|
|
|
_output.WriteLine($"site_events estimate {eventsOnly} -> {eventsAfterBallast}; file {fileBefore} -> {fileAfter}");
|
|
|
|
// The file grew several-fold; the event log's own measured footprint did not move at all.
|
|
Assert.True(fileAfter > fileBefore * 2,
|
|
$"Ballast must visibly grow the file ({fileBefore} -> {fileAfter}).");
|
|
Assert.Equal(eventsOnly, eventsAfterBallast);
|
|
}
|
|
|
|
[Fact]
|
|
public void PurgeByStorageCap_WithLargeBallastInTheSameFile_DoesNotTrimAnUnderCapEventLog()
|
|
{
|
|
// The most direct expression of row 81: on a replicated node with an undrained oplog the
|
|
// file dwarfs site_events. Under the old whole-file cap the trim would run — and delete
|
|
// events — purely because of bytes the event log does not own.
|
|
SeedEvents(4000);
|
|
|
|
var sizingProbe = CreatePurgeService(CapOptions(1024));
|
|
var eventBytes = sizingProbe.EstimateSiteEventsSize().EstimatedBytes;
|
|
|
|
SeedBallast(rows: 40_000, bytesPerRow: 500);
|
|
|
|
// Cap comfortably above site_events but far BELOW the whole file.
|
|
var capMb = (int)Math.Max(1, (eventBytes * 2) / (1024 * 1024));
|
|
var purge = CreatePurgeService(CapOptions(capMb));
|
|
|
|
Assert.True(purge.GetDatabaseSizeBytes() > (long)capMb * 1024 * 1024,
|
|
"Precondition: the whole file must exceed the cap, so a file-scoped cap would trim.");
|
|
|
|
purge.RunPurge();
|
|
|
|
Assert.Equal(4000, EventCount());
|
|
}
|
|
|
|
[Fact]
|
|
public void PurgeByStorageCap_WithLargeBallastInTheSameFile_StillEnforcesTheCapOnEventsAndDoesNotEmptyTheTable()
|
|
{
|
|
// The other half: the cap must still be MET. Under the old whole-file measurement this
|
|
// was impossible with unreclaimable ballast present — the trim either emptied the table
|
|
// chasing a file size it could not reach, or (as measured) tripped the progress guard
|
|
// and left the log 2.5x over cap.
|
|
SeedEvents(6000);
|
|
SeedBallast(rows: 40_000, bytesPerRow: 500);
|
|
|
|
var sizingProbe = CreatePurgeService(CapOptions(1024));
|
|
var eventBytes = sizingProbe.EstimateSiteEventsSize().EstimatedBytes;
|
|
|
|
var capBytes = eventBytes / 2;
|
|
var capMb = (int)Math.Max(1, capBytes / (1024 * 1024));
|
|
var purge = CreatePurgeService(CapOptions(capMb));
|
|
|
|
purge.RunPurge();
|
|
|
|
var remaining = EventCount();
|
|
var finalEstimate = purge.EstimateSiteEventsSize().EstimatedBytes;
|
|
var finalCapBytes = (long)capMb * 1024 * 1024;
|
|
|
|
_output.WriteLine($"remaining={remaining} estimate={finalEstimate} cap={finalCapBytes} file={purge.GetDatabaseSizeBytes()}");
|
|
|
|
Assert.True(remaining > 0, "The cap trim must not empty the event table.");
|
|
Assert.True(remaining < 6000, "The cap trim must remove events when the event log is over cap.");
|
|
Assert.True(finalEstimate <= finalCapBytes,
|
|
$"site_events estimate {finalEstimate} must be at or below the cap {finalCapBytes}.");
|
|
|
|
// And the proof that the cap is table-scoped: the FILE is still way over it, and that is
|
|
// correct — those bytes belong to LocalDb bookkeeping and the other consolidated tables.
|
|
Assert.True(purge.GetDatabaseSizeBytes() > finalCapBytes,
|
|
"The whole file is expected to stay over the cap — the cap no longer measures it.");
|
|
}
|
|
|
|
// ── size-model accuracy ──
|
|
|
|
public static TheoryData<string, int, int, double> Workloads => new()
|
|
{
|
|
// name, rows, details length (0 = no details column), details on every row
|
|
{ "narrow rows, no details", 8000, 0, 1.0 },
|
|
{ "typical rows, 200B details", 6000, 200, 1.0 },
|
|
{ "wide rows, 2KB details", 3000, 2048, 1.0 },
|
|
};
|
|
|
|
[Theory]
|
|
[MemberData(nameof(Workloads))]
|
|
public void EstimateSiteEventsSize_TracksTheRealFootprint(string name, int rows, int detailsLength, double detailsFraction)
|
|
{
|
|
// Calibration guard for the modelled estimate. site_events' true page count is obtained
|
|
// DIFFERENTIALLY: the file is measured with ballast only, the events are then added, and
|
|
// the growth is what the table and its four indexes actually cost. Seeding the ballast
|
|
// first also keeps the estimator's whole-file clamp slack, so this scores the model
|
|
// itself rather than the clamp.
|
|
//
|
|
// The band is deliberately asymmetric. The model is tuned to run somewhat high, because
|
|
// a cap that fires early wastes a slice of the budget whereas one that reads low lets
|
|
// the log overrun the disk allowance the cap exists to defend.
|
|
SeedBallast(rows: 4_000, bytesPerRow: 400);
|
|
|
|
var purge = CreatePurgeService(CapOptions(1024));
|
|
var baselineBytes = purge.GetDatabaseSizeBytes();
|
|
|
|
var details = detailsLength > 0 ? new string('d', detailsLength) : null;
|
|
_eventLogger.WithConnection(connection =>
|
|
{
|
|
using var tx = connection.BeginTransaction();
|
|
using var cmd = connection.CreateCommand();
|
|
cmd.Transaction = tx;
|
|
cmd.CommandText = """
|
|
INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details)
|
|
VALUES ($id, $ts, 'ScriptExecution', 'Information', $inst, 'SiteRuntime', $msg, $details)
|
|
""";
|
|
var id = cmd.Parameters.Add("$id", SqliteType.Text);
|
|
var ts = cmd.Parameters.Add("$ts", SqliteType.Text);
|
|
var inst = cmd.Parameters.Add("$inst", SqliteType.Text);
|
|
var msg = cmd.Parameters.Add("$msg", SqliteType.Text);
|
|
var det = cmd.Parameters.Add("$details", SqliteType.Text);
|
|
var start = new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero);
|
|
var rnd = new Random(7);
|
|
for (var i = 0; i < rows; i++)
|
|
{
|
|
id.Value = Guid.NewGuid().ToString();
|
|
ts.Value = start.AddSeconds(i).ToString("o");
|
|
inst.Value = i % 3 == 0 ? DBNull.Value : Guid.NewGuid().ToString();
|
|
msg.Value = $"Script 'Recipe{i % 50}' completed in {rnd.Next(1, 900)} ms";
|
|
det.Value = details is not null && rnd.NextDouble() < detailsFraction ? details : (object)DBNull.Value;
|
|
cmd.ExecuteNonQuery();
|
|
}
|
|
tx.Commit();
|
|
});
|
|
|
|
var estimated = purge.EstimateSiteEventsSize().EstimatedBytes;
|
|
var actual = purge.GetDatabaseSizeBytes() - baselineBytes;
|
|
var error = (estimated - (double)actual) / actual;
|
|
|
|
_output.WriteLine($"{name}: rows={rows} estimated={estimated} actual={actual} error={error:P1}");
|
|
|
|
Assert.InRange(error, -0.05, 0.25);
|
|
}
|
|
|
|
// ── wipe-prevention backstops ──
|
|
|
|
/// <summary>Purge service whose size estimate and row count can be pinned by a test.</summary>
|
|
private sealed class StubbedEstimatePurgeService(
|
|
SiteEventLogger eventLogger,
|
|
IOptions<SiteEventLogOptions> options,
|
|
ILogger<EventLogPurgeService> logger,
|
|
EventLogPurgeService.SiteEventsSizeEstimate? estimate,
|
|
long? frozenRowCount)
|
|
: EventLogPurgeService(eventLogger, options, logger)
|
|
{
|
|
internal override EventLogPurgeService.SiteEventsSizeEstimate EstimateSiteEventsSize() =>
|
|
estimate ?? base.EstimateSiteEventsSize();
|
|
|
|
internal override long GetSiteEventsRowCount() =>
|
|
frozenRowCount ?? base.GetSiteEventsRowCount();
|
|
}
|
|
|
|
[Fact]
|
|
public void PurgeByStorageCap_WhenRowWidthCannotBeSampled_DeletesNothingAndWarns()
|
|
{
|
|
// First backstop. A zero row width makes "how many rows put us under cap" unanswerable.
|
|
// The old loop's answer to an unanswerable cap was to keep deleting until the file
|
|
// shrank, which is precisely how a cap that can never be met empties a table.
|
|
SeedEvents(2000);
|
|
|
|
var logger = new CapturingLogger();
|
|
var purge = new StubbedEstimatePurgeService(
|
|
_eventLogger,
|
|
Options.Create(CapOptions(0)),
|
|
logger,
|
|
new EventLogPurgeService.SiteEventsSizeEstimate(RowCount: 2000, BytesPerRow: 0),
|
|
frozenRowCount: null);
|
|
|
|
purge.RunPurge();
|
|
|
|
Assert.Equal(2000, EventCount());
|
|
Assert.Contains(logger.Entries, e =>
|
|
e.Level == LogLevel.Warning && e.Message.Contains("row width could not be sampled", StringComparison.Ordinal));
|
|
}
|
|
|
|
[Fact]
|
|
public void PurgeByStorageCap_WhenTheTableStopsShrinking_StopsRatherThanEmptyingTheLog()
|
|
{
|
|
// Second backstop, carried over from the old "size did not decrease" guard but re-based
|
|
// onto the table-scoped metric. It can no longer be tripped by replication bookkeeping;
|
|
// a frozen row count is what it now models — writers arriving as fast as the trim deletes.
|
|
SeedEvents(5000);
|
|
|
|
var logger = new CapturingLogger();
|
|
var purge = new StubbedEstimatePurgeService(
|
|
_eventLogger,
|
|
Options.Create(CapOptions(0)), // a 0 MB cap would otherwise delete every row
|
|
logger,
|
|
estimate: null,
|
|
frozenRowCount: 5000);
|
|
|
|
purge.RunPurge();
|
|
|
|
var remaining = EventCount();
|
|
Assert.True(remaining > 0, "The guard must stop the trim before the table is emptied.");
|
|
Assert.True(remaining >= 4000, $"Only one batch should have been deleted; {5000 - remaining} rows went.");
|
|
Assert.Contains(logger.Entries, e =>
|
|
e.Level == LogLevel.Warning && e.Message.Contains("did not decrease", StringComparison.Ordinal));
|
|
}
|
|
|
|
private sealed record LogEntry(LogLevel Level, string Message);
|
|
|
|
private sealed class CapturingLogger : ILogger<EventLogPurgeService>
|
|
{
|
|
public List<LogEntry> Entries { get; } = [];
|
|
|
|
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
|
|
|
|
public bool IsEnabled(LogLevel logLevel) => true;
|
|
|
|
public void Log<TState>(
|
|
LogLevel logLevel, EventId eventId, TState state, Exception? exception,
|
|
Func<TState, Exception?, string> formatter) =>
|
|
Entries.Add(new LogEntry(logLevel, formatter(state, exception)));
|
|
}
|
|
}
|