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
This commit is contained in:
Joseph Doherty
2026-10-09 15:14:46 -04:00
parent e2011a653e
commit 5fdf205caa
4 changed files with 168 additions and 0 deletions
@@ -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: <code>`, 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`.