docs(mesh): Phase 1B live gate record
Node→central ApplyAcks over gRPC, gated live on the docker-dev rig at4a2a3d3a. All 7 checks PASS (the 6 planned plus the mandated 4b hang drill). The 4b drill is the one that earns its place: with central-1 PAUSED rather than stopped, both site-a nodes burned a full AckTimeoutSeconds on it as DeadlineExceeded and still reached central-2 with a live deadline — the per-endpoint FRESH deadline from667639e6, proven on the failure shape a hoisted deadline could not survive. Observed failover latency ~10 s, exactly one AckTimeoutSeconds. It also produced the run's only duplicate ack, and that turned into evidence rather than a defect: the frozen central had in fact received both acks and replayed them on unpause, and the coordinator reported 2/6 acks landed, not 4/6 — the idempotent absorption the sender's at-least-once remark asserts, observed instead of argued. Coexistence is per pair in one deployment: site-a's rows are Applied with matching ReportApply lines on central and zero receptionist associations, site-b's are Applied with zero ReportApply lines and a live receptionist association. Neither pair could have used the other's transport. Carry-forwards recorded: the I-4 cold-PSK-cache latency is structurally unmeasurable on docker-dev (ClusterPsks is read ahead of the store, so InvalidateAll clears an empty cache) and moves to a store-backed rig; a restarted central's cached channel can stay in backoff ~2 min on the node that watched it die, absorbed by the walk with no ack lost. The 1A finding-5 wording fix gains a second confirmation — 4 of 4 admin boots lost the PreStart race, and every ack central-1 accepted proves the provider it said would NEVER be published was. Docs only; the rig flip and the four Serilog Debug overrides were reverted and are not in this diff. Rig restored to six healthy, all-ClusterClient, sealing 6/6. Claude-Session: https://claude.ai/code/session_014WNM4vjoVksyyBraTXSZE1
This commit is contained in:
@@ -649,20 +649,387 @@ if its cutover has to be reversed.
|
||||
|
||||
---
|
||||
|
||||
## Phase 1B — node→central ack plane — **PENDING**
|
||||
## Phase 1B — node→central ack plane — **PASS**
|
||||
|
||||
Branch `feat/grpc-central-ack` @ `________` (rebased on merged 1A). Rig-only flip:
|
||||
site-a-1/-2 → `Grpc`; site-b stays `ClusterClient`; central back on `ClusterClient` mode
|
||||
Branch `feat/grpc-central-ack` @ `4a2a3d3a` (rebased on `master`, which carries the merged 1A).
|
||||
Rig-only flip: site-a-1/-2 → `Grpc`; site-b stays `ClusterClient`; central stays `ClusterClient`
|
||||
(its command direction) — acks are governed by the **node's** mode, so this isolates 1B.
|
||||
|
||||
| # | Check | Result |
|
||||
|---|---|---|
|
||||
| 1 | Deploy e2e: site-a acks arrive via `ReportApply` (central `CentralCommandService` log lines carry site-a node ids), `NodeDeploymentState` rows land, deployment seals | PENDING |
|
||||
| 2 | Site-b acks still arrive via ClusterClient in the same deployment — per-pair coexistence proven | PENDING |
|
||||
| 3 | Exactly **one** ack row per site-a node per dispatch (no double-count from endpoint failover) | PENDING |
|
||||
| 4 | Kill central-1 before the apply completes: site-a acks fail over to central-2's endpoint; deployment still seals | PENDING |
|
||||
| 5 | Unauthenticated / wrong-cluster-key / missing `x-otopcua-cluster` probes against central `:4055` `CentralCommandService/ReportApply` ⇒ `PermissionDenied` (missing-header rejection is central-side by design) | PENDING |
|
||||
| 6 | ConfigServe (`DeploymentArtifactService`) on the same listener unaffected: fetches succeed, 0 auth failures | PENDING |
|
||||
| 1 | Deploy e2e: site-a acks arrive via `ReportApply`, `NodeDeploymentState` rows land, deployment seals | **PASS** — deployment `53BD2626…` `Status=2` (Sealed) with all six rows `Status=1` (Applied) inside ~50 ms; both site-a nodes logged `Posted the ApplyAck … to http://central-1:4055` and central-1 logged the matching `ApplyAck … from site-a-1:4053 / site-a-2:4053 … handed to the central communication actor`. **10/10 acks delivered across the whole run**, 0 drops on any node |
|
||||
| 2 | Site-b acks still arrive via ClusterClient in the SAME deployment — per-pair coexistence | **PASS** — in `53BD2626…` site-b-1/-2 rows are `Applied` while **0** `ReportApply` lines name a site-b node on either central node, and site-b-1/-2 each hold a live `Connected to [akka.tcp://otopcua@central-2:4053/system/receptionist]`; conversely site-a-1/-2 hold **0** receptionist associations and created **0** ClusterClients. Each pair's only possible ack route is the one its mode selects |
|
||||
| 3 | Exactly **one** ack row per site-a node per dispatch (no double-count from endpoint failover) | **PASS** — across 10 dispatches, `acks=1` for every (site-a node, deployment) pair on the happy path and on the `docker stop` failover. The **one** exception is the 4b pause drill (`458b8629…`, `acks=2` per node) and it is the documented at-least-once case, not a defect: the frozen server had in fact received the ack, and **the coordinator absorbed it without inflating the count — it reported `2/6 acks landed`, not `4/6`**. `NodeDeploymentState` holds exactly one row per node per deployment throughout |
|
||||
| 4 | Kill central-1 (`docker stop`) before the apply: site-a acks fail over to central-2; restart, verify convergence | **PASS** — with central-1 stopped, both site-a nodes logged the Information failover line `… to http://central-2:4055 after 1 endpoint(s) failed (http://central-1:4055 => Unavailable)` and central-2 accepted both **within the same second**; the deployment honestly ended `Status=4` (TimedOut) with central-1 alone at `Status=0` — sealing 6/6 is structurally impossible while one of the six expected nodes is down. After `start central-1` the pair reconverged (`members 2, unreachable 0`) and the next dispatch sealed **6/6** |
|
||||
| **4b** | **Hang drill** (`docker pause central-1`): the per-endpoint FRESH deadline is what lets central-2 be reached at all | **PASS** — with central-1 **paused** (hung, not refusing), both site-a nodes logged `… to http://central-2:4055 after 1 endpoint(s) failed (http://central-1:4055 => DeadlineExceeded)` and the ack landed on central-2. **Observed failover latency ≈ 10 s** (dispatch accepted 13:03:51 → ack at 13:04:01), i.e. exactly one `AckTimeoutSeconds`. A single hoisted deadline would have entered the central-2 attempt already expired and dropped the ack; this is the live proof of the fix in `667639e6` |
|
||||
| 5 | Auth probes against central `:4055` `CentralCommandService/ReportApply` | **PASS** — 7/7 as designed: no bearer ⇒ `PermissionDenied`; SITE-B's key claiming SITE-A ⇒ `PermissionDenied`; no `x-otopcua-cluster` ⇒ `PermissionDenied`; unknown cluster `SITE-Z` with a valid key ⇒ `PermissionDenied`; unauthenticated against central-**2** ⇒ `PermissionDenied`; correct key+header with a **fake** deployment id ⇒ `{}` (auth passed, coordinator ignored it — **0 rows written** for that id); malformed id ⇒ `InvalidArgument` (auth passed, payload refused). Positive control: SITE-B key + SITE-B header also reaches the decoder |
|
||||
| 6 | ConfigServe (`DeploymentArtifactService`) on the same listener unaffected | **PASS** — all four site nodes **Fetched + verified** a 28 296-byte artifact from `http://central-1:4055` on a real revision change, and a direct authenticated `Fetch` returned artifact bytes; unauthenticated `Fetch` is refused by its **own** interceptor (`Unauthenticated` / "Config-serve authentication failed."), never by the mesh one — which is the method-path scoping holding. **1** config-serve denial in the whole run: the deliberate probe |
|
||||
|
||||
### Provenance
|
||||
|
||||
`docker compose -f docker-dev/docker-compose.yml up -d --build` from the worktree
|
||||
`/Users/dohertj2/Desktop/OtOpcUa/.worktrees/grpc-1b`, **exit 0**; image `otopcua-host:dev`
|
||||
rebuilt to `4105cf631003` at 12:51:47 UTC. **All six host nodes plus `migrator`,
|
||||
`cluster-seed` and `traefik` were recreated** (both one-shots exit 0); `sql` and its volume
|
||||
were kept. Nothing else touched the stack during the run, so it is not a
|
||||
concurrent-rebuild-invalidated one. Four rig-only Serilog `MinimumLevel:Override` Debug scopes
|
||||
were added on all six nodes for this run only — `ZB.MOM.WW.OtOpcUa.Runtime.Communication` (the
|
||||
sender's `Posted the ApplyAck` line), `ZB.MOM.WW.OtOpcUa.AdminUI.Grpc` (central's accept line),
|
||||
`ZB.MOM.WW.OtOpcUa.ControlPlane.Communication` and `Akka.Cluster.Tools.Client` — because the
|
||||
rig's default Serilog level is Information and checks 1–3 would otherwise have had no signal.
|
||||
Flip and overrides reverted after the gate, never committed.
|
||||
|
||||
```
|
||||
$ for c in central-1 central-2 site-a-1 site-a-2 site-b-1 site-b-2; do … done
|
||||
central-1 running restarts=0 mode=ClusterClient hostingFailed=0 resolveErr=2
|
||||
central-2 running restarts=0 mode=ClusterClient hostingFailed=0 resolveErr=2
|
||||
site-a-1 running restarts=0 mode=Grpc hostingFailed=0 resolveErr=0
|
||||
site-a-2 running restarts=0 mode=Grpc hostingFailed=0 resolveErr=0
|
||||
site-b-1 running restarts=0 mode=ClusterClient hostingFailed=0 resolveErr=0
|
||||
site-b-2 running restarts=0 mode=ClusterClient hostingFailed=0 resolveErr=0
|
||||
|
||||
$ curl … /health/ready → Healthy, members 2, unreachable 0 (MAIN)
|
||||
$ … http://<site>:8080/health/ready → 200 on all four site nodes
|
||||
```
|
||||
|
||||
### Checks 1 + 2 evidence — the two transports, side by side in one deployment
|
||||
|
||||
```
|
||||
$ curl -X POST http://localhost:9200/api/deployments -H 'X-Api-Key: docker-dev-deploy-key' \
|
||||
-d '{"createdBy":"1b-gate-check1"}'
|
||||
{"outcome":"Accepted","deploymentId":"53bd2626-ce9f-4255-a964-24e4cf3c7ccb", …} HTTP 202
|
||||
|
||||
$ … SELECT Status FROM dbo.Deployment WHERE DeploymentId='53bd2626-…'
|
||||
2 -- Sealed
|
||||
$ … SELECT NodeId, Status, AppliedAtUtc FROM dbo.NodeDeploymentState WHERE DeploymentId='53bd2626-…'
|
||||
central-1:4053|1|2026-08-06 12:55:53.909 site-a-1:4053|1|2026-08-06 12:55:53.930
|
||||
central-2:4053|1|2026-08-06 12:55:53.890 site-a-2:4053|1|2026-08-06 12:55:53.936
|
||||
site-b-1:4053|1|2026-08-06 12:55:53.915 site-b-2:4053|1|2026-08-06 12:55:53.924
|
||||
|
||||
# node side — the gRPC pair:
|
||||
site-a-1 [12:55:53 DBG] Posted the ApplyAck for 53bd2626… (Applied) to http://central-1:4055.
|
||||
site-a-2 [12:55:53 DBG] Posted the ApplyAck for 53bd2626… (Applied) to http://central-1:4055.
|
||||
# central side — same two acks, named:
|
||||
central-1 [12:55:53 DBG] ApplyAck for 53bd2626… from site-a-1:4053 (Applied) handed to the central communication actor
|
||||
central-1 [12:55:53 DBG] ApplyAck for 53bd2626… from site-a-2:4053 (Applied) handed to the central communication actor
|
||||
central-2 (none)
|
||||
|
||||
# per-node ReportApply accept counts, BOTH central nodes, this deployment:
|
||||
central-1 site-a-1=1 site-a-2=1 site-b-1=0 site-b-2=0 central-1=0 central-2=0
|
||||
central-2 site-a-1=0 site-a-2=0 site-b-1=0 site-b-2=0 central-1=0 central-2=0
|
||||
```
|
||||
|
||||
The site-b half is proven by exclusion plus its live association, which is the same shape 1A
|
||||
used for the site pairs:
|
||||
|
||||
```
|
||||
$ for c in site-b-1 site-b-2; do docker logs … | grep -c "Posted the ApplyAck"; done → 0, 0
|
||||
site-b-1 [12:53:02 INF] Connected to [akka.tcp://otopcua@central-2:4053/system/receptionist]
|
||||
site-b-2 [12:53:07 INF] Connected to [akka.tcp://otopcua@central-2:4053/system/receptionist]
|
||||
|
||||
$ for c in site-a-1 site-a-2; do docker logs … | grep -c "Connected to .*receptionist"; done → 0, 0
|
||||
$ for c in site-a-1 site-a-2 site-b-1 site-b-2; do grep -c "Mesh ClusterClient for cluster"; done → 0,0,0,0
|
||||
```
|
||||
|
||||
Site-b rows are `Applied` while nothing on either central node logged a `ReportApply` for them,
|
||||
and site-a holds no receptionist association at all — so neither pair could have used the
|
||||
other's transport. Coexistence is per pair, in one deployment, from one dispatch.
|
||||
|
||||
### Check 3 evidence — one ack per dispatch, and the duplicate that proved the absorber
|
||||
|
||||
Across all ten dispatches, counting `ReportApply` accepts on **both** central nodes:
|
||||
|
||||
```
|
||||
site-a-1 dep=53bd2626… acks=1 site-a-2 dep=53bd2626… acks=1
|
||||
site-a-1 dep=d0869c9e… acks=1 site-a-2 dep=d0869c9e… acks=1
|
||||
site-a-1 dep=17507001… acks=1 site-a-2 dep=17507001… acks=1 # the stop-failover dispatch
|
||||
site-a-1 dep=b1e837a2… acks=1 site-a-2 dep=b1e837a2… acks=1
|
||||
site-a-1 dep=a394eec6… acks=1 site-a-2 dep=a394eec6… acks=1
|
||||
site-a-1 dep=9bb520a4… acks=1 site-a-2 dep=9bb520a4… acks=1
|
||||
site-a-1 dep=458b8629… acks=2 site-a-2 dep=458b8629… acks=2 # the 4b PAUSE dispatch
|
||||
site-a-1 dep=fc2b7b64… acks=1 site-a-2 dep=fc2b7b64… acks=1
|
||||
site-a-1 dep=41e4935d… acks=1 site-a-2 dep=41e4935d… acks=1
|
||||
site-a-1 dep=4126636e… acks=1 site-a-2 dep=4126636e… acks=1
|
||||
$ … SELECT NodeId, COUNT(*) FROM dbo.NodeDeploymentState WHERE DeploymentId='53bd2626-…' GROUP BY NodeId
|
||||
central-1:4053|1 central-2:4053|1 site-a-1:4053|1 site-a-2:4053|1 site-b-1:4053|1 site-b-2:4053|1
|
||||
```
|
||||
|
||||
A refused endpoint (`docker stop`) cannot produce a duplicate — the server never saw the call —
|
||||
which is why `17507001…` is 1 per node despite failing over. The pause drill is the one shape
|
||||
that can, and it did:
|
||||
|
||||
```
|
||||
central-2 [13:04:01 DBG] ApplyAck for 458b8629… from site-a-1:4053 (Applied) handed … # failover target
|
||||
central-2 [13:04:01 DBG] ApplyAck for 458b8629… from site-a-2:4053 (Applied) handed …
|
||||
central-1 [13:04:33 DBG] ApplyAck for 458b8629… from site-a-1:4053 (Applied) handed … # at `docker unpause`
|
||||
central-1 [13:04:33 DBG] ApplyAck for 458b8629… from site-a-2:4053 (Applied) handed …
|
||||
central-1 [13:05:03 INF] Coordinator recovered in-flight deployment 458b8629… (2/6 acks landed)
|
||||
```
|
||||
|
||||
`2/6`, not `4/6`. The frozen central had in fact received both acks and replayed them on
|
||||
unpause, and `ConfigPublishCoordinator.HandleAck`'s NodeId-keyed absorption made the duplicate
|
||||
free — the exact claim `GrpcApplyAckSender`'s "at-least-once walk" remark makes, observed
|
||||
rather than argued.
|
||||
|
||||
### Check 4 evidence — refusal failover
|
||||
|
||||
```
|
||||
$ docker compose stop central-1 # 12:57:11
|
||||
$ curl -X POST … -d '{"createdBy":"1b-gate-check4-failover"}' # 12:57:30
|
||||
site-a-1 [12:57:30 INF] Posted the ApplyAck for 17507001… (Applied) to http://central-2:4055
|
||||
after 1 endpoint(s) failed (http://central-1:4055 => Unavailable).
|
||||
site-a-2 [12:57:30 INF] …identical…
|
||||
central-2 [12:57:30 DBG] ApplyAck for 17507001… from site-a-1:4053 (Applied) handed …
|
||||
central-2 [12:57:30 DBG] ApplyAck for 17507001… from site-a-2:4053 (Applied) handed …
|
||||
|
||||
$ … SELECT NodeId, Status FROM dbo.NodeDeploymentState WHERE DeploymentId='17507001-…'
|
||||
central-1:4053|0 central-2:4053|1 site-a-1:4053|1 site-a-2:4053|1
|
||||
site-b-1:4053|1 site-b-2:4053|1
|
||||
$ … SELECT Status FROM dbo.Deployment … → 4 (TimedOut) after the 2-minute deadline
|
||||
|
||||
$ docker compose start central-1 # 13:00:10
|
||||
$ curl … /health/ready → Healthy, members 2, unreachable 0
|
||||
$ curl -X POST … -d '{"createdBy":"1b-gate-check4-converge"}' → Status=2, all six Status=1
|
||||
```
|
||||
|
||||
**One operational detail worth carrying.** After central-1 returned, site-a-**1**'s cached
|
||||
`GrpcChannel` to `http://central-1:4055` stayed in transient failure for roughly two minutes
|
||||
while site-a-**2** reached the same restarted endpoint immediately — three dispatches apart:
|
||||
|
||||
```
|
||||
13:01:25 site-a-1 → central-2 after (central-1 => Unavailable) | site-a-2 → central-1 OK
|
||||
13:01:48 site-a-1 → central-2 after (central-1 => Unavailable) | site-a-2 → central-1 OK
|
||||
13:02:49 site-a-1 → central-1 OK | site-a-2 → central-1 OK
|
||||
$ docker exec otopcua-dev-site-a-1-1 bash -c '</dev/tcp/central-1/4055 && echo OPEN' → OPEN
|
||||
$ central-1 mesh denials in that window → 0 # the call never reached the interceptor
|
||||
```
|
||||
|
||||
TCP was open and central-1 logged nothing, so this is the client channel's own reconnect
|
||||
backoff, not a server or auth problem. **No ack was lost** — the ordered walk absorbed it every
|
||||
time and said so in the log. The Phase 2 reading: a central restart shifts that node's ack load
|
||||
onto the surviving endpoint for a minute or two afterwards, which a soak's failover-line count
|
||||
will show as a burst rather than a fault.
|
||||
|
||||
### Check 4b evidence — the hang, and why the fresh deadline is the whole check
|
||||
|
||||
```
|
||||
$ docker pause otopcua-dev-central-1-1 # 13:03:35
|
||||
$ curl … /health/ready → self akka.tcp://otopcua@central-2:4053 # traefik dropped central-1
|
||||
$ curl -X POST … -d '{"createdBy":"1b-gate-check4b-hang"}' # 13:03:51 (202)
|
||||
site-a-1 [13:04:01 INF] Posted the ApplyAck for 458b8629… (Applied) to http://central-2:4055
|
||||
after 1 endpoint(s) failed (http://central-1:4055 => DeadlineExceeded).
|
||||
site-a-2 [13:04:01 INF] …identical…
|
||||
central-2 [13:04:01 DBG] ApplyAck for 458b8629… from site-a-1:4053 (Applied) handed …
|
||||
central-2 [13:04:01 DBG] ApplyAck for 458b8629… from site-a-2:4053 (Applied) handed …
|
||||
$ … SELECT NodeId, Status, AppliedAtUtc … WHERE DeploymentId='458b8629-…'
|
||||
site-a-1:4053|1|2026-08-06 13:04:01.837 site-a-2:4053|1|2026-08-06 13:04:01.774
|
||||
central-1:4053|0|NULL central-2:4053|0|NULL site-b-1:4053|0|NULL site-b-2:4053|0|NULL
|
||||
$ docker unpause otopcua-dev-central-1-1 # 13:04:33
|
||||
```
|
||||
|
||||
`DeadlineExceeded` — not `Unavailable` — is the discriminator: the first endpoint burned a full
|
||||
`AckTimeoutSeconds` (10 s, the default; `13:03:51 → 13:04:01`) and central-2 was **still**
|
||||
dialled with a live deadline. Under the hoisted deadline this branch shipped before
|
||||
`667639e6`, that second attempt would have started already expired and the ack would have been
|
||||
dropped with a Warning. Observed failover latency: **≈10 s, one whole `AckTimeoutSeconds`**.
|
||||
|
||||
**Collateral the drill produced, recorded because it is the honest picture of a `pause`.**
|
||||
Pausing a cluster member is a heavier disturbance than stopping one: central-2 marked central-1
|
||||
UNREACHABLE at 13:03:46 and auto-downed it at 13:04:01, and after `unpause` the two central
|
||||
nodes each held a one-member view until central-1 was restarted (13:06:36). In that window the
|
||||
**two gRPC acks landed and none of the four ClusterClient acks did** — central-2 and both
|
||||
site-b nodes all logged `received DispatchDeployment` at 13:03:51 yet produced no ack the
|
||||
coordinator saw, and the deployment ended `TimedOut` at `2/6` naming exactly those four:
|
||||
|
||||
```
|
||||
central-1 [13:05:51 WRN] Deployment 458b8629… timed out after 00:02:00 (2/6 acks landed).
|
||||
No ack from: central-1:4053, central-2:4053, site-b-1:4053, site-b-2:4053
|
||||
central-1 [13:06:36 WRN] DriverHost central-1:4053: found orphan Applying row for deployment
|
||||
458b8629-…; replaying
|
||||
central-1 [13:06:37 INF] DriverHost central-1:4053: applied deployment 458b8629… (children=10)
|
||||
```
|
||||
|
||||
Stated at the strength the evidence supports: the four ClusterClient nodes received the
|
||||
dispatch and none of their acks reached the coordinator, while both gRPC nodes' acks did. The
|
||||
site nodes emit no apply-completion line, so whether each of the four actually finished
|
||||
applying is not determinable from their logs — what is determinable is that the ack did not
|
||||
arrive and the deadline said so honestly. The boot-replay backstop then repaired central-1.
|
||||
Not a 1B finding either way (no gRPC ack was involved), but it is the Phase 2 auto-down
|
||||
behaviour showing up early, and the split view needed a manual `restart central-1` to heal.
|
||||
|
||||
### Check 5 evidence — the auth matrix on the ack endpoint
|
||||
|
||||
`-import-path` onto the in-repo proto (the node serves no reflection). `PermissionDenied` means
|
||||
the interceptor refused; anything past it (`{}` or `InvalidArgument`) means auth **passed** and
|
||||
only the payload was graded:
|
||||
|
||||
```
|
||||
$ P=src/Core/ZB.MOM.WW.OtOpcUa.Commons/Protos
|
||||
$ G="docker run --rm --network otopcua-dev_default -v $PWD/$P:/protos:ro fullstorydev/grpcurl \
|
||||
-plaintext -import-path /protos -proto mesh_transport.proto"
|
||||
$ BODY='{"deploymentId":"ffffffffffffffffffffffffffffffff","nodeId":"site-a-1:4053",
|
||||
"outcome":"APPLY_OUTCOME_APPLIED","correlationId":"eeeeeeee…"}'
|
||||
|
||||
# 5a no bearer, cluster header present -> central-1
|
||||
Code: PermissionDenied Message: Central command authentication failed.
|
||||
# 5b Bearer dev-mesh-psk-SITE-B + cluster SITE-A -> central-1
|
||||
Code: PermissionDenied Message: Central command authentication failed.
|
||||
# 5c Bearer dev-mesh-psk-SITE-A, NO cluster header-> central-1
|
||||
Code: PermissionDenied Message: Central command authentication failed.
|
||||
# 5d Bearer dev-mesh-psk-SITE-A + cluster SITE-A, FAKE deployment id
|
||||
{}
|
||||
# 5e same, MALFORMED deployment id "not-a-guid"
|
||||
Code: InvalidArgument Message: undecodable ApplyAck
|
||||
# 5f Bearer dev-mesh-psk-SITE-B + cluster SITE-B (positive control)
|
||||
Code: InvalidArgument Message: undecodable ApplyAck
|
||||
# 5g Bearer dev-mesh-psk-SITE-A + cluster SITE-Z (unknown cluster)
|
||||
Code: PermissionDenied Message: Central command authentication failed.
|
||||
# 5h no bearer -> central-2
|
||||
Code: PermissionDenied Message: Central command authentication failed.
|
||||
```
|
||||
|
||||
The accepted fake ack changed nothing — the coordinator ignored a deployment it is not tracking:
|
||||
|
||||
```
|
||||
$ … SELECT COUNT(*) FROM dbo.NodeDeploymentState WHERE DeploymentId='ffffffff-…' → 0
|
||||
$ … SELECT COUNT(*) FROM dbo.Deployment WHERE DeploymentId='ffffffff-…' → 0
|
||||
central-1 [13:08:08 DBG] ApplyAck for ffffffff… from site-a-1:4053 (Applied) handed to the
|
||||
central communication actor
|
||||
```
|
||||
|
||||
Central's denial log separates the three operator-facing causes even though the wire status is
|
||||
deliberately uniform:
|
||||
|
||||
```
|
||||
[13:08:07 WRN] Rejected a central command call to /mesh_transport.v1.CentralCommandService/ReportApply
|
||||
claiming cluster SITE-A: no bearer token presented.
|
||||
[13:08:07 WRN] … claiming cluster SITE-A: the presented bearer token did not match that cluster's
|
||||
pre-shared key, no key could be established for it, or it is not a cluster this node knows…
|
||||
[13:08:07 WRN] Rejected a central command call to …/ReportApply: no x-otopcua-cluster header, so there
|
||||
is no cluster whose pre-shared key the caller could be graded against.
|
||||
[13:08:25 WRN] … claiming cluster SITE-Z: … or it is not a cluster this node knows…
|
||||
```
|
||||
|
||||
5g is the **known-cluster gate answering live**: a valid SITE-A key presented for `SITE-Z` is
|
||||
refused in O(1), which also confirms the gate had in fact been published — see observation (b).
|
||||
|
||||
### Check 6 evidence — ConfigServe on the same listener
|
||||
|
||||
A real node-driven fetch needed a real revision change, so `ServerCluster.Notes` for `MAIN` was
|
||||
edited, deployed, and **restored** (the revision hash returned to its pre-gate
|
||||
`642b9d6f79b9…`, verified by a further dispatch):
|
||||
|
||||
```
|
||||
$ … UPDATE dbo.ServerCluster SET Notes = '<original> | 1b-gate-fetch-probe' WHERE ClusterId='MAIN'
|
||||
$ curl -X POST … → revisionHash 20af950fb211… (was 642b9d6f79b9…) Status=2
|
||||
site-a-1 [13:09:31 INF] Fetched + verified artifact for 41e4935d… from http://central-1:4055 (28296 bytes).
|
||||
site-a-2 [13:09:31 INF] …same… site-b-1 [13:09:32 INF] …same… site-b-2 [13:09:32 INF] …same…
|
||||
$ … UPDATE dbo.ServerCluster SET Notes = '<original>' …
|
||||
$ curl -X POST … → revisionHash 642b9d6f79b9… Status=2 # restored, byte-identical
|
||||
```
|
||||
|
||||
Both interceptors on the one listener, each answering for its own service:
|
||||
|
||||
```
|
||||
# authenticated Fetch, config-serve key:
|
||||
$ $G -H 'authorization: Bearer configserve-docker-dev-key' -d '{"deploymentId":"FC2B7B64-…"}' \
|
||||
central-1:4055 deployment_artifact.v1.DeploymentArtifactService/Fetch
|
||||
{ "data": "eyJDbHVzdGVycyI6W3siQ2x1c3RlcklkIjoiTUFJTiIsIk5hbWUiOiJNYWluIGNsdXN0ZXIiL…" }
|
||||
# unauthenticated Fetch — refused by the CONFIG-SERVE interceptor, not the mesh one:
|
||||
Code: Unauthenticated Message: Config-serve authentication failed.
|
||||
```
|
||||
|
||||
`Unauthenticated` here versus `PermissionDenied` on the mesh service is the method-path scoping
|
||||
in `CentralCommandAuthInterceptor` holding: the two services share one `AddGrpc` pipeline and
|
||||
neither interceptor grades the other's calls.
|
||||
|
||||
### Observations carried forward from the reviews
|
||||
|
||||
**(a) The I-4 shape is not exercisable on this rig, and that is a property of the rig, not a
|
||||
skipped check.** `MeshPskProvider.TryGetPsk` consults `MeshTransport:ClusterPsks` **before** the
|
||||
secret store and caches only store-resolved values, and docker-dev supplies
|
||||
`MeshTransport__ClusterPsks__{MAIN,SITE-A,SITE-B}` on both central nodes. The
|
||||
`InvalidateAll()` a contact-refresh tick performs (`ContactRefreshSeconds` = 60) therefore drops
|
||||
an always-empty cache, and an ack arriving just after a tick pays no store read. No latency
|
||||
delta was measurable and none should be: every ack in the run landed inside the same second it
|
||||
was posted, refresh tick or not. A real deployment resolving `OT-MESH-PSK-<clusterId>` from the
|
||||
store is where I-4 becomes observable — Phase 2 on a store-backed rig, not here.
|
||||
|
||||
**(b) The `Failed to resolve` Error fired on 4 of 4 admin boots — and healed every time.** Worse
|
||||
odds than 1A's 2 of 3, and both dependencies lost the race on every boot:
|
||||
|
||||
```
|
||||
central-1 [12:53:00 ERR] Failed to resolve IMeshCommandDialer … / IMeshPskProvider … # boot 1
|
||||
central-1 [13:00:29 ERR] …both again… # boot 2 (check 4 restart)
|
||||
central-1 [13:06:36 ERR] …both again… # boot 3 (4b restart)
|
||||
central-2 [12:53:02 ERR] …both… # its single boot
|
||||
central-1 [12:53:00 ERR] No IMeshPskProvider was supplied to this actor; the known-cluster gate
|
||||
will NEVER be published and cached per-cluster keys will NEVER be dropped…
|
||||
```
|
||||
|
||||
The second line is the one that reads worst, and 1B disproves it directly rather than by
|
||||
argument: **every site-a ack central-1 accepted required that provider**, including the ones
|
||||
after its third boot (13:07:36, 13:09:31, 13:09:59), and probe 5g's `SITE-Z` refusal is only
|
||||
possible if `SetKnownClusters` had in fact been published. The memoize heals it; the Error text
|
||||
does not say so. This is the 1A finding-5 carry-forward, now with a second, independent live
|
||||
confirmation and a stronger case for the wording fix — the message contains the word "NEVER"
|
||||
twice about something that self-corrects within one deploy.
|
||||
|
||||
**(c) Zero mesh interceptor denials outside the deliberate probes.** Whole-run counts on every
|
||||
node and every interceptor:
|
||||
|
||||
```
|
||||
central-1 telemetry=0 configserve=1 localdbsync=0 meshCentralCmd=4 nodeCmd=0
|
||||
central-2 telemetry=0 configserve=0 localdbsync=0 meshCentralCmd=1 nodeCmd=0
|
||||
site-a-1 telemetry=0 configserve=0 localdbsync=0 meshCentralCmd=0 nodeCmd=0
|
||||
site-a-2 telemetry=0 configserve=0 localdbsync=0 meshCentralCmd=0 nodeCmd=0
|
||||
site-b-1 telemetry=0 configserve=0 localdbsync=0 meshCentralCmd=0 nodeCmd=0
|
||||
site-b-2 telemetry=0 configserve=0 localdbsync=0 meshCentralCmd=0 nodeCmd=0
|
||||
```
|
||||
|
||||
`meshCentralCmd` = 4 on central-1 (probes 5a/5b/5c/5g) + 1 on central-2 (5h) = exactly the five
|
||||
deliberate negatives; `configserve` = 1 = the deliberate 6b. Nothing else was refused anywhere.
|
||||
|
||||
**(d) Pre-existing rig noise, so a Phase 2 error grep is not surprised by it.** Site nodes log
|
||||
`Unavailable … Name or service not known` from the historian client — the rig points
|
||||
`ServerHistorian__Endpoint` at `http://histgw-absent.invalid:5222` on purpose (45 occurrences on
|
||||
site-a-1, 1 on site-b-1, 4 on central-1 in this run). Nothing to do with the ack plane.
|
||||
|
||||
### Rig state after the gate — **restored, six healthy, all-ClusterClient, on the branch image**
|
||||
|
||||
The flip and the four Serilog overrides were reverted (`git checkout docker-dev/docker-compose.yml`,
|
||||
`grep -c "GATE-1B ONLY"` → 0) and the nodes recreated on the committed compose. The simultaneous
|
||||
recreate cold-started both central nodes at once and they self-formed one-member views — the
|
||||
known simultaneous-cold-start split-brain the (default-OFF) `Cluster:BootstrapGuard` addresses —
|
||||
healed with a single `restart central-2`:
|
||||
|
||||
```
|
||||
central-1 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
central-2 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
site-a-1 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
site-a-2 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
site-b-1 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
site-b-2 running restarts=0 mode=ClusterClient image=4105cf631003 hostingFailed=0
|
||||
|
||||
$ for h in central-1 central-2; do … /health/ready; done
|
||||
central-1 Healthy members 2 unreachable 0 leader akka.tcp://otopcua@central-1:4053
|
||||
central-2 Healthy members 2 unreachable 0 leader akka.tcp://otopcua@central-1:4053
|
||||
$ … http://<site>:8080/health/ready → 200 ×4
|
||||
|
||||
$ curl -X POST … -d '{"createdBy":"1b-gate-rig-restore-verify"}'
|
||||
CDDA1D80-…|2 central-1|1 central-2|1 site-a-1|1 site-a-2|1 site-b-1|1 site-b-2|1
|
||||
$ for c in site-a-1 site-a-2 site-b-1 site-b-2; do grep -c "Posted the ApplyAck"; done → 0,0,0,0
|
||||
$ for c in central-1 central-2; do grep -c "Mesh ClusterClient for cluster"; done → 3 per boot
|
||||
```
|
||||
|
||||
Zero gRPC acks after the rollback and three ClusterClients per central boot: the dark switch
|
||||
rolls back cleanly in the ack direction too, which is what Phase 2 depends on if its cutover has
|
||||
to be reversed. Rig configuration is byte-identical to its pre-gate state (`ServerCluster.Notes`
|
||||
restored; revision hash back to `642b9d6f79b9…`).
|
||||
|
||||
### Phase 1B defects
|
||||
|
||||
**None.** No product code was changed during or after this gate.
|
||||
|
||||
---
|
||||
|
||||
@@ -712,7 +1079,9 @@ is re-checked in the next gate (the ScadaBridge proportionate-gate rule).
|
||||
| Check 4 acknowledge half — the condition actually acknowledging | 1A run 1 | The rig's one `ScriptedAlarm` sits Normal and its owning central node was down | — | **CLOSED in 1A run 2** — acked from the real `/alerts` page, `ACKNOWLEDGED` row observed |
|
||||
| Check 8 for telemetry + config-serve | 1A run 1 | Central dials both planes and never booted, so neither carried a call — 0 denials was vacuous | — | **CLOSED in 1A run 2** — both planes carried authenticated traffic with 0 denials |
|
||||
| Check 3 central half — `RestartDriver`/`ReconnectDriver` **originating at the AdminUI** | 1A runs 1 + 2 | **Structurally undrivable, not a rig problem:** `<DriverStatusPanel` has 0 usages repo-wide (the 5 name hits are comments), no rendered page carries a Restart/Reconnect control, and the only non-script-analysis HTTP POST is `/api/deployments`. Pre-existing on `master`, not caused by this program | Composition the controller accepted: run 1's live node-side leg for both commands + run 2's check 4, which drives the identical `AdminOperationsActor.Dispatch` → `DispatchOverGrpc` origin path from the AdminUI for another command type; per-type difference is `ToEnvelope`, covered by the T0.2 goldens | **CLOSED by composition.** The orphaned panel itself is out of this program's scope — file separately if the control is meant to exist |
|
||||
| `Failed to resolve` Error text says "continuing without it", which reads permanent although first use retries; and it will trip a soak's error grep on a healthy node | 1A run 2 (finding 5) | Cosmetic/observability, not behaviour | The self-heal proven live (finding 5) | Phase 2 |
|
||||
| `Failed to resolve` Error text says "continuing without it", which reads permanent although first use retries; and it will trip a soak's error grep on a healthy node | 1A run 2 (finding 5) | Cosmetic/observability, not behaviour | The self-heal proven live (finding 5), and **re-confirmed independently in 1B**: 4 of 4 admin boots lost the race, yet every site-a ack central-1 accepted and probe 5g's `SITE-Z` refusal both require the provider it claimed would "NEVER" be published | Phase 2 |
|
||||
| I-4 cold-PSK-cache latency after a contact-refresh tick | 1B | **Not exercisable on docker-dev, structurally:** `TryGetPsk` reads `MeshTransport:ClusterPsks` ahead of the store and caches only store-resolved values, and the rig configures that map — so `InvalidateAll()` clears an always-empty cache and no ack pays a store read | Every ack in the run landed inside the second it was posted, tick or no tick (1B observation (a)) | Phase 2, on a store-backed rig |
|
||||
| A restarted central's cached `GrpcChannel` can stay in transient failure for ~2 min on the node that saw it die, while a sibling node reaches the same endpoint at once | 1B check 4 | Not a defect — the ordered walk absorbed it and logged the failover each time; no ack lost. TCP was open and central logged nothing, so it is the client channel's backoff | 3 dispatches across the window, 2 failed over and the 3rd went direct (1B check 4 evidence) | Phase 2 soak — expect a burst of failover lines after any central restart, not a fault |
|
||||
|
||||
### Defects the gates caught that the suite did not
|
||||
|
||||
|
||||
Reference in New Issue
Block a user