docs(localdb): phase 2 rig soak findings — GATE FAILS on a phase 1 defect

Task 1 of the Phase 2 plan. The gate stops the plan, but not for the reason it anticipated: oplog sizing is fine and D6 is resolved. BLOCKER: the Phase 1 consolidated LocalDb (site-localdb.db) throws SQLite Error 10 'disk I/O error' on essentially every write on the ACTIVE node under sustained load — site_events, OperationTracking and the audit telemetry paths all fail, and site event logging silently drops events. Isolated to the load (not the node, not host-side observation) by failing over between nodes, and to LocalDb specifically (legacy store-and-forward.db / scadabridge.db in the same bind-mounted directory take zero errors under identical load). Phase 2 would register 8 more tables into that database — including the two highest-volume ones — while deleting the bespoke mechanisms that currently carry them. Must be root-caused first. Also recorded: D6's premise corrected (largest known production config_json is ~60-70 KB, not >128 KB — but MaxBatchSize 500 is still unsafe, use 16); D4's premise corrected (alarm writes are bounded by per-SourceReference coalescing at a 100 ms flush); sf_messages has a hard 50 rows/sec structural ceiling; and exceeding the oplog caps is a graceful snapshot-resync, not a failure. Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
2026-07-20 01:06:59 -04:00
parent cf46e59680
commit fc553bd9ba
1 changed files with 277 additions and 0 deletions
@@ -0,0 +1,277 @@
 # LocalDb Phase 2 — rig soak findings
 **Run date:** 2026-07-19 / 2026-07-20 (UTC) · **Rig:** local 8-node docker cluster, site-a pair
 **Task:** Task 1 of [`2026-07-19-localdb-adoption-phase2.md`](2026-07-19-localdb-adoption-phase2.md)
 > ## GATE VERDICT: **STOP — do not proceed to Task 3.**
 >
 > Not for the reason the plan anticipated. Oplog sizing is fine and D6 is resolved. The soak
 > instead surfaced a **pre-existing Phase 1 defect**: the consolidated LocalDb database
 > (`site-localdb.db`) throws `SQLite Error 10: 'disk I/O error'` on essentially every write on
 > the **active** node under sustained concurrent load. Phase 2 moves eight more tables —
 > including the two highest-volume ones — into exactly that database. See
 > [Finding 1](#finding-1-blocker).
 ---
 ## 1. Method as actually executed
 The plan's method needed four corrections before it would run. Recorded here so the next run
 does not rediscover them.
 | Plan said | Reality |
 |---|---|
 | `docker exec … curl -s localhost:8084/metrics` | **No `curl` in the `aspnet:10.0` image.** Use a sidecar sharing the container netns: `docker run --rm --network container:scadabridge-site-a-a curlimages/curl:latest -s localhost:8084/metrics` |
 | Sample with host-side `sqlite3` against the bind mounts | **Unsafe under live writes** — SQLite's `-shm` shared-memory index is not reliable across the Docker VM boundary. Ultimately *not* the cause of Finding 1 (proven below), but it should not be done against a database the container is actively writing. Copy the files first, or read counters from `/metrics`. |
 | Drive alarm churn on a deployed instance | **Not possible on this rig.** `infra/mssql/seed-config.sql` seeds zero `TemplateNativeAlarmSources`, opc-plc runs with no alarm flags, and no simulator or harness exists anywhere in the repo. `native_alarm_state` stayed at 0 rows throughout. Bounded analytically instead — see [Finding 3](#finding-3). |
 | Drive S&F churn via template 4's `TestExternalSystem` script | Template 4 exists after a reseed but is **not deployable** (34 pre-deployment validation errors: 30 `ConnectionBinding` + 4 `ScriptCompilation`). A purpose-built `SoakGenerator` template was used instead — see below. |
 ### The generator that worked
 `ExternalSystem.Call` does **not** buffer to store-and-forward in practice; `ExternalSystem.CachedCall`
 is the buffering surface. This is the single most important operational detail for reproducing
 S&F load.
 - Template `SoakGenerator` (id 2021), one `Interval` script at `{"intervalMs":5000}`:
  ```csharp
  var parms = new Dictionary<string, object?> { ["a"] = 2, ["b"] = 3 };
  await ExternalSystem.CachedCall("Test REST API", "Add", parms);
  ```
 - No attributes, no compositions, no connection bindings — deliberately, so it deploys cleanly.
 - `ExternalSystemDefinitions` id 1 repointed to `http://127.0.0.1:9` (discard port → connection
  refused → classified transient → buffered).
 - 4 instances (`soakgen-1..4`) deployed to site-a.
 Sustained rate observed: ~**2.9 HTTP attempts/sec** (688–864 connection-refused per 4 min).
 ### Two rig-tooling bugs found and fixed en route
 1. **`docker/seed-sites.sh` seeded stale role names** — `Design`/`Deployment` instead of the
   canonical `Designer`/`Deployer` (`src/ZB.MOM.WW.ScadaBridge.Security/Roles.cs:46-47`). Every
   Designer/Deployer-gated management command failed `UNAUTHORIZED` on a freshly reseeded rig,
   including `seed-sites.sh`'s own trailing `deploy artifacts` and `reseed.sh` stage 6d.
   **Fixed** (commit `cf46e596`).
 2. **`infra/mssql/setup.sql` never executes.** It is mounted into
   `/docker-entrypoint-initdb.d/`, a convention the official `mcr.microsoft.com/mssql/server`
   image does not implement. After `reseed.sh` drops the volume (`docker compose down -v`),
   nothing recreates `ScadaBridgeConfig` or the `scadabridge_app` login, so `reseed.sh` hangs
   forever on its "Waiting for setup.sql to create ScadaBridgeConfig" poll. Worked around by
   applying the three init scripts by hand. **NOT yet fixed in the repo.**
 ---
 ## Finding 1 (BLOCKER)
 ### The Phase 1 consolidated LocalDb fails under sustained write load on the active node
 `site-localdb.db` throws `SQLite Error 10: 'disk I/O error'` on essentially every write once the
 active node is under concurrent load. Both Phase 1 tables and the audit telemetry paths are
 affected.
 Representative stacks (`docker logs scadabridge-site-a-b`):
 ```
 Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 10: 'disk I/O error'.
   at ZB.MOM.WW.ScadaBridge.SiteEventLogging.SiteEventLogger.ProcessWriteQueueAsync()
      SiteEventLogger.cs:line 221/236
 Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 10: 'disk I/O error'.
   at ZB.MOM.WW.ScadaBridge.SiteRuntime.Tracking.OperationTrackingStore.RecordEnqueueAsync(...)
      OperationTrackingStore.cs:line 137
   at ...CachedCallTelemetryForwarder.TryEmitTrackingAsync(...) line 148
 ```
 User-visible symptom: `[ERR] Failed to record event: script from ScriptActor:SoakCall` — **site
 event logging is silently dropping events on the floor under load.**
 #### It follows the load, not the node, not the observer
 The failure was isolated by moving the load between nodes:
 | Node | Role | Under load | `disk I/O error` in 4 min |
 |---|---|---|---|
 | site-a-a | active | yes | 2 175 |
 | site-a-a | standby (after restart) | no | **0** |
 | site-a-b | standby | no | **0** |
 | site-a-b | active (after failover) | yes | **4 391** |
 #### It is LocalDb-specific, not the filesystem
 The decisive control. Under identical load, on the same node, in the same bind-mounted
 directory, counting error-stack frames over 3 minutes:
 | Store | Backing file | Errors |
 |---|---|---|
 | `OperationTrackingStore` | `site-localdb.db` (LocalDb) | 13 044 |
 | `SiteAuditTelemetryActor` | `site-localdb.db` (LocalDb) | 4 350 |
 | `SiteEventLogger` | `site-localdb.db` (LocalDb) | 900 |
 | `CachedCallTelemetryForwarder` | `site-localdb.db` (LocalDb) | 162 |
 | `StoreAndForwardStorage` | `store-and-forward.db` (legacy) | **0** |
 | `SiteStorageService` | `scadabridge.db` (legacy) | **0** |
 Ordinary SQLite on the same bind mount is completely healthy. Only the LocalDb-managed
 database fails.
 #### Ruling out the observer
 Onset (04:56:37) was one second after a host-side `sqlite3` sample (04:56:36), which made
 observer-induced `-shm` corruption the leading hypothesis. It is **excluded**: after node-a was
 restarted (fresh open, recovered shm) and the load failed over to node-b, node-b began erroring
 at a *higher* rate while no host process touched its files, and node-a — whose files *had* been
 sampled — went to zero once it stopped carrying load. The variable that tracks the errors is
 **load**, not host access.
 #### Secondary defect, same area
 ```
 [ERROR][akka://scadabridge/user/site-audit-telemetry] There is no active ActorContext,
 this is most likely due to use of async operations from within this actor.
 Cause: System.NotSupportedException
 ```
 `SiteAuditTelemetryActor` is closing over `ActorContext` across an `await`. Likely a
 contributing cause rather than a separate issue — it is in the same write path — but it is a
 real bug on its own terms.
 #### Why this blocks Phase 2
 Phase 2 registers **eight further tables** into this database, including `native_alarm_state`
 (the highest-volume table in either DB) and `sf_messages`. It also **deletes** the bespoke
 mechanisms (`SiteReplicationActor`, `ReplicationService`) that currently carry that data
 independently of LocalDb. Cutting over onto a store that cannot absorb the *current* write
 load — and doing so in the same commit that removes the fallback — would convert a logging
 defect into site-wide config and buffer loss.
 This is a Phase 1 defect. It must be root-caused and fixed before Phase 2's Task 3.
 ---
 ## Finding 2 — D6 resolved: no stop condition, but `MaxBatchSize` must be lowered
 The plan asserts `deployed_configurations.config_json` is "documented to exceed 128 KB per row."
 That misreads the source. `docs/known-issues/2026-06-26-deploy-config-exceeds-akka-frame-size.md`
 says the *escaped Akka envelope* exceeded the 128 KB frame, and that the default serializer
 double-escapes the payload, so **"the raw flattened JSON only needs to be ~60-70 KB to blow the
 128 KB frame."**
 So the largest known real production `config_json` is on the order of **60–70 KB**.
 Measured on the rig (4 deployed configs): **max 715 B, avg 714 B** — trivially small, as the plan
 predicted, hence the production figure above is the one to size against. (A direct measurement
 against wonder was attempted; `wonder-app-vd03.zmr.zimmer.com` resolves over the VPN but the
 servecli SSH service on :2222 refuses connections, so the box was unreachable.)
 **Verdict: no stop condition.** Nothing approaches the 4 MB single-row ceiling.
 **But the batching risk is real.** Batching is row-count-only (`MaxBatchSize` default **500**),
 and neither side configures gRPC message limits, so the 4 MB default receive cap applies:
 ```
 500 rows × 70 KB ≈ 35 MB  ≫  4 MB   →  poison batch, stream wedged
 ```
 Recommended for Task 19:
 ```
 LocalDb:Replication:MaxBatchSize = 16
 ```
 `16 × 128 KB = 2 MB` — 2× headroom on row size over the known worst case, and 2× headroom
 against the 4 MB cap.
 ---
 ## Finding 3 — D4 corrected: alarm write rate is bounded, not unbounded
 The plan calls `native_alarm_state` "unbounded by design." It is not.
 `NativeAlarmActor.MarkDirtyUpsert` (`NativeAlarmActor.cs:473-502`) coalesces into a dictionary
 **keyed by `SourceReference`** and flushes on a timer (`_persistFlushInterval`, default
 **100 ms**). One flush writes at most one row per distinct source reference, regardless of how
 many transitions occurred in that window.
 ```
 worst-case rows/sec  =  distinct_source_refs × 10
 ```
 An alarm storm on N sources costs N rows per 100 ms flush, not N × transition-rate. This makes
 the table analytically sizeable without a generator — which matters, because this rig cannot
 produce alarm load at all (see §1).
 **Not empirically validated.** `native_alarm_state` held 0 rows for the entire run.
 ---
 ## Finding 4 — `sf_messages` has a hard structural ceiling of 50 rows/sec
 Confirmed by code rather than measurement, which is stronger here. The retry sweep takes at most
 `SweepBatchLimit` messages every `RetryTimerInterval`, and each failed attempt is one `UPDATE`
 incrementing `retry_count`:
 ```
 SweepBatchLimit (500) ÷ RetryTimerInterval (10 s)  =  50 row-writes/sec, hard ceiling
 ```
 This confirms the plan's "~50 row-writes/sec worst case" — and it is a ceiling, not an estimate.
 `DefaultMaxRetries = 50` at `DefaultRetryInterval = 30 s` bounds each message to 50 updates over
 25 minutes.
 Observed during the run: ~2.9 attempts/sec, far below the ceiling. Row counts could not be
 sampled reliably (see §1) and the run was cut short by Finding 1.
 ---
 ## Finding 5 — exceeding the oplog caps is a graceful degradation, not a failure
 The plan's Task 1 step 7 treats "the shared oplog cannot absorb this write profile" as a hard
 stop requiring the keyed-instances escape hatch. It is much weaker than that.
 `OplogStore.EnforceCapsAsync` (`OplogStore.cs:109-138`) prunes to the ceiling and sets
 `needs_snapshot`; `MaintenanceBackgroundService.cs:57` logs *"Oplog backlog/age caps exceeded:
 pruned to the ceiling and flagged needs_snapshot — the peer must snapshot-resync."*
 `SyncSession.ComputeSnapshotRequiredAsync` (`:413-415`) then forces a snapshot resync.
 So overrunning the caps costs a **full snapshot resync**, not data loss and not a wedged stream.
 The caps therefore express *"how long may a peer be absent before it needs a full resync"*, and
 should be sized to the longest tolerable peer outage rather than treated as a correctness
 boundary. In healthy two-node operation the oplog drains continuously — `localdb_oplog_depth`
 read **0** throughout.
 ### Provisional cap recommendation (Task 19)
 Sized for a ~3-hour peer outage at a conservative 100 rows/sec aggregate, pending re-measurement
 after Finding 1 is fixed:
 ```
 LocalDb:Replication:MaxOplogRows = 1000000   # default; ≈2.8 h at 100 rows/s
 LocalDb:Replication:MaxOplogAge  = 3.00:00:00
 LocalDb:Replication:MaxBatchSize = 16        # Finding 2 — this one is NOT optional
 ```
 Only `MaxBatchSize` is firmly evidence-backed. The other two rest on an assumed aggregate write
 rate that this run could not measure.
 ---
 ## 2. What still owes measurement
 Carry into the re-run once Finding 1 is fixed:
 1. Sustained `sf_messages` rows/sec under a saturating generator (needs many more instances or a
   shorter interval to approach the 50/s ceiling).
 2. Any `native_alarm_state` measurement at all — requires building alarm-source seeding plus an
   A&C-capable server. The `OpcUaAlarmLiveSmokeTests` **passed**, so the rig's opc-plc *does*
   answer ConditionRefresh with a `SnapshotComplete`; the missing piece is ongoing transitions
   and a seeded `TemplateNativeAlarmSource`. (The test's own doc comment claiming the simulator
   "does not reliably expose A&C" is stale.)
 3. A production-representative `config_json` from wonder, to replace the ~60–70 KB inference.
 4. The empirical oplog drain-under-churn check — Task 20 evidence item 10.
 ## 3. Rig state left behind
 - Fully reseeded (central config volume dropped and replayed; site SQLite state wiped by
  `reseed.sh` stage 2).
 - `ExternalSystemDefinitions` id 1 is **repointed to `http://127.0.0.1:9`** — restore to
  `http://scadabridge-restapi:5200` before using the rig for anything else.
 - Template `SoakGenerator` (2021) and instances `soakgen-1..4` (ids 5–8) remain deployed on
  site-a and are **still generating load**. Undeploy or delete them before the Task 20 live gate.
 - `LdapGroupMappings` corrected in the live DB to the canonical role names.