dohertj2/ScadaBridge
1
0
Fork 0
Code Issues 2 Pull Requests 1 Actions Packages Projects Releases Wiki Activity

fix(audit): let an unresolvable cached row leave the drain queue

Browse Source 
A cached-telemetry audit row whose OperationTracking snapshot could not be
resolved was skipped and left Pending. Nothing ever removed it, so the next
drain re-read it, failed identically, and logged again — forever.

The severity was worse than the original write-up said. The queue is read
oldest-first with a fixed BatchSize (default 256), so once a batch's worth of
permanently-unresolvable rows collected at the head, every drain re-read
exactly those rows and NEVER REACHED the newer rows behind them. That is a
permanent stall of the cached-telemetry path, not the "log flood, no data loss"
the issue was first filed as. Measured on the rig at ~2,800 warnings/minute,
surviving both a process restart and a container restart.

Fix: after a grace period (CachedTrackingGraceSeconds, default 300 s) the
operational half is abandoned and the row marked Forwarded. A row with no
CorrelationId is abandoned immediately — it can never resolve.

Marking Forwarded does not drop audit data. That state means "no longer owed by
the drain, still eligible for reconciliation", which is exactly this situation:
ReadPendingSinceAsync covers Forwarded as well as Pending and central dedups on
EventId, so the reconciliation pull still delivers the audit half. What is lost
is the operational (SiteCalls) half, which is unrecoverable anyway once the
tracking row is gone.

Three deliberate boundaries:
- Inside the grace window the row is still retried — a missing snapshot is
  normally a brief write race, and abandoning on the first failed lookup would
  discard the operational half of every cached call that lost that race.
- A tracking-store THROW never abandons, however old the row: a throw is a
  store fault (locked, corrupt, mid-restore), not a verdict about the row.
- Logging is per drain pass, not per row. Deferred rows dropped to Debug —
  being inside the grace window is normal operation, not a warning.

CachedDrain_OrphanRow_NoTrackingSnapshot_IsSkipped_DoesNotCrash was RETARGETED
rather than deleted: it pinned the defect ("skipped and stays Pending"), so its
orphan assertion is inverted and the half that still holds is kept verbatim.
Three tests added, including the starvation regression. Both "must NOT abandon"
tests carry a positive control on the read count, so they cannot pass by virtue
of a drain that never ran.

