dohertj2/lmxopcua
1
0
Fork 0
Code Issues 14 Pull Requests Actions Packages Projects Releases Wiki Activity

Continuous historization: one failing tag re-writes every healthy tag on every drain pass, outbox grows unbounded #538

New Issue
Closed
opened 2026-08-04 11:28:56 -04:00 by dohertj2 · 1 comment
dohertj2 commented 2026-08-04 11:28:56 -04:00
Owner
Copy Link
Copy Source

Split out of #491's read-back run (2026-08-04). Found live, filed rather than fixed — the fix changes the outbox contract.

ContinuousHistorizationRecorder.DrainOnceAsync peeks a batch, writes every per-tag group, and then acks all-or-nothing:

foreach (var group in batch.GroupBy(e => e.Tag, StringComparer.Ordinal)) {
    ok = await _writer.WriteLiveValuesAsync(group.Key, values, ct);   // every group IS written
    if (!ok) allOk = false;
}
if (!allOk) return new DrainResult(false, 0, batch.Count);            // ...but nothing is acked
await _outbox.RemoveAsync(batch[^1].Id, ct);

So a single permanently-failing tag — e.g. one whose historian tag was never provisioned, which is easy to hit given EnsureTags only fires for newly-added tags — means the FIFO head never advances, and every healthy tag in that batch is re-written to the historian on every drain pass, indefinitely.

Two consequences:

  1. Duplicate samples in the historian. The healthy tags' values are re-submitted at their original timestamps every DrainIntervalSeconds (default 2s), for as long as the bad tag keeps failing.
  2. The outbox grows without bound. Capacity defaults to 0 (unbounded), so nothing ever truncates. Observed at 8.3 MB on a docker-dev node with one unprovisionable tag, with the gateway's ok and error counters climbing together — the signature of this bug.

Not a simple "stop writing the good ones"

The all-or-nothing ack is deliberate, and the code comment says why: IHistorizationOutbox.RemoveAsync truncates the FIFO head through the acked id, so acking one tag's entries could silently drop older, unwritten entries belonging to another tag. Given a prefix-truncating outbox, all-or-nothing is the only safe ack.

Candidate directions, all of which touch the outbox contract:

  • Per-entry / sparse ack — let RemoveAsync (or a new AckAsync(ids)) remove specific ids rather than a prefix. Most correct, biggest change; FasterLog is prefix-truncating by nature, so this likely needs a tombstone/compaction layer.
  • Skip-and-quarantine — after N consecutive failures for a given tag, move those entries to a dead-letter sink (the alarm S&F sink already has this shape: MaxAttempts + dead-letter + DeadLetterRetentionDays) so the head can advance. Probably the best fit, and consistent with an existing pattern in this repo.
  • Per-tag outboxes — isolates blast radius, multiplies FasterLog instances.

At minimum, bound the damage: a non-zero default Capacity, and an operator-visible warning when a tag has failed for N consecutive passes (today a failing drain is only a silent back-off — the honest counter lives on the gateway's /metrics, not in OtOpcUa's logs).

Evidence: docs/plans/2026-08-01-continuous-historization-live-gate.md §"Second defect found".

