fix(audit): let an unresolvable cached row leave the drain queue #24
Assignees
dohertj2 (dohertj2)
Clear assignees
dohertj2 (dohertj2)
No Assignees
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: dohertj2/ScadaBridge#24
Reference in New Issue
Block a user
Delete Branch "fix/cached-telemetry-drain-hot-loop"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Summary
Fixes the cached-telemetry drain hot-loop (
docs/known-issues/2026-07-20-cached-telemetry-drain-hot-loop.md).A cached-telemetry audit row whose
OperationTrackingsnapshot could not be resolved was skipped and leftPending. Nothing ever removed it, so the next drain re-read it, failed identically, and logged again — forever.The severity was worse than the issue was filed as. 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" originally recorded. Measured on the rig at ~2,800 warnings/minute, surviving both a process restart and a container restart.The fix
After a grace period (
CachedTrackingGraceSeconds, default 300 s) the operational half is abandoned and the row markedForwarded. A row with noCorrelationIdis abandoned immediately — it can never resolve.Marking
Forwardeddoes not drop audit data. That state means "no longer owed by the drain, still eligible for reconciliation", which is exactly this situation:ReadPendingSinceAsynccoversForwardedas well asPending, and central dedups onEventId, so the reconciliation pull still delivers the audit half. What is lost is the operational (SiteCalls) half — unrecoverable anyway once the tracking row is gone.Three deliberate boundaries, each with a test:
Logging moved to per drain pass rather than per row. Deferred rows dropped to Debug — being inside the grace window is normal operation, not a warning.
Test Plan
CachedDrain_OrphanRow_NoTrackingSnapshot_IsSkipped_DoesNotCrashretargeted, not deleted — it pinned the defect ("skipped and stays Pending"), so its orphan assertion is inverted while the half that still holds is kept verbatimCachedDrain_FullBatchOfUnresolvableRows_DoesNotStarveTheQueue— the actual regressionOrigin
Found while cleaning the rig after the LocalDb Phase 2 live gate. Two production triggers need no operator error: the tracking retention window elapsing before the drain catches up (long central outage, large backlog), or restoring one store independently of the other — easy to do because the two live in different places (
auditlog.dbis inside the container on the docker rig; tracking is in the bind-mounted LocalDb database).https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
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_01BL2Vu1ESDQ9SCN4gVKkdtsView command line instructions
Checkout
From your project repository, check out a new branch and test the changes.