From ad744734527defb6e3932ed2e51d3ecfb9cba46c Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sat, 1 Aug 2026 19:57:37 -0400 Subject: [PATCH] =?UTF-8?q?fix(historian):=20the=20recorder=20died=20on=20?= =?UTF-8?q?its=20first=20value=20=E2=80=94=20live=20gate=20for=20continuou?= =?UTF-8?q?s=20historization=20(#491)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- CLAUDE.md | 34 +++- docker-dev/docker-compose.yml | 26 ++- docs/Historian.md | 30 ++- ...8-01-continuous-historization-live-gate.md | 186 ++++++++++++++++++ .../ContinuousHistorizationRecorder.cs | 20 +- .../ContinuousHistorizationRecorderTests.cs | 94 ++++++++- 6 files changed, 369 insertions(+), 21 deletions(-) create mode 100644 docs/plans/2026-08-01-continuous-historization-live-gate.md diff --git a/CLAUDE.md b/CLAUDE.md index b17bf8ee..2858c492 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -906,8 +906,32 @@ later at deploy time, not at actor-spawn time. **The ref-feed gap is now closed: through `ActorHistorizedTagSubscriptionSink` → the recorder's `UpdateHistorizedRefs` message, and the recorder keeps the full set and re-registers its dependency-mux interest. So the recorder converges to the deployed set of historized value tags from the first deploy onward (the feed is a non-blocking, deploy-safe -`Tell`; a faulting feed can never break a deploy). **Reads and alarm-writes work today, and the value-capture -path is code-complete.** What remains is the **live gate**: an end-to-end verification against a real gateway -(deploy → dependency-mux value delta → outbox append → `WriteLiveValues`) plus a restart-convergence test -proving the recorder re-registers the deployed set after a process restart. Until that live verification runs, -treat continuous value-capture as unproven-in-production rather than absent. Tracked as **issue #491**. +`Tell`; a faulting feed can never break a deploy). + +**The live gate RAN 2026-08-01 against a real HistorianGateway + a real AVEVA Historian, and it found a +production-fatal defect** — see `docs/plans/2026-08-01-continuous-historization-live-gate.md`. Three things +to know: + +- ⚠️ **`ConfigureAwait(false)` in an Akka handler destroys `Self`.** `OnValueChangedAsync` touched `Self` + after awaiting `IHistorizationOutbox.AppendAsync(...).ConfigureAwait(false)`, which discards Akka's + `ActorTaskScheduler` synchronization context — so `ActorBase.Context` was gone and it threw + `NotSupportedException` on the FIRST value. The throw reached supervision, the actor **restarted**, and + because production seeds an **empty** ref set the restart discarded every historized ref: one value + captured, then silence. Fixed by capturing `IActorRef self = Self` before the await (the idiom the + `GetStatus` handler already used for `Sender`). +- ⚠️ **A fake that completes synchronously hides this entire class of bug**, and 13 tests passed because + of one. `ValueTask.CompletedTask` never yields, so the continuation ran inline with the context intact. + Worse, the obvious fix to the fake — `await Task.Yield()` — is *also* vacuous: `Yield()` posts back to + the captured context, so the caller still resumes on the actor thread. The fake must complete on a + **pool** thread (`await Task.Delay(1).ConfigureAwait(false)`), as a real per-entry fsync does. Only + reverting the production fix exposed that the first regression test proved nothing. +- **Both pair nodes historize the same value** — the recorder has **no Primary gate**, unlike the alarm + store-and-forward sink. A redundant pair therefore sends duplicate live values per historized tag. + Deliberately recorded, not "fixed": gating it introduces a failover window with no capture. + +Gate status: outbox append, drain, `WriteLiveValues` **accepted by a real historian**, and +**restart-convergence** are all ✅. The final **read-back** hop is ❌ **not** proven — the LAN historian +(`10.100.0.48`) accepts writes but serves no reads under a `License violation: Database tag count exceeds +license tag count`, and the licensed `wonder-sql-vd03` needs the VPN. `EnsureTags` provisioning likewise +could not run there (it is `RemoteGrpc`-only and that CAP is not listening). **Issue #491 stays open for +the read-back hop alone**; treat the rest of continuous value-capture as live-proven. diff --git a/docker-dev/docker-compose.yml b/docker-dev/docker-compose.yml index 924f1bfb..d24e64a6 100644 --- a/docker-dev/docker-compose.yml +++ b/docker-dev/docker-compose.yml @@ -374,8 +374,23 @@ services: ServerHistorian__Enabled: "${OTOPCUA_HISTORIAN_ENABLED:-false}" ServerHistorian__Endpoint: "${OTOPCUA_HISTORIAN_ENDPOINT:-}" ServerHistorian__ApiKey: "${ServerHistorian__ApiKey:-}" - ServerHistorian__UseTls: "true" + # UseTls must match the Endpoint scheme (http:// = h2c ⇒ false). Parameterized because a + # locally-run gateway is usually plaintext h2c while a deployed one is https. + ServerHistorian__UseTls: "${OTOPCUA_HISTORIAN_USETLS:-true}" ServerHistorian__AllowUntrustedServerCertificate: "true" + # Continuous historization of driver tag values (Gitea #491's live gate). Gated on BOTH + # ContinuousHistorization:Enabled AND ServerHistorian:Enabled — with either off no recorder is + # spawned, so this stays inert on the default rig. OutboxPath is the FasterLog crash boundary and + # points at the per-node named volume so the outbox survives a container recreate (that durability + # is exactly what the restart-convergence leg of the gate exercises). + # To run the gate: + # OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_ENDPOINT=http://:5221 \ + # OTOPCUA_HISTORIAN_USETLS=false OTOPCUA_CONTHIST_ENABLED=true \ + # docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2 + ContinuousHistorization__Enabled: "${OTOPCUA_CONTHIST_ENABLED:-false}" + ContinuousHistorization__OutboxPath: "/app/data/historization-outbox" + ContinuousHistorization__CommitMode: "${OTOPCUA_CONTHIST_COMMITMODE:-PerEntry}" + ContinuousHistorization__DrainIntervalSeconds: "${OTOPCUA_CONTHIST_DRAIN_SECONDS:-2}" # Pin EF Core + ASP.NET Core to Warning so the per-poll Deployment SELECT / # "Executed DbCommand" Information|Debug lines stop flooding the Serilog # pipeline and starving the Akka cluster heartbeat thread. The host logs via @@ -478,8 +493,15 @@ services: ServerHistorian__Enabled: "${OTOPCUA_HISTORIAN_ENABLED:-false}" ServerHistorian__Endpoint: "${OTOPCUA_HISTORIAN_ENDPOINT:-}" ServerHistorian__ApiKey: "${ServerHistorian__ApiKey:-}" - ServerHistorian__UseTls: "true" + ServerHistorian__UseTls: "${OTOPCUA_HISTORIAN_USETLS:-true}" ServerHistorian__AllowUntrustedServerCertificate: "true" + # Continuous historization — see central-1 for the full note + the gate recipe. Both centrals + # carry it so the pair is symmetric; :9200 round-robins them, and the recorder must exist on + # whichever node holds the drivers. + ContinuousHistorization__Enabled: "${OTOPCUA_CONTHIST_ENABLED:-false}" + ContinuousHistorization__OutboxPath: "/app/data/historization-outbox" + ContinuousHistorization__CommitMode: "${OTOPCUA_CONTHIST_COMMITMODE:-PerEntry}" + ContinuousHistorization__DrainIntervalSeconds: "${OTOPCUA_CONTHIST_DRAIN_SECONDS:-2}" # Quiet EF/AspNetCore SQL flood — see central-1 (Serilog override). mem_limit/ # mem_reservation are inherited from the *otopcua-host anchor. Serilog__MinimumLevel__Override__Microsoft.EntityFrameworkCore: "Warning" diff --git a/docs/Historian.md b/docs/Historian.md index 2a367bc2..1ee6935d 100644 --- a/docs/Historian.md +++ b/docs/Historian.md @@ -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 diff --git a/docs/plans/2026-08-01-continuous-historization-live-gate.md b/docs/plans/2026-08-01-continuous-historization-live-gate.md new file mode 100644 index 00000000..fdc7cc91 --- /dev/null +++ b/docs/plans/2026-08-01-continuous-historization-live-gate.md @@ -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). diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Historian/ContinuousHistorizationRecorder.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Historian/ContinuousHistorizationRecorder.cs index 3815e952..1bd11017 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Historian/ContinuousHistorizationRecorder.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Historian/ContinuousHistorizationRecorder.cs @@ -247,6 +247,21 @@ public sealed class ContinuousHistorizationRecorder : ReceiveActor, IWithTimers var timestampUtc = DateTime.SpecifyKind(msg.TimestampUtc, DateTimeKind.Utc); + // Capture Self BEFORE the first await. Self reads ActorBase.Context, and the awaits below use + // ConfigureAwait(false) — which drops Akka's ActorTaskScheduler synchronization context, so any + // continuation that actually resumes off the actor thread finds NO ActorContext and throws + // NotSupportedException. This is the same idiom the GetStatus handler already applies to Sender. + // + // It only bites when the append genuinely YIELDS: the production FasterLog outbox fsyncs per entry + // (PerEntry commit mode), so it does; a fake outbox returning ValueTask.CompletedTask completes + // synchronously, the continuation runs inline with the context still installed, and the bug is + // invisible. That is exactly how it reached production — see the yielding fake in + // ContinuousHistorizationRecorderTests. Live-caught on the docker-dev rig (Gitea #491), where the + // throw escaped the handler into supervision: the actor restarted, and because production seeds an + // EMPTY ref set (the deployed set arrives later via UpdateHistorizedRefs), the restart silently + // dropped every historized ref — so historization stopped dead after the FIRST value. + IActorRef self = Self; + // One outbox entry PER historian name: a single mux fan-out must reach every aliased historized tag // (each its own historian name), not just one — collapsing to one name here would silently drop the // rest. Snapshot the names first: although the mailbox is suspended across the awaits below (so the @@ -290,8 +305,9 @@ public sealed class ContinuousHistorizationRecorder : ReceiveActor, IWithTimers } // Nudge a prompt drain attempt; the DrainTick handler de-dups (already draining) and honours - // any active backoff window, so this never bypasses a failure cooldown. - Self.Tell(DrainTick.Instance); + // any active backoff window, so this never bypasses a failure cooldown. Uses the pre-await + // capture, never `Self` — see the note above. + self.Tell(DrainTick.Instance); } /// diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs index b665e221..c0614e95 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs @@ -338,6 +338,54 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit Assert.Empty(writer.Snapshot()); } + /// + /// An append that genuinely YIELDS must not kill the recorder (Gitea #491, live-caught). + /// + /// The handler awaits IHistorizationOutbox.AppendAsync with ConfigureAwait(false), + /// which discards Akka's ActorTaskScheduler synchronization context. Touching Self after + /// that await therefore reads ActorBase.Context with no context installed and throws + /// — which escapes into supervision and RESTARTS the actor. + /// Production seeds an empty ref set (the deployed set arrives later via + /// ), so a restart silently + /// discards every historized ref and historization stops after the FIRST value. + /// + /// + /// The yield is the whole point: every other test here uses an outbox that returns + /// ValueTask.CompletedTask, so the continuation runs inline with the context still + /// installed and the defect is invisible. The production FasterLog outbox fsyncs per entry. + /// + /// + [Fact] + public async Task A_yielding_append_neither_faults_the_actor_nor_loses_the_value() + { + var mux = CreateTestProbe(); + var writer = new FakeValueWriter(); + var outbox = new InMemoryOutbox(yieldOnAppend: true); + + IActorRef rec = Sys.ActorOf(ContinuousHistorizationRecorder.Props( + mux.Ref, writer, outbox, historizedRefs: new[] { "Pump1.Temp" }, + drainInterval: TimeSpan.FromMilliseconds(200))); + mux.ExpectMsg(); + + var stamp = new DateTime(2026, 8, 1, 12, 0, 0, DateTimeKind.Utc); + rec.Tell(new VirtualTagActor.DependencyValueChanged("Pump1.Temp", 42.5, stamp)); + + // The value reaches the writer... + await AwaitAssertAsync(() => + { + Assert.Single(writer.Snapshot()); + return Task.CompletedTask; + }); + + // ...and — the load-bearing half — the actor is still the SAME incarnation, holding the ref set + // it was seeded with. A restart would reset TotalRecorded to 0 and re-register interest, so this + // assertion is what goes red when Self is touched after the await. + var status = await rec.Ask( + ContinuousHistorizationRecorder.GetStatus.Instance, TimeSpan.FromSeconds(3)); + Assert.Equal(1, status.TotalRecorded); + mux.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); // no PreStart re-register == no restart + } + /// In-memory double: records every value written and /// returns as the ack. Thread-safe — the recorder drains off the actor thread. private sealed class FakeValueWriter : IHistorianValueWriter @@ -403,7 +451,24 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit private readonly int _capacity; private long _dropped; - public InMemoryOutbox(int capacity = 0) => _capacity = capacity; + private readonly bool _yieldOnAppend; + + /// Drop-oldest capacity; 0 means unbounded. + /// + /// When true, genuinely yields before recording the entry — + /// modelling the production FasterLogHistorizationOutbox, which fsyncs per entry under + /// PerEntry commit mode. This matters because the recorder awaits the append with + /// ConfigureAwait(false): only a real yield resumes the continuation OFF the actor + /// thread, where Akka's ActorContext is gone. The default (false) returns + /// ValueTask.CompletedTask, so the continuation runs inline with the context still + /// installed — which is why every test here passed against a recorder that threw on the very + /// first value in production. + /// + public InMemoryOutbox(int capacity = 0, bool yieldOnAppend = false) + { + _capacity = capacity; + _yieldOnAppend = yieldOnAppend; + } public long DroppedCount { @@ -417,6 +482,31 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit } public ValueTask AppendAsync(HistorizationOutboxEntry entry, CancellationToken ct) + { + if (_yieldOnAppend) + { + return AppendYieldingAsync(entry); + } + + AppendCore(entry); + return ValueTask.CompletedTask; + } + + private async ValueTask AppendYieldingAsync(HistorizationOutboxEntry entry) + { + // Must complete on a POOL thread, carrying no synchronization context — that is what a real + // per-entry fsync does, and it is what strips the ActorContext from the caller's + // ConfigureAwait(false) continuation. + // + // A bare `await Task.Yield()` does NOT reproduce it: Yield posts back to the CAPTURED context + // (Akka's ActorTaskScheduler), so this method completes ON the actor thread, and the caller's + // ConfigureAwait(false) then resumes inline right there — with the context still installed. + // Verified by reverting the production fix and watching the test still pass. + await Task.Delay(1).ConfigureAwait(false); + AppendCore(entry); + } + + private void AppendCore(HistorizationOutboxEntry entry) { lock (_gate) { @@ -427,8 +517,6 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit _dropped++; } } - - return ValueTask.CompletedTask; } public ValueTask> PeekBatchAsync(int max, CancellationToken ct)