dohertj2/lmxopcua
1
0
Fork 0
Code Issues 38 Pull Requests Actions Packages Projects Releases Wiki Activity

docs(reviews): record docker-dev Wave-4 gates A/B/C/E (lmxopcua#761)

Browse Source 
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
This commit is contained in:
Joseph Doherty
2026-11-09 21:09:02 -05:00
parent 1b9c36f38d
commit 7cbeb9a7cc
1 changed files with 214 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
docs/reviews/2026-10-21/gates.md
+214
View File
@@ -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.