diff --git a/archreview/plans/R3-02-stale-good-family-plan.md b/archreview/plans/R3-02-stale-good-family-plan.md index 9eca0c0f..0247749b 100644 --- a/archreview/plans/R3-02-stale-good-family-plan.md +++ b/archreview/plans/R3-02-stale-good-family-plan.md @@ -873,10 +873,11 @@ this plan each appended last: ## Outstanding -- **T19 — the live gate (merge-blocking).** Not run: it needs the docker-dev rig plus the shared Modbus - fixture, and it is the only evidence that the identical-value recovery works end to end on a real - device. Recipe unchanged in §Live gate; the constant HR[5] vs auto-incrementing HR[100] pairing is what - makes it non-vacuous. +- **T19 — the live gate: RUN 2026-08-20, PASS** on the Modbus / calc / deadband / operator-restart legs + (see "Live gate result" below). The MQTT leg (step 12) was **not run** — it needs the + `docker-compose.mqtt.yml` overlay plus the authenticated Mosquitto fixture and was outside the gate + session's brief; T2–T5 stay covered by their driver-level tests. The VT leg was folded into the + Calculation leg (same seams, same contract; no VirtualTag was authored). --- @@ -908,3 +909,114 @@ says, i.e. the same class of bug this plan exists to close, one hop further out. **STATUS.md corrected:** the anonymous Runtime.Tests flake is `DriverHostActorNativeAlarmAckRoutingTests.RouteNativeAlarmAck_routes_to_driver_AcknowledgeAsync_with_principal` — untouched by this branch, known #500 profile, 3× green in isolation per the reviewer. + +## Live gate result (2026-08-20, T19) — **PASS** on docker-dev (Modbus const register + UNS mirror + Calculation; deadband + operator-restart legs) + +Rig: `docker-dev/docker-compose.yml` on OrbStack, image `otopcua-host:dev` = `97cb5cefb6d2` (master `b9b3cf9a`) on all six +containers (parity via `docker inspect --format '{{.Image}}'`), `DisableLogin=true`, ACL off (the S18 re-gate that ran first on +the same image had its override removed and its rows deleted before this gate). Deploys via `./docker-dev/deploy.sh`. Modbus +fixture `otopcua-pymodbus-standard` on `10.100.0.35:5020`, stopped/started over SSH. Client.CLI `subscribe -i 500`, one process +per node, anonymous, against central-1 (`opc.tcp://localhost:4840`). + +**Authoring (by SQL, then deployed `79262f19…`):** raw tags `MAIN-modbus-hr5` (`HR5`, holding register 5, UInt16) and +`MAIN-modbus-hr100` (`HR100`, the auto-increment register — re-added; the seed had only `HR200`); UNS `a` / `l` / equipment `e1` +(`EQ-32296cc68964` — the deploy gate enforces `[a-z0-9-]{1,32}` segment names and the `EQ-<12 hex of uuid>` id derivation, so the +plan's `A`/`L`/`E1` literals are unauthorable) with `UnsTagReference` → `HR5`; driver `Calc` (`Calculation`) / device `eng` / tag +`HR5x2` bound to script `return Convert.ToInt32(ctx.GetTag("pymodbus/plc/HR5").Value) * 2;`. Nodes: `ns=2;s=pymodbus/plc/HR5`, +`ns=3;s=a/l/e1/HR5`, `ns=2;s=Calc/eng/HR5x2`, `ns=2;s=pymodbus/plc/HR100`. + +**Recipe correction — the first cycle was vacuous, and the fixture itself said so.** `HR5` read **`1005`** before the first +outage (someone had written register 5 since the fixture was last restarted — `[0,31]` is a writable block), and +`docker stop`/`start` re-seeds the simulator from `standard.json`, so the value came back as **`5`**. A Good re-publish after a +value change proves nothing (the exact trap the plan's HR[5]/HR[100] pairing exists to avoid). The cycle was re-run with `5` +on both sides; that second cycle is the evidence below. **Check the register reads its seed value before stopping the +fixture** — a restart silently resets every written register. + +### Cycle 2 — identical-value recovery (non-vacuous): PASS + +| node | before | Modbus per-tag degrade | watchdog re-stamp | recovery | +|---|---|---|---|---| +| `ns=2;s=pymodbus/plc/HR5` (raw) | `5 Good` (one notification, 18:17:48.635 — static, confirmed by silence) | `(0x80050000)` @ 18:20:49.268 | `(0x80310000)` @ 18:21:08.596 | **`5 Good` @ 18:21:48.617** | +| `ns=3;s=a/l/e1/HR5` (UNS mirror) | `5 Good` same timestamp | `0x80050000` @ 18:20:49.268 (same ms) | `0x80310000` @ 18:21:08.596 | **`5 Good` @ 18:21:48.617** (same ms as raw) | +| `ns=2;s=Calc/eng/HR5x2` | `10 Good` | `0x80050000` @ 18:20:49.268 | `0x80310000` @ 18:21:08.596 | **`10 Good` @ 18:21:48.617** | +| `ns=2;s=pymodbus/plc/HR100` (positive control) | counting 1/s | `0x80050000` @ 18:20:49.268 | `0x80310000` @ 18:21:08.596 | `1 Good` @ 18:21:48.617, then counting | + +Fixture stopped 18:19:27, started 18:21:35. The plant value of HR5 was `5` before, during (re-seeded) and after — the +`5 Good` at 18:21:48 can only be the force re-publish. Raw and UNS fan in the same millisecond at every transition (one publish, +one fan-out). central-1: + +``` +[18:21:08 WRN] DriverInstance MAIN-modbus: no successful read for 00:01:43… while reporting Degraded (Transport not connected) — declaring comms lost and reconnecting +[18:21:08 WRN] DriverInstance MAIN-modbus: disconnect observed (no successful read for 104s while reporting Degraded); reconnecting +[18:21:08 INF] DriverHost central-1:4053: driver MAIN-modbus disconnected — 4 value node(s) marked BadNoCommunication (value retained) +[18:21:28 WRN] Driver resilience circuit-breaker OPENED: instance=MAIN-modbus … capability=Initialize breakDuration=00:00:15: Connection refused +[18:21:48 INF] Driver resilience circuit-breaker closed (recovered) … / DriverInstance MAIN-modbus: reconnected / subscribed to 3 refs (poll-sub-3) +``` + +(the first cycle — 18:15:26 → 18:17:48 — produced the identical sequence with `1005 → 5`, and is recorded only as the vacuous +control). Four nodes = HR5, HR100, HR200 and the UNS mirror — the calc node is not the Modbus driver's and follows through its +input instead, which is the STAB-19 leg: `HR5x2` carried the input's sub-code at both transitions (`0x80050000` then +`0x80310000`) and came back `10 Good` with the input. + +**`comms_latched_refs`: 0.** `otopcua_driver_comms_latched_refs` is absent from `/metrics` after every cycle (a counter that has +never been added is not exported; `apikey_store_bounded` on the same endpoint proves the exporter works), and +`grep -ci "still BadNoCommunication\|latched"` on central-1 over the whole session = **0**. + +### Timing notes (observations, not failures) + +- **Modbus's own per-tag degrade took ~82 s, not the plan's "1–2 s".** Fixture stopped ≈18:19:27 (the `docker stop` itself + took 11 s of SIGTERM grace), first `0x80050000` at 18:20:49. The stopped container's published port is simply gone, so the + driver's existing TCP socket sees no RST — each poll rides out `TimeoutMs=2000` plus the probe cadence before the transport is + declared not connected. Pre-existing Modbus behaviour, outside this plan's seams; the watchdog's 90 s `LastSuccessfulRead` + freeze then lands ≈20 s after that. Worth knowing when reading a timeline: "Bad within ~90 s" held (82 s), the + `BadNoCommunication` re-stamp landed at 101–104 s. +- Recovery was 11–13 s after `docker start` (breaker `Initialize` half-open 15 s after a refused connect that pre-dated the + fixture coming up), inside the plan's ~15 s. + +### "Last value retained" is server-side state and NOT observable over the wire — worth knowing before the next gate + +Every Bad notification above prints an **empty** value, calc included, although `CalculationDriver.MarkInputsBad` carries +`st.LastValue` and the node-manager test `OtOpcUaNodeManagerWriteStatusesTests` asserts the SDK variable keeps it. The reason +is the OPC Foundation stack, not this code: `NodeState.ReadAttribute` (UA-.NETStandard `1.5.377.21`, +`Stack/Opc.Ua.Core/Stack/State/NodeState.cs:3376-3378`) does +`if (StatusCode.IsBad(value.StatusCode)) value.WrappedValue = Variant.Null;` on every read and every monitored-item sample. So +a client can never see a value alongside a Bad status from this server; the retention is what lets the *next Good* re-publish +carry the same value and what the `(value, status)`-keyed dedup compares against. The plan's step-7 assertion "the last value +is retained on the calc/VT nodes" is therefore checked by the unit tests, not by a subscription; the wire-visible contract is +the status sub-code and the identical-value Good after recovery, both of which passed. A CLI `read` of a Bad node throws +client-side (`NodeCache.FetchValueAsync`), so that path cannot show it either. + +### Step 10 — deadband falsification leg: PASS (recovered; audit Warning correctly absent) + +`HR5` TagConfig given `"deadband": 1000`, deployed `b9863c2b…` at 18:25:32 (a driver-restarting apply: the T11 PostStop mark +`4 value node(s) marked BadNoCommunication (value retained)` and `subscribed to 3 refs (poll-sub-2)` landed in the same second; +no Bad reached the 500 ms subscriptions). Fixture stopped 18:26:21, started 18:28:28. `HR5` raw + UNS: `5 Good` → +`0x80050000` @ 18:27:42.989 → `0x80310000` @ 18:28:02.501 → **`5 Good` @ 18:28:42.518**; `HR5x2` `10 → Bad → Bad → 10 Good` +at the same instants. The driver-side deadband cache did not survive the reconnect (`TeardownAsync` clears it), so the Good +re-publish arrived with no audit Warning and the counter stayed absent — the "recovers" outcome, which is the passing one. +Deadband removed and redeployed (`e0a466c1…`) at restore. + +### Step 11 — operator Restart leg: PASS + +`/hosts → pymodbus (MAIN-modbus) → Controls → Restart → Confirm restart` at 18:30:42. central-1: +`restarting driver MAIN-modbus by request of multi-role-test` → `driver MAIN-modbus disconnected — 4 value node(s) marked +BadNoCommunication (value retained)` → `DriverInstance MAIN-modbus: connected` → `subscribed to 3 refs (poll-sub-1)`, all in +18:30:42. Subscriptions: `HR5` raw `5 Good @ 18:30:42.375` and `HR5x2` `10 Good @ 18:30:42.375` — **a fresh Good notification +with an unchanged value** on a static register, i.e. the re-subscribe initial push plus the status-keyed calc re-publish; +`HR100` resumed counting (`283, 285, 287 …`). As in R3-03's gate, **no Bad flash was visible at 500 ms sampling** — the mark and +the reconnect fall inside one second and the SDK's queue coalesces them; the server-side mark is in the log. + +### Not run + +- **Step 12 (MQTT retained replay + rebuild-shows-cached-value):** needs the `docker-compose.mqtt.yml` overlay and the + authenticated Mosquitto fixture; outside this session's brief. T2–T5 remain covered by `Driver.Mqtt.Tests` (initial push, + `ConnectionLost` stale, Sparkplug variants) and the driver-level recovery test from T5. +- **VirtualTag (`VT5`):** not authored; the Calculation tag exercises the same `InputQuality.WorstOf` / hold-on-Bad / + status-keyed-dedup contract through `DependencyConsumerMuxAdapter`, and `VirtualTagActor` has the T16 unit pair. + +### Restore + +Deadband removed, final deploy `e0a466c1…` Sealed; `HR5` reads `5 Good`. The gate's rows (`HR5`, `HR100`, UNS `a/l/e1` + +mirror, `Calc`/`eng`/`HR5x2` + script) are **kept** — like R3-03's `HR100`, they are the only static-vs-changing pair and the only +calc on the rig, and the next quality gate will want them. Modbus fixture running (`Up` on `10.100.0.35`); rig UP on +`97cb5cefb6d2` ×6 with no overrides. diff --git a/archreview/plans/R3-02-stale-good-family-plan.md.tasks.json b/archreview/plans/R3-02-stale-good-family-plan.md.tasks.json index 60e9a6c5..d5857b4d 100644 --- a/archreview/plans/R3-02-stale-good-family-plan.md.tasks.json +++ b/archreview/plans/R3-02-stale-good-family-plan.md.tasks.json @@ -10,7 +10,7 @@ }, { "id": "T2", - "subject": "MQTT plain-mode initial push of cached snapshots on SubscribeAsync — push-model forceRaise (05/STAB-18 shape b)", + "subject": "MQTT plain-mode initial push of cached snapshots on SubscribeAsync \u2014 push-model forceRaise (05/STAB-18 shape b)", "status": "done", "blockedBy": [] }, @@ -54,7 +54,7 @@ }, { "id": "T8", - "subject": "DriverHostActor.FanCommsLossToValueNodes: one BadNoCommunication status batch over raw + UNS nodes on ConnectivityChanged(false); nothing on reconnect (new method — R3-03 boundary)", + "subject": "DriverHostActor.FanCommsLossToValueNodes: one BadNoCommunication status batch over raw + UNS nodes on ConnectivityChanged(false); nothing on reconnect (new method \u2014 R3-03 boundary)", "status": "done", "blockedBy": [ "T7" @@ -144,10 +144,11 @@ { "id": "T19", "subject": "LIVE GATE: docker-dev comms-loss -> identical-value recovery (Modbus constant HR[5] raw+UNS, calc, VT, deadband falsification leg, restart leg, MQTT retained replay)", - "status": "pending", + "status": "done", "blockedBy": [ "T18" - ] + ], + "note": "RUN 2026-08-20 on docker-dev at 97cb5cefb6d2 (master b9b3cf9a): PASS. Non-vacuous leg \u2014 HR5 = 5 before and after a 2-min fixture stop, re-published 5 Good on raw AND UNS (same ms) with no value change; calc HR5x2 10\u21920x80050000\u21920x80310000\u219210 Good; HR100 positive control; comms_latched_refs 0, no audit Warning; deadband-1000 leg recovered; operator Restart leg re-published unchanged values with no visible Bad flash at 500 ms. First cycle was vacuous (1005\u21925: the fixture re-seeds registers on restart) and was re-run. 'Value retained' is unobservable over the wire \u2014 the SDK's NodeState.ReadAttribute nulls the value on any Bad status. NOT run: step 12 MQTT leg (needs the mqtt overlay + fixture); VT folded into the calc leg." } ] }