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

docs(plans): R3-05 S18 re-gate — PASS on docker-dev at 97cb5cefb6d2 (master b9b3cf9a): with SQL paused a keyed activation is denied in 2.42 s, the 2000 ms Warning lands at the deadline not at unpause, the open subscription's max gap is 1.00 s (was 57 s), timeout counter 1, no-activation control clean; T11 done

Browse Source
This commit is contained in:
Joseph Doherty
2026-08-20 14:32:30 -04:00
parent b9b3cf9a58
commit 1234d869c0
2 changed files with 53 additions and 10 deletions
Download Patch File Download Diff File Expand all files Collapse all files
archreview/plans/R3-05-acl-hot-path-expiry-plan.md
+50 -7
View File
@@ -988,13 +988,56 @@ control.
Re-run **step 8's paused-SQL leg only** (setup steps 2-4 unchanged, and step 1 now needs no scratch
override). Expected, versus what the gate saw:
| Observation | Gate (defective) | Expected now |
|---|---|---|
| Keyed `read` connect with SQL paused | 42.9 s, client `BadRequestTimeout` | denies in ≈ `StoreTimeoutMs` (2 s) |
| *"did not answer within 2000 ms"* Warning | at unpause, ~40 s late | at the deadline, while SQL is still paused |
| Already-open subscription on the same node | 57 s gap | no gap beyond the ~2 s of the activation |
| `apikey_store_bounded{outcome="timeout"}` | 1, ~40 s late | 1, promptly |
| Falsification control (pause with **no** activation) | streamed clean | must still stream clean |
| Observation | Gate (defective) | Expected now | **Re-gate (2026-08-20, image `97cb5cefb6d2` = master `b9b3cf9a`)** |
|---|---|---|---|
| Keyed `read` connect with SQL paused | 42.9 s, client `BadRequestTimeout` | denies in ≈ `StoreTimeoutMs` (2 s) | **2.42 s wall clock**, client `ServiceResultException [80210000]` (`BadIdentityTokenRejected`) — **PASS** |
| *"did not answer within 2000 ms"* Warning | at unpause, ~40 s late | at the deadline, while SQL is still paused | `[18:11:54 WRN]` — connect started 18:11:52.1, SQL unpaused 18:11:59.7 — **PASS** |
| Already-open subscription on the same node | 57 s gap | no gap beyond the ~2 s of the activation | **max inter-notification gap 1.00 s** across the whole 18:11:33 → 18:13:xx window (98 Good notifications, 1/s; no gap > 1.6 s) — **PASS** |
| `apikey_store_bounded{outcome="timeout"}` | 1, ~40 s late | 1, promptly | `outcome="timeout"} 1` (+ `cache_hit` 5) read at 18:13:12 — **PASS** |
| Falsification control (pause with **no** activation) | streamed clean | must still stream clean | 40 s pause `18:12:19 → 18:12:59`, same subscription streamed 1/s throughout — **PASS** |
⚠️ The Debug abandonment line is not visible at the rig's default log level — it is not part of the gate's
pass criteria; the Warning and the restored subscription are.
## Live gate result (2026-08-20, S18 re-gate) — **PASS**; T11 now fully green
Rig rebuilt from master `b9b3cf9a` (contains `f665e8b8`, the hard-deadline fix, and the compose `OTOPCUA_ACL_ENABLED`
wiring for the centrals): `otopcua-host:dev` = `97cb5cefb6d2`, parity asserted ×6 via `docker inspect --format '{{.Image}}'`.
`OTOPCUA_ACL_ENABLED=true docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2` now **does** what the plan's
step 1 says — `Security__Acl__Enabled=true` read back in both containers, no scratch override needed — and enforcement was live
before the leg ran (anonymous `browse` → `[801F0000]`).
Setup: key `s18-regate` (id `a1b2c3d4e5f60718`, secret hashed with the rig's committed pepper and inserted by SQL) +
`NodeAcl('acl-s18-cluster','MAIN','s18-regate',ScopeKind='Cluster',ScopeId=NULL,PermissionFlags=7)`, deployed (`3cb5415c…`,
Sealed). Subscription under test: `ns=2;s=pymodbus/plc/HR100` (the fixture's auto-increment register) at `-i 500`, keyed, on
central-1 (`opc.tcp://localhost:4840`) — the only node kind that carries `BoundedApiKeyStore`.
Timeline (UTC):
- `18:11:45.1` `docker pause otopcua-dev-sql-1` (the rig's SQL is local on OrbStack — not the shared host).
- `18:11:52.1` new keyed `read` connect (7 s after the pause, past the 5 s `StoreCacheSeconds` TTL, so a guaranteed miss).
- `18:11:54.5` client returns `ServiceResultException [80210000]` — **2.42 s** end to end (the 2000 ms bound plus the
OPC UA handshake). central-1 at the same second:
`[18:11:54 WRN] ApiKeyStore: the key store did not answer within 2000 ms — denying this activation. The lookup is abandoned and
its result, if it ever arrives, is discarded. …` followed by `[18:11:54 ERR] ApiKeyAuth: key store threw for key id a1b2c3d4e5f60718
System.OperationCanceledException: The API key store did not answer within 2000 ms; the lookup was abandoned.` (stack through
`BoundedApiKeyStore.BoundAsync` line 278 → `FindAsync` line 120) and `UserName auth denied for apikey: Invalid API key.` — the
standard opaque denial, fail-closed.
- `18:11:59.7` `docker unpause`. The open subscription's notifications: `… 18:11:52.7, 18:11:53.7, 18:11:54.7, 18:11:55.7 …` —
**no missed second** through the activation, the pause, or the unpause (first gate: a 57 s hole starting at the activation).
- After unpause: **zero** `Unobserved` lines on central-1. The abandoned SqlClient call surfaced only as the expected ConfigDb
health-check noise (`Health check configdb … 'Database connection failed.'`, `Connection Timeout Expired … pre-login handshake`)
and a `batch is aborted` inner exception attached to the *already-logged* activation error — nothing new, nothing unobserved. The
Debug abandonment line is below the rig's log level, as the follow-up note predicted.
- `18:12:19 → 18:12:59` falsification control: SQL paused 40 s with **no** activation; the subscription streamed 1/s throughout
(max gap over the whole session 1.00 s) — so a paused SQL still does not hurt the data plane by itself, and the first gate's 57 s
stall is attributable to the activation alone, now bounded.
- `18:13:12` `http://central-1:9000/metrics`: `otopcua_opcua_apikey_store_bounded_total{outcome="timeout"} 1`,
`{outcome="cache_hit"} 5`.
Restore: `NodeAcl` row + `ApiKey` row deleted, centrals recreated **without** the override (`Security__Acl__Enabled=false` ×2,
image `97cb5cefb6d2` ×2 re-asserted), deploy `2a97271f…` Sealed, anonymous reads answer values again. Rig left UP on the master
image; the R3-02 gate's rows (HR5/HR100 raw tags, UNS `a/l/e1` + mirror, `Calc` driver) are unrelated to this gate and are
described in that plan.
**T11 → `done`.** S19 (timer expiry) passed in the first gate; S18 (bounded store) passes now.
archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json
+3 -3
View File
@@ -84,13 +84,13 @@
},
{
"id": "T11",
"subject": "LIVE GATE: docker-dev with OTOPCUA_ACL_ENABLED=true — subscription goes BadUserAccessDenied within one interval of ExpiresUtc with no deploy (+ long-expiry negative control, + bounded-store leg)",
"status": "failed",
"subject": "LIVE GATE: docker-dev with OTOPCUA_ACL_ENABLED=true \u2014 subscription goes BadUserAccessDenied within one interval of ExpiresUtc with no deploy (+ long-expiry negative control, + bounded-store leg)",
"status": "done",
"blockedBy": [
"T5",
"T9"
],
"note": "S19 expiry leg PASS (BadUserAccessDenied 0.09 s after ExpiresUtc, no deploy; negative control clean). S18 bounded-store leg FAIL: cache_hit meter non-zero, but with the SQL container paused a keyed activation hung 42 s (StoreTimeoutMs=2000 is a cooperative token SqlClient does not honour on a stalled socket) and the already-open subscription on the same node stalled 57 s behind it — the exact S18 lock. See plan \"Live gate result (2026-08-20)\"."
"note": "S19 expiry leg PASS in the first gate (BadUserAccessDenied 0.09 s after ExpiresUtc, no deploy; negative control clean). S18 bounded-store leg FAILED in the first gate (42.9 s hang, 57 s subscription stall \u2014 cooperative token) and PASSED on the 2026-08-20 re-gate after f665e8b8: keyed connect denied in 2.42 s with SQL paused, Warning logged at the deadline (5 s before unpause), open subscription max gap 1.00 s, timeout counter 1, no-activation control clean, no unobserved exception after unpause. See plan 'Live gate result (2026-08-20, S18 re-gate)'."
},
{
"id": "T12",