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

test(historian): live end-to-end gate for continuous-historization value capture #491

New Issue
Closed
opened 2026-07-21 03:36:41 -04:00 by dohertj2 · 2 comments
dohertj2 commented 2026-07-21 03:36:41 -04:00
Owner
Copy Link
Copy Source

Tracks KNOWN LIMITATION 2 in CLAUDE.md, filed so it is not carried indefinitely as a doc banner.

The ContinuousHistorizationRecorder is fully wired — actor + FasterLog outbox + gateway value-writer + meters — and the ref-feed gap is closed (2982cc4b: AddressSpaceApplier.FeedHistorizedRefs → ActorHistorizedTagSubscriptionSink → UpdateHistorizedRefs), so the recorder converges on the deployed historized set from the first deploy.

What has not been run is the live gate:

  1. End-to-end value capture against a real gateway: deploy → dependency-mux value delta → outbox append → WriteLiveValues → value readable back from the historian.
  2. Restart convergence: prove the recorder re-registers the deployed historized-ref set after a process restart (the ref set is built at deploy time, and the actor spawns with an empty initial set by design).

Until both run, treat continuous value capture as unproven in production rather than absent. Reads and alarm-writes are separately live-validated and green.

Prerequisites are the ones already documented: gateway with RuntimeDb:Enabled=true, an API key carrying historian:read + historian:write + historian:tags:write, and ContinuousHistorization:Enabled=true with an absolute OutboxPath.

Note: KNOWN LIMITATION 1 in the same CLAUDE.md section is stale — that live suite ran green (docs/plans/2026-06-27-otopcua-historian-followups.md: read ✅, write-persist ✅, alarm-send ✅, alarm-readback skipped as a confirmed protocol limitation). Being corrected separately.

Tracks **KNOWN LIMITATION 2** in `CLAUDE.md`, filed so it is not carried indefinitely as a doc banner. The `ContinuousHistorizationRecorder` is fully wired — actor + FasterLog outbox + gateway value-writer + meters — and the ref-feed gap is **closed** (`2982cc4b`: `AddressSpaceApplier.FeedHistorizedRefs` → `ActorHistorizedTagSubscriptionSink` → `UpdateHistorizedRefs`), so the recorder converges on the deployed historized set from the first deploy. What has **not** been run is the live gate: 1. **End-to-end value capture** against a real gateway: deploy → dependency-mux value delta → outbox append → `WriteLiveValues` → value readable back from the historian. 2. **Restart convergence**: prove the recorder re-registers the deployed historized-ref set after a process restart (the ref set is built at deploy time, and the actor spawns with an empty initial set by design). Until both run, treat continuous value capture as **unproven in production rather than absent**. Reads and alarm-writes are separately live-validated and green. Prerequisites are the ones already documented: gateway with `RuntimeDb:Enabled=true`, an API key carrying `historian:read` + `historian:write` + `historian:tags:write`, and `ContinuousHistorization:Enabled=true` with an absolute `OutboxPath`. Note: **KNOWN LIMITATION 1** in the same CLAUDE.md section is stale — that live suite ran green (`docs/plans/2026-06-27-otopcua-historian-followups.md`: read ✅, write-persist ✅, alarm-send ✅, alarm-readback skipped as a confirmed protocol limitation). Being corrected separately.
dohertj2 commented 2026-08-01 19:58:04 -04:00
Author
Owner
Copy Link
Copy Source

Gate run 2026-08-01 — it found a production-fatal defect. Fixed in ad744734.

Ran against a real ZB.MOM.WW.HistorianGateway talking to a real AVEVA Historian. Evidence: docs/plans/2026-08-01-continuous-historization-live-gate.md.

The defect

ContinuousHistorizationRecorder threw on the very first value it ever appended, and historization then stopped dead.

OnValueChangedAsync touched Self after await _outbox.AppendAsync(...).ConfigureAwait(false). ConfigureAwait(false) discards Akka's ActorTaskScheduler synchronization context, so Self — reading ActorBase.Context — threw NotSupportedException. The throw escaped into supervision, which restarted the actor; and because the recorder is seeded with an empty ref set (the deployed set arrives later via UpdateHistorizedRefs), the restart silently discarded every historized ref. One value captured, then silence, with no further error to show for it.