**Split out of #491's read-back run (2026-08-04). Found live, filed rather than fixed — the fix changes the outbox contract.** `ContinuousHistorizationRecorder.DrainOnceAsync` peeks a batch, **writes every per-tag group**, and then acks **all-or-nothing**: ```csharp foreach (var group in batch.GroupBy(e => e.Tag, StringComparer.Ordinal)) { ok = await _writer.WriteLiveValuesAsync(group.Key, values, ct); // every group IS written if (!ok) allOk = false; } if (!allOk) return new DrainResult(false, 0, batch.Count); // ...but nothing is acked await _outbox.RemoveAsync(batch[^1].Id, ct); ``` So a **single permanently-failing tag** — e.g. one whose historian tag was never provisioned, which is easy to hit given `EnsureTags` only fires for newly-*added* tags — means the FIFO head never advances, and **every healthy tag in that batch is re-written to the historian on every drain pass**, indefinitely. Two consequences: 1. **Duplicate samples in the historian.** The healthy tags' values are re-submitted at their original timestamps every `DrainIntervalSeconds` (default 2s), for as long as the bad tag keeps failing. 2. **The outbox grows without bound.** `Capacity` defaults to `0` (unbounded), so nothing ever truncates. **Observed at 8.3 MB** on a docker-dev node with one unprovisionable tag, with the gateway's `ok` and `error` counters climbing *together* — the signature of this bug. ### Not a simple "stop writing the good ones" The all-or-nothing ack is **deliberate**, and the code comment says why: `IHistorizationOutbox.RemoveAsync` truncates the FIFO head *through* the acked id, so acking one tag's entries could silently drop **older, unwritten** entries belonging to another tag. Given a prefix-truncating outbox, all-or-nothing is the only safe ack. Candidate directions, all of which touch the outbox contract: - **Per-entry / sparse ack** — let `RemoveAsync` (or a new `AckAsync(ids)`) remove specific ids rather than a prefix. Most correct, biggest change; FasterLog is prefix-truncating by nature, so this likely needs a tombstone/compaction layer. - **Skip-and-quarantine** — after N consecutive failures for a given tag, move those entries to a dead-letter sink (the alarm S&F sink already has this shape: `MaxAttempts` + dead-letter + `DeadLetterRetentionDays`) so the head can advance. Probably the best fit, and consistent with an existing pattern in this repo. - **Per-tag outboxes** — isolates blast radius, multiplies FasterLog instances. At minimum, **bound the damage**: a non-zero default `Capacity`, and an operator-visible warning when a tag has failed for N consecutive passes (today a failing drain is only a silent back-off — the honest counter lives on the *gateway's* `/metrics`, not in OtOpcUa's logs). Evidence: `docs/plans/2026-08-01-continuous-historization-live-gate.md` §"Second defect found".
dohertj2 commented 2026-08-04 12:37:06 -04:00
Author
Owner
Copy Link
Copy Source

FIXED + live-gated — e7fbe977 (fix) / 4bdce910 (gate evidence), master 4bdce910.

Took the skip-and-quarantine direction this issue listed, and left the all-or-nothing ack and the
outbox contract alone — RemoveAsync still truncates through an id, so the prefix ack stays the only safe
one. DrainOnceAsync now tracks consecutive failures per historian tag and abandons that tag's queued
entries once it exceeds the new ContinuousHistorization:MaxWriteAttempts (default 5), letting the head
advance.

⚠️ The discriminator is "did another tag write this pass?", NOT a failure count — and this is the part
worth remembering. A count-only quarantine looks identical on the poison-tag case and silently discards the
entire backlog during an ordinary gateway restart, where every tag fails, converting a
duplicate-samples bug into a lost-history one. The counter therefore only advances on a pass where some
other tag succeeded; a pass where nothing wrote abandons nothing and retains everything, exactly as
before. The load-bearing test is the falsification control
(A_backend_that_fails_every_tag_abandons_nothing), which goes red when the evidence check is removed
while the poison-tag test stays green.

Abandonment is also deferred until every failing tag in the batch is over budget, so nothing is discarded
on a pass that could not have advanced the head anyway.

Capacity also gained a non-zero default (500,000 entries) as the "bound the damage" this issue asked
for — the disk backstop for the one case the quarantine deliberately cannot resolve, a historian refusing
every write. 0 restores unbounded retention. Each abandonment logs a Warning naming the tag and the
discarded sample count; the total rides RecorderStatus.AbandonedEntries.

Live gate (2026-08-04, real gateway + real AVEVA Historian)

The poison tag was the real shape, not a synthetic fault: an existing tag's historianTagname was
changed, which Issue 5 guarantees is never provisioned.

Leg Observation
Quarantine fires historian tag OtOpcUa.Gate538.PoisonTag has failed 6 consecutive write attempts while other tags wrote successfully; discarding 1 queued sample(s) so the outbox can drain.
Head advances 5 value changes over 30s -> ok +5, error +5 — one write per tag per change, against a 2s drain interval
Idle is silent 40s with no value changes -> both counters unchanged, outbox byte size flat
Backlog On promotion, a 10-sample poison backlog cleared in one pass

⚠️ The idle leg is the decisive one and the only one that could not be faked. The driven-rate legs show
a rate that happens to look right; a pre-fix build re-writes its queued healthy entries on every drain pass
whether or not anything new arrives, so its counters climb during a quiet window with no input at all.

