From 7621b489259362a0ffa9a8f18f2a0c275a46a42e Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 20 Jul 2026 05:59:35 -0400 Subject: [PATCH] docs(known-issues): cached-telemetry drain hot-loops on a missing tracking snapshot MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An audit row whose tracking snapshot cannot be resolved is skipped and left Pending, on the reasoning that central reconciliation will pick it up. Nothing removes it from the local drain queue, so the next tick re-reads it, fails identically, and logs again — forever. Measured on the rig at ~2,800 warnings/minute, sustained across both a process restart and a container restart, until the audit database itself was discarded. The code comment already names the cause ("the tracking store was reset"), so this is an anticipated input, not an exotic one. 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. The two stores are easy to desync because they live in different places — audit in auditlog.db, which on the docker rig is INSIDE the container, and tracking in the bind-mounted LocalDb database. Skipping the row is right; leaving it Pending with no other state change is not. There is no attempt counter, no backoff, no terminal state, and one Warning per row per pass. Suggested fixes ranked by effort, the cheapest being to rate-limit the warning the way MaintenanceBackgroundService already does for oplog caps. No data loss — the audit rows are intact and still reach central by the reconciliation path. Found while cleaning the rig after the Phase 2 live gate. Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts --- ...6-07-20-cached-telemetry-drain-hot-loop.md | 92 +++++++++++++++++++ 1 file changed, 92 insertions(+) create mode 100644 docs/known-issues/2026-07-20-cached-telemetry-drain-hot-loop.md diff --git a/docs/known-issues/2026-07-20-cached-telemetry-drain-hot-loop.md b/docs/known-issues/2026-07-20-cached-telemetry-drain-hot-loop.md new file mode 100644 index 00000000..d44037a5 --- /dev/null +++ b/docs/known-issues/2026-07-20-cached-telemetry-drain-hot-loop.md @@ -0,0 +1,92 @@ +# Cached-telemetry drain hot-loops forever on a row whose tracking snapshot is gone + +**Date:** 2026-07-20 · **Status:** OPEN · **Severity:** Medium (log flood + wasted I/O; no data loss) +· **Area:** AuditLog / Site Telemetry + +## Summary + +`SiteAuditTelemetryActor`'s cached-telemetry drain reads Pending audit rows, looks up each row's +tracking snapshot by `CorrelationId`, and pushes the combined packet to central. When the lookup +returns `null` the row is **skipped and deliberately left Pending** +(`SiteAuditTelemetryActor.cs:307`), on the reasoning that "central reconciliation will pick it up". + +Nothing ever removes such a row from the local drain queue. The next tick re-reads it, fails the +same lookup, logs the same warning, and leaves it Pending again — **forever**. With a batch of +unresolvable rows the actor spins at its non-idle rate and emits one warning per row per pass. + +Measured on the docker rig: **~2 800 warnings/minute, sustained**, surviving both a process restart +and a container restart, until the audit database itself was discarded. + +``` +[09:57:41 WRN] [Site/scadabridge-site-a-a] Cached-telemetry drain: no tracking snapshot for + a5392796-291f-4f5b-9fbf-5817c1ec76c7 (TrackedOperationId 59bd4bf8-…); skipping. +``` + +## Why the rows became unresolvable + +Two independent stores must agree: + +- the **audit** rows live in `auditlog.db` (site-local, and on the docker rig **inside the + container at `/app/auditlog.db`**, not on the bind-mounted data volume); +- the **tracking** rows live in `OperationTracking`, which LocalDb Phase 1 moved into the + consolidated `LocalDb:Path` database (bind-mounted). + +Anything that resets one without the other strands every audit row that referenced it. The code +comment already anticipates the cause — *"possible if the audit row is older than the tracking +retention window, or the tracking store was reset"* — so this is a known-and-accepted input, not an +exotic one. + +**Two realistic production triggers, neither requiring operator error:** + +1. **Tracking retention expiry.** If the tracking retention window elapses before the audit drain + catches up — a long central outage, a large backlog — the snapshots are pruned out from under + still-Pending audit rows and every one of them becomes a permanent hot-loop entry. +2. **Restoring or resetting one store independently of the other**, e.g. rebuilding a node's + LocalDb file from its peer while its container-local `auditlog.db` survives. + +It was hit here by (2): the two site-a LocalDb databases were dropped during a rig cleanup while +`auditlog.db` — being inside the container — survived. + +## Why the current handling is not enough + +Skipping the row is correct; **leaving it Pending with no other state change is not**. The row is +now in a state it can never leave: + +- no attempt counter, so an unresolvable row is indistinguishable from a transiently-failing one; +- no backoff, so the actor runs at full non-idle rate against a queue that can never shrink; +- no terminal state, so it is retried for the life of the database; +- one Warning per row per pass, which buries every other log line on the node. + +The "central reconciliation will pick it up" comment is about the **audit half** reaching central by +another path. That may well be true — but it does not release the row from the local drain queue, +which is what actually loops. + +## Suggested fix + +Give an unresolvable row somewhere to go. Roughly, in increasing order of effort: + +1. **Bound the retries.** Add an attempt count; past a threshold mark the row terminal + (`TrackingUnavailable`) and stop re-reading it. Emit a single summary Warning with the count + rather than one per row per pass. +2. **Rate-limit the warning** to one per drain episode regardless of row count — the same pattern + `MaintenanceBackgroundService` already uses for the oplog caps-exceeded warning (`_snapshotFlagWarned`). +3. **Push the audit half alone** when the tracking snapshot is missing, rather than skipping the row + entirely, so the row can be marked emitted and leave the queue. Needs a decision on whether + central accepts a packet with no tracking half. + +(2) alone would remove the operational damage; (1) or (3) is needed to stop the wasted I/O. + +## Reproduction + +1. Run a site node until it has cached-call audit rows with tracking correlations. +2. Stop the node; delete its consolidated LocalDb database (which holds `OperationTracking`); + leave `auditlog.db` in place. +3. Start the node. The drain warning repeats indefinitely; the rate does not decay. + +## Notes + +- **No data loss.** The audit rows are intact and still reach central by the reconciliation path; + what is broken is the local drain's ability to ever finish. +- Discovered while cleaning the rig after the LocalDb Phase 2 live gate + (`docs/plans/2026-07-19-localdb-phase2-live-gate.md`), which is also where the related + "deleting an instance orphans its buffered messages" observation is recorded.