From 5fdf205caaaa812237251ebb0c4aa7b6cd18b57f Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Fri, 9 Oct 2026 15:14:46 -0400 Subject: [PATCH] test(historian): live gate PASSED on docker-dev (SqlServer backend); CLI prints node-level HistoryUpdate result Gate: Primary-only typed recording with real status, raw+UNS HistoryRead/Processed parity, HistoryUpdate insert/duplicate/replace/delete + WriteOperate-only and anonymous denied, failover at 1x, Modbus device loss stored as BadCommunicationError then a BadNoCommunication outage marker. Gate found the CLI hid the node-level refusal code (fixed + pinned) and a pre-existing OpcUaClient comms-loss gap (filed separately). docker-dev compose gains ServerHistorian__Backend / __SqlServer__ConnectionString (default Gateway). Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe --- docker-dev/docker-compose.yml | 14 ++ ...026-10-09-pluggable-historian-live-gate.md | 133 ++++++++++++++++++ .../Commands/HistoryUpdateCommand.cs | 4 + .../HistoryUpdateCommandTests.cs | 17 +++ 4 files changed, 168 insertions(+) create mode 100644 docs/plans/2026-10-09-pluggable-historian-live-gate.md diff --git a/docker-dev/docker-compose.yml b/docker-dev/docker-compose.yml index 1b8391b0..3d410597 100644 --- a/docker-dev/docker-compose.yml +++ b/docker-dev/docker-compose.yml @@ -434,6 +434,13 @@ services: # locally-run gateway is usually plaintext h2c while a deployed one is https. ServerHistorian__UseTls: "${OTOPCUA_HISTORIAN_USETLS:-true}" ServerHistorian__AllowUntrustedServerCertificate: "true" + # Backend selection (pluggable historian, 2026-10). Gateway = the HistorianGateway keys above; SqlServer = + # a plain SQL Server historian. For the rig, the `sql` container hosts it (db OtOpcUaHistorian, auto-created + # schema `hist` — create the database first): + # OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_BACKEND=SqlServer OTOPCUA_CONTHIST_ENABLED=true \ + # docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2 + ServerHistorian__Backend: "${OTOPCUA_HISTORIAN_BACKEND:-Gateway}" + ServerHistorian__SqlServer__ConnectionString: "${OTOPCUA_HISTORIAN_SQL:-Server=sql,1433;Database=OtOpcUaHistorian;User Id=sa;Password=OtOpcUa!Dev123;TrustServerCertificate=True;Encrypt=False}" # 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 @@ -560,6 +567,13 @@ services: ServerHistorian__ApiKey: "${ServerHistorian__ApiKey:-}" ServerHistorian__UseTls: "${OTOPCUA_HISTORIAN_USETLS:-true}" ServerHistorian__AllowUntrustedServerCertificate: "true" + # Backend selection (pluggable historian, 2026-10). Gateway = the HistorianGateway keys above; SqlServer = + # a plain SQL Server historian. For the rig, the `sql` container hosts it (db OtOpcUaHistorian, auto-created + # schema `hist` — create the database first): + # OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_BACKEND=SqlServer OTOPCUA_CONTHIST_ENABLED=true \ + # docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2 + ServerHistorian__Backend: "${OTOPCUA_HISTORIAN_BACKEND:-Gateway}" + ServerHistorian__SqlServer__ConnectionString: "${OTOPCUA_HISTORIAN_SQL:-Server=sql,1433;Database=OtOpcUaHistorian;User Id=sa;Password=OtOpcUa!Dev123;TrustServerCertificate=True;Encrypt=False}" # 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. diff --git a/docs/plans/2026-10-09-pluggable-historian-live-gate.md b/docs/plans/2026-10-09-pluggable-historian-live-gate.md new file mode 100644 index 00000000..3367841d --- /dev/null +++ b/docs/plans/2026-10-09-pluggable-historian-live-gate.md @@ -0,0 +1,133 @@ +# Pluggable historian — live gate (T15), 2026-10-09 + +**Verdict: PASSED.** All six legs passed on the docker-dev rig. The rig ran `feat/pluggable-historian` at +`e2011a65` (plus the gate CLI fix), with the central pair on image `923f5f09e805`, rebuilt for this gate. The SQL Server backend +pointed at the rig's `sql` container (database `OtOpcUaHistorian`). + +The gate also found two defects: +- A display gap in Client.CLI `historyupdate`. It is fixed in the same change. +- An OpcUaClient driver comms-loss gap that predates this work. It is filed separately. + +## Setup + +- `CREATE DATABASE OtOpcUaHistorian` on `otopcua-dev-sql-1`. The schema `hist` was auto-created by the + bootstrapper on first use: `SchemaVersion`, `Tag`, `Sample`, `Event`. +- `docker-dev/docker-compose.yml` gained `ServerHistorian__Backend` (`OTOPCUA_HISTORIAN_BACKEND`, default + `Gateway`) and `ServerHistorian__SqlServer__ConnectionString` (`OTOPCUA_HISTORIAN_SQL`). +- Central-1 and central-2 were started with: + + ``` + OTOPCUA_HISTORIAN_ENABLED=true OTOPCUA_HISTORIAN_BACKEND=SqlServer OTOPCUA_CONTHIST_ENABLED=true \ + docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2 + ``` + + Both containers ran the new image, with `Backend=SqlServer`. +- Cluster `MAIN` fixtures: opc-plc (`opcplc/plc/FastUInt1`, UInt32, about 1 Hz) and pymodbus `standard` + (`pymodbus/plc/HR5`). +- New Calculation String tag `Calc/eng/FastLabel` = `"v" + FastUInt1`. `FastUInt1`, `FastLabel` and later + `HR5` were marked `isHistorized`. A UNS reference `a/l/e1/FastUInt1` was added. The configuration was + deployed headlessly (`deploy.sh`), and the tags were provisioned: + - `hist.Tag` 1 = FastLabel (DataType 9, String) + - `hist.Tag` 2 = FastUInt1 (5, Int64) + - `hist.Tag` 3 = HR5 (4) +- Two data-plane API keys were minted for this gate, each with a `Cluster`-scoped grant: + - `gate-historyupdate`: ReadOnly | HistoryUpdate (4239) + - `gate-writeop`: ReadOnly | WriteOperate (159) + + ACL flag off, which is the rig default. + +## 1. Recording: Primary-only, typed, real status, one row per value + +- Rows carry real kinds and statuses: + - `ValueKind=2` Int64 `477`/`479`/…, status `0` + - `ValueKind=4` String `v477`/`v479`/…, status `0` + - startup `ValueKind=0` Empty, with `0x80320000` (BadWaitingForInitialData) and `0x80310000` +- Primary-only: + - Central-2 was the driver Primary, and its outbox held `hlog.log.0`. + - Central-1's outbox directory was empty, and it logged "this node is not the recording Primary … suppressing + value capture". +- One row per published value, checked over 82 s: + - 79 Good FastUInt1 rows and 79 Good FastLabel rows. + - All 79 pair one-to-one: same `SourceTimeUtc`, `StrValue = 'v' + IntValue`. + - 0 duplicate values. + +## 2. HistoryRead through the raw and UNS NodeIds + +These reads went to central-1 (`:4840`). Central-2's `:4841` returns "Server did not return the +certificate used to create the secure channel" to the CLI; that rig port-mapping quirk is unrelated. + +- Raw read 19:00:40–19:00:50 on `ns=2;s=opcplc/plc/FastUInt1` and on `ns=3;s=a/l/e1/FastUInt1`: + - Identical 8 rows (493…502). Only the header line differs. + - They equal the `hist.Sample` rows exactly. + - The gaps (497, 501) come from the driver's 1 s sampling of a 1 s counter. They are in the stored rows and + in the publish stream alike. +- Average at 10 s, 19:00:40–19:01:10, through both NodeIds: + - Both return `497.125 / 507.5 / 517.5`, Good. + - These equal a direct SQL `AVG` per 10 s bucket (8, 10 and 10 samples). + +## 3. HistoryUpdate + +These calls went to central-1 with `-U apikey`. Each was checked by `historyread` and by direct SQL. + +| Call | Result | Confirmed | +|---|---|---| +| insert 18:00:00 = 42 (`gate-historyupdate`) | `GoodEntryInserted` | row `42`, status 0 | +| repeat insert = 43 | `BadEntryExists`, exit 1 | row still `42` | +| replace 18:00:00 = 99 | `GoodEntryReplaced` | read and SQL show `99` | +| replace 18:00:30 (no entry) | `BadNoEntryExists` | — | +| delete-at-time 18:00:00 | `Good`, exit 0 | read returns 0 values; SQL row gone | +| insert with `gate-writeop` (WriteOperate only) | Node result `BadUserAccessDenied`, exit 1 | no row | +| insert, anonymous | Node result `BadUserAccessDenied`, exit 1 | no row | + +**Gate finding (fixed):** the CLI printed only "(no result returned)" for a refused node. The refusal +reason is in the node-level result, and the CLI never showed it. `HistoryUpdateCommand` now prints +`Node result: `, pinned by `Execute_NodeLevelDenial_PrintsNodeResult`. The rows above are from the +fixed build. + +## 4. Failover + +- 19:03:08: `docker stop` central-2, the Primary. +- 19:02:58: central-1 logged "this node is now the recording Primary … resuming value capture". It was + promoted when central-2 began leaving. Its outbox appeared, and recording continued with no gap + (633 → 644 …). +- Central-2 was restarted and rejoined as standby: + - Its `hlog.log.0` stayed frozen at 22528 bytes. + - Central-1's grew (13824 → 15360). +- Rate over the whole sequence was 1×. Per-30 s counts of FastUInt1 from 19:02:00 on: 30, 29, 29, 30, 30. There + was no doubling during or after the failover. + +## 5. Device loss: driver Bad sample and comms-loss outage marker + +This leg ran on Modbus (`HR5`), as planned. Stopping `otopcua-pymodbus-standard` at 19:09:00 produced: + +| SourceTimeUtc | ValueKind | Value | Status | +|---|---|---|---| +| 19:08:38.2408 | 2 | 5 | `0x00000000` | +| 19:09:00.2649 | 0 (Empty) | NULL | `0x80050000` BadCommunicationError (driver's own Bad publish) | +| 19:10:38.2327 | 0 (Empty) | NULL | `0x80310000` BadNoCommunication (#527 watchdog outage marker, ~98 s later) | +| 19:12:38.4474 | 2 | 5 | `0x00000000` (fixture restarted 19:12:37; recovery re-publish) | + +This confirms design §9.10 as amended: comms loss is historized as an outage marker. The plan's original +leg-6 text predated that correction. + +Reads over the outage: +- Raw `historyread` shows Bad/Good/Bad/Bad/Good. +- Average at 120 s gives `5 Uncertain` / `(null) Bad` / `5 Good`. + +The outage is visible and is not bridged. + +**Gate finding (pre-existing, filed separately):** stopping opc-plc first produced NO Bad sample. The +OpcUaClient driver kept serving `FastUInt1 = 745`, status Good, for more than 3.5 minutes. It did not +recover after opc-plc was restarted either. Its session loss never reaches the node status or driver +health, so the #527 watchdog cannot fire. This is unrelated to the historian; Modbus behaves as designed. + +## Restore + +- The rig was restored afterwards: + - central-1 and central-2 were recreated with the compose defaults (historian off). + - The gate tags, script, UNS reference, API keys and ACL rows were removed. + - The `HR5` and `FastUInt1` TagConfigs were reverted. + - The configuration was redeployed. + - `OtOpcUaHistorian` was dropped. + - The opc-plc and pymodbus fixtures were stopped (normally down). +- The compose keys stay, defaulting to `Gateway`. diff --git a/src/Client/ZB.MOM.WW.OtOpcUa.Client.CLI/Commands/HistoryUpdateCommand.cs b/src/Client/ZB.MOM.WW.OtOpcUa.Client.CLI/Commands/HistoryUpdateCommand.cs index 38a05bcc..9bf63263 100644 --- a/src/Client/ZB.MOM.WW.OtOpcUa.Client.CLI/Commands/HistoryUpdateCommand.cs +++ b/src/Client/ZB.MOM.WW.OtOpcUa.Client.CLI/Commands/HistoryUpdateCommand.cs @@ -198,6 +198,10 @@ public class HistoryUpdateCommand : CommandBase } else { + // Print the node-level result too: a node the server refuses outright (e.g. BadUserAccessDenied) + // carries its reason HERE with no per-item results, so the table alone shows only "(no result + // returned)" and hides why. + await console.Output.WriteLineAsync($"Node result: {StatusName(outcome.ResultStatus[0])}"); failed |= !StatusCode.IsGood(outcome.ResultStatus[0]); } diff --git a/tests/Client/ZB.MOM.WW.OtOpcUa.Client.CLI.Tests/HistoryUpdateCommandTests.cs b/tests/Client/ZB.MOM.WW.OtOpcUa.Client.CLI.Tests/HistoryUpdateCommandTests.cs index f7137a34..1074ae1f 100644 --- a/tests/Client/ZB.MOM.WW.OtOpcUa.Client.CLI.Tests/HistoryUpdateCommandTests.cs +++ b/tests/Client/ZB.MOM.WW.OtOpcUa.Client.CLI.Tests/HistoryUpdateCommandTests.cs @@ -147,6 +147,23 @@ public class HistoryUpdateCommandTests TestConsoleHelper.GetOutput(console).ShouldContain("(no result returned)"); } + /// + /// A node the server refuses outright carries its reason in the node-level result with no per-item + /// results; the CLI must print that reason, not just "(no result returned)" (found by the live gate). + /// + [Fact] + public async Task Execute_NodeLevelDenial_PrintsNodeResult() + { + var svc = new FakeOpcUaClientService + { + HistoryUpdateResult = new HistoryUpdateOutcome(StatusCodes.Good, [StatusCodes.BadUserAccessDenied], []) + }; + using var console = TestConsoleHelper.CreateConsole(); + await Should.ThrowAsync(async () => + await Make(svc, values: ["1", "2"], times: TwoTimes).ExecuteAsync(console)); + TestConsoleHelper.GetOutput(console).ShouldContain("Node result: BadUserAccessDenied"); + } + /// Fewer per-item results than items sent must not exit 0, even when every returned one is Good. [Fact] public async Task Execute_TooFewItemResults_Throws()