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 89f6ddf0..f9556123 100644 --- a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md +++ b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md @@ -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. 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 90360d98..711652fe 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 @@ -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",