fix(comms): review findings — consumer-based debug orphan net, foreign-cancel triad, honest onConnected, served-row-exact retirement, full-rate reconcile
F1 (HIGH) DebugStreamBridgeActor: the 5-minute orphan net measured the MAILBOX (SetReceiveTimeout), and once stream events were correctly marked INotInfluenceReceiveTimeout nothing recurring reset it — the snapshot lands once and GrpcStreamStable once — so every healthy session self-terminated at ~6 min with a false "Site disconnected". Replaced with a periodic self-tick (ConsumerLivenessCheckInterval, 30s) over a consumer-last-seen stamp renewed only by DebugStreamConsumerAlive, which DebugStreamService Tells on a shared timer to every session still in its registry (holding a session there IS "a consumer is attached" — both the Blazor view and the SignalR hub release it on dispose/disconnect, and it works headless). Reverting the wrapper was rejected: it would restore the quiet-instance orphan bug. F2 (MED) SiteStreamGrpcClient: the RpcException(Cancelled) filter now requires cts.IsCancellationRequested. A peer-originated / channel-dispose Cancelled fired none of onError/onCompleted/onConnected, leaving SiteAlarmAggregatorActor with _streamDown=false forever (IsLive stuck true, reconcile reopen guard never fired). F3 (MED) SiteStreamGrpcClient: a header TIMEOUT is no longer reported as connected — that shape is exactly what an unreachable site produces, and it cleared _streamDown, consumed _seedOnConnect and launched a full snapshot fan-out at a dead site. AwaitHeadersAsync returns bool; the first received event is the fallback connected signal, fired at most once from headers OR first event. F4 (LOW-MED) SqliteAuditWriter.MarkReconciledUpToAsync: the blanket below-cursor UPDATE retired late-stamped inserts that were never served (then age-purged — silent loss). The flip is now bounded by insertion order: a Pending row retires only if its rowid is at or below the high-water mark of rows this instance has served from ReadPendingSinceAsync (clamped on purge, since SQLite reuses rowids); Forwarded rows are exempt (central ACKed them over the push path). At-least-once is unchanged. F5 (LOW) Documented the liveness dependency (a served row never covered by a later cursor stays Pending forever; PurgeExpiredAsync never purges Pending) in ISiteAuditQueue + Component-AuditLog.md, and added a cheap site-health signal: SiteAuditBacklogReporter logs a rate-limited warning when the existing oldest-pending metric exceeds 24h. F6 (MED) SiteAlarmAggregatorActor: _fanoutSinceLastTick was armed by the reconcile's OWN fan-out, so steady state ran fan-out→skip→fan-out→skip — one reconcile per 2x interval (120s), halving the not-reporting refresh and the alarm reconcile backstop. The skip is now armed only by connect/failover-driven seeds (initial, _seedOnConnect, and a re-seed queued behind one). Tests: Communication.Tests 691 passed (+13), AuditLog.Tests 382 passed (+5).
This commit is contained in:
Joseph Doherty
+64
@@ -1,4 +1,5 @@
|
||||
using System.Diagnostics;
|
||||
using Microsoft.Extensions.Logging;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Microsoft.Extensions.Options;
|
||||
using NSubstitute;
|
||||
@@ -115,4 +116,67 @@ public class SiteAuditBacklogReporterCadenceTests
|
||||
|
||||
Assert.Equal(TimeSpan.FromSeconds(3), reporter.RefreshInterval);
|
||||
}
|
||||
|
||||
// ----- Stale-Pending signal (review F5) ----- //
|
||||
|
||||
[Fact]
|
||||
public void StalePendingBacklog_IsWarned_ThenRateLimited()
|
||||
{
|
||||
// Pending rows are exempt from the retention purge by design, so a standing Pending
|
||||
// backlog is the one site-store condition that never self-heals on age — it clears
|
||||
// only when central acknowledges the rows. It is worth a log line, not just a number
|
||||
// on the health report, and the warning must not spam every 30 s poll.
|
||||
var logger = new CapturingLogger();
|
||||
var reporter = new SiteAuditBacklogReporter(
|
||||
Substitute.For<ISiteAuditQueue>(),
|
||||
Substitute.For<ISiteHealthCollector>(),
|
||||
logger,
|
||||
TimeSpan.FromHours(1),
|
||||
null);
|
||||
|
||||
var stale = DateTime.UtcNow - SiteAuditBacklogReporter.StalePendingThreshold - TimeSpan.FromHours(1);
|
||||
reporter.WarnIfPendingIsStale(stale, pendingCount: 4321);
|
||||
reporter.WarnIfPendingIsStale(stale, pendingCount: 4321); // same poll cycle-ish
|
||||
|
||||
var warning = Assert.Single(logger.Entries, e => e.Level == LogLevel.Warning);
|
||||
Assert.Contains("4321", warning.Message);
|
||||
Assert.Contains("pending", warning.Message, StringComparison.OrdinalIgnoreCase);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FreshOrEmptyPendingBacklog_IsNotWarned()
|
||||
{
|
||||
var logger = new CapturingLogger();
|
||||
var reporter = new SiteAuditBacklogReporter(
|
||||
Substitute.For<ISiteAuditQueue>(),
|
||||
Substitute.For<ISiteHealthCollector>(),
|
||||
logger,
|
||||
TimeSpan.FromHours(1),
|
||||
null);
|
||||
|
||||
reporter.WarnIfPendingIsStale(null, pendingCount: 0); // nothing pending
|
||||
reporter.WarnIfPendingIsStale(DateTime.UtcNow.AddMinutes(-5), 12); // a normal drain lag
|
||||
|
||||
Assert.DoesNotContain(logger.Entries, e => e.Level == LogLevel.Warning);
|
||||
}
|
||||
|
||||
/// <summary>Captures log entries so the stale-pending signal can be asserted.</summary>
|
||||
private sealed class CapturingLogger : ILogger<SiteAuditBacklogReporter>
|
||||
{
|
||||
public List<(LogLevel Level, Exception? Exception, string Message)> Entries { get; } = new();
|
||||
|
||||
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, exception, formatter(state, exception)));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -614,6 +614,10 @@ public class SqliteAuditWriterWriteTests
|
||||
await writer.WriteAsync(older);
|
||||
await writer.WriteAsync(boundary);
|
||||
|
||||
// Serve them first — retirement is bounded by what has actually been served, which
|
||||
// is exactly the order the pull handler runs in (read, then next pull's cursor).
|
||||
await writer.ReadPendingSinceAsync(DateTime.MinValue, batchSize: 100);
|
||||
|
||||
var flipped = await writer.MarkReconciledUpToAsync(instant, afterId: null);
|
||||
|
||||
Assert.Equal(1, flipped);
|
||||
@@ -648,6 +652,99 @@ public class SqliteAuditWriterWriteTests
|
||||
second.Select(r => r.EventId).ToHashSet());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task MarkReconciledUpToAsync_LateStampedInsertBelowTheCursor_IsNeverRetired()
|
||||
{
|
||||
// THE data-loss case. OccurredAtUtc is caller-stamped, so a row can be INSERTED
|
||||
// after a batch was served yet carry a timestamp BELOW central's (by then advanced)
|
||||
// cursor — a script that back-dates, a clock nudge, a queued write flushed late.
|
||||
// The blanket cursor UPDATE retired exactly those rows: never served, never servable
|
||||
// again (the keyset read has moved past them) and, being Reconciled, purged on age.
|
||||
// The insertion-order (rowid) bound makes them unreachable by the flip.
|
||||
var (writer, dataSource) = CreateWriter(
|
||||
nameof(MarkReconciledUpToAsync_LateStampedInsertBelowTheCursor_IsNeverRetired));
|
||||
await using var _w = writer;
|
||||
|
||||
var t0 = new DateTime(2026, 5, 20, 12, 0, 0, DateTimeKind.Utc);
|
||||
var served1 = NewEvent(occurredAtUtc: t0);
|
||||
var served2 = NewEvent(occurredAtUtc: t0.AddSeconds(20));
|
||||
await writer.WriteAsync(served1);
|
||||
await writer.WriteAsync(served2);
|
||||
|
||||
// Central pulls both and advances its cursor to the newest row.
|
||||
var page = await writer.ReadPendingSinceAsync(DateTime.MinValue, batchSize: 100);
|
||||
Assert.Equal(2, page.Count);
|
||||
var cursorTime = t0.AddSeconds(20);
|
||||
var cursorId = served2.EventId.ToString();
|
||||
|
||||
// A row lands NOW carrying a timestamp between the two served rows.
|
||||
var lateStamped = NewEvent(occurredAtUtc: t0.AddSeconds(10));
|
||||
await writer.WriteAsync(lateStamped);
|
||||
|
||||
var flipped = await writer.MarkReconciledUpToAsync(cursorTime, cursorId);
|
||||
|
||||
// The two genuinely served rows retire; the late-stamped one does not.
|
||||
Assert.Equal(2, flipped);
|
||||
Assert.Equal(AuditForwardState.Reconciled.ToString(), ReadForwardState(dataSource, served1.EventId));
|
||||
Assert.Equal(AuditForwardState.Reconciled.ToString(), ReadForwardState(dataSource, served2.EventId));
|
||||
Assert.Equal(AuditForwardState.Pending.ToString(), ReadForwardState(dataSource, lateStamped.EventId));
|
||||
|
||||
// Still recoverable: a central that restarts (cursor resets to MinValue) re-serves it,
|
||||
// and — being Pending — the retention purge can never drop it in the meantime.
|
||||
var reread = await writer.ReadPendingSinceAsync(DateTime.MinValue, batchSize: 100);
|
||||
Assert.Equal(lateStamped.EventId, Assert.Single(reread).EventId);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task MarkReconciledUpToAsync_ForwardedRowsRetire_EvenWithoutHavingBeenPulled()
|
||||
{
|
||||
// The bound applies to PENDING rows (nothing proves central saw them but the pull).
|
||||
// A FORWARDED row was ACKED by central through the telemetry push path, so the cursor
|
||||
// may retire it whether or not this node has ever served it in a pull — otherwise a
|
||||
// site node that never serves a pull would accumulate acked rows forever.
|
||||
var (writer, dataSource) = CreateWriter(
|
||||
nameof(MarkReconciledUpToAsync_ForwardedRowsRetire_EvenWithoutHavingBeenPulled));
|
||||
await using var _w = writer;
|
||||
|
||||
var t0 = new DateTime(2026, 5, 20, 12, 0, 0, DateTimeKind.Utc);
|
||||
var pushed = NewEvent(occurredAtUtc: t0);
|
||||
var neverShipped = NewEvent(occurredAtUtc: t0.AddSeconds(1));
|
||||
await writer.WriteAsync(pushed);
|
||||
await writer.WriteAsync(neverShipped);
|
||||
|
||||
// Central acked the first row over the telemetry drain — no pull involved.
|
||||
await writer.MarkForwardedAsync(new[] { pushed.EventId });
|
||||
|
||||
var flipped = await writer.MarkReconciledUpToAsync(t0.AddSeconds(30), afterId: null);
|
||||
|
||||
Assert.Equal(1, flipped);
|
||||
Assert.Equal(AuditForwardState.Reconciled.ToString(), ReadForwardState(dataSource, pushed.EventId));
|
||||
Assert.Equal(AuditForwardState.Pending.ToString(), ReadForwardState(dataSource, neverShipped.EventId));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task MarkReconciledUpToAsync_BeforeAnyPull_RetiresNothingPending()
|
||||
{
|
||||
// Bound state is per-process: after a site-node restart nothing has been served yet,
|
||||
// so an incoming cursor retires no Pending row. Conservative in the safe direction —
|
||||
// the rows stay servable and the next pull re-establishes the bound.
|
||||
var (writer, dataSource) = CreateWriter(nameof(MarkReconciledUpToAsync_BeforeAnyPull_RetiresNothingPending));
|
||||
await using var _w = writer;
|
||||
|
||||
var t0 = new DateTime(2026, 5, 20, 12, 0, 0, DateTimeKind.Utc);
|
||||
var evt = NewEvent(occurredAtUtc: t0);
|
||||
await writer.WriteAsync(evt);
|
||||
|
||||
var flipped = await writer.MarkReconciledUpToAsync(t0.AddHours(1), afterId: null);
|
||||
|
||||
Assert.Equal(0, flipped);
|
||||
Assert.Equal(AuditForwardState.Pending.ToString(), ReadForwardState(dataSource, evt.EventId));
|
||||
|
||||
// …and the very next pull cycle retires it normally.
|
||||
await writer.ReadPendingSinceAsync(DateTime.MinValue, batchSize: 100);
|
||||
Assert.Equal(1, await writer.MarkReconciledUpToAsync(t0.AddHours(1), afterId: null));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ReadPendingSinceAsync_InvalidBatchSize_Throws()
|
||||
{
|
||||
|
||||
Reference in New Issue
Block a user