Merge branch 'fix/cached-telemetry-drain-hot-loop'

src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs

@@ -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();

src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryOptions.cs

@@ -25,4 +25,33 @@ public sealed class SiteAuditTelemetryOptions
     /// Longer interval avoids hammering an idle SQLite + gRPC channel.
     /// </summary>
     public int IdleIntervalSeconds { get; set; } = 30;
+
+    /// <summary>
+    /// How long a cached-telemetry audit row may go without a resolvable
+    /// <c>OperationTracking</c> snapshot before the drain ABANDONS its
+    /// operational half and marks the row Forwarded. Default: 300 s.
+    /// </summary>
+    /// <remarks>
+    /// <para>
+    /// A missing tracking snapshot is normally a brief write race — the audit
+    /// row lands microseconds before the tracking row — so the drain retries
+    /// within this grace period. Past it the snapshot is almost certainly gone
+    /// for good (tracking retention elapsed while central was unreachable, or
+    /// the two stores were reset independently), and retrying forever is
+    /// actively harmful: the queue is read oldest-first with a fixed
+    /// <see cref="BatchSize"/>, so a batch's worth of permanently-unresolvable
+    /// rows at the head STARVES every newer cached row behind them.
+    /// </para>
+    /// <para>
+    /// Abandoning costs only the operational (<c>SiteCalls</c>) half, which is
+    /// unrecoverable anyway once the tracking row is gone. The audit half is
+    /// NOT lost: the reconciliation pull covers Forwarded rows as well as
+    /// Pending ones, and central dedups on EventId.
+    /// </para>
+    /// <para>
+    /// Set to 0 to abandon on the first failed lookup. Negative values are
+    /// treated as 0.
+    /// </para>
+    /// </remarks>
+    public int CachedTrackingGraceSeconds { get; set; } = 300;
 }