fix(auditlog)+fix(siteeventlog): complete audit write tasks only after commit; run event-log retention on standby (arch-review 2026-08-19 P4-2 + P4-4)
P4-2: SqliteAuditWriter.FlushBatch completed each pending row's Task (TrySetResult) inside the per-row insert loop, before transaction.Commit() ran. A later failure in the same batch (another row's insert throwing, or the commit itself failing) rolled the whole transaction back, but the earlier rows' Tasks had already completed successfully -- the caller and FallbackAuditWriter (whose ring-buffer fallback exists precisely for this outage) both saw false success while the rows were actually gone from the database; the outer catch's TrySetException became a silent no-op against an already-completed TaskCompletionSource. Every row's Completion is now deferred and only resolved (TrySetResult for the whole batch, or TrySetException for the whole batch) after transaction.Commit() succeeds or the transaction rolls back, mirroring SiteEventLogger.FlushBatch. P4-4: EventLogPurgeService gated the daily site_events purge on the active-node check, early-exiting on the standby, on the stale premise that "the standby receives no writes". DataConnectionActor runs on both site nodes and writes site_events regardless of active/standby status (register rows 89/90/97), so an unreplicated standby (the rig's site-b/site-c posture) grew its site_events file forever with no retention and no cap. The gate is removed; every node now purges its own file every tick. Safe on a replicated pair because the retention/cap deletes are CDC-captured and converge under LWW regardless of which node issues them; required on an unreplicated pair because each node's file is independent. The active-node check is retained only to annotate the purge tick's log line. Tests: new SqliteAuditWriterCommitFailureTests forces a genuine non-swallowed mid-batch INSERT failure via a real SQLite trigger + custom scalar function on the writer's own connection (reflection seam), proving (a) a row whose own insert succeeded still faults when a later row in the same batch fails, and (b) FallbackAuditWriter rings every faulted row and increments the failure counter for each -- both assertions fail against the pre-fix code (proof-of-failure verified by temporarily reverting the fix). EventLogPurgeServiceTests' standby case is inverted to assert the purge now runs (not skips) on a standby node.
This commit is contained in:
@@ -77,8 +77,11 @@ Each event entry contains:
|
|||||||
## Storage
|
## Storage
|
||||||
|
|
||||||
- Events are stored in the **consolidated site LocalDb** SQLite file (`site_events` table;
|
- Events are stored in the **consolidated site LocalDb** SQLite file (`site_events` table;
|
||||||
see CLAUDE.md → Consolidated site database). Only the **active node** generates and stores
|
see CLAUDE.md → Consolidated site database). The active node generates most events (a
|
||||||
events (a standby runs no scripts, subsystems, or deployments to log).
|
standby runs no scripts, subsystems, or deployments to log), but DataConnectionActor
|
||||||
|
runs on **both** site nodes and writes its own `site_events` rows regardless of
|
||||||
|
active/standby status (register rows 89/90/97) — see *Retention* below for the
|
||||||
|
purge consequence.
|
||||||
- **`site_events` IS replicated** (`SiteLocalDbSetup.ReplicatedTables`) on a site pair with
|
- **`site_events` IS replicated** (`SiteLocalDbSetup.ReplicatedTables`) on a site pair with
|
||||||
replication configured — this reverses the component's pre-LocalDb-Phase-1 behavior, and the
|
replication configured — this reverses the component's pre-LocalDb-Phase-1 behavior, and the
|
||||||
reason is **failover history continuity, not either-node queries**: the query handler
|
reason is **failover history continuity, not either-node queries**: the query handler
|
||||||
@@ -92,7 +95,7 @@ Each event entry contains:
|
|||||||
On a site pair running **without** replication configured (by deliberate choice, e.g. the
|
On a site pair running **without** replication configured (by deliberate choice, e.g. the
|
||||||
rig's site-b/site-c), the log stays node-local and a failover does start it fresh — the
|
rig's site-b/site-c), the log stays node-local and a failover does start it fresh — the
|
||||||
documented trade of not configuring a peer, unchanged by this policy.
|
documented trade of not configuring a peer, unchanged by this policy.
|
||||||
- **Retention**: 30 days. A **daily background job** runs on the active node and deletes all events older than 30 days. Hard delete — no archival. Deletes are sliced into bounded 1000-row batches per DELETE statement rather than one unbounded statement, so a large expired backlog does not hold the write lock (and every concurrent recorder flush) for the duration of the purge.
|
- **Retention**: 30 days. A **daily background job** runs on **every** site node (arch-review 2026-08-19 P4-4 — previously active-node-only, but the standby writes its own `site_events` rows too, so an unreplicated standby's file grew unbounded under the old active-only gate) and deletes that node's own events older than 30 days. Hard delete — no archival. Deletes are sliced into bounded 1000-row batches per DELETE statement rather than one unbounded statement, so a large expired backlog does not hold the write lock (and every concurrent recorder flush) for the duration of the purge.
|
||||||
- **Storage cap**: A configurable maximum size (default: 1 GB) is enforced. If the cap is reached
|
- **Storage cap**: A configurable maximum size (default: 1 GB) is enforced. If the cap is reached
|
||||||
before the 30-day retention window, the oldest events are purged first. This prevents disk
|
before the 30-day retention window, the oldest events are purged first. This prevents disk
|
||||||
exhaustion from alarm storms, script failure loops, or connection flapping.
|
exhaustion from alarm storms, script failure loops, or connection flapping.
|
||||||
|
|||||||
@@ -484,7 +484,16 @@ public class SqliteAuditWriter : IAuditWriter, ISiteAuditQueue, IAsyncDisposable
|
|||||||
{
|
{
|
||||||
eventCmd.ExecuteNonQuery();
|
eventCmd.ExecuteNonQuery();
|
||||||
fwdCmd.ExecuteNonQuery();
|
fwdCmd.ExecuteNonQuery();
|
||||||
pending.Completion.TrySetResult();
|
// Do NOT complete pending.Completion here (arch-review 2026-08-19
|
||||||
|
// P4-2). A row's INSERTs succeeding is not durable until the
|
||||||
|
// transaction actually commits below — completing the caller's Task
|
||||||
|
// this early means a later commit failure (SQLITE_FULL, IOERR, or a
|
||||||
|
// later row in this same batch throwing) reports false success: the
|
||||||
|
// row is rolled back out of the database but the caller — and
|
||||||
|
// FallbackAuditWriter, whose ring-buffer fallback exists precisely
|
||||||
|
// for this outage — already saw it as delivered. Every row in this
|
||||||
|
// batch is completed with TrySetResult() together, AFTER
|
||||||
|
// transaction.Commit() succeeds, mirroring SiteEventLogger.FlushBatch.
|
||||||
}
|
}
|
||||||
catch (SqliteException ex) when (ex.SqliteErrorCode == SqliteErrorConstraint)
|
catch (SqliteException ex) when (ex.SqliteErrorCode == SqliteErrorConstraint)
|
||||||
{
|
{
|
||||||
@@ -492,21 +501,35 @@ public class SqliteAuditWriter : IAuditWriter, ISiteAuditQueue, IAsyncDisposable
|
|||||||
// audit_event PRIMARY KEY throws before the sidecar insert
|
// audit_event PRIMARY KEY throws before the sidecar insert
|
||||||
// runs, so neither table gains a second row. Treat as
|
// runs, so neither table gains a second row. Treat as
|
||||||
// success: the lifecycle event is durably recorded under
|
// success: the lifecycle event is durably recorded under
|
||||||
// the first writer's payload.
|
// the first writer's payload. Still deferred to after Commit()
|
||||||
|
// below — the surrounding transaction (this row's canonical/sidecar
|
||||||
|
// insert never ran, but earlier rows in the batch did) must still
|
||||||
|
// commit for that to be true.
|
||||||
_logger.LogDebug(ex,
|
_logger.LogDebug(ex,
|
||||||
"Duplicate EventId {EventId} swallowed by SqliteAuditWriter",
|
"Duplicate EventId {EventId} swallowed by SqliteAuditWriter",
|
||||||
evt.EventId);
|
evt.EventId);
|
||||||
pending.Completion.TrySetResult();
|
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
transaction.Commit();
|
transaction.Commit();
|
||||||
_flushCountForTests++;
|
_flushCountForTests++;
|
||||||
|
|
||||||
|
// Only NOW — after the whole batch is durably committed — tell every
|
||||||
|
// caller (and FallbackAuditWriter) that their row landed.
|
||||||
|
foreach (var pending in batch)
|
||||||
|
{
|
||||||
|
pending.Completion.TrySetResult();
|
||||||
|
}
|
||||||
}
|
}
|
||||||
catch (Exception ex)
|
catch (Exception ex)
|
||||||
{
|
{
|
||||||
transaction.Rollback();
|
transaction.Rollback();
|
||||||
_logger.LogError(ex, "SqliteAuditWriter batch insert failed; faulting {Count} pending events", batch.Count);
|
_logger.LogError(ex, "SqliteAuditWriter batch insert failed; faulting {Count} pending events", batch.Count);
|
||||||
|
// Fault EVERY row in the batch, including any whose own INSERTs succeeded
|
||||||
|
// above — none of that is true anymore, since the whole transaction (this
|
||||||
|
// row's insert included) just rolled back. No TrySetResult has run yet for
|
||||||
|
// any row in this batch (see above), so every TrySetException here is a
|
||||||
|
// real transition, not a no-op racing an already-completed Task.
|
||||||
foreach (var pending in batch)
|
foreach (var pending in batch)
|
||||||
{
|
{
|
||||||
pending.Completion.TrySetException(ex);
|
pending.Completion.TrySetException(ex);
|
||||||
|
|||||||
@@ -210,20 +210,23 @@ public static class SiteServiceRegistration
|
|||||||
return new AkkaClusterNodeProvider(akkaService, siteRole);
|
return new AkkaClusterNodeProvider(akkaService, siteRole);
|
||||||
});
|
});
|
||||||
|
|
||||||
// The EventLogPurgeService runs on every
|
// The EventLogPurgeService runs on every site host node and, as of arch-review
|
||||||
// site host node but consults this optional gate each tick and early-exits on
|
// 2026-08-19 P4-4, purges its own site_events file on EVERY node — the old
|
||||||
// the standby. Register it to delegate to IClusterNodeProvider.SelfIsPrimary
|
// early-exit-on-standby gate this delegate drove is gone (DataConnectionActor
|
||||||
// (the canonical "this node is the oldest Up member (singleton host)" check) so purge
|
// writes site_events on both site nodes, so a standby that never purged would grow
|
||||||
// runs ONLY on the active node — no duplicated cluster logic. Non-clustered test hosts that
|
// unbounded on an unreplicated site). Register it to delegate to
|
||||||
// never call SiteServiceRegistration leave it unregistered, so the purge defaults
|
// IClusterNodeProvider.SelfIsPrimary (the canonical "this node is the oldest Up
|
||||||
// to always-run (the pre-fix behaviour, preserved).
|
// member (singleton host)" check) purely so the purge tick's log line can say
|
||||||
|
// whether this node is active — no duplicated cluster logic, no gating. Non-clustered
|
||||||
|
// test hosts that never call SiteServiceRegistration leave it unregistered, so the
|
||||||
|
// purge just logs every tick as active.
|
||||||
services.AddSingleton<SiteEventLogActiveNodeCheck>(sp =>
|
services.AddSingleton<SiteEventLogActiveNodeCheck>(sp =>
|
||||||
{
|
{
|
||||||
var nodeProvider = sp.GetRequiredService<IClusterNodeProvider>();
|
var nodeProvider = sp.GetRequiredService<IClusterNodeProvider>();
|
||||||
return () => nodeProvider.SelfIsPrimary;
|
return () => nodeProvider.SelfIsPrimary;
|
||||||
});
|
});
|
||||||
|
|
||||||
// Wording-only companion to the gate above: when a purge on a replication-enabled node
|
// Wording-only companion to the delegate above: when a purge on a replication-enabled node
|
||||||
// actually deletes rows, it appends an operator note explaining the LocalDbOplogBacklog
|
// actually deletes rows, it appends an operator note explaining the LocalDbOplogBacklog
|
||||||
// spike that follows. site_events is a replicated table and a retention/cap DELETE is
|
// spike that follows. site_events is a replicated table and a retention/cap DELETE is
|
||||||
// CDC-captured like any other write (LocalDb Phase 2 — no purge-exemption path), so the
|
// CDC-captured like any other write (LocalDb Phase 2 — no purge-exemption path), so the
|
||||||
|
|||||||
@@ -8,17 +8,16 @@ using ZB.MOM.WW.ScadaBridge.Commons.Observability;
|
|||||||
namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging;
|
namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging;
|
||||||
|
|
||||||
/// <summary>
|
/// <summary>
|
||||||
/// Predicate the <see cref="EventLogPurgeService"/>
|
/// Predicate the <see cref="EventLogPurgeService"/> consults at the top of every purge
|
||||||
/// consults at the top of every purge tick to decide whether THIS node should
|
/// tick. As of arch-review 2026-08-19 P4-4 it no longer GATES the purge — DataConnectionActor
|
||||||
/// run the daily purge. The design states "a daily background job runs on the
|
/// writes <c>site_events</c> on both site nodes (register rows 89/90/97), so a standby that
|
||||||
/// active node and deletes all events older than 30 days"; the standby's local
|
/// skipped its own purge would grow its file unboundedly on an unreplicated site. Every node
|
||||||
/// SQLite receives no writes, so purging there is harmless but unnecessary —
|
/// now purges its own file every tick; this predicate is consulted only to annotate the tick's
|
||||||
/// and silently doing it anyway diverges from the design.
|
/// log line with whether this node is the active one.
|
||||||
///
|
///
|
||||||
/// Registration is the Host's responsibility (it knows the cluster topology);
|
/// Registration is the Host's responsibility (it knows the cluster topology);
|
||||||
/// when no implementation is registered the purge service defaults to "always
|
/// when no implementation is registered the purge service treats every tick as active for
|
||||||
/// active" so non-clustered hosts and unit tests are unaffected — backward
|
/// logging purposes — backward compatible with hosts that never register this delegate.
|
||||||
/// compatible with the prior "run on every host" behaviour.
|
|
||||||
/// </summary>
|
/// </summary>
|
||||||
/// <returns><c>true</c> if this node is the active site member and should run the purge; <c>false</c> to skip.</returns>
|
/// <returns><c>true</c> if this node is the active site member and should run the purge; <c>false</c> to skip.</returns>
|
||||||
public delegate bool SiteEventLogActiveNodeCheck();
|
public delegate bool SiteEventLogActiveNodeCheck();
|
||||||
@@ -116,11 +115,11 @@ public class EventLogPurgeService : BackgroundService
|
|||||||
/// <param name="options">Site event log options (retention days, storage cap, purge interval).</param>
|
/// <param name="options">Site event log options (retention days, storage cap, purge interval).</param>
|
||||||
/// <param name="logger">Logger instance.</param>
|
/// <param name="logger">Logger instance.</param>
|
||||||
/// <param name="isActiveNode">
|
/// <param name="isActiveNode">
|
||||||
/// Optional active-node check. When <c>null</c>, the
|
/// Optional active-node check, consulted only to annotate the purge tick's log line
|
||||||
/// service runs the purge on every tick (preserves the pre-fix behaviour
|
/// (arch-review 2026-08-19 P4-4 removed the early-exit this used to drive — every node
|
||||||
/// for non-clustered hosts and existing tests). When supplied — e.g. by
|
/// purges its own <c>site_events</c> file every tick, since DataConnectionActor writes
|
||||||
/// the Host on a site node — each tick early-exits on the standby so the
|
/// on both site nodes and a standby that skipped its own purge would grow unbounded on
|
||||||
/// daily purge runs only on the active node, matching the design.
|
/// an unreplicated site). When <c>null</c> every tick logs as active.
|
||||||
/// </param>
|
/// </param>
|
||||||
/// <param name="isReplicationConfigured">
|
/// <param name="isReplicationConfigured">
|
||||||
/// Optional LocalDb-replication check. When <c>null</c> — non-clustered hosts,
|
/// Optional LocalDb-replication check. When <c>null</c> — non-clustered hosts,
|
||||||
@@ -193,13 +192,20 @@ public class EventLogPurgeService : BackgroundService
|
|||||||
{
|
{
|
||||||
try
|
try
|
||||||
{
|
{
|
||||||
// Gate every tick on the active-node check.
|
// arch-review 2026-08-19 P4-4: purge no longer gates on the active-node check.
|
||||||
// The standby's local SQLite receives no writes, so purging there
|
// DataConnectionActor writes site_events on BOTH site nodes (register rows
|
||||||
// is harmless but unnecessary; the design (Component-SiteEventLogging
|
// 89/90/97), so the old "standby receives no writes" premise this gate was
|
||||||
// → Storage) explicitly states the purge runs on the active node.
|
// built on is stale — a standby that never purges its own file grows
|
||||||
// Defensive try/catch: a transient cluster-state read failure must
|
// site_events forever (no retention, no cap) on an UNREPLICATED site (the rig's
|
||||||
// not stop the purge loop — fall back to running the purge (the
|
// site-b/site-c posture). On a REPLICATED pair this was masked because the
|
||||||
// pre-fix behaviour was "always run", which is harmless on standby).
|
// retention/cap DELETEs are CDC-captured and converge under LWW regardless of
|
||||||
|
// which node issues them (same reasoning as the existing purge-on-replicated
|
||||||
|
// design — see the replication-backlog note below and CLAUDE.md's LocalDb
|
||||||
|
// bullet); it is REQUIRED on an unreplicated pair because each node's file is
|
||||||
|
// independent. Both nodes now run retention + cap trim against their own file
|
||||||
|
// every tick. isActive is retained only to annotate the log line below (and
|
||||||
|
// defensively defaults to true if the check itself throws) — it no longer
|
||||||
|
// skips any work.
|
||||||
bool isActive;
|
bool isActive;
|
||||||
try
|
try
|
||||||
{
|
{
|
||||||
@@ -208,15 +214,11 @@ public class EventLogPurgeService : BackgroundService
|
|||||||
catch (Exception checkEx)
|
catch (Exception checkEx)
|
||||||
{
|
{
|
||||||
_logger.LogDebug(checkEx,
|
_logger.LogDebug(checkEx,
|
||||||
"Active-node check threw during purge tick; running purge to be safe");
|
"Active-node check threw during purge tick; treating as active for logging purposes");
|
||||||
isActive = true;
|
isActive = true;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (!isActive)
|
_logger.LogDebug("Running event log purge tick (active={IsActive})", isActive);
|
||||||
{
|
|
||||||
_logger.LogDebug("Skipping event log purge tick — this node is not the active site member");
|
|
||||||
return false;
|
|
||||||
}
|
|
||||||
|
|
||||||
var budget = new PurgeBudget(_options.MaxPurgedRowsPerTick);
|
var budget = new PurgeBudget(_options.MaxPurgedRowsPerTick);
|
||||||
PurgeByRetention(budget);
|
PurgeByRetention(budget);
|
||||||
|
|||||||
@@ -23,13 +23,14 @@ public static class ServiceCollectionExtensions
|
|||||||
services.AddSingleton<ISiteEventLogger>(sp => sp.GetRequiredService<SiteEventLogger>());
|
services.AddSingleton<ISiteEventLogger>(sp => sp.GetRequiredService<SiteEventLogger>());
|
||||||
services.AddSingleton<IEventLogQueryService, EventLogQueryService>();
|
services.AddSingleton<IEventLogQueryService, EventLogQueryService>();
|
||||||
|
|
||||||
// The purge service still registers on every host
|
// The purge service registers on every host node and purges its own
|
||||||
// node, but it consults an optional SiteEventLogActiveNodeCheck on each
|
// site_events file on every tick, on every node (arch-review 2026-08-19 P4-4 —
|
||||||
// tick and early-exits on the standby. The Host registers the real
|
// the standby writes site_events too, so it can no longer skip its own purge).
|
||||||
// active-node check on site nodes; tests and non-clustered hosts leave
|
// It still consults an optional SiteEventLogActiveNodeCheck, but only to annotate
|
||||||
// it unregistered, and the purge defaults to "always run" (the
|
// the tick's log line, not to gate it. The Host registers the real active-node
|
||||||
// pre-fix behaviour). Building the service via a factory so the
|
// check on site nodes; tests and non-clustered hosts leave it unregistered, and
|
||||||
// optional delegate flows from DI rather than the constructor default.
|
// the log line just reports every tick as active. Building the service via a
|
||||||
|
// factory so the optional delegate flows from DI rather than the constructor default.
|
||||||
//
|
//
|
||||||
// SiteEventLogReplicationCheck flows the same way and is likewise Host-supplied:
|
// SiteEventLogReplicationCheck flows the same way and is likewise Host-supplied:
|
||||||
// it only selects the wording of the purge log line (whether to add the
|
// it only selects the wording of the purge log line (whether to add the
|
||||||
|
|||||||
+190
@@ -0,0 +1,190 @@
|
|||||||
|
using System.Reflection;
|
||||||
|
using Microsoft.Data.Sqlite;
|
||||||
|
using Microsoft.Extensions.Logging.Abstractions;
|
||||||
|
using Microsoft.Extensions.Options;
|
||||||
|
using NSubstitute;
|
||||||
|
using ZB.MOM.WW.Audit;
|
||||||
|
using ZB.MOM.WW.ScadaBridge.AuditLog.Site;
|
||||||
|
using ZB.MOM.WW.ScadaBridge.AuditLog.Tests.TestSupport;
|
||||||
|
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
|
||||||
|
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
|
||||||
|
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
|
||||||
|
using IAuditWriter = ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services.IAuditWriter;
|
||||||
|
|
||||||
|
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Tests.Site;
|
||||||
|
|
||||||
|
/// <summary>
|
||||||
|
/// arch-review 2026-08-19 P4-2 regression coverage. <see cref="SqliteAuditWriter.FlushBatch"/>
|
||||||
|
/// used to call <c>pending.Completion.TrySetResult()</c> per row BEFORE
|
||||||
|
/// <c>transaction.Commit()</c> ran. A later failure in the SAME batch — another row's insert
|
||||||
|
/// throwing, or the commit itself failing (SQLITE_FULL, IOERR) — rolled the whole transaction
|
||||||
|
/// back, but the earlier row's <see cref="System.Threading.Tasks.Task"/> had already completed
|
||||||
|
/// successfully: the caller, and <see cref="FallbackAuditWriter"/> (whose ring-buffer fallback
|
||||||
|
/// exists precisely for this outage), both saw false success while the row was actually gone
|
||||||
|
/// from the database — <c>TrySetException</c> in the outer catch is a no-op against an
|
||||||
|
/// already-completed <see cref="System.Threading.Tasks.TaskCompletionSource"/>.
|
||||||
|
/// </summary>
|
||||||
|
/// <remarks>
|
||||||
|
/// A committed transaction can't practically be made to fail via public SQLite surface without
|
||||||
|
/// exhausting disk or injecting a custom VFS, so these tests force a genuine, non-swallowed
|
||||||
|
/// mid-batch INSERT failure instead (the "bonus defect" the finding also calls out: a mid-batch
|
||||||
|
/// insert failure on a later row loses the rows that inserted fine before it, the same way).
|
||||||
|
/// That failure is reached through a real SQLite trigger + a custom scalar function registered
|
||||||
|
/// directly on the writer's own connection (via reflection — <see cref="SqliteAuditWriter"/>
|
||||||
|
/// deliberately doesn't expose it), so the whole path under test — transaction, per-row
|
||||||
|
/// try/catch, rollback, TrySetException — is the writer's real production code, not a mock.
|
||||||
|
/// </remarks>
|
||||||
|
public class SqliteAuditWriterCommitFailureTests
|
||||||
|
{
|
||||||
|
private const string FailMarker = "P4-2-FORCED-FAILURE";
|
||||||
|
|
||||||
|
private static AuditEvent NewEvent(string target) => ScadaBridgeAuditEventFactory.Create(
|
||||||
|
channel: AuditChannel.ApiOutbound,
|
||||||
|
kind: AuditKind.ApiCall,
|
||||||
|
status: AuditStatus.Delivered,
|
||||||
|
eventId: Guid.NewGuid(),
|
||||||
|
occurredAtUtc: DateTime.UtcNow,
|
||||||
|
target: target);
|
||||||
|
|
||||||
|
/// <summary>
|
||||||
|
/// Installs a BEFORE INSERT trigger on <c>audit_event</c> that calls a custom scalar
|
||||||
|
/// function throwing whenever the inserted row's <c>Target</c> is <see cref="FailMarker"/>.
|
||||||
|
/// An exception thrown from a Microsoft.Data.Sqlite custom function surfaces as a generic
|
||||||
|
/// SQLITE_ERROR (code 1), NOT SQLITE_CONSTRAINT (code 19) — so it is NOT caught by
|
||||||
|
/// FlushBatch's duplicate-EventId swallow (which matches only code 19) and instead reaches
|
||||||
|
/// the outer catch exactly like a real disk-outage commit failure would.
|
||||||
|
/// </summary>
|
||||||
|
private static void InstallFailureTrigger(SqliteAuditWriter writer)
|
||||||
|
{
|
||||||
|
var connectionField = typeof(SqliteAuditWriter).GetField(
|
||||||
|
"_connection", BindingFlags.NonPublic | BindingFlags.Instance)
|
||||||
|
?? throw new InvalidOperationException("SqliteAuditWriter._connection not found — test seam broke.");
|
||||||
|
var connection = (SqliteConnection)connectionField.GetValue(writer)!;
|
||||||
|
|
||||||
|
connection.CreateFunction<string, long>("throw_if_marker", target =>
|
||||||
|
{
|
||||||
|
if (target == FailMarker)
|
||||||
|
{
|
||||||
|
throw new InvalidOperationException("P4-2 test-forced insert failure");
|
||||||
|
}
|
||||||
|
return 0;
|
||||||
|
});
|
||||||
|
|
||||||
|
using var cmd = connection.CreateCommand();
|
||||||
|
cmd.CommandText = $"""
|
||||||
|
CREATE TRIGGER test_fail_marker
|
||||||
|
BEFORE INSERT ON audit_event
|
||||||
|
FOR EACH ROW WHEN NEW.Target = '{FailMarker}'
|
||||||
|
BEGIN
|
||||||
|
SELECT throw_if_marker(NEW.Target);
|
||||||
|
END;
|
||||||
|
""";
|
||||||
|
cmd.ExecuteNonQuery();
|
||||||
|
}
|
||||||
|
|
||||||
|
private static (SqliteAuditWriter writer, string dataSource) CreateWriter(string testName)
|
||||||
|
{
|
||||||
|
var dataSource = $"file:{testName}-{Guid.NewGuid():N}?mode=memory&cache=shared";
|
||||||
|
var opts = new SqliteAuditWriterOptions
|
||||||
|
{
|
||||||
|
DatabasePath = dataSource,
|
||||||
|
// Generous flush window: both writes below are enqueued back-to-back with no
|
||||||
|
// await between them, so they are already both in the channel long before the
|
||||||
|
// background loop's first drain attempt — this just gives extra margin so the
|
||||||
|
// test can't flake into two separate flushes on a slow CI box.
|
||||||
|
FlushIntervalMs = 1000,
|
||||||
|
};
|
||||||
|
var writer = new SqliteAuditWriter(
|
||||||
|
Options.Create(opts),
|
||||||
|
NullLogger<SqliteAuditWriter>.Instance,
|
||||||
|
new FakeNodeIdentityProvider(),
|
||||||
|
connectionStringOverride: $"Data Source={dataSource};Cache=Shared");
|
||||||
|
return (writer, dataSource);
|
||||||
|
}
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public async Task FlushBatch_MidBatchInsertFailure_FaultsEveryRowInBatch_NotJustTheFailingRow()
|
||||||
|
{
|
||||||
|
var (writer, dataSource) = CreateWriter(
|
||||||
|
nameof(FlushBatch_MidBatchInsertFailure_FaultsEveryRowInBatch_NotJustTheFailingRow));
|
||||||
|
await using var _ = writer;
|
||||||
|
|
||||||
|
InstallFailureTrigger(writer);
|
||||||
|
|
||||||
|
// evt1 is an ordinary row — its own two INSERTs succeed. evt2 carries the marker and
|
||||||
|
// throws mid-batch, from WITHIN the same transaction as evt1's already-successful
|
||||||
|
// inserts. Fired without individually awaiting so both land in the channel before the
|
||||||
|
// background loop's first drain — i.e. the same FlushBatch transaction.
|
||||||
|
var evt1 = NewEvent("normal-row");
|
||||||
|
var evt2 = NewEvent(FailMarker);
|
||||||
|
|
||||||
|
var t1 = writer.WriteAsync(evt1);
|
||||||
|
var t2 = writer.WriteAsync(evt2);
|
||||||
|
|
||||||
|
try
|
||||||
|
{
|
||||||
|
await Task.WhenAll(t1, t2).WaitAsync(TimeSpan.FromSeconds(10));
|
||||||
|
}
|
||||||
|
catch
|
||||||
|
{
|
||||||
|
// Expected: both tasks fault. Individually asserted below so a failure here
|
||||||
|
// reports which one didn't behave as expected, not just "something threw".
|
||||||
|
}
|
||||||
|
|
||||||
|
// THE regression assertion: evt1's own inserts succeeded, but the batch it shared
|
||||||
|
// with evt2 rolled back — its Task must fault, not silently report success. Pre-fix,
|
||||||
|
// t1 would already be RanToCompletion at this point (TrySetResult ran inside the loop
|
||||||
|
// before evt2's insert threw), and the later TrySetException in the outer catch would
|
||||||
|
// be a silent no-op against the already-completed TaskCompletionSource.
|
||||||
|
Assert.True(t1.IsFaulted,
|
||||||
|
"evt1's row was rolled back along with the rest of the batch, so its Task must fault instead of reporting false success.");
|
||||||
|
Assert.True(t2.IsFaulted, "evt2's own insert threw directly and must fault its Task.");
|
||||||
|
|
||||||
|
// No commit ever happened for this batch.
|
||||||
|
Assert.Equal(0, writer.FlushCountForTests);
|
||||||
|
|
||||||
|
// And the database genuinely holds neither row — proves the rollback actually
|
||||||
|
// happened, not just that the Task-completion contract changed.
|
||||||
|
using var verify = new SqliteConnection($"Data Source={dataSource};Cache=Shared");
|
||||||
|
verify.Open();
|
||||||
|
using var countCmd = verify.CreateCommand();
|
||||||
|
countCmd.CommandText = "SELECT COUNT(*) FROM audit_event;";
|
||||||
|
Assert.Equal(0L, (long)countCmd.ExecuteScalar()!);
|
||||||
|
}
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public async Task FallbackAuditWriter_MidBatchInsertFailure_RingsEveryFaultedRow_AndIncrementsFailureCounterForEach()
|
||||||
|
{
|
||||||
|
// End-to-end proof the fix actually closes the loop the finding describes:
|
||||||
|
// FallbackAuditWriter composes the REAL SqliteAuditWriter as its primary. Before the
|
||||||
|
// fix, evt1's primary write would appear to SUCCEED (its Task completed before the
|
||||||
|
// rollback), so FallbackAuditWriter would never route it to the ring or count it as a
|
||||||
|
// failure — the whole batch would be silently lost with SiteAuditWriteFailures staying
|
||||||
|
// at 0, exactly as the finding describes.
|
||||||
|
var (writer, _) = CreateWriter(
|
||||||
|
nameof(FallbackAuditWriter_MidBatchInsertFailure_RingsEveryFaultedRow_AndIncrementsFailureCounterForEach));
|
||||||
|
await using var _w = writer;
|
||||||
|
|
||||||
|
InstallFailureTrigger(writer);
|
||||||
|
|
||||||
|
var ring = new RingBufferFallback(capacity: 16);
|
||||||
|
var counter = Substitute.For<IAuditWriteFailureCounter>();
|
||||||
|
var fallback = new FallbackAuditWriter(
|
||||||
|
writer, ring, counter, NullLogger<FallbackAuditWriter>.Instance);
|
||||||
|
|
||||||
|
var evt1 = NewEvent("normal-row");
|
||||||
|
var evt2 = NewEvent(FailMarker);
|
||||||
|
|
||||||
|
// FallbackAuditWriter.WriteAsync never throws (audit failures are always swallowed at
|
||||||
|
// that layer) — fired concurrently, same reasoning as above, so both land in one
|
||||||
|
// FlushBatch transaction.
|
||||||
|
var t1 = fallback.WriteAsync(evt1);
|
||||||
|
var t2 = fallback.WriteAsync(evt2);
|
||||||
|
await Task.WhenAll(t1, t2).WaitAsync(TimeSpan.FromSeconds(10));
|
||||||
|
|
||||||
|
// Both rows — including the one whose own INSERT succeeded before the batch rolled
|
||||||
|
// back — must have been routed to the ring and counted as a primary failure.
|
||||||
|
Assert.Equal(2, ring.Count);
|
||||||
|
counter.Received(2).Increment();
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -475,8 +475,10 @@ public class SiteCompositionRootTests : IDisposable
|
|||||||
new object[] { typeof(IEventLogQueryService) },
|
new object[] { typeof(IEventLogQueryService) },
|
||||||
new object[] { typeof(ISiteIdentityProvider) },
|
new object[] { typeof(ISiteIdentityProvider) },
|
||||||
new object[] { typeof(IHealthReportTransport) },
|
new object[] { typeof(IHealthReportTransport) },
|
||||||
// M2.15 (#29): the active-node purge gate must be registered on site nodes
|
// M2.15 (#29): the active-node check must be registered on site nodes so
|
||||||
// so EventLogPurge only runs on the active node.
|
// EventLogPurge's log line can report whether this node is active (arch-review
|
||||||
|
// 2026-08-19 P4-4: it no longer gates which node purges — every node purges its
|
||||||
|
// own site_events file).
|
||||||
new object[] { typeof(SiteEventLogActiveNodeCheck) },
|
new object[] { typeof(SiteEventLogActiveNodeCheck) },
|
||||||
};
|
};
|
||||||
|
|
||||||
|
|||||||
@@ -410,32 +410,32 @@ public class EventLogPurgeServiceTests : IDisposable
|
|||||||
Assert.Empty(exceptions);
|
Assert.Empty(exceptions);
|
||||||
}
|
}
|
||||||
|
|
||||||
// ── SiteEventLogging-019: purge runs only on the active node ──
|
// ── arch-review 2026-08-19 P4-4: purge runs on every node, not just the active one ──
|
||||||
|
// (supersedes the old SiteEventLogging-019 "active-node-only gate" — DataConnectionActor
|
||||||
|
// writes site_events on both site nodes, so a standby that skipped its own purge would
|
||||||
|
// grow its file unbounded on an unreplicated site.)
|
||||||
|
|
||||||
[Fact]
|
[Fact]
|
||||||
public void RunPurge_OnStandbyNode_SkipsAllWork()
|
public void RunPurge_OnStandbyNode_StillRunsThePurge()
|
||||||
{
|
{
|
||||||
// SiteEventLogging-019: per design, the daily purge runs on the active
|
// P4-4 regression: before the fix, a standby (isActiveNode returning false) early-exited
|
||||||
// node only. The standby's local SQLite receives no writes, so purging
|
// the purge tick entirely, leaving this well-past-retention row in place forever on an
|
||||||
// there is unnecessary; we gate the purge tick on the injected
|
// unreplicated standby. The gate is gone — the standby purges its own file exactly like
|
||||||
// active-node check and early-exit when it returns false. The row
|
// the active node.
|
||||||
// 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));
|
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||||
Assert.Equal(1, GetEventCount());
|
Assert.Equal(1, GetEventCount());
|
||||||
|
|
||||||
var purge = CreatePurgeService(isActiveNode: () => false);
|
var purge = CreatePurgeService(isActiveNode: () => false);
|
||||||
purge.RunPurge();
|
purge.RunPurge();
|
||||||
|
|
||||||
Assert.Equal(1, GetEventCount());
|
Assert.Equal(0, GetEventCount());
|
||||||
}
|
}
|
||||||
|
|
||||||
[Fact]
|
[Fact]
|
||||||
public void RunPurge_OnActiveNode_RunsTheRetentionPurge()
|
public void RunPurge_OnActiveNode_RunsTheRetentionPurge()
|
||||||
{
|
{
|
||||||
// SiteEventLogging-019: when the active-node check returns true the
|
// Pinned alongside the standby case above so a future regression that reintroduces
|
||||||
// service runs the purge as before. Pinned alongside the standby case
|
// asymmetric active/standby purge behaviour is caught from either side.
|
||||||
// so a future regression that inverts the gate is caught.
|
|
||||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
|
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
|
||||||
|
|
||||||
@@ -446,12 +446,11 @@ public class EventLogPurgeServiceTests : IDisposable
|
|||||||
}
|
}
|
||||||
|
|
||||||
[Fact]
|
[Fact]
|
||||||
public void RunPurge_WithNullCheck_FallsBackToRunning()
|
public void RunPurge_WithNullCheck_StillRuns()
|
||||||
{
|
{
|
||||||
// SiteEventLogging-019: when no active-node check is supplied (the
|
// When no active-node check is supplied (the default for non-clustered hosts and
|
||||||
// default for non-clustered hosts and pre-existing tests), the service
|
// pre-existing tests), the service runs the purge — unaffected by P4-4 since the
|
||||||
// preserves the pre-fix "run on every tick" behaviour rather than
|
// check was never gating anything for this caller either.
|
||||||
// silently skipping every tick. Backward compatibility guard.
|
|
||||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||||
|
|
||||||
var purge = CreatePurgeService(isActiveNode: null);
|
var purge = CreatePurgeService(isActiveNode: null);
|
||||||
|
|||||||
Reference in New Issue
Block a user