Incidental finding, filed against Issue 5 rather than fixed: a node restart cures an unprovisioned
tag. A full address-space rebuild at boot treats every historized tag as added and re-runs EnsureTags
(dispatched=2, requested=2, ensured=2, failed=0), where the incremental deploy that introduced the
renamed tag did not. So an operator who restarts a node while diagnosing "my tag isn't historizing" makes
the symptom disappear without learning the cause.

Evidence: docs/plans/2026-08-01-continuous-historization-live-gate.md §"Live gate for the two fixes".
Design: docs/Historian.md §"A poison tag no longer pins the outbox".

**FIXED + live-gated** — `e7fbe977` (fix) / `4bdce910` (gate evidence), master `4bdce910`. Took the **skip-and-quarantine** direction this issue listed, and left the all-or-nothing ack and the outbox contract alone — `RemoveAsync` still truncates through an id, so the prefix ack stays the only safe one. `DrainOnceAsync` now tracks consecutive failures per historian tag and abandons that tag's queued entries once it exceeds the new `ContinuousHistorization:MaxWriteAttempts` (default 5), letting the head advance. ⚠️ **The discriminator is "did another tag write this pass?", NOT a failure count** — and this is the part worth remembering. A count-only quarantine looks identical on the poison-tag case and silently discards the **entire backlog during an ordinary gateway restart**, where every tag fails, converting a duplicate-samples bug into a lost-history one. The counter therefore only advances on a pass where some *other* tag succeeded; a pass where nothing wrote abandons nothing and retains everything, exactly as before. The load-bearing test is the falsification control (`A_backend_that_fails_every_tag_abandons_nothing`), which goes red when the evidence check is removed while the poison-tag test stays green. Abandonment is also deferred until *every* failing tag in the batch is over budget, so nothing is discarded on a pass that could not have advanced the head anyway. `Capacity` also gained a non-zero default (**500,000** entries) as the "bound the damage" this issue asked for — the disk backstop for the one case the quarantine deliberately cannot resolve, a historian refusing every write. `0` restores unbounded retention. Each abandonment logs a Warning naming the tag and the discarded sample count; the total rides `RecorderStatus.AbandonedEntries`. ### Live gate (2026-08-04, real gateway + real AVEVA Historian) The poison tag was the **real shape, not a synthetic fault**: an existing tag's `historianTagname` was *changed*, which Issue 5 guarantees is never provisioned. | Leg | Observation | |---|---| | Quarantine fires | `historian tag OtOpcUa.Gate538.PoisonTag has failed 6 consecutive write attempts while other tags wrote successfully; discarding 1 queued sample(s) so the outbox can drain.` | | Head advances | 5 value changes over 30s -> `ok` **+5**, `error` **+5** — one write per tag per change, against a 2s drain interval | | **Idle is silent** | 40s with no value changes -> both counters unchanged, outbox byte size flat | | Backlog | On promotion, a 10-sample poison backlog cleared in one pass | ⚠️ **The idle leg is the decisive one and the only one that could not be faked.** The driven-rate legs show a rate that happens to look right; a pre-fix build re-writes its queued healthy entries on every drain pass **whether or not anything new arrives**, so its counters climb during a quiet window with no input at all. **Incidental finding, filed against Issue 5 rather than fixed:** a node **restart cures** an unprovisioned tag. A full address-space rebuild at boot treats every historized tag as *added* and re-runs `EnsureTags` (`dispatched=2, requested=2, ensured=2, failed=0`), where the incremental deploy that introduced the renamed tag did not. So an operator who restarts a node while diagnosing "my tag isn't historizing" makes the symptom disappear without learning the cause. Evidence: `docs/plans/2026-08-01-continuous-historization-live-gate.md` §"Live gate for the two fixes". Design: `docs/Historian.md` §"A poison tag no longer pins the outbox".
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
auto-managed
queue management
 cross-driver
queue management
 driver/abcip
queue management
 driver/ablegacy
queue management
 driver/focas
queue management
 driver/mqtt
MQTT / Sparkplug B broker-subscribe driver
 driver/opcuaclient
queue management
 driver/s7
queue management
 driver/twincat
queue management
 phase/1
queue management
 phase/2
queue management
 phase/3
queue management
 phase/4
queue management
 phase/5
queue management
 phase/6
queue management
 queue/blocked
queue management
 queue/done
queue management
 queue/failed
queue management
 queue/in-progress
queue management
 queue/queued
queue management
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
dohertj2 (dohertj2)
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dohertj2/lmxopcua#538
Delete Branch "%!s()"

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?