Fixed by capturing IActorRef self = Self before the await — the idiom the GetStatus handler already applied to Sender.

13 unit tests missed it because InMemoryOutbox.AppendAsync returned ValueTask.CompletedTask, which never yields, so the continuation ran inline with the context intact. The production FasterLog outbox fsyncs per entry and does yield. Worth knowing: the obvious fix to the fake — await Task.Yield() — is also vacuous, because Yield() posts back to the captured context; reverting the production fix left that test green. The fake has to complete on a pool thread.

Leg results

Leg Result
Recorder spawns + converges on the deployed ref set ✅
Driver value → dependency-mux → FasterLog outbox append ✅
Drain → WriteLiveValues accepted by the real historian ✅
Value readable back from the historian ❌
Restart convergence (leg 2) ✅

Restart convergence, with no new deployment and the partner node stopped so the counter attributes cleanly:

before restart: ok=12
[23:51:29 INF] DriverHost central-1:4053: restored served state for applied deployment d8cacd20... on bootstrap
after restart+90s: ok=19

Why this stays open

The read-back hop only. Neither historian available today can serve it:

  • The LAN historian (10.100.0.48) logs License violation: Database tag count exceeds license tag count. It accepts writes (the SQL insert succeeds and original.dat grows within seconds) but retrieval returns nothing for any tag — even its own SysTimeSec yields a single boundary row over a 5-minute wwRetrievalMode='Full' window. Environment/licensing, entirely outside OtOpcUa.
  • wonder-sql-vd03, where read/write/alarm-send were previously validated green, needs the VPN — currently down.

EnsureTags provisioning is unexercised for the same reason: it goes through OpenSessionAsync, which is RemoteGrpc-only, and that CAP is not listening on the LAN box. The gate worked around it via a historianTagname override onto a pre-existing tag. The consequence was visible and correct: the existing tag writes ok, the unprovisioned one returns Unavailable/SqlException, and its outbox entries are retained rather than dropped.

Re-running this needs only the VPN plus the recipe in the evidence doc.

Rig change

docker-dev carried ServerHistorian__* but no ContinuousHistorization__* keys at all, so the recorder could never spawn and this gate was unrunnable. Both centrals now carry them (default OFF), with the outbox on the per-node named volume. ServerHistorian__UseTls was hard-coded true and is now parameterized.

Secondary finding — filed separately below

ContinuousHistorizationRecorder has no Primary gate, unlike the alarm store-and-forward sink, so both nodes of a redundant pair send duplicate live values for every historized tag (the gateway's ok counter advances twice per value; stopping one node halves it). Recorded rather than silently changed — gating it introduces a failover window with no capture.

**Gate run 2026-08-01 — it found a production-fatal defect. Fixed in `ad744734`.** Ran against a real `ZB.MOM.WW.HistorianGateway` talking to a real AVEVA Historian. Evidence: `docs/plans/2026-08-01-continuous-historization-live-gate.md`. ### The defect `ContinuousHistorizationRecorder` **threw on the very first value it ever appended**, and historization then stopped dead. `OnValueChangedAsync` touched `Self` after `await _outbox.AppendAsync(...).ConfigureAwait(false)`. `ConfigureAwait(false)` discards Akka's `ActorTaskScheduler` synchronization context, so `Self` — reading `ActorBase.Context` — threw `NotSupportedException`. The throw escaped into supervision, which **restarted** the actor; and because the recorder is seeded with an **empty** ref set (the deployed set arrives later via `UpdateHistorizedRefs`), the restart silently discarded every historized ref. One value captured, then silence, with no further error to show for it. Fixed by capturing `IActorRef self = Self` before the await — the idiom the `GetStatus` handler already applied to `Sender`. **13 unit tests missed it** because `InMemoryOutbox.AppendAsync` returned `ValueTask.CompletedTask`, which never yields, so the continuation ran inline with the context intact. The production FasterLog outbox fsyncs per entry and does yield. Worth knowing: the obvious fix to the fake — `await Task.Yield()` — is **also** vacuous, because `Yield()` posts back to the *captured* context; reverting the production fix left that test green. The fake has to complete on a **pool** thread. ### Leg results | Leg | Result | |---|---| | Recorder spawns + converges on the deployed ref set | ✅ | | Driver value → dependency-mux → FasterLog outbox append | ✅ | | Drain → `WriteLiveValues` **accepted by the real historian** | ✅ | | Value **readable back** from the historian | ❌ | | **Restart convergence** (leg 2) | ✅ | Restart convergence, with no new deployment and the partner node stopped so the counter attributes cleanly: ``` before restart: ok=12 [23:51:29 INF] DriverHost central-1:4053: restored served state for applied deployment d8cacd20... on bootstrap after restart+90s: ok=19 ``` ### Why this stays open **The read-back hop only.** Neither historian available today can serve it: - The LAN historian (`10.100.0.48`) logs `License violation: Database tag count exceeds license tag count`. It **accepts** writes (the SQL insert succeeds and `original.dat` grows within seconds) but retrieval returns nothing for *any* tag — even its own `SysTimeSec` yields a single boundary row over a 5-minute `wwRetrievalMode='Full'` window. Environment/licensing, entirely outside OtOpcUa. - `wonder-sql-vd03`, where read/write/alarm-send were previously validated green, needs the VPN — currently down. `EnsureTags` provisioning is unexercised for the same reason: it goes through `OpenSessionAsync`, which is **`RemoteGrpc`-only**, and that CAP is not listening on the LAN box. The gate worked around it via a `historianTagname` override onto a pre-existing tag. The consequence was visible and correct: the existing tag writes `ok`, the unprovisioned one returns `Unavailable/SqlException`, and its outbox entries are **retained** rather than dropped. **Re-running this needs only the VPN** plus the recipe in the evidence doc. ### Rig change `docker-dev` carried `ServerHistorian__*` but **no `ContinuousHistorization__*` keys at all**, so the recorder could never spawn and this gate was unrunnable. Both centrals now carry them (default OFF), with the outbox on the per-node named volume. `ServerHistorian__UseTls` was hard-coded `true` and is now parameterized. ### Secondary finding — filed separately below `ContinuousHistorizationRecorder` has **no Primary gate**, unlike the alarm store-and-forward sink, so **both nodes of a redundant pair send duplicate live values** for every historized tag (the gateway's `ok` counter advances twice per value; stopping one node halves it). Recorded rather than silently changed — gating it introduces a failover window with no capture.
dohertj2 commented 2026-08-04 11:29:42 -04:00
Author
Owner
Copy Link
Copy Source

CLOSED — read-back passed against wonder-sql-vd03 with the VPN up (2026-08-04, e77ea4aa).

Both legs of this issue are now proven end-to-end, plus EnsureTags provisioning, which the 2026-08-01 attempt could not exercise at all.

EnsureTags provisioning ✅

[15:25:59 INF] AddressSpaceApplier: historian provisioning completed (dispatched=2, requested=2, ensured=2, skipped=0, failed=0)

⚠️ Re-confirmed live: provisioning fires only for newly-ADDED historized tags. Flipping an existing tag's historianTagname produced no provisioning line at all — the applier iterates the added set. That is Issue 5 of docs/plans/2026-06-27-historian-gateway-integration-issues.md, still open.

Read-back ✅

A first attempt read back 0, which proves nothing — the same trap #536 recorded ("a sim where every tag reads 0 can't distinguish a correct decode from a wrong one"). So the proof was rebuilt on two registers carrying distinct non-zero constants, where a crossed or fabricated value would be visible:

Historian tag Source Read back
OtOpcUa.Gate491.RegA Modbus HR 20 = 8224 value=8224 opcQuality=192
OtOpcUa.Gate491.RegB Modbus HR 3 = 120 value=120 opcQuality=192

Each matched its own source register. Two samples per tag per instant — one from each pair node, i.e. #537 visible again.

Full chain proven: deploy → EnsureTags → dependency-mux value delta → FasterLog outbox append → drain → WriteLiveValues → value read back out of the historian; plus restart convergence (closed 2026-08-01).

Second defect found during this run — filed as #538

DrainOnceAsync writes every per-tag group in a batch and then acks all-or-nothing, so one permanently-failing tag stops the FIFO head advancing while the healthy tags' values are re-submitted to the historian on every drain pass, indefinitely — duplicate samples, and an outbox that never truncates (Capacity defaults to 0; observed at 8.3 MB, with the gateway's ok and error counters climbing together). The all-or-nothing ack is deliberate, so the fix changes the outbox contract — filed rather than folded in here.

Recap of what this gate was actually worth

It caught a production-fatal defect (ad744734): the recorder threw on the first value it ever appended — Self touched after await …ConfigureAwait(false), which discards Akka's ActorContext — and the resulting supervision restart wiped the empty-seeded ref set, so historization stopped dead after one value. 13 unit tests missed it because the fake outbox completed synchronously; the first regression test was also vacuous (Task.Yield() posts back to the captured context) and only falsification exposed that.

Evidence: docs/plans/2026-08-01-continuous-historization-live-gate.md.

**CLOSED — read-back passed against `wonder-sql-vd03` with the VPN up (2026-08-04, `e77ea4aa`).** Both legs of this issue are now proven end-to-end, plus `EnsureTags` provisioning, which the 2026-08-01 attempt could not exercise at all. ### `EnsureTags` provisioning ✅ ``` [15:25:59 INF] AddressSpaceApplier: historian provisioning completed (dispatched=2, requested=2, ensured=2, skipped=0, failed=0) ``` ⚠️ Re-confirmed live: provisioning fires **only for newly-ADDED** historized tags. Flipping an existing tag's `historianTagname` produced *no provisioning line at all* — the applier iterates the added set. That is Issue 5 of `docs/plans/2026-06-27-historian-gateway-integration-issues.md`, still open. ### Read-back ✅ A first attempt read back `0`, which proves nothing — the same trap #536 recorded ("a sim where every tag reads 0 can't distinguish a correct decode from a wrong one"). So the proof was rebuilt on two registers carrying **distinct non-zero** constants, where a crossed or fabricated value would be visible: | Historian tag | Source | Read back | |---|---|---| | `OtOpcUa.Gate491.RegA` | Modbus HR **20** = `8224` | `value=8224 opcQuality=192` | | `OtOpcUa.Gate491.RegB` | Modbus HR **3** = `120` | `value=120 opcQuality=192` | Each matched its own source register. Two samples per tag per instant — one from each pair node, i.e. #537 visible again. Full chain proven: deploy → `EnsureTags` → dependency-mux value delta → FasterLog outbox append → drain → `WriteLiveValues` → **value read back out of the historian**; plus restart convergence (closed 2026-08-01). ### Second defect found during this run — filed as #538 `DrainOnceAsync` writes **every** per-tag group in a batch and then acks **all-or-nothing**, so one permanently-failing tag stops the FIFO head advancing while the healthy tags' values are **re-submitted to the historian on every drain pass**, indefinitely — duplicate samples, and an outbox that never truncates (`Capacity` defaults to `0`; observed at **8.3 MB**, with the gateway's `ok` and `error` counters climbing together). The all-or-nothing ack is deliberate, so the fix changes the outbox contract — filed rather than folded in here. ### Recap of what this gate was actually worth It caught a **production-fatal defect** (`ad744734`): the recorder threw on the **first value it ever appended** — `Self` touched after `await …ConfigureAwait(false)`, which discards Akka's ActorContext — and the resulting supervision restart wiped the empty-seeded ref set, so historization stopped dead after one value. 13 unit tests missed it because the fake outbox completed synchronously; the first regression test was *also* vacuous (`Task.Yield()` posts back to the captured context) and only falsification exposed that. Evidence: `docs/plans/2026-08-01-continuous-historization-live-gate.md`.
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#491
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?