docs+log(siteeventlogging): explain the site_events purge oplog-backlog burst (R7)
The daily site_events retention purge (and the storage-cap trim) is CDC-captured on a replication-enabled site node exactly like any other write — correct by design, since LocalDb Phase 2 deliberately has no purge-exemption path — so the backlog jumps by the deleted batch size at purge time. LocalDbOplogBacklog / localdb_oplog_depth spike, drain, and an operator watching the gauge with no context reads it as a replication fault. Documentation + one log line, no behaviour change: - topology-guide.md gains "Reading the replication backlog — the daily site_events purge burst": when it fires (PurgeInterval 24h, anchored to the active node's PROCESS START, not a wall-clock hour, so it moves after every failover), where it shows (replicated nodes only — not rig site-b/site-c), the healthy signature (LocalDbReplicationConnected stays true, backlog returns to ~0) and what a genuine fault looks like instead. - Component-SiteEventLogging.md Storage records the same under retention/purge; Component-HealthMonitoring.md gains the two previously-undocumented LocalDbReplicationConnected / LocalDbOplogBacklog metric rows carrying the caveat, with cross-references both ways. - EventLogPurgeService emits one Information line naming the row count and the expected transient backlog when a purge deleted rows on a replication-enabled node, so the spike is correlatable in the log. Replication-awareness comes in as a Host-supplied SiteEventLogReplicationCheck delegate, mirroring the existing SiteEventLogActiveNodeCheck seam: SiteLocalDbSetup.ReplicationIsConfigured goes internal so the PeerAddress-OR-ApiKey rule stays in one place and SiteEventLogging never learns to read LocalDb config. Unregistered ⇒ no note, matching the default that replication is opt-in and off. Both delete paths carry the note (a cap trim is usually the larger burst); the predicate is try/caught since a log-wording check must never break the purge. Tests: 5 new EventLogPurgeServiceTests cases (replicated logs it, unreplicated does not, zero-rows does not, cap purge logs it, throwing predicate still purges and swallows) via a local capturing ILogger. SiteEventLogging 81/81 green, Host 490/490 green, full solution build clean (0 warnings).
This commit is contained in:
@@ -1,3 +1,4 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Microsoft.Extensions.Options;
|
||||
|
||||
@@ -45,14 +46,17 @@ public class EventLogPurgeServiceTests : IDisposable
|
||||
|
||||
private EventLogPurgeService CreatePurgeService(
|
||||
SiteEventLogOptions? optionsOverride = null,
|
||||
SiteEventLogActiveNodeCheck? isActiveNode = null)
|
||||
SiteEventLogActiveNodeCheck? isActiveNode = null,
|
||||
SiteEventLogReplicationCheck? isReplicationConfigured = null,
|
||||
ILogger<EventLogPurgeService>? logger = null)
|
||||
{
|
||||
var opts = optionsOverride ?? _options;
|
||||
return new EventLogPurgeService(
|
||||
_eventLogger,
|
||||
Options.Create(opts),
|
||||
NullLogger<EventLogPurgeService>.Instance,
|
||||
isActiveNode);
|
||||
logger ?? NullLogger<EventLogPurgeService>.Instance,
|
||||
isActiveNode,
|
||||
isReplicationConfigured);
|
||||
}
|
||||
|
||||
private void InsertEventWithTimestamp(DateTimeOffset timestamp)
|
||||
@@ -455,4 +459,135 @@ public class EventLogPurgeServiceTests : IDisposable
|
||||
|
||||
Assert.Equal(0, GetEventCount());
|
||||
}
|
||||
|
||||
// ── R7: replication-backlog operator note on the purge log line ──
|
||||
|
||||
/// <summary>
|
||||
/// Fragment unique to the R7 note, matched against the rendered log message.
|
||||
/// Deliberately not the whole sentence — the wording is operator prose and may be
|
||||
/// reworded; what must not regress is that the note fires (or does not) per the
|
||||
/// replication predicate.
|
||||
/// </summary>
|
||||
private const string BacklogNoteFragment = "transient LocalDb oplog backlog";
|
||||
|
||||
[Fact]
|
||||
public void PurgeByRetention_OnReplicatedNode_LogsTheOplogBacklogNote()
|
||||
{
|
||||
// R7: site_events is a replicated table and the retention DELETE is CDC-captured
|
||||
// like any other write — no purge-exemption path by design — so the purge inflates
|
||||
// LocalDbOplogBacklog / localdb_oplog_depth until the peer acks. The Information
|
||||
// line is the breadcrumb that lets an operator tie the spike to the purge instead
|
||||
// of reading it as a replication fault.
|
||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||
|
||||
var logger = new CapturingLogger();
|
||||
var purge = CreatePurgeService(isReplicationConfigured: () => true, logger: logger);
|
||||
purge.RunPurge();
|
||||
|
||||
Assert.Equal(0, GetEventCount());
|
||||
var note = Assert.Single(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
|
||||
Assert.Equal(LogLevel.Information, note.Level);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PurgeByRetention_OnUnreplicatedNode_DoesNotLogTheNote()
|
||||
{
|
||||
// The other half of the gate: site-b/site-c on the rig run with no replication
|
||||
// configured, have no CDC triggers at all, and therefore no backlog to explain.
|
||||
// Emitting the note there would be noise pointing at a metric that reads null.
|
||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||
|
||||
var logger = new CapturingLogger();
|
||||
var purge = CreatePurgeService(isReplicationConfigured: () => false, logger: logger);
|
||||
purge.RunPurge();
|
||||
|
||||
Assert.Equal(0, GetEventCount());
|
||||
Assert.DoesNotContain(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PurgeByRetention_WithNoRowsDeleted_DoesNotLogTheNote()
|
||||
{
|
||||
// The note is a companion to a purge line, not a tick heartbeat: a daily tick that
|
||||
// deleted nothing produces no oplog rows and so must stay silent, otherwise the
|
||||
// breadcrumb loses all correlating value.
|
||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
|
||||
|
||||
var logger = new CapturingLogger();
|
||||
var purge = CreatePurgeService(isReplicationConfigured: () => true, logger: logger);
|
||||
purge.RunPurge();
|
||||
|
||||
Assert.Equal(1, GetEventCount());
|
||||
Assert.DoesNotContain(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PurgeByStorageCap_OnReplicatedNode_LogsTheOplogBacklogNote()
|
||||
{
|
||||
// A cap-driven trim deletes rows through the same replicated table and is usually
|
||||
// the larger of the two bursts, so it carries the same note.
|
||||
for (int i = 0; i < 100; i++)
|
||||
{
|
||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow);
|
||||
}
|
||||
|
||||
var capOptions = new SiteEventLogOptions
|
||||
{
|
||||
DatabasePath = _dbPath,
|
||||
RetentionDays = 30,
|
||||
MaxStorageMb = 0 // 0 MB cap forces the cap purge; retention deletes nothing here
|
||||
};
|
||||
|
||||
var logger = new CapturingLogger();
|
||||
var purge = CreatePurgeService(capOptions, isReplicationConfigured: () => true, logger: logger);
|
||||
purge.RunPurge();
|
||||
|
||||
Assert.Equal(0, GetEventCount());
|
||||
var note = Assert.Single(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
|
||||
Assert.Equal(LogLevel.Information, note.Level);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RunPurge_WhenReplicationCheckThrows_StillPurgesAndSwallows()
|
||||
{
|
||||
// Defensive: the replication predicate only selects log wording. A throw from it
|
||||
// must never escape the purge — the rows are already deleted by the time it is
|
||||
// consulted, and an exception here would surface as "Error during event log purge"
|
||||
// for a purge that in fact succeeded.
|
||||
InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31));
|
||||
|
||||
var logger = new CapturingLogger();
|
||||
var purge = CreatePurgeService(
|
||||
isReplicationConfigured: () => throw new InvalidOperationException("boom"),
|
||||
logger: logger);
|
||||
purge.RunPurge();
|
||||
|
||||
Assert.Equal(0, GetEventCount());
|
||||
Assert.DoesNotContain(logger.Entries, e => e.Level == LogLevel.Error);
|
||||
Assert.DoesNotContain(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Minimal <see cref="ILogger{TCategoryName}"/> that records level + rendered message.
|
||||
/// The purge service has no other observable output for a log-only change, and the
|
||||
/// suite has no shared capturing logger to reuse.
|
||||
/// </summary>
|
||||
private sealed class CapturingLogger : ILogger<EventLogPurgeService>
|
||||
{
|
||||
public List<(LogLevel Level, string Message)> 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((logLevel, formatter(state, exception)));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user