Verified non-vacuous: with abandonment disabled the two abandonment tests go
red and the two guards stay green. Build 0 warnings; AuditLog 358, Host 330,
SiteRuntime 512, StoreAndForward 130, Communication 312, Commons 684,
Integration 94 — all pass.

Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
This commit is contained in:
Joseph Doherty
2026-07-20 06:29:22 -04:00
parent 28ca04d7de
commit 62cddcfa56
4 changed files with 328 additions and 28 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs
+114 -23
View File
@@ -261,6 +261,18 @@ public class SiteAuditTelemetryActor : ReceiveActor
var batch = new CachedTelemetryBatch();
var emittedEventIds = new List<Guid>(pending.Count);
// Rows whose operational half can never be built. They are marked
// Forwarded so they LEAVE this queue — see AbandonUnresolvableAsync
// for why that is safe and why leaving them Pending is not.
var abandonedEventIds = new List<Guid>();
// Counted, not logged per row: a whole batch can fail identically
// (tracking store down, tracking retention elapsed), and one line
// per row per drain is what turned this into a log flood.
var deferredNoSnapshot = 0;
var lookupFailures = 0;
Exception? firstLookupFailure = null;
var graceSeconds = Math.Max(0, _options.CachedTrackingGraceSeconds);
var abandonBefore = DateTime.UtcNow - TimeSpan.FromSeconds(graceSeconds);
foreach (var auditRow in pending)
{
@@ -268,13 +280,9 @@ public class SiteAuditTelemetryActor : ReceiveActor
{
// CorrelationId carries the TrackedOperationId for cached
// rows — see CachedCallLifecycleBridge.BuildPacket. Without
// it we can't look up the tracking row; log + skip so the
// bad row doesn't block the rest of the batch. The audit
// row stays Pending (still not in emittedEventIds) and
// central reconciliation will pick it up.
_logger.LogWarning(
"Cached-telemetry drain: audit row {EventId} ({Action}) has no CorrelationId; skipping.",
auditRow.EventId, auditRow.Action);
// it there is nothing to look up, ever, so this row is
// abandoned immediately rather than after the grace period.
abandonedEventIds.Add(auditRow.EventId);
continue;
}
@@ -288,24 +296,32 @@ public class SiteAuditTelemetryActor : ReceiveActor
catch (Exception ex)
{
// A tracking-store throw must NOT abort the rest of the
// batch — the audit half is best-effort. Log and skip
// this row; it stays Pending for the next drain.
_logger.LogWarning(ex,
"Cached-telemetry drain: tracking lookup threw for {EventId} (TrackedOperationId {Tid}, sqlite {SqliteError}); skipping.",
auditRow.EventId, auditRow.CorrelationId, SqliteErrorCodes.Describe(ex));
// batch — the audit half is best-effort. A throw is a
// STORE fault (locked, corrupt) rather than a verdict about
// this row, so the row is never abandoned on this path: it
// stays Pending and retries once the store recovers.
lookupFailures++;
firstLookupFailure ??= ex;
continue;
}
if (snapshot is null)
{
// No tracking row — possible if the audit row is older
// than the tracking retention window, or the tracking
// store was reset. The audit half remains valid and will
// be picked up by central reconciliation; skip the
// combined push for this row.
_logger.LogWarning(
"Cached-telemetry drain: no tracking snapshot for {EventId} (TrackedOperationId {Tid}); skipping.",
auditRow.EventId, auditRow.CorrelationId);
// No tracking row. Within the grace window this is the
// ordinary write race (the audit row landed first), so
// retry. Past it the snapshot is gone for good — tracking
// retention elapsed, or the two stores were reset
// independently — and retrying forever would wedge the
// queue behind these rows.
if (auditRow.OccurredAtUtc <= abandonBefore)
{
abandonedEventIds.Add(auditRow.EventId);
}
else
{
deferredNoSnapshot++;
}
continue;
}
@@ -314,11 +330,33 @@ public class SiteAuditTelemetryActor : ReceiveActor
emittedEventIds.Add(auditRow.EventId);
}
if (lookupFailures > 0)
{
_logger.LogWarning(firstLookupFailure,
"Cached-telemetry drain: tracking lookup failed for {Count} of {Total} rows " +
"(sqlite {SqliteError}); they stay Pending and retry next drain. First failure attached.",
lookupFailures, pending.Count, SqliteErrorCodes.Describe(firstLookupFailure!));
}
if (deferredNoSnapshot > 0)
{
_logger.LogDebug(
"Cached-telemetry drain: {Count} row(s) have no tracking snapshot yet and are inside the " +
"{Grace}s grace window; retrying next drain.",
deferredNoSnapshot, graceSeconds);
}
if (abandonedEventIds.Count > 0)
{
await AbandonUnresolvableAsync(abandonedEventIds, graceSeconds, ct)
.ConfigureAwait(false);
}
if (batch.Packets.Count == 0)
{
// Every row in this read was skipped (no CorrelationId / no
// tracking snapshot). Leave them Pending and try again next
// drain — the underlying race normally resolves on its own.
// Nothing resolvable in this read. Any permanently-unresolvable
// rows have just been marked Forwarded above, so the next drain
// sees past them rather than re-reading the same head of queue.
return;
}
@@ -358,6 +396,59 @@ public class SiteAuditTelemetryActor : ReceiveActor
}
}
/// <summary>
/// Marks cached rows whose operational half can never be built as
/// Forwarded, so they leave the cached-drain queue.
/// </summary>
/// <remarks>
/// <para>
/// <b>Why they must leave.</b> Leaving an unresolvable row Pending — the
/// previous behaviour — is not a harmless skip. The queue is read
/// oldest-first with a fixed <c>BatchSize</c>, so once a batch's worth of
/// unresolvable rows collects at the head, every drain re-reads exactly
/// those rows, fails identically, and never sees the newer rows behind
/// them. The cached-telemetry path stalls permanently, and each pass logs
/// once per row (measured at ~2 800 warnings/minute on a rig).
/// </para>
/// <para>
/// <b>Why Forwarded is the honest state.</b> Its role in this state machine
/// is "no longer owed by the drain, still eligible for reconciliation" —
/// which is exactly the situation here. The audit half is NOT dropped:
/// <c>ReadPendingSinceAsync</c> covers Forwarded rows as well as Pending
/// ones and central dedups on EventId, so the reconciliation pull still
/// delivers them. What is genuinely lost is the operational
/// (<c>SiteCalls</c>) half — and that is unrecoverable regardless, because
/// the tracking row it would have been built from no longer exists.
/// </para>
/// <para>
/// A failure to mark is swallowed: the rows simply stay Pending and the
/// next drain retries. Escalating here would take down the audit drain over
/// a best-effort cleanup.
/// </para>
/// </remarks>
private async Task AbandonUnresolvableAsync(
IReadOnlyList<Guid> eventIds, int graceSeconds, CancellationToken ct)
{
try
{
await _queue.MarkForwardedAsync(eventIds, ct).ConfigureAwait(false);
_logger.LogWarning(
"Cached-telemetry drain: abandoned the operational half of {Count} row(s) with no " +
"resolvable tracking snapshot after {Grace}s; marked Forwarded so they no longer block " +
"the queue. The audit half still reaches central via the reconciliation pull. This is " +
"expected after tracking retention elapses or the tracking store is reset independently " +
"of the audit store.",
eventIds.Count, graceSeconds);
}
catch (Exception ex)
{
_logger.LogWarning(ex,
"Cached-telemetry drain: could not mark {Count} unresolvable row(s) Forwarded " +
"(sqlite {SqliteError}); they stay Pending and will be retried.",
eventIds.Count, SqliteErrorCodes.Describe(ex));
}
}
private static AuditEventBatch BuildBatch(IReadOnlyList<AuditEvent> events)
{
var batch = new AuditEventBatch();