diff --git a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md index 12d4c14b..d917512f 100644 --- a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md +++ b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md @@ -817,3 +817,96 @@ OpcUaServer.Tests rerun green. **Verification after the fixes:** solution build 0 errors · Host.Tests **134 passed / 0 failed** (was 132) · OpcUaServer.Tests **493 passed / 1 skipped**. T11 remains `pending` for the orchestrator. + +--- + +## Live gate result (2026-08-20) — **S19 PASS, S18 FAIL** on docker-dev + +Rig: `docker-dev/docker-compose.yml` on OrbStack (Mac), image `otopcua-host:dev` = `b344565cad3d` (master +`e280db37`) on all six containers (parity asserted via `docker inspect --format '{{.Image}}'`), AdminUI on +`Security__Auth__DisableLogin=true`. Deploys via `./docker-dev/deploy.sh` (`POST /api/deployments`, `X-Api-Key`). +Subscriptions via Client.CLI against `opc.tcp://localhost:4840` (central-1, fused admin+driver — the only node +kind that carries `BoundedApiKeyStore`). The node under test was the Modbus fixture's auto-increment register, +raw tag `MAIN-modbus-hr100` → `ns=2;s=pymodbus/plc/HR100` (added for R3-03's gate; it changes every second, so +"still streaming" is observable). + +**Recipe correction — the plan's step 1 does not do what it says.** `OTOPCUA_ACL_ENABLED` in +`docker-dev/docker-compose.yml` is wired only to **site-a-1 / site-a-2** (`:605`, `:722`), not to the centrals — +`OTOPCUA_ACL_ENABLED=true docker compose up -d central-1 central-2` is a no-op ("Running", no recreate, no env). +The gate used a scratch compose override (`services.central-1/central-2.environment.Security__Acl__Enabled: "true"`) +passed as a second `-f`, verified in-container (`Security__Acl__Enabled=true` ×2), and dropped at restore. Worth +fixing in the compose (or the plan) before the next ACL gate. + +### Setup (steps 2-4) + +- `/apikeys`: minted name/principal `expiry-probe`, key id **`c81b4e50705281a1`** (secret captured from the one-time + banner, not recorded here). +- Grant by SQL (the scope picker flow is stage-7-gated and not what this gate tests): + `NodeAcl('acl-expiry-probe-hr100', 'MAIN', 'expiry-probe', ScopeKind='Tag', ScopeId='MAIN-modbus-hr100', PermissionFlags=7)` + = `Browse|Read|Subscribe` on that one tag. +- Enforcement confirmed live before anything else: an **anonymous** `read` of `HR100` → `ServiceResultException + [801F0000]` (`BadUserAccessDenied`) with `AclGate: Read withheld 1 of 1 node(s) for principal anonymous` on + central-1 (×3 probes); a **keyed** read/subscribe → values. Both `AclRevalidationTimer: live monitored items will be + re-authorized every 00:01:00` lines present (default interval, deliberately not shortened). + +### Step 7 first — negative control (1 h expiry): **PASS** + +`ExpiresUtc = 18:03:25Z` set by SQL, deployed (`6df8f967…`; central-1 `data-plane authority generation 2 installed +(… keys=1, grants=1, resolvedScopes=1)` at 17:03:26). Keyed subscription from `17:03:45Z` to `17:09:02Z` (5 min 17 s): +**279 Good notifications, 0 non-Good**, and zero `RevalidateSubscriptions withheld` lines on either central across the +window. (The stream has one 57 s gap inside it — caused by the S18 leg below, not by the timer.) + +### Steps 5-6 — the timer leg (3 min expiry, no deploy in between): **PASS** + +- `UPDATE ApiKey SET ExpiresUtc = DATEADD(minute, 3, GETUTCDATE())` → **`ExpiresUtc = 17:12:20.987Z`** + (`GETUTCDATE()` read back `17:09:20.990Z`). Deployed `f35664e5…` at 17:09:21; central-1 + `data-plane authority generation 3 installed (… keys=1, grants=1 …)` at `17:09:21`. **No later deployment exists** + (`SELECT TOP 1 CreatedAtUtc FROM Deployment` = `17:09:21.072` at the end of the leg). +- New keyed subscription from `17:09:26Z`: Good values at 1/s (`40623 → 40970`). +- **Last Good: `40970 @ 17:12:20.1518Z`. Next and final notification: `ns=2;s=pymodbus/plc/HR100 = (0x801F0000)` + @ `17:12:21.0729Z`** = `BadUserAccessDenied`, **0.09 s after `ExpiresUtc`**, then nothing further (checked at + 17:13:37). central-1: `[17:12:21 INF] AclGate: RevalidateSubscriptions withheld 2 of 2 node(s) for principal (none)` + (the second item is the still-open session from the negative control, whose CLI process had been killed but whose + OPC UA session had not yet timed out). The timer tick (armed 17:02:21, 60 s period → 17:12:21) happened to fall + within a second of the expiry; the bound being proven is "≤ one `RevalidationIntervalSeconds`", and the + observation is inside it. + +### Step 8 — S18 bounded store: **cache-hit half PASS, pause half FAIL** + +- **Cache-hit counter (PASS):** after one keyed subscribe activation and three keyed `read` connects within ~2 s, + central-1's `/metrics` (port 9000 in-container) read + `otopcua_opcua_apikey_store_bounded_total{outcome="cache_hit"} 2` — first read a miss (the subscribe activation was + > `StoreCacheSeconds`=5 earlier), reads 2 and 3 hits. The decorator is wired and the TTL is on. The instrument is + exported via the Host's Prometheus endpoint; `http://localhost:9200/metrics` round-robins through Traefik so it + must be read on the specific central. +- **Paused-SQL activation (FAIL — both sub-assertions):** with the negative-control subscription streaming, + `docker pause otopcua-dev-sql-1` at `17:04:49`, then (3 s later, past the 5 s TTL) a keyed `read` connect. + - The connect did **not** deny in ~2 s: the CLI ran **42.9 s** and failed client-side with `[80860000]` + (`BadRequestTimeout`). The server's denial line + `[17:05:35 WRN] ApiKeyStore: the key store did not answer within 2000 ms — denying this activation …` + was logged at **17:05:35 — the instant the container was unpaused**, not at 17:04:55. The stack under it is + `ConfigDbApiKeyStore.FindAsync` → `BoundedApiKeyStore.BoundAsync` line 226 (`return await call(cts.Token)`), and + a neighbouring `Failed executing DbCommand (35,009ms)` shows SqlClient sat on the black-holed socket until its own + internal timeout. **`StoreTimeoutMs` is a cooperative deadline — it is observed only when the inner call chooses + to observe the token, and `Microsoft.Data.SqlClient` does not while a stalled connection/login is in flight.** + `outcome="timeout"` did increment to 1, but 40 s late. + - **The already-open subscription on the same node stalled behind it:** `HR100` notifications stop at + `17:04:54.107Z` and resume at `17:05:49.105Z` (**57 s**, i.e. for the whole time the activation was wedged plus + ~14 s of SqlClient recovery). This is precisely the `SessionManager`-lock serialization S18 describes. + - **Falsification control (run immediately after, required to attribute the stall):** `docker pause` the SQL + container again for 40 s (`17:06:21 → 17:07:01`) with **no** new activation ⇒ the same subscription streamed + through it **without a single missed second** (`17:06:00 … 17:07:21`, 1/s throughout). So the stall is not "SQL + paused hurts the data plane" in general — it is the activation's store lookup holding the lock past its + advertised bound. +- Consequence: on a fused/admin node, a ConfigDb that goes unresponsive (as opposed to refusing connections) still + wedges every session activation and every open session's publish for tens of seconds per attempt. The bound needs + to be a hard race (`Task.WhenAny` against the deadline, abandoning the in-flight SqlClient call and letting it die + on its own), or the lookup must be moved off the lock — the T3 TTL cache helps only for keys seen in the last 5 s. + **Filed as a follow-up under the S18 slice; not fixed in this gate.** + +### Restore + +Gate rows deleted (`NodeAcl` row, the `expiry-probe` key, nothing else had been added for this gate), centrals +recreated **without** the override (`Security__Acl__Enabled` absent from both env lists, i.e. default `false`), +parity `b344565cad3d` ×6 re-asserted, readiness back, final deploy `1c666be3…` Sealed, anonymous read of `HR100` +answers a value again. Rig left UP on the master image with `DisableLogin=true`. diff --git a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json index 82045b5b..90360d98 100644 --- a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json +++ b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json @@ -85,11 +85,12 @@ { "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": "pending", + "status": "failed", "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)\"." }, { "id": "T12",