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

Continuous-historization live gate (Gitea #491)

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 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 read-back hop, which was blocked by the only historian reachable that day (a licence violation) and by the VPN being down. With the VPN up, the run was repeated against the licensed wonder-sql-vd03 and read-back passed, as did EnsureTags provisioning. See §"Read-back leg (2026-08-04)". A second defect — unbounded duplicate re-writes behind one failing tag — was found during that run and filed rather than fixed.

What #491 asked for

1. End-to-end value capture — deploy → dependency-mux value delta → outbox append → WriteLiveValues → value readable back from the historian.
2. Restart convergence — the recorder re-registers the deployed historized-ref set after a process restart (it spawns with an empty initial set by design; the set arrives at deploy time).

The defect the gate found

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

OnValueChangedAsync awaited IHistorizationOutbox.AppendAsync(...) with ConfigureAwait(false) and then touched Self. ConfigureAwait(false) discards Akka's ActorTaskScheduler synchronization context, so Self — which reads ActorBase.Context — threw:

[ERR] There is no active ActorContext, this is most likely due to use of async operations from within this actor.
System.NotSupportedException: There is no active ActorContext ...
   at ZB.MOM.WW.OtOpcUa.Runtime.Historian.ContinuousHistorizationRecorder.OnValueChangedAsync(...)
      ContinuousHistorizationRecorder.cs:line 294

The throw escaped the handler into supervision, which restarted the actor — and because production seeds an empty ref set (the deployed set arrives later via UpdateHistorizedRefs), the restart silently discarded every historized ref. Net effect: one value captured, then nothing, with no further error to show for it.

Fix: capture IActorRef self = Self before the first await and use that — the same idiom the GetStatus handler already applied to Sender, whose author clearly knew the hazard for Sender and missed it for Self.

Why 13 unit tests missed it

InMemoryOutbox.AppendAsync returned ValueTask.CompletedTask. A completed ValueTask never yields, so the ConfigureAwait(false) continuation ran inline on the actor thread with the context still installed. The production FasterLogHistorizationOutbox fsyncs per entry under PerEntry commit mode, so it genuinely yields — and only then is the context gone.

⚠️ The obvious regression test was itself vacuous, and only falsification caught that. The first version of the fake used await Task.Yield(). That does not reproduce the bug: Yield() posts back to the captured context (Akka's scheduler), so AppendAsync completes on the actor thread, and the caller's ConfigureAwait(false) then resumes inline right there — context intact. Reverting the production fix left the new test green. The fake has to complete on a pool thread with no synchronization context (await Task.Delay(1).ConfigureAwait(false)), which is what a real fsync does. With that, reverting the fix turns exactly one test red.

Pinned by ContinuousHistorizationRecorderTests.A_yielding_append_neither_faults_the_actor_nor_loses_the_value.

Rig changes

docker-dev/docker-compose.yml carried ServerHistorian__* but no ContinuousHistorization__* keys at all, so the recorder could never spawn on the rig and this gate was unrunnable. Both centrals now carry them, default-OFF (the recorder needs ContinuousHistorization:Enabled and ServerHistorian:Enabled, so the default rig stays inert):

Key	Value
ContinuousHistorization__Enabled	${OTOPCUA_CONTHIST_ENABLED:-false}
ContinuousHistorization__OutboxPath	/app/data/historization-outbox (per-node named volume — survives recreate)
ContinuousHistorization__CommitMode	${OTOPCUA_CONTHIST_COMMITMODE:-PerEntry}
ContinuousHistorization__DrainIntervalSeconds	${OTOPCUA_CONTHIST_DRAIN_SECONDS:-2}

ServerHistorian__UseTls was also parameterized (${OTOPCUA_HISTORIAN_USETLS:-true}) — it was hard-coded true on both centrals, which cannot talk to a plaintext h2c gateway.

Re-running the gate

Gateway. The corporate historian (wonder-sql-vd03) needs the VPN. A second AVEVA Historian lives on the local LAN at 10.100.0.48 (DESKTOP-6JL3KKO, passwordless SSH, PowerShell default shell) and needs no VPN. Run the gateway on that box so it authenticates to the historian and to SQL with the local Windows identity — no credentials leave the machine, and no Kerberos/GSSAPI container problem:

# Publish on the Mac (the VM has no credentialed NuGet feed) and copy across:
cd ~/Desktop/HistorianGateway
dotnet publish src/ZB.MOM.WW.HistorianGateway.Server -c Release -o /tmp/histgw-pub -p:UseAppHost=false
tar czf /tmp/histgw-pub.tgz -C /tmp histgw-pub
scp /tmp/histgw-pub.tgz dohertj2@10.100.0.48:C:/Temp/histgw-pub.tgz
ssh dohertj2@10.100.0.48 'cd C:\Temp; tar xzf histgw-pub.tgz; Move-Item histgw-pub histgw'
# …then a run.cmd setting Historian__Host=localhost, RuntimeDb__Enabled/EventReadsEnabled=true with an
# Integrated Security connection string, ApiKeys__Mode=Disabled, Dashboard__DisableLogin=true, and the
# Ldap__* block (AddZbLdapAuth registers a ValidateOnStart that requires a non-empty Ldap:Server even
# when login is disabled), launched detached via Win32_Process.Create.

⚠️ The launcher script must have CRLF line endings. A batch file written on macOS with LF endings runs — @echo off and the final dotnet line execute — but the set lines silently do not take effect, so the gateway boots on appsettings.json defaults and fails with a misleading error (it crashed on the LDAP validator while every env var appeared correct in the file). This cost two debugging cycles.

Rig:

OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_ENDPOINT=http://10.100.0.48:5221 \
OTOPCUA_HISTORIAN_USETLS=false OTOPCUA_CONTHIST_ENABLED=true \
ServerHistorian__ApiKey=histgw_local_vm-gate-placeholder \
docker compose -f docker-dev/docker-compose.yml up -d --force-recreate central-1 central-2
curl -s -X POST http://localhost:9200/api/deployments -H "X-Api-Key: docker-dev-deploy-key" \
     -H "Content-Type: application/json" -d '{"createdBy":"issue-491-gate"}'

The gateway's own /metrics is the observation point — OtOpcUa logs a failed drain only as a back-off, so the honest counter lives on the gateway side:

curl -s http://10.100.0.48:5220/metrics | grep 'requests_total.*WriteLiveValues'

Results

Leg	Result
Recorder spawns + converges on the deployed ref set	✅
Driver value → dependency-mux fan-out → FasterLog outbox append	✅ hlog.log.0 + log-commits grow on both nodes
Outbox drain → WriteLiveValues accepted by the real historian	✅ gateway outcome="ok" climbs continuously
Value readable back from the historian	✅ (2026-08-04, wonder-sql-vd03 — see below)
EnsureTags provisioning	✅ (2026-08-04, ensured=2 failed=0)
Restart convergence (leg 2)	✅
No ActorContext faults on the fixed build	✅ 0 occurrences

Restart convergence evidence. With central-2 stopped (so the counter attributes to one node), central-1 was restarted with no new deployment:

before restart: ok=12
[23:51:29 INF] DriverHost central-1:4053: restored served state for applied deployment d8cacd20… on bootstrap
[23:51:29 INF] AddressSpaceApplier: historian provisioning completed (dispatched=1, requested=1, …)
after restart+90s: ok=19

The boot-time apply re-ran AddressSpaceApplier, which re-fed the historized refs through ActorHistorizedTagSubscriptionSink → UpdateHistorizedRefs, and capture resumed against a recorder that had started with an empty set. The retained outbox entries also survived the restart and drained afterwards, exercising the durable crash boundary.

Read-back leg (2026-08-04) — CLOSED

Re-run with the VPN up, against the licensed wonder-sql-vd03. The gateway ran locally in Docker from ~/Desktop/HistorianGateway/docker/ (republish first — a stale docker/publish silently ships old behaviour), reporting every readiness check Healthy including historian-connection. The rig's centrals pointed at http://host.docker.internal:5221.

EnsureTags provisioning also passed here, which the 2026-08-01 run could not exercise:

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

⚠️ 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. This is the already-known limitation in docs/plans/2026-06-27-historian-gateway-integration-issues.md Issue 5, confirmed live. The gate had to add genuinely new tags to exercise the path.

Read-back, with values chosen so a wrong answer is visible. 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"). Two registers carrying distinct non-zero constants were historized instead, so a crossed or fabricated value would show:

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 value matched its own source register — not crossed, not defaulted. Two samples per tag per instant, one from each pair node (the #537 duplicate-write finding, visible again).

Fixture note: the otopcua-modbus fixture was down; the live source used was oee-modbus-sim on 10.100.0.35:1502 (another project's stack, but a real Modbus endpoint). Its registers are static, which is why distinct constants rather than a moving value carry the proof.

Second defect found — one failing tag re-writes every healthy tag, forever (filed)

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 (here: one whose historian tag was never provisioned) means the FIFO head never advances, and every healthy tag in that batch is re-written to the historian on every drain pass — duplicate samples at the same timestamps, unboundedly, plus an outbox that never truncates. Observed: the outbox reached 8.3 MB while the failure persisted, with the gateway's ok and error counters both climbing together.

The all-or-nothing ack is deliberate and the comment explains why (RemoveAsync truncates through an id, so partial acking could drop older unwritten entries) — but the consequence is undocumented and is a real operational hazard, since Capacity defaults to 0 (unbounded). Filed, not fixed: the fix is a per-tag or non-prefix ack, which changes the outbox contract.

Update 2026-08-07 (truth sweep): filed as Gitea #538 and FIXED the same day (e7fbe977, gate record 4bdce910 — PASSED live). The drain now tracks consecutive failures per historian tag and abandons a tag's entries once past MaxWriteAttempts (default 5) so the FIFO head advances; the counter only advances on a pass where some other tag wrote successfully, which is what separates "this tag is poison" from "the backend is down" (a plain count would discard the backlog during an ordinary gateway restart). Abandonments log a Warning and ride RecorderStatus.AbandonedEntries. The same fix also gave Capacity a non-zero default (500,000 entries) as the disk backstop for the one case the quarantine deliberately cannot resolve (a historian refusing every write); 0 restores unbounded retention.

Environment notes from the 2026-08-01 run (superseded for read-back, still accurate)

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

• 10.100.0.48 logs License violation: Database tag count exceeds license tag count hourly (1780 configured analog tags against a smaller licence). It accepts writes — the SQL INSERT into Runtime.dbo.History succeeds and C:\Historian\original.dat is appended within seconds — but retrieval returns nothing, for any tag: even the historian's own SysTimeSec yields a single boundary row over a 5-minute wwRetrievalMode='Full' window. This is an environment/licensing fault, entirely outside OtOpcUa.
• wonder-sql-vd03 (the licensed corporate historian, where read/write/alarm-send were previously live-validated green) needs the VPN, which is down — its IPs 10.220.157.253 / .247 are unreachable.

EnsureTags provisioning. The hook fires and is correctly non-blocking, logging dispatched=1, requested=1, ensured=0, skipped=0, failed=1 — but it cannot succeed on this instance: EnsureTags goes through HistorianClient.OpenSessionAsync, which is RemoteGrpc-only, and the historian's gRPC Client Access Point is not listening on 10.100.0.48. Port 32565 is held by a supervised autossh remote-forward from the developer Mac (-R 32565:wonder-sql-vd03…:32565, deliberate infrastructure — do not kill it; it self-heals anyway), so the CAP process has no listening sockets at all. The gate worked around this by pointing the historized tag at a pre-existing historian tag via historianTagname, which exercises the override resolution path as a bonus.

The consequence is directly visible and is itself a correct-behaviour observation: the tag that exists writes ok, the unprovisioned one returns Unavailable/SqlException, its outbox entries are retained rather than dropped, and the drain backs off. No data loss on a failing write.

Secondary finding — both pair nodes historize the same value

ContinuousHistorizationRecorder has no Primary gate. With both centrals up, the gateway's ok counter advances twice per value; stopping central-2 halves it. So a redundant pair sends duplicate live values to the historian for every historized tag.

This contrasts with the alarm store-and-forward sink, which is Primary-gated (drainGate fed from IRedundancyRoleView) precisely so a pair does not double-deliver. Whether duplicate analog samples are acceptable (the historian may fold same-timestamp samples) or whether the recorder should take the same 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.

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

• #491 CLOSED 2026-08-04 — both legs proven.
• #537 CLOSED — the recorder now gates its capture (not its drain — the outbox is node-local and replicates to nobody, unlike the alarm queue) on PrimaryGatePolicy.ShouldRecordHistorizedValues, read per value through IHistorizationRoleView. It stands down only for a Primary that records the same refs — a partner in its own per-cluster mesh — and a node with no cluster-scoped role never stands down. See docs/Historian.md §"Only the recording Primary captures".
• #538 CLOSED — the drain now abandons a tag's queued entries after MaxWriteAttempts consecutive failures, counted only across passes where some other tag wrote successfully, so a whole-backend outage still retains everything. The all-or-nothing ack is unchanged. Capacity also gained a non-zero default (500,000) as the disk backstop for the total-outage case. See docs/Historian.md §"A poison tag no longer pins the outbox".
• 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.

---

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.