8652eab98e
The Phase 2 soak's "LocalDb fails under load" blocker is NOT a product defect. Root cause: host-side (macOS) sqlite3 reads of the live, bind-mounted WAL databases. POSIX advisory locks do not propagate across the virtiofs boundary, so the host reader believes it is the only connection, checkpoints on close and resets the WAL to 0 bytes under the container. The container's still-mapped WAL index then references frames that no longer exist and every subsequent statement fails SQLITE_IOERR_SHORT_READ (522) -> primary code 10, permanently until the process reopens the database. Reproduced on demand both on the rig (one sqlite3 SELECT reset a 4.6 MiB WAL and produced the first error one second later) and in a minimal python:3.12-alpine repro with no LocalDb or .NET involved. Refuted the converse: a freshly-reopened node sustained the full soak load 10+ minutes with zero errors. The original brief's isolation was confounded - both nodes had been poisoned by the same sampling pass, and a poisoned standby looks healthy only because it issues almost no statements. Corrections annotated in place. Hardening shipped alongside: - SqliteErrorCodes.Describe: log SQLite primary AND extended codes at the LocalDb-adjacent catch sites (the missing extended code is what made the original diagnosis so slow). - SiteAuditTelemetryActor: stop touching ActorContext across an await (NotSupportedException), with regression coverage. - infra/reseed.sh: apply the MSSQL init scripts explicitly. The official mssql/server image does not implement /docker-entrypoint-initdb.d, so a fresh volume hung the reseed forever; compose mounts annotated as informational. Deliberately NOT done: detect-and-reopen self-heal in SqliteLocalDb. It defends only against external interference, which is now prevented at the source, and same-kernel production readers see the locks correctly. Build 0 warnings; SiteAuditTelemetryActorTests 9/9, SiteEventLogging 70/70. Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
476 lines
28 KiB
Markdown
476 lines
28 KiB
Markdown
# LocalDb throws `SQLite Error 10: 'disk I/O error'` on the active site node under sustained write load
|
||
|
||
**Date:** 2026-07-20 · **Status:** ROOT-CAUSED + FIX PASS COMPLETE 2026-07-20 (same day) — observer-induced, **not a LocalDb defect**; see §0 (cause) and §11a (fixes) · **Severity:** was High; resolved to an operational rule (now enforced in the tooling docs) + shipped hardening
|
||
**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` (symptom observed on Phase 1 code)
|
||
|
||
> **Update 2026-07-20:** the mechanism has been identified and reproduced on demand, both in a
|
||
> minimal SQLite-only repro and on the live rig, and the follow-up fixes have shipped.
|
||
> Sections §0, §11a and §11 below are authoritative; the original brief (§1–§10) is preserved
|
||
> as written, with corrections annotated where its conclusions did not survive
|
||
> (§4.2, §4.3, §7, §9) and fix notes where they did (§5.1, §8).
|
||
|
||
---
|
||
|
||
## 0. ROOT CAUSE (verified)
|
||
|
||
**A host-side (macOS) `sqlite3` read of a live, bind-mounted WAL database checkpoints and
|
||
resets the WAL out from under the container process, permanently poisoning that process's
|
||
connections.** LocalDb, its connection handling, its UDF, and its triggers are not involved —
|
||
the mechanism reproduces with plain Python `sqlite3` and no LocalDb code at all.
|
||
|
||
Mechanism, step by step:
|
||
|
||
1. POSIX advisory locks do **not** propagate across the Docker Desktop virtiofs bind-mount
|
||
boundary. A host `sqlite3` opening the database cannot see the container's locks (and vice
|
||
versa), so it believes it is the **only** connection.
|
||
2. On close, the "last" connection in WAL mode runs a full checkpoint and **resets the WAL to
|
||
0 bytes**. Because the read happened while the container was idle (a standby node, or a gap
|
||
between write bursts), nothing blocks the checkpoint. This is exactly the file signature
|
||
found on both rig nodes: main DB mtime + 0-byte `-wal` stamped at the sampling minute.
|
||
3. The container process still holds the old WAL-index state (its per-inode `-shm` mapping,
|
||
kept alive forever by the held-open `_master` connection and the Microsoft.Data.Sqlite
|
||
connection pool). That index says the WAL contains N frames; the file now has none. Every
|
||
subsequent statement — reads and writes both consult the WAL index — fails with
|
||
**`SQLITE_IOERR_SHORT_READ` (extended code 522)**, surfaced as primary code 10
|
||
`'disk I/O error'` (some paths surface `SQLITE_NOTADB` (26) instead). The poisoning is
|
||
**permanent until the process reopens the database** (restart).
|
||
|
||
### Why the original brief's conclusions were wrong
|
||
|
||
- **"It tracks the load, not the node" (§4.1)** — confounded. *Both* nodes were poisoned by
|
||
the 04:56 UTC host-side sampling (both nodes' `site-localdb.db` main files carry the 04:56
|
||
mtime; node-b's WAL was left at 0 bytes). A poisoned **standby** shows zero errors only
|
||
because a standby issues ~zero LocalDb statements; the errors "followed the load" because
|
||
the load is what generates statements against an already-poisoned handle. Node-b's very
|
||
first write attempt after failover (04:59:37, `OperationTrackingStore.RecordAttemptAsync`)
|
||
failed — it had been poisoned for 3 minutes with nothing to say about it.
|
||
- **"It is LocalDb-specific" (§4.2)** — sampling-selection bias. The legacy WAL databases in
|
||
the same directory were healthy only because no host process ever read *them*. The minimal
|
||
repro poisons an arbitrary WAL database the same way.
|
||
- **"The observer has been ruled out" (§4.3)** — the exclusion assumed an error-free standby
|
||
was an unpoisoned standby. It wasn't; it was a poisoned node with no traffic.
|
||
|
||
### Verification (2026-07-20, all on the live rig + minimal repro)
|
||
|
||
1. **Load alone is harmless:** restarted the poisoned active node (site-a-b); freshly-reopened
|
||
site-a-a took the full soak load for **10+ minutes with zero errors** (the original model
|
||
predicted onset within ~2 min), WAL growing/checkpointing normally, DB 188 KiB → 476 KiB.
|
||
2. **One host read is sufficient and immediate:** a single
|
||
`sqlite3 docker/site-a-node-a/data/site-localdb.db "SELECT count(*) FROM site_events;"`
|
||
against the healthy loaded node reset its 4.6 MiB WAL to 0 bytes in place and produced the
|
||
first `disk I/O error` **one second later** (05:32:48 → 05:32:49), 203 errors in the next
|
||
40 s — the same one-second onset correlation as the original 04:56:36 → 04:56:37 incident.
|
||
3. **Minimal repro (no LocalDb, no .NET):** a `python:3.12-alpine` container writing a
|
||
WAL-mode SQLite DB on a bind mount (held master connection + fresh connection per op,
|
||
`synchronous=NORMAL`, `busy_timeout=5000`). A host `sqlite3 "SELECT count(*)"`:
|
||
- against the **actively-writing** DB → immediate `SQLITE_IOERR_SHORT_READ` (522) +
|
||
`SQLITE_NOTADB` burst, then recovery (checkpoint could not fully reset a hot WAL);
|
||
- during an **idle window** (connections held open, WAL populated) → WAL reset
|
||
1.2 MiB → 0 bytes, then **every fresh-connection write failed for the rest of the run
|
||
(200/200)** — the persistent variant, matching the rig.
|
||
|
||
### Consequences
|
||
|
||
1. **The operational rule in §5.3 ("do not query the databases with host-side `sqlite3`") is
|
||
the root cause, not a hygiene note.** One violation silently destroys the node's local
|
||
persistence until restart. This applies to *every* WAL SQLite file on the bind mount
|
||
(`scadabridge.db`, `store-and-forward.db` included), not just LocalDb.
|
||
2. **Safe inspection recipes:** copy the file triplet (`.db`, `-wal`, `-shm`) and open the
|
||
copy; or read from inside the container boundary (same kernel ⇒ locks visible), e.g.
|
||
`docker run --rm -v <dir>:/d alpine/sqlite3 sqlite3 /d/site-localdb.db "..."` — never the
|
||
macOS host against live files.
|
||
3. **LocalDb Phase 2 is unblocked** on this issue: the library sustained the full soak write
|
||
load indefinitely once nothing external touched its file.
|
||
4. Hardening follow-ups — **status as of the 2026-07-20 fix pass (see §11a):**
|
||
- **DONE — extended-code logging:** the LocalDb-adjacent catch sites (`SiteAuditTelemetryActor`,
|
||
`CachedCallTelemetryForwarder`, `SiteEventLogger`) now log
|
||
`SqliteException` primary/extended codes (`sqlite 10/522`-style) via
|
||
`SqliteErrorCodes.Describe` / `DescribeSqliteError`.
|
||
- **DONE — §8 async-context bug** (see §8).
|
||
- **DONE — §9.5 load regression test** (see §9).
|
||
- **NOT DONE (deliberately):** a detect-and-reopen self-heal in `SqliteLocalDb` for
|
||
persistent `SQLITE_IOERR`/`SQLITE_NOTADB`. This is a real library design change
|
||
(pool clear + master reopen + in-flight coordination) protecting against *external
|
||
interference only* — the trigger is operator/tooling action, now prevented at the
|
||
source, and on same-kernel production deployments external readers see the locks and
|
||
are safe. File as its own issue if production ever runs where a foreign-kernel reader
|
||
can touch the files.
|
||
|
||
---
|
||
|
||
> **Original brief follows, preserved as written on 2026-07-20 before root-causing.**
|
||
|
||
---
|
||
|
||
## 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 — **WRONG, see §0**
|
||
|
||
> **Correction 2026-07-20:** sampling-selection bias — only the LocalDb file was ever read
|
||
> from the host. Any of these WAL databases is equally poisonable (minimal-repro-proven).
|
||
|
||
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 — **WRONG, see §0: the observer was the cause**
|
||
|
||
> **Correction 2026-07-20:** the exclusion below assumed an error-free standby was an
|
||
> unpoisoned standby. Node-b's files carry the 04:56 sampling-time mtimes (WAL left at
|
||
> 0 bytes); it was poisoned then and merely silent until failover gave it write traffic.
|
||
|
||
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** — **FIXED 2026-07-20**: `infra/reseed.sh` now
|
||
applies the three init scripts itself via `sqlcmd` once MSSQL accepts connections (the
|
||
`/docker-entrypoint-initdb.d/` compose mounts are informational only — the official
|
||
`mcr.microsoft.com/mssql/server` image does not implement that hook; noted in the compose
|
||
file). The manual workaround below is retained for historical context / older checkouts.
|
||
Original problem: after `infra/reseed.sh` dropped the volume, nothing created
|
||
`ScadaBridgeConfig` or the `scadabridge_app` login and `reseed.sh` hung forever on its
|
||
setup.sql poll. The by-hand equivalent:
|
||
|
||
```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
|
||
|
||
> **Resolution 2026-07-20:** none of the four below is the cause. The mechanism is a variant
|
||
> of #2's territory (bind-mount `-shm`/WAL fragility) but triggered *only* by a host-side
|
||
> reader — LocalDb's concurrency, pooling, and UDF (hypotheses 1/3/4) are exonerated. The
|
||
> extended code, since captured, is `SQLITE_IOERR_SHORT_READ` (522).
|
||
|
||
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 — **FIXED 2026-07-20**
|
||
|
||
```
|
||
[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.
|
||
|
||
> **Fixed 2026-07-20.** Root cause: both drain handlers await with `ConfigureAwait(false)`, so
|
||
> their `finally`-block re-arm (`ScheduleNext`/`ScheduleNextCached`) runs on a pool thread with
|
||
> no active ActorContext. Investigation found the failure is **bimodal**, and the second mode is
|
||
> worse than the logged one: depending on what the pool thread's thread-static cell slot holds,
|
||
> `Context`/`Self` either **throw** `NotSupportedException` (the logged variant — actor crashes
|
||
> and restarts once per drain) or **silently resolve a STALE cell of whatever actor last ran on
|
||
> that thread**, re-arming the tick at the *wrong actor* so the drain loop just stops (observed
|
||
> under TestKit: the tick landed on the TestActor). Fix: capture `Context.System.Scheduler` and
|
||
> `Self` into fields at construction (both are thread-safe immutable handles) and use only those
|
||
> from the re-arm path. Regression test
|
||
> `SiteAuditTelemetryActorTests.Drains_Whose_Awaits_Complete_Off_The_Actor_Thread_Keep_Draining_Without_Crashing`
|
||
> forces the mock awaits to complete off the actor thread — which every pre-existing test
|
||
> avoided by returning already-completed tasks — and catches **both** variants (EventFilter for
|
||
> the throw, sustained-drain counts for the silent stall). AuditLog suite 355/355 green.
|
||
|
||
## 9. What a fix must satisfy
|
||
|
||
> **Resolution 2026-07-20:** criteria 1–4 are already satisfied by the unmodified code once no
|
||
> host process touches the live files — verified 10+ min of soak load with zero errors, events
|
||
> durably written, WAL checkpointing normally. Criterion 5 (a sustained concurrent-write load
|
||
> test) would **not** have caught this — the trigger is an external reader, not load — but is
|
||
> now in place anyway: `ConcurrentWriteLoadTests` in `ZB.MOM.WW.LocalDb.Tests` (8 concurrent
|
||
> writers × 250 inserts through fresh pooled connections against a registered/triggered table on
|
||
> a real file, with concurrent readers; asserts zero failures + exact row/oplog counts; suite
|
||
> 145/145). §8's `SiteAuditTelemetryActor` async-context bug is **fixed** — see §8.
|
||
|
||
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.
|
||
|
||
## 11a. Fix pass (2026-07-20, same day — all verified)
|
||
|
||
Everything actionable that this incident identified is now fixed (uncommitted on each repo's
|
||
current branch; ScadaBridge full solution builds clean, 0 warnings):
|
||
|
||
| # | Issue | Fix | Verification |
|
||
|---|---|---|---|
|
||
| 1 | §8 `SiteAuditTelemetryActor` async-context bug (bimodal: crash-per-drain OR silent tick misroute) | Capture `Context.System.Scheduler` + `Self` at construction; re-arm path never reads thread-static context | New red→green regression test forcing off-actor-thread continuations; AuditLog suite 355/355 |
|
||
| 2 | Diagnostics gap: logs carried only the primary SQLite code | `SqliteErrorCodes.Describe` (AuditLog) + `DescribeSqliteError` (SiteEventLogging) — catch sites now log `sqlite <primary>/<extended>` | Builds clean; suites green (this gap cost the investigation a from-scratch repro to learn code 522) |
|
||
| 3 | §5.1 `reseed.sh` hangs forever waiting on the initdb hook the mssql image doesn't have | `reseed.sh` applies `setup.sql`/`machinedata_seed.sql`/`setup-env2.sql` itself via `sqlcmd`; compose mounts annotated as informational | `bash -n` clean; scripts verified idempotent (`IF NOT EXISTS` guards) |
|
||
| 4 | §9.5 missing concurrent-write load test | `ConcurrentWriteLoadTests` in `ZB.MOM.WW.LocalDb.Tests` (scadaproj) — 8 writers × 250 pooled-connection inserts on a registered table + concurrent readers, exact row/oplog count asserts | LocalDb suite 145/145 |
|
||
| 5 | Root cause itself (operator/tooling host reads) | Poisonous instructions removed from the Phase 2 plan + `.tasks.json` (safe `snap()` copy-based sampling); soak-doc verdict corrected; family-wide memory rule recorded | On-demand on/off reproduction, §0 |
|
||
|
||
Deliberately **not** done: the `SqliteLocalDb` detect-and-reopen self-heal (see §0
|
||
consequence 4 for the rationale and the condition under which to file it).
|
||
|
||
## 11. Rig state after root-causing (2026-07-20 ~05:40 UTC)
|
||
|
||
- Both site-a nodes restarted during verification, curing both poisonings. End state:
|
||
**site-a-b active** carrying the soak load, site-a-a standby, **zero `disk I/O error` on
|
||
both** under sustained load.
|
||
- The §10 items still stand: `ExternalSystemDefinitions` id 1 still points at
|
||
`http://127.0.0.1:9`, and `SoakGenerator` + `soakgen-1..4` are still deployed and
|
||
generating load — the Phase 2 soak can now proceed on a clean baseline.
|
||
- Minimal-repro scripts (`writer.py` burst variant, `writer2.py` idle-window variant) lived in
|
||
the session scratchpad; the recipe is fully described in §0 and takes ~2 minutes to rebuild.
|