perf(comms+audit): close phase-2 residuals — direct ingest path, monotonic timeouts, synthetic probe, not-reporting set, cursor-exact audit pull

This commit is contained in:
Joseph Doherty
2026-08-14 21:38:23 -04:00
parent 4cd1441984
commit a5882753dd
38 changed files with 1254 additions and 443 deletions
@@ -58,15 +58,21 @@ public class AuditLogIngestActor : ReceiveActor
/// SHORTER than the gRPC Ask that wraps it.
/// </summary>
/// <remarks>
/// The path used to stack three identical 30 s budgets — the site's Ask
/// (<c>CommunicationOptions.NotificationForwardTimeout</c>), the central gRPC
/// handler's Ask (<c>SiteStreamGrpcServer.AuditIngestAskTimeout</c>) and the
/// ADO.NET command default — so they all expired at the same instant. The
/// The path used to stack three identical 30 s budgets — the site's Ask, the
/// central gRPC handler's Ask (<c>SiteStreamGrpcServer.AuditIngestAskTimeout</c>)
/// and the ADO.NET command default — so they all expired at the same instant. The
/// caller therefore learned nothing except "it took 30 s": no partial ack, no
/// distinction between a slow database and a wedged singleton. Making the
/// innermost budget strictly smallest means a slow batch is abandoned by the
/// actor FIRST, with the accepted-so-far ids still replied, while the outer
/// Asks are still waiting.
/// <para>
/// The full ladder is now strictly monotonic end to end:
/// <c>CommunicationOptions.AuditForwardTimeout</c> (35 s, the site-side forward Ask) &gt;
/// <c>SiteStreamGrpcServer.AuditIngestAskTimeout</c> (30 s, the gRPC deadline AND central's
/// Ask of this singleton) &gt; <see cref="IngestBudget"/> (20 s) &gt;
/// <see cref="IngestSqlCommandTimeout"/> (15 s).
/// </para>
/// </remarks>
internal static readonly TimeSpan IngestBudget = TimeSpan.FromSeconds(20);
@@ -73,6 +73,7 @@ public sealed class GrpcPullAuditEventsClient : IPullAuditEventsClient
public async Task<PullAuditEventsResponse> PullAsync(
string siteId,
DateTime sinceUtc,
string? afterId,
int batchSize,
CancellationToken ct)
{
@@ -93,6 +94,10 @@ public sealed class GrpcPullAuditEventsClient : IPullAuditEventsClient
// EnsureUtc keeps Timestamp.FromDateTime happy (it requires UTC kind).
SinceUtc = Timestamp.FromDateTime(EnsureUtc(sinceUtc)),
BatchSize = batchSize,
// Composite-keyset tiebreak (proto field 3), mirroring PullSiteCalls exactly.
// proto3 has no nullable string — an unset/empty AfterId is the site's signal to
// keep the legacy inclusive-timestamp contract (also what a first pull sends).
AfterId = afterId ?? string.Empty,
};
var (reply, transportFault) = await TryInvokeAsync(endpoint, request, siteId, ct)
@@ -121,10 +126,13 @@ public sealed class GrpcPullAuditEventsClient : IPullAuditEventsClient
// Map proto DTOs to canonical AuditEvent records and order oldest-first
// (the wire is already ordered by the site queue, but the
// IPullAuditEventsClient contract is explicit, so sort defensively).
// IPullAuditEventsClient contract is explicit, so sort defensively). The EventId
// tiebreak matches the site's own composite ordering — ordinal over the "D" GUID
// text, which is what SQLite's BINARY collation compares.
var events = reply.Events
.Select(AuditEventDtoMapper.FromDto)
.OrderBy(e => e.OccurredAtUtc)
.ThenBy(e => e.EventId.ToString(), StringComparer.Ordinal)
.ToList();
return new PullAuditEventsResponse(events, reply.MoreAvailable);
@@ -39,12 +39,24 @@ public interface IPullAuditEventsClient
/// </summary>
/// <param name="siteId">The identifier of the site to pull audit events from.</param>
/// <param name="sinceUtc">Only events with an <c>OccurredAtUtc</c> at or after this cursor time are returned.</param>
/// <param name="afterId">
/// The composite-keyset tiebreak cursor, mirroring
/// <see cref="IPullSiteCallsClient.PullAsync"/>. When non-null it is the
/// <c>EventId</c> ("D" GUID form) of the last row already consumed at
/// <paramref name="sinceUtc"/>; the site returns only rows strictly greater than the
/// composite <c>(OccurredAtUtc, EventId)</c> pair, so a burst sharing one exact instant
/// drains via the id tiebreak instead of pinning the inclusive-timestamp cursor — and the
/// site's <c>MarkReconciledUpToAsync</c> can retire the rows AT that instant, which a bare
/// timestamp can never prove received. Null on the first pull (or against a legacy site)
/// preserves the inclusive <c>&gt;=</c> contract.
/// </param>
/// <param name="batchSize">Maximum number of events to return per call.</param>
/// <param name="ct">Cancellation token.</param>
/// <returns>A task that resolves to the next reconciliation batch with a <c>MoreAvailable</c> flag.</returns>
Task<PullAuditEventsResponse> PullAsync(
string siteId,
DateTime sinceUtc,
string? afterId,
int batchSize,
CancellationToken ct);
}
@@ -76,14 +76,28 @@ public class SiteAuditReconciliationActor : ReceiveActor
private readonly ILogger<SiteAuditReconciliationActor> _logger;
/// <summary>
/// Per-site reconciliation watermark — the highest
/// <see cref="AuditEvent.OccurredAtUtc"/> seen for that site on a previous
/// tick. Asking for <c>OccurredAtUtc &gt;= cursor</c> rather than &gt;
/// is the site contract (<see cref="ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services.ISiteAuditQueue.ReadPendingSinceAsync"/>);
/// duplicate-with-same-timestamp rows are filtered out by the idempotent
/// repository write.
/// Per-site reconciliation watermark — the COMPOSITE
/// <c>(OccurredAtUtc, EventId)</c> of the highest row seen for that site on a previous tick,
/// mirroring <c>SiteCallAuditActor</c>'s <c>PullSiteCalls</c> cursor.
/// </summary>
private readonly Dictionary<string, DateTime> _cursors = new();
/// <remarks>
/// <para>
/// The site's
/// <see cref="ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services.ISiteAuditQueue.ReadPendingSinceAsync"/>
/// serves rows strictly after the pair when <c>AfterId</c> is set, and falls back to the
/// legacy inclusive <c>OccurredAtUtc &gt;= since</c> when it is null (the first pull).
/// Sending the id half matters twice over: a burst sharing one exact instant drains via the
/// tiebreak instead of pinning the timestamp forever, and
/// <see cref="ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services.ISiteAuditQueue.MarkReconciledUpToAsync"/>
/// can retire the rows AT the cursor instant — a bare timestamp can only prove receipt of
/// rows strictly older than itself, so the boundary rows stayed servable forever.
/// </para>
/// <para>
/// Duplicates that a re-pull does produce are still filtered by the idempotent repository
/// write, so the cursor is an optimization for exactness, never a correctness crutch.
/// </para>
/// </remarks>
private readonly Dictionary<string, (DateTime Since, string? AfterId)> _cursors = new();
/// <summary>
/// Per-site count of consecutive non-draining cycles. Resets to zero on the
@@ -239,20 +253,33 @@ public class SiteAuditReconciliationActor : ReceiveActor
/// <summary>
/// Issues one <c>PullAuditEvents</c> RPC against the site, ingests the
/// returned rows idempotently into the central repository, and advances
/// the cursor based on the maximum <see cref="AuditEvent.OccurredAtUtc"/>
/// observed. The brief's "saturate until backlog clears" intent is met by
/// the natural cadence — each tick issues one pull, and a backed-up site
/// the composite <c>(<see cref="AuditEvent.OccurredAtUtc"/>, <see cref="AuditEvent.EventId"/>)</c>
/// cursor to the maximum row observed. The brief's "saturate until backlog clears" intent is
/// met by the natural cadence — each tick issues one pull, and a backed-up site
/// drains across consecutive ticks. The stalled signal (two non-draining
/// ticks in a row) surfaces when that drain isn't keeping up.
/// </summary>
/// <remarks>
/// Unlike <c>SiteCallAuditActor</c> this does NOT page within a tick; one pull per tick is
/// deliberate (the stalled signal is how a lagging drain surfaces). The composite cursor is
/// what makes that safe against a same-instant burst larger than one batch: the id tiebreak
/// advances even when the timestamp cannot, so consecutive ticks make real progress instead
/// of re-serving the same window forever.
/// </remarks>
private async Task PullSiteAsync(SiteEntry site, IAuditLogRepository repository, Akka.Event.EventStream eventStream)
{
var since = _cursors.TryGetValue(site.SiteId, out var c) ? c : DateTime.MinValue;
var cursor = _cursors.TryGetValue(site.SiteId, out var c)
? c
: (Since: DateTime.MinValue, AfterId: (string?)null);
var since = cursor.Since;
var afterId = cursor.AfterId;
var response = await _client.PullAsync(
site.SiteId, since, _options.BatchSize, CancellationToken.None)
site.SiteId, since, afterId, _options.BatchSize, CancellationToken.None)
.ConfigureAwait(false);
var maxOccurred = since;
var maxAfterId = afterId;
var hasUnresolvedFailure = false;
var nowUtc = DateTime.UtcNow;
foreach (var evt in response.Events)
@@ -310,10 +337,18 @@ public class SiteAuditReconciliationActor : ReceiveActor
}
// Canonical OccurredAtUtc is a DateTimeOffset; the cursor is a UTC DateTime.
// Advance the COMPOSITE max, exactly as SiteCallAuditActor does: a greater
// timestamp wins; on a tie the greater EventId (ordinal over the "D" GUID text,
// matching the site's SQLite BINARY collation) wins. CompareOrdinal handles the
// null seed — CompareOrdinal(x, null) > 0 for any non-null x.
var occurredUtc = evt.OccurredAtUtc.UtcDateTime;
if (advanceForThisRow && occurredUtc > maxOccurred)
var rowId = evt.EventId.ToString();
if (advanceForThisRow &&
(occurredUtc > maxOccurred ||
(occurredUtc == maxOccurred && string.CompareOrdinal(rowId, maxAfterId) > 0)))
{
maxOccurred = occurredUtc;
maxAfterId = rowId;
}
}
@@ -322,8 +357,11 @@ public class SiteAuditReconciliationActor : ReceiveActor
// the whole batch next tick — successful rows are no-ops thanks to
// InsertIfNotExistsAsync's idempotency, and the failing row gets
// another attempt. Once it succeeds (or hits the permanent-abandon
// threshold) the cursor unblocks naturally.
_cursors[site.SiteId] = hasUnresolvedFailure ? since : maxOccurred;
// threshold) the cursor unblocks naturally. Both halves move together: holding the
// timestamp back while advancing the id would skip the very rows being retried.
_cursors[site.SiteId] = hasUnresolvedFailure
? (since, afterId)
: (maxOccurred, maxAfterId);
var nonDraining = response.MoreAvailable && response.Events.Count > 0;
UpdateStalledState(site.SiteId, draining: !nonDraining, eventStream);