Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/SiteAuditBacklogReporterCadenceTests.cs
T
Joseph Doherty fd5e023d08 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).
2026-08-14 23:52:25 -04:00

183 lines
7.2 KiB
C#

using System.Diagnostics;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;
using NSubstitute;
using ZB.MOM.WW.ScadaBridge.AuditLog.Site;
using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services;
using ZB.MOM.WW.ScadaBridge.Commons.Types;
using ZB.MOM.WW.ScadaBridge.HealthMonitoring;
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Tests.Site;
/// <summary>
/// Deferred-work #21: the backlog reporter's poll cadence is configurable via
/// <see cref="SqliteAuditWriterOptions.BacklogPollIntervalSeconds"/> instead of the
/// old hard-coded 30 s constant.
/// </summary>
public class SiteAuditBacklogReporterCadenceTests
{
private static SiteAuditBacklogReporter Create(
IOptions<SqliteAuditWriterOptions>? options, TimeSpan? explicitInterval = null) =>
new(
Substitute.For<ISiteAuditQueue>(),
Substitute.For<ISiteHealthCollector>(),
NullLogger<SiteAuditBacklogReporter>.Instance,
explicitInterval,
options);
[Fact]
public async Task StopAsync_WhileProbeInFlight_LoopCompletesCleanly()
{
// SafeProbeAsync rethrows OperationCanceledException by design so a shutdown
// aborts the probe promptly — but RunLoopAsync must absorb it, because StopAsync
// hands _loop straight to the host and a canceled task there throws out of
// Host.StopAsync. Mirrors the guard SiteAuditRetentionService already carries
// (arch-review 04 round 2, R7).
var probeStarted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
var queue = Substitute.For<ISiteAuditQueue>();
queue.GetBacklogStatsAsync(Arg.Any<CancellationToken>())
.Returns(ci => BlockUntilCancelledAsync(probeStarted, ci.Arg<CancellationToken>()));
var reporter = new SiteAuditBacklogReporter(
queue,
Substitute.For<ISiteHealthCollector>(),
NullLogger<SiteAuditBacklogReporter>.Instance,
TimeSpan.FromHours(1),
null);
await reporter.StartAsync(CancellationToken.None);
await probeStarted.Task; // the immediate first probe is now in flight
// The assertion is that awaiting the loop task does not throw.
await reporter.StopAsync(CancellationToken.None);
reporter.Dispose();
}
private static async Task<SiteAuditBacklogSnapshot> BlockUntilCancelledAsync(
TaskCompletionSource started, CancellationToken ct)
{
started.TrySetResult();
await Task.Delay(Timeout.Infinite, ct);
throw new UnreachableException("the delay above always throws on cancellation");
}
[Fact]
public async Task StopAsync_AfterDispose_DoesNotThrow()
{
// Regression (Gitea #15 follow-up): Dispose tears down the CTS StopAsync
// cancels, and the host does not guarantee StopAsync is driven before the DI
// container is disposed. Cancel() on a disposed CTS throws, and letting that
// escape an IHostedService aborts the host's whole shutdown sequence.
var reporter = Create(Options.Create(new SqliteAuditWriterOptions()), TimeSpan.FromHours(1));
await reporter.StartAsync(CancellationToken.None);
reporter.Dispose();
// The assertion is the absence of ObjectDisposedException.
await reporter.StopAsync(CancellationToken.None);
reporter.Dispose();
}
[Fact]
public void Cadence_ComesFromOptions_WhenConfigured()
{
var options = Options.Create(new SqliteAuditWriterOptions { BacklogPollIntervalSeconds = 12 });
var reporter = Create(options);
Assert.Equal(TimeSpan.FromSeconds(12), reporter.RefreshInterval);
}
[Fact]
public void Cadence_FallsBackToDefault_WhenOptionsNonPositive()
{
var options = Options.Create(new SqliteAuditWriterOptions { BacklogPollIntervalSeconds = 0 });
var reporter = Create(options);
Assert.Equal(SiteAuditBacklogReporter.DefaultRefreshInterval, reporter.RefreshInterval);
}
[Fact]
public void Cadence_FallsBackToDefault_WhenNoOptions()
{
var reporter = Create(options: null);
Assert.Equal(SiteAuditBacklogReporter.DefaultRefreshInterval, reporter.RefreshInterval);
}
[Fact]
public void ExplicitInterval_WinsOverOptions()
{
var options = Options.Create(new SqliteAuditWriterOptions { BacklogPollIntervalSeconds = 12 });
var reporter = Create(options, explicitInterval: TimeSpan.FromSeconds(3));
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)));
}
}
}