5da7ba6517
Ran the full item-1 grind (authored a live Modbus equipment tag, connected to the sim, LDAP-authed writes, docker pause the peer). 4 failing wrapped writes produced 0 retry/breaker lines on either central. Root cause (corrects the issue's hypothesis): ModbusDriver.WriteAsync swallows all exceptions and returns WriteResult(StatusBadInternalError) — never throws; CapabilityInvoker feeds only exceptions to Polly; breaker ShouldHandle is Handle<Exception>; Write retry pinned to 0 (R2-02/S-8). So a failing wrapped write emits no line by construction, for any polling driver. The line is reachable ONLY for a session driver (OpcUaClient) faulting mid-Discover/Subscribe (30s Polly timeout throws) — a production timing race, not deterministically forcible on the rig. Behaviour stays unit-proven by the pipeline-builder test. - New: archreview/plans/artifacts/456-retry-breaker-live-finding-2026-07-15.md - FOLLOWUP-10 updated with the structural finding + recommendation to close item 1.
84 lines
6.4 KiB
Markdown
84 lines
6.4 KiB
Markdown
# #456 item 1 — live retry/breaker log-line capture: structural finding (2026-07-15)
|
||
|
||
**Outcome:** the log line was **not** captured, but the "grind" produced a **definitive structural
|
||
finding** that supersedes the issue's acceptance framing: the trigger the issue proposes (an idempotent
|
||
`WriteAsync` to a dead endpoint) is **structurally incapable** of emitting a retry/breaker line, and the line
|
||
is reachable in production **only** for a session-based driver (OpcUaClient) faulting *mid-`Discover`/`Subscribe`*
|
||
— a racy transient that cannot be deterministically forced on the dev rig. This is why three sessions with
|
||
polling-driver fixtures never observed it.
|
||
|
||
## What was actually driven live (the grind)
|
||
|
||
Full end-to-end wrapped-dispatch exercise on the docker-dev central cluster (`central-1`/`central-2`, MAIN):
|
||
|
||
1. Brought up the modbus sim on the shared host (`10.100.0.35:5020`, `otopcua-pymodbus-standard`).
|
||
2. **Authored a complete Modbus equipment hierarchy via SQL** (MAIN cluster): Equipment-kind `Namespace`
|
||
`ns-mb-eq` → `DriverInstance drv-mb` (`Modbus`, `{"Host":"10.100.0.35","Port":5020,"UnitId":1}`) → `Device`
|
||
→ `UnsArea`/`UnsLine` → `Equipment EQ-111111111111` → writable `Tag reg1`
|
||
(`{"region":"HoldingRegisters","address":1,"dataType":"Int16","byteOrder":"BigEndian","writable":true}`,
|
||
`AccessLevel=ReadWrite`, `WriteIdempotent=1`).
|
||
3. Deployed headless (`POST :9200/api/deployments`). Runtime log: `spawned Modbus driver drv-mb` →
|
||
`DriverInstance drv-mb: connected` → `subscribed to 1 refs`. Node materialized at
|
||
`ns=2;s=EQ-111111111111/reg1`.
|
||
4. **Baseline (sim up):** live read `Good` (value 1); LDAP-authed (`multi-role`, `WriteOperate` role via the
|
||
shared GLAuth data-plane `GroupToRole`) write `= 123` → `Write successful`. **The wrapped write path is
|
||
fully live end-to-end** (OPC UA write → `NodeWriteRouter` → `DriverHostActor.RouteNodeWrite` →
|
||
`DriverInstanceActor.WriteAsync` invoker-wrapped site → `ModbusDriver` → sim).
|
||
5. **Fault:** `docker pause otopcua-pymodbus-standard` (frozen peer — driver stays `Connected`), then drove 4
|
||
LDAP-authed writes into the frozen peer.
|
||
6. **Result:** every write logged `Operator write to EQ-111111111111/reg1 rejected: StatusCode=0x80020000`
|
||
(BadInternalError), node reverted. **`grep "Driver resilience retry|circuit-breaker OPENED"` on BOTH
|
||
centrals = 0 matches** despite 4 exercised, failing wrapped writes.
|
||
|
||
## Why the write trigger is structurally impossible
|
||
|
||
- **`ModbusDriver.WriteAsync` swallows every exception and returns a bad `WriteResult` status — it never
|
||
throws** (`ModbusDriver.cs:964-967`: `catch (Exception) { results[i] = new WriteResult(StatusBadInternalError); }`
|
||
→ `0x80020000`, exactly the observed reject status).
|
||
- **The `CapabilityInvoker` only feeds *exceptions* to the Polly pipeline** (`CapabilityInvoker.cs:84/112/147`:
|
||
`await pipeline.ExecuteAsync(callSite, …)` — the `callSite` is the driver's `WriteAsync`; a non-throwing
|
||
return is a pipeline **success**). The invoker does **not** inspect the returned `WriteResult` status.
|
||
- The circuit breaker's `ShouldHandle` is `Handle<Exception>` (`DriverResiliencePipelineBuilder.cs`), and
|
||
`Write` retry is **pinned to 0** as an invariant (R2-02/S-8, `DriverResilienceOptions.cs:64-66`).
|
||
- ∴ a failing wrapped **write** produces **no exception → no retry, no breaker count, no log line** — by
|
||
construction, for **any** driver that maps write failures to a status (all polling drivers do). The issue's
|
||
hypothesis ("the only invoker-wrapped Modbus site that throws is an idempotent `WriteAsync` to a dead
|
||
endpoint") is **incorrect** — even an idempotent write to a truly dead endpoint returns
|
||
`StatusBadInternalError` rather than throwing.
|
||
|
||
## Where the line IS reachable (and why it's elusive)
|
||
|
||
The retry/breaker pipeline fires only when a **wrapped capability call throws**. Of the 6 wrapped sites in
|
||
`DriverInstanceActor` (`Write`, `Acknowledge`, `Subscribe`, `Unsubscribe`, `SubscribeAlarms`, `Discover`):
|
||
|
||
- **Polling drivers (Modbus/S7/AbCip/AbLegacy/TwinCAT/Focas):** `WriteAsync`/`AcknowledgeAsync` swallow →
|
||
status; `SubscribeAsync` is a lazy poll-registration (no connect, no throw); `DiscoverAsync` is
|
||
offline/config-driven (enumerates authored tags, no connect). **None of their wrapped sites throw a
|
||
transient exception through the seam.**
|
||
- **Session drivers (OpcUaClient):** `DiscoverAsync` (remote browse) and `SubscribeAsync`
|
||
(CreateSubscription/CreateMonitoredItems) require a live session and **do** throw on a session fault. The
|
||
post-connect discovery loop (`DriverInstanceActor.StartDiscovery`, honouring `RediscoverPolicy`) runs
|
||
`DiscoverAsync` under a 30 s Polly timeout on each `Connected` entry.
|
||
|
||
So the **only** way to emit the line is a session driver whose session faults **while a wrapped
|
||
`Discover`/`Subscribe` is in flight** (e.g. `docker pause` of a live OPC UA endpoint mid-discovery → the
|
||
30 s timeout throws `TimeoutRejectedException` → `Discover` retry ×2 → `Driver resilience retry`). This is a
|
||
genuine production event under real network faults, but it is a **timing race** — connect must succeed, then
|
||
the fault must land during the wrapped call, before the session-keepalive drops the driver to `Reconnecting`
|
||
(where the wrapped sites no longer fire). It cannot be deterministically forced on the rig with the available
|
||
fixtures (opc-plc was down; no on-demand rediscovery trigger).
|
||
|
||
## Conclusion / recommendation
|
||
|
||
- **Item 2 (the real code gap — `ResilienceConfig` in the deploy artifact)** is done + live-verified on both
|
||
nodes (PR #461).
|
||
- **Item 1** is **deterministically proven** by the `DriverResiliencePipelineBuilder` logging unit test (the
|
||
`OnRetry`/`OnOpened` handlers emit the exact lines) plus `CapabilityInvoker` retry tests and the factory
|
||
override test. The **live** capture is not deterministically achievable from the dev rig — and, more
|
||
importantly, the grind proved the issue's proposed write-trigger is **structurally impossible**. The line is
|
||
an OpcUaClient-only, transient-fault-mid-`Discover`/`Subscribe` event.
|
||
- **Recommend closing item 1** on this finding: the observability surface is unit-proven and the wrapped
|
||
dispatch path is now **live-confirmed end-to-end** (authored driver → connected → LDAP write → wrapped
|
||
`WriteAsync` → faulted → surfaced). The remaining "eyeball the raw line" is an operator/staging observation
|
||
during a real OpcUaClient session fault, not a code deliverable.
|