From f64b10b964bceacf2b66ff6f4da00e72c6693fc3 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 17 Aug 2026 07:06:07 -0400 Subject: [PATCH 01/17] =?UTF-8?q?docs(plan):=20perf=20follow-ups=20round?= =?UTF-8?q?=203=20=E2=80=94=20r2=20register=20closes=20+=20four=20local=20?= =?UTF-8?q?live=20gates?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/plans/2026-08-17-perf-followups-r3.md | 432 ++++++++++++++++++ ...2026-08-17-perf-followups-r3.md.tasks.json | 14 + 2 files changed, 446 insertions(+) create mode 100644 docs/plans/2026-08-17-perf-followups-r3.md create mode 100644 docs/plans/2026-08-17-perf-followups-r3.md.tasks.json 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..7bc9fc9a --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -0,0 +1,432 @@ +# 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 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. 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..630b1012 --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json @@ -0,0 +1,14 @@ +{ + "planPath": "docs/plans/2026-08-17-perf-followups-r3.md", + "tasks": [ + {"id": 1, "subject": "Task 1: ACL InvalidateIfStale — monotonic-max CAS loop", "status": "pending"}, + {"id": 2, "subject": "Task 2: S7 read-pass health — worst-state-wins aggregation", "status": "pending"}, + {"id": 3, "subject": "Task 3: Fix stale OTOPCUA_CONFIG_MODE docs", "status": "pending"}, + {"id": 4, "subject": "Task 4: Live gate — first-POST-404 catch + no-body POST binding", "status": "pending", "blockedBy": [1, 2, 3]}, + {"id": 5, "subject": "Task 5: Live gate — FetchAndCache legs", "status": "pending", "blockedBy": [4]}, + {"id": 6, "subject": "Task 6: Live gate — alarm-bearing surgical ratchet", "status": "pending", "blockedBy": [5]}, + {"id": 7, "subject": "Task 7: Live gate — ACL-enabled enforcement on site-a", "status": "pending", "blockedBy": [6]}, + {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "pending", "blockedBy": [1, 2, 3, 4, 5, 6, 7]} + ], + "lastUpdated": "2026-08-17T19:05:00Z" +} From e9ba174156492b989a30abd0938d8e1c3f6bfc7c Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 17 Aug 2026 07:07:51 -0400 Subject: [PATCH 02/17] =?UTF-8?q?docs(config):=20OTOPCUA=5FCONFIG=5FMODE?= =?UTF-8?q?=20is=20gone=20=E2=80=94=20site=20nodes=20are=20hardcoded=20Fet?= =?UTF-8?q?chAndCache=20(Phase=204)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CLAUDE.md | 5 +++-- docs/Configuration.md | 2 +- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index e02d5fb1..2cf73e4a 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`. diff --git a/docs/Configuration.md b/docs/Configuration.md index c28def93..d6b03b42 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** From 4c161181052502a15b4ddbf47d659ae4d302c089 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 17 Aug 2026 07:14:32 -0400 Subject: [PATCH 03/17] =?UTF-8?q?fix(s7):=20read-pass=20health=20is=20wors?= =?UTF-8?q?t-state-wins=20=E2=80=94=20a=20mixed=20pass=20can=20no=20longer?= =?UTF-8?q?=20report=20Healthy?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs | 134 +++++++++++++--- .../S7SpanReadParityTests.cs | 151 +++++++++++++++++- 2 files changed, 261 insertions(+), 24 deletions(-) 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..82f8516b 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,90 @@ 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); } } + + // THE single health write of the pass — worst-state-wins over every outcome above. + // Deliberately the last statement of the try body rather than a finally: the three OCE + // arms abandon the batch mid-pass, and a partially-observed pass must not stamp a + // verdict. LastSuccessfulRead advances whenever ANYTHING read, even into a + // Degraded/Faulted state — see ReadPassOutcome for why that is load-bearing. + _health = new DriverHealth( + outcome.WorstFailure, + outcome.AnySuccess ? now : _health.LastSuccessfulRead, + outcome.WorstFailure == DriverState.Healthy ? null : outcome.FirstError); } finally { _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 failure's message — the causal one. A later failure is as likely to be a + /// consequence of the first as an independent fault, so it does not overwrite it. + /// + public string? FirstError { get; private set; } + + /// Records that one tag read successfully. + public void RecordSuccess() => AnySuccess = true; + + /// Records one failed tag, keeping the worst state and the first message. + /// 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)) WorstFailure = state; + FirstError ??= 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 +822,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 +831,7 @@ public sealed class S7Driver List leftovers, DataValueSnapshot[] results, DateTime now, + ReadPassOutcome outcome, CancellationToken ct) { var stillPerTag = new List(); @@ -825,13 +906,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 +983,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 +1009,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 +1021,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 +1082,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 +1116,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 +1127,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/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..b55761b5 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,135 @@ 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()); + 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"); } /// @@ -611,6 +743,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 +885,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)]; From 441b34a39179f9f814d0b45c20d6634e2613430a Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 17 Aug 2026 07:15:30 -0400 Subject: [PATCH 04/17] =?UTF-8?q?fix(acl):=20make=20InvalidateIfStale=20a?= =?UTF-8?q?=20monotonic-max=20CAS=20loop=20=E2=80=94=20stamp=20publication?= =?UTF-8?q?=20is=20never=20deferred?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../Security/SessionAclDecisionCache.cs | 47 +++++++- .../SessionAclDecisionCacheTests.cs | 110 ++++++++++++++++++ 2 files changed, 151 insertions(+), 6 deletions(-) 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/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs index 4d75d858..d78cffe5 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs @@ -520,6 +520,116 @@ 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 + /// quarter to a half of all rounds red. So a round or two is enough in practice, and the + /// twenty thousand are for the machine that is slower or busier than this one. + /// + /// + /// 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 = 20_000; + const int spinsBeforeYield = 4_000; + + // The cache under race, handed over through a slot the starter rewrites between rounds. + 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; + + // 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 }; + + 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(); + + 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, From b35e423c1dd2d2f7157eaaba0ed458460244702b Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:00:33 -0400 Subject: [PATCH 05/17] =?UTF-8?q?fix(s7):=20a=20read=20pass=20that=20obser?= =?UTF-8?q?ves=20nothing=20reports=20nothing=20=E2=80=94=20empty=20pass=20?= =?UTF-8?q?no=20longer=20clears=20Faulted?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs | 15 ++++++-- .../S7SpanReadParityTests.cs | 38 +++++++++++++++++++ 2 files changed, 49 insertions(+), 4 deletions(-) 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 82f8516b..60926e7c 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs @@ -672,10 +672,17 @@ public sealed class S7Driver // arms abandon the batch mid-pass, and a partially-observed pass must not stamp a // verdict. LastSuccessfulRead advances whenever ANYTHING read, even into a // Degraded/Faulted state — see ReadPassOutcome for why that is load-bearing. - _health = new DriverHealth( - outcome.WorstFailure, - outcome.AnySuccess ? now : _health.LastSuccessfulRead, - outcome.WorstFailure == DriverState.Healthy ? null : outcome.FirstError); + // + // A pass that observed NOTHING — an empty batch, or one whose every reference was + // unresolvable — reports nothing: it writes no health at all, preserving a prior + // Faulted (e.g. the access-denied config alert) that a Healthy write would have erased. + if (outcome.AnySuccess || outcome.WorstFailure != DriverState.Healthy) + { + _health = new DriverHealth( + outcome.WorstFailure, + outcome.AnySuccess ? now : _health.LastSuccessfulRead, + outcome.WorstFailure == DriverState.Healthy ? null : outcome.FirstError); + } } finally { _gate.Release(); } return results; 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 b55761b5..454a2798 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 @@ -555,6 +555,44 @@ public sealed class S7SpanReadParityTests before!.Value, "one tag read fine, so the watchdog's evidence must still advance"); } + /// + /// 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"); + } + /// /// An answer of the wrong SHAPE — one item short — cannot be mapped back onto the request's /// indexes, so the driver refuses to guess which tag got which value and falls the whole From 088a1a1e816e34f66c00d515ba7d9607ebe7b332 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:00:42 -0400 Subject: [PATCH 06/17] =?UTF-8?q?docs(plan):=20r3=20amendment=20=E2=80=94?= =?UTF-8?q?=20ScadaBridge=20register=20rows=2038/39=20join=20as=20Tasks=20?= =?UTF-8?q?9-10?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/plans/2026-08-17-perf-followups-r3.md | 77 +++++++++++++++++++ ...2026-08-17-perf-followups-r3.md.tasks.json | 6 +- 2 files changed, 81 insertions(+), 2 deletions(-) diff --git a/docs/plans/2026-08-17-perf-followups-r3.md b/docs/plans/2026-08-17-perf-followups-r3.md index 7bc9fc9a..72fb449f 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -413,6 +413,83 @@ 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) + +**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) 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 index 630b1012..f4c749d3 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json +++ b/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json @@ -3,12 +3,14 @@ "tasks": [ {"id": 1, "subject": "Task 1: ACL InvalidateIfStale — monotonic-max CAS loop", "status": "pending"}, {"id": 2, "subject": "Task 2: S7 read-pass health — worst-state-wins aggregation", "status": "pending"}, - {"id": 3, "subject": "Task 3: Fix stale OTOPCUA_CONFIG_MODE docs", "status": "pending"}, + {"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": "pending", "blockedBy": [1, 2, 3]}, {"id": 5, "subject": "Task 5: Live gate — FetchAndCache legs", "status": "pending", "blockedBy": [4]}, {"id": 6, "subject": "Task 6: Live gate — alarm-bearing surgical ratchet", "status": "pending", "blockedBy": [5]}, {"id": 7, "subject": "Task 7: Live gate — ACL-enabled enforcement on site-a", "status": "pending", "blockedBy": [6]}, - {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "pending", "blockedBy": [1, 2, 3, 4, 5, 6, 7]} + {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "pending", "blockedBy": [1, 2, 3, 4, 5, 6, 7, 9, 10]}, + {"id": 9, "subject": "Task 9: Roslyn evaluator racing test — remove timing assumption (ScadaBridge row 38)", "status": "pending"}, + {"id": 10, "subject": "Task 10: LocalDb conditional registration + baseline + deregister self-heal (ScadaBridge row 39)", "status": "pending"} ], "lastUpdated": "2026-08-17T19:05:00Z" } From f4b91dbbaba96419eef26c9e16ef8838d9f235d8 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:10:44 -0400 Subject: [PATCH 07/17] =?UTF-8?q?test(acl):=20race=20harness=20=E2=80=94?= =?UTF-8?q?=20hit=20diagnostics,=2010k=20rounds,=20idiom=20notes=20(review?= =?UTF-8?q?=20round)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../SessionAclDecisionCacheTests.cs | 46 +++++++++++++++++-- 1 file changed, 41 insertions(+), 5 deletions(-) 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 d78cffe5..2ab67dce 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"; @@ -540,8 +541,18 @@ public sealed class SessionAclDecisionCacheTests /// 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 - /// quarter to a half of all rounds red. So a round or two is enough in practice, and the - /// twenty thousand are for the machine that is slower or busier than this one. + /// 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 @@ -564,21 +575,31 @@ public sealed class SessionAclDecisionCacheTests [Fact] public void Concurrent_lookups_at_mixed_generations_always_publish_the_highest() { - const int rounds = 20_000; + const int rounds = 10_000; const int spinsBeforeYield = 4_000; - // The cache under race, handed over through a slot the starter rewrites between rounds. + // Array-as-ref-cell: a one-element array is the cheapest storage a lambda can close over AND that + // Volatile.Read/Write can take a `ref` to — a captured local cannot be passed by ref, and a plain + // field would need the test moved onto the class. 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(); @@ -602,6 +623,21 @@ public sealed class SessionAclDecisionCacheTests 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 " + From 1765e30063488f4983019386b9bb7267c444f3ce Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:10:51 -0400 Subject: [PATCH 08/17] fix(s7): worst-severity error message + OCE flushes recorded pass evidence (review round) --- .../ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs | 70 ++++++++++---- .../S7SpanReadParityTests.cs | 94 +++++++++++++++++++ 2 files changed, 146 insertions(+), 18 deletions(-) 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 60926e7c..bed5e1bc 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs @@ -666,25 +666,33 @@ public sealed class S7Driver results[i] = new DataValueSnapshot(null, RecordReadFailure(ex, outcome), null, now); } } - - // THE single health write of the pass — worst-state-wins over every outcome above. - // Deliberately the last statement of the try body rather than a finally: the three OCE - // arms abandon the batch mid-pass, and a partially-observed pass must not stamp a - // verdict. LastSuccessfulRead advances whenever ANYTHING read, even into a - // Degraded/Faulted state — see ReadPassOutcome for why that is load-bearing. + } + 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 — an empty batch, or one whose every reference was - // unresolvable — reports nothing: it writes no health at all, preserving a prior - // Faulted (e.g. the access-denied config alert) that a Healthy write would have erased. - if (outcome.AnySuccess || outcome.WorstFailure != DriverState.Healthy) + // 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.FirstError); + outcome.WorstFailure == DriverState.Healthy ? null : outcome.WorstError); } + + _gate.Release(); } - finally { _gate.Release(); } return results; } @@ -726,21 +734,47 @@ public sealed class S7Driver public DriverState WorstFailure { get; private set; } = DriverState.Healthy; /// - /// The FIRST failure's message — the causal one. A later failure is as likely to be a - /// consequence of the first as an independent fault, so it does not overwrite it. + /// The first message recorded at the worst severity — the one that explains + /// . /// - public string? FirstError { get; private set; } + /// + /// 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 first message. + /// + /// 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)) WorstFailure = state; - FirstError ??= 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. 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 454a2798..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 @@ -489,6 +489,16 @@ public sealed class S7SpanReadParityTests 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); @@ -555,6 +565,90 @@ public sealed class S7SpanReadParityTests 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 From e29fab19f6c8594b451b720fe7fc6e337bf18db0 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:13:16 -0400 Subject: [PATCH 09/17] =?UTF-8?q?test(acl):=20correct=20the=20array-cell?= =?UTF-8?q?=20comment=20=E2=80=94=20captured=20locals=20do=20take=20ref=20?= =?UTF-8?q?(re-review=20nit)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../SessionAclDecisionCacheTests.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) 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 2ab67dce..325f181a 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs @@ -578,9 +578,9 @@ public sealed class SessionAclDecisionCacheTests(ITestOutputHelper output) const int rounds = 10_000; const int spinsBeforeYield = 4_000; - // Array-as-ref-cell: a one-element array is the cheapest storage a lambda can close over AND that - // Volatile.Read/Write can take a `ref` to — a captured local cannot be passed by ref, and a plain - // field would need the test moved onto the class. + // 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 From 3e62f1617b54549882cc65d0a38d688e49c50c8a Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:25:01 -0400 Subject: [PATCH 10/17] =?UTF-8?q?fix(localdb):=20registration=20follows=20?= =?UTF-8?q?replication=20config=20=E2=80=94=20baseline=20on=20enable,=20de?= =?UTF-8?q?register=20self-heal=20on=20disable=20(pair-symmetric)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LocalDbSetup.OnReady registered all four replicated tables unconditionally 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 made baselineExistingRows unusable, so enabling replication on a long-running default-OFF node converged on SUBSEQUENT WRITES ONLY and the rows already in the file stayed invisible to the peer, silently and forever. Registration now follows one predicate, LocalDbSetup.ReplicationIsConfigured: LocalDb:Replication:PeerAddress OR :ApiKey non-blank. The OR is load-bearing — only the dialling half of a pair sets PeerAddress, so keying on it alone would strip capture from every passive node and the pair would converge in one direction only. SyncListenPort deliberately does not join it: the passive endpoint is fail-closed on the key, so a port with no ApiKey syncs with nobody. configured => RegisterReplicated(table, baselineExistingRows: true), per table, in the unchanged load-bearing DDL->register order unconfigured => DeregisterReplicated(table), an idempotent boot self-heal that drops the capture triggers an earlier build left behind and prunes that table's oplog/row-version rows. One Information line, only when it actually cleaned something. PAIR SYMMETRY: 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. Documented in CLAUDE.md, docs/Configuration.md and the replication runbook (which claimed "this repo never calls DeregisterReplicated"). Verified against the pinned LocalDb 0.2.1: RegisterReplicated(string, bool) and DeregisterReplicated(string) -> bool both exist; baselining seeds __localdb_row_version at HLC 0 and the deregister return value distinguishes "cleaned" from "nothing to clean". No pin bump needed. Tests: LocalDbSetupTests gains pins for both branches (configured via PeerAddress alone and via ApiKey alone; unconfigured => no tables, zero triggers; late-enable => an HLC-0 baseline ledger entry; the log line fires once and only when something was cleaned) — four went red against the old unconditional code, and all four go red again under a constant-true predicate. LocalDbWiringTests splits its exact-set pin into a replicating graph and a default-OFF one. LocalDbPairHarness and AlarmSfLegacyMigratorTests built their database from LocalDb:Path alone while configuring the replication engine from a second config — production reads one configuration, so the two are now aligned. Host.IntegrationTests: 224 passed, 0 failed, 5 skipped. --- CLAUDE.md | 59 ++-- docs/Configuration.md | 12 + .../2026-07-20-localdb-pair-replication.md | 24 +- .../Configuration/LocalDbSetup.cs | 199 ++++++++++++- .../LocalDb/AlarmSfLegacyMigratorTests.cs | 11 +- .../LocalDb/LocalDbPairHarness.cs | 20 +- .../LocalDbSetupTests.cs | 271 ++++++++++++++---- .../LocalDbWiringTests.cs | 39 ++- 8 files changed, 542 insertions(+), 93 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 2cf73e4a..cb59b809 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -650,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 @@ -660,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/docs/Configuration.md b/docs/Configuration.md index d6b03b42..2bccc843 100644 --- a/docs/Configuration.md +++ b/docs/Configuration.md @@ -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/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs index cd70e38c..87c307cc 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,45 @@ 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. + /// + /// /// 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 +103,138 @@ 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 unset), 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/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..d749d476 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs @@ -1,6 +1,8 @@ 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; @@ -20,49 +22,153 @@ 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. + /// + 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 +179,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 +190,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 +200,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 +212,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 +229,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 +239,114 @@ 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), - parameters: null, - TestContext.Current.CancellationToken); + (await ScalarAsync(db, "SELECT COUNT(*) FROM __localdb_oplog")).ShouldBeGreaterThanOrEqualTo(1); + } - oplogRows[0].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_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(); + } + + 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() { From df5339164635a5c6912010acdc2ae1fc9e538fcb Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:42:06 -0400 Subject: [PATCH 11/17] test(localdb): deregister preserves data + partial-flip fails loudly (review round) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review round on 3e62f161. Two coverage gaps and three wording/comment nits. IMPORTANT 1 — deregistration is now proven DATA-PRESERVING. The self-heal test inserted a deployment_pointer row and rebooted unconfigured but never looked at the row again, so a library regression that touched base-table data during cleanup would have gone unnoticed — on the very tables that ARE the boot-from-cache backstop, and on the default-OFF nodes least likely to notice. The new DisablingReplication_PrunesBookkeepingButNeverTouchesTheCachedDataItself asserts the row's CONTENT survives (not just its count — a count passes against a cleanup that blanks columns) while __localdb_row_version and __localdb_oplog, the bookkeeping deregistration does own, go to zero. IMPORTANT 2 — mid-loop partial failure is documented and pinned. Both loops flip four tables with no try/catch, so a throw on the third leaves two flipped and propagates out of the AddZbLocalDb singleton factory, failing host start. That is correct — a node that came up anyway would be silently capturing on an arbitrary subset — and both library calls are idempotent, so the retried boot completes the flip. Written into OnReady's remarks and pinned by AFailureMidwayThroughRegistration_FailsBootLoudly_AndTheRetriedBootConverges, which drives OnReady through a delegating ILocalDb that throws on the Nth RegisterReplicated, asserts the throw propagates, asserts the wrapper actually reached that call, then re-runs OnReady unwrapped and asserts all four converge. MINOR 3 — the Boot helper now records that OnReady's null-logger fallback lands on Serilog's static Log.Logger, which this assembly never assigns; assertions about logging pass an explicit logger. MINOR 5 — log wording: "are both unset" -> "are both absent — unset or blank", matching IsNullOrWhiteSpace. MINOR 4 — LocalDbDeploymentArtifactCacheTests said its setup "mirrors LocalDbSetup.OnReady"; it reproduces the two tables only and registers them unconditionally without baselining. Softened to say so and to name the divergence as intentional and inert there. Falsified both new pins. Wrapper set to failOnCall: 99 (never throws) => the partial-flip pin is the SOLE failure, so it genuinely exercises the Nth-call throw path rather than some incidental exception. Predicate forced constant-true => five pins red including the new data-preservation one. Both mutations reverted. LocalDbSetupTests 15/15. Host.IntegrationTests 226 passed / 0 failed / 5 skipped. Runtime.Tests LocalDbDeploymentArtifactCacheTests 12/12. --- .../Configuration/LocalDbSetup.cs | 11 +- .../LocalDbSetupTests.cs | 120 +++++++++++++++++- .../LocalDbDeploymentArtifactCacheTests.cs | 12 +- 3 files changed, 134 insertions(+), 9 deletions(-) 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 87c307cc..11b1c8d9 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Configuration/LocalDbSetup.cs @@ -67,6 +67,14 @@ public static class LocalDbSetup /// 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, and regardless of replication. Creating /// one lazily when the sink first appears would mean a node that enables the historian @@ -229,7 +237,8 @@ public static class LocalDbSetup { logger.Information( "LocalDb: removed stale change-capture from {TableCount} table(s) — this node has no " - + "replication configured ({PeerAddressKey}/{ApiKeyKey} are both unset), so the capture " + + "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, 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 d749d476..197439df 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/LocalDbSetupTests.cs @@ -6,6 +6,7 @@ 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; @@ -70,10 +71,20 @@ public sealed class LocalDbSetupTests : IDisposable /// 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. + /// + /// 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, @@ -294,6 +305,36 @@ public sealed class LocalDbSetupTests : IDisposable .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); + + 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() { @@ -321,6 +362,77 @@ public sealed class LocalDbSetupTests : IDisposable 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(); 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 From 34829ea0d757585a205f4e539efeccb3f9d49e65 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:48:44 -0400 Subject: [PATCH 12/17] test(scripting): Evaluate_racing_ClearCompiledScripts no longer assumes a single clear per evaluation The racing test encoded two timing assumptions and failed under full-solution parallel load while passing in isolation. Both are removed; no production code changed. 1. Assertion shape. failures.ShouldBeEmpty() assumed at most ONE apply-boundary clear can land inside a single evaluation, so the evaluator's one-shot retry always suffices. Under contention two can land and the retry legitimately exhausts. The test now asserts the invariant the retry actually guarantees and which is timing-independent: no raw disposed-script failure ESCAPES the retry. Every failure must be the documented exhaustion outcome ("evaluator disposed during evaluation") and never the pre-fix generic escape ("script threw: Cannot access a disposed object..."), plus a deliberately loose bound on the exhaustion rate so the check cannot go vacuous. 2. Workload shape. The fixed 12x400 evaluations against a fixed 45s WaitAsync budget is CPU-dependent (every clear forces a recompile). Four concurrent instances of this class reproduced a hard TimeoutException 4/4 - the likely real shape of the reported load failure. The loops are now duration-bounded (10s race window or 400 iterations, whichever first); the 45s WaitAsync stays purely as a hang detector. Renamed to Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure so the name matches what it now asserts; the old name is cited in the doc-comment for traceability. --- .../RoslynVirtualTagEvaluatorTests.cs | 118 +++++++++++++++--- 1 file changed, 98 insertions(+), 20 deletions(-) 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..df2bf96c 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -380,15 +380,74 @@ 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. + /// The one reason string the evaluator is documented to surface when its one-shot retry + /// is exhausted (a SECOND apply-boundary clear landing inside the same evaluation). Anything else + /// carrying "disposed" — notably the pre-fix generic escape "script threw: Cannot access a + /// disposed object…" — is a raw ObjectDisposedException leaking past the retry, i.e. the bug. + private const string RetryExhaustedReason = "evaluator disposed during evaluation"; + + /// 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. Every failure this race produces must be the documented retry-exhaustion outcome + /// () and nothing else — a "script threw: Cannot access a disposed + /// object…" (the generic-catch escape) fails the test on the first occurrence, however loaded the box + /// is. A loose upper bound on the exhaustion RATE keeps the assertion non-vacuous: a build whose retry + /// never absorbs anything (every raced evaluation exhausting straight to the documented reason) would + /// pass a shape-only check, so exhaustions must stay a small minority of all evaluations. + /// + /// 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 the exhaustion bound (be sceptical of it). 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. If a loaded box ever does trip THIS 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. using var sut = new RoslynVirtualTagEvaluator( @@ -396,29 +455,31 @@ public sealed class RoslynVirtualTagEvaluatorTests 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 +492,28 @@ 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)}"); + // (1) The invariant: nothing but the documented retry-exhaustion outcome may surface. A raw + // ObjectDisposedException escaping the retry (pre-fix: "script threw: Cannot access a + // disposed object…") lands here, as does any other unexpected failure mode. + var leaked = failures.Where(reason => reason != RetryExhaustedReason).ToArray(); + leaked.ShouldBeEmpty( + $"a racing ClearCompiledScripts must never surface anything but \"{RetryExhaustedReason}\"; " + + $"observed: {string.Join(" | ", leaked)}"); + + // (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it. + // Loose by design (see the doc-comment) — a broken-retry detector, not a timing gate. The + // absolute floor keeps a starved run (few evaluations landed) from tripping on a single one. + var exhausted = failures.Count; + var totalEvaluations = Volatile.Read(ref evaluated); + exhausted.ShouldBeLessThan( + Math.Max(totalEvaluations / 10, 8), + $"the one-shot retry must absorb the overwhelming majority of raced clears; " + + $"{exhausted}/{totalEvaluations} evaluations exhausted it"); } /// Reads the count of the private compiled-script cache via reflection. The cache is a From 326ca33800cb05df43ad811f5913f02c6e0a64cf Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 07:49:54 -0400 Subject: [PATCH 13/17] docs(plan): record the T9 test rename in the live plan --- docs/plans/2026-08-17-perf-followups-r3.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/docs/plans/2026-08-17-perf-followups-r3.md b/docs/plans/2026-08-17-perf-followups-r3.md index 72fb449f..37db4a9c 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -424,7 +424,8 @@ because it exercises the real authoring path. **Files:** - Modify: `tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs` - (`Evaluate_racing_ClearCompiledScripts_never_fails_with_disposed`, ~:391) + (`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 From 3f04a4d4e5aa8a36915767238cca93d4cadac0ec Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 08:00:47 -0400 Subject: [PATCH 14/17] =?UTF-8?q?docs(docker-dev):=20first-POST-404=20caug?= =?UTF-8?q?ht=20=E2=80=94=20Traefik=20entrypoint-before-dynamic-config=20w?= =?UTF-8?q?indow=20+=20no-body=20POST=20binding=20verified?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Live gate on the local OrbStack docker-dev rig (branch tip images, fresh down -v + up -d --build). 404: did NOT reproduce through deploy.sh on a fresh boot — the readiness gate passed on its first poll, and compose's depends_on: service_healthy serialization means up -d returns ~30 s after Traefik starts, so the window is already closed. Reproduced it directly instead, by rapid-polling :9200 across a traefik container restart: connection-refused -> 404 for ~65-160 ms -> 200. Body is exactly Go's "404 page not found" (19 bytes) and the access log records it with an EMPTY RouterName/ServiceName at 0ms, so no router matched and no backend was dialled. Mechanism: the entrypoint binds before the dynamic file-provider config is loaded. The competing candidate (health- checked service with no healthy server) is excluded — that is a matched router answering 503, and there are zero 503s in the log. Caveat recorded: the earliest 404s predate the accesslog handler itself and are not logged, so an empty access log does not prove absence. No-body POST: verified, not 400. The minimal-API DeployRequest? binds both a missing body and a Content-Length: 0 body as null; the handler falls back to createdBy = "rest-api". A bare ./docker-dev/deploy.sh answered 202 Accepted and the Deployment row carried CreatedBy = rest-api. deploy.sh's header NOTE goes from "unverified" to the observed truth. --- docker-dev/README.md | 44 +++++++++++++++++++++++++++++++++++--------- docker-dev/deploy.sh | 27 ++++++++++++++++++++------- 2 files changed, 55 insertions(+), 16 deletions(-) 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 From 837d8a17eb034356632dae4056d675712f4e6de2 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 08:05:51 -0400 Subject: [PATCH 15/17] test(scripting): timeout under starvation is not a leak; share the exhaustion-reason constant Review follow-ups to 34829ea0. IMPORTANT - the leak filter had its own flake vector. This test saturates the thread pool by design, and TimedScriptEvaluator starts its 5s clock at WaitAsync rather than when the inner Task.Run gets a thread, so a legitimately-enqueued evaluation can blow the budget while still queued and surface "script timed out after 5.0s". The reason != exhaustion filter classified that as a raw disposed escape and hard-failed on it - handing the test back the load-fragility the reshape removed. Timeouts are now their own bucket, tolerated and rate-bounded exactly as exhaustions are; a raw disposed escape still fails on first occurrence. Doc-comment names this second residual vector alongside the exhaustion calibration. MINOR (scope extension authorised by review) - "evaluator disposed during evaluation" existed as three unshared literals. Promoted to ScriptEvalFailureReasons alongside VirtualTagEvalResult in Commons.Engines (the assembly all three already reference) and referenced from both evaluators and the test. The timeout prefix joins it, since the test now classifies on it too. String values are byte-identical - no behaviour change. Falsified: with a 12ms script budget the race produced real timeouts (3/2695). Classified as leaks (the pre-review filter) they hard-failed the test 6/6 items; bucketed as starvation they sit 0.11% under the 10% bound and the test is green. --- .../Engines/IVirtualTagEvaluator.cs | 30 ++++++++ .../CalculationEvaluator.cs | 5 +- .../Engines/RoslynVirtualTagEvaluator.cs | 5 +- .../RoslynVirtualTagEvaluatorTests.cs | 77 ++++++++++++------- 4 files changed, 86 insertions(+), 31 deletions(-) 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/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/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs index df2bf96c..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,12 +381,6 @@ public sealed class RoslynVirtualTagEvaluatorTests CompiledCacheCount(sut).ShouldBe(1); } - /// The one reason string the evaluator is documented to surface when its one-shot retry - /// is exhausted (a SECOND apply-boundary clear landing inside the same evaluation). Anything else - /// carrying "disposed" — notably the pre-fix generic escape "script threw: Cannot access a - /// disposed object…" — is a raw ObjectDisposedException leaking past the retry, i.e. the bug. - private const string RetryExhaustedReason = "evaluator disposed during evaluation"; - /// 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. @@ -417,12 +412,20 @@ public sealed class RoslynVirtualTagEvaluatorTests /// 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. Every failure this race produces must be the documented retry-exhaustion outcome - /// () and nothing else — a "script threw: Cannot access a disposed - /// object…" (the generic-catch escape) fails the test on the first occurrence, however loaded the box - /// is. A loose upper bound on the exhaustion RATE keeps the assertion non-vacuous: a build whose retry - /// never absorbs anything (every raced evaluation exhausting straight to the documented reason) would - /// pass a shape-only check, so exhaustions must stay a small minority of all evaluations. + /// 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. @@ -435,7 +438,7 @@ public sealed class RoslynVirtualTagEvaluatorTests /// 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 the exhaustion bound (be sceptical of it). The disposed-race did NOT + /// 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 @@ -444,12 +447,16 @@ public sealed class RoslynVirtualTagEvaluatorTests /// 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. If a loaded box ever does trip THIS bound, the - /// rate itself is the finding: record it before widening the number. + /// 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_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;"; @@ -497,23 +504,39 @@ public sealed class RoslynVirtualTagEvaluatorTests await Task.WhenAll(evalLoops.Append(clearLoop)) .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); - // (1) The invariant: nothing but the documented retry-exhaustion outcome may surface. A raw + 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. - var leaked = failures.Where(reason => reason != RetryExhaustedReason).ToArray(); + // 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 anything but \"{RetryExhaustedReason}\"; " + - $"observed: {string.Join(" | ", leaked)}"); + "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. - // Loose by design (see the doc-comment) — a broken-retry detector, not a timing gate. The - // absolute floor keeps a starved run (few evaluations landed) from tripping on a single one. - var exhausted = failures.Count; - var totalEvaluations = Volatile.Read(ref evaluated); exhausted.ShouldBeLessThan( - Math.Max(totalEvaluations / 10, 8), - $"the one-shot retry must absorb the overwhelming majority of raced clears; " + + 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 From c4d6cba7e1e357c9da94e2e9a30632ca2139c598 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 08:48:40 -0400 Subject: [PATCH 16/17] =?UTF-8?q?docs(plan):=20r3=20close-out=20=E2=80=94?= =?UTF-8?q?=20outcomes,=20sweep=20record,=20register=20annotations?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/plans/2026-08-17-perf-followups-r2.md | 20 ++ docs/plans/2026-08-17-perf-followups-r3.md | 363 +++++++++++++++++++++ 2 files changed, 383 insertions(+) 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 index 37db4a9c..9292f0da 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -508,3 +508,366 @@ ScadaBridge closed the same class with conditional registration + boot-time self 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. + +**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. From caf8830bbefee73ab01efea5ef4a7c1c9f6332b0 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 08:50:11 -0400 Subject: [PATCH 17/17] docs(plan): r3 ledger finalized + Client.CLI logger-flake register entry --- docs/plans/2026-08-17-perf-followups-r3.md | 10 +++++++++ ...2026-08-17-perf-followups-r3.md.tasks.json | 21 ++++++++++--------- 2 files changed, 21 insertions(+), 10 deletions(-) diff --git a/docs/plans/2026-08-17-perf-followups-r3.md b/docs/plans/2026-08-17-perf-followups-r3.md index 9292f0da..ece17990 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md +++ b/docs/plans/2026-08-17-perf-followups-r3.md @@ -856,6 +856,16 @@ round-2 register. **None of these blocks the branch.** 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 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 index f4c749d3..10258dd7 100644 --- a/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json +++ b/docs/plans/2026-08-17-perf-followups-r3.md.tasks.json @@ -1,16 +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": "pending"}, - {"id": 2, "subject": "Task 2: S7 read-pass health — worst-state-wins aggregation", "status": "pending"}, + {"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": "pending", "blockedBy": [1, 2, 3]}, - {"id": 5, "subject": "Task 5: Live gate — FetchAndCache legs", "status": "pending", "blockedBy": [4]}, - {"id": 6, "subject": "Task 6: Live gate — alarm-bearing surgical ratchet", "status": "pending", "blockedBy": [5]}, - {"id": 7, "subject": "Task 7: Live gate — ACL-enabled enforcement on site-a", "status": "pending", "blockedBy": [6]}, - {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "pending", "blockedBy": [1, 2, 3, 4, 5, 6, 7, 9, 10]}, - {"id": 9, "subject": "Task 9: Roslyn evaluator racing test — remove timing assumption (ScadaBridge row 38)", "status": "pending"}, - {"id": 10, "subject": "Task 10: LocalDb conditional registration + baseline + deregister self-heal (ScadaBridge row 39)", "status": "pending"} + {"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"} ], - "lastUpdated": "2026-08-17T19:05:00Z" + "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" }