docs(plans): R3-05 live gate — S19 PASS (BadUserAccessDenied 0.09 s after ExpiresUtc, no deploy; 1 h negative control clean), S18 FAIL (paused SQL: keyed activation hung 42 s past the 2 s bound and stalled an open subscription 57 s; cooperative token not honoured by SqlClient)
This commit is contained in:
Joseph Doherty
@@ -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`.
|
||||
|
||||
@@ -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",
|
||||
|
||||
Reference in New Issue
Block a user