From e9e11d635eba93e543ab273e3da30390f596e4da Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 20 Jul 2026 01:11:08 -0400 Subject: [PATCH] docs(known-issues): root-cause brief for the LocalDb disk-I/O-error-under-load defect Standalone handoff for a follow-up investigation. Records the symptom, a full reproduction (including the two rig-tooling blockers and the CachedCall-vs-Call detail needed to generate load at all), the isolation evidence, a code map of the LocalDb connection model, four ranked hypotheses, and acceptance criteria. Not root-caused. Highest-value next step identified: capture the SQLite EXTENDED result code (logs only carry the generic primary code 10), and run the load with LocalDb:Path off the bind mount to partition environmental vs library causes. Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts --- ...-07-20-localdb-disk-io-error-under-load.md | 315 ++++++++++++++++++ 1 file changed, 315 insertions(+) create mode 100644 docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md diff --git a/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md b/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md new file mode 100644 index 00000000..a5ff583a --- /dev/null +++ b/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md @@ -0,0 +1,315 @@ +# LocalDb throws `SQLite Error 10: 'disk I/O error'` on the active site node under sustained write load + +**Date:** 2026-07-20 · **Status:** OPEN — not root-caused · **Severity:** High (silent event loss; blocks LocalDb Phase 2) +**Area:** `ZB.MOM.WW.LocalDb` (library, `~/Desktop/scadaproj/ZB.MOM.WW.LocalDb/`) as consumed by ScadaBridge site nodes +**Found by:** the Phase 2 rig soak — [`docs/plans/2026-07-19-localdb-phase2-soak.md`](../plans/2026-07-19-localdb-phase2-soak.md) +**Branch:** `feat/localdb-phase2` (defect is in Phase 1 code, present on `feat/localdb-phase1`) + +> **This document is a root-cause brief.** The investigation below establishes *what* fails and +> rules out several explanations. It does **not** identify the mechanism. Nothing has been fixed. + +--- + +## 1. Summary + +On a ScadaBridge site node, once the node is **active** and under sustained concurrent write +load, effectively every write to the consolidated LocalDb database (`site-localdb.db`) fails +with: + +``` +Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 10: 'disk I/O error'. +``` + +Observed rate: **~1 000–1 500 failures per minute**, sustained, not transient. The node stays up +and reports healthy. Ordinary (non-LocalDb) SQLite databases in the same directory, in the same +process, under the same load, are completely unaffected. + +## 2. Why it matters + +1. **Silent data loss today.** `SiteEventLogger` fails its inserts and logs + `[ERR] Failed to record event: script from ScriptActor:…`. Site event logging is dropping + events on the floor on the active node whenever the site is busy. `OperationTracking` writes + fail too, which breaks cached-call status tracking (`Cached-telemetry drain: no tracking + snapshot for …; skipping`). +2. **It blocks LocalDb Phase 2.** Phase 2 registers eight further tables into this same + database — including `native_alarm_state` (highest-volume table on the node) and + `sf_messages` — **and deletes the bespoke mechanisms that currently carry that data** + (`SiteReplicationActor`, `StoreAndForward.ReplicationService`) in the same commit. Cutting + over onto this store while removing the fallback would convert a logging defect into config + and buffer loss. +3. Phase 1 was previously live-gated as PASS. That gate exercised correctness and convergence, + **not sustained write load** — which is why this was not caught. + +## 3. Exact symptom + +Two representative stacks, both from `docker logs scadabridge-site-a-b` while that node was +active and under load: + +``` +Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 10: 'disk I/O error'. + at Microsoft.Data.Sqlite.SqliteDataReader.NextResult() + at Microsoft.Data.Sqlite.SqliteCommand.ExecuteReader(CommandBehavior behavior) + at ZB.MOM.WW.ScadaBridge.SiteEventLogging.SiteEventLogger.<>c__DisplayClass15_0.b__0(SqliteConnection connection) + in /src/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs:line 236 + at ZB.MOM.WW.ScadaBridge.SiteEventLogging.SiteEventLogger.ProcessWriteQueueAsync() + in /src/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs:line 221 +``` + +``` +Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 10: 'disk I/O error'. + at Microsoft.Data.Sqlite.SqliteDataReader.NextResult() + at Microsoft.Data.Sqlite.SqliteCommand.ExecuteNonQuery() + at ZB.MOM.WW.ScadaBridge.SiteRuntime.Tracking.OperationTrackingStore.RecordEnqueueAsync(...) + in /src/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Tracking/OperationTrackingStore.cs:line 137 + at ZB.MOM.WW.ScadaBridge.AuditLog.Site.Telemetry.CachedCallTelemetryForwarder.TryEmitTrackingAsync(...) + in /src/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs:line 148 +``` + +Note both fail inside `SqliteDataReader.NextResult()` — i.e. at statement execution, not at +`Open()`. Connections are being acquired successfully; the failure is on the write itself. + +### Error-source distribution + +Error-stack frames counted over one 3-minute window on the loaded node: + +| Store | Backing file | Frames | +|---|---|---| +| `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** | + +## 4. Evidence — what has been established + +### 4.1 It tracks the load, not the node + +The load was moved between the two site-a nodes by restarting the active one (the surviving node +becomes oldest-up and takes over): + +| Node | Role | Under load | `disk I/O error` / 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** | + +### 4.2 It is LocalDb-specific, not the filesystem or the bind mount + +This is the strongest signal. `store-and-forward.db` and `scadabridge.db` live in the **same +bind-mounted directory** (`/app/data`, host `docker/site-a-node-*/data/`), are opened by the +**same process**, are also **WAL-mode**, and are being written **concurrently under the same +load** — and they log zero errors. Only the LocalDb-managed file fails. + +### 4.3 The observer has been ruled out + +Onset (04:56:37) was **one second after** a host-side `sqlite3` read of the bind-mounted +database (04:56:36), making observer-induced `-shm` corruption the leading hypothesis. It is +excluded: + +- After node-a was restarted (fresh open, `-shm` recovered) and load failed over to node-b, + **node-b** — whose files no host process had touched since a single baseline read, and which + had been error-free for the entire preceding period — began erroring immediately at a *higher* + rate. +- **node-a**, whose files *had* been sampled, dropped to zero once it stopped carrying load. + +The variable that tracks the errors is load. (Host-side `sqlite3` against a live WAL database +over a bind mount is still unsafe and should be avoided — it is just not the cause here.) + +### 4.4 Not disk pressure + +Host had 215 GiB free throughout (`df -h`: 76 % used on the data volume). Files are small: +`site-localdb.db` 188 KiB, WAL peaked around 4.1 MiB then checkpointed to 0. + +## 5. Reproduction + +Fully reproducible in ~10 minutes on the local docker rig. + +### 5.1 Rig prerequisites + +Two rig-tooling bugs will block a fresh reseed; both are documented in the soak findings: + +- `docker/seed-sites.sh` role names — **already fixed** (commit `cf46e596`). +- **`infra/mssql/setup.sql` never executes** — still broken. It is mounted into + `/docker-entrypoint-initdb.d/`, which the official `mcr.microsoft.com/mssql/server` image does + not implement. After `infra/reseed.sh` drops the volume, nothing creates `ScadaBridgeConfig` or + the `scadabridge_app` login and `reseed.sh` hangs forever on its setup.sql poll. Work around + by applying the init scripts by hand once MSSQL is accepting connections: + + ```bash + cd ~/Desktop/ScadaBridge/infra + for f in mssql/setup.sql mssql/machinedata_seed.sql mssql/setup-env2.sql; do + docker exec -i scadabridge-mssql /opt/mssql-tools18/bin/sqlcmd \ + -S localhost -U sa -P 'ScadaBridge_Dev1#' -C -b < "$f" + done + ``` + Then restart the app containers so EF migrations run, and restart central again after + `seed-sites.sh` writes `LdapGroupMappings` (they are cached at startup). + +### 5.2 Build the load generator + +**The seeded `Motor Controller` template (id 4) cannot be used** — it fails pre-deployment +validation with 34 errors (30 `ConnectionBinding`, 4 `ScriptCompilation`). Build a minimal one. + +**Critical:** `ExternalSystem.Call` does **not** buffer to store-and-forward in practice. +`ExternalSystem.CachedCall` is the buffering surface. Using `Call` produces HTTP traffic and no +S&F rows, and will not reproduce this. + +```bash +cd ~/Desktop/ScadaBridge +SB=src/ZB.MOM.WW.ScadaBridge.CLI/bin/Debug/net10.0/scadabridge # dotnet build src/...CLI first +AUTH="--url http://localhost:9000 --username multi-role --password password" + +# 1. Point the seeded external system at a refusing address (discard port). +$SB $AUTH external-system update --id 1 --name "Test REST API" \ + --endpoint-url "http://127.0.0.1:9" --auth-type ApiKey --auth-config "scadabridge-test-key-1" + +# 2. Minimal template: no attributes, no compositions, no connection bindings. +$SB $AUTH --format json template create --name "SoakGenerator" # -> note the id + +$SB $AUTH --format json template script add --template-id --name "SoakCall" \ + --trigger-type Interval --trigger-config '{"intervalMs":5000}' \ + --code 'var parms = new Dictionary { ["a"] = 2, ["b"] = 3 }; await ExternalSystem.CachedCall("Test REST API", "Add", parms);' + +# 3. Four instances on site-a (site id 1), then deploy each. +for i in 1 2 3 4; do + $SB $AUTH --format json instance create --name "soakgen-$i" --template-id --site-id 1 +done +$SB $AUTH instance deploy --id +``` + +Note the CLI's `template script update` requires `--name` and `--trigger-type` even when only +changing `--code`. In zsh, do not put the auth flags in an unquoted variable — zsh does not +word-split, so pass them literally or use `${=AUTH}`. + +### 5.3 Observe + +```bash +# Identify the ACTIVE node — it is the one running the ScriptActors. +docker logs --since 4m scadabridge-site-a-a 2>&1 | grep -c "Connection refused" +docker logs --since 4m scadabridge-site-a-b 2>&1 | grep -c "Connection refused" + +# Errors appear on that node within ~2 minutes of load starting. +docker logs --since 4m scadabridge-site-a- 2>&1 | grep -c "disk I/O error" +``` + +Metrics (port 8084 is **not** published, and the `aspnet:10.0` image has **no `curl`**) — use a +sidecar in the container's network namespace: + +```bash +docker run --rm --network container:scadabridge-site-a-a curlimages/curl:latest \ + -s localhost:8084/metrics | grep '^localdb_' +``` + +Do **not** query the databases with host-side `sqlite3` while containers are writing them. + +## 6. Code map + +### Library — `~/Desktop/scadaproj/ZB.MOM.WW.LocalDb/src/ZB.MOM.WW.LocalDb/Internal/SqliteLocalDb.cs` + +Facts relevant to the failure: + +- **A `_master` connection is held open for the object's entire lifetime** (`:31`), explicitly to + "anchor the WAL journal". It is guarded by a `Lock _masterLock` because `SqliteConnection` is + not thread-safe. +- **`CreateConnection()` (`:83`) opens a brand-new `SqliteConnection` per call** — one per + operation, from many concurrent actors. Every call then runs + `PRAGMA synchronous=…; PRAGMA busy_timeout=…; PRAGMA foreign_keys=ON;` and registers a UDF: + ```csharp + conn.CreateFunction("zb_hlc_next", () => _clock.Next()); + ``` +- The connection string is **only** `DataSource=` (`:57`) — **connection pooling is left at + the Microsoft.Data.Sqlite default (enabled)**, and no `Cache=` or `Mode=` is set. +- Effective options on the rig are the defaults: `BusyTimeoutMs = 5000`, `Synchronous = NORMAL`. + ScadaBridge's rig config (`docker/site-a-node-*/appsettings.Site.json`, `LocalDb` section) sets + only `Path` and the replication block. +- `zb_hlc_next()` is invoked **from inside the capture triggers**, i.e. on the SQLite thread + during every INSERT/UPDATE/DELETE on a registered table, and it calls into the shared + `HybridLogicalClock` from arbitrary threads. + +### Failing call sites (ScadaBridge) + +- `src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs:221,236` — a channel-drained + single-writer loop (`ProcessWriteQueueAsync`) using a `WithConnection(...)` helper. +- `src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Tracking/OperationTrackingStore.cs:137` (`RecordEnqueueAsync`), + `:260,266` (`GetStatusAsync`). +- `src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs:148`. +- `src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs` — also see §8. + +## 7. Hypotheses, ranked + +None verified. Ordered by how well they fit "LocalDb only, load-dependent, same directory as +healthy WAL databases". + +1. **Connection churn × pooling × per-connection UDF registration.** LocalDb opens a fresh + `SqliteConnection` per operation with pooling enabled, and calls `CreateFunction` on every + acquisition. Under high concurrency this drives far more open/close and `-shm` mapping churn + than the legacy stores (which reuse a small number of connections), and is the clearest + structural difference between the failing and healthy databases. Suspect the interaction of + the pool with the long-lived `_master` connection and WAL index growth. +2. **`-shm` / WAL-index growth over the bind mount, triggered only at LocalDb's concurrency.** + Would explain why the same mount is fine for lower-concurrency databases. `mmap` of the shared + WAL index across virtiofs is a known-fragile area. **Distinguishing test: run the same load + with `LocalDb:Path` pointed at a container-local path (a `tmpfs` or a plain volume rather than + the bind mount).** If the errors vanish, this is confirmed and the fix is environmental / + deployment-shaped rather than a library bug. **Run this test first — it is cheap and it + partitions the hypothesis space.** +3. **`zb_hlc_next` UDF failing inside a trigger.** An exception thrown out of the managed UDF + callback during trigger execution can surface as a generic SQLite error at the statement + level. Check `HybridLogicalClock.Next()` for thread-safety and for anything that can throw + under contention (e.g. a spin/overflow path when many callers request stamps in the same + millisecond). +4. **Busy-timeout exhaustion misreported.** `BusyTimeoutMs = 5000` with heavy multi-connection + write contention on one file. This would normally surface as `SQLITE_BUSY` (5), not + `SQLITE_IOERR` (10), so it is a weaker fit — but worth excluding. + +### The single highest-value next step + +**Capture the extended result code.** The logs only show the primary code (`10` = `SQLITE_IOERR`), +which is generic. `SqliteException.SqliteExtendedErrorCode` names the failing syscall and would +likely settle this outright: + +| Extended code | Meaning | Points at | +|---|---|---| +| `SQLITE_IOERR_SHMMAP` (6154) / `SQLITE_IOERR_SHMSIZE` (4874) | WAL index mmap/resize failed | hypothesis 2 | +| `SQLITE_IOERR_WRITE` (778) / `SQLITE_IOERR_FSYNC` (1034) | plain write/fsync failed | filesystem | +| `SQLITE_IOERR_LOCK` (3850) | file locking failed | bind mount locking | + +Add the extended code to the exception logging (or attach a debugger / run the repro against a +local non-container build) before pursuing any fix. + +## 8. Secondary defect in the same path + +``` +[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 touching `Context` (or `Self`/`Sender`) after an `await`. This is a +real bug independent of the I/O errors, though it sits in the same write path and may be +contributing. Note the family-wide rule already recorded for Akka work: never read `Self`/`Context` +after an `await` inside an actor. + +## 9. What a fix must satisfy + +1. The §5 repro runs for **30 minutes under sustained load with zero `disk I/O error`** on the + active node. +2. No `Failed to record event` errors — site events are durably written under load. +3. `localdb_oplog_depth` rises under load and **drains** between bursts; zero dead letters. +4. Replication still converges across the site-a pair (Phase 1's existing convergence suite and + live gate still pass). +5. A regression test that would have caught this — i.e. a **concurrent-write load test** against + a real LocalDb file, not just the correctness/convergence tests Phase 1 shipped. Phase 1's + gate passed precisely because no test applied sustained concurrent write pressure. + +## 10. Rig state as left + +- Rig fully reseeded; central config volume dropped and replayed; site SQLite state wiped + (`reseed.sh` stage 2 does `rm -rf docker/site-*/data/*`). +- `ExternalSystemDefinitions` id 1 is **still repointed to `http://127.0.0.1:9`** — restore to + `http://scadabridge-restapi:5200` when done. +- Template `SoakGenerator` (id 2021) and instances `soakgen-1..4` (ids 5–8) are **still deployed + and still generating load** on site-a. +- `LdapGroupMappings` corrected in the live DB to the canonical `Designer`/`Deployer` names.