fix(siteeventlog)+fix(host): purge startup yield + auto_vacuum reality (arch-review 2026-08-19 P4-5 + P4-6)

P4-5: EventLogPurgeService.ExecuteAsync now yields (Task.Yield()) before running the initial RunPurge(), making "the purge never runs synchronously on the caller's thread" a property of the method itself rather than an artifact of .NET 8+'s BackgroundService scheduling (verified empirically not to reproduce the literal "StartAsync blocks" symptom on this repo's net10.0 target — a 1.5s synchronous Thread.Sleep in ExecuteAsync still lets StartAsync return in ~2ms). Proven instead via a reflection-invoked ExecuteAsync test that bypasses BackgroundService's Task.Run wrapper, which is timing-independent. Also: a throwing isActive predicate now fails CLOSED (logged as inactive, at Warning) instead of silently claiming "active" — the predicate only affects the tick's log line since P4-4, but a throw must not masquerade as a successful check. P4-6: PRAGMA auto_vacuum = INCREMENTAL only takes effect on a table-less database, and LocalDbSchema.EnsureCreated (inside SqliteLocalDb's constructor) always creates LocalDb's own bookkeeping tables before SiteEventLogSchema.Apply ever gets a connection — so the pragma there had never once taken effect, in any real call path. Real fix per plan decision 2: SiteLocalDbSetup.EnsureAutoVacuumOnFreshFile pre-creates a genuinely fresh LocalDb file with the pragma set, called from SiteServiceRegistration.Configure BEFORE AddZbLocalDb's lazy singleton ever constructs SqliteLocalDb — no LocalDb API change needed. Only helps NEW site databases; an existing file (every node on the docker rig today) is left untouched rather than VACUUM'd, per the plan's explicit rejection of an unconditional VACUUM against a live ~1 GB file. The now-dead pragma call in SiteEventLogSchema.Apply is removed and its comment corrected. Tests proven to fail against the unfixed code (git-diff-and-restore, not stash — this repo shares one stash ref across all worktrees): ExecuteAsync_YieldsBeforeRunningTheInitial- PurgeSynchronously and RunPurge_ActiveNodeCheckThrows_TickLogsAsInactive_NotActive fail without the EventLogPurgeService fix; SiteLocalDbAutoVacuumTests fails to compile without EnsureAutoVacuumOnFreshFile. SiteEventLogging.Tests 112/112 and Host.Tests 526/526 green with the fix applied.
2026-08-19 16:31:57 -04:00
parent 99da32d635
commit 11675285af
6 changed files with 387 additions and 15 deletions
@@ -1,3 +1,4 @@
+using System.Reflection;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
@@ -355,6 +356,92 @@ public class EventLogPurgeServiceTests : IDisposable
        await purge.StopAsync(CancellationToken.None);
    }

+    [Fact]
+    public async Task ExecuteAsync_YieldsBeforeRunningTheInitialPurgeSynchronously()
+    {
+        // arch-review 2026-08-19 P4-5 — timing-independent companion to
+        // StartAsync_DoesNotBlock_OnTheInitialPurge above.
+        //
+        // That test times BackgroundService.StartAsync as a whole and passes even on the
+        // UNFIXED code, because .NET 8+ already invokes ExecuteAsync via Task.Run — the
+        // synchronous prelude runs on a pool thread, not the caller's, so StartAsync itself
+        // never blocks regardless of whether ExecuteAsync yields first. Verified empirically
+        // against this repo's actual net10.0 target (a BackgroundService whose ExecuteAsync
+        // does Thread.Sleep(1500) before its first await still returns from StartAsync in
+        // ~2 ms). So P4-5's literal "StartAsync blocks" symptom does not reproduce here, and
+        // a wall-clock test cannot prove the fix.
+        //
+        // What CAN be proven without any timing is the ExecuteAsync-level contract itself:
+        // invoking the protected ExecuteAsync directly via reflection — bypassing
+        // BackgroundService's Task.Run wrapper entirely — still runs it synchronously, on
+        // the calling thread, up through its first genuinely-suspending await (that is what
+        // "async Task method" means; MethodInfo.Invoke does not change it). On the unfixed
+        // code ExecuteAsync's first statement is RunPurge() with no await before it, so
+        // Invoke would not return until the initial purge had fully run — deleting the
+        // expired row before this method's Assert ever executes. With Task.Yield() as the
+        // very first statement, Invoke returns as soon as MoveNext() hits the (always
+        // IsCompleted == false) yield point, before RunPurge has been called at all.
+        InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
+        Assert.Equal(1, GetEventCount());
+
+        var purge = CreatePurgeService();
+        var executeAsync = typeof(EventLogPurgeService).GetMethod(
+            "ExecuteAsync", BindingFlags.NonPublic | BindingFlags.Instance);
+        Assert.NotNull(executeAsync);
+
+        using var cts = new CancellationTokenSource();
+        var task = (Task)executeAsync!.Invoke(purge, [cts.Token])!;
+
+        // Reflection Invoke has already returned control here — a synchronous
+        // RunPurge() ahead of any await would have already deleted the row by now.
+        Assert.Equal(1, GetEventCount());
+
+        // The initial purge still runs, just after control has been yielded back.
+        var deadline = DateTime.UtcNow.AddSeconds(5);
+        while (GetEventCount() != 0 && DateTime.UtcNow < deadline)
+        {
+            await Task.Delay(25);
+        }
+        Assert.Equal(0, GetEventCount());
+
+        await cts.CancelAsync();
+        try
+        {
+            await task;
+        }
+        catch (OperationCanceledException)
+        {
+            // Expected: the loop's Task.Delay observes the cancellation.
+        }
+    }
+
+    [Fact]
+    public void RunPurge_ActiveNodeCheckThrows_TickLogsAsInactive_NotActive()
+    {
+        // arch-review 2026-08-19 P4-5: a throwing isActive predicate must fail CLOSED
+        // (logged as inactive) rather than silently claiming "active". The predicate no
+        // longer gates any purge work (P4-4 — every node purges its own file every tick
+        // regardless), so a wrong value here cannot skip work; but an operator correlating
+        // this line against the real active-node state must not be misled into thinking the
+        // check actually succeeded and reported active.
+        var logger = new CapturingLogger();
+        var purge = CreatePurgeService(
+            isActiveNode: () => throw new InvalidOperationException("boom"),
+            logger: logger);
+
+        purge.RunPurge();
+
+        var warnLine = Assert.Single(
+            logger.Entries,
+            e => e.Message.Contains("Active-node check threw", StringComparison.Ordinal));
+        Assert.Equal(LogLevel.Warning, warnLine.Level);
+
+        var tickLine = Assert.Single(
+            logger.Entries,
+            e => e.Message.Contains("Running event log purge tick", StringComparison.Ordinal));
+        Assert.Contains("active=False", tickLine.Message, StringComparison.Ordinal);
+    }
+
    [Fact]
    public async Task PurgeByStorageCap_ConcurrentWritesDoNotCorruptConnection()
    {