diff --git a/CLAUDE.md b/CLAUDE.md index e02d5fb1..cb59b809 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -550,8 +550,9 @@ fail-closed). Things worth knowing before touching it: is Phase 4 — resist folding it in, or the "no SQL" scope becomes unprovable-in-parts. On the docker-dev rig the central pair carries `ConfigServe` (`:4055`, committed dev key) and stays -`Direct`; the four site nodes carry `ConfigSource` (endpoints + matching key) defaulting to `Direct`. -Flip only the site nodes with `OTOPCUA_CONFIG_MODE=FetchAndCache` at `docker compose up`. See +hardcoded `Direct` via its admin role; the four site nodes carry `ConfigSource` (endpoints + matching +key) hardcoded `FetchAndCache` — mandatory for driver-only nodes since Phase 4, not a flip. There is +no `OTOPCUA_CONFIG_MODE` env var in the compose file. See `docs/Configuration.md` §`ConfigSource` / `ConfigServe`, `docs/Redundancy.md` §"Command transport", and `docs/plans/2026-07-22-mesh-phase3-config-fetch-and-cache.md`. @@ -649,7 +650,9 @@ deliberately unresolvable gateway endpoint, so the buffer is always a live, non- `.Replication`), bumped from `0.1.3` on 2026-08-15. It was a **pure pin bump — no code change**: `RegisterReplicated(string)` is unchanged, everything 0.2.x added is additive, the wire protocol is untouched (0.1.x peers still sync), and the on-disk bookkeeping schema v1 → v2 upgrades in place on -open, so no rig or volume action was needed. Three things about it are worth knowing: +open, so no rig or volume action was needed. **Its two new APIs — `DeregisterReplicated` and +`RegisterReplicated(table, baselineExistingRows:)` — are now both used** (2026-08-18); the bullets +below are the shape that landed, not the bump itself. Two things are worth knowing: - **`MaxBatchSize` no longer means what the rig's `16` was chosen to mean.** 0.2.0 made batching **byte-budgeted** — `LocalDb:Replication:MaxBatchBytes` (2 MB default, left unset here, sized @@ -659,21 +662,46 @@ open, so no rig or volume action was needed. Three things about it are worth kno `16` — it now bounds that transient allocation (≈2.7 MB at ≈171 KB artifact chunk rows), not the message size. Every comment and doc row that called it "row-count-only against gRPC's 4 MB cap" was corrected with the bump; do not restore that rationale. -- **`DeregisterReplicated` exists and this repo deliberately does not call it.** `LocalDbSetup.OnReady` - registers all four tables **unconditionally**, on every driver node, replicating or not — a - replication-configured node and a default-OFF one (central, site-b) carry identical CDC triggers. - ScadaBridge went the other way (conditional registration + a boot-time deregister self-heal), so - do not read that pattern across as settled here: it would be a behaviour change, and - `LocalDbSetupTests` pins the registered-table set and the DDL→register ordering exactly. The - cost of the current shape is three unused triggers per table on an unreplicated node; the - benefit is that turning replication on is a config change that needs no re-registration pass. -- **Consequently, `baselineExistingRows` is not used either.** Rows written on a node *before* - replication is enabled are not in `__localdb_row_version`, so enabling replication on a - long-running default-OFF node (central, site-b) converges on subsequent **writes**, not on the - rows already in the file. Passing `RegisterReplicated(table, baselineExistingRows: true)` is the - library's answer, but it flags a snapshot resync and is only correct when gated on replication - actually being configured — which the unconditional registration above cannot express. Enable - replication on a fresh pair, or accept the gap and let the next deploy re-cache. +- **Registration FOLLOWS the replication config — it is no longer unconditional (2026-08-18).** + `LocalDbSetup.OnReady` reads one predicate, `LocalDbSetup.ReplicationIsConfigured`: + **`LocalDb:Replication:PeerAddress` OR `LocalDb:Replication:ApiKey` is non-blank.** The **OR is + not belt-and-braces** — only the dialling half of a pair sets `PeerAddress`, so keying on it + alone would strip capture from every *passive* node (site-a-2 carries `ApiKey` + + `LocalDb:SyncListenPort` and nothing else) and the pair would converge in one direction only, + silently. ⚠️ **`SyncListenPort` deliberately does NOT join the OR:** the passive endpoint is + fail-closed on the key, so a port without an `ApiKey` rejects every inbound stream and has + nothing to capture for. + - **Configured ⇒ `RegisterReplicated(table, baselineExistingRows: true)`**, per table, in the + same load-bearing DDL→register order. Baselining is what makes enabling replication on a node + that has been running *without* it actually converge: capture is CDC and the snapshot streamer + pages from `__localdb_row_version`, so pre-registration rows were in neither and a late opt-in + used to replicate only writes made after the restart. It seeds the ledger at the LWW floor + (HLC `0`, this node's id) and flags a resync — a baselined row loses to any genuine remote + write of the same key and wins only where the peer has no version at all. It is idempotent, so + it is free on every boot after the first. ⚠️ On the pinned **0.2.1** the snapshot flag is + per-**database**, not per-table, so baselining anything streams *every* registered table in + full, in both directions at once — trim `alarm_sf_events` before enabling replication on a node + that has been buffering alarm history for months, and expect one slow first sync. + - **Not configured ⇒ `DeregisterReplicated(table)` per table**, an idempotent boot-time + self-heal: it drops the capture triggers an earlier (unconditional) build left in the file and + prunes that table's oplog + row-version rows. Merely declining to register would leave every + pre-2026-08-18 file capturing forever — two INSERTs plus a `json_object` of the whole row + inside every write transaction — on precisely the node that has no peer to capture for. The + call returns `true` when it removed something, so the Information line fires **once, and only + when it actually cleaned**; a default-OFF node's ordinary boot stays silent. The logger is + Serilog's static `Log.Logger` (this runs inside the `AddZbLocalDb` singleton factory, where + resolving one from DI would nest a resolution inside a singleton construction; `Program.cs` + assigns it before anything resolves `ILocalDb`), with an optional parameter so tests observe + the line rather than infer it. + - ⚠️ **PAIR SYMMETRY: flipping registration is a BOTH-NODES-TOGETHER change.** The sync handshake + compares registered-table digests **fail-closed**, so a node that deregisters a table its peer + still replicates stops syncing with a schema mismatch. Enabling replication on an established + pair means setting the config and **restarting both nodes** — do it on both, or on neither. + - **Rollout note:** the only replicating pair in the fleet is docker-dev **site-a**, and it was + enabled from a fresh pair, so the impact of the old gap was low — central and site-b are + default-OFF and simply shed their unused triggers on their next boot. `LocalDbSetupTests` + pins both branches (registered-table set on a configured node, empty set + zero triggers + + the HLC-0 baseline ledger entry on the other) and the DDL→register ordering, unchanged. See `docs/Configuration.md` (`LocalDb` section), `docs/Redundancy.md` (pair-local config cache), `docs/AlarmHistorian.md`, and the runbook diff --git a/docker-dev/README.md b/docker-dev/README.md index c728f431..857da28b 100644 --- a/docker-dev/README.md +++ b/docker-dev/README.md @@ -95,7 +95,14 @@ issues the single, un-retried `POST http://localhost:9200/api/deployments` with `X-Api-Key: docker-dev-deploy-key`. Override the URL / key / timeout via `OTOPCUA_ADMIN_URL`, `OTOPCUA_DEPLOY_API_KEY`, `OTOPCUA_READY_TIMEOUT_SECONDS`. -### First-POST 404 +The body is optional and the no-body form is fully supported (verified on this rig 2026-08-18): +the minimal-API `DeployRequest?` parameter binds a missing body *and* a `Content-Length: 0` body +as **null** — it does not 400 — and the handler defaults the audit field to +`CreatedBy = "rest-api"`. A bare `./docker-dev/deploy.sh` answers `202 Accepted` with the new +`deploymentId` + `revisionHash`, `200` when there is nothing to deploy, and `409` while another +deployment is still in flight. + +### First-POST 404 — mechanism CONFIRMED (2026-08-18) The first headless POST after `up -d` was seen answering **404** ~40 s into boot (2026-08-17 live gate), clearing on retry. Neither end can produce it: the AdminUI maps every route synchronously @@ -104,14 +111,33 @@ failure modes are 503 / 401 / 422 / 409 / 500 — it has no 404 path; and Traefi router whose servers are all down with **503 "no available server"** (the checked-in `traefik-dynamic.yml` router is `PathPrefix(/)` → `otopcua-admin` with a `/health/active` healthCheck). Traefik's `api@internal` router (`PathPrefix(/api)`) is bound to the `:8080` -entrypoint (host 8089), not `web`/`:9200`, so it does not shadow `/api/deployments` either. So a -404 from `:9200` is Go's default "404 page not found" — **no router matched at that instant**; -the mechanism is unconfirmed. The `--accesslog=true --accesslog.fields.defaultmode=keep` flags on -the `traefik` service exist to diagnose the next occurrence: `docker compose -f -docker-dev/docker-compose.yml logs traefik` and look for the request with an empty `RouterName`. -The readiness gate in `deploy.sh` avoids the race (a 200 through `:9200` proves both a matched -router and a live backend), so a 404 *after* the gate is new evidence and the script fails loudly -saying so. +entrypoint (host 8089), not `web`/`:9200`, so it does not shadow `/api/deployments` either. + +**The mechanism is the window between Traefik binding the `web` entrypoint and loading the +dynamic file-provider config** (`--providers.file.filename=/etc/traefik/dynamic.yml`). The +entrypoint accepts connections *before* the router table exists, and until it does, every request +gets Go's default `http.NotFound` handler. Reproduced 2026-08-18 by rapid-polling `:9200` across a +`docker restart otopcua-dev-traefik-1`: the port goes from connection-refused straight to **404 for +~65–160 ms**, then 200. The response body is exactly `404 page not found` (19 bytes), and the +access log — with the `--accesslog=true --accesslog.fields.defaultmode=keep` flags this service +carries for precisely this purpose — records it as: + +``` +192.168.97.1 - - [18/Aug/2026:11:58:26 +0000] "GET /health/ready HTTP/1.1" 404 19 "-" "-" 1 "-" "-" 0ms +``` + +**Empty `RouterName`, empty `ServiceName`, `0ms`** — nothing matched and no backend was dialled. +The competing candidate is **excluded**: a healthCheck'd service with no healthy server yet would +be a *matched* router (`otopcua-admin@file`) answering **503**, and zero 503s appear anywhere in +the log. Note the window has two sub-phases — the earliest 404s are not access-logged at all +(the accesslog handler is itself part of the not-yet-built dynamic chain), later ones are; both are +the same client-visible 404, so **absence from the access log does not mean absence of the 404**. + +The readiness gate in `deploy.sh` closes the race (it loops on any non-200, and a 200 through +`:9200` proves both a matched router and a live backend), so a 404 *after* the gate is new evidence +and the script fails loudly saying so. A plain `docker compose up -d` also hides the window on this +rig without the gate helping: `up -d` blocks on the `depends_on: service_healthy` conditions and +returns ~30 s *after* Traefik starts, by which time the router table is long loaded. ## Tear down diff --git a/docker-dev/deploy.sh b/docker-dev/deploy.sh index d3202c80..7d089255 100755 --- a/docker-dev/deploy.sh +++ b/docker-dev/deploy.sh @@ -8,23 +8,36 @@ # end of the request: the AdminUI maps every route synchronously before RunAsync and # the deploy endpoint has no 404 path (503/401/422/409/500 only), and Traefik answers # a matched-router-with-all-servers-down as 503 "no available server". So the 404 means -# no Traefik router matched at that instant. Polling /health/ready through :9200 until -# it answers 200 proves both halves are in place — the router table carries the -# otopcua-admin router AND a backend is up — before the single, un-retried POST. +# no Traefik router matched at that instant. +# +# CONFIRMED 2026-08-18: the window is between Traefik binding the `web` entrypoint and +# loading its dynamic file-provider config — the port accepts connections before the +# router table exists, so requests get Go's default `404 page not found` (19 bytes), +# access-logged with an EMPTY RouterName/ServiceName and 0ms. Measured at ~65-160 ms +# across a `docker restart` of the traefik container. See docker-dev/README.md +# §"First-POST 404". Polling /health/ready through :9200 until it answers 200 proves +# both halves are in place — the router table carries the otopcua-admin router AND a +# backend is up — before the single, un-retried POST. # # A 404 AFTER the gate is therefore new evidence, not the known boot race: it should be # investigated against the Traefik access log (`--accesslog=true` on the traefik service; # `docker compose -f docker-dev/docker-compose.yml logs traefik`), which records the -# RouterName (empty on an unmatched request) for the failing call. +# RouterName (empty on an unmatched request) for the failing call. Caveat: the earliest +# 404s of the window predate the accesslog handler itself and are NOT logged at all, so +# an empty access log does not prove the 404 did not happen. # # Usage: # ./deploy.sh # no body (matches the bare README snippet) # ./deploy.sh artifact.json # send that file as the JSON request body # cat artifact.json | ./deploy.sh # -# NOTE (unverified against a live rig): the no-body invocation sends -# `Content-Type: application/json` with an empty body. Whether the minimal-API -# `DeployRequest?` parameter binds that as null or answers 400 has not been confirmed. +# NOTE (verified on the docker-dev rig 2026-08-18): the no-body invocation sends +# `Content-Type: application/json` with no body (or `Content-Length: 0` when stdin is a +# redirected-but-empty non-tty, which takes the `--data-binary @-` branch below). The +# minimal-API `DeployRequest?` parameter binds BOTH shapes as null — it does NOT 400 — +# and the handler falls back to `createdBy = "rest-api"` (DeployApiEndpoints.cs). Confirmed +# end to end: a bare `./deploy.sh` returned `HTTP 202 {"outcome":"Accepted",...}` and the +# resulting Deployment row carried `CreatedBy = rest-api`. # set -euo pipefail diff --git a/docs/Configuration.md b/docs/Configuration.md index c28def93..2bccc843 100644 --- a/docs/Configuration.md +++ b/docs/Configuration.md @@ -250,7 +250,7 @@ from the bytes emitted at compose time and never re-derived from the JSON, so an costs at most one spurious "changed" revision after a runtime upgrade. Snapshot determinism is unaffected — compression wraps the final bytes and reorders nothing.) -On the docker-dev rig the central pair carries `ConfigServe` (port `4055`, dev key) and stays `Direct`; the four site nodes carry `ConfigSource` (endpoints + matching key) defaulting to `Direct`. Flip only the site nodes with `OTOPCUA_CONFIG_MODE=FetchAndCache` at `docker compose up` — central keeps SQL and models the target topology. +On the docker-dev rig the central pair carries `ConfigServe` (port `4055`, dev key) and stays hardcoded `Direct` via its admin role; the four site nodes carry `ConfigSource` (endpoints + matching key) hardcoded `FetchAndCache` — mandatory for driver-only nodes since Phase 4, not a flip. There is no `OTOPCUA_CONFIG_MODE` env var in the compose file; central keeps SQL and models the target topology. **`FetchAndCache` is mandatory on a driver-only node — per-cluster mesh Phase 4.** `Program.cs` now registers `AddOtOpcUaConfigDb` only when the node carries the `admin` role, so a **driver-only** @@ -418,6 +418,18 @@ replication stays inert until the sync port + peer are set. | `LocalDb:Replication:MaxBatchSize` | `500` (library) | **Secondary** row-count cap on a batch — *and* the DB read-page size. `16` on the replicating pair. Since LocalDb 0.2.0 the wire message is bounded by `MaxBatchBytes`, not by this, so it is no longer the hand-tuned byte proxy the 4 MB cap once forced. It still matters because `OplogStore.ReadBatchAboveAsync`/`SnapshotStreamer` materialise a whole read page **before** the byte-budget split runs — `16` bounds that transient allocation at ≈2.7 MB for ≈171 KB artifact chunk rows. | | `LocalDb:Replication:MaxBatchBytes` | `2 MB` (library) | **Primary** cap on one outbound delta/snapshot message: the summed serialized size of its entries, sized under gRPC's 4 MB receive limit. Left unset across the fleet. A single row larger than the budget is sent **alone** rather than stalling the stream. Added in LocalDb 0.2.0; needs no wire change, so a node on this version interoperates with any earlier peer in both directions. | +**These two keys also decide whether the node captures at all.** `LocalDbSetup.ReplicationIsConfigured` is +`PeerAddress` **OR** `ApiKey` non-blank — the OR because only the *dialling* half sets `PeerAddress`, so +keying on it alone would strip change capture from every passive node and leave the pair converging in one +direction only. `SyncListenPort` is deliberately **not** part of it (a port with no `ApiKey` is fail-closed +and syncs with nobody). A configured node registers all four tables with `baselineExistingRows: true`, so +turning replication on converges the rows **already in the file** and not merely subsequent writes; an +unconfigured node **deregisters** them at boot, dropping capture triggers an earlier build installed. ⚠️ The +sync handshake compares registered-table digests **fail-closed**, so flipping either key is a +both-nodes-together change: set it on both and restart both. On LocalDb 0.2.1 baselining flags a +**per-database** snapshot resync (every registered table, in full, both directions), so trim a long-running +`alarm_sf_events` buffer before enabling replication late. + Replication is **default-OFF** across the fleet; it is enabled per-pair as an opt-in. See [`docs/operations/2026-07-20-localdb-pair-replication.md`](operations/2026-07-20-localdb-pair-replication.md) for the enablement runbook (ApiKey handling, stop/start-together rule, tombstone-retention window, and the diff --git a/docs/operations/2026-07-20-localdb-pair-replication.md b/docs/operations/2026-07-20-localdb-pair-replication.md index 2afe8ca6..51c401c8 100644 --- a/docs/operations/2026-07-20-localdb-pair-replication.md +++ b/docs/operations/2026-07-20-localdb-pair-replication.md @@ -82,8 +82,28 @@ Replication has two knobs, both under `LocalDb`: > wire protocol is unchanged (0.1.x peers still sync), and the on-disk bookkeeping schema v1 → v2 > is upgraded **in place on open**, so an existing node's database file needs no operator action. > Two behaviours changed that an operator should know: batching is now byte-budgeted (the two rows -> above), and `DeregisterReplicated` exists — this repo never calls it, so the deregistration -> symmetry rule and the HLC-anchor fix 0.2.1 shipped for it do not apply to an OtOpcUa node. +> above), and **both of 0.2.x's lifecycle APIs are now used** (2026-08-18) — see the box below. + +> **⚠️ Registration follows this config, and flipping it is a BOTH-NODES change.** Since +> 2026-08-18 `LocalDbSetup.OnReady` installs the change-capture triggers only when the node is +> configured to replicate — the predicate is **`PeerAddress` OR `ApiKey` non-blank** (the OR because +> the passive node has no `PeerAddress`; `SyncListenPort` is deliberately not part of it, since a +> port with no key is fail-closed and syncs with nobody). Consequences at enablement time: +> +> - A configured node registers with **`baselineExistingRows: true`**, so the rows **already in the +> file** are seeded into the row-version ledger at the LWW floor (HLC `0`) and actually travel. +> Before this, enabling replication on a node that had been running converged on *subsequent +> writes only*. ⚠️ On 0.2.1 the snapshot flag is **per-database**: baselining streams *every* +> registered table in full, in both directions at once. **Trim a long-standing `alarm_sf_events` +> backlog before enabling replication late**, and expect one slow first sync. +> - An unconfigured node **deregisters** at boot — the capture triggers a pre-2026-08-18 build left +> behind are dropped and that table's oplog/row-version rows pruned. It logs one Information line +> naming the table count, and stays silent when there was nothing to clean. +> - The sync handshake compares **registered-table digests, fail-closed**, so a node that +> deregisters a table its peer still replicates stops syncing with a schema mismatch. **Set the +> keys on both nodes and restart both** — never one. (0.2.1's HLC-anchor fix now matters here: +> the clock is flushed inside the deregistration transaction, so a crash right after a +> deregister boot cannot bring the clock below stamps the peer already holds.) Example (site-a-1 initiator, site-a-2 passive): diff --git a/docs/plans/2026-08-17-perf-followups-r2.md b/docs/plans/2026-08-17-perf-followups-r2.md index 3ad01266..51258611 100644 --- a/docs/plans/2026-08-17-perf-followups-r2.md +++ b/docs/plans/2026-08-17-perf-followups-r2.md @@ -564,22 +564,41 @@ closed on the round-1 register. **None blocks the branch.** one call. **Pre-existing and benign** — it self-heals on the next call and **no verdict is affected** (a deferred stamp cannot serve a stale grant; the generation gate on `TryGet` is what decides that, and it is unaffected). Recorded so the next reader does not re-derive it as a bug. + - **Closed by `441b34a3` (r3).** `InvalidateIfStale` is now a monotonic-max CAS **loop** with + the `<=` guard re-read inside each attempt, so a straggler that loses the CAS retries against + the moved stamp instead of falling out unpublished. **S7** - **Per-item decode health is last-writer-wins.** Pre-existing; now **pinned and documented** rather than fixed, because changing it is a behaviour change to how a mixed-outcome chunk reports driver health, not a test gap. + - **Closed by `4c161181` + `b35e423c` + `1765e300` (r3), for the READ path.** One + worst-state-wins accumulator per `ReadAsync` pass, one end-of-pass `_health` write, with + `LastSuccessfulRead` advanced whenever *any* item succeeded. ⚠️ **Modbus (all paths) and the + S7 WRITE path deliberately keep last-writer-wins** — recorded as a known asymmetry on the r3 + register, not an oversight. - **TM/CT decode at a non-zero device number still needs a real CPU.** The test exists and the env var (`S7_TIMER_NUMBER_ADDRESSING=1`) is ready; python-snap7 cannot serve it (see the BIT-address quirk above). + - **Carried (r3).** Unchanged — still blocked on hardware; explicitly out of scope in the r3 + plan. **docker-dev** - **The first-POST 404's mechanism is unconfirmed** until the new access log catches an occurrence. The gate prevents the symptom; the cause is still open. + - **Closed by `3f04a4d4` (r3).** Mechanism: the window between Traefik binding the `web` + entrypoint and loading the dynamic file-provider config — the listener accepts before the + router table exists (~65–160 ms on the rig; empty `RouterName`/`ServiceName`, `0ms`, Go's + `404 page not found`). The 503 candidate is excluded on evidence. ⚠️ **Not all 404s are + access-logged** — the accesslog handler is itself part of the not-yet-built dynamic chain, so + an empty log does not prove absence. - **The no-body `POST` `Content-Type` binding is unverified against a live rig** — carried as a header NOTE in `deploy.sh` rather than silently assumed correct. + - **Closed by `3f04a4d4` (r3).** Verified live across four request shapes: `DeployRequest?` + **binds null** (no 400, no 415), the request returns **202 Accepted**, and the handler's + fallback puts `CreatedBy = rest-api` — confirmed in the ConfigDb. **SQL test infrastructure** @@ -587,3 +606,4 @@ closed on the round-1 register. **None blocks the branch.** **accepted**: two test processes racing on the same instance can have one reap what the other just planted. The 24 h age floor makes it vanishingly unlikely in practice, and the alternative (a lock table on a shared dev server) costs more than it buys. + - **Carried (r3).** Still accepted, unchanged; explicitly out of scope in the r3 plan. diff --git a/docs/plans/2026-08-17-perf-followups-r3.md b/docs/plans/2026-08-17-perf-followups-r3.md new file mode 100644 index 00000000..ece17990 --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -0,0 +1,883 @@ +# Perf Follow-ups Round 3 Implementation Plan + +> **For Claude:** REQUIRED SUB-SKILL: Use superpowers-extended-cc:subagent-driven-development +> to implement this plan task-by-task (per the standing preference: Opus implementers, +> classification-driven review chains). + +**Goal:** Close the actionable items in the round-2 follow-up register +(`docs/plans/2026-08-17-perf-followups-r2.md` §"Follow-up register") and run the +still-unexercised local live gates (FetchAndCache legs, alarm-bearing surgical ratchet, +ACL-enabled enforcement, docker-dev first-POST-404 catch), on branch `perf/followups-r3` +off master merge `49d05bc2`. + +**Architecture:** Two surgical code fixes in already-reviewed code (the ACL cache's +single-shot CAS becomes a monotonic-max loop; S7 read-pass health becomes worst-state-wins +aggregation), one doc-staleness fix found during exploration, and four live gates on the +local docker-dev rig (OrbStack) sequenced on one rig session. No new subsystems. + +**Tech Stack:** .NET 10 / C#, xUnit + Shouldly, docker-dev rig (OrbStack), Traefik v3.1 +access log, Client.CLI, Chrome browser automation for AdminUI authoring. + +**Out of scope (recorded, deliberately not here):** +- **TM/CT decode at a non-zero device number** — needs a real S7 CPU; the test exists and + is env-gated on `S7_TIMER_NUMBER_ADDRESSING=1`. Nothing to do until hardware exists. +- **Cross-process plant-vs-reap race on the shared SQL server** — accepted in r2; the 24 h + age floor is the mitigation. No work. +- **Modbus per-tag health last-writer-wins** — Task 2 fixes S7 only (the recorded item). + Modbus has the same shape (`ModbusDriver.ReadAsync:493/511/518` + the coalesced path); + fixing it here doubles the blast radius of a watchdog-adjacent change. Recorded in this + round's register as a deliberate asymmetry. +- **S7 write-path per-item health** (`S7Driver.cs:1575/1633/1645/1654`) — same + last-writer-wins shape on `WriteAsync`; out of scope for the same reason, recorded. +- Historian end-to-end live gate — needs the `wonder-sql-vd03` VPN (user-driven). +- HistorianGateway batch `WriteLiveValues` RPC — cross-repo. +- Load-scale throughput — needs a load harness; not defined enough to gate. + +**Execution rules (unchanged from prior rounds):** shared checkout — explicit-pathspec +`git add`/`git commit -- ` only (never a bare commit); never checkout/switch/reset/ +stash/clean; retry on `index.lock` and CS2012/MSB3030 build races; reviewers judge commits +via `git show`; falsification mutations applied AND reverted via Edit (never git), run +against a freshly built binary (never `--no-build` after a mutation), and labeled honestly +("pin, not red-first" where the behaviour predates the test; "probabilistic red" where the +mutation trips a race). Live-gate rig work is serial — one rig session, Tasks 4→5→6→7 in +that order, images built from the branch tip AFTER Tasks 1–3 land so the gates also +regression the new code. + +--- + +### Task 1: ACL `InvalidateIfStale` — monotonic-max CAS loop (publication never deferred) + +**Classification:** high-risk +**Estimated implement time:** ~4 min +**Parallelizable with:** Tasks 2, 3 + +**Files:** +- Modify: `src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs:453-461` + (+ the XML remarks block `:430-452`) +- Test: `tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs` + +**Context.** The r2 register records: the single-shot CAS in `InvalidateIfStale` can defer +stamp publication by one call. Two callers read the same `seen` baseline; gen-N wins the +CAS, gen-N+1's CAS fails against the moved stamp and falls out with **no retry** — N+1 is +not published on that call, so its `TryGet` misses and its `Set` is dropped at `:223`. +Benign (verdict safety lives in the per-shard generation gate), but it costs a lost store +exactly in the post-deploy window. Current code: + +```csharp +private void InvalidateIfStale(long generation) +{ + var seen = Interlocked.Read(ref _generation); + if (generation <= seen) return; + if (Interlocked.CompareExchange(ref _generation, generation, seen) == seen) ClearAll(); +} +``` + +**Step 1: Write the racing pin (red against current code — probabilistic red, say so).** + +```csharp +[Fact] +public void Concurrent_lookups_at_mixed_generations_always_publish_the_highest() +{ + // The single-shot CAS defect: when gen-1 wins the shared-baseline race, gen-2's CAS + // fails and is never retried, leaving Generation == 1. Red is probabilistic per + // round; 200 barrier-synchronised rounds make it effectively certain. + for (var round = 0; round < 200; round++) + { + var cache = /* fresh cache, generation seed -1 */; + using var barrier = new Barrier(2); + var low = Task.Run(() => { barrier.SignalAndWait(); /* TryGet at generation 1 */ }); + var high = Task.Run(() => { barrier.SignalAndWait(); /* TryGet at generation 2 */ }); + Task.WaitAll(low, high); + cache.Generation.ShouldBe(2L, + $"round {round}: the newer generation must publish even when it loses the CAS race"); + } +} +``` + +Use the ordinary `TryGet` lookup path (as the straggler test at `:286` does), NOT +`AdvanceGenerationForTest` — the defect lives in the lookup path's invalidation. + +**Step 2: Run it, observe red.** `dotnet test tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests --filter "FullyQualifiedName~Concurrent_lookups_at_mixed_generations"` — expect FAIL within a few rounds. If 200 rounds pass green against unmodified code, the test is not exercising the race — fix the test, do not proceed. + +**Step 3: Implement the monotonic-max loop.** + +```csharp +private void InvalidateIfStale(long generation) +{ + while (true) + { + var seen = Interlocked.Read(ref _generation); + if (generation <= seen) return; // guard re-checked per attempt + if (Interlocked.CompareExchange(ref _generation, generation, seen) == seen) + { + ClearAll(); + return; + } + } +} +``` + +Invariants (update the XML remarks `:430-452` to say all of this): +- The `<=` guard is INSIDE the loop against a fresh read — a straggler that lost a CAS + re-reads the newer stamp and exits; hoisting the guard reintroduces the 98d6a190 defect. +- Only the thread whose CAS moved the stamp clears (elected clear preserved). A rollover + now legitimately clears once per distinct generation (N then N+1) — bounded by + generations, not request volume. +- The loop self-terminates: each iteration exits via the guard or CASes against a strictly + larger `seen`, and `_generation` only rises. +- The `-1` seed still admits generation 0. + +**Step 4: Run the new test + the full cache suite.** All 18 green (17 existing + 1 new), +especially `A_straggler_from_an_older_generation_neither_clears_nor_rolls_the_stamp_back` +(`:286`) and `No_hit_ever_returns_a_verdict_from_another_generation` (`:363`). + +**Step 5: Falsify.** Via Edit, revert the loop to the single-shot form (fresh build, not +`--no-build`) → the new test must go red (probabilistic; report the failing round). Revert +via Edit. Separately, move the `<=` guard outside the loop → the straggler test at `:286` +must go red. Revert. + +**Step 6: Commit.** +```bash +git add -- src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs \ + tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs +git commit -m "fix(acl): make InvalidateIfStale a monotonic-max CAS loop — stamp publication is never deferred" -- +``` + +--- + +### Task 2: S7 read-pass health — worst-state-wins aggregation + +**Classification:** high-risk +**Estimated implement time:** ~5 min +**Parallelizable with:** Tasks 1, 3 + +**Files:** +- Modify: `src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs` — per-item health sites + `:647` (per-tag loop), `:828` (multi-var decode loop), `:941` (span member loop), + `RecordReadFailure:1010-1046`, plus one end-of-pass write in `ReadAsync` +- Test: `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs` + (flip the `:423` pin; doc-comment `:389-393` rewritten; new tests) + +**Context.** The r2 register records: per-item decode health is last-writer-wins — a mixed +chunk reports whatever the LAST item's outcome was, so `Healthy` can be reported for a +pass that had failures (pinned at `:396-423`), and the `:1023` access-denied `Faulted` can +be overwritten by a later good item. Fix = aggregate one outcome per `ReadAsync` pass. + +**Watchdog contract (MUST hold — CLAUDE.md comms-loss section):** `Degraded` means +connected-but-some-bad; `LastSuccessfulRead` advances on ANY success and is preserved on +failure. The aggregate write must advance `LastSuccessfulRead` when ANY item succeeded, +even when the state lands `Degraded`/`Faulted` — gating it on `Healthy` turns the fix into +a false-positive reconnect storm. + +**Step 1: Red tests first** (the flip IS red-first; the rest are new): +1. Flip `:423`: `One_undecodable_multi_var_item...` now expects `Degraded` (rename to say + worst-state-wins; rewrite doc-comment `:389-393` — the last-writer-wins pin is being + deliberately retired). +2. New: a mixed multi-var pass reports `Degraded` AND `LastSuccessfulRead` is advanced + (non-null / newer than the pre-pass value). +3. New: span path — one bad member decode then a good member ⇒ `Degraded` (today: Healthy). +4. New: an access-denied `PlcException` on one tag followed by a success ⇒ state stays + `Faulted` (ordering `Healthy < Degraded < Faulted`), `LastSuccessfulRead` advanced. + Use the per-tag path if the multi-var fake can't produce a per-item PlcException. +5. Must-stay-green: `:326` (`A_failing_multi_var_chunk_falls_back...`, asserts Healthy at + `:346`) and `:432` (short answer, Healthy at `:447`) — a multi-var REQUEST fault whose + tags are re-served Good by the per-tag tail is NOT a failed outcome. The chunk-fault + catch (`:806-814`) stays outside the aggregate. + +**Step 2: Run, observe red on 1–4** (each for its own reason; report per-test). + +**Step 3: Implement.** A small per-pass accumulator threaded through the pass: + +```csharp +private sealed class ReadPassOutcome +{ + public bool AnySuccess; + public DriverState WorstFailure = DriverState.Healthy; // Healthy = none recorded + public string? FirstError; // first failure is causal + public void RecordSuccess() => AnySuccess = true; + public void RecordFailure(DriverState state, string message) + { + if (Rank(state) > Rank(WorstFailure)) WorstFailure = state; + FirstError ??= message; + static int Rank(DriverState s) => s switch + { + DriverState.Faulted => 2, DriverState.Degraded => 1, _ => 0 + }; + } +} +``` + +- The three success sites (`:647`, `:828`, `:941`) call `outcome.RecordSuccess()` instead + of assigning `_health`. +- `RecordReadFailure` takes the outcome, records `(Degraded|Faulted, message)` into it + instead of assigning `_health`, and KEEPS its `_plcDead` / `MarkConnectionDeadIfFatal` + side effects immediate. It still returns the per-item status code. +- One `_health` write at the end of the `ReadAsync` try body (NOT `finally` — the OCE + arms at `:649`/`:801`/`:920` rethrow and must skip it): + +```csharp +_health = new DriverHealth( + outcome.WorstFailure == DriverState.Healthy + ? DriverState.Healthy : outcome.WorstFailure, + outcome.AnySuccess ? now : _health.LastSuccessfulRead, + outcome.WorstFailure == DriverState.Healthy ? null : outcome.FirstError); +``` + +- Untouched: the `:567` connect-failure early return; `HandlePollError` (`:1980`); the + entire write path; init/shutdown sites. `ReadSpanAsync` / `ReadLeftoversByMultiVarAsync` + gain an outcome parameter — signature changes, no logic movement. + +**Step 4: Run the full S7 suite** (`dotnet test tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests`) +— all green including the parity anchor `:202` (all-members-fail ⇒ Degraded both paths). + +**Step 5: Falsify.** Via Edit: (a) make the end-of-pass write use the LAST recorded state +instead of the worst → tests 1/3/4 red; (b) gate `LastSuccessfulRead` advancement on the +state being Healthy → test 2 red. Fresh builds. Revert via Edit. + +**Step 6: Commit** (explicit pathspec, message +`fix(s7): read-pass health is worst-state-wins — a mixed pass can no longer report Healthy`). + +--- + +### Task 3: Fix stale `OTOPCUA_CONFIG_MODE` docs + +**Classification:** trivial +**Estimated implement time:** ~2 min +**Parallelizable with:** Tasks 1, 2 + +**Files:** +- Modify: `docs/Configuration.md` (~line 253) — "Flip only the site nodes with + `OTOPCUA_CONFIG_MODE=FetchAndCache` at `docker compose up`" is stale +- Modify: `CLAUDE.md` — same sentence in the `ConfigSource`/`ConfigServe` section +- Check-and-fix if matched: `grep -rn "OTOPCUA_CONFIG_MODE" docs/ docker-dev/ CLAUDE.md` + +**Spec.** Phase 4 made `FetchAndCache` mandatory on driver-only nodes +(`ConfigSourceOptionsValidator` fails host start on `Direct`), and the rig's four site +nodes are hardcoded `ConfigSource__Mode: "FetchAndCache"` in +`docker-dev/docker-compose.yml:572-579/691-696/787-792/858-863`. The env var appears +nowhere in the compose file; setting it is a no-op. Rewrite both sentences to state: the +site nodes run `FetchAndCache` unconditionally (mandatory for driver-only nodes since +Phase 4); central stays `Direct` via its admin role. No review (doc-only). Commit with +explicit pathspec, message `docs(config): OTOPCUA_CONFIG_MODE is gone — site nodes are hardcoded FetchAndCache (Phase 4)`. + +--- + +### Task 4: Live gate — docker-dev first-POST-404 catch + no-body POST binding + +**Classification:** live-gate (rig session step 1 — FRESH BOOT window) +**Estimated implement time:** ~10 min wall (mostly rig boot) +**Parallelizable with:** none (rig serial; runs after Tasks 1–3 land, images built from branch tip) + +**Files:** +- Possibly modify: `docker-dev/deploy.sh` (the header NOTE about no-body binding), + `docker-dev/README.md` (§"First-POST 404" — mechanism note if caught) +- Evidence: write to the scratchpad; Task 8 folds it into the plan's Outcomes + +**Procedure:** +1. Fresh rig: `docker compose -f docker-dev/docker-compose.yml down -v` then + `up -d --build` (build mandatory — the branch tip must be in the images). +2. IMMEDIATELY run `./docker-dev/deploy.sh` (no body). Its 2 s `/health/ready` poll rides + through Traefik during the boot window — every poll is access-logged with + `defaultmode=keep`, and an unmatched request shows an EMPTY `RouterName`. +3. After the deploy completes (or fails), capture + `docker compose -f docker-dev/docker-compose.yml logs traefik` and extract every + non-2xx access-log line from the boot window. **If any 404 appears:** name the + mechanism from `RouterName`/`ServiceName`/timing (the r2 elimination says: AdminUI + cannot 404 that path; backend-down is 503; so 404 = no router matched at that instant + — presumably the window before the dynamic-config file provider loads or before the + health-checked service has a server). Update `docker-dev/README.md` §"First-POST 404" + with the observed mechanism. **If it does not reproduce:** record that honestly — + "did not reproduce under the readiness gate; register item stays open" — do NOT + invent a mechanism. +4. No-body POST binding: with the rig ready, run `./docker-dev/deploy.sh` bare and record + the HTTP status + response body. Determine whether the minimal-API `DeployRequest?` + binds null (and what the endpoint then does) or 400s. Update the header NOTE in + `deploy.sh` from "unverified" to the observed behaviour, and `README.md` if wrong. +5. Leave the rig UP for Task 5. + +Commit any `deploy.sh`/`README.md` edits (explicit pathspec). Report: the access-log +excerpt, the no-body verdict, and whether the 404 reproduced. + +--- + +### Task 5: Live gate — FetchAndCache legs on the running rig + +**Classification:** live-gate (rig session step 2) +**Estimated implement time:** ~8 min wall +**Parallelizable with:** none (rig serial, after Task 4) + +**Procedure** (rig already up from Task 4; a deploy already ran): +1. **Fetch + verify:** `docker compose -f docker-dev/docker-compose.yml logs site-a-1 | + grep -E "Fetched \+ verified artifact"` — expect + `Fetched + verified artifact for {DeploymentId} from http://central-… ({Bytes} bytes).` +2. **Served (central side):** `logs central-1 central-2 | grep "Served artifact"` — + `Served artifact for {DeploymentId} ({Bytes} bytes, {Chunks} chunks)`. +3. **Applied-from-fetch + cached:** `logs site-a-1 | grep -E "applied fetched deployment|cached applied deployment"` — both lines must appear (the `fetched` variant, NOT the + Direct `applied deployment` form). +4. **Boot-from-cache:** `docker compose restart site-a-1`, wait for boot, then + `logs site-a-1 | grep "FetchAndCache boot"` — expect + `restored served state for deployment {Id} (rev {Rev}) from the LocalDb pointer.` +5. **Absence proof:** on site-a-1 logs, assert NO occurrence of `entering Stale`, + `ConfigDb back`, or the Direct-form `applied deployment {Id} (rev` (without + `fetched`). A FetchAndCache node must never reach Stale. +6. Evidence excerpts to the scratchpad for Task 8. Rig stays UP for Task 6. + +No commit expected. If any leg fails, STOP and report — that is a real regression, not a +gate formality. + +--- + +### Task 6: Live gate — alarm-bearing surgical ratchet + +**Classification:** live-gate (rig session step 3) +**Estimated implement time:** ~12 min wall +**Parallelizable with:** none (rig serial, after Task 5) + +**Context.** The surgical-deploys classifier routes an alarm-bearing raw-tag delta +(`Alarm != null` on EITHER side) to `Rebuild`; a whitelisted non-alarm attribute delta +(`Writable` among them) is surgical. Never observed live. The ONLY seam is the applier +summary line (`AddressSpaceApplier.cs:322-326`): +`applied plan (kind={Kind}, …, surgicalRawTags={SurgicalRaw}, …, rebuild={Rebuild})`. + +**Procedure:** +1. Pick TWO alarm-free raw tags in the rig's seeded config (browse `/raw` via AdminUI at + `http://localhost:9200`, login disabled — or read the ConfigDb `Tag` rows). Call them + TagS (surgical lever) and TagA (alarm lever). +2. **Surgical control first:** toggle TagS's Access level (Read ↔ ReadWrite) — via the + RawTagModal in the browser, or a direct ConfigDb UPDATE of the tag row (the rig's DB + on `10.100.0.35,14330`; acceptable for a classifier gate, note which route was used). + Deploy via `./docker-dev/deploy.sh`. Expect on central-1: + `kind=AttributeOnly, … surgicalRawTags=1, … rebuild=False`. +3. **Alarm add ⇒ rebuild:** add `"alarm": {"alarmType": "OffNormalAlarm", "severity": 500}` + to TagA's `TagConfig` JSON (raw-JSON textarea — available because the seeded device is + a Galaxy driver, which has no typed editor — or the same direct-DB route). Deploy. + Expect `kind=Rebuild, … surgicalRawTags=0, … rebuild=True`. +4. **Alarm remove ⇒ rebuild:** remove the `alarm` object, deploy, expect `rebuild=True` + again (Alarm != null on the PREVIOUS side also disqualifies). +5. **Restore:** revert TagS's access level, deploy once more (surgical again — also + re-proves the ratchet is per-deploy, not latched). +6. Evidence: the four applier lines (grep `docker compose logs central-1 site-a-1 | + grep "applied plan (kind="` — note which nodes applied). Scratchpad for Task 8. Rig + stays UP for Task 7. + +No commit expected. Failure of the expected routing = STOP and report. + +--- + +### Task 7: Live gate — ACL-enabled enforcement on site-a (re-shaped cache) + +**Classification:** live-gate (rig session step 4) +**Estimated implement time:** ~20 min wall +**Parallelizable with:** none (rig serial, after Task 6) + +**Context.** `Security:Acl:Enabled` has never been exercised live since the r1/r2 cache +re-shape (per-key shards, generation stamp, Task 1's CAS loop). Site-a is the env-gated +demo pair: `OTOPCUA_ACL_ENABLED=true` reaches site-a-1/-2 only +(`docker-compose.yml:585/:702`); site-b stays off as the A/B control. Site-a OPC UA: +host ports 4842/4843; site-b: 4844/4845. Keys/grants reach driver-only site nodes ONLY +via the deployment artifact — every authoring step needs a deploy after it. + +**Procedure:** +1. Restart site-a gated: `OTOPCUA_ACL_ENABLED=true docker compose -f docker-dev/docker-compose.yml up -d site-a-1 site-a-2`. Confirm the boot Warning on both: + `node ACL enforcement is ENABLED — EVERY data-plane operation … requires a matching NodeAcl grant`. +2. Mint a key: AdminUI `/apikeys` (Chrome automation; login disabled) — Name + `r3-acl-gate`, Principal `r3gate`. COPY the one-time `otua_…` credential immediately. +3. Author a grant: `/clusters/{site-a cluster id}/acls/new` — Principal `r3gate`, scope + picked via the AclScopePickerModal on a WRITABLE raw tag (or its device — inheritance + covers the tag), permissions: the Operator bundle (must include Browse/Read/ + WriteOperate). Save; expect no "authorizes nobody" warning. +4. Deploy (`./docker-dev/deploy.sh`) so the key + grant ride the artifact to site-a. + Confirm on site-a-1: `data-plane authority generation {G} installed (… keys=…, grants=…)`. +5. **The load-bearing ALLOW:** Client.CLI write through the grant — + `dotnet run --project src/Client/ZB.MOM.WW.OtOpcUa.Client.CLI -- write -u opc.tcp://localhost:4842 -n "" -v -U apikey -P otua_…` + Expect success (the session carries NO server-wide role; the grant alone authorizes — + a deny-only gate would pass against a build where the ACL is never consulted). + Note: the rig's Galaxy driver has no live gateway, so the DEVICE write may fail + downstream — the gate is that the request passes the ACL (not `BadUserAccessDenied`); + any downstream Bad status is fine and should be reported as such. +6. **Deny controls:** (a) same write WITHOUT credentials (anonymous) ⇒ denied; (b) a + read/browse on a node OUTSIDE the granted scope with the key ⇒ withheld (grep + site-a-1 for `AclGate: denied {Operation} on {NodeId} for principal r3gate`). +7. **Revocation reaches the artifact path:** disable the key on `/apikeys`, deploy, + confirm a NEW `data-plane authority generation {G+1} installed` on site-a-1, and the + same CLI write now fails auth (`ApiKeyAuth: denied — no enabled, unexpired key`). +8. **Teardown:** restore site-a ungated (`docker compose up -d site-a-1 site-a-2` without + the env), optionally delete the gate key/grant, and `docker compose down` the rig + unless Task 8 needs it. Evidence excerpts to the scratchpad. + +No commit expected. If Chrome automation of the scope picker proves impractical, direct +ConfigDb inserts for `ApiKey`/`NodeAcl` rows are acceptable ONLY as a fallback — say so, +and keep the key's peppered HMAC consistent with the rig pepper +(`docker-dev-apikey-pepper-not-for-production`); minting via the UI is strongly preferred +because it exercises the real authoring path. + +--- + +### Task 9: Roslyn evaluator racing test — remove the timing assumption + +**Classification:** standard +**Estimated implement time:** ~5 min +**Parallelizable with:** Task 10 (disjoint files); independent of the rig tasks + +**Origin:** ScadaBridge deferred-work register row 38, relayed cross-session 2026-08-18 +(coordinated by the ScadaBridge session on Joe's behalf). + +**Files:** +- Modify: `tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs` + (`Evaluate_racing_ClearCompiledScripts_never_fails_with_disposed`, ~:391 — renamed by + the implementation to `Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure`) + +**Spec.** The test is load-fragile: it fails under full-solution parallel test load but +passes 3/3 in isolation. Its design assumes at most ONE `ClearCompiledScripts` lands +inside a single evaluation (so the product's one-shot retry suffices); under contention +two can land and the retry legitimately exhausts. Test-design issue, NOT a product bug. +Fix by removing the timing assumption while keeping the original intent (no +disposed-script failure ever ESCAPES the retry): either bound the clear cadence relative +to observed evaluation latency, or assert on retry-exhaustion behaviour instead of zero +failures — implementer picks whichever preserves intent with less machinery, documents +the choice in the test doc-comment, and demonstrates the test survives a +full-parallel-load run (run the containing suite alongside another heavy suite, or +repeat-run the suite ≥5×; report what was actually run). + +--- + +### Task 10: LocalDb conditional registration + baseline + deregister self-heal + +**Classification:** high-risk +**Estimated implement time:** ~8 min +**Parallelizable with:** Task 9 (disjoint files) + +**Origin:** ScadaBridge deferred-work register row 39, relayed cross-session 2026-08-18. +ScadaBridge closed the same class with conditional registration + boot-time self-heal +(`Host/SiteLocalDbSetup.cs`, arch-review WP1.3/WP3.3); port that pattern here. + +**Files:** +- Modify: `src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs` (`OnReady`, + registration at :63-66) +- Read for the predicate: `src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbRegistration.cs` + (`LocalDb:SyncListenPort`, `LocalDb:Replication:*` keys) +- Modify: `tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs` + (the registered-table-set + ordering pins — update DELIBERATELY, say so in the diff) +- Modify: `CLAUDE.md` LocalDb section — the two bullets recording unconditional + registration as deliberate ("DeregisterReplicated exists and this repo deliberately + does not call it" / "Consequently, baselineExistingRows is not used either") must be + rewritten to record the new conditional shape and why it changed. + +**Spec.** +- "Replication configured" = `PeerAddress` OR `ApiKey` present (OR, because only the + dialling half sets PeerAddress while the passive half carries just the key + listen + port — verify the exact key names against `LocalDbRegistration`). +- Configured ⇒ `RegisterReplicated(table, baselineExistingRows: true)` per table, in the + existing DDL→register order (the ordering is load-bearing and pinned) — seeds + row-versions at the LWW floor and flags snapshot resync, so late-enabled replication + on an established node converges on EXISTING rows, not just subsequent writes. +- NOT configured ⇒ `DeregisterReplicated` on every table at boot — idempotent self-heal: + drops stale triggers, prunes oplog/row-version rows, logs once at Information when it + actually cleaned something (and stays silent when there was nothing to clean). +- Registration stays per-table in a loop (0.3.0 made the snapshot flag per-table; the + loop preserves that granularity if the pin ever moves). +- **Pin note:** this repo is on `ZB.MOM.WW.LocalDb 0.2.1`, which has both + `baselineExistingRows` and `DeregisterReplicated`. Do NOT bump the pin unless a needed + API is genuinely absent at 0.2.1 — if it is, stop and report before bumping. +- **Traps (both hit by ScadaBridge):** the registered-table set is pinned by + `LocalDbSetupTests` — update the pins deliberately with the behaviour change named in + the test doc-comment; and deregistration must be pair-symmetric — the sync handshake + compares registered-table digests fail-closed, so flipping registration is a + both-nodes-together change. Record the pair-symmetry consequence in CLAUDE.md and in + the rollout note (docker-dev site-a has replication ON and was enabled from fresh, so + current impact is low; the change is correctness-before-someone-enables-late). +- Tests: pin the new predicate both ways (configured ⇒ registered with baseline; + unconfigured ⇒ deregistered/self-healed) and keep the DDL→register ordering pin green. + +--- + +### Task 8: Close-out — sweep + Outcomes + register annotations + +**Classification:** close-out (blockedBy: all) +**Estimated implement time:** ~15 min + +1. Full build (`dotnet build ZB.MOM.WW.OtOpcUa.slnx`) — 0 errors; warning count vs r2's + 904 explained. +2. Full unit sweep, every `*.Tests` project, per-project; reconcile the passed-count + delta against Tasks 1–2's added/changed tests exactly. DB suites must RUN (AdminUI + `0 skipped`, Configuration `0 skipped`). +3. Write `## Outcomes` on this plan: sweep record, per-task table, all four live-gate + evidence excerpts, falsification notes, and this round's register (Modbus + S7-write + asymmetry, TM/CT real-CPU, cross-process reap race carried; whatever Tasks 4–7 leave + open). +4. Annotate the r2 register in `2026-08-17-perf-followups-r2.md` append-only with + "Closed by (r3)" / "Gated live (r3)" sub-bullets. +5. Update the `.tasks.json` ledger; commit docs with explicit pathspec. + +--- + +## Outcomes + +*Written at close-out, 2026-08-18, on branch `perf/followups-r3`. All 10 tasks complete +(8 planned + Tasks 9/10 joined mid-round by amendment `088a1a1e`). This round is a +**follow-up round**: every code item it closes was opened by the round-2 register in +`2026-08-17-perf-followups-r2.md`, and that register is annotated in place with the closing +SHAs. Tasks 9 and 10 are **cross-repo** — rows 38 and 39 of the ScadaBridge deferred-work +register, relayed on Joe's behalf and closed here.* + +### Sweep record + +**The docker-dev rig was torn down BEFORE the sweep** (`docker compose -f +docker-dev/docker-compose.yml down`, 0 `otopcua-dev-*` containers remaining). This is not +housekeeping — a running rig un-skips env-gated tests and would have made the skip count +incomparable to the r2 baseline. It did: `Host.IntegrationTests` reports **229 / 0 / 2** with +the rig up and **226 / 0 / 5** with it down, the same 231 total. + +`dotnet build ZB.MOM.WW.OtOpcUa.slnx --no-incremental` → **0 errors, 904 warnings** — +**identical to r2's 904**, not merely close. The non-incremental flag matters: an incremental +build reported 896 because up-to-date projects re-emit nothing. The two pre-existing families +are unchanged in kind and in count (`OTOPCUA0001` CapabilityInvoker analyzer on test call sites +1012, `xUnit1051` cancellation-token advice 696, plus the small CS tail). **No delta to +attribute** — this round's new test call sites happened to land in files already carrying the +same families, so nothing moved. + +Full unit sweep — every `*.Tests` project, run per-project with `--no-build` after the single +solution build, against the tree at `837d8a17`. `*.IntegrationTests` are build-only by +convention (as in r2); `Host.IntegrationTests` is recorded **separately below** because r2's +baseline did not include it. + +**43 / 43 test projects green.** + +| | Round 2 | **This round** | Δ | +|---|---|---|---| +| Passed | 10 370 | **10 377** | **+7** | +| Failed | 0 | **0** | — | +| Skipped | 19 | **19** | — | +| **Total** | 10 389 | **10 396** | +7 | + +The +7 reconciles **exactly** against the two suites this round added tests to, with nothing +unaccounted for — confirmed at class granularity, not just project granularity: + +| Project | Round 2 | This round | Δ | Source | +|---|---|---|---|---| +| `OpcUaServer.Tests` | 481 | **482** | +1 | `SessionAclDecisionCacheTests` 17 → **18** (T1) | +| `Driver.S7.Tests` | 401 | **407** | +6 | `S7SpanReadParityTests` 13 → **19** (T2) | + +⚠️ **The S7 +6 is the sum of three separate commits, not one addition** — `4c161181` (+3, the +worst-state-wins pins), `b35e423c` (+1, the observe-nothing guard the spec review found), and +`1765e300` (+2, the code-review round's severity-escalation and OCE-flush pins). T3 (docs) and +T4–T7 (live gates) added no tests by design. + +**All 19 skips are the pre-existing env-gated ones, project for project** — `Core.Tests` (1), +`Driver.Galaxy.Tests` (8), `Driver.Historian.Gateway.Tests` (6, the `LiveIntegration` category +needing the `wonder-sql-vd03` VPN), `OpcUaServer.Tests` (1), `Runtime.Tests` (3). **This round +added no skips**, and `Runtime.Tests` is unchanged at 637 / 3 as expected. + +The DB-backed suites ran **against a reachable** `10.100.0.35,14330` — executed, not skipped: +`AdminUI.Tests` **1540 passed / 0 skipped**, `Configuration.Tests` **190 passed / 0 skipped**. + +#### `Host.IntegrationTests` (T9 + T10) — **226 passed / 0 failed / 5 skipped** (231 total) + +Not part of the r2 baseline, so there is no measured predecessor. Derived from the diff against +the merge-base `49d05bc2`, the expected delta is **+9**, all plain `[Fact]` (no theories, so +attribute count equals test count): `LocalDbSetupTests` **7 → 15** (+8) and `LocalDbWiringTests` +**6 → 7** (+1); `RoslynVirtualTagEvaluatorTests` stays **20 → 20** because T9 reworked its +racing test *in place*. ⚠️ **The task brief's "LocalDbSetupTests 13 → 15" was an intermediate +reading** — 13 was the count after `3e62f161` and before the `df533916` review round; against +the merge-base it is 7 → 15. The 5 skips are the rig/fixture-gated +`DriverTestConnectE2eTests` (2, Modbus fixture) and `DriverProbeHandshakeE2eTests` (3) — three +of which run when the rig is up, which is exactly the teardown effect noted above. + +#### ⚠️ One flake, isolated and cleared — `Client.CLI.Tests` + +The first sweep pass reported `Client.CLI.Tests` **1 failed / 103 passed**: +`LoggerLifecycleTests.ConfigureLogging_DisposesPreviousLogger_BeforeReassigning`, asserting +`trackerSink.Disposed` was `False`. **Isolation re-runs cleared it: the single test alone +1/1 green, and the whole project green twice more (104 / 104 both times).** + +The mechanism is a **pre-existing intra-assembly race on the process-global +`Serilog.Log.Logger` static**, not a regression: the test assigns `Log.Logger` at +`LoggerLifecycleTests.cs:26` and then asserts, at `:41`, that the command's `ConfigureLogging` +disposed *that* instance — but the class carries no `[Collection]` and no +`DisableTestParallelization`, so any concurrently-scheduled test whose command path also calls +`ConfigureLogging` (which does `Log.CloseAndFlush()` then reassigns) can swap the global out +from under it in that window. **No commit in this round touches `src/Client` or `tests/Client`** +(`git log 49d05bc2..HEAD -- src/Client tests/Client` is empty). Recorded here rather than in +the register, which the close-out brief scoped explicitly; it is a worthwhile one-line fix +(pin the class to a serial collection) whenever someone is next in that file. + +### Per-task outcomes + +| # | Task | Commit(s) | Outcome + deviation | +|---|---|---|---| +| 1 | ACL `InvalidateIfStale` — monotonic-max CAS loop | `441b34a3`, `f4b91dbb`, `e29fab19` | Done; closes the r2 register's deferred-publication item. ⚠️ **The plan's own 200-round `Barrier` harness was measured GREEN-ON-DEFECT** (~1-in-19k hit rate — `Barrier`'s post-phase release hands one racer a head start), so it was rebuilt as long-lived racers with a third-thread release store: 25–50 % of rounds red, falsification red at rounds 1–13. 10 000 rounds kept over the reviewer's suggested 2 000 after measuring a **1-in-3 vacuous pass at 2 000** under full-suite parallelism (misses burst-correlate). 18/18. | +| 2 | S7 read-pass health — worst-state-wins | `4c161181`, `b35e423c`, `1765e300` | Done; closes the r2 register's last-writer-wins item **for the S7 READ path only** (asymmetry recorded below). The spec review found a second defect in-round — an **empty pass that observed nothing must report nothing**, or it clears a live `Faulted`. The code review then found that the OCE arms skipped the end-of-pass write and froze `LastSuccessfulRead`; the coordinator ruled the OCE path must **flush** the recorded pass evidence via `finally`, which is what protects the watchdog contract. Five falsifications, each red on its own test. 19/19. | +| 3 | Stale `OTOPCUA_CONFIG_MODE` docs | `e9ba1741` | Done as specified; compose facts verified before editing. Historical plan docs deliberately untouched. Trivial ⇒ no review. | +| 4 | Live gate — first-POST 404 + no-body POST | `3f04a4d4` | **PASSED — and the 404 mechanism is now NAMED**, closing an r2 register item the gate was only expected to instrument. Detail below. | +| 5 | Live gate — FetchAndCache legs | *(none — gate only)* | **PASSED, all six legs.** Detail below. | +| 6 | Live gate — alarm-bearing surgical ratchet | *(none — gate only)* | **PASSED, all four routings.** Detail below. | +| 7 | Live gate — ACL-enabled enforcement | *(none — gate only)* | **PASSED**, with a topology adaptation and two non-blocking findings. Detail below. | +| 9 | Roslyn evaluator racing test — remove the timing assumption | `34829ea0`, `837d8a17` | Done. **Cross-repo: ScadaBridge deferred-work register row 38**, relayed 2026-08-18. Detail below. | +| 10 | LocalDb conditional registration + baseline + deregister self-heal | `3e62f161`, `df533916` | Done. **Cross-repo: ScadaBridge deferred-work register row 39.** No pin bump. **The scadaproj umbrella index was updated and pushed to `main` as `1145df6`.** Detail below. | +| 8 | Close-out — sweep + Outcomes + register annotations | *this commit* | Done. Rig torn down first, full build + sweep, this Outcomes section, and the append-only r2 register annotations. | + +### Task 4 — the first-POST 404, mechanism CONFIRMED + +**2026-08-18, local OrbStack docker-dev rig built from the branch tip. Two results, and the +second is the one that matters.** + +- **The prescribed fresh-boot run did NOT reproduce the 404** — the entire Traefik access log + for the boot window was **3 lines, all 2xx**, every one carrying + `RouterName = otopcua-admin@file`. ⚠️ **And `deploy.sh` under `up -d` can never reproduce + it**: Compose blocks on the `depends_on: service_healthy` chain, so `up -d` returned ~30 s + *after* Traefik started and the first poll landed long after the window closed. +- **So the window was exercised directly** — rapid-poll (~10 ms) across + `docker restart otopcua-dev-traefik-1`, twice. Result: `000` (port unbound) → **`404` for + ~65–160 ms** → `200`. Body is exactly `404 page not found` (Go's `http.NotFound`), and the + access-log signature is the discriminator the r2 round asked for: **`RouterName = "-"`, + `ServiceName = "-"`, `0ms`** — no router matched, no backend dialled. +- **NAMED MECHANISM: the window between Traefik binding the `web` entrypoint and loading the + dynamic file-provider config from `/etc/traefik/dynamic.yml`.** The listener accepts + connections before the router table exists. +- **The competing candidate is excluded on evidence, not argument** — a health-checked service + with no healthy server yet would be a *matched* router answering **503**; there are **zero + 503s** anywhere in the session's access log. +- ⚠️ **Caveat now recorded in both `deploy.sh` and the README: not all 404s are + access-logged.** Probe 1's seven 404s produced **zero** log lines; probe 2's produced 4 of 7. + The accesslog handler is itself part of the dynamic chain that has not been built yet, so + **an empty access log does NOT prove the 404 did not happen.** +- **No-body POST binding — VERIFIED**, four request shapes (script stdin, no data flag at all, + explicit empty body, valid JSON), all reaching the handler. The minimal-API `DeployRequest?` + **binds null**; it does not 400 and does not 415. A clean post-seal run returned **HTTP 202 + `Accepted`**, and the DB confirms the null took the fallback: `CreatedBy = rest-api`. + +### Task 5 — FetchAndCache, all six legs + +**PASSED. Two independent full cycles** (deploy `1e990163` rev `0b9289fb`, then the revert +deploy `da56012f` rev `315de861`), both sealed `acks=6`. + +- **Fetch + SHA-verify:** all four site nodes — + `Fetched + verified artifact for 1e99016312004ceca5f73aaba2c899b1 from http://central-1:4055 (1584 bytes).` + The template only logs *after* the SHA-256 == RevisionHash check, so its presence is the + verify proof. The byte count tracked the composition (1584 → 1468 on revert). +- **Serve (central):** four `Served artifact for … (1584 bytes, 1 chunks)` on `central-1`. +- **Applied-from-fetch + cached:** the **`applied fetched deployment`** variant on every site + node — and the two `Direct` central nodes emitted the plain `applied deployment` form on the + *same* deploy, which is the falsification control that the two templates are distinguishable. +- **Boot-from-cache:** after `restart site-a-1`, + `FetchAndCache boot — restored served state for deployment 1e9901… (rev 0b9289fb…) from the LocalDb pointer.` + — the wanted variant, not the empty-cache or failed-pointer ones, matching what the node + cached 52 s earlier. +- **Absence proof** over the node's whole 302-line lifetime: `entering Stale` **0**, any + `stale` **0**, `ConfigDb back` **0**, Direct-form apply **0**, and `[ERR]`/`[WRN]`/`[FTL]` + **0**. ⚠️ The Direct-form check must anchor on `": applied deployment "` — a naive + `grep "applied deployment"` matches the *cache* template and reports a false positive. +- **Bonus:** a post-restart browse showed both namespaces live (`ns=2` raw + `ns=3` UNS) + including the temporary gate area — proof the node materialised the address space from the + artifact it fetched and restored, not from a stale cache. +- ⚠️ **Method note worth carrying:** **same-revision deploys short-circuit the fetch path** + entirely (`DriverHostActor.HandleDispatchFromSteady` immediate-ACK). A bare re-run of this + gate on unchanged config shows **zero fetch lines** and that is not a failure — force a new + revision first. The gate did so with a temporary `UnsArea` row, then reverted; the revert + deploy came back **byte-identical** to the pre-gate revision. + +### Task 6 — the alarm-bearing surgical ratchet, four deploys + +**PASSED. All four applier lines emitted identically on `central-1` and `central-2`**, every +deploy sealed 6/6: + +| Step | Lever | Applier line | Verdict | +|---|---|---|---| +| 1 | `AccessLevel` ReadWrite → Read | `kind=AttributeOnly, changed=1, surgicalRawTags=1, rebuild=False` | surgical ✅ | +| 2 | alarm ADD | `kind=Rebuild, changed=1, surgicalRawTags=0, rebuild=True` | rebuild ✅ (`Alarm != null` current side) | +| 3 | alarm REMOVE | `kind=Rebuild, changed=1, surgicalRawTags=0, rebuild=True` | rebuild ✅ (**previous** side also disqualifies) | +| 4 | `AccessLevel` Read → ReadWrite | `kind=AttributeOnly, changed=1, surgicalRawTags=1, rebuild=False` | surgical ✅ — **the ratchet is per-deploy, not latched** | + +- **Deviation, and why it is sound:** the rig's ConfigDb holds exactly **one** `Tag` row, so + TagS and TagA are the same tag exercised sequentially. Each step is an independent deploy + producing exactly **one** raw-tag delta over orthogonal fields, so every verdict is + unambiguous; a second tag would have added an *added-node* delta for no gain. +- **Proven at the artifact seam, not just the log:** each `Deployment.ArtifactBlob` was pulled, + gunzipped and semantically diffed — **each step's artifact differs by exactly the intended + lever and nothing else.** +- **Only the cluster-MAIN nodes emit an applier line.** Site nodes acked every deploy but + logged nothing: `DeploymentArtifact.ResolveClusterScope` self-scopes the fleet-wide artifact, + the site plan is empty, and `Apply` early-returns on `plan.IsEmpty` before the summary log. + Confirmed they *did* process each artifact via their authority-generation lines. +- ⚠️ **A live-gate fact worth knowing for every future rig gate: the revision hash can never + return to its baseline after any `UPDATE`.** `ConfigComposer` snapshots the SQL Server + `rowversion` column into the artifact, and `rowversion` increments on every `UPDATE` including + one that writes back an identical value. A byte-diff confirmed `RowVersion` was the **only** + difference in the entire 4922-byte artifact. Semantic restore was verified instead (config + hash back to `7F75AB45…`, rowcount unchanged). + +### Task 7 — ACL-enabled enforcement, first live run since the cache re-shape + +**PASSED**, with a forced topology adaptation and two findings. + +- ⚠️ **The planned gated node was not executable.** `site-a` serves **containers only** — the + rig's single tag belongs to cluster **MAIN**, so `site-a-1`'s authority generation always + reports `keys=0, grants=0, resolvedScopes=0` and there is no writable value node to authorize. + The gate moved to **`central-1`** (fused `admin,driver,cluster-MAIN`, serving + `ns=2;s=pymodbus/plc/HR200`) via a **scratchpad-only compose overlay** — the repo compose + file was never edited — with **`central-2` as the ungated A/B control**. Consequence recorded: + central-1 is a ConfigDb node so *key* revocation is immediate rather than next-deployment; + **grants still arrive only via the artifact**, so the code actually under test is exercised + as intended. +- **Authoring fell back to direct ConfigDb INSERT** (the Chrome extension was not connected). + `ApiKeySecret.Generate` was reproduced from source and the pepper read live off the container; + the construction is proven correct because the server accepted the key. +- **The ALLOW leg is genuinely load-bearing, because the ungated baseline was captured first.** + The *identical* key and call on the *ungated* node returned `0x801F0000` — the `Tag`-scoped + grant confers no role, so `ApiKeyInterimRoleMapper` leaves the session with `roles []` and the + server-wide gate denies. With the gate on, the same call returned **`Write successful`**. + That is the live demonstration that **the ACL decision REPLACES the role check** rather than + chaining with it — a deny-only gate would have passed against a build that never consults the + ACL. +- **Denials fail closed:** anonymous write and read both `0x801F0000` with + `AclGate: Read withheld 1 of 1 node(s) for principal anonymous`; out-of-scope browse refused; + the ungated control node still open on the same NodeId. +- **Revocation was split into its two distinct code paths, and only the first tests this + round's fix.** *Grant removal* → generation **1 → 2**, `grants=0, resolvedScopes=0`, a + deliberately **primed** decision cache discarded, and the denial arrives while + `ApiKeyAuth: granted` still logs — that is the per-key-shard/CAS-loop path. *Key disable* → + `0x80210000` `BadIdentityTokenRejected` and + `ApiKeyAuth: denied — no enabled, unexpired key with id …` — a different status, because the + session never activates and never reaches the gate. +- **Restore verified by hash:** the post-task revision returned to the exact pre-task + `a3a9061bbf50…`, with 0 `ApiKey` / 0 `NodeAcl` rows and the ENABLED warning gone. + +### Task 9 — the racing test, and an honest disclosure + +Renamed to `Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure` and +re-shaped around **three-bucket classification** (leaked ⇒ fail on first; exhausted and starved +each bounded at `max(evals/10, 8)`) with duration-bounded loops (10 s **or** 400 iterations). + +- ⚠️ **The real load failure was not the one the ticket described.** It was the test's own 45 s + `WaitAsync` budget expiring under recompile pressure, not the retry legitimately exhausting. + Old shape: **RED 4/4** at 4-way concurrency. New shape: **GREEN 4/4, then 8/8**. +- The review found a further flake vector — `TimedScriptEvaluator`'s 5 s clock starts at + **enqueue**, so a starved evaluation can time out without any product fault. Closed and + falsified with a 12 ms-budget probe (old classification RED, new GREEN at a 0.11 % starve rate). +- Failure-reason literals were promoted to a shared `ScriptEvalFailureReasons` in Commons, used + by both evaluators and the test. +- ⚠️ **Disclosed honestly: the disposed race does not reproduce on this arm64 macOS box at + all.** The raw-escape assertion is the load-independent guarantee; the exhaustion/starvation + bounds are calibrated loose (see the register). + +### Task 10 — LocalDb registration now follows replication config + +Ported from ScadaBridge's WP1.3/WP3.3 pattern. Predicate = **`PeerAddress` OR `ApiKey`** +(`SyncListenPort` deliberately excluded — the passive endpoint fails closed on the key). +Configured ⇒ `RegisterReplicated(table, baselineExistingRows: true)` per table in the pinned +DDL→register order; not configured ⇒ `DeregisterReplicated` on every table at boot as an +idempotent self-heal. The `CLAUDE.md` bullets that recorded the *unconditional* shape as +deliberate were rewritten in the same commit. + +- **No pin bump.** The 0.2.1 APIs were verified by reflection **and** a live probe (baseline + seeds `hlc=0`; `DeregisterReplicated` returns `bool`) rather than assumed from the changelog. +- **Two vacuous-fixture bugs were surfaced and fixed** in passing (`LocalDbPairHarness`, and an + `AlarmSfLegacyMigrator` two-config split) — fixtures that would have let the new predicate + pass without being exercised. +- **Pair-symmetry is the operational trap**, recorded in `CLAUDE.md` and the runbook: the sync + handshake compares registered-table digests fail-closed, so flipping registration is a + **both-nodes-together** change. +- The scadaproj umbrella index was updated and **pushed to `main` as `1145df6`**, per the + standing cross-repo rule. + +### Review chain + +9 implementers; **12 review verdicts** across the 4 reviewed code tasks (T1 spec + code + +delta re-review; T2 spec + code + delta re-review; T9 spec + code + delta re-review; T10 spec + +code + delta re-review); **4 fix rounds**; **2 CHANGES REQUESTED** (T2, T9). T3 was trivial +(doc-only ⇒ no review) and T4–T7 are live gates with no code to review. **Zero findings papered +over**; one coordinator ruling (T2's OCE flush). + +Three **evidence-hygiene** lessons from this round, all worth carrying forward: + +- ⚠️ **A race harness can be green-on-defect, and you must measure its hit rate to know.** + T1's plan-supplied `Barrier` harness "passed" at ~1-in-19 000 — it looked like a working test. + Only measuring the hit rate exposed that `Barrier`'s post-phase release hands one racer a head + start. **Round count is a function of the measured hit rate under full-suite parallelism**, not + a round number: 2 000 rounds was measured vacuous 1 time in 3 because misses burst-correlate. +- ⚠️ **Tear the rig down before a comparison sweep.** A running rig silently un-skips env-gated + tests; the r2 skip count is only comparable because the rig was down for both. +- ⚠️ **Name the version of a count you are quoting.** The "13 → 15" in this round's own close-out + brief was a mid-round reading; against the merge-base it is 7 → 15. Intermediate counts drift + the moment a review round lands. + +### Follow-up register (opened by this round) + +Only genuinely **new or still-open** items. Everything this round closed is annotated on the +round-2 register. **None of these blocks the branch.** + +**ACL** + +- ⚠️ **Browse transit stops below the realm root — a grant-holding client cannot browse down to + its own granted tag.** With the gate on, the key browses `ns=2;s=pymodbus` and + `ns=2;s=pymodbus/plc` fine but is refused `0x801F0000` on `ns=2;s=OtOpcUa` and on a recursive + browse from the Objects root. `PermissionTrieNode.BrowseTransitPrincipals` marks the ancestors + lying on the tag's **RawPath**; the synthetic realm root sits *above* the RawPath space and is + not in the trie at all. It **fails closed** (not a security hole) and blocked no leg, but it + would make an ACL-enabled deployment look broken to any browse-driven client — including the + Client.CLI's own default recursive browse. Discovered by the T7 live gate. **RECOMMEND filing a + Gitea issue before anyone enables `Security:Acl:Enabled` in production.** Likely fix: mark the + realm-root container browse-transit whenever any grant resolves beneath it. +- **`ns=0` standard nodes are ungated — the boot warning overstates.** With the gate on, both + the key and anonymous read `i=2256` and browse `i=2253` successfully: those are served by the + SDK's `CoreNodeManager` and never reach `DataPlaneAuthorizer`. Defensible (standard server + metadata, no process data), but "A principal with no grant can connect and see **nothing**" + is not literally true. Informational — a doc softening or a deliberate decision to gate ns=0. + +**S7** + +- **`_health` remains a plain field, versus Modbus's `Volatile.Read`/`Volatile.Write` idiom.** + Pre-existing, but **more of an outlier now** that the read pass consolidates to a single + end-of-pass write — the one place an alignment would be cheap and obvious. Follow-up + alignment, not a correctness claim. +- **Worst-state-wins landed for the S7 READ pass only.** Modbus (all paths) and the S7 **WRITE** + path keep last-writer-wins. **Deliberate scope** — both were named out of scope in this plan + because fixing them here doubles the blast radius of a watchdog-adjacent change. Recorded as a + known asymmetry so the next reader does not mistake it for an oversight. + +**LocalDb** + +- **`ZB.MOM.WW.LocalDb 0.3.1` is published to the Gitea feed** (per-table snapshot flags + a sync + fault-teardown fix). **This repo deliberately stays on `0.2.1`** — the 0.2.1 APIs cover + everything Task 10 needed, verified by probe. The per-**database** snapshot caveat is documented; + 0.3.x makes it per-table. ⚠️ A bump is a **both-nodes-together** change (bookkeeping schema + v2 → v3 is one-way), so it wants a planned window, not an incidental pin edit. + +**FetchAndCache** + +- **`central-2`'s serve path was never exercised live.** All four site nodes resolved + `central-1:4055` first and stopped there — the documented walk-in-order, stop-at-first-success + behaviour, so central-2 served nothing. Not a fault; simply an untested half of the pair. + +**Scripting / test calibration** + +- **The disposed race does not reproduce on this arm64 macOS box at all.** The raw-escape + assertion is the load-independent guarantee and holds regardless; the **exhaustion and + starvation bounds are calibrated loose** on a machine that cannot produce the phenomenon they + bound. They would benefit from a Linux-CI observation to tighten. + +**Test reliability** + +- **`Client.CLI.Tests` `LoggerLifecycleTests.ConfigureLogging_DisposesPreviousLogger_BeforeReassigning` + is flaky under intra-assembly parallelism** — observed once in the r3 close-out sweep, green in + isolation (1/1) and on two whole-project re-runs (104/104). Mechanism: a pre-existing race on the + process-global `Serilog.Log.Logger` — the class carries no `[Collection]`, so a concurrent test's + `ConfigureLogging` (`CloseAndFlush` + reassign) can swap the global between arrange and assert. + No r3 commit touches `src/Client` or `tests/Client`. One-line fix when picked up: pin the class + to a serial collection. + +**Carried from round 2, still open** + +- **TM/CT decode at a non-zero device number still needs a real S7 CPU.** The test exists and the + env var (`S7_TIMER_NUMBER_ADDRESSING=1`) is ready; python-snap7 resolves TM/CT as a BIT address + and cannot serve it. +- **The cross-*process* plant-vs-reap race on the shared SQL server is accepted.** The 24 h age + floor is the mitigation; a lock table on a shared dev server costs more than it buys. + +### Round-2 register items CLOSED by this round + +- **ACL single-shot CAS deferred publication** → closed by **`441b34a3`** (T1). +- **S7 per-item decode health last-writer-wins** → closed by **`4c161181` + `b35e423c` + + `1765e300`** (T2), for the **read path**; the write-path and Modbus asymmetry is recorded above. +- **docker-dev first-POST 404** → **mechanism NAMED** by **`3f04a4d4`** (T4), and the **no-body + POST binding VERIFIED** by the same commit. diff --git a/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json b/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json new file mode 100644 index 00000000..10258dd7 --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json @@ -0,0 +1,17 @@ +{ + "planPath": "docs/plans/2026-08-17-perf-followups-r3.md", + "tasks": [ + {"id": 1, "subject": "Task 1: ACL InvalidateIfStale — monotonic-max CAS loop", "status": "completed", "note": "441b34a3 + f4b91dbb (review round: hit diagnostics via ITestOutputHelper, idiom comments) + e29fab19 (coordinator: comment-fact fix). Spec ✅ + code APPROVED + delta re-APPROVED. Key learning: the plan's 200-round Barrier harness was measured GREEN-ON-DEFECT (~1/19k hit rate — Barrier post-phase release hands one racer a head start); rebuilt as long-lived racers + third-thread release store (25-50% rounds red, falsification red at rounds 1-13). 10,000 rounds kept over the reviewer's 2,000 after measuring a 1-in-3 vacuous pass at 2,000 under full-suite parallelism (misses burst-correlate). Suite 481→482/1 skip"}, + {"id": 2, "subject": "Task 2: S7 read-pass health — worst-state-wins aggregation", "status": "completed", "note": "4c161181 + b35e423c (observe-nothing guard, spec-review-found) + 1765e300 (code-review round: WorstError re-points on severity escalation; OCE now FLUSHES recorded pass evidence via finally — coordinator ruling, protects the watchdog LastSuccessfulRead contract; HasObservations; poison precondition pin). Spec ✅ + code CHANGES REQUESTED → delta re-APPROVED. Suite 401→407. Falsifications: last-writer revert (4 red), timestamp-gate (3 red), guard removal (1 red), escalation revert (red on PUT/GET message), flush revert (timestamp frozen). Register: Modbus + S7-write-path last-writer-wins asymmetry deliberate; S7 _health Volatile alignment deferred"}, + {"id": 3, "subject": "Task 3: Fix stale OTOPCUA_CONFIG_MODE docs", "status": "completed", "note": "e9ba1741; docs/Configuration.md:253 + CLAUDE.md:554 rewritten (compose facts verified first); historical plan docs deliberately untouched; trivial => no review"}, + {"id": 4, "subject": "Task 4: Live gate — first-POST-404 catch + no-body POST binding", "status": "completed", "note": "3f04a4d4 (README + deploy.sh). 404 MECHANISM NAMED: window between Traefik binding the web entrypoint and loading the dynamic file-provider config — listener accepts before the router table exists; Go '404 page not found', empty RouterName/ServiceName/0ms; 503-candidate excluded (zero 503s in session). Caught via rapid-poll across docker restart traefik (2×, 65-160ms window) — deploy.sh under up -d can NEVER ride the window (depends_on service_healthy returns ~30s after traefik start); ⚠️ not all 404s are access-logged (the accesslog handler is part of the not-yet-built chain) — documented. No-body POST: binds null, 202 Accepted, CreatedBy=rest-api fallback confirmed in DB. Rig left UP; first deploy raced site-b-2 boot (failure status) — T5 evidence must use the later acks=6 deploys"}, + {"id": 5, "subject": "Task 5: Live gate — FetchAndCache legs", "status": "completed", "note": "GATE PASSED, no commit. All 6 legs: fetch+SHA-verify on all 4 site nodes (1584 bytes from central-1:4055), Served×4 central-side, applied-FETCHED + cached on site-a-1 (acks=6), boot-from-cache after restart (restored rev matches what it cached 52s earlier), absence proof (0 Stale/ConfigDb-back/Direct-form/ERR/WRN over full lifetime), post-restart browse proves both namespaces materialised (ns=2 raw + ns=3 UNS). Method: same-revision deploys short-circuit the fetch path (immediate-ACK at HandleDispatchFromSteady) — gate forced a temp UnsArea row then reverted; rig config restored byte-identical (rev 315de861). Register: central-2 serve path unexercised (first-success endpoint walk always hit central-1)"}, + {"id": 6, "subject": "Task 6: Live gate — alarm-bearing surgical ratchet", "status": "completed", "note": "GATE PASSED, no commit. Four deploys, all routings correct: Writable flip ⇒ kind=AttributeOnly surgicalRawTags=1 rebuild=False; alarm ADD ⇒ kind=Rebuild rebuild=True; alarm REMOVE ⇒ rebuild=True (previous-side disqualifies); restore ⇒ surgical again (ratchet per-deploy, not latched). All sealed 6/6 acks. Authoring: direct UPDATE on the rig's OWN sql container (Database=OtOpcUa — NOT 10.100.0.35; sqlcmd needs -I for QUOTED_IDENTIFIER). Findings: only cluster-MAIN nodes emit applier lines (site plans empty via ResolveClusterScope, apply early-returns); artifact hash can never return to baseline after any UPDATE — ConfigComposer snapshots SQL rowversion (verified by gunzip+diff: only the RowVersion differs). Rig config semantically restored; rig UP"}, + {"id": 7, "subject": "Task 7: Live gate — ACL-enabled enforcement on site-a", "status": "completed", "note": "GATE PASSED, no commit. TOPOLOGY ADAPTATION: gated node = central-1 via scratchpad-only compose overlay (site-a serves NO value nodes — the rig's one tag is cluster MAIN; central-2 became the ungated A/B control). ALLOW leg genuinely load-bearing: ungated baseline captured first — same key+call DENIED 0x801F0000 with ACL off (Tag grant confers no role), SUCCEEDED with ACL on ⇒ ACL decision REPLACES the role check, live. Deny×3 (anonymous write, out-of-scope browse, ungated control reads fine); revocation split into grant-removal (gen 1→2, primed per-key shard discarded — exercises this round's CAS-loop path) and key-disable (pre-cache re-check). Authoring: DB fallback (Chrome extension not connected) — ApiKeySecret hashing reproduced from source, pepper verified live. Restore byte-identical (rev a3a9061b), zero residue. FINDINGS for register: (1) browse transit stops below the realm root — grant holder cannot browse DOWN to its own tag from ns=2;s=OtOpcUa (fails closed; file as issue); (2) ns=0 core nodes are ungated (CoreNodeManager bypasses DataPlaneAuthorizer) — boot warning overstates 'see nothing'"}, + {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "completed", "blockedBy": [1, 2, 3, 4, 5, 6, 7, 9, 10], "note": "c4d6cba7 (Outcomes + sweep record + r2 register annotations, +383/−0) + the coordinator's flake-register append. Rig torn down BEFORE the sweep (rig-up skews skips: Host.IntegrationTests 229/0/2 up vs 226/0/5 down). Build 0 errors / 904 warnings — IDENTICAL to r2 (note: incremental builds under-report at 896). Sweep 43/43 green: 10,377 / 0 / 19 — +7 reconciled exactly (OpcUaServer +1 T1, S7 +6 T2); skips identical project-for-project; AdminUI 1540/0-skipped + Configuration 190/0-skipped ran vs 10.100.0.35,14330. Host.IntegrationTests (outside the 43-project baseline) +9 vs merge-base (LocalDbSetupTests 7→15, WiringTests 6→7). One flake isolated: Client.CLI LoggerLifecycleTests — pre-existing global-Serilog race, no r3 commit touches it, registered"} + {"id": 9, "subject": "Task 9: Roslyn evaluator racing test — remove timing assumption (ScadaBridge row 38)", "status": "completed", "note": "34829ea0 + 837d8a17 (review round). Option (b): renamed to Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure; three-bucket classification (leaked=fail-first, exhausted + starved each bounded max(evals/10,8)); duration-bounded loops (10s OR 400 iters) — the REAL load failure was the test's own 45s WaitAsync budget under recompile pressure (old shape RED 4/4 at 4-way concurrency, new GREEN 4/4 + 8/8); reviewer-found starvation-timeout flake vector closed (TimedScriptEvaluator's 5s clock starts at enqueue), falsified via 12ms-budget probe (old classification RED, new GREEN at 0.11%); literals promoted to shared ScriptEvalFailureReasons in Commons (both evaluators + test). Honest disclosure: disposed race does not reproduce on this arm64 box at all. Spec ✅ + code CHANGES REQUESTED → delta re-APPROVED. Host.IntegrationTests 229/0/2, Calculation 53/53"}, + {"id": 10, "subject": "Task 10: LocalDb conditional registration + baseline + deregister self-heal (ScadaBridge row 39)", "status": "completed", "note": "3e62f161 + df533916 (review round: content-based data-survival pin, mid-loop loud-fail pin via exhaustive delegating fake, Log.Logger assumption comment). Spec ✅ + code APPROVED + delta re-APPROVED. Predicate = PeerAddress OR ApiKey (SyncListenPort deliberately out — passive endpoint fail-closed on key); 0.2.1 APIs verified by reflection+probe (baseline seeds hlc=0; DeregisterReplicated returns bool) — NO pin bump; 0.3.1 now published (ScadaBridge heads-up) — bump recorded as deliberate both-nodes-together future change (bookkeeping v2→v3 one-way). Surfaced+fixed two vacuous-fixture bugs (PairHarness/AlarmSfLegacyMigrator two-config split). scadaproj index updated + pushed (1145df6). Suites: LocalDbSetupTests 15/15, Host.IntegrationTests 226/0/5"} + ], + "closeOut": "Round 3 (perf/followups-r3) complete: 7 implementation/gate tasks + 2 cross-repo tasks + close-out, all 10 green. Landed: T1 ACL monotonic-max CAS loop — publication never deferred (441b34a3, f4b91dbb, e29fab19; the plan's own 200-round Barrier harness was measured green-on-defect and rebuilt); T2 S7 worst-state-wins read-pass health with WorstError severity re-pointing and OCE evidence flush (4c161181, b35e423c, 1765e300); T3 stale OTOPCUA_CONFIG_MODE docs (e9ba1741); T4 first-POST-404 MECHANISM NAMED — Traefik entrypoint-bound-before-dynamic-config window, some 404s never access-logged; no-body POST binds null/202 (3f04a4d4); T5 FetchAndCache all six legs PASSED (same-revision deploys short-circuit the fetch path — gates must force a revision); T6 alarm ratchet all four routings PASSED (per-deploy, not latched; artifact hash can never return to baseline — rowversion is snapshotted); T7 ACL-enabled enforcement PASSED on central-1 (site-a serves no value nodes) with an ungated-baseline-first ALLOW proving the ACL replaces the role check, grant-revocation exercising the new CAS path live; T9 ScadaBridge row 38 — Roslyn racing test de-flaked, three-bucket classification, shared ScriptEvalFailureReasons consts (34829ea0, 837d8a17); T10 ScadaBridge row 39 — LocalDb conditional registration + baseline + deregister self-heal on 0.2.1, pair-symmetry documented (3e62f161, df533916; scadaproj index pushed 1145df6; both ScadaBridge register rows confirmed closed by that session). Review chain: 9 implementers (incl. resumed hot-context fix rounds across a session-limit interruption), 12 review verdicts, 5 fix rounds, 2 CHANGES REQUESTED both resolved, zero findings papered over. Sweep 10,377/0/19 across 43/43 (+7 reconciled exactly), build 0 errors/904 warnings identical to r2. Open r3 register (none blocking): ACL browse-transit-below-realm-root (RECOMMEND Gitea issue before enabling ACL in production), ns=0 ungated boot-warning overstatement, S7 _health Volatile alignment, Modbus/S7-write last-writer-wins asymmetry (deliberate), LocalDb 0.3.1 available (both-nodes-together bump), central-2 serve path unexercised, Roslyn bounds want a Linux-CI observation, Client.CLI logger flake (serial-collection one-liner), carried TM/CT real-CPU + cross-process reap race.", + "lastUpdated": "2026-08-18T13:40:00Z" +} diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs index 78d5ff4a..7864246c 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs @@ -37,6 +37,36 @@ public sealed record VirtualTagEvalResult(bool Success, object? Value, string? R public static VirtualTagEvalResult Failure(string reason) => new(false, null, reason); } +/// +/// Failure reasons the script evaluators put on and that +/// callers / tests classify on. The two evaluators — RoslynVirtualTagEvaluator (virtual tags) +/// and CalculationEvaluator (calc tags) — are deliberate mirrors of one another, so these +/// strings are a shared contract rather than two coincidentally-equal literals. They lived as three +/// unshared copies (the two evaluators plus a test const); a reader could not tell the contracts were +/// meant to be identical, and drift on one side would silently break a classifier keyed on the other. +/// Only the reasons something outside the evaluator matches on live here — the purely descriptive ones +/// (compile error:, sandbox violation:, script threw:) stay inline. +/// +public static class ScriptEvalFailureReasons +{ + /// + /// The evaluator's one-shot retry was exhausted: a SECOND concurrent apply-boundary + /// ClearCompiledScripts disposed the compiled script inside the same evaluation. This is the + /// documented, well-formed outcome of losing that race twice — distinct from an + /// escaping to the generic catch as "script threw: …", + /// which is a bug. + /// + public const string EvaluatorDisposedDuringEvaluation = "evaluator disposed during evaluation"; + + /// + /// Prefix of the wall-clock-timeout failure; the evaluator completes it with the budget it applied + /// ("{seconds:F1}s"). Note the timeout covers the enqueue too — TimedScriptEvaluator + /// starts its clock at WaitAsync, not when the inner Task.Run gets a thread — so on a + /// starved pool this reason can mean "never got to run", not "ran too long". + /// + public const string TimedOutPrefix = "script timed out after "; +} + /// Returns from every call. Bound by default /// when the production VirtualTagEngine adapter hasn't been registered (Mac dev, tests). public sealed class NullVirtualTagEvaluator : IVirtualTagEvaluator diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs index b3f069cf..b2077008 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs @@ -148,7 +148,8 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } catch (ScriptTimeoutException) { - return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s"); + return VirtualTagEvalResult.Failure( + $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { @@ -159,7 +160,7 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } catch (ObjectDisposedException) { - return VirtualTagEvalResult.Failure("evaluator disposed during evaluation"); + return VirtualTagEvalResult.Failure(ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); } catch (Exception ex) { diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs index 6dd2a123..bed5e1bc 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs @@ -544,6 +544,9 @@ public sealed class S7Driver RequireInitialized(); var now = DateTime.UtcNow; var results = new DataValueSnapshot[fullReferences.Count]; + // Health is decided ONCE, at the end of the pass, from every outcome the pass observed — + // never per item. See ReadPassOutcome. + var outcome = new ReadPassOutcome(); await _gate.WaitAsync(cancellationToken).ConfigureAwait(false); try @@ -612,7 +615,7 @@ public sealed class S7Driver perTag.Add(span.Members[0].OriginalIndex); continue; } - await ReadSpanAsync(plc, span, results, now, cancellationToken).ConfigureAwait(false); + await ReadSpanAsync(plc, span, results, now, outcome, cancellationToken).ConfigureAwait(false); } perTag.AddRange(plan.LeftoverIndexes); } @@ -635,7 +638,7 @@ public sealed class S7Driver if (_options.SpanReadMaxGapBytes >= 0) { perTag = await ReadLeftoversByMultiVarAsync( - plc, resolved, perTag, results, now, cancellationToken).ConfigureAwait(false); + plc, resolved, perTag, results, now, outcome, cancellationToken).ConfigureAwait(false); } foreach (var i in perTag) @@ -644,7 +647,7 @@ public sealed class S7Driver { var value = await ReadOneAsync(plc, resolved[i]!, cancellationToken).ConfigureAwait(false); results[i] = new DataValueSnapshot(value, 0u, now, now); - _health = new DriverHealth(DriverState.Healthy, now, null); + outcome.RecordSuccess(); } catch (OperationCanceledException) { @@ -660,14 +663,131 @@ public sealed class S7Driver } catch (Exception ex) { - results[i] = new DataValueSnapshot(null, RecordReadFailure(ex), null, now); + results[i] = new DataValueSnapshot(null, RecordReadFailure(ex, outcome), null, now); } } } - finally { _gate.Release(); } + finally + { + // THE single health write of the pass — worst-state-wins over every outcome recorded + // above. In a FINALLY, so evidence the pass already gathered survives an abandoned + // batch: the three OCE arms rethrow mid-pass, and on a partially-working device a + // repeatedly-cancelled poll would otherwise freeze LastSuccessfulRead while tags were + // demonstrably still being read — tripping the comms-loss watchdog into a reconnect + // loop, the exact false positive the AnySuccess design exists to prevent. + // + // A pass that observed NOTHING reports nothing (HasObservations), which is also what + // makes flushing here safe on the two paths that reach the finally with no outcomes: + // the connect-failure early return, whose own Degraded write must NOT be overwritten, + // and an OCE that fired before any tag was stamped. Both no-op. + // + // LastSuccessfulRead advances whenever ANYTHING read, even into a Degraded/Faulted + // state — see ReadPassOutcome for why that is load-bearing. + if (outcome.HasObservations) + { + _health = new DriverHealth( + outcome.WorstFailure, + outcome.AnySuccess ? now : _health.LastSuccessfulRead, + outcome.WorstFailure == DriverState.Healthy ? null : outcome.WorstError); + } + + _gate.Release(); + } return results; } + /// + /// The outcomes ONE pass observed, accumulated so the pass writes + /// exactly once — worst state wins. + /// + /// + /// + /// Health used to be stamped per item, in three separate read loops, so the pass + /// reported whatever its LAST item happened to be: a mixed pass read Healthy, and + /// the access-denied Faulted config alert — usually a minority of the batch — was + /// erased by any later good tag. Ranking (Healthy < Degraded < Faulted) and + /// deciding once at the end makes the verdict a function of the whole pass rather than + /// of its item ordering. + /// + /// + /// is tracked separately from the state on purpose. The + /// comms-loss watchdog trips only on a non-Healthy state AND a frozen + /// LastSuccessfulRead; several drivers latch Degraded off a single unreadable + /// address, so a pass that lands Degraded must still advance the timestamp when + /// anything at all was read, or an entirely reachable CPU would be reconnected every + /// 90 s forever. + /// + /// + /// Not thread-safe, and does not need to be: a pass runs wholly under + /// and every read loop inside it is sequential. + /// + /// + private sealed class ReadPassOutcome + { + /// True once any tag in the pass read successfully. + public bool AnySuccess { get; private set; } + + /// + /// The worst failure state recorded so far; means no + /// failure has been recorded at all. + /// + public DriverState WorstFailure { get; private set; } = DriverState.Healthy; + + /// + /// The first message recorded at the worst severity — the one that explains + /// . + /// + /// + /// It must move WITH the state, not independently of it. Keeping the pass's + /// chronologically-first message instead desynced the pair whenever a Degraded fault + /// preceded a Faulted one: the driver reported the access-denied config alert while its + /// message talked about some unrelated device fault and never mentioned PUT/GET, which + /// is the one thing the operator has to act on. Within a severity the FIRST message + /// still wins — a later peer failure is as likely to be a consequence of it as an + /// independent fault. + /// + public string? WorstError { get; private set; } + + /// + /// True once the pass observed anything at all — a success or a failure. False for a + /// degenerate pass (empty batch, or every reference unresolvable), which must report + /// nothing rather than invent a verdict. + /// + public bool HasObservations => AnySuccess || WorstFailure != DriverState.Healthy; + + /// Records that one tag read successfully. + public void RecordSuccess() => AnySuccess = true; + + /// + /// Records one failed tag, keeping the worst state and the message that explains it. + /// + /// The state this failure would have stamped on its own. + /// The failure's operator-facing message. + public void RecordFailure(DriverState state, string message) + { + if (Rank(state) > Rank(WorstFailure)) + { + // Escalating the severity MUST re-point the message at the new cause. + WorstFailure = state; + WorstError = message; + } + else + { + WorstError ??= message; + } + } + + /// Severity order the pass ranks by: Healthy (none) < Degraded < Faulted. + /// The state to rank. + /// Its severity, higher being worse. + private static int Rank(DriverState state) => state switch + { + DriverState.Faulted => 2, + DriverState.Degraded => 1, + _ => 0, + }; + } + /// /// Items one multi-var request may carry. The caller owns chunking — S7.Net does NOT /// split a multi-var read, it throws when the request or the projected response exceeds @@ -743,6 +863,7 @@ public sealed class S7Driver /// Indexes the span pass left for the per-tag path, ascending. /// The batch's result array, written in place at each tag's original index. /// The batch timestamp, shared by every tag in the batch. + /// The pass's outcome accumulator; every decoded item records into it. /// Cancellation token for the reads. /// The indexes still owed an individual read, ascending. private async Task> ReadLeftoversByMultiVarAsync( @@ -751,6 +872,7 @@ public sealed class S7Driver List leftovers, DataValueSnapshot[] results, DateTime now, + ReadPassOutcome outcome, CancellationToken ct) { var stillPerTag = new List(); @@ -825,13 +947,13 @@ public sealed class S7Driver ?? throw new System.IO.InvalidDataException( $"S7.Net returned null multi-var value for '{tag.Address}'"); results[index] = new DataValueSnapshot(ReinterpretRawValue(tag, addr, raw), 0u, now, now); - _health = new DriverHealth(DriverState.Healthy, now, null); + outcome.RecordSuccess(); } catch (Exception ex) { // Decoding is pure and synchronous — no cancellation can surface here, so there // is deliberately no OperationCanceledException arm to shadow the request one. - results[index] = new DataValueSnapshot(null, RecordReadFailure(ex), null, now); + results[index] = new DataValueSnapshot(null, RecordReadFailure(ex, outcome), null, now); } } } @@ -902,10 +1024,12 @@ public sealed class S7Driver /// The planned block read. /// The batch's result array, written in place at each member's original index. /// The batch timestamp, shared by every tag in the batch. + /// The pass's outcome accumulator; every member records into it. /// Cancellation token for the read. /// A task that completes once every member of the span has been stamped. private async Task ReadSpanAsync( - IS7Plc plc, S7ReadSpanPlanner.Span span, DataValueSnapshot[] results, DateTime now, CancellationToken ct) + IS7Plc plc, S7ReadSpanPlanner.Span span, DataValueSnapshot[] results, DateTime now, + ReadPassOutcome outcome, CancellationToken ct) { byte[] block; try @@ -926,7 +1050,7 @@ public sealed class S7Driver } catch (Exception ex) { - var status = RecordReadFailure(ex); + var status = RecordReadFailure(ex, outcome); foreach (var member in span.Members) results[member.OriginalIndex] = new DataValueSnapshot(null, status, null, now); return; @@ -938,13 +1062,14 @@ public sealed class S7Driver { var value = DecodeMember(member, block); results[member.OriginalIndex] = new DataValueSnapshot(value, 0u, now, now); - _health = new DriverHealth(DriverState.Healthy, now, null); + outcome.RecordSuccess(); } catch (Exception ex) { // Decoding is pure and synchronous — no cancellation can surface here, so there is // deliberately no OperationCanceledException arm to shadow the block-read one above. - results[member.OriginalIndex] = new DataValueSnapshot(null, RecordReadFailure(ex), null, now); + results[member.OriginalIndex] = + new DataValueSnapshot(null, RecordReadFailure(ex, outcome), null, now); } } } @@ -998,17 +1123,29 @@ public sealed class S7Driver /// /// The read-failure classification ladder, shared by the per-tag path and the span path so /// a failed span stamps every member with exactly the status the same exception would have - /// produced on a single tag. Applies the health / dead-handle side effects and returns the - /// status code the caller must stamp. + /// produced on a single tag. Records the failure into the pass's outcome, applies the + /// dead-handle side effect, and returns the status code the caller must stamp. /// /// - /// is deliberately NOT handled here: it is control - /// flow rather than a per-tag status (it marks the handle dead and propagates), and - /// rethrowing it from a helper would rewrite the stack. Both call sites catch it first. + /// + /// The health state is recorded, not applied. It goes into + /// so the pass can write once at the + /// end, worst-state-wins — writing it here is what let a later good tag erase this + /// failure. The _plcDead / side effects + /// stay IMMEDIATE: they govern whether the very next read reopens the handle, which + /// cannot wait for the pass to finish. + /// + /// + /// is deliberately NOT handled here: it is + /// control flow rather than a per-tag status (it marks the handle dead and propagates), + /// and rethrowing it from a helper would rewrite the stack. Both call sites catch it + /// first. + /// /// /// The exception observed on a read. + /// The pass's outcome accumulator this failure is recorded into. /// The OPC UA status code every affected tag must be stamped with. - private uint RecordReadFailure(Exception ex) + private uint RecordReadFailure(Exception ex, ReadPassOutcome outcome) { switch (ex) { @@ -1020,7 +1157,7 @@ public sealed class S7Driver // fault, NOT a transient one. Blind retry is wasted effort, so map it to // BadNotSupported and flag the driver as a config alert (Faulted) rather than // Degraded — per driver-specs.md §5. - _health = new DriverHealth(DriverState.Faulted, _health.LastSuccessfulRead, + outcome.RecordFailure(DriverState.Faulted, "S7 access denied — enable PUT/GET communication in TIA Portal " + $"(Protection & Security) for this CPU. PLC reported: {pex.Message}"); return StatusBadNotSupported; @@ -1031,14 +1168,14 @@ public sealed class S7Driver // PlcException (socket drop / ConnectionError) additionally marks the handle dead // so the next read reopens it. MarkConnectionDeadIfFatal(pex); - _health = new DriverHealth(DriverState.Degraded, _health.LastSuccessfulRead, pex.Message); + outcome.RecordFailure(DriverState.Degraded, pex.Message); return StatusBadDeviceFailure; default: // Socket / timeout / transport fault — mark the handle dead when it's a connection // loss so EnsureConnectedAsync reopens on the next call. MarkConnectionDeadIfFatal(ex); - _health = new DriverHealth(DriverState.Degraded, _health.LastSuccessfulRead, ex.Message); + outcome.RecordFailure(DriverState.Degraded, ex.Message); return StatusBadCommunicationError; } } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs index cd70e38c..11b1c8d9 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs @@ -7,8 +7,8 @@ namespace ZB.MOM.WW.OtOpcUa.Host.Configuration; /// /// The onReady callback handed to AddZbLocalDb: creates the deployment-cache, -/// alarm store-and-forward, and scripted-alarm condition-state tables and opts them into -/// replication. +/// alarm store-and-forward, and scripted-alarm condition-state tables and — when this node +/// actually replicates — opts them into change capture. /// /// /// @@ -21,7 +21,25 @@ namespace ZB.MOM.WW.OtOpcUa.Host.Configuration; public static class LocalDbSetup { /// - /// Initialises the local database: DDL first, then replication registration. + /// The four tables that participate in replication — registered when this node is configured + /// to replicate, and deregistered (stale capture triggers dropped) when it is not. + /// + /// + /// One list shared by both branches on purpose. A table added to only the registration + /// branch would replicate on a configured node and then never be cleaned off an + /// unconfigured one; a table added to only the deregistration branch would be cleaned on a + /// node that never registered it. + /// + private static readonly string[] ReplicatedTables = + [ + DeploymentCacheSchema.ArtifactsTable, + DeploymentCacheSchema.PointerTable, + AlarmSfSchema.EventsTable, + AlarmConditionStateSchema.StateTable, + ]; + + /// + /// Initialises the local database: DDL first, then replication registration (or its removal). /// /// /// @@ -33,20 +51,53 @@ public static class LocalDbSetup /// registration — it writes rows, and they must be captured like any other write. /// /// + /// Registration is CONDITIONAL on . It used + /// to be unconditional, on every driver node, replicating or not. That was not merely + /// wasteful — an unreplicated node paid two INSERTs plus a json_object of the + /// whole row inside every write transaction, for an oplog nothing ever drained — it also + /// made baselineExistingRows unusable, because passing it on a node with no peer + /// would flag a snapshot resync for a peer that does not exist. The ordering rule above + /// is unaffected: when registration is skipped there is no capture to be too late for. + /// + /// + /// The unconfigured branch actively cleans up rather than merely abstaining. + /// DeregisterReplicated drops any capture triggers an earlier build left in the + /// file and prunes that table's oplog and row-version rows. Declining to register alone + /// would leave every file written by a pre-2026-08-18 build capturing forever — on + /// precisely the node that has no peer to capture for. + /// + /// + /// A failure part-way through either loop fails host start, and that is deliberate. + /// Neither branch catches, so a throw on the third of four tables leaves two flipped and + /// propagates out of the AddZbLocalDb singleton factory — a node that came up + /// anyway would be capturing (or not) on an arbitrary subset, which is silently partial + /// replication with nothing in the log to say so. Both library calls are idempotent, so + /// the retried boot simply completes the flip rather than compounding it. + /// + /// /// The alarm buffer's tables are created unconditionally, regardless of whether this - /// node has AlarmHistorian:Enabled set. An empty registered table costs three - /// triggers and nothing else, whereas creating it lazily when the sink first appears - /// would mean a node that enables the historian later writes rows before its triggers - /// exist — which is precisely the silent-loss shape above. + /// node has AlarmHistorian:Enabled set, and regardless of replication. Creating + /// one lazily when the sink first appears would mean a node that enables the historian + /// later writes rows before its triggers exist — which is precisely the silent-loss + /// shape above. /// /// /// The freshly constructed local database. /// - /// Application configuration, read by the legacy migrator for the pre-consolidation queue's - /// path. Required rather than optional: an overload that silently skipped the migration - /// would be one wiring mistake away from discarding a node's undelivered alarm history. + /// Application configuration, read for the replication predicate and by the legacy migrator + /// for the pre-consolidation queue's path. Required rather than optional: an overload that + /// silently skipped the migration would be one wiring mistake away from discarding a node's + /// undelivered alarm history. /// - public static void OnReady(ILocalDb db, IConfiguration configuration) + /// + /// Where the deregistration self-heal reports what it cleaned. Defaults to Serilog's static + /// logger, which is what production uses: this runs inside the AddZbLocalDb singleton + /// factory, where resolving an ILogger would nest a service resolution inside a + /// singleton construction. Program.cs assigns Serilog.Log.Logger from the DI + /// root logger before anything resolves ILocalDb. The parameter exists so tests can + /// observe the line rather than infer it. + /// + public static void OnReady(ILocalDb db, IConfiguration configuration, Serilog.ILogger? logger = null) { ArgumentNullException.ThrowIfNull(db); ArgumentNullException.ThrowIfNull(configuration); @@ -60,12 +111,139 @@ public static class LocalDbSetup AlarmConditionStateSchema.Apply(connection); } - db.RegisterReplicated(DeploymentCacheSchema.ArtifactsTable); - db.RegisterReplicated(DeploymentCacheSchema.PointerTable); - db.RegisterReplicated(AlarmSfSchema.EventsTable); - db.RegisterReplicated(AlarmConditionStateSchema.StateTable); + if (ReplicationIsConfigured(configuration)) + RegisterForCapture(db); + else + RemoveStaleCapture(db, logger ?? Serilog.Log.Logger); // LAST, and only here. This is the one call in OnReady that writes rows. AlarmSfLegacyMigrator.Migrate(db, configuration); } + + /// + /// Whether this node participates in LocalDb replication, and therefore needs the capture + /// triggers at all. + /// + /// + /// + /// Either key counts, and the OR is not belt-and-braces — it is the only predicate + /// that is true on BOTH halves of a replicating pair. Replication is one + /// bidirectional stream that exactly one side dials, so only the initiator sets + /// LocalDb:Replication:PeerAddress; the passive node carries the shared + /// ApiKey and a LocalDb:SyncListenPort and nothing else. (The docker-dev + /// rig is the reference: site-a-1 has PeerAddress + ApiKey, site-a-2 has + /// ApiKey + SyncListenPort, and central / site-b carry no Replication section at + /// all.) Keying on PeerAddress alone would strip capture from every passive node — its + /// local writes would stop reaching the initiator and the pair would converge in one + /// direction only, silently. + /// + /// + /// LocalDb:SyncListenPort deliberately does NOT join the OR. The passive + /// endpoint is fail-closed on the key: with a port but no ApiKey, + /// LocalDbSyncAuthInterceptor refuses every inbound stream, so such a node + /// replicates nothing and has nothing to capture for. Adding the port to the predicate + /// would install capture triggers on a node whose sync endpoint rejects all callers. + /// LocalDbReplicationHealthCheck deliberately asks a different question — + /// "was this node MEANT to replicate?", which is PeerAddress OR a bound listen + /// port — so a port-without-key node correctly reports Degraded there while correctly + /// capturing nothing here. The two predicates diverge only on that misconfiguration, + /// and each is right about its own question. + /// + /// + /// The keys are read straight from configuration rather than through + /// IOptions<ReplicationOptions> because this runs inside the + /// AddZbLocalDb factory, where resolving another option would nest a service + /// resolution inside a singleton construction. The section path is + /// — the same constant + /// AddZbLocalDbReplication binds — so the predicate and the engine cannot + /// disagree about which node replicates. + /// + /// + /// Both directions of a change to this predicate are handled at boot, and both + /// require the PAIR to be changed together. The sync handshake compares + /// registered-table digests fail-closed, so a node that drops a table its peer still + /// replicates stops syncing with a schema mismatch. Enable (or disable) replication on + /// both nodes and restart both — never one. + /// + /// + /// The application configuration. + /// true when this node is configured to replicate. + public static bool ReplicationIsConfigured(IConfiguration configuration) + { + ArgumentNullException.ThrowIfNull(configuration); + + var section = configuration.GetSection(LocalDbRegistration.ReplicationSectionPath); + + return !string.IsNullOrWhiteSpace(section["PeerAddress"]) + || !string.IsNullOrWhiteSpace(section["ApiKey"]); + } + + /// Opts every replicated table into change capture, baselining what is already there. + /// + /// + /// baselineExistingRows: true is what makes turning replication ON for a node that + /// has been running WITHOUT it actually converge. Capture is change-data-capture and the + /// snapshot streamer pages from __localdb_row_version, so rows written before the + /// first registration are in neither: a late opt-in used to replicate only writes made + /// after the restart, silently and forever. Baselining seeds the ledger at the LWW floor + /// (HLC 0, this node's id) and flags a snapshot resync, so a baselined row loses to any + /// genuine remote write of the same key and wins only where the peer has no version at + /// all. It is idempotent, and therefore free on every boot after the first — which is + /// why it is unconditional here rather than behind a one-shot flag. + /// + /// + /// ⚠️ On the pinned LocalDb 0.2.1 the snapshot flag is per-DATABASE, not per-table. + /// Baselining anything flags a resync that streams every registered table in full, + /// and on a pair enabling replication late both nodes do that to each other at once — the + /// largest transfer the library performs. Bounded, but expect one slow first sync, and + /// trim alarm_sf_events before enabling replication on a node that has been + /// buffering alarm history for a long time. + /// + /// + /// The per-table loop is kept rather than collapsed into a hypothetical bulk call: the + /// library's contract is per-table (PK validation, digest, and — from LocalDb 0.3.0 — the + /// snapshot flag itself), so a bulk API would only be able to give back the coarse + /// behaviour. + /// + /// + private static void RegisterForCapture(ILocalDb db) + { + foreach (var table in ReplicatedTables) + db.RegisterReplicated(table, baselineExistingRows: true); + } + + /// Drops capture this node must not pay for, and says so once if it found any. + /// + /// DeregisterReplicated is idempotent and deliberately usable on a table this process + /// never registered, so a never-replicated file simply reports nothing to clean and stays + /// silent. Symmetry is not a concern on this branch: this node has no peer, so there is no + /// handshake digest for a one-sided deregistration to fail — and re-enabling later is safe + /// despite the ledger prune, because baselines. + /// + private static void RemoveStaleCapture(ILocalDb db, Serilog.ILogger logger) + { + var cleaned = 0; + + foreach (var table in ReplicatedTables) + { + if (db.DeregisterReplicated(table)) + cleaned++; + } + + // Only when something was actually removed. Every default-OFF node in the fleet takes this + // branch on every boot; logging unconditionally would be a daily non-event, which is how the + // one boot that DID silently stop capturing gets overlooked. + if (cleaned > 0) + { + logger.Information( + "LocalDb: removed stale change-capture from {TableCount} table(s) — this node has no " + + "replication configured ({PeerAddressKey}/{ApiKeyKey} are both absent — unset or blank), " + + "so the capture " + + "triggers an earlier build installed have been dropped and their oplog/row-version " + + "rows pruned.", + cleaned, + $"{LocalDbRegistration.ReplicationSectionPath}:PeerAddress", + $"{LocalDbRegistration.ReplicationSectionPath}:ApiKey"); + } + } } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs index 2391bd56..2e028c28 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs @@ -136,7 +136,8 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac } catch (ScriptTimeoutException) { - return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s"); + return VirtualTagEvalResult.Failure( + $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { @@ -148,7 +149,7 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac } catch (ObjectDisposedException) { - return VirtualTagEvalResult.Failure("evaluator disposed during evaluation"); + return VirtualTagEvalResult.Failure(ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); } catch (Exception ex) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs index 21b40271..9657ea87 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs @@ -429,6 +429,8 @@ public sealed class SessionAclDecisionCache /// /// Advances the cache-wide stamp when this call presents a newer generation, and purges on the way. + /// The stamp ends up holding the highest generation any caller has presented — never a lower one, + /// and never one call late. /// /// /// @@ -443,21 +445,54 @@ public sealed class SessionAclDecisionCache /// carries its own generation; what is at stake here is only whether the cache is any use. /// /// + /// ⚠️ That guard lives INSIDE the loop, against a freshly re-read stamp — hoisting it to a + /// single check before the loop reintroduces exactly the backward roll it exists to prevent: a + /// straggler that lost its exchange would spin back round and re-attempt against the newer stamp + /// it just lost to, and eventually succeed in rolling it back. Re-reading means the straggler + /// sees the newer value on its second pass and leaves. + /// + /// + /// Why a loop rather than one exchange. A single shot defers publication by a call: two + /// callers read the same baseline, the older one's exchange lands first, and the newer one's + /// fails and falls out having published nothing. Its own lookup then misses and the + /// that follows is dropped by the Generation != generation guard, which + /// costs a store in the post-deploy window where the cache is coldest. Retrying against the moved + /// stamp closes that: the higher generation is published on the call that presents it. + /// + /// + /// The elected clear survives the loop. Only the thread whose exchange actually moved the + /// stamp clears, so a burst of concurrent requests arriving just after a deploy still repopulates + /// once rather than each clearing the others' fresh entries. A retry can now clear too, but only + /// by winning a move to a strictly higher generation — so clears stay bounded by the number of + /// distinct generations presented, not by request volume. + /// + /// + /// It terminates. Each iteration either returns through the guard or exchanges against a + /// seen strictly larger than the last iteration's (a failed exchange means someone raised + /// the stamp), and _generation only ever rises — so the guard is reached within a bounded + /// number of passes. + /// + /// /// The straggler's own lookup is unaffected by returning early: its shard-generation check misses /// against the newer shards regardless, so it recomputes, which is the correct outcome for a /// request holding a superseded snapshot. _generation starts at -1, below any real - /// generation, so the first one still passes. + /// generation, so the first one — generation 0 included — still passes. /// /// /// The generation the calling request is being decided under. private void InvalidateIfStale(long generation) { - var seen = Interlocked.Read(ref _generation); - if (generation <= seen) return; + while (true) + { + var seen = Interlocked.Read(ref _generation); + if (generation <= seen) return; - // Only the thread that actually moves the stamp clears, so a burst of concurrent requests arriving - // just after a deploy repopulates once rather than each clearing the others' fresh entries. - if (Interlocked.CompareExchange(ref _generation, generation, seen) == seen) ClearAll(); + if (Interlocked.CompareExchange(ref _generation, generation, seen) == seen) + { + ClearAll(); + return; + } + } } /// diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs index 73f661b1..d6d752c8 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs @@ -387,10 +387,14 @@ public sealed class S7SpanReadParityTests /// failed REQUEST, and firing it here would re-read tags that already have good values. /// /// - /// Health ends Healthy rather than Degraded because the decode loop stamps - /// health per item in chunk order, so the good item after the bad one re-stamps it. That is - /// the same last-writer-wins behaviour the per-tag loop has always had; it is pinned here so - /// a change to it is a deliberate one. + /// Health ends Degraded, NOT Healthy. This pin used to assert the opposite: + /// the decode loop stamped health per item in chunk order, so the good item after the bad + /// one re-stamped it and a pass with failures reported Healthy — last-writer-wins. + /// That was deliberately replaced (perf follow-ups round 3) by worst-state-wins: the + /// whole read pass accumulates its outcomes and writes health ONCE at the end, so a mixed + /// pass can no longer report Healthy. Only the driver-level health claim changed — the + /// per-tag statuses below are exactly as they were, because a per-ITEM decode fault still + /// spoils only its own tag. /// [Fact] public async Task One_undecodable_multi_var_item_stamps_only_its_own_tag_Bad() @@ -420,7 +424,267 @@ public sealed class S7SpanReadParityTests factory.MultiVarCalls.ShouldBe(1); factory.StringReadCalls.ShouldBe(0); factory.ReadBytesCalls.ShouldBe(0); - driver.GetHealth().State.ShouldBe(DriverState.Healthy); + driver.GetHealth().State.ShouldBe(DriverState.Degraded); + } + + // ── Worst-state-wins read-pass health ──────────────────────────────────────────────── + + /// + /// A pass with BOTH failures and successes reports Degraded — the failure is not + /// erased by the later success — AND still advances LastSuccessfulRead, because + /// something genuinely was read. + /// + /// + /// Advancing the timestamp on a Degraded pass is load-bearing, not cosmetic: the + /// comms-loss watchdog (CLAUDE.md §"Comms-loss detection") trips on non-Healthy state + /// AND a frozen LastSuccessfulRead. Several drivers latch Degraded off one + /// unreadable address, so freezing the timestamp on any non-Healthy pass would reconnect a + /// perfectly reachable PLC every 90 s forever. + /// + [Fact] + public async Task A_mixed_read_pass_reports_Degraded_and_still_advances_LastSuccessfulRead() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()) { NullItemIndex = 1 }; + using var driver = new S7Driver(Options(ScatteredWords(3), maxGap: 2), "s7-mixed-pass", factory); + await driver.InitializeAsync("{}", ct); + + // The connect stamped a LastSuccessfulRead; the pass must move it PAST that value, so a + // frozen timestamp is distinguishable from a merely non-null one. + var before = driver.GetHealth().LastSuccessfulRead; + before.ShouldNotBeNull(); + + var results = await driver.ReadAsync(ScatteredRefs(3), ct); + + results[0].StatusCode.ShouldBe(0u); + results[1].StatusCode.ShouldBe(StatusBadCommunicationError); + results[2].StatusCode.ShouldBe(0u); + + var health = driver.GetHealth(); + health.State.ShouldBe(DriverState.Degraded, "a pass that had a failure must not report Healthy"); + health.LastSuccessfulRead.ShouldNotBeNull(); + health.LastSuccessfulRead!.Value.ShouldBeGreaterThan( + before!.Value, "two of the three tags read fine — the watchdog's evidence must advance"); + } + + /// + /// The SPAN path obeys the same rule: one member that fails to decode leaves the pass + /// Degraded even though a later member of the same block decoded fine. + /// + /// + /// The block read itself succeeds — this is the per-member decode guard, the span-path + /// sibling of the multi-var per-item guard above. The poisoned member is an S7 STRING laid + /// over the image's filler pattern, whose two-byte header declares a current length larger + /// than its capacity; S7String.FromByteArray rejects that. It is deliberately the + /// FIRST member (lower offset) so the good member decodes after it — the exact ordering + /// last-writer-wins used to erase. + /// + [Fact] + public async Task One_undecodable_span_member_leaves_the_pass_Degraded() + { + var ct = TestContext.Current.CancellationToken; + // The STRING occupies DB1 bytes 100..111 (StringLength + 2), so the word at 112 is + // adjacent and lands in the SAME span. + var tags = S7RawTags.Entries( + new S7TagDefinition("BadStr", "DB1.DBB100", S7DataType.String, Writable: false, StringLength: 10), + new S7TagDefinition("GoodWord", "DB1.DBW112", S7DataType.UInt16, Writable: false)); + var factory = new ImageS7PlcFactory(Images()); + + // The poison is the FILLER, not a fake knob: Images() writes (i * 37 + 11) & 0xFF, which + // steps +37 per byte and so runs ASCENDING except in the ~15% of positions where it wraps + // past 256. Byte 100 is not one of those, so the STRING header at 100/101 reads + // maxLen 127 / curLen 164 — a current length larger than the capacity, which + // S7String.FromByteArray rejects. Asserted rather than assumed, so a change to the filler + // pattern fails HERE, loudly, instead of silently turning this into a passing no-op test. + var db1Image = factory.Images[(S7NetDataType.DataBlock, 1)]; + db1Image[101].ShouldBeGreaterThan( + db1Image[100], "the S7 STRING at DB1.DBB100 must declare curLen > maxLen to be undecodable"); + using var driver = new S7Driver(Options(tags, maxGap: 16), "s7-span-decode-fault", factory); + await driver.InitializeAsync("{}", ct); + + var before = driver.GetHealth().LastSuccessfulRead; + var results = await driver.ReadAsync(["BadStr", "GoodWord"], ct); + + // ONE block read served both members — this really is the span path, not two per-tag reads. + factory.ReadBytesCalls.ShouldBe(1); + factory.StringReadCalls.ShouldBe(0); + + // Only the poisoned member is Bad; its block-mate keeps its value. + results[0].StatusCode.ShouldNotBe(0u); + results[0].Value.ShouldBeNull(); + results[1].StatusCode.ShouldBe(0u); + results[1].Value.ShouldNotBeNull(); + + var health = driver.GetHealth(); + health.State.ShouldBe(DriverState.Degraded, "a span member that failed to decode must not be erased"); + health.LastSuccessfulRead!.Value.ShouldBeGreaterThan(before!.Value); + } + + /// + /// Faulted outranks BOTH Degraded and Healthy: an access-denied read (the permanent PUT/GET + /// configuration fault) on one tag survives a later device-fault tag AND a later tag that + /// read successfully, all in the same pass. + /// + /// + /// The ordering is Healthy < Degraded < Faulted, so the config alert — the one state + /// an operator must act on — is precisely the one last-writer-wins was most likely to + /// erase, since the denied tag is usually a minority of the batch. Both later outcomes are + /// present deliberately: the success falsifies "any success clears the failure", the + /// Degraded falsifies "the last failure wins". LastSuccessfulRead still advances, + /// because one tag really was read. + /// + [Fact] + public async Task An_access_denied_tag_keeps_the_pass_Faulted_even_after_a_later_tag_succeeds() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()); + // A: "not allowed" is what IsAccessDenied matches — PUT/GET disabled on an S7-1200/1500, + // which is the Faulted config alert. B: an ordinary device-layer fault, merely Degraded, + // observed AFTER it. C: no fault at all. + factory.PerTagFaults["DB1.DBW0"] = new PlcException(ErrorCode.ReadData, "Accessing object not allowed"); + factory.PerTagFaults["DB1.DBW2"] = new PlcException(ErrorCode.ReadData, "S7 CPU reported a device fault"); + // maxGap -1 turns grouping off entirely, so every tag takes the per-tag read path and the + // faults can be aimed at individual addresses. + using var driver = new S7Driver(Options(NarrowTags(), maxGap: -1), "s7-access-denied", factory); + await driver.InitializeAsync("{}", ct); + + var before = driver.GetHealth().LastSuccessfulRead; + var results = await driver.ReadAsync(["A", "B", "C"], ct); + + results[0].StatusCode.ShouldNotBe(0u); + results[1].StatusCode.ShouldBe(StatusBadDeviceFailure); + results[2].StatusCode.ShouldBe(0u); + + var health = driver.GetHealth(); + health.State.ShouldBe( + DriverState.Faulted, "a config alert must outrank a later device fault AND a later success"); + health.LastError.ShouldNotBeNull(); + // The FIRST failure is the causal one — the later device fault does not overwrite it. + health.LastError!.ShouldContain("PUT/GET"); + health.LastSuccessfulRead!.Value.ShouldBeGreaterThan( + before!.Value, "one tag read fine, so the watchdog's evidence must still advance"); + } + + /// + /// The pass's message must explain the state it reports. When a merely-Degraded fault is + /// observed BEFORE the access-denied one, escalating to Faulted has to re-point + /// LastError at the access-denied cause — reporting the config alert under the + /// earlier device-fault message tells the operator to chase the wrong thing. + /// + /// + /// This is the reversed ordering of + /// , + /// and the pair is the point: keeping the pass's chronologically-first message satisfies + /// that test and fails this one, so only a message that moves WITH the severity passes both. + /// + [Fact] + public async Task Escalating_to_Faulted_re_points_the_error_message_at_the_access_denied_cause() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()); + // A: an ordinary device-layer fault (Degraded) FIRST. B: the access-denied config alert + // (Faulted) after it. C: no fault at all. + factory.PerTagFaults["DB1.DBW0"] = new PlcException(ErrorCode.ReadData, "S7 CPU reported a device fault"); + factory.PerTagFaults["DB1.DBW2"] = new PlcException(ErrorCode.ReadData, "Accessing object not allowed"); + using var driver = new S7Driver(Options(NarrowTags(), maxGap: -1), "s7-escalation-message", factory); + await driver.InitializeAsync("{}", ct); + + var before = driver.GetHealth().LastSuccessfulRead; + var results = await driver.ReadAsync(["A", "B", "C"], ct); + + results[0].StatusCode.ShouldBe(StatusBadDeviceFailure); + results[1].StatusCode.ShouldNotBe(0u); + results[2].StatusCode.ShouldBe(0u); + + var health = driver.GetHealth(); + health.State.ShouldBe(DriverState.Faulted, "the access-denied fault must still outrank the earlier one"); + health.LastError.ShouldNotBeNull(); + health.LastError!.ShouldContain( + "PUT/GET", + customMessage: "the message must explain the FAULTED state, not the earlier Degraded one"); + health.LastSuccessfulRead!.Value.ShouldBeGreaterThan(before!.Value); + } + + /// + /// Cancellation mid-pass abandons the batch but must NOT discard the evidence the pass had + /// already gathered: a tag that read successfully before the cancellation still advances + /// LastSuccessfulRead. + /// + /// + /// Deciding health once at the end of the pass makes this a real risk, which per-item + /// writes did not have. On a partially-working device a repeatedly-cancelled poll would + /// freeze LastSuccessfulRead while tags were demonstrably still being read, and the + /// comms-loss watchdog — which trips on non-Healthy state AND a frozen timestamp — would + /// reconnect a CPU that is answering. Flushing from a finally is what prevents it. + /// + [Fact] + public async Task A_cancelled_pass_still_flushes_the_evidence_it_had_already_gathered() + { + var ct = TestContext.Current.CancellationToken; + // Narrow first (a per-address read, which the hang knob does NOT intercept), then a wide + // Int64 (a BLOCK read, which it does) — so the pass banks one success and is then cancelled + // mid-flight on the very next tag. + var tags = S7RawTags.Entries( + new S7TagDefinition("Narrow", "DB1.DBW0", S7DataType.UInt16, Writable: false), + new S7TagDefinition("Wide", "DB1.DBB8", S7DataType.Int64, Writable: false)); + var factory = new ImageS7PlcFactory(Images()) { HangReadBytes = true }; + // maxGap -1 keeps both tags on the per-tag path, in reference order. + using var driver = new S7Driver(Options(tags, maxGap: -1), "s7-cancel-flush", factory); + await driver.InitializeAsync("{}", ct); + + var before = driver.GetHealth().LastSuccessfulRead; + + using var cts = new CancellationTokenSource(); + var reading = driver.ReadAsync(["Narrow", "Wide"], cts.Token); + await factory.ReadBytesEntered.Task.WaitAsync(TimeSpan.FromSeconds(10), ct); + await cts.CancelAsync(); + + await Should.ThrowAsync(async () => await reading); + + // The first tag really was served before the cancellation — one per-address read happened. + factory.StringReadCalls.ShouldBe(1); + + var health = driver.GetHealth(); + health.LastSuccessfulRead!.Value.ShouldBeGreaterThan( + before!.Value, "the banked success must survive the abandoned batch"); + } + + /// + /// A pass that observes NOTHING — every reference unresolvable, so not one tag was read and + /// not one failed — reports nothing: it must leave the driver's prior Faulted config + /// alert (and its LastSuccessfulRead) exactly as it found them. + /// + /// + /// Deciding health once per pass means the pass has to answer "what did I observe?", and a + /// degenerate pass observed nothing at all — writing Healthy for it would invent + /// evidence and silently clear a PUT/GET config alert an operator still has to act on. The + /// per-item health writes this replaced had that property for free (no item, no write); the + /// end-of-pass guard is what preserves it. + /// + [Fact] + public async Task A_pass_that_observes_nothing_leaves_a_prior_Faulted_untouched() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()); + factory.PerTagFaults["DB1.DBW0"] = new PlcException(ErrorCode.ReadData, "Accessing object not allowed"); + using var driver = new S7Driver(Options(NarrowTags(), maxGap: -1), "s7-observes-nothing", factory); + await driver.InitializeAsync("{}", ct); + + // Drive the driver into the access-denied config alert first. + _ = await driver.ReadAsync(["A"], ct); + var faulted = driver.GetHealth(); + faulted.State.ShouldBe(DriverState.Faulted); + + // Now a pass whose every reference is unresolvable: they are stamped BadNodeIdUnknown + // before the planner ever sees them, so no span, no multi-var item and no per-tag read + // happens — the pass observes neither a success nor a failure. + var results = await driver.ReadAsync(["NoSuchTag", "AlsoMissing"], ct); + results.ShouldAllBe(s => s.StatusCode == StatusBadNodeIdUnknown); + + var after = driver.GetHealth(); + after.State.ShouldBe(DriverState.Faulted, "an observe-nothing pass must not clear the config alert"); + after.LastError.ShouldBe(faulted.LastError); + after.LastSuccessfulRead.ShouldBe(faulted.LastSuccessfulRead, "nothing was read, so nothing advances"); } /// @@ -611,6 +875,14 @@ public sealed class S7SpanReadParityTests /// When set, only the MULTI-VAR read throws this — the per-tag fallback still serves the image. public Exception? MultiVarFault { get; init; } + /// + /// Per-address read faults, keyed by the address string (e.g. DB1.DBW0): only + /// those addresses throw, every other one still serves the image. Lets a test put + /// faults of DIFFERENT severities and successes in ONE pass, which + /// (all-or-nothing) cannot express. + /// + public Dictionary PerTagFaults { get; } = new(StringComparer.OrdinalIgnoreCase); + /// /// When true, ReadBytesAsync hangs until its token is cancelled, so cancellation is /// the only way out of a block read (STAB-15a). Settable so a test can turn it back off @@ -745,6 +1017,7 @@ public sealed class S7SpanReadParityTests public Task ReadAsync(string address, CancellationToken ct) { Interlocked.Increment(ref owner.StringReadCalls); + if (owner.PerTagFaults.TryGetValue(address, out var aimed)) throw aimed; if (owner.ReadFault is { } fault) throw fault; var addr = S7AddressParser.Parse(address); var image = owner.Images[(ToS7NetArea(addr.Area), addr.DbNumber)]; diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/AlarmSfLegacyMigratorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/AlarmSfLegacyMigratorTests.cs index 0a581633..30660edd 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/AlarmSfLegacyMigratorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/AlarmSfLegacyMigratorTests.cs @@ -194,8 +194,17 @@ public sealed class AlarmSfLegacyMigratorTests : IDisposable private ILocalDb BuildDb() { + // The sync ApiKey is what makes OnReady register the tables for capture at all — since + // 2026-08-18 registration follows the replication config rather than being unconditional + // (see LocalDbSetup.ReplicationIsConfigured). Without it these databases would have no + // capture triggers and Migrated_rows_enter_the_oplog would pin nothing. A passive node + // carries exactly this and no PeerAddress, so it is also the realistic shape. var configuration = new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["LocalDb:Path"] = _dbPath }) + .AddInMemoryCollection(new Dictionary + { + ["LocalDb:Path"] = _dbPath, + ["LocalDb:Replication:ApiKey"] = "test-sync-key", + }) .Build(); _provider = new ServiceCollection() diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/LocalDbPairHarness.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/LocalDbPairHarness.cs index abfd7e75..0c4a7884 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/LocalDbPairHarness.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDb/LocalDbPairHarness.cs @@ -91,8 +91,8 @@ public sealed class LocalDbPairHarness : IAsyncDisposable _apiKeyA = apiKeyA ?? DefaultApiKey; _apiKeyB = apiKeyB ?? DefaultApiKey; - _dbProviderA = BuildDatabaseProvider(_pathA); - _dbProviderB = BuildDatabaseProvider(_pathB); + _dbProviderA = BuildDatabaseProvider(_pathA, _apiKeyA); + _dbProviderB = BuildDatabaseProvider(_pathB, _apiKeyB); } /// Node A — the initiator, which dials the peer. @@ -148,7 +148,7 @@ public sealed class LocalDbPairHarness : IAsyncDisposable DeleteDatabaseFiles(_pathB); _pathB = Path.Combine(Path.GetTempPath(), $"otopcua-pairB-{Guid.NewGuid():N}.db"); - _dbProviderB = BuildDatabaseProvider(_pathB); + _dbProviderB = BuildDatabaseProvider(_pathB, _apiKeyB); _ = B; } @@ -258,10 +258,20 @@ public sealed class LocalDbPairHarness : IAsyncDisposable /// A provider owning one deployment-cache database, initialised through the host's own /// — same schema, same registration order. /// - private static ServiceProvider BuildDatabaseProvider(string path) + private static ServiceProvider BuildDatabaseProvider(string path, string apiKey) { + // The ApiKey is not decoration here. Since 2026-08-18 OnReady registers the tables for + // change capture only when this node is CONFIGURED to replicate — PeerAddress or ApiKey + // (LocalDbSetup.ReplicationIsConfigured) — so a database built from `LocalDb:Path` alone + // would come up with no capture triggers and every convergence scenario below would time + // out with nothing to send. Production reads one configuration; this harness happens to + // build the database and the replication engine from two, and they must agree. var config = new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["LocalDb:Path"] = path }) + .AddInMemoryCollection(new Dictionary + { + ["LocalDb:Path"] = path, + ["LocalDb:Replication:ApiKey"] = apiKey, + }) .Build(); return new ServiceCollection() diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs index df45f06a..197439df 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs @@ -1,9 +1,12 @@ using Microsoft.Data.Sqlite; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Serilog.Core; +using Serilog.Events; using Shouldly; using Xunit; using ZB.MOM.WW.LocalDb; +using ZB.MOM.WW.LocalDb.Registration; using ZB.MOM.WW.OtOpcUa.Host.Configuration; namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests; @@ -20,49 +23,163 @@ namespace ZB.MOM.WW.OtOpcUa.Host.IntegrationTests; /// every schema-shape test while shipping a replication path that quietly moves nothing. /// /// +/// BEHAVIOUR CHANGE (2026-08-18): registration is CONDITIONAL on this node actually +/// being configured to replicate. Until now OnReady registered all four tables +/// unconditionally, so every test here could build a database from LocalDb:Path +/// alone and still find them registered. They now pass a replication section, because that +/// is what makes registration happen at all — see +/// +/// for the other branch. The registered-table-set pin is therefore now a pin on +/// configured nodes; the unconfigured node's pin is the deregistration self-heal. +/// +/// /// Built against a real temp-file rather than a hand-written schema: /// the library has no in-memory mode, and asserting against a schema the test itself wrote -/// would only prove the test agrees with itself. +/// would only prove the test agrees with itself. That is doubly true here — the baseline and +/// deregistration behaviours live entirely inside the library, so only a real file can show +/// them. /// /// public sealed class LocalDbSetupTests : IDisposable { + /// + /// The initiating half of a replicating pair: it dials, so it carries PeerAddress. + /// + private static readonly KeyValuePair[] InitiatorReplication = + [ + new("LocalDb:Replication:PeerAddress", "http://peer:9001"), + new("LocalDb:Replication:ApiKey", "test-sync-key"), + ]; + + /// + /// The passive half of the same pair. It never dials, so it has no PeerAddress + /// — only the shared key (plus a listen port, which is Program.cs's concern). Keying the + /// predicate on PeerAddress alone would strip capture from this node and leave the + /// pair converging in one direction only. + /// + private static readonly KeyValuePair[] PassiveReplication = + [ + new("LocalDb:Replication:ApiKey", "test-sync-key"), + ]; + private readonly string _dbPath = Path.Combine(Path.GetTempPath(), $"otopcua-localdb-setup-{Guid.NewGuid():N}.db"); - private ServiceProvider? _provider; + private readonly List _providers = []; - private ILocalDb BuildDb() + /// + /// Boots over the test's database file. + /// + /// + /// + /// Successive calls reopen the same file, which is how the self-heal and + /// late-opt-in cases are expressed: boot once under one replication configuration, write + /// rows, then boot again under another. That is exactly the sequence an operator + /// performs by editing config and restarting the node. + /// + /// + /// A null lets OnReady fall back to Serilog's static + /// Log.Logger, which in this assembly is never assigned and is therefore the + /// library's silent default. That is a load-bearing assumption for the two cases that + /// DO pass a logger: were anything here to install a static logger, they would still + /// pass (they assert on their own sink) but the silent cases would start writing to it. + /// Pass a logger whenever the assertion is about logging. + /// + /// + private ILocalDb Boot( + KeyValuePair[]? replication = null, + Serilog.ILogger? logger = null) { + // A previous boot's provider still holds the file open; the library has no second-handle + // mode. Closing it (and the pool) is what makes a reopen behave like a process restart. + DisposeProviders(); + + var settings = new List> + { + new("LocalDb:Path", _dbPath), + }; + settings.AddRange(replication ?? []); + var configuration = new ConfigurationBuilder() - .AddInMemoryCollection(new Dictionary { ["LocalDb:Path"] = _dbPath }) + .AddInMemoryCollection(settings) .Build(); - _provider = new ServiceCollection() - .AddZbLocalDb(configuration, db => LocalDbSetup.OnReady(db, configuration)) + var provider = new ServiceCollection() + .AddZbLocalDb(configuration, db => LocalDbSetup.OnReady(db, configuration, logger)) .BuildServiceProvider(); - return _provider.GetRequiredService(); + _providers.Add(provider); + + return provider.GetRequiredService(); } + private static async Task ScalarAsync(ILocalDb db, string sql) => + (await db.QueryAsync(sql, r => r.GetInt32(0), parameters: null, TestContext.Current.CancellationToken))[0]; + + private static Task InsertPointerAsync(ILocalDb db, string clusterId) => + db.ExecuteAsync( + """ + INSERT INTO deployment_pointer + (cluster_id, deployment_id, revision_hash, artifact_sha256, applied_at_utc) + VALUES (@ClusterId, @DeploymentId, @RevisionHash, @Sha, @AppliedAtUtc) + """, + new + { + ClusterId = clusterId, + DeploymentId = "0123456789abcdef0123456789abcdef", + RevisionHash = new string('a', 64), + Sha = new string('b', 64), + AppliedAtUtc = "2026-07-20T00:00:00.0000000Z", + }, + TestContext.Current.CancellationToken); + [Fact] - public void OnReady_RegistersExactlyTheFourReplicatedTables() + public void OnReady_WhenReplicationIsConfigured_RegistersExactlyTheFourReplicatedTables() { // Both directions are load-bearing. "No fewer" catches a dropped RegisterReplicated call // (that table then never replicates). "No more" catches an accidental registration — // every replicated table costs three triggers and oplog volume on every write. - var db = BuildDb(); + var db = Boot(InitiatorReplication); db.ReplicatedTables.Keys.OrderBy(k => k, StringComparer.Ordinal) .ShouldBe(["alarm_condition_state", "alarm_sf_events", "deployment_artifacts", "deployment_pointer"]); } + [Fact] + public void OnReady_WhenOnlyTheSyncApiKeyIsSet_StillRegistersTheFourTables() + { + // The passive half of a pair carries the key and nothing else. If the predicate were + // "PeerAddress is set", this node would install no capture triggers and its OWN writes + // would never reach the initiator — a pair that replicates in one direction only, with + // nothing logged anywhere. This test is the falsifier for that narrower predicate. + var db = Boot(PassiveReplication); + + db.ReplicatedTables.Keys.OrderBy(k => k, StringComparer.Ordinal) + .ShouldBe(["alarm_condition_state", "alarm_sf_events", "deployment_artifacts", "deployment_pointer"]); + } + + [Fact] + public async Task OnReady_WhenReplicationIsNotConfigured_RegistersNothingAndInstallsNoTriggers() + { + // The default-OFF node. It has no peer, so capture buys it nothing and costs it two INSERTs + // plus a json_object of the whole row inside every write transaction — for an oplog that is + // never drained. Asserting the trigger count as well as ReplicatedTables matters: the + // dictionary is in-process bookkeeping, the triggers are what actually run. + var db = Boot(); + + db.ReplicatedTables.ShouldBeEmpty(); + + // None of the three application schemas defines a trigger of its own, so every trigger in + // this file would be a capture trigger. + (await ScalarAsync(db, "SELECT COUNT(*) FROM sqlite_master WHERE type = 'trigger'")).ShouldBe(0); + } + [Fact] public void DeploymentArtifacts_PkIsDeploymentIdPlusChunkIndex() { // The composite PK is what makes an artifact chunkable. A single-column PK here would // make every chunk of a deployment collide onto one row under LWW. - var db = BuildDb(); + var db = Boot(InitiatorReplication); db.ReplicatedTables["deployment_artifacts"].PkColumns .ShouldBe(["deployment_id", "chunk_index"]); @@ -73,7 +190,7 @@ public sealed class LocalDbSetupTests : IDisposable { // One current-deployment pointer per cluster: the pair's two nodes converge on the same // row rather than each keeping its own. - var db = BuildDb(); + var db = Boot(InitiatorReplication); db.ReplicatedTables["deployment_pointer"].PkColumns.ShouldBe(["cluster_id"]); } @@ -84,7 +201,7 @@ public sealed class LocalDbSetupTests : IDisposable // A single TEXT PK the application mints. The legacy queue this table replaces keyed on // `RowId INTEGER PRIMARY KEY AUTOINCREMENT`, which LWW cannot replicate: two nodes would // independently allocate rowid 7 for different alarms and silently overwrite each other. - var db = BuildDb(); + var db = Boot(InitiatorReplication); db.ReplicatedTables["alarm_sf_events"].PkColumns.ShouldBe(["id"]); } @@ -94,7 +211,7 @@ public sealed class LocalDbSetupTests : IDisposable { // One condition-state row per alarm identity. The pair's two nodes converge on the same row // under LWW rather than each keeping its own, and Save is an unconditional upsert onto it. - var db = BuildDb(); + var db = Boot(InitiatorReplication); db.ReplicatedTables["alarm_condition_state"].PkColumns.ShouldBe(["scripted_alarm_id"]); } @@ -106,7 +223,7 @@ public sealed class LocalDbSetupTests : IDisposable // Worth its own case because the alarm table is registered by a different call site, and a // registration added ahead of its DDL would fail loudly while one added after the migrator // would fail silently. - var db = BuildDb(); + var db = Boot(InitiatorReplication); await db.ExecuteAsync( """ @@ -123,13 +240,8 @@ public sealed class LocalDbSetupTests : IDisposable }, TestContext.Current.CancellationToken); - var oplogRows = await db.QueryAsync( - "SELECT COUNT(*) FROM __localdb_oplog WHERE table_name = 'alarm_sf_events'", - r => r.GetInt32(0), - parameters: null, - TestContext.Current.CancellationToken); - - oplogRows[0].ShouldBe(1); + (await ScalarAsync(db, "SELECT COUNT(*) FROM __localdb_oplog WHERE table_name = 'alarm_sf_events'")) + .ShouldBe(1); } [Fact] @@ -138,40 +250,215 @@ public sealed class LocalDbSetupTests : IDisposable // THE ordering assertion. If DDL and RegisterReplicated were swapped — or a write were // added to OnReady ahead of registration — the triggers would not exist at write time and // this count would stay 0 while every other test in this file still passed. - var db = BuildDb(); + var db = Boot(InitiatorReplication); - await db.ExecuteAsync( - """ - INSERT INTO deployment_pointer - (cluster_id, deployment_id, revision_hash, artifact_sha256, applied_at_utc) - VALUES (@ClusterId, @DeploymentId, @RevisionHash, @Sha, @AppliedAtUtc) - """, - new - { - ClusterId = "SITE-A", - DeploymentId = "0123456789abcdef0123456789abcdef", - RevisionHash = new string('a', 64), - Sha = new string('b', 64), - AppliedAtUtc = "2026-07-20T00:00:00.0000000Z", - }, - TestContext.Current.CancellationToken); + await InsertPointerAsync(db, "SITE-A"); - var oplogRows = await db.QueryAsync( - "SELECT COUNT(*) FROM __localdb_oplog", - r => r.GetInt32(0), + (await ScalarAsync(db, "SELECT COUNT(*) FROM __localdb_oplog")).ShouldBeGreaterThanOrEqualTo(1); + } + + [Fact] + public async Task EnablingReplicationLater_BaselinesTheRowsAlreadyInTheFile() + { + // The defect this whole change exists for. Capture is change-data-capture and the snapshot + // streamer pages from __localdb_row_version, so rows written while replication was off are + // in neither — a late opt-in used to converge on subsequent writes only, silently and + // forever. RegisterReplicated(table, baselineExistingRows: true) seeds the ledger at the LWW + // floor and flags a resync so they actually travel. + // + // The assertion is on the ledger entry's HLC, not merely on its existence. A row captured by + // a trigger carries a genuine (large, non-zero) stamp; a BASELINED row is seeded at the LWW + // floor of HLC 0, which is what makes it lose to any real remote write of the same key and + // win only where the peer holds no version at all. Asserting existence alone would pass + // against the old unconditional registration, where the trigger simply captured the write — + // i.e. it would prove nothing about the flag. + var unreplicated = Boot(); + await InsertPointerAsync(unreplicated, "SITE-A"); + + var replicated = Boot(InitiatorReplication); + + (await ScalarAsync( + replicated, + """ + SELECT COUNT(*) FROM __localdb_row_version + WHERE table_name = 'deployment_pointer' AND hlc = 0 + """)) + .ShouldBe(1); + } + + [Fact] + public async Task DisablingReplication_DropsTheCaptureTriggersAnEarlierBootInstalled() + { + // The self-heal half. Merely declining to register would leave a file registered by an + // earlier build capturing forever — on precisely the node that has no peer to capture for. + // DeregisterReplicated drops the triggers and prunes that table's oplog and row-version + // rows. + var replicated = Boot(InitiatorReplication); + await InsertPointerAsync(replicated, "SITE-A"); + (await ScalarAsync(replicated, "SELECT COUNT(*) FROM sqlite_master WHERE type = 'trigger'")) + .ShouldBe(12); + + var unreplicated = Boot(); + + unreplicated.ReplicatedTables.ShouldBeEmpty(); + (await ScalarAsync(unreplicated, "SELECT COUNT(*) FROM sqlite_master WHERE type = 'trigger'")) + .ShouldBe(0); + } + + [Fact] + public async Task DisablingReplication_PrunesBookkeepingButNeverTouchesTheCachedDataItself() + { + // Deregistration prunes the table's oplog and row-version rows — BOOKKEEPING. It must not + // touch the base table, because deployment_pointer/deployment_artifacts ARE the + // boot-from-cache backstop: a node whose central SQL is unreachable serves its address space + // from exactly these rows. A library regression that cleaned the base table along with the + // ledger would take that safety net out silently, on the very nodes that never replicate + // (central, site-b) and so would never notice a replication fault either. + var replicated = Boot(InitiatorReplication); + await InsertPointerAsync(replicated, "SITE-A"); + (await ScalarAsync(replicated, "SELECT COUNT(*) FROM __localdb_row_version")).ShouldBeGreaterThan(0); + + var unreplicated = Boot(); + + // The row survives, and with its content intact — a count alone would pass against a + // cleanup that blanked the columns it does not own. + var pointers = await unreplicated.QueryAsync( + "SELECT cluster_id || '|' || deployment_id || '|' || revision_hash FROM deployment_pointer", + static r => r.GetString(0), parameters: null, TestContext.Current.CancellationToken); - oplogRows[0].ShouldBeGreaterThanOrEqualTo(1); + pointers.ShouldBe([$"SITE-A|0123456789abcdef0123456789abcdef|{new string('a', 64)}"]); + + // …while the bookkeeping it DOES own is gone. + (await ScalarAsync(unreplicated, "SELECT COUNT(*) FROM __localdb_row_version")).ShouldBe(0); + (await ScalarAsync(unreplicated, "SELECT COUNT(*) FROM __localdb_oplog")).ShouldBe(0); + } + + [Fact] + public async Task DisablingReplication_LogsOnceWhenItActuallyCleanedSomething() + { + // An operator-visible record that a node just stopped capturing, and how much it dropped. + // Silent trigger removal on a node someone MEANT to replicate is the failure this line + // exists to make diagnosable. + var replicated = Boot(InitiatorReplication); + await InsertPointerAsync(replicated, "SITE-A"); + + var sink = new CollectingSink(); + Boot(replication: null, logger: BuildLogger(sink)); + + sink.Events.Count(e => e.Level == LogEventLevel.Information).ShouldBe(1); + } + + [Fact] + public void DisablingReplication_SaysNothingWhenThereWasNothingToClean() + { + // The steady state of every default-OFF node in the fleet: it boots unreplicated every day + // and has nothing to deregister. A log line here would be a daily false alarm, which is how + // the real one gets ignored. + var sink = new CollectingSink(); + Boot(replication: null, logger: BuildLogger(sink)); + + sink.Events.ShouldBeEmpty(); + } + + [Fact] + public void AFailureMidwayThroughRegistration_FailsBootLoudly_AndTheRetriedBootConverges() + { + // OnReady flips four tables in a loop with no try/catch, so a failure on the third leaves + // two registered and two not. That is the RIGHT behaviour and this pins both halves of why: + // the throw propagates out of the AddZbLocalDb singleton factory and fails host start + // (a node half-capturing is a node whose replication is silently partial), and because both + // library APIs are idempotent the retried boot completes the flip rather than compounding it. + // + // Swallowing the throw would leave the node up, serving, and replicating two of four tables + // with nothing in the log to say so. + var real = Boot(InitiatorReplication); + + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection([new KeyValuePair("LocalDb:Path", _dbPath), .. InitiatorReplication]) + .Build(); + + var faulty = new FailsOnNthRegistration(real, failOnCall: 3); + + Should.Throw(() => LocalDbSetup.OnReady(faulty, configuration)); + + // The wrapper really did reach the third call — otherwise the assertion above would be + // pinning some unrelated throw, and the "partial flip" it claims to model never happened. + faulty.Calls.ShouldBe(3); + + // The retry: same file, no wrapper. Idempotent re-registration converges on all four. + LocalDbSetup.OnReady(real, configuration); + + real.ReplicatedTables.Keys.OrderBy(k => k, StringComparer.Ordinal) + .ShouldBe(["alarm_condition_state", "alarm_sf_events", "deployment_artifacts", "deployment_pointer"]); + } + + /// + /// Passes everything through to a real database except the failOnCall-th + /// RegisterReplicated, which throws — the mid-loop partial-flip shape. + /// + private sealed class FailsOnNthRegistration(ILocalDb inner, int failOnCall) : ILocalDb + { + /// How many registrations were attempted, successful or not. + public int Calls { get; private set; } + + public IReadOnlyDictionary ReplicatedTables => inner.ReplicatedTables; + + public SqliteConnection CreateConnection() => inner.CreateConnection(); + + public Task ExecuteAsync(string sql, object? parameters, CancellationToken cancellationToken) => + inner.ExecuteAsync(sql, parameters, cancellationToken); + + public Task> QueryAsync( + string sql, Func map, object? parameters, CancellationToken cancellationToken) => + inner.QueryAsync(sql, map, parameters, cancellationToken); + + public Task BeginTransactionAsync(CancellationToken cancellationToken) => + inner.BeginTransactionAsync(cancellationToken); + + public ReplicatedTable RegisterReplicated(string tableName) => + RegisterReplicated(tableName, baselineExistingRows: false); + + public ReplicatedTable RegisterReplicated(string tableName, bool baselineExistingRows) + { + Calls++; + + if (Calls == failOnCall) + throw new InvalidOperationException($"simulated registration failure on '{tableName}'"); + + return inner.RegisterReplicated(tableName, baselineExistingRows); + } + + public bool DeregisterReplicated(string tableName) => inner.DeregisterReplicated(tableName); + } + + private static Serilog.ILogger BuildLogger(ILogEventSink sink) => + new Serilog.LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sink).CreateLogger(); + + /// Captures whatever logs. + private sealed class CollectingSink : ILogEventSink + { + public List Events { get; } = []; + + public void Emit(LogEvent logEvent) => Events.Add(logEvent); + } + + private void DisposeProviders() + { + foreach (var provider in _providers) + provider.Dispose(); + + _providers.Clear(); + + // No in-memory mode, so these are real files. Pooled connections keep a handle open past + // dispose; clearing the pools first is what lets a reopen (or the delete below) succeed. + SqliteConnection.ClearAllPools(); } public void Dispose() { - _provider?.Dispose(); - - // No in-memory mode, so these are real files. Pooled connections keep a handle open past - // dispose; clearing the pools first is what makes the delete actually succeed. - SqliteConnection.ClearAllPools(); + DisposeProviders(); foreach (var path in new[] { _dbPath, $"{_dbPath}-wal", $"{_dbPath}-shm" }) { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbWiringTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbWiringTests.cs index 4dc9bd56..6798faf5 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbWiringTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbWiringTests.cs @@ -45,16 +45,27 @@ public sealed class LocalDbWiringTests : IDisposable /// , health, and observability methods, /// over a temp-file LocalDb:Path. /// - private IServiceProvider BuildDriverGraph() + /// + /// Whether this node carries a replication configuration. Since 2026-08-18 that is what + /// decides whether LocalDbSetup.OnReady registers the tables for change capture at + /// all, so the two graphs are genuinely different nodes and both are pinned below. Most of + /// the fleet is the default-OFF one. + /// + private IServiceProvider BuildDriverGraph(bool replicating = false) { var dbPath = Path.Combine(Path.GetTempPath(), $"otopcua-wiring-{Guid.NewGuid():N}.db"); _dbPaths.Add(dbPath); - var builder = WebApplication.CreateBuilder(new WebApplicationOptions { Args = [] }); - builder.Configuration.AddInMemoryCollection(new Dictionary + var settings = new Dictionary { ["LocalDb:Path"] = dbPath, - }); + }; + + if (replicating) + settings["LocalDb:Replication:ApiKey"] = "wiring-test-sync-key"; + + var builder = WebApplication.CreateBuilder(new WebApplicationOptions { Args = [] }); + builder.Configuration.AddInMemoryCollection(settings); // The exact LocalDb composition Program.cs runs under hasDriver. builder.Services.AddOtOpcUaLocalDb(builder.Configuration); @@ -86,9 +97,9 @@ public sealed class LocalDbWiringTests : IDisposable } [Fact] - public void DriverGraph_LocalDbResolvesAsASingletonWithEveryReplicatedTableRegistered() + public void ReplicatingDriverGraph_LocalDbResolvesAsASingletonWithEveryReplicatedTableRegistered() { - var sp = BuildDriverGraph(); + var sp = BuildDriverGraph(replicating: true); var first = sp.GetService(); first.ShouldNotBeNull(); @@ -100,6 +111,22 @@ public sealed class LocalDbWiringTests : IDisposable .ShouldBe(["alarm_condition_state", "alarm_sf_events", "deployment_artifacts", "deployment_pointer"]); } + [Fact] + public void DefaultOffDriverGraph_LocalDbStillResolvesButRegistersNoTables() + { + // BEHAVIOUR CHANGE (2026-08-18): registration follows the replication config. This graph is + // most of the fleet — central and site-b are default-OFF — and it must still get a working + // local database (the artifact cache and the alarm buffer both depend on it) while paying + // for none of the change-capture machinery it has no peer to send to. + var sp = BuildDriverGraph(); + + var db = sp.GetService(); + db.ShouldNotBeNull(); + sp.GetService().ShouldNotBeNull(); + + db.ReplicatedTables.ShouldBeEmpty(); + } + [Fact] public void DriverGraph_ArtifactCacheResolvesToTheLocalDbBackedImplementation() { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs index d4edc62d..c25bbdb9 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -5,6 +5,7 @@ using Serilog; using Serilog.Events; using Shouldly; using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Engines; using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Host.Engines; @@ -380,45 +381,112 @@ public sealed class RoslynVirtualTagEvaluatorTests CompiledCacheCount(sut).ShouldBe(1); } - /// 02/S12 concurrent stress repro (RED on current code): while one loop runs many compiled - /// (non-passthrough) evaluations of the same expression, a second loop hammers - /// — the apply-boundary clear. On the - /// unfixed tree a clear landing between a child's GetOrCompile and the run's disposed-guard - /// surfaces an ObjectDisposedException as a Failure("script threw: Cannot access a disposed - /// object…"); the fix retries once and every result stays Success. The whole test is WaitAsync- - /// bounded so a regression fails fast rather than hanging. + /// How long the racing loops below keep hammering the evaluator. A DURATION rather than a + /// fixed iteration count: every clear forces a recompile, so a fixed workload's wall-clock cost tracks + /// whatever CPU the box has left, and a busy box then blows the test's own hang budget. + private static readonly TimeSpan RaceWindow = TimeSpan.FromSeconds(10); + + /// Upper bound on evaluations per racing loop, so an idle box does bounded work rather than + /// spinning for the whole . + private const int MaxIterationsPerLoop = 400; + + /// 02/S12 concurrent stress: while many loops run compiled (non-passthrough) evaluations of + /// the same expression, a second loop hammers + /// — the apply-boundary clear. A clear landing between a child's GetOrCompile and the run's + /// disposed-guard raises an inside the evaluation; on the unfixed + /// tree that escaped as Failure("script threw: Cannot access a disposed object…"), and the fix + /// re-fetches into the current cache generation and retries ONCE. The whole test is WaitAsync-bounded so + /// a regression fails fast rather than hanging. + /// + /// Shape history — why this is not a zero-failure assertion (renamed 2026-08-18 from + /// Evaluate_racing_ClearCompiledScripts_never_fails_with_disposed). The test previously + /// asserted failures.ShouldBeEmpty(), which silently encoded a TIMING assumption: that at most + /// ONE clear can land inside a single evaluation, so the product's one-shot retry always suffices. The + /// clear loop's spin cadence was tuned to hold that assumption. It does not hold under full-solution + /// parallel test load — with the thread pool saturated the fetch→run window stretches, TWO clears land + /// inside one evaluation, and the retry legitimately exhausts. The test failed under load while passing + /// 3/3 in isolation. That is a test-design defect, not a product defect: exhausting a one-shot retry + /// under a clear cadence no production apply comes close to is a documented, bounded outcome. + /// + /// The fix could have re-paced the clears against observed evaluation latency, but that only + /// swaps one timing assumption for a safer one — it stays load-sensitive, and needs machinery to + /// measure latency at runtime. Instead the assertion now targets the invariant the retry actually + /// guarantees, which is timing-independent: no raw disposed-script failure ever ESCAPES the + /// retry. A "script threw: Cannot access a disposed object…" (the generic-catch escape) fails the + /// test on the first occurrence, however loaded the box is. Everything else this race can legitimately + /// produce is bucketed and rate-bounded rather than banned, which keeps the check non-vacuous — a build + /// whose retry never absorbs anything would otherwise sail through a shape-only assertion: + /// + /// — the documented + /// retry-exhaustion outcome (two clears inside one evaluation). + /// — the second residual vector, and it + /// is a starvation symptom, not a disposed-race escape. This test deliberately saturates the thread + /// pool (hundreds of Task.Run enqueues per second from 12 loops plus a spinning clear loop), and + /// TimedScriptEvaluator starts its clock at WaitAsync rather than when the inner + /// Task.Run gets a thread — so a perfectly healthy evaluation can blow the 5 s budget while still + /// queued. Classifying that as a leak would hand the test back the load-fragility this reshape removed. + /// + /// + /// The workload is duration-bounded, and that is the SECOND timing assumption removed. The + /// loops used to run a fixed 12 × 400 = 4800 evaluations against a fixed 45 s WaitAsync budget. + /// Every clear forces the next evaluation to recompile (5-20 ms), so the wall-clock cost of that fixed + /// workload is set by how much CPU the box will spare — and running four instances of this test class + /// concurrently on the dev box reproduced a hard failure that has nothing to do with the race: + /// System.TimeoutException at the 45 s budget, 4/4 runs. That is almost certainly the shape the + /// original "fails under full-solution parallel test load" report saw. The loops now stop at + /// OR , whichever comes first, so a starved + /// box simply lands fewer evaluations instead of blowing a budget; the 45 s WaitAsync is left in + /// place purely as a hang detector, with 4× headroom over the window it now guards. + /// + /// Calibration of both bounds (be sceptical of them). The disposed-race did NOT + /// reproduce at all on the arm64 macOS dev box this reshape was written on — zero failures in isolation, + /// zero under concurrently-running Runtime.Tests / Host.Tests / OpcUaServer suites, and still zero with + /// the product's one-shot retry experimentally disabled, i.e. the fetch→run window never opened there + /// and this test was vacuous on that hardware whatever it asserted. So the bound could not be fitted to + /// a measured rate; it is 10% of the evaluations actually performed, hundreds of times looser than the + /// old fire-on-the-first-failure assertion. Exhaustion needs a clear inside BOTH the first attempt's + /// window and the retry's, so its rate goes as the square of the single-window hit rate — 10% of + /// evaluations exhausting implies roughly a third of them hitting a disposed evaluator on the first + /// try, which is a broken retry, not a busy machine. The starvation-timeout bucket gets the same bound + /// for the same reason: a handful of queued-too-long evaluations is the environment, but 10% of them + /// missing a 5 s budget means the evaluator stopped evaluating. If a loaded box ever does trip EITHER + /// bound, the rate itself is the finding: record it before widening the number. [Fact] - public async Task Evaluate_racing_ClearCompiledScripts_never_fails_with_disposed() + public async Task Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure() { - // Generous timeout so the wall-clock budget never fires and confounds the race assertion. + // Generous script budget so the wall-clock timeout rarely fires and confounds the race assertion — + // "rarely", not "never": it covers the Task.Run enqueue, so a starved pool can still blow it. That + // residual is bucketed and bounded below rather than treated as a disposed-race escape. using var sut = new RoslynVirtualTagEvaluator( NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromSeconds(5)); const string expr = "return (int)ctx.GetTag(\"a\").Value + 1;"; const int loopCount = 12; - const int iterations = 400; var failures = new System.Collections.Concurrent.ConcurrentBag(); - var remaining = loopCount; // number of concurrent evaluation loops still running + var evaluated = 0; // evaluations actually performed (the race window may cut loops short) + var remaining = loopCount; // number of concurrent evaluation loops still running + var stopAtMs = Environment.TickCount64 + (long)RaceWindow.TotalMilliseconds; // Many concurrent evaluation loops put the thread pool under enough pressure that the inner // Task.Run hop inside TimedScriptEvaluator is measurably delayed — widening the - // fetch→run-disposed-guard window so a clear reliably lands inside SOME in-flight evaluation. - // The clear loop clears on a short spin cadence (not back-to-back) so (a) most evaluations hit - // the warm cache — keeping compile cost bounded — and (b) at most one clear lands within a - // single evaluation, so the single retry the fix adds is sufficient (a back-to-back clear loop - // would both compile-swamp the RED run into a timeout and defeat the one-shot retry). Pre-fix a - // clear disposing the just-fetched evaluator surfaces as Failure("script threw: Cannot access a - // disposed object…"); post-fix the retry re-fetches into the current generation → all Success. + // fetch→run-disposed-guard window so a clear can land inside an in-flight evaluation. + // The clear loop clears on a short spin cadence rather than back-to-back purely as a COST bound: + // most evaluations then hit the warm cache instead of recompiling. Neither the cadence nor the + // iteration count is a correctness knob any more — the assertions below hold for any number of + // clears landing inside a single evaluation, and for any number of evaluations completed. var evalLoops = Enumerable.Range(0, loopCount).Select(_ => Task.Run(() => { - for (var i = 0; i < iterations; i++) + var done = 0; + for (var i = 0; i < MaxIterationsPerLoop && Environment.TickCount64 < stopAtMs; i++) { var r = sut.Evaluate("vt-race", expr, new Dictionary { ["a"] = i }); + done++; if (!r.Success) { failures.Add(r.Reason ?? ""); } } + Interlocked.Add(ref evaluated, done); Interlocked.Decrement(ref remaining); }, TestContext.Current.CancellationToken)).ToArray(); @@ -431,11 +499,44 @@ public sealed class RoslynVirtualTagEvaluatorTests } }, TestContext.Current.CancellationToken); + // Hang detector only: the loops self-terminate at RaceWindow, so firing this means something + // wedged, not that the box was slow. await Task.WhenAll(evalLoops.Append(clearLoop)) .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); - failures.ShouldBeEmpty( - $"every evaluation must succeed despite racing clears; observed: {string.Join(" | ", failures)}"); + var totalEvaluations = Volatile.Read(ref evaluated); + // Loose by design, with an absolute floor so a starved run (few evaluations landed) cannot trip on + // a single occurrence. See the doc-comment: broken-behaviour detectors, not timing gates. + var rateBound = Math.Max(totalEvaluations / 10, 8); + + var exhausted = failures.Count(r => r == ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); + var starved = failures.Count(r => r.StartsWith(ScriptEvalFailureReasons.TimedOutPrefix, StringComparison.Ordinal)); + + // (1) The invariant, and the only assertion that fires on a single occurrence: a raw + // ObjectDisposedException escaping the retry (pre-fix: "script threw: Cannot access a + // disposed object…") lands here, as does any other unexpected failure mode. The two + // legitimate outcomes above are excluded — they are rate-bounded instead, below. + var leaked = failures + .Where(r => r != ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation) + .Where(r => !r.StartsWith(ScriptEvalFailureReasons.TimedOutPrefix, StringComparison.Ordinal)) + .ToArray(); + leaked.ShouldBeEmpty( + "a racing ClearCompiledScripts must never surface a failure other than " + + $"\"{ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation}\" or " + + $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}"); + + // (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it. + exhausted.ShouldBeLessThan( + rateBound, + "the one-shot retry must absorb the overwhelming majority of raced clears; " + + $"{exhausted}/{totalEvaluations} evaluations exhausted it"); + + // (3) The starvation bucket is tolerated but not unbounded — at 10% the evaluator has stopped + // evaluating rather than the box being busy. + starved.ShouldBeLessThan( + rateBound, + "queue-starvation timeouts are expected under this stress but must stay marginal; " + + $"{starved}/{totalEvaluations} evaluations missed the 5s budget"); } /// Reads the count of the private compiled-script cache via reflection. The cache is a diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs index 4d75d858..325f181a 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Commons.OpcUa; @@ -14,7 +15,7 @@ namespace ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests; /// different from the one asked. Each test below pins one dimension the key must discriminate on, /// because a key that collides across any of them hands one session another's authority. /// -public sealed class SessionAclDecisionCacheTests +public sealed class SessionAclDecisionCacheTests(ITestOutputHelper output) { private const string Session = "key-1"; private const string Node = "Plant/Modbus/dev1/Speed"; @@ -520,6 +521,151 @@ public sealed class SessionAclDecisionCacheTests cache.LiveShardCount.ShouldBe(cache.Count); } + /// + /// Two lookups arriving together at different generations must leave the higher one stamped, + /// whichever of them wins the compare-exchange. + /// + /// + /// + /// The single-shot-CAS defect: both callers read the same baseline stamp, and if the older + /// generation's exchange lands first, the newer one's exchange fails against the moved stamp and + /// falls out with no retry. Its generation is never published, so its own TryGet misses and + /// the Set that follows is dropped at the Generation != generation guard — a lost + /// store in exactly the post-deploy window where the cache is coldest. Verdict safety is not at + /// stake (the per-shard generation check decides that); cache usefulness is. + /// + /// + /// ⚠️ Red is probabilistic per round — it needs both racers to read the baseline stamp + /// before either exchanges, a window a few instructions wide. Everything about the harness + /// exists to buy those odds, and the measurements are why it looks the way it does: fresh + /// threads per round land red about once in twenty thousand, a two-party + /// no better (its post-phase action releases from inside one racer, handing it a head + /// start), while the long-lived racers plus a third-thread starter used below turn roughly a + /// sixth to a half of all rounds red. + /// + /// + /// ⚠️ Do not cut the round count on that arithmetic. A per-round rate near 25% suggests a + /// couple of hundred rounds would be overwhelming — but the misses are not independent, they + /// arrive in run-length bursts: the racers get descheduled together for a stretch, and the + /// stretch can be the whole run. Measured, against the mutation, with the rest of this assembly + /// running in parallel as it does in CI: 2,000 rounds passed vacuously in 1 run of 3 + /// (stale=0 — the defect present and undetected), while 10,000 was red in 5 of 5, first hit + /// within rounds 1-13, stale 1,595-4,591. The same 2,000 rounds run alone never missed + /// (70-986 stale), so the load from the sibling classes is the variable that matters, and a + /// standalone measurement will overstate the margin. The cost of the margin is ~20ms. + /// + /// + /// Every round gets a fresh cache: both racers must start from the -1 seed, or the + /// previous round's stamp would let the <= guard return before either reaches the + /// exchange and the race would never be run at all. + /// + /// + /// It is also the only pin on the retry loop's straggler guard being re-read per attempt. + /// Hoisting that guard to a single check before the loop leaves + /// + /// green — that straggler is sequential, so the one pre-loop check still catches it — while a + /// straggler that lost an exchange spins back, re-reads the newer stamp as its expected + /// value, and rolls it backward. That lands here, as the same stale-stamp failure. + /// + /// + /// Nothing here uses AdvanceGenerationForTest: the stamp must move through the ordinary + /// lookup path, which is the path the defect lives on. + /// + /// + [Fact] + public void Concurrent_lookups_at_mixed_generations_always_publish_the_highest() + { + const int rounds = 10_000; + const int spinsBeforeYield = 4_000; + + // Array-as-ref-cell: the one cell that is re-seated every round (a fresh cache per round), shared + // by the starter and both racers. A captured local would also take `ref` (gate/finished below do + // exactly that) — the array is a readability choice marking the re-seated slot, not a necessity. + var slot = new SessionAclDecisionCache[1]; + var gate = 0; // starter's release signal: the round number both racers are cleared to run + var finished = 0; // racers' completion count for the current round + var firstStaleRound = -1; + var staleRounds = 0; + + // ⚠️ Deliberately NOT the file's Barrier-per-round idiom (see + // Concurrent_eviction_and_insertion_leave_the_counter_exact, which is the right shape for its job: + // many workers that only need to start together). This gate/finished spin protocol exists because + // the window here is nanoseconds wide and a Barrier releases from inside one of the racers — see the + // remarks above. Both idioms are in the file on purpose; neither is a stray. + // + // Raw threads rather than the thread pool: the pool may serialise two work items onto one thread, + // which would make the race unreachable. Held for the whole run so the release is the only skew. + var low = new Thread(() => Race(1L)) { IsBackground = true }; + var high = new Thread(() => Race(2L)) { IsBackground = true }; + + var started = Stopwatch.GetTimestamp(); + + low.Start(); + high.Start(); + + for (var round = 0; round < rounds; round++) + { + Volatile.Write(ref slot[0], new SessionAclDecisionCache()); + Volatile.Write(ref finished, 0); + Volatile.Write(ref gate, round + 1); // both racers are spinning on this one store + + for (var spins = 0; Volatile.Read(ref finished) != 2; spins++) + if (spins < spinsBeforeYield) Thread.SpinWait(1); + else Thread.Yield(); + + if (Volatile.Read(ref slot[0]).Generation != 2L) + { + if (firstStaleRound < 0) firstStaleRound = round; + staleRounds++; + } + } + + low.Join(); + high.Join(); + + var elapsed = Stopwatch.GetElapsedTime(started); + + // Emitted unconditionally, because the way this test fails on a constrained runner is by passing. + // ⚠️ It cannot report a hit rate: under the fixed code no round is stale BY DEFINITION, and how many + // rounds actually entered the read-then-exchange window is unobservable from out here — the only way + // to see it would be to instrument production, which is not worth a diagnostic. So it reports what it + // can honestly measure, and the reading is: fewer than 3 processors means the three threads cannot + // run concurrently and the race is unreachable, while a per-round cost well above the 1.5-3us/round + // this machine turns in means the racers are being descheduled rather than spinning (24us/round was + // observed under load, and that is the shape of a run that proves less than it looks like it does). + // The measured red rate under the single-shot mutation is 16-46% of rounds. + output.WriteLine( + $"rounds={rounds} stale={staleRounds} processors={Environment.ProcessorCount} " + + $"elapsed={elapsed.TotalMilliseconds:F1}ms perRound={elapsed.TotalMicroseconds / rounds:F2}us"); + + firstStaleRound.ShouldBe( + -1, + $"round {firstStaleRound} (of {staleRounds} stale in {rounds}): the newer generation must " + + "publish even when it loses the CAS race"); + + void Race(long generation) + { + for (var round = 0; round < rounds; round++) + { + // Tight spin on the starter's store, not a park: both racers take the same invalidation from + // a third core and so leave the spin within a few nanoseconds of each other. Releasing from + // one of the racers instead (a Barrier's post-phase action) hands the releaser a head start + // of roughly the other's wake-up latency, which is orders of magnitude wider than the + // read-then-exchange window and drives the hit rate to near zero. The yield after + // spinsBeforeYield is only a liveness backstop for a machine with fewer cores than this + // needs threads — the release normally lands long before it. + for (var spins = 0; Volatile.Read(ref gate) != round + 1; spins++) + if (spins < spinsBeforeYield) Thread.SpinWait(1); + else Thread.Yield(); + + Volatile.Read(ref slot[0]) + .TryGet(generation, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out _); + + Interlocked.Increment(ref finished); + } + } + } + private static bool Ask( SessionAclDecisionCache cache, long generation, diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Deployment/LocalDbDeploymentArtifactCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Deployment/LocalDbDeploymentArtifactCacheTests.cs index d34c5ccc..4fc391ab 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Deployment/LocalDbDeploymentArtifactCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Deployment/LocalDbDeploymentArtifactCacheTests.cs @@ -23,10 +23,14 @@ namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.DeploymentCache; /// semantics — live entirely in SQL, so a mocked seam would assert nothing about them. /// /// -/// This project cannot reference the Host, so the schema setup here mirrors -/// LocalDbSetup.OnReady rather than calling it. The load-bearing -/// DDL → RegisterReplicated ordering is pinned by the Host's own -/// LocalDbSetupTests; what matters here is only that the tables exist. +/// This project cannot reference the Host, so the setup here reproduces only the two +/// cache tables — not LocalDbSetup.OnReady's behaviour. In particular it +/// registers them unconditionally and without baselining, whereas the production callback +/// registers only when the node is configured to replicate and deregisters when it is not. +/// That divergence is intentional and inert here: these tests need a database whose tables +/// exist and capture, and nothing below asserts anything about registration. The +/// load-bearing DDL-then-RegisterReplicated ordering and the conditional-registration rules +/// are pinned by the Host's own LocalDbSetupTests. /// /// public sealed class LocalDbDeploymentArtifactCacheTests : IDisposable