diff --git a/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md b/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md index a5ff583a..6be51122 100644 --- a/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md +++ b/docs/known-issues/2026-07-20-localdb-disk-io-error-under-load.md @@ -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 :/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 /` | 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. diff --git a/docs/plans/2026-07-19-localdb-adoption-phase2.md b/docs/plans/2026-07-19-localdb-adoption-phase2.md index ea5fd918..30fe5dc3 100644 --- a/docs/plans/2026-07-19-localdb-adoption-phase2.md +++ b/docs/plans/2026-07-19-localdb-adoption-phase2.md @@ -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 "" — 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;" ``` diff --git a/docs/plans/2026-07-19-localdb-adoption-phase2.md.tasks.json b/docs/plans/2026-07-19-localdb-adoption-phase2.md.tasks.json index de5b004b..64b301b9 100644 --- a/docs/plans/2026-07-19-localdb-adoption-phase2.md.tasks.json +++ b/docs/plans/2026-07-19-localdb-adoption-phase2.md.tasks.json @@ -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": [ diff --git a/docs/plans/2026-07-19-localdb-phase2-soak.md b/docs/plans/2026-07-19-localdb-phase2-soak.md index 99c69c86..d80c2433 100644 --- a/docs/plans/2026-07-19-localdb-phase2-soak.md +++ b/docs/plans/2026-07-19-localdb-phase2-soak.md @@ -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. --- diff --git a/infra/docker-compose.yml b/infra/docker-compose.yml index cd32c86d..1d06f4e7 100644 --- a/infra/docker-compose.yml +++ b/infra/docker-compose.yml @@ -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 diff --git a/infra/reseed.sh b/infra/reseed.sh index dfae57d7..50257d91 100755 --- a/infra/reseed.sh +++ b/infra/reseed.sh @@ -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." diff --git a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs index b376da08..7df5588c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs +++ b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs @@ -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)); } } } diff --git a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs index 88169bce..dbc9e463 100644 --- a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SiteAuditTelemetryActor.cs @@ -68,6 +68,15 @@ public class SiteAuditTelemetryActor : ReceiveActor private readonly IOperationTrackingStore? _trackingStore; private readonly SiteAuditTelemetryOptions _options; private readonly ILogger _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(_ => OnDrainAsync()); ReceiveAsync(_ => 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); } /// Self-tick message that triggers an audit-only drain cycle. diff --git a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SqliteErrorCodes.cs b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SqliteErrorCodes.cs new file mode 100644 index 00000000..83bc351a --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/SqliteErrorCodes.cs @@ -0,0 +1,31 @@ +using Microsoft.Data.Sqlite; + +namespace ZB.MOM.WW.ScadaBridge.AuditLog.Site.Telemetry; + +/// +/// Renders the primary/extended SQLite result codes of a +/// 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. +/// +internal static class SqliteErrorCodes +{ + /// + /// "primary/extended" (e.g. "10/522") for a + /// anywhere in the exception chain; "n/a" for non-SQLite failures. + /// + 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"; + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs index 0b95b684..95f2361c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogger.cs @@ -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 } } + /// + /// "primary/extended" SQLite result codes (e.g. "10/522") for a + /// 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). + /// + 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"; + } + /// An event awaiting persistence by the background writer. private sealed record PendingEvent( string Id, diff --git a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/SiteAuditTelemetryActorTests.cs b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/SiteAuditTelemetryActorTests.cs index 1aad60dd..c19ed203 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/SiteAuditTelemetryActorTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/SiteAuditTelemetryActorTests.cs @@ -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); } + + /// + /// 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 ConfigureAwait(false), so when a + /// dependency call completes off the actor thread (as real SQLite/gRPC + /// always do) the finally-block re-arm runs on a pool thread with no + /// active ActorContext. Depending on what that thread's thread-static cell + /// slot holds, Context/Self either throw + /// NotSupportedException: There is no active ActorContext (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. + /// + [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(), Arg.Any()) + .Returns(async _ => + { + await Task.Delay(25).ConfigureAwait(false); + return (IReadOnlyList)Array.Empty(); + }); + _queue.ReadPendingCachedTelemetryAsync(Arg.Any(), Arg.Any()) + .Returns(async _ => + { + await Task.Delay(25).ConfigureAwait(false); + return (IReadOnlyList)Array.Empty(); + }); + + // 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().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(), Arg.Any()); + await _queue.Received(Quantity.Within(3, int.MaxValue)).ReadPendingCachedTelemetryAsync(Arg.Any(), Arg.Any()); + }, TimeSpan.FromSeconds(10)); + }); + } }