fix(historian): the recorder died on its first value — live gate for continuous historization (#491)
Ran #491's live gate against a real ZB.MOM.WW.HistorianGateway talking to a real AVEVA Historian, and it found a production-fatal defect on the first value it ever saw. ContinuousHistorizationRecorder.OnValueChangedAsync touched `Self` after awaiting IHistorizationOutbox.AppendAsync(...).ConfigureAwait(false). ConfigureAwait(false) discards Akka's ActorTaskScheduler synchronization context, so `Self` — which reads ActorBase.Context — threw NotSupportedException. The throw escaped into supervision, which RESTARTED the actor; 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. Fixed by capturing `IActorRef self = Self` before the await — the idiom the GetStatus handler already applied to Sender. Thirteen unit tests missed it because InMemoryOutbox.AppendAsync returned ValueTask.CompletedTask: a completed ValueTask never yields, so the continuation ran inline with the context still installed. The production FasterLog outbox fsyncs per entry and does yield. The first regression test was itself vacuous — `await Task.Yield()` posts back to the CAPTURED context, so the append still completed on the actor thread and reverting the fix left the test green. The fake must complete on a POOL thread (Task.Delay(1).ConfigureAwait(false)), as a real fsync does; with that, reverting the fix reddens exactly one test. The rig could not run this gate at all: docker-dev carried ServerHistorian__* but no ContinuousHistorization__* keys, so the recorder could never spawn. Both centrals now carry them (default OFF — the recorder needs ContinuousHistorization:Enabled AND ServerHistorian:Enabled), with the outbox on the per-node named volume so it survives a container recreate. ServerHistorian__UseTls was hard-coded true and is now parameterized; a plaintext h2c gateway was unreachable without it. Gate results: outbox append, drain, WriteLiveValues accepted by a real historian, and restart convergence (capture resumes after a restart with no new deployment) all pass. The read-back hop is NOT proven — the LAN historian accepts writes but serves no reads under a "License violation: Database tag count exceeds license tag count", and the licensed corporate one needs the VPN. EnsureTags provisioning is likewise unexercised there (RemoteGrpc-only, and that CAP is not listening). #491 stays open for the read-back hop alone. Also recorded, not fixed: the recorder has NO Primary gate, unlike the alarm store-and-forward sink, so both nodes of a redundant pair send duplicate live values. Gating it would introduce a failover window with no capture — that is a design decision, not a cleanup. Evidence: docs/plans/2026-08-01-continuous-historization-live-gate.md Claude-Session: https://claude.ai/code/session_015p7wGqy3YpZNCpDzTpGMKo
This commit is contained in:
+21
-9
@@ -114,15 +114,27 @@ source it from there.
|
||||
> hardcodes OPC-DA Good, `192`). Capturing real per-node quality will not persist until the gateway honors
|
||||
> the field — see `GatewayHistorianValueWriter`'s remarks (archreview 06/C-7).
|
||||
|
||||
> ⚠️ **Continuous value capture is code-complete but UNPROVEN IN PRODUCTION
|
||||
> ([#491](https://gitea.dohertylan.com/dohertj2/lmxopcua/issues/491)).** The recorder, the FasterLog
|
||||
> outbox, the gateway value-writer and the deploy-time historized-ref feed
|
||||
> (`AddressSpaceApplier.FeedHistorizedRefs` → `ActorHistorizedTagSubscriptionSink` →
|
||||
> `ContinuousHistorizationRecorder.UpdateHistorizedRefs`) are all wired, and the recorder converges to
|
||||
> the deployed ref set from the first deploy onward. What has **not** run is the end-to-end live gate
|
||||
> (deploy → dependency-mux value delta → outbox append → `WriteLiveValues`) plus a restart-convergence
|
||||
> test. **Reads and alarm-writes are live-validated; treat value capture as unproven rather than
|
||||
> absent.** See the "KNOWN LIMITATION 2" section of `CLAUDE.md`.
|
||||
> ✅ **Continuous value capture is LIVE-PROVEN as far as the historian's door
|
||||
> ([#491](https://gitea.dohertylan.com/dohertj2/lmxopcua/issues/491), gate run 2026-08-01 — see
|
||||
> `docs/plans/2026-08-01-continuous-historization-live-gate.md`).** Against a real
|
||||
> `ZB.MOM.WW.HistorianGateway` talking to a real AVEVA Historian: deploy → dependency-mux value delta →
|
||||
> FasterLog outbox append → drain → `WriteLiveValues` **accepted**, and **restart convergence** (the
|
||||
> recorder re-registers the deployed ref set after a process restart, with no new deployment) both pass.
|
||||
>
|
||||
> ⚠️ The gate found a **production-fatal defect**: the recorder threw `NotSupportedException` on the
|
||||
> **first value it ever appended**, because it touched `Self` after an `await …ConfigureAwait(false)`,
|
||||
> which discards Akka's ActorContext. Supervision restarted the actor, and since the recorder is seeded
|
||||
> with an *empty* ref set, the restart discarded every historized ref — historization stopped after one
|
||||
> value. Fixed; pinned by a regression test whose outbox fake completes on a **pool** thread (a fake
|
||||
> returning `ValueTask.CompletedTask`, or even `await Task.Yield()`, cannot reproduce it).
|
||||
>
|
||||
> ❌ **Still unproven: the read-back hop** — no available historian can serve it today (the LAN instance
|
||||
> accepts writes but serves no reads under a licence tag-count violation; the licensed corporate one needs
|
||||
> the VPN). `EnsureTags` provisioning is likewise unexercised there (`RemoteGrpc`-only). **#491 stays open
|
||||
> for that hop alone.**
|
||||
>
|
||||
> ⚠️ **Both nodes of a redundant pair historize the same value** — the recorder has no Primary gate,
|
||||
> unlike the alarm store-and-forward sink, so the historian receives duplicate live values per tag.
|
||||
>
|
||||
> **Related, separately open:** `EnsureTags` provisioning fires only for **newly-added** historized
|
||||
> tags (`AddressSpaceApplier` iterates the added set), so flipping an **existing** tag to
|
||||
|
||||
@@ -0,0 +1,186 @@
|
||||
# Continuous-historization live gate (Gitea #491)
|
||||
|
||||
**Date:** 2026-08-01 · **Rig:** `docker-dev` central pair + a real `ZB.MOM.WW.HistorianGateway`
|
||||
against a real AVEVA Historian · **Outcome:** the gate found and fixed a **production-fatal defect**;
|
||||
leg 2 CLOSED, leg 1 closed up to the historian's acceptance of the write, with the final read-back
|
||||
hop blocked by the historian instance (not by OtOpcUa).
|
||||
|
||||
## 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:
|
||||
|
||||
```bash
|
||||
# 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:**
|
||||
|
||||
```bash
|
||||
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:
|
||||
|
||||
```bash
|
||||
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 | ❌ blocked — see below |
|
||||
| **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.
|
||||
|
||||
## What is still not proven, and why
|
||||
|
||||
**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.
|
||||
|
||||
## Follow-ups
|
||||
|
||||
- **#491 stays open** for the read-back hop only, to be closed by re-running the gate against
|
||||
`wonder-sql-vd03` on the VPN (the `HISTGW_*` live-suite recipe in `CLAUDE.md` still applies).
|
||||
- File the Primary-gate question for the recorder (secondary finding above).
|
||||
Reference in New Issue
Block a user