dohertj2/ScadaBridge
1
0
Fork 0
Code Issues 2 Pull Requests 1 Actions Packages Projects Releases Wiki Activity

docs(known-issues): root-cause brief for the LocalDb disk-I/O-error-under-load defect

Browse Source 
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
This commit is contained in:
Joseph Doherty
2026-07-20 01:11:08 -04:00
parent 82c869a1df
commit e9e11d635e
1 changed files with 315 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md
+315
View File
@@ -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.<ProcessWriteQueueAsync>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 <TID> --name "SoakCall" \
--trigger-type Interval --trigger-config '{"intervalMs":5000}' \
--code 'var parms = new Dictionary<string, object?> { ["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 <TID> --site-id 1
done
$SB $AUTH instance deploy --id <each instance 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-<active> 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=<path>` (`: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.