merge(agent-b): rows 81+84 — storage cap now measures site_events' own footprint (sampled page-layout model; dbstat probed unavailable and pinned); backlog note once per tick

2026-08-17 03:59:21 -04:00
parent 817a72108e ddb3c32e06
commit 5162408a9f
10 changed files with 1171 additions and 46 deletions
@@ -547,6 +547,47 @@ public class EventLogPurgeServiceTests : IDisposable
        Assert.Equal(LogLevel.Information, note.Level);
    }

+    [Fact]
+    public void RunPurge_WhenBothPhasesDeleteRows_LogsTheBacklogNoteOnceForTheWholeTick()
+    {
+        // Register row 84. The note used to be emitted by each phase, so a tick in which the
+        // retention purge AND the cap trim both deleted rows produced two identical Information
+        // lines. It is now emitted once, from the tick's shared delete budget — which also makes
+        // the number it reports the figure an operator actually wants next to an oplog spike:
+        // the whole tick's contribution, not one phase's.
+        const int expiredRows = 50;
+        const int recentRows = 50;
+        for (int i = 0; i < expiredRows; i++)
+        {
+            InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
+        }
+        for (int i = 0; i < recentRows; i++)
+        {
+            InsertEventWithTimestamp(DateTimeOffset.UtcNow);
+        }
+
+        var capOptions = new SiteEventLogOptions
+        {
+            DatabasePath = _dbPath,
+            RetentionDays = 30,
+            MaxStorageMb = 0  // retention takes the expired rows; the cap trim takes the rest
+        };
+
+        var logger = new CapturingLogger();
+        var purge = CreatePurgeService(capOptions, isReplicationConfigured: () => true, logger: logger);
+        purge.RunPurge();
+
+        // Both phases really did delete — otherwise this would pass for the wrong reason.
+        Assert.Contains(logger.Entries, e =>
+            e.Message.Contains($"Purged {expiredRows} events older than", StringComparison.Ordinal));
+        Assert.Contains(logger.Entries, e => e.Message.Contains("over the 0 MB cap", StringComparison.Ordinal));
+        Assert.Equal(0, GetEventCount());
+
+        var note = Assert.Single(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
+        Assert.Equal(LogLevel.Information, note.Level);
+        Assert.Contains($"Purged {expiredRows + recentRows} site_events rows", note.Message, StringComparison.Ordinal);
+    }
+
    [Fact]
    public void RunPurge_WhenReplicationCheckThrows_StillPurgesAndSwallows()
    {
@@ -0,0 +1,365 @@
+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)));
+    }
+}
@@ -0,0 +1,84 @@
+using Microsoft.Data.Sqlite;
+
+namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests;
+
+/// <summary>
+/// Pins the two SQLite provider capabilities the storage cap's size model depends on
+/// (register row 81, <c>docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md</c>).
+/// </summary>
+/// <remarks>
+/// The intended fix for row 81 was to measure <c>site_events</c>' own pages exactly through the
+/// <c>dbstat</c> virtual table. These tests are the evidence that this is not possible with the
+/// native SQLite this solution ships, and the tripwire that will tell us if that ever changes —
+/// if <c>dbstat</c> appears, the modelled estimate in
+/// <see cref="EventLogPurgeService.EstimateSiteEventsSize"/> should be replaced by a real
+/// measurement.
+/// </remarks>
+public class SqliteCapabilityTests
+{
+    private static SqliteConnection OpenMemory()
+    {
+        var connection = new SqliteConnection("Data Source=:memory:");
+        connection.Open();
+        return connection;
+    }
+
+    [Fact]
+    public void DbStat_IsNotAvailable_SoThePerTablePageCountMustBeModelled()
+    {
+        // If this test starts FAILING, that is good news, not a regression: the bundled
+        // e_sqlite3 has gained SQLITE_ENABLE_DBSTAT_VTAB and the cap can measure
+        // `SELECT sum(pgsize) FROM dbstat WHERE name='site_events'` exactly instead of
+        // modelling it. Delete the model, not this expectation, if that day comes.
+        using var connection = OpenMemory();
+
+        using var compileOptions = connection.CreateCommand();
+        compileOptions.CommandText = "PRAGMA compile_options";
+        var options = new List<string>();
+        using (var reader = compileOptions.ExecuteReader())
+        {
+            while (reader.Read())
+                options.Add(reader.GetString(0));
+        }
+
+        Assert.DoesNotContain("ENABLE_DBSTAT_VTAB", options);
+
+        using var modules = connection.CreateCommand();
+        modules.CommandText = "SELECT name FROM pragma_module_list";
+        var names = new List<string>();
+        using (var reader = modules.ExecuteReader())
+        {
+            while (reader.Read())
+                names.Add(reader.GetString(0));
+        }
+
+        // The list is non-empty (fts3/4/5, rtree, geopoly …) so an empty result is not being
+        // mistaken for "no dbstat".
+        Assert.NotEmpty(names);
+        Assert.DoesNotContain("dbstat", names);
+        Assert.DoesNotContain("sqlite_dbpage", names);
+
+        using var query = connection.CreateCommand();
+        query.CommandText = "SELECT sum(pgsize) FROM dbstat";
+        var ex = Assert.Throws<SqliteException>(() => query.ExecuteScalar());
+        Assert.Contains("dbstat", ex.Message, StringComparison.OrdinalIgnoreCase);
+    }
+
+    [Fact]
+    public void OctetLength_IsAvailable_SoRowWidthIsSampledInBytesNotCharacters()
+    {
+        // The size model samples row width with octet_length() (SQLite 3.43+). length() counts
+        // CHARACTERS, so a multi-byte UTF-8 message would be under-sized and the cap enforced
+        // late. A provider downgrade that drops octet_length must fail here rather than
+        // silently shrinking every estimate at runtime.
+        using var connection = OpenMemory();
+
+        using var cmd = connection.CreateCommand();
+        cmd.CommandText = "SELECT octet_length('skål'), length('skål')";
+        using var reader = cmd.ExecuteReader();
+
+        Assert.True(reader.Read());
+        Assert.Equal(5, reader.GetInt32(0));  // 'å' is two bytes in UTF-8
+        Assert.Equal(4, reader.GetInt32(1));
+    }
+}