Files
ScadaBridge/docs/plans/2026-07-19-localdb-phase2-soak.md
T
Joseph Doherty 12eb97e07a docs(localdb): close the phase 2 gate — questions answered, plan written
Task 2 of the Phase 2 plan, plus the clean re-run of Task 1's cut-short
sampling that Task 2 was waiting on.

Gate doc: status NOT STARTED -> CLOSED. All five §5 open questions answered
inline. The questions are kept, not deleted — several of the answers overturn
a premise the gate itself stated, and that reasoning is the value:

- Oplog sizing is not the binding constraint. Cap overrun prunes and flags
  needs_snapshot (graceful resync), so the caps need no defensive sizing; the
  real ceiling is D6's 4 MB gRPC cap, binding on MaxBatchSize x row-bytes.
- LWW-vs-in-flight-send cannot arise on a correct pair (only the active node
  sweeps). The honest cost is D2's semantic change: the standby is convergent,
  no longer byte-identical.
- Migration-under-load is designed out, not managed — both mechanisms are
  deleted in the same commit and D5 forecloses rolling upgrades.
- Rollback is genuinely "revert the commit": the migration is additive and
  leaves the legacy files intact. Bounded cost is the post-cutover delta.
- One DB per process stays; every write axis is bounded.

§2's requirement to state CDC's duplicate-delivery bound is routed explicitly
to Task 21 rather than left implicit.

Task 1 re-run (safe copy-based snap(), both nodes restarted first, six 60s
intervals): sf_messages 0.80 rows/sec insert, 0/sec retry-UPDATE, oplog 0,
alarms 0, max payload_json 76 B, zero SQLite errors across 30 min, both site-a
nodes converged at 3564 rows. Independently confirms the disk-I/O storm was
observer-induced. Recorded with its limits stated: 0.80/s is ~1.6% of the 50/s
ceiling and the retry path was never exercised — acceptable only because that
ceiling is structural rather than empirical, and the rig's 721 B config rows
are explicitly NOT representative.

GATE VERDICT: PROCEED to Task 3. Binding output is MaxBatchSize 500 -> 16.

Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
2026-07-20 02:15:53 -04:00

19 KiB
Raw Blame History

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

GATE VERDICT: STOP — do not proceed to Task 3. (superseded — see update)

Not for the reason the plan anticipated. Oplog sizing is fine and D6 is resolved. The soak instead surfaced what looked like 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. See Finding 1.

Update 2026-07-20: Finding 1 is root-caused and is NOT a product defect. The soak's own host-side sqlite3 sampling poisoned both nodes (WAL reset across the virtiofs boundary); the unmodified code sustains the full soak load indefinitely with zero errors — reproduced/refuted on demand, see docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md §0. Finding 1 therefore no longer blocks Task 3. What still stands before proceeding: re-run the cut-short sampling (Findings 4/5 write-rate numbers) using the safe copy-based snap recipe now in the plan, on a rig where both site-a nodes have been restarted since any host-side read.

GATE VERDICT (final, 2026-07-20): PROCEED to Task 3.

The re-run is done — §1b. Safe copy-based sampling, both nodes restarted first, six clean 60-second intervals: 0.80 sf_messages rows/sec sustained, zero SQLite errors across the full window, both nodes converged. No stop condition from any of D1D6 is met. The one binding number Phase 2 must honour is LocalDb:Replication:MaxBatchSize = 16 (Finding 2 / D6), which Task 19 sets.


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 This IS the cause of Finding 1 (root-caused 2026-07-20 — the "ruled out" verdict below did not survive; see the known-issue doc §0). Host↔container POSIX locks don't propagate over virtiofs; a host-side read checkpoints + resets the WAL under the container and permanently poisons its connections. Copy the file triplet and query the copy, 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.
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}:
    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 (688864 connection-refused per 4 min).

Two rig-tooling bugs found and fixed en route

  1. docker/seed-sites.sh seeded stale role namesDesign/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) — root-caused 2026-07-20: observer-induced, not a product defect; see the gate-verdict update and the known-issue doc §0

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:SoakCallsite 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 — wrong: sampling-selection bias; only the LocalDb file was ever host-read

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 — RETRACTED 2026-07-20: the observer was the cause

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. The original run "excluded" it: after node-a was restarted and the load failed over to node-b, node-b began erroring while no host process touched its files, and sampled node-a went to zero once idle.

That exclusion was wrong. The 04:56 sampling had poisoned both nodes' files (both carry the 04:56 main-DB mtime; node-b's WAL was left at 0 bytes) — node-b was silent only because a standby issues ~no LocalDb statements, and erupted on its first post-failover write. Verified 2026-07-20: 10+ min of full soak load on a freshly-reopened node with zero errors, then a single host sqlite3 read reset its 4.6 MiB WAL to 0 bytes and started the error storm one second later (SQLITE_IOERR_SHORT_READ, 522). Full mechanism + minimal repro: docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md §0.

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. Root-caused 2026-07-20: not a Phase 1 defect — observer-induced WAL reset across the virtiofs bind-mount boundary; see the gate-verdict update at the top of this document.


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 6070 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.


1b. Clean re-run (2026-07-20, post-root-cause)

The original sampling was cut short by Finding 1 and was itself the cause of it. Re-run after both site-a nodes were restarted, using the plan's copy-based snap() helper — no host-side sqlite3 ever touched a live file. Six consecutive 60-second intervals, generator load unchanged (SoakGenerator ×4 against a refusing endpoint):

UTC sf_messages rows SUM(retry_count) status=0 __localdb_oplog native_alarm_state
06:07:57 3384 200 3380 0 0
06:08:57 3432 200 3428 0 0
06:09:57 3480 200 3476 0 0
06:10:57 3528 200 3524 0 0
06:11:57 3576 200 3572 0 0
06:12:57 3624 200 3620 0 0
06:13:57 3672 200 3668 0 0

Measured:

  • sf_messages insert rate: exactly 48 rows/min = 0.80 rows/sec, dead steady across all six intervals (+288 rows over 360 s, zero variance).
  • Retry-UPDATE rate: 0/sec. SUM(retry_count) never moved. Only 4 rows ever reached retry_count = 50 (status 2, dead-lettered); the other ~3.6 k sit at retry_count = 0, status 0 — enqueued but never swept. So this generator exercises the insert path only.
  • Row sizes: sf_messages.payload_json max 76 B; deployed_configurations.config_json max 721 B over 4 rows (rig config is trivially small — see the caveat below).
  • native_alarm_state: 0 rows — no alarm generator on this rig, as previously recorded.
  • __localdb_oplog: 0 throughout — the Phase 1 tables are genuinely idle under this load, which is the expected result and not a measurement failure (Phase 2's tables are not yet registered, so this load cannot reach the oplog by construction).
  • Zero SQLite errors in docker logs scadabridge-site-a-a across the full 30-minute window (grep -ciE "disk I/O|SQLITE_IOERR|NOTADB"0). This is the direct confirmation that Finding 1 was observer-induced: identical load, identical library, nothing host-reading the files, no errors.
  • Both site-a nodes converged identically (3564 rows on each at a common sample point) under the bespoke replicator — the pre-cutover baseline Task 20 should reproduce under CDC.

Honest limits of this measurement. 0.80 rows/sec is ~1.6 % of the 50 rows/sec structural ceiling, and the retry path — the expensive one, one UPDATE per message per sweep — was never exercised at all. This re-run therefore confirms steady-state health and the absence of the Finding 1 pathology; it does not probe the ceiling. That is acceptable because the ceiling is structural rather than empirical (Finding 4: SweepBatchLimit ÷ RetryTimerInterval), so sizing does not depend on observing it. Likewise the rig's 721 B config rows are not representative — D6's sizing rests on the documented ~6070 KB production config_json, not on this number.

2. What still owes measurement

Carry forward (items 12 partially discharged by §1b above):

  1. Sustained sf_messages rows/secmeasured (§1b: 0.80/s insert, 0/s retry). Still unmeasured: the retry-UPDATE path under a saturating generator approaching the 50/s ceiling. Not required for sizing (the ceiling is structural), but it is the honest gap.
  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 ~6070 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 58) 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.