LocalDb adoption Phase 1 + 2: consolidate the site database, delete the bespoke replicators #23
@@ -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.
|
||||
Reference in New Issue
Block a user