fix(localdb): root-cause the soak disk-I/O failure + ship the hardening follow-ups
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
This commit is contained in:
Joseph Doherty
@@ -1,12 +1,106 @@
|
||||
# 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)
|
||||
**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` (defect is in Phase 1 code, present on `feat/localdb-phase1`)
|
||||
**Branch:** `feat/localdb-phase2` (symptom observed on Phase 1 code)
|
||||
|
||||
> **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.
|
||||
> **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.**
|
||||
|
||||
---
|
||||
|
||||
@@ -95,14 +189,21 @@ becomes oldest-up and takes over):
|
||||
| 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
|
||||
### 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
|
||||
### 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
|
||||
@@ -131,11 +232,14 @@ Fully reproducible in ~10 minutes on the local docker rig.
|
||||
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:
|
||||
- **`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
|
||||
@@ -239,6 +343,11 @@ Facts relevant to the failure:
|
||||
|
||||
## 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".
|
||||
|
||||
@@ -279,7 +388,7 @@ likely settle this outright:
|
||||
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
|
||||
## 8. Secondary defect in the same path — **FIXED 2026-07-20**
|
||||
|
||||
```
|
||||
[ERROR][akka://scadabridge/user/site-audit-telemetry] There is no active ActorContext,
|
||||
@@ -292,8 +401,32 @@ real bug independent of the I/O errors, though it sits in the same write path an
|
||||
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.
|
||||
@@ -313,3 +446,30 @@ after an `await` inside an actor.
|
||||
- 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.
|
||||
|
||||
@@ -203,8 +203,23 @@ This is the gate item from `2026-07-19-localdb-phase2-gate.md` §5. It is measur
|
||||
> the oplog sizing arithmetically, and (b) that the Phase 1 oplog stays healthy alongside. The
|
||||
> *empirical* post-cutover drain check lives in Task 20 (evidence item 10).
|
||||
>
|
||||
> Also: the containers have **no `sqlite3` binary** (bare `aspnet:10.0` image), but the data dirs
|
||||
> are **host bind mounts** — run `sqlite3` on the host against `docker/site-a-node-*/data/`.
|
||||
> Also: the containers have **no `sqlite3` binary** (bare `aspnet:10.0` image), and the data dirs
|
||||
> are host bind mounts — but **NEVER run `sqlite3` on the macOS host against the live files**:
|
||||
> host↔container POSIX locks do not propagate across the virtiofs boundary, and a single host-side
|
||||
> read checkpoints + resets the WAL out from under the container, permanently poisoning its
|
||||
> connections (`SQLITE_IOERR_SHORT_READ` → `disk I/O error` storm until restart). This is the
|
||||
> **root cause of the 2026-07-20 "disk I/O error under load" incident** — see
|
||||
> [`docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md`](../known-issues/2026-07-20-localdb-disk-io-error-under-load.md) §0.
|
||||
> Safe sampling: copy the file triplet first (`cp x.db x.db-wal x.db-shm /tmp/…` — plain `cp`
|
||||
> takes no SQLite locks and cannot harm the live DB), then query the copy. The helper used below:
|
||||
>
|
||||
> ```bash
|
||||
> snap() { # snap <node-dir> <db> "<sql>" — query a throwaway copy, never the live file
|
||||
> local d; d=$(mktemp -d)
|
||||
> cp "$1/$2" "$d/" && cp "$1/$2-wal" "$1/$2-shm" "$d/" 2>/dev/null
|
||||
> sqlite3 "$d/$2" "$3"; rm -rf "$d"
|
||||
> }
|
||||
> ```
|
||||
> Metrics are on port **8084** inside the container (not published to the host).
|
||||
|
||||
**Step 1: Bring up the rig with Phase 1 replication enabled**
|
||||
@@ -224,14 +239,14 @@ Expected: `localdb_*` series present (`localdb_oplog_depth`, `localdb_sync_*`
|
||||
`ZB.MOM.WW.LocalDb.Replication`). If absent, the meter allowlist regressed — see
|
||||
`SiteServiceRegistration.ObservedMeters`.
|
||||
|
||||
**Step 2: Capture baselines (host-side, against the bind mounts)**
|
||||
**Step 2: Capture baselines (from throwaway copies — never the live files, see the `snap` helper above)**
|
||||
|
||||
```bash
|
||||
cd ~/Desktop/ScadaBridge/docker
|
||||
sqlite3 site-a-node-a/data/site-localdb.db "SELECT COUNT(*) FROM __localdb_oplog;"
|
||||
sqlite3 site-a-node-a/data/store-and-forward.db \
|
||||
snap site-a-node-a/data site-localdb.db "SELECT COUNT(*) FROM __localdb_oplog;"
|
||||
snap site-a-node-a/data store-and-forward.db \
|
||||
"SELECT COUNT(*), COALESCE(SUM(retry_count),0) FROM sf_messages;"
|
||||
sqlite3 site-a-node-a/data/scadabridge.db "SELECT COUNT(*) FROM native_alarm_state;"
|
||||
snap site-a-node-a/data scadabridge.db "SELECT COUNT(*) FROM native_alarm_state;"
|
||||
```
|
||||
|
||||
Record all values and the wall-clock time. (`COUNT + SUM(retry_count)` is the S&F row-write
|
||||
@@ -253,11 +268,11 @@ Two generators, run concurrently:
|
||||
cd ~/Desktop/ScadaBridge/docker
|
||||
for i in $(seq 1 6); do
|
||||
echo "=== t+$((i*5))m ==="
|
||||
sqlite3 site-a-node-a/data/store-and-forward.db \
|
||||
snap site-a-node-a/data store-and-forward.db \
|
||||
"SELECT COUNT(*), COALESCE(SUM(retry_count),0) FROM sf_messages;"
|
||||
sqlite3 site-a-node-a/data/scadabridge.db \
|
||||
snap site-a-node-a/data scadabridge.db \
|
||||
"SELECT COUNT(*), COUNT(CASE WHEN last_transition_at > datetime('now','-5 minutes') THEN 1 END) FROM native_alarm_state;"
|
||||
sqlite3 site-a-node-a/data/site-localdb.db "SELECT COUNT(*) FROM __localdb_oplog;"
|
||||
snap site-a-node-a/data site-localdb.db "SELECT COUNT(*) FROM __localdb_oplog;"
|
||||
docker exec scadabridge-site-a-a curl -s localhost:8084/metrics \
|
||||
| grep -E '^localdb_(oplog_depth|sync)'
|
||||
sleep 300
|
||||
@@ -271,7 +286,7 @@ upserts — say so in the findings if alarm volume is near a threshold).
|
||||
**Step 5: Measure `config_json` sizes (D6)**
|
||||
|
||||
```bash
|
||||
sqlite3 site-a-node-a/data/scadabridge.db \
|
||||
snap site-a-node-a/data scadabridge.db \
|
||||
"SELECT COUNT(*), MAX(LENGTH(config_json)), AVG(LENGTH(config_json)) FROM deployed_configurations;"
|
||||
```
|
||||
|
||||
|
||||
@@ -16,7 +16,7 @@
|
||||
},
|
||||
"reviewPass": {
|
||||
"date": "2026-07-19",
|
||||
"note": "Plan verified against actual code (3 verification sweeps + LocalDb library source) and corrected in place. Headline corrections: D1 (StoreDeployedConfigIfNewerAsync has a SECOND surviving caller, SiteReconciliationActor.cs:166 - the method and guard STAY; original Task 13 would also not have compiled, deleting a method whose caller dies only in Task 15), D3 (the active node ALREADY purges at DeploymentManagerActor.cs:1921 - Task 12 became a pin test, nothing is re-homed), D6 added (4 MB gRPC receive cap x row-count-only MaxBatchSize batching; config_json > 128 KB documented - measure in Task 1, size MaxBatchSize in Task 19, single row near 4 MB = stop/lib work), Task 1 rewritten (Phase 2 tables are NOT registered on the Phase 1 rig so driven churn never reaches __localdb_oplog - measure legacy-DB write rates + arithmetic; metrics port 8084 not 8080; real metric names are localdb_oplog_depth / localdb_sync_*, the plan's localdb_oplog_backlog/replication_dead_letters/sync_connected never existed; containers have no sqlite3 - use host-side sqlite3 on the bind mounts; branch already exists, no checkout -b), Task 14 (register 8 tables NOT 11 - notification_lists/smtp_configurations deliberately unregistered, reversing the original instruction; keep Migrate LAST in OnReady)."
|
||||
"note": "Plan verified against actual code (3 verification sweeps + LocalDb library source) and corrected in place. Headline corrections: D1 (StoreDeployedConfigIfNewerAsync has a SECOND surviving caller, SiteReconciliationActor.cs:166 - the method and guard STAY; original Task 13 would also not have compiled, deleting a method whose caller dies only in Task 15), D3 (the active node ALREADY purges at DeploymentManagerActor.cs:1921 - Task 12 became a pin test, nothing is re-homed), D6 added (4 MB gRPC receive cap x row-count-only MaxBatchSize batching; config_json > 128 KB documented - measure in Task 1, size MaxBatchSize in Task 19, single row near 4 MB = stop/lib work), Task 1 rewritten (Phase 2 tables are NOT registered on the Phase 1 rig so driven churn never reaches __localdb_oplog - measure legacy-DB write rates + arithmetic; metrics port 8084 not 8080; real metric names are localdb_oplog_depth / localdb_sync_*, the plan's localdb_oplog_backlog/replication_dead_letters/sync_connected never existed; containers have no sqlite3 - sample via throwaway copies of the DB triplet, NEVER host-side sqlite3 against the live files [2026-07-20: that poisons the container's WAL state - see docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md]; branch already exists, no checkout -b), Task 14 (register 8 tables NOT 11 - notification_lists/smtp_configurations deliberately unregistered, reversing the original instruction; keep Migrate LAST in OnReady)."
|
||||
},
|
||||
"decisions": [
|
||||
{
|
||||
@@ -64,7 +64,7 @@
|
||||
"StoreAndForwardService: :39 is the _replication FIELD, :243 the ctor param; exactly 6 emission sites (:654,805,836,872,1120,1146). ServiceCollectionExtensions.cs:32 also resolves ReplicationService inside the StoreAndForwardService factory - must go in Task 14.",
|
||||
"ReplicationMessages.cs holds ONLY the 10 Replicate*/Apply* records; the four SfBuffer resync records live at the bottom of SiteReplicationActor.cs (:678-707) and die with the actor file.",
|
||||
"10 (not 9) appsettings.Site.json files set the legacy paths - deploy/wonder-app-vd03/appsettings.Site.json was missed (also sets ReplicationEnabled:false).",
|
||||
"Rig facts: site metrics on port 8084 (AnyIP in-container, NOT published to host; 8080 is Traefik); real metric names localdb_oplog_depth / localdb_sync_* (meter ZB.MOM.WW.LocalDb.Replication); containers (aspnet:10.0) have NO sqlite3 - data dirs are host bind mounts, run sqlite3 host-side; ReplicationOptions bind at LocalDb:Replication:* (lib binds the section).",
|
||||
"Rig facts: site metrics on port 8084 (AnyIP in-container, NOT published to host; 8080 is Traefik); real metric names localdb_oplog_depth / localdb_sync_* (meter ZB.MOM.WW.LocalDb.Replication); containers (aspnet:10.0) have NO sqlite3 - data dirs are host bind mounts but NEVER run sqlite3 host-side against the live files (poisons the container's WAL state, root cause of the 2026-07-20 disk-I/O-error incident): cp the .db/-wal/-shm triplet and query the copy (see the snap() helper in the plan); ReplicationOptions bind at LocalDb:Replication:* (lib binds the section).",
|
||||
"Phase 1's LocalDbSitePairConvergenceTests uses ONE shared API key (:47) - it never did a mismatched-key non-vacuity run; wrong-key denial is unit-covered in Host.Tests/LocalDbSyncAuthInterceptorTests.cs. Task 18's non-vacuity check must be done directly for the new scenarios.",
|
||||
"MigrateEvents synthesizes deterministic 'mig-{node}-{legacyId}' ids (NOT fresh GUIDs - crash-rerun idempotency). Migration runs AFTER RegisterReplicated in OnReady (order is load-bearing); Task 8's oplog pin test must register sf_messages on its own TestLocalDb since production doesn't register it until Task 14."
|
||||
],
|
||||
@@ -88,7 +88,7 @@
|
||||
{"id": 17, "subject": "Task 17: Config-key cleanup (incl. ConfigFetchRetryCount; 10 appsettings files)", "status": "pending", "classification": "standard", "blockedBy": [16]},
|
||||
{"id": 18, "subject": "Task 18: Two-node convergence suite for the Phase 2 tables", "status": "pending", "classification": "high-risk", "blockedBy": [17], "note": "Non-vacuity must be proven directly (Phase 1 never did the mismatched-key run the original plan claimed)."},
|
||||
{"id": 19, "subject": "Task 19: Rig configuration (MaxOplogRows/MaxOplogAge + MaxBatchSize per D6)", "status": "pending", "classification": "small", "blockedBy": [17]},
|
||||
{"id": 20, "subject": "Task 20: Live gate on the docker rig (10 evidence items)", "status": "pending", "classification": "high-risk", "blockedBy": [18, 19], "note": "Includes the post-cutover oplog drain-under-churn check (evidence 10) that Task 1 cannot measure pre-cutover. Host-side sqlite3 on bind mounts; metrics on :8084 in-container."},
|
||||
{"id": 20, "subject": "Task 20: Live gate on the docker rig (10 evidence items)", "status": "pending", "classification": "high-risk", "blockedBy": [18, 19], "note": "Includes the post-cutover oplog drain-under-churn check (evidence 10) that Task 1 cannot measure pre-cutover. Sample DBs via throwaway copies (snap() helper), never host-side sqlite3 on live files; metrics on :8084 in-container."},
|
||||
{"id": 21, "subject": "Task 21: Documentation truth pass", "status": "pending", "classification": "standard", "blockedBy": [20]}
|
||||
],
|
||||
"knownFlakes": [
|
||||
|
||||
@@ -3,14 +3,22 @@
|
||||
**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.**
|
||||
> ## 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 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
|
||||
> 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](#finding-1-blocker).
|
||||
>
|
||||
> **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`](../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.
|
||||
|
||||
---
|
||||
|
||||
@@ -22,7 +30,7 @@ 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`. |
|
||||
| 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](#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. |
|
||||
|
||||
@@ -60,7 +68,7 @@ Sustained rate observed: ~**2.9 HTTP attempts/sec** (688–864 connection-refuse
|
||||
|
||||
---
|
||||
|
||||
## Finding 1 (BLOCKER)
|
||||
## 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
|
||||
|
||||
@@ -95,7 +103,7 @@ The failure was isolated by moving the load between nodes:
|
||||
| site-a-b | standby | no | **0** |
|
||||
| site-a-b | active (after failover) | yes | **4 391** |
|
||||
|
||||
#### It is LocalDb-specific, not the filesystem
|
||||
#### 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:
|
||||
@@ -112,14 +120,20 @@ directory, counting error-stack frames over 3 minutes:
|
||||
Ordinary SQLite on the same bind mount is completely healthy. Only the LocalDb-managed
|
||||
database fails.
|
||||
|
||||
#### Ruling out the observer
|
||||
#### 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. 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.
|
||||
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`](../known-issues/2026-07-20-localdb-disk-io-error-under-load.md) §0.
|
||||
|
||||
#### Secondary defect, same area
|
||||
|
||||
@@ -142,7 +156,9 @@ independently of LocalDb. Cutting over onto a store that cannot absorb the *curr
|
||||
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.
|
||||
~~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.
|
||||
|
||||
---
|
||||
|
||||
|
||||
@@ -68,6 +68,9 @@ services:
|
||||
MSSQL_PID: "Developer"
|
||||
volumes:
|
||||
- scadabridge-mssql-data:/var/opt/mssql
|
||||
# NOTE: the official mssql/server image does NOT run
|
||||
# /docker-entrypoint-initdb.d — these mounts are informational only;
|
||||
# infra/reseed.sh applies the scripts explicitly via sqlcmd.
|
||||
- ./mssql/setup.sql:/docker-entrypoint-initdb.d/setup.sql:ro
|
||||
- ./mssql/machinedata_seed.sql:/docker-entrypoint-initdb.d/machinedata_seed.sql:ro
|
||||
- ./mssql/setup-env2.sql:/docker-entrypoint-initdb.d/setup-env2.sql:ro
|
||||
|
||||
+9
-6
@@ -82,12 +82,15 @@ if ! $SKIP_TEARDOWN; then
|
||||
done
|
||||
echo " MSSQL ready."
|
||||
|
||||
echo " Waiting for setup.sql to create ScadaBridgeConfig..."
|
||||
until docker exec scadabridge-mssql /opt/mssql-tools18/bin/sqlcmd \
|
||||
-S localhost -U sa -P 'ScadaBridge_Dev1#' -C \
|
||||
-Q "IF DB_ID('ScadaBridgeConfig') IS NULL THROW 50000, 'not ready', 1;" \
|
||||
>/dev/null 2>&1; do
|
||||
sleep 2
|
||||
# The official mcr.microsoft.com/mssql/server image does NOT implement
|
||||
# /docker-entrypoint-initdb.d, so the compose-mounted init scripts never run
|
||||
# on their own — waiting for them here hangs forever on a fresh volume.
|
||||
# Apply them explicitly instead (all are idempotent).
|
||||
echo " Applying MSSQL init scripts (the mssql/server image has no initdb hook)..."
|
||||
for f in mssql/setup.sql mssql/machinedata_seed.sql mssql/setup-env2.sql; do
|
||||
echo " $f"
|
||||
docker exec -i scadabridge-mssql /opt/mssql-tools18/bin/sqlcmd \
|
||||
-S localhost -U sa -P 'ScadaBridge_Dev1#' -C -b < "$SCRIPT_DIR/$f"
|
||||
done
|
||||
echo " ScadaBridgeConfig present."
|
||||
|
||||
|
||||
@@ -114,8 +114,8 @@ public sealed class CachedCallTelemetryForwarder : ICachedCallTelemetryForwarder
|
||||
// Kind/Status are domain fields carried in DetailsJson — decompose to log them.
|
||||
var d = AuditRowProjection.Decompose(telemetry.Audit);
|
||||
_logger.LogWarning(ex,
|
||||
"CachedCallTelemetryForwarder: audit emission threw for EventId {EventId} (Kind {Kind}, Status {Status})",
|
||||
d.EventId, d.Kind, d.Status);
|
||||
"CachedCallTelemetryForwarder: audit emission threw for EventId {EventId} (Kind {Kind}, Status {Status}, sqlite {SqliteError})",
|
||||
d.EventId, d.Kind, d.Status, SqliteErrorCodes.Describe(ex));
|
||||
}
|
||||
}
|
||||
|
||||
@@ -192,8 +192,8 @@ public sealed class CachedCallTelemetryForwarder : ICachedCallTelemetryForwarder
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogWarning(ex,
|
||||
"CachedCallTelemetryForwarder: tracking-store emission threw for TrackedOperationId {Id} (Status {Status})",
|
||||
telemetry.Operational.TrackedOperationId, telemetry.Operational.Status);
|
||||
"CachedCallTelemetryForwarder: tracking-store emission threw for TrackedOperationId {Id} (Status {Status}, sqlite {SqliteError})",
|
||||
telemetry.Operational.TrackedOperationId, telemetry.Operational.Status, SqliteErrorCodes.Describe(ex));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -68,6 +68,15 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
private readonly IOperationTrackingStore? _trackingStore;
|
||||
private readonly SiteAuditTelemetryOptions _options;
|
||||
private readonly ILogger<SiteAuditTelemetryActor> _logger;
|
||||
// Captured at construction (both are thread-safe immutable handles) because
|
||||
// ScheduleNext/ScheduleNextCached run from the drains' finally blocks, whose
|
||||
// ConfigureAwait(false) continuations complete on pool threads with no
|
||||
// active ActorContext — reading Context/Self there either throws
|
||||
// NotSupportedException or, worse, silently resolves a STALE cell left in
|
||||
// the thread-static slot and re-arms the tick at the wrong actor
|
||||
// (known-issues/2026-07-20-localdb-disk-io-error-under-load.md §8).
|
||||
private readonly IScheduler _scheduler;
|
||||
private readonly IActorRef _self;
|
||||
private ICancelable? _pendingTick;
|
||||
private ICancelable? _pendingCachedTick;
|
||||
// Per-actor lifecycle CTS so an in-flight drain (queue read,
|
||||
@@ -108,6 +117,8 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
_options = options.Value;
|
||||
_logger = logger;
|
||||
_trackingStore = trackingStore;
|
||||
_scheduler = Context.System.Scheduler;
|
||||
_self = Self;
|
||||
|
||||
ReceiveAsync<Drain>(_ => OnDrainAsync());
|
||||
ReceiveAsync<CachedDrain>(_ => OnCachedDrainAsync());
|
||||
@@ -197,7 +208,9 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
{
|
||||
// Catch-all so a SQLite hiccup or mapper bug never crashes the
|
||||
// actor. The next tick is still scheduled in the finally block.
|
||||
_logger.LogError(ex, "Unexpected error during audit-log telemetry drain.");
|
||||
_logger.LogError(ex,
|
||||
"Unexpected error during audit-log telemetry drain (sqlite {SqliteError}).",
|
||||
SqliteErrorCodes.Describe(ex));
|
||||
}
|
||||
finally
|
||||
{
|
||||
@@ -278,8 +291,8 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
// batch — the audit half is best-effort. Log and skip
|
||||
// this row; it stays Pending for the next drain.
|
||||
_logger.LogWarning(ex,
|
||||
"Cached-telemetry drain: tracking lookup threw for {EventId} (TrackedOperationId {Tid}); skipping.",
|
||||
auditRow.EventId, auditRow.CorrelationId);
|
||||
"Cached-telemetry drain: tracking lookup threw for {EventId} (TrackedOperationId {Tid}, sqlite {SqliteError}); skipping.",
|
||||
auditRow.EventId, auditRow.CorrelationId, SqliteErrorCodes.Describe(ex));
|
||||
continue;
|
||||
}
|
||||
|
||||
@@ -332,7 +345,9 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogError(ex, "Unexpected error during cached-telemetry drain.");
|
||||
_logger.LogError(ex,
|
||||
"Unexpected error during cached-telemetry drain (sqlite {SqliteError}).",
|
||||
SqliteErrorCodes.Describe(ex));
|
||||
}
|
||||
finally
|
||||
{
|
||||
@@ -428,24 +443,26 @@ public class SiteAuditTelemetryActor : ReceiveActor
|
||||
return list;
|
||||
}
|
||||
|
||||
// Must stay off Context/Self: called from off-context continuations — see
|
||||
// the _scheduler/_self field comment.
|
||||
private void ScheduleNext(TimeSpan delay)
|
||||
{
|
||||
_pendingTick?.Cancel();
|
||||
_pendingTick = Context.System.Scheduler.ScheduleTellOnceCancelable(
|
||||
_pendingTick = _scheduler.ScheduleTellOnceCancelable(
|
||||
delay,
|
||||
Self,
|
||||
_self,
|
||||
Drain.Instance,
|
||||
Self);
|
||||
_self);
|
||||
}
|
||||
|
||||
private void ScheduleNextCached(TimeSpan delay)
|
||||
{
|
||||
_pendingCachedTick?.Cancel();
|
||||
_pendingCachedTick = Context.System.Scheduler.ScheduleTellOnceCancelable(
|
||||
_pendingCachedTick = _scheduler.ScheduleTellOnceCancelable(
|
||||
delay,
|
||||
Self,
|
||||
_self,
|
||||
CachedDrain.Instance,
|
||||
Self);
|
||||
_self);
|
||||
}
|
||||
|
||||
/// <summary>Self-tick message that triggers an audit-only drain cycle.</summary>
|
||||
|
||||
@@ -0,0 +1,31 @@
|
||||
using Microsoft.Data.Sqlite;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Site.Telemetry;
|
||||
|
||||
/// <summary>
|
||||
/// Renders the primary/extended SQLite result codes of a
|
||||
/// <see cref="SqliteException"/> for log messages. The exception's own message
|
||||
/// carries only the primary code ("SQLite Error 10: 'disk I/O error'"), which
|
||||
/// is too generic to act on — the 2026-07-20 disk-I/O incident
|
||||
/// (known-issues/2026-07-20-localdb-disk-io-error-under-load.md) had to be
|
||||
/// reproduced from scratch to learn the extended code (522 =
|
||||
/// SQLITE_IOERR_SHORT_READ) that names the failing operation.
|
||||
/// </summary>
|
||||
internal static class SqliteErrorCodes
|
||||
{
|
||||
/// <summary>
|
||||
/// "primary/extended" (e.g. "10/522") for a <see cref="SqliteException"/>
|
||||
/// anywhere in the exception chain; "n/a" for non-SQLite failures.
|
||||
/// </summary>
|
||||
public static string Describe(Exception ex)
|
||||
{
|
||||
for (Exception? e = ex; e is not null; e = e.InnerException)
|
||||
{
|
||||
if (e is SqliteException se)
|
||||
{
|
||||
return $"{se.SqliteErrorCode}/{se.SqliteExtendedErrorCode}";
|
||||
}
|
||||
}
|
||||
return "n/a";
|
||||
}
|
||||
}
|
||||
@@ -257,8 +257,8 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
|
||||
// (Health Monitoring reads FailedWriteCount) and fault the caller's
|
||||
// Task instead of silently discarding the exception.
|
||||
Interlocked.Increment(ref _failedWriteCount);
|
||||
_logger.LogError(ex, "Failed to record event: {EventType} from {Source}",
|
||||
pending.EventType, pending.Source);
|
||||
_logger.LogError(ex, "Failed to record event: {EventType} from {Source} (sqlite {SqliteError})",
|
||||
pending.EventType, pending.Source, DescribeSqliteError(ex));
|
||||
pending.Completion.TrySetException(ex);
|
||||
}
|
||||
}
|
||||
@@ -297,6 +297,25 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// "primary/extended" SQLite result codes (e.g. "10/522") for a
|
||||
/// <see cref="SqliteException"/> anywhere in the chain; "n/a" otherwise.
|
||||
/// The exception message alone carries only the primary code, which proved
|
||||
/// too generic to diagnose the 2026-07-20 disk-I/O incident
|
||||
/// (known-issues/2026-07-20-localdb-disk-io-error-under-load.md).
|
||||
/// </summary>
|
||||
private static string DescribeSqliteError(Exception ex)
|
||||
{
|
||||
for (Exception? e = ex; e is not null; e = e.InnerException)
|
||||
{
|
||||
if (e is SqliteException se)
|
||||
{
|
||||
return $"{se.SqliteErrorCode}/{se.SqliteExtendedErrorCode}";
|
||||
}
|
||||
}
|
||||
return "n/a";
|
||||
}
|
||||
|
||||
/// <summary>An event awaiting persistence by the background writer.</summary>
|
||||
private sealed record PendingEvent(
|
||||
string Id,
|
||||
|
||||
+52
@@ -5,6 +5,7 @@ using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Microsoft.Extensions.Options;
|
||||
using NSubstitute;
|
||||
using NSubstitute.ExceptionExtensions;
|
||||
using NSubstitute.ReceivedExtensions;
|
||||
using ZB.MOM.WW.ScadaBridge.AuditLog.Site.Telemetry;
|
||||
using ZB.MOM.WW.Audit;
|
||||
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
|
||||
@@ -451,4 +452,55 @@ public class SiteAuditTelemetryActorTests : TestKit
|
||||
await _client.DidNotReceiveWithAnyArgs().IngestCachedTelemetryAsync(default!, default);
|
||||
await _queue.DidNotReceiveWithAnyArgs().ReadPendingCachedTelemetryAsync(default, default);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Regression for the 2026-07-20 rig finding (known-issues/2026-07-20-localdb-disk-io-error-under-load.md §8):
|
||||
/// both drain handlers await with <c>ConfigureAwait(false)</c>, so when a
|
||||
/// dependency call completes off the actor thread (as real SQLite/gRPC
|
||||
/// always do) the <c>finally</c>-block re-arm runs on a pool thread with no
|
||||
/// active ActorContext. Depending on what that thread's thread-static cell
|
||||
/// slot holds, <c>Context</c>/<c>Self</c> either throw
|
||||
/// <c>NotSupportedException: There is no active ActorContext</c> (crashing
|
||||
/// the actor once per drain — the rig's logged variant) or silently resolve
|
||||
/// to a STALE cell of some other actor, misrouting the tick so the drain
|
||||
/// loop stops. The two assertions below catch one variant each. Every other
|
||||
/// test in this class masks the bug by returning already-completed tasks
|
||||
/// from the mocks, which keeps the continuations on the actor thread.
|
||||
/// </summary>
|
||||
[Fact]
|
||||
public async Task Drains_Whose_Awaits_Complete_Off_The_Actor_Thread_Keep_Draining_Without_Crashing()
|
||||
{
|
||||
// Task.Delay completes on a timer thread; with ConfigureAwait(false)
|
||||
// everything after the await — including the finally-block re-arm —
|
||||
// stays off the actor context.
|
||||
_queue.ReadPendingAsync(Arg.Any<int>(), Arg.Any<CancellationToken>())
|
||||
.Returns(async _ =>
|
||||
{
|
||||
await Task.Delay(25).ConfigureAwait(false);
|
||||
return (IReadOnlyList<AuditEvent>)Array.Empty<AuditEvent>();
|
||||
});
|
||||
_queue.ReadPendingCachedTelemetryAsync(Arg.Any<int>(), Arg.Any<CancellationToken>())
|
||||
.Returns(async _ =>
|
||||
{
|
||||
await Task.Delay(25).ConfigureAwait(false);
|
||||
return (IReadOnlyList<AuditEvent>)Array.Empty<AuditEvent>();
|
||||
});
|
||||
|
||||
// Variant 1 (throw → restart storm): any NotSupportedException logged
|
||||
// during the run fails the filter. Variant 2 (silent misroute → the
|
||||
// drain loop stalls after the first tick): the sustained-drain
|
||||
// assertion inside fails because reads stop at 1.
|
||||
await EventFilter.Exception<NotSupportedException>().ExpectAsync(0, async () =>
|
||||
{
|
||||
CreateActorWithCachedDrain(Opts(busySeconds: 1, idleSeconds: 1));
|
||||
|
||||
// Three full cycles prove the finally-block re-arm works from an
|
||||
// off-context thread: tick → drain → re-arm → tick → …
|
||||
await AwaitAssertAsync(async () =>
|
||||
{
|
||||
await _queue.Received(Quantity.Within(3, int.MaxValue)).ReadPendingAsync(Arg.Any<int>(), Arg.Any<CancellationToken>());
|
||||
await _queue.Received(Quantity.Within(3, int.MaxValue)).ReadPendingCachedTelemetryAsync(Arg.Any<int>(), Arg.Any<CancellationToken>());
|
||||
}, TimeSpan.FromSeconds(10));
|
||||
});
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user