From 7cbeb9a7cc05f6d8c17cd568e7e3b5af38290777 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 21:09:02 -0500 Subject: [PATCH] docs(reviews): record docker-dev Wave-4 gates A/B/C/E (lmxopcua#761) Gates A (#731), B (#732), C (#733) and E (#734) run on the local docker-dev rig against origin/master 1b9c36f3 on 2026-11-09: all four PASS. Records the procedure, the measured thread/fd/RSS, subscription and deploy-status numbers per gate, plus six non-blocking observations. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- docs/reviews/2026-10-21/gates.md | 214 +++++++++++++++++++++++++++++++ 1 file changed, 214 insertions(+) create mode 100644 docs/reviews/2026-10-21/gates.md diff --git a/docs/reviews/2026-10-21/gates.md b/docs/reviews/2026-10-21/gates.md new file mode 100644 index 000000000..d3cdd9115 --- /dev/null +++ b/docs/reviews/2026-10-21/gates.md @@ -0,0 +1,214 @@ +# 2026-10-21 review remediation — Wave-4 gate record + +Tracking issue: lmxopcua#761. This file records each gate run with its date, the commit tested, the procedure, +the measured numbers and the verdict. Gates not listed here have not been run. + +## docker-dev gates A, B, C, E — 2026-11-09 + +| | | +|---|---| +| Commit tested | `1b9c36f3` (`origin/master`, "docs(plans): OPC UA SDK 2.0 upgrade spike catalogue (lmxopcua#782)") | +| Rig | local `docker-dev/` (6 host nodes: MAIN `central-1/2`, SITE-A `site-a-1/2`, SITE-B `site-b-1/2`), image `otopcua-host:dev` `sha256:24f9d7287ed2` built from that commit, migrator re-run (no pending migrations) | +| Clock | Times below are rig UTC (2026-11-10 01:37–02:07 UTC = 2026-11-09 evening US Eastern) | +| Config | The existing ConfigDb: MAIN carries `MAIN-modbus` (pymodbus `10.100.0.35:5020`), `MAIN-opcua` (opc-plc `10.100.0.35:50000`), `MAIN-calc`, 48 `int3b-mb-*` Modbus drivers and one `int3b-blackhole` driver, 52 children in total. Equipment `EQ-32296cc68964` (`a/l/e1`) has the HR5 reference and the change-triggered virtual tag `okvt` (= HR100 + 1). | +| Tools | `POST /api/deployments` + `GET /api/deployments/{id}` (`X-Api-Key: docker-dev-deploy-key`), `Client.CLI` built from the same commit, `/proc/1/status` (Threads) and `/proc/1/fd` inside the containers. `dotnet-counters` is not in the runtime image, so it was not used. ConfigDb edits were made with `sqlcmd -I` (QUOTED_IDENTIFIER on). | + +**Summary: A PASS, B PASS, C PASS, E PASS.** None of the four gates failed. Observations are listed at the end. None of +them blocks a gate. + +### Gate A (#731) — a driver config change disposes the old instance; threads and handles stay flat — PASS + +**Procedure.** Each iteration edits both `MAIN-modbus.DriverConfig` (`TimeoutMs` 2000+i) and `MAIN-opcua.DriverConfig` +(`SessionName` `gateA-i`), deploys, waits for the deploy to seal plus 8 s, then samples PID 1 in `central-1` and +`central-2` (both run the MAIN drivers). That is 20 iterations, so 20 respawns of each driver on each node: 80 driver +disposals in total. Two warm-up respawns ran before the baseline. + +**Disposal evidence** (log lines in the 01:41:47–01:45:10 window): + +| node | `MAIN-modbus: disposed Modbus driver on stop` | `MAIN-opcua: disposed OpcUaClient driver on stop` | `spawned … MAIN-modbus` / `MAIN-opcua` | shutdown/dispose timeout or throw | +|---|---|---|---|---| +| central-1 | 20 | 20 | 20 / 20 | 0 | +| central-2 | 20 | 20 | 20 / 20 | 0 | + +**Counts** (threads / open fds / RSS KiB): + +| sample | central-1 | central-2 | +|---|---|---| +| baseline (01:41:47) | 46 / 714 / 490 748 | 46 / 717 / 516 600 | +| after respawn 5 | 50 / 725 / 506 576 | 51 / 725 / 529 472 | +| after respawn 10 | 50 / 725 / 507 084 | 48 / 726 / 532 972 | +| after respawn 15 | 48 / 726 / 497 648 | 48 / 724 / 525 440 | +| after respawn 20 (01:44:59) | 52 / 726 / 499 048 | 48 / 723 / 526 184 | +| settled, 75 s later (01:46:14) | 48 / 712 | 46 / 715 | + +Across the 20 respawns, threads moved between 47 and 55 with no upward trend; that range is normal thread-pool +movement. The fd count rose by about 11 on the first respawn, which is the new driver's sockets landing before the old +ones close. It then stayed flat at 723–726, and after settling it was lower than the baseline (712/715). RSS stayed +flat (±25 MB). + +After a respawn, the static Modbus values (HR5 and HR200, which do not change) read Good on both 4840 and 4841. The +dead child's `BadNoCommunication` fan, which lands after the new child's first push, was overwritten by the re-push. + +### Gate B (#732) — a subscription survives a surgical add; a re-created item after a rebuild receives data — PASS + +**Procedure.** Session 1 opens two `Client.CLI subscribe` processes (500 ms) on `opc.tcp://localhost:4840`, which +are held for 170 s: + +- the raw node `ns=2;s=pymodbus/plc/HR100` (ticks about 1 Hz) +- the UNS virtual tag `ns=3;s=EQ-32296cc68964/okvt` + +1. **Surgical add (01:47:42).** Insert the raw tag `HR101` on `MAIN-modbus-dev`, then deploy. The applier logged + `kind=PureAdd, added=1, removed=0, changed=0, rebuild=False` on both central nodes. +2. **Read the new node.** `ns=2;s=pymodbus/plc/HR101` exists and is served. Its status is `BadOutOfRange` because the + pymodbus fixture refuses address 101 with exception 0x02. The device answered, so this is the fixture's register + map and not a server fault. +3. **Rebuild (01:48:19).** Rename equipment `e1` to `e1r`, which is a `ChangedEquipment` delta, then deploy. The + applier logged `kind=Rebuild, … rebuild=True`. +4. **Re-create (01:48:35).** With session 1 still open and still holding its stale items, start session 2 with new + subscriptions on the same two NodeIds for 20 s. + +**Results.** + +| subscription | samples | non-Good samples | +|---|---|---| +| session 1, HR100 | 59 | `01:47:43.1426 BadNoCommunication` (one sample; Good `31505` 0.9 ms later, then 1 Hz Good through 01:48:19); `01:48:19.97 BadNodeIdUnknown`, then nothing (item dead, as B2a specifies) | +| session 1, okvt | 59 | same pattern: one `BadNoCommunication` sample at 01:47:43.1426, Good again at .1435; `BadNodeIdUnknown` at 01:48:19.97 | +| session 2, HR100 (after the rebuild) | 20 | 0. Values ran from 36580 at 01:48:34.99 to 38405 at 01:48:54.00 | +| session 2, okvt (after the rebuild) | 20 | 0. Values ran from 36581 to 38406 | + +- **Surgical add:** the subscription survived. The items were never invalidated and Good data continued at 1 Hz. The + single `BadNoCommunication` sample is not address-space churn. Adding a tag changes the driver's spawn spec, so + `MAIN-modbus` respawned (`stopped driver child` / `disposed` / `spawned` at 01:47:43). The dead child's + connectivity-lost fan then reached the item for under 1 ms before the new child's push (see observation 3). +- **Rebuild:** the old items received `BadNodeIdUnknown` and no further data. New items on the same NodeIds, created + while the stale items were still open in another session, received live data immediately. That is the B2a positive + control: before the fix, a stale `MonitoredNode2` captured the new item. + +The CLI cannot re-create an item inside the same session. The same-session case is covered by the +`OpcUaServer.IntegrationTests` test, not by this gate. + +### Gate C (#733) — kill a central mid-dispatch, the next deploy succeeds; port 4840 taken ⇒ `/health/ready` 503 — PASS + +To hold a deployment in flight long enough to kill a node, `site-b-1` was `docker pause`d before each deploy, so its +ack could not land. The dispatch is otherwise sub-second on this rig. Both centrals were killed in turn: +`central-1`, which the issue names, and `central-2`, which was hosting the `config-publish` / `admin-operations` +singletons at the time. Killing the singleton host is what exercises the C1 PreStart recovery. + +**C-a: `docker kill central-1` mid-dispatch.** Deployment `197e31b4` was `AwaitingApplyAcks` with 5 of 6 rows +Applied (site-b-1 Applying) when central-1 was killed at 01:51:42. + +- A second POST while it was in flight returned **409 AnotherDeploymentInFlight**, which is correct. +- After `site-b-1` was unpaused, the coordinator closed the deployment at the 2 min deadline (01:53:38) as + `TimedOut`. It logged `No ack from: site-b-1:4053`, because the gRPC dispatch to the paused node was lost. +- central-1 was restarted, and the **next deploy, `b27ede2a`, sealed with 6 of 6 Applied.** + +**C-b: `docker kill central-2` (singleton host) mid-dispatch.** Deployment `970e7770` was `AwaitingApplyAcks` +(5 of 6) when central-2 was killed at 01:54:03. + +- 01:54:30: central-1 auto-downed central-2. +- 01:54:46: the singletons started on central-1 and logged `Coordinator recovered in-flight deployment 970e7770… (5/6 acks landed)`. +- The AdminUI was unavailable through Traefik from about 01:54:05 to 01:54:35 during the hand-over. +- The recovered deployment closed `TimedOut` at its original deadline (01:56:00). +- central-2 was restarted, and the **next deploy, `cb0b8134`, sealed with 6 of 6 Applied.** Neither run left a + deployment wedged in flight. + +**C-port: port 4840 taken.** + +- **Fused admin+driver node.** central-2 was stopped. A replacement container was started from the same compose + service (`compose run --use-aliases`). A `perl` listener in it bound `0.0.0.0:4840` before + `dotnet OtOpcUa.Host.dll` started. Results: + - `GET /health/ready` returned **HTTP 503**, overall status `Unhealthy`, with + `opcua-endpoint: Unhealthy — "OPC UA SDK failed to start: Failed to establish tcp listener sockets for Ipv4 and + IPv6." (status Failed)`. `configdb` and `akka` were both Healthy. + - The node logged `OpcUaEndpointStepDown: … not the driver Primary — nothing to step down from`. +- **Driver-only node.** The same setup on `site-a-2` (driver-only): the host logged + `FTL OtOpcUa.Host terminated: Failed to establish tcp listener sockets…` and the **process exited with code 1** + (C3 "a driver-only node rethrows"). +- Both replacement containers were removed and the original containers restarted. The ServiceLevel half of C3 is + #762 and was not part of this gate. + +### Gate E (#734) — a `while(true)` virtual tag leaves the node responsive, the tag shows quarantined, threads stay flat over 2 min — PASS + +**Procedure.** + +- **Script:** `gateE-spin` with source `var v = ctx.GetTag("pymodbus/plc/HR100").Value; while (true) { }`. +- **Virtual tag:** `spinvt` on `EQ-32296cc68964`, Int32, change-triggered, so it fires about 1 Hz on HR100. +- **Healthy sibling:** `okvt`, on the same equipment and the same trigger. +- Deployed at 02:01:11. Before the deploy and every 6 s for about 3.5 min after it, the following were sampled: + - threads and CPU ticks of PID 1 on both centrals + - `/health/ready` latency + - `Client.CLI read` of `okvt` and `spinvt` on 4840 + +An earlier attempt used a timer-only trigger (`TimerIntervalMs=1000`, no dependency), and the script never ran; see +observation 4. + +**Quarantine.** + +- The first run started at about 02:01:16. The following triggers were refused, as designed: refusals do not count as + strikes. +- At 02:01:36, after 20.2 s, which is past `StuckOrphanQuarantineFactor` 10 × the 2 s budget, both centrals logged + this Error to `scripts-*.log`: `Script gateE-vt-spin quarantined: its previous evaluation has been running for + 20.2 s, over 10x its 2000 ms budget … not evaluated again until its source changes or it is redeployed`. +- `/metrics`: + - `otopcua_script_quarantined_total{reason="stuck",script="gateE-vt-spin"} 1` + - `otopcua_script_run_refused_total{script="gateE-vt-spin"} 21` + - Both stayed at 1 and 21 for the rest of the run, so evaluation stopped after the quarantine. +- OPC UA status of `ns=3;s=EQ-32296cc68964/spinvt`: `BadWaitingForInitialData` until the first run, then + `BadInternalError` (0x80020000) from 02:01:23 onward. + +**Responsiveness.** + +| metric | before the deploy | over the 3.5 min after | +|---|---|---| +| `/health/ready` | 200 in 3–20 ms | 200 in 3–11 ms | +| `Client.CLI read` (connect + read) | 0.34–0.46 s | 0.33–0.49 s | + +`okvt`, the healthy sibling, kept evaluating Good throughout (30656 → 41368). + +**Threads** (central-1 / central-2): + +| sample | central-1 | central-2 | +|---|---|---| +| before | 50–53 | 49–50 | +| 02:01:17 – 02:04:42 (3.5 min, sampled every 6–9 s) | 50–54 | 50–54 | + +There was no growth, and at most one thread was orphaned per node. + +**CPU.** The orphaned run cannot be pre-empted in-process. Both nodes went from about 0.1 core to about 1.04 cores +(about 104 ticks/s), and that continued after the virtual tag was deleted and redeployed (1022 ticks per 10 s at +02:05). Only a process restart cleared it, so both centrals were rolling-restarted after the gate. This is the +documented limitation: the out-of-process runner is #750. The gate criteria (responsive, quarantined, threads flat) +hold. + +### Observations (none blocks a gate) + +1. **The status API does not say why a deployment timed out.** In the normal timeout branch (some acks landed), + `GET /api/deployments/{id}` returns `status: TimedOut` with `failureReason: null`. Only the central log names the + silent node (`No ack from: site-b-1:4053`). The no-expected-rows branch does set a reason. An automation client + polling the API cannot see which node to fix. +2. **Rig: mesh PSK warnings on the centrals.** central logs `Mesh PSK secret ot-mesh-psk-{main,site-a,site-b} … is + absent (or blank) in the store; the key is REVOKED — commands to that cluster and acks from it are refused`. Yet + every gRPC dispatch and ack in these runs succeeded. Either the rig's PSK secrets are not seeded and enforcement is + off, or the warning is stale. Not investigated. +3. **A surgical raw-tag add respawns that driver.** The driver's spawn spec carries its tag set, so adding one tag + reconnects the whole driver (the accepted cost noted in `DriverSpawnPlanner`). On a live subscriber this shows as + one `BadNoCommunication` sample (< 1 ms) on every value of that driver, including UNS references and virtual tags + fed by it. ScadaBridge-style clients that alarm on a single Bad sample would see it on every tag add. +4. **A timer-only virtual tag never evaluates, and nothing flags it.** `VirtualTag.TimerIntervalMs` is not consumed + by the runtime: `VirtualTagActor` evaluates on dependency changes only, and no timer scheduler exists. A virtual + tag with `TimerIntervalMs=1000` and no `ctx.GetTag` dependency deployed cleanly and sat at + `BadWaitingForInitialData` indefinitely. The `CalculationNoEffectiveTrigger` DraftValidator rule (E4) covers + Calculation tags only, not virtual tags. +5. **The quarantine line in the main log has no script name.** The guard's Error is mirrored into the main log by + `ScriptLogCompanionSink` as `WRN [Script] unknown emitted Error: Script "gateE-vt-spin" quarantined: …`. The guard's + logger carries no `ScriptName`/`ScriptId` property, so the mirror labels it `unknown`, and it is rate-limited under + that shared key. `scripts-*.log` has the correct `[ERR]` line. +6. **The quarantine shows as `BadInternalError` on OPC UA.** A client sees no quarantine-specific status. The reason + is only in the logs and metrics. + +### Rig state left behind + +- All six nodes run `otopcua-host:dev` `sha256:24f9d7287ed2` (commit `1b9c36f3`). +- Every gate edit was reverted in the ConfigDb: `HR101` deleted; `e1` name restored; `gateE-spin`/`spinvt` deleted; + both driver configs restored. A clean-up deploy, `cd41a890`, sealed 6 of 6. +- Both centrals were restarted afterwards to clear the gate-E orphan thread.