docs(historian): live gate for #537 and #538 — both PASSED
v2-ci / build (push) Successful in 4m29s
v2-ci / unit-tests (push) Failing after 17m6s

Ran on the docker-dev central pair against the local HistorianGateway container talking to the real
AVEVA Historian on wonder-sql-vd03 (VPN up), with the host image rebuilt at e7fbe977.

Two things about the setup matter more than the results:

The value source had to be DRIVEN. Both the project Modbus fixture and oee-modbus-sim hold static
registers, and a static source produces no dependency-mux fan-out at all — the recorder captures
once at deploy and then goes quiet, which reads exactly like a broken recorder. Hand-written
Modbus FC6 writes put the value stream under the gate's control, which is what makes the rate
measurements below mean anything. The project fixture was also brought back up on the docker host
and MAIN-modbus-dev repointed to it, undoing the temporary :1502 repoint the read-back leg made.

The poison tag is the real shape, not a synthetic fault: GATE491-B's historianTagname was CHANGED
on an EXISTING tag, which Issue 5 guarantees is never provisioned, so its writes fail permanently
against a historian that has no such tag. That is how #538 was reached in the first place.

#537 — both nodes up: the Secondary logged the suppression line once and its outbox file froze
while the Primary's kept growing; 6 value changes x 2 tags gave WriteLiveValues{ok} +12 exactly,
where the pre-fix measurement was twice that. Failover: stopping the Primary made the survivor log
"now the recording Primary ... resuming value capture" and pick up every subsequent change. Return:
the restarted node was demoted, logged suppression, and the rate stayed at one node.

#538 — the quarantine fired with the tag named; 5 value changes over 30s gave ok +5 and error +5,
exactly one write per tag per change against a 2s drain interval.

The decisive leg is the IDLE one: 40s with no value changes left both counters unchanged and the
outbox byte size flat. The driven-rate legs only 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. Flat counters over idle is the
observation the bug cannot produce.

Incidental finding, recorded against Issue 5 rather than treated as a fix: a node RESTART cures an
unprovisioned tag. central-2's boot logged provisioning (dispatched=2, requested=2, ensured=2,
failed=0) and the poison tag started succeeding, because a full address-space rebuild treats every
historized tag as added and re-runs EnsureTags — 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.

Docs only; no production code changed.

Claude-Session: https://claude.ai/code/session_015p7wGqy3YpZNCpDzTpGMKo
This commit is contained in:
Joseph Doherty
2026-08-04 12:36:19 -04:00
parent e7fbe97759
commit 4bdce91002
2 changed files with 81 additions and 3 deletions
+2 -2
View File
@@ -936,8 +936,8 @@ read-back leg ran against the licensed `wonder-sql-vd03` with the VPN up: two re
*distinct non-zero* constants (`8224`, `120`) each read back as its own value — a `0`-valued source *distinct non-zero* constants (`8224`, `120`) each read back as its own value — a `0`-valued source
would have proved nothing (the #536 trap). would have proved nothing (the #536 trap).
**Both gate findings are now CLOSED — #537 (Primary gate) and #538 (poison tag). Two things to know **Both gate findings are now CLOSED and separately live-gated — #537 (Primary gate) and #538 (poison
before touching either.** tag); evidence in the same plan doc. Two things to know before touching either.**
- **#538 — the discriminator is "did another tag write this pass?", NOT a failure count.** `DrainOnceAsync` - **#538 — the discriminator is "did another tag write this pass?", NOT a failure count.** `DrainOnceAsync`
writes every per-tag group and acks **all-or-nothing** (deliberate: `RemoveAsync` truncates *through* an writes every per-tag group and acks **all-or-nothing** (deliberate: `RemoveAsync` truncates *through* an
@@ -2,7 +2,8 @@
**Date:** 2026-08-01, completed 2026-08-04 · **Rig:** `docker-dev` central pair + a real **Date:** 2026-08-01, completed 2026-08-04 · **Rig:** `docker-dev` central pair + a real
`ZB.MOM.WW.HistorianGateway` against a real AVEVA Historian · **Outcome: BOTH LEGS CLOSED.** The gate `ZB.MOM.WW.HistorianGateway` against a real AVEVA Historian · **Outcome: BOTH LEGS CLOSED.** The gate
found and fixed a **production-fatal defect**, and surfaced a second (unfixed, filed) one. found and fixed a **production-fatal defect**, and surfaced two more (#537, #538) — both since fixed and
live-gated in turn; see §"Live gate for the two fixes" at the end of this document.
> **2026-08-04 update — the gate is complete.** The 2026-08-01 run closed everything except the > **2026-08-04 update — the gate is complete.** The 2026-08-01 run closed everything except the
> read-back hop, which was blocked by the only historian reachable that day (a licence violation) and > read-back hop, which was blocked by the only historian reachable that day (a licence violation) and
@@ -245,6 +246,12 @@ acceptable (the historian may fold same-timestamp samples) or whether the record
gate is a **design decision that has not been made** — recorded here rather than silently "fixed", gate is a **design decision that has not been made** — recorded here rather than silently "fixed",
because gating it would also mean a failover window with no capture at all. because gating it would also mean a failover window with no capture at all.
> **Resolved (2026-08-04, #537).** The decision went to gating the **capture**, not the drain — the
> reverse of what this paragraph anticipated, because the historization outbox is node-local and
> replicates to nobody, so a drain-only gate leaves the standby's queue growing forever with no one to
> empty it. The failover window is real and accepted; it is bounded by the promoted node's first
> redundancy snapshot, and the live gate below exercises it. See §"Live gate for the two fixes".
## Follow-ups ## Follow-ups
- **#491 CLOSED** 2026-08-04 — both legs proven. - **#491 CLOSED** 2026-08-04 — both legs proven.
@@ -260,3 +267,74 @@ because gating it would also mean a failover window with no capture at all.
no longer pins the outbox". no longer pins the outbox".
- Still open from before this gate: `EnsureTags` fires only for newly-*added* historized tags - Still open from before this gate: `EnsureTags` fires only for newly-*added* historized tags
(`2026-06-27-historian-gateway-integration-issues.md` Issue 5) — re-confirmed live here. (`2026-06-27-historian-gateway-integration-issues.md` Issue 5) — re-confirmed live here.
---
# Live gate for the two fixes (#537, #538) — 2026-08-04, PASSED
Run against the same rig as the read-back leg, with `otopcua-host:dev` rebuilt at `e7fbe977`.
**Rig.** docker-dev central pair (both `admin,driver,cluster-MAIN`), `ContinuousHistorization__Enabled=true`
on both; local `zb-historiangw` container against the real AVEVA Historian on `wonder-sql-vd03` (VPN up).
**Source.** The project's own Modbus fixture, brought back up
(`ssh dohertj2@10.100.0.35 'cd /opt/otopcua-modbus && docker compose --profile standard up -d'`) and driven
by hand-written **Modbus FC6 writes** so the value stream is under the gate's control rather than the
fixture's. Both the project fixture and `oee-modbus-sim` hold *static* registers, and a static source
produces no mux fan-out at all — the recorder captures once at deploy and then nothing, which reads exactly
like a broken recorder. Driving the registers is what makes the rate measurements below mean anything.
`MAIN-modbus-dev` was repointed back to `10.100.0.35:5020`, undoing the temporary `:1502` repoint the
read-back leg made while the fixture was down.
**The poison tag is the real shape, not a synthetic fault.** `GATE491-B`'s `historianTagname` was *changed*
on an *existing* tag to `OtOpcUa.Gate538.PoisonTag`. Issue 5 guarantees a changed name is never provisioned,
so its writes fail permanently against a historian that has no such tag — which is how #538 was reached in
the first place. `GATE491-A` kept `OtOpcUa.Gate491.RegA` (already provisioned) as the healthy tag.
## #537 — only the recording Primary captures
| Leg | Observation |
|---|---|
| Both nodes up | central-1 (Secondary) logged, **once**, `ContinuousHistorization: this node is not the recording Primary for its address space; suppressing value capture…`. Its outbox file froze at its 16:15 size while central-2's kept growing. |
| Steady state | 6 value changes × 2 historized tags → gateway `WriteLiveValues{ok}` **+12 exactly**. Pre-fix this was +24 (measured on the #491 gate as "twice per value, halving when one central stopped"). |
| Failover | central-2 stopped → central-1 logged `…this node is now the recording Primary…; resuming value capture` and captured every subsequent change. |
| Return | central-2 restarted → demoted, logged the suppression line; 5 changes → `ok` **+10**, still one node. |
The failover leg is the one worth keeping: gating the *capture* is only defensible if promotion resumes it
promptly, and the gate is read per value rather than latched precisely so it does.
## #538 — a poison tag no longer pins the head
| Leg | Observation |
|---|---|
| Quarantine fires | `ContinuousHistorization: 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** and `error` **+5**: exactly one write per tag per change, against a **2 s** drain interval. Pre-fix the healthy tag's entries were re-submitted on every pass. |
| **Idle is silent** | 40 s with **no** value changes → `ok` and `error` both unchanged, outbox byte size flat. |
| Backlog | On promotion, central-1 cleared a 10-sample poison backlog in a single pass (`discarding 10 queued sample(s)`). |
⚠️ **The idle leg is the decisive one, and it is the only one that could not be faked.** The driven-rate
legs show a *rate* that happens to look right; a pre-fix build with a pinned head 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. Flat counters over 40 idle seconds is the observation the bug cannot
produce.
## Incidental finding — a node restart cures an unprovisioned tag
central-2's restart logged `AddressSpaceApplier: historian provisioning completed (dispatched=2,
requested=2, ensured=2, skipped=0, failed=0)` and the poison tag **started succeeding** — `error` stopped
moving from that point. A full address-space rebuild at boot treats every historized tag as *added*, so it
re-runs `EnsureTags` over the whole set, where the incremental deploy that introduced the renamed tag did
not (`changed=3`, no provisioning line).
So **restarting the node is a usable workaround for Issue 5**: a changed `historianTagname` is never
provisioned by the deploy that changes it, but is by the next boot. Recorded against Issue 5 rather than
treated as a fix — it is a side effect of the rebuild path, not a deliberate behaviour, and it means an
operator who restarts a node while diagnosing "my tag isn't historizing" makes the symptom disappear
without learning the cause.
## Rig state left behind
The gate config is still in place: `GATE491-A`/`GATE491-B` on HR5/HR6 of the project fixture, the latter
still named `OtOpcUa.Gate538.PoisonTag` (now provisioned, so no longer poison), `MAIN-modbus-hr200` /
`MAIN-modbus-gate491` de-historized onto HR7, and both centrals running with historization enabled against
the local gateway container.