From 0ccbe140aea247d25f57770591e7a4a68b556a29 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sun, 6 Sep 2026 12:35:41 -0400 Subject: [PATCH] perf(audit-log): cached-call forwarder enqueues the audit row instead of awaiting its commit (194 ms -> 25 ms) Measuring the tracking-store queue on the rig moved nothing: the DB-done -> Notify.Send gap stayed at 108 ms. The cost was the audit half of CachedCallTelemetryForwarder: SqliteAuditWriter.WriteAsync enqueues synchronously but returns the BATCH completion, and the writer loop coalesces for FlushIntervalMs (50 ms) before it commits, so each awaited audit row cost ~50 ms + fsync and a cached call awaited three (submit, attempted, resolve) on the script thread. Every other script-path emitter already fired-and-observed; only this forwarder awaited. TryEmitAuditAsync now hands the row to the writer and observes the completion on a fault-logging continuation (the FallbackAuditWriter ring-buffer fallback still runs inside that task). Best-effort contract unchanged; per-store FIFO unchanged; nothing joins the audit and tracking stores by commit order. Rig, FlowOutboundDemo, 5-run medians: inbound 194 -> 25 ms, site script run 176 -> 17 ms, CachedWrite submit->done 61 -> 11 ms, DB done -> Notify.Send 108 -> 0.1 ms. The tracking queue stays (three fewer fsyncs per call, batched). Docs corrected to attribute the cost to the flush wait, with the trap recorded in CLAUDE.md and Component-SiteRuntime.md. Tests: ForwardAsync returns while the audit commit is still pending (never-completing writer task) and still records tracking; a late commit fault is swallowed. Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29 --- CLAUDE.md | 2 +- ...9-06-tracking-store-async-writes-design.md | 42 ++++++++++--- docs/requirements/Component-SiteRuntime.md | 2 +- .../requirements/Component-StoreAndForward.md | 2 +- .../Telemetry/CachedCallTelemetryForwarder.cs | 63 +++++++++++++++---- .../CachedCallTelemetryForwarderTests.cs | 41 ++++++++++++ 6 files changed, 129 insertions(+), 23 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 09a6edde..892ebc83 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -152,7 +152,7 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - No Akka replication — MS SQL is the HA store; daily purge of terminal rows after a configurable window (default 365 days). - Notification Outbox retry reuses central SMTP max-retry-count and fixed interval for Email; Sms uses SmsConfiguration.MaxRetries/RetryDelay, falling back to the SMTP policy when unset. - Cached calls (`ExternalSystem.CachedCall`, `Database.CachedWrite`) return a `TrackedOperationId` tracking handle, unified with `Notify.Send`'s existing tracking model (`Notify.Status` retained as a thin alias). -- A site-local operation tracking table (SQLite, alongside the S&F buffer) is the source of truth for cached-call status; `Tracking.Status(id)` reads it site-locally and authoritatively; terminal rows purged after a configurable window (default 7 days). **Its writes are OFF the script thread as of 2026-09-06:** `OperationTrackingStore` is a single-writer queue (FIFO, batch-per-transaction pump, reads barrier on earlier queued writes so `Tracking.Status` keeps read-your-writes, `DisposeAsync` drains, sync `Dispose()` doesn't). Motivation: a Flow Debugger run showed one `Database.CachedWrite` paying three awaited SQLite commits, ~108 ms of a 176 ms site run. Trade: a queued-but-unapplied row is lost on a hard crash (ms window). Design: `docs/plans/2026-09-06-tracking-store-async-writes-design.md`. +- A site-local operation tracking table (SQLite, alongside the S&F buffer) is the source of truth for cached-call status; `Tracking.Status(id)` reads it site-locally and authoritatively; terminal rows purged after a configurable window (default 7 days). **Cached-call telemetry is OFF the script thread as of 2026-09-06** — a Flow Debugger run showed a `Database.CachedWrite` spending ~160 of a 176 ms site run on bookkeeping. The real cost was NOT the SQLite commits: `CachedCallTelemetryForwarder` awaited `IAuditWriter.WriteAsync` three times, and `SqliteAuditWriter.WriteAsync` returns the *batch completion*, which lands only after the writer's `FlushIntervalMs` (50 ms) coalescing wait — so **never `await` an audit write on a script path**; enqueue and observe the fault on a continuation, as every other emitter already did. Same change made `OperationTrackingStore` a single-writer queue (FIFO, batch-per-transaction pump, reads barrier on earlier queued writes so `Tracking.Status` keeps read-your-writes, `DisposeAsync` drains, sync `Dispose()` doesn't; trade: a queued-but-unapplied row is lost on a hard crash, ms window). Measured: inbound 194 → 25 ms, script run 176 → 17 ms. Design + numbers: `docs/plans/2026-09-06-tracking-store-async-writes-design.md`. - Unified tracking status lifecycle `Pending → Retrying → Delivered / Parked / Failed / Discarded`; `Failed` = permanent failure (also returned synchronously to the calling script). No `Forwarding` state for cached calls. - Site Call Audit (#22): central `SiteCallAuditActor` singleton with a `SiteCalls` audit table (central MS SQL) fed by best-effort site telemetry plus periodic reconciliation pulls — an eventually-consistent mirror, NOT a dispatcher; cached-call delivery stays site-local. Ingest is insert-if-not-exists then upsert-on-newer-status. - Central UI Site Calls page + central→site `RetryParkedOperation`/`DiscardParkedOperation` relay for parked cached calls; central never mutates the `SiteCalls` row directly. diff --git a/docs/plans/2026-09-06-tracking-store-async-writes-design.md b/docs/plans/2026-09-06-tracking-store-async-writes-design.md index 28571d30..adf303f9 100644 --- a/docs/plans/2026-09-06-tracking-store-async-writes-design.md +++ b/docs/plans/2026-09-06-tracking-store-async-writes-design.md @@ -1,6 +1,6 @@ -# Operation tracking store: writes off the script thread +# Cached-call telemetry off the script thread (tracking store queue + audit enqueue-and-observe) -**Date:** 2026-09-06 · **Status:** implemented the same day (branch `feat/tracking-store-async-writes`) +**Date:** 2026-09-06 · **Status:** implemented and measured the same day (branch `feat/tracking-store-async-writes`) ## Problem @@ -17,9 +17,10 @@ which the site script run was 176 ms. Reading the audit rows against the code pa `OperationTrackingStore` executed every `Record*Async` as its own autocommit SQLite transaction on the consolidated LocalDb file, **awaited inline on the script thread** through `CachedCallTelemetryForwarder.ForwardAsync`. Each commit is a WAL append + fsync -(`synchronous=NORMAL`, Docker volume): ~30–50 ms apiece here. The audit half of the same forwarder was -already cheap — `SqliteAuditWriter.WriteAsync` is a `Channel.TryWrite` — so the tracking half was the -whole cost. The API cached-call path (`ExternalSystem.CachedCall`) pays the same three commits. +(`synchronous=NORMAL`, Docker volume). The initial reading — which turned out to be wrong, see the +correction below — was that the audit half of the same forwarder was already cheap because +`SqliteAuditWriter.WriteAsync` enqueues with `Channel.TryWrite`, so the tracking commits were the whole +cost. The API cached-call path (`ExternalSystem.CachedCall`) takes the same three-packet path. ## Decision @@ -73,9 +74,36 @@ untouched, and their existing `await`s now cost a channel write. - *A bigger LocalDb `synchronous` relaxation*: `OFF` would remove the fsync but risk corruption on power loss for every replicated table, not just this one. +## What the measurement actually showed (correction) + +The tracking-store queue alone moved **nothing**: five runs on that image still sat at 108 ms for the +DB-done → `Notify.Send` gap and ~176 ms for the script run. The commits were cheap; the wait was the +**audit half** of the same forwarder. `SqliteAuditWriter.WriteAsync` enqueues synchronously but +returns the *batch's completion task*, and the writer loop deliberately coalesces for +`FlushIntervalMs` (50 ms default) before it commits — so every awaited audit row costs ~50 ms + fsync, +and a cached call awaits three of them (submit, attempted, resolve) on the script thread: ~160 ms. +Every other script-path audit emission (`AuditingDbCommand`, `ScriptRunLauncher`, the trace rows) +already fired-and-observed; only `CachedCallTelemetryForwarder.TryEmitAuditAsync` awaited. + +Second change, same branch: the forwarder now enqueues the audit row and observes the completion on +a fault-logging continuation (the `FallbackAuditWriter` ring-buffer fallback still runs inside that +task). Nothing joins the audit and tracking stores by commit order; each keeps per-store FIFO. + +| Segment (5-run median, rig) | before | tracking queue only | + audit enqueue-and-observe | +|---|---|---|---| +| inbound request total | 194 ms | 186 ms | **25 ms** | +| site script run | 176 ms | 173 ms | **17 ms** | +| `Database.CachedWrite` submit → done | 61 ms | 58 ms | **11 ms** | +| DB done → `Notify.Send` | 108 ms | 108 ms | **0.1 ms** | + +The tracking-store queue is kept: it removes three fsyncs per cached call from the script path and +batches them, and `FlushIntervalMs` no longer bounds a script's latency — a cached call now costs +its real I/O (the REST or SQL round trip) plus microseconds of bookkeeping. + ## Verification - Store tests: a write returns while another connection holds the database write lock and lands once it is released; reads observe every earlier write in order; `DisposeAsync` drains the queue. -- Rig: rerun `FlowOutboundDemo` through the Flow Debugger and compare the `DbCall`-to-`NotifySend` - gap and the run total against the 108 ms / 176 ms baseline above. +- Forwarder tests: `ForwardAsync` returns while the audit commit is still pending; a late commit + fault is swallowed and logged. +- Rig: `FlowOutboundDemo` five times per image through `flow-debug run-method`; table above. diff --git a/docs/requirements/Component-SiteRuntime.md b/docs/requirements/Component-SiteRuntime.md index 7eb2e8e8..6a9a5466 100644 --- a/docs/requirements/Component-SiteRuntime.md +++ b/docs/requirements/Component-SiteRuntime.md @@ -504,7 +504,7 @@ Available to all script runs and alarm on-trigger runs: ### Operation Tracking - `Tracking.Status("trackedOperationId")` — Returns a status record (status, retry count, last error, key timestamps) for any tracked operation: a cached external system call, a cached database write, or a notification. For cached calls and writes the answer is always site-local and authoritative — the site owns the operation tracking table. (`Notify.Status(...)` is a thin alias scoped to the notification domain.) -- **Tracking writes are off the script thread (2026-09-06).** `OperationTrackingStore` is a single-writer queue: `RecordEnqueue/Attempt/TerminalAsync` (reached from the script through `CachedCallTelemetryForwarder`) return once the row is *queued*, and one background pump applies each drained batch in one SQLite transaction — one fsync per batch instead of one per lifecycle row. Before this, a `Database.CachedWrite` that delivered immediately paid three awaited autocommit transactions on the consolidated LocalDb file, ~108 ms of a 176 ms script run measured on the rig. Preserved: FIFO order across the three lifecycle rows; **read-your-writes** — `GetStatusAsync` (behind `Tracking.Status`, and the telemetry actor's status join) and `ReadChangedSinceAsync` (central's `PullSiteCalls`) wait for every write queued before them; timestamps are stamped when recorded, not when applied; `PurgeTerminalAsync` returns after the purge lands; `DisposeAsync` drains the queue (the sync `Dispose()` does not — host shutdown uses the async path). Accepted: a row queued but unapplied is lost on a hard crash (milliseconds), leaving the tracking row at its previous state until reconciled; the S&F buffer and audit rows are unaffected. The queue is bounded (8 192) with wait backpressure — it never drops. `FlushAsync()` is the explicit barrier for callers that go to the file directly. Design: `docs/plans/2026-09-06-tracking-store-async-writes-design.md`. +- **Cached-call telemetry is off the script thread (2026-09-06).** A `Database.CachedWrite` / `ExternalSystem.CachedCall` emits three `CachedCallTelemetry` packets (submit, attempted, resolve) through `CachedCallTelemetryForwarder`, each an audit row plus a tracking row. Both halves used to be awaited to commit on the script thread; the audit half was the real cost — `SqliteAuditWriter.WriteAsync` returns the batch completion, and the writer coalesces for `FlushIntervalMs` (50 ms) before committing — so a cached call paid ~160 ms of a 176 ms run for bookkeeping (measured on the rig; now 17 ms). The forwarder now **enqueues the audit row and observes its completion on a fault-logging continuation** (the same pattern every other script-path audit emission already used), and `OperationTrackingStore` is a **single-writer queue**: `RecordEnqueue/Attempt/TerminalAsync` return once the row is *queued*, and one background pump applies each drained batch in one SQLite transaction. Preserved: FIFO order across the three lifecycle rows; **read-your-writes** — `GetStatusAsync` (behind `Tracking.Status`, and the telemetry actor's status join) and `ReadChangedSinceAsync` (central's `PullSiteCalls`) wait for every write queued before them; timestamps are stamped when recorded, not when applied; `PurgeTerminalAsync` returns after the purge lands; `DisposeAsync` drains the queue (the sync `Dispose()` does not — host shutdown uses the async path). Accepted: a row queued but unapplied is lost on a hard crash (milliseconds), leaving the tracking row at its previous state until reconciled; the S&F buffer and audit rows are unaffected. The queue is bounded (8 192) with wait backpressure — it never drops. `FlushAsync()` is the explicit barrier for callers that go to the file directly. **Trap for new audit emitters on a script path:** never `await` `IAuditWriter.WriteAsync` there — it waits for the writer's flush, not the enqueue. Design + measurements: `docs/plans/2026-09-06-tracking-store-async-writes-design.md`. ### Alarm State (read-only) - `Alarms.CurrentAsync()` — Returns a snapshot of the instance's **current** alarm conditions as `IReadOnlyList` (`Commons.Types.Scripts`), covering computed alarms and mirrored native (OPC UA A&C / MxAccess Gateway) conditions alike. Served by a **local Ask** (`GetAlarmSnapshotRequest`/`GetAlarmSnapshotResponse`) to the script's own Instance Actor — the same mechanism attribute reads use, never a cross-cluster hop. diff --git a/docs/requirements/Component-StoreAndForward.md b/docs/requirements/Component-StoreAndForward.md index a8ff7ae3..0296024b 100644 --- a/docs/requirements/Component-StoreAndForward.md +++ b/docs/requirements/Component-StoreAndForward.md @@ -53,7 +53,7 @@ For notifications, "delivery" means forwarding the message to the central cluste There are now exactly two ways a notification parks. First, a **corrupt buffered payload** (a row whose stored JSON no longer deserialises to a `NotificationSubmit`, or deserialises to null): the forwarder returns the delivery-handler contract's permanent-failure signal (`false`) so the engine parks the row, preserving the payload for operator forensics. This **supersedes `StoreAndForward-018`**, which discarded such rows by reporting them as delivered — a silent data loss with no parked row, no central `Notifications` row, and no audit trail. Retrying a corrupt payload is pointless (it can never deserialise), so parking, not retrying, is the correct home for it. Second, retry exhaustion under the `DefaultMaxRetries` cap — but because `Notify.Send` enqueues with `maxRetries: 0` (its unbounded-retry contract, above), that second cause is **off for script-produced notifications**, leaving corrupt payload as their only parking cause. (Retry-exhaustion parking remains reachable only for a hypothetical notification enqueued with a positive `maxRetries`.) -For the cached-call categories (`ExternalCall` and `DatabaseWrite`), the operation tracking table is the status record and the S&F buffer is purely the retry mechanism. A cached call that succeeds on its first immediate attempt is written directly as a terminal `Delivered` tracking row and never enters the S&F buffer. When immediate delivery fails transiently, the message is buffered and its tracking row moves to `Pending`/`Retrying`; the buffered message carries its `TrackedOperationId` so the tracking row and the retry record stay linked. When immediate delivery fails **permanently** (e.g. HTTP 4xx), the message is not buffered — the error is returned synchronously to the calling script as before — but the tracking row is written directly as a terminal `Failed` row capturing the error. On every tracking-table status transition the site emits `CachedCallTelemetry` to central. The tracking row itself is written through a single-writer queue (Site Runtime, 2026-09-06): the script's `await` on each lifecycle emission returns once the row is queued, not committed, and reads of the table wait for earlier queued writes so status stays read-your-writes — see `Component-SiteRuntime.md` → *Operation Tracking*. +For the cached-call categories (`ExternalCall` and `DatabaseWrite`), the operation tracking table is the status record and the S&F buffer is purely the retry mechanism. A cached call that succeeds on its first immediate attempt is written directly as a terminal `Delivered` tracking row and never enters the S&F buffer. When immediate delivery fails transiently, the message is buffered and its tracking row moves to `Pending`/`Retrying`; the buffered message carries its `TrackedOperationId` so the tracking row and the retry record stay linked. When immediate delivery fails **permanently** (e.g. HTTP 4xx), the message is not buffered — the error is returned synchronously to the calling script as before — but the tracking row is written directly as a terminal `Failed` row capturing the error. On every tracking-table status transition the site emits `CachedCallTelemetry` to central. Neither the audit row nor the tracking row of that telemetry is awaited to commit on the script thread (Site Runtime, 2026-09-06): the audit row is enqueued on the site writer and its completion observed off-thread, and the tracking row goes through a single-writer queue whose reads wait for earlier queued writes so `Tracking.Status` stays read-your-writes — see `Component-SiteRuntime.md` → *Operation Tracking*. Every cached-call outcome maps to a tracking-table state: immediate success → `Delivered`; transient failure → `Pending`/`Retrying`, eventually `Delivered` or `Parked`; permanent failure → terminal `Failed`; operator discard of a parked row → terminal `Discarded`. 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 2e638029..cfb3644a 100644 --- a/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs +++ b/src/ZB.MOM.WW.ScadaBridge.AuditLog/Site/Telemetry/CachedCallTelemetryForwarder.cs @@ -34,8 +34,22 @@ namespace ZB.MOM.WW.ScadaBridge.AuditLog.Site.Telemetry; /// returns normally. /// /// +/// Neither half is awaited to durability (2026-09-06). The audit row is +/// enqueued on the writer — SqliteAuditWriter.WriteAsync returns the +/// batch's completion task, and that batch coalesces for FlushIntervalMs +/// (50 ms) before it commits — so awaiting it here made every cached call pay +/// the flush wait three times over, on the script thread (measured: ~160 ms of a +/// 176 ms Database.CachedWrite run on the rig; see +/// docs/plans/2026-09-06-tracking-store-async-writes-design.md). The +/// completion is observed on a continuation that logs a fault; the +/// FallbackAuditWriter chain still routes a failed commit to its ring +/// buffer inside that task. The tracking half is a queue write since the same +/// day (OperationTrackingStore). The ordering the two stores need is +/// per-store FIFO, which both keep; nothing joins them by commit order. +/// +/// /// Local-write only — the wire push is the drain actor's job. This -/// forwarder is deliberately synchronous against the two site-local SQLite +/// forwarder writes only to the two site-local SQLite /// stores and never pushes to central itself. The site→central transport is /// now live: SiteCommunicationAuditClient is the production binding of /// on site roles (with @@ -98,25 +112,48 @@ public sealed class CachedCallTelemetryForwarder : ICachedCallTelemetryForwarder await TryEmitTrackingAsync(telemetry, ct).ConfigureAwait(false); } - private async Task TryEmitAuditAsync(CachedCallTelemetry telemetry, CancellationToken ct) + private Task TryEmitAuditAsync(CachedCallTelemetry telemetry, CancellationToken ct) { + // Enqueue-and-observe, NOT await-to-commit: WriteAsync hands the row to + // the writer synchronously and returns the batch's completion, which + // lands only after the writer's FlushIntervalMs coalescing wait + fsync. + // The caller is a script thread; it must not pay for that. Same pattern as + // AuditingDbCommand / ScriptRunLauncher's own audit rows. try { - await _auditWriter.WriteAsync(telemetry.Audit, ct).ConfigureAwait(false); + var write = _auditWriter.WriteAsync(telemetry.Audit, ct); + if (write.IsCompletedSuccessfully) + return Task.CompletedTask; + if (write.IsFaulted) + { + LogAuditFailure(telemetry, write.Exception!.GetBaseException()); + return Task.CompletedTask; + } + _ = write.ContinueWith( + t => LogAuditFailure(telemetry, t.Exception!.GetBaseException()), + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); } catch (Exception ex) { - // alog.md §7 best-effort contract — log and swallow. The audit - // pipeline's own retry/recovery (RingBufferFallback in the - // FallbackAuditWriter) handles transient writer failures upstream; - // a throw bubbling up here means the writer's own swallow contract - // failed, which is itself best-effort-handled. - // 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}, sqlite {SqliteError})", - d.EventId, d.Kind, d.Status, SqliteErrorCodes.Describe(ex)); + LogAuditFailure(telemetry, ex); } + return Task.CompletedTask; + } + + private void LogAuditFailure(CachedCallTelemetry telemetry, Exception ex) + { + // alog.md §7 best-effort contract — log and swallow. The audit + // pipeline's own retry/recovery (RingBufferFallback in the + // FallbackAuditWriter) handles transient writer failures upstream; + // a throw reaching here means the writer's own swallow contract + // failed, which is itself best-effort-handled. + // Kind/Status are domain fields carried in DetailsJson — decompose to log them. + var d = AuditRowProjection.Decompose(telemetry.Audit); + _logger.LogWarning(ex, + "CachedCallTelemetryForwarder: audit emission failed for EventId {EventId} (Kind {Kind}, Status {Status}, sqlite {SqliteError})", + d.EventId, d.Kind, d.Status, SqliteErrorCodes.Describe(ex)); } private async Task TryEmitTrackingAsync(CachedCallTelemetry telemetry, CancellationToken ct) diff --git a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/CachedCallTelemetryForwarderTests.cs b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/CachedCallTelemetryForwarderTests.cs index d16bb5cc..0c9a72e9 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/CachedCallTelemetryForwarderTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Site/Telemetry/CachedCallTelemetryForwarderTests.cs @@ -193,6 +193,47 @@ public class CachedCallTelemetryForwarderTests default, default!, default, default, default, default); } + // ── 2026-09-06: the audit row is enqueued, never awaited to commit ───── + // Design: docs/plans/2026-09-06-tracking-store-async-writes-design.md + + [Fact] + public async Task ForwardAsync_ReturnsWhileTheAuditCommitIsStillPending() + { + // SqliteAuditWriter.WriteAsync returns the batch completion, which lands only + // after FlushIntervalMs + fsync. A never-completing task models "not flushed + // yet": ForwardAsync must still return and still record the tracking half. + var neverFlushed = new TaskCompletionSource(); + _writer.WriteAsync(Arg.Any(), Arg.Any()) + .Returns(neverFlushed.Task); + + var sut = CreateSut(); + var forward = sut.ForwardAsync(ResolvePacket(), CancellationToken.None); + + var finished = await Task.WhenAny(forward, Task.Delay(TimeSpan.FromSeconds(2))); + Assert.Same(forward, finished); + await _writer.Received(1).WriteAsync(Arg.Any(), Arg.Any()); + await _tracking.Received(1).RecordTerminalAsync( + _id, "Delivered", Arg.Any(), Arg.Any(), Arg.Any()); + } + + [Fact] + public async Task ForwardAsync_AuditCommitFaultsLater_IsSwallowed() + { + var lateFault = new TaskCompletionSource(); + _writer.WriteAsync(Arg.Any(), Arg.Any()) + .Returns(lateFault.Task); + + var sut = CreateSut(); + await sut.ForwardAsync(SubmitPacket(), CancellationToken.None); // returns before the fault + lateFault.SetException(new InvalidOperationException("disk full")); + await Task.Yield(); + + // Nothing propagates anywhere the script could see; the tracking half ran. + await _tracking.Received(1).RecordEnqueueAsync( + Arg.Any(), Arg.Any(), Arg.Any(), + Arg.Any(), Arg.Any(), Arg.Any(), Arg.Any()); + } + [Fact] public async Task ForwardAsync_WriterThrows_Logs_DoesNotPropagate() {