fix(central): review findings — no client-side audit truncation, insert-first upsert, QI-safe scripts, honest operator replies

Six adversarial-review findings in the central SQL/ingest layer.

F1 (AuditLogRepository.InsertChunkAsync) — the set-based ingest declared each
string parameter at its COLUMN width (Actor/Target 256, Action 64, Outcome 16,
Category 32, SourceNode 64), so SqlClient truncated an over-long value at bind
time and committed the mutilated row — silent, in an append-only store, with no
PayloadTruncated flag — while the per-row and reconciliation paths sent the same
value in full and let the server reject it with 2628. Bind at the value's own
length instead; explicit SqlDbType is kept (it fixes the VALUES constructor's
derived column types and datetime2 precision). Design: reject everywhere,
truncate nowhere — matching today's per-row behaviour.

F2 (SiteCallAuditRepository.UpsertAsync) — the single-statement upsert ran the
monotonic UPDATE first and INSERTed only if nothing matched. Two writers racing
the first packet of one TrackedOperationId (the cached dual-write and the
reconciliation pull carry DIFFERENT lifecycle states) both matched nothing, and
the loser then skipped its INSERT or swallowed a 2627 — dropping its
Status/RetryCount/HttpStatus/TerminalAtUtc. Legs swapped to
`IF NOT EXISTS … INSERT; UPDATE <monotonic>` — still one round trip, and the
loser's UPDATE now lands on the winner's row. The duplicate-key catch re-runs
the monotonic UPDATE for the same reason. Moved to raw SQL with explicitly-typed
parameters so the intricate rank predicate exists in exactly one place (an
untyped DateTime would bind as `datetime` and round the freshness tiebreaker).

F3 (docs/plans/sql/*.sql) — filtered-index DDL failed with error 1934 under the
documented `docker exec … sqlcmd` path, which defaults QUOTED_IDENTIFIER OFF;
once IX_Notifications_Delivered exists, QI-OFF DML on Notifications fails too.
All four scripts now open with `SET QUOTED_IDENTIFIER ON; SET ANSI_NULLS ON; GO`
(own batch, so it is in force when the next batch parses), and the migration
convention in Component-ConfigurationDatabase.md documents `sqlcmd -I`. Verified
live: the pre-fix script fails 1934 without -I, the fixed one applies.

F4 (SiteCallAuditActor) — the off-mailbox reconciliation/purge passes reuse the
injected repository, so tests drove one DbContext from the pass and a mailbox
handler concurrently. Serialized at the CALL via a private SerializedRepository
wrapper applied only by the test constructors, rather than running the pass
on-mailbox: production keeps its PipeTo shape untouched, and the existing
"a blocked drain does not stall ingest/query/KPI" regression tests stay
meaningful (they would have been invalidated by suspending the mailbox).

F5 (AuditLogIngestActor) — when the batch failed because the 20 s IngestBudget
expired, the per-row fallback reused the same expired token: N instant failures,
N counter bumps, zero accepted. The fallback now gets a fresh 5 s budget (inside
the 30 s outer Ask), and a blown budget bumps the failure counter ONCE for the
batch instead of once per row.

F6 (NotificationOutboxRepository.UpdateAsync) — ExecuteUpdate's row count was
discarded, so an operator Retry/Discard of a notification the retention purge had
already deleted reported success (the pre-ExecuteUpdate code threw
DbUpdateConcurrencyException). UpdateAsync now returns whether a row matched; the
operator one-shots answer "notification not found" and emit no audit row for the
action that did not happen, while the dispatcher logs a warning (its delivery
already happened; nothing to retry). GetByIdAsync switched to AsNoTracking since
the write is out-of-band.

Tests: 5 new SQL-backed regressions (over-long Target rejected on both paths +
boundary round-trip; concurrent first-write and already-created-by-another-writer
upserts; vanished-row UpdateAsync), a token-identity pin on the ingest fallback,
a repository-concurrency detector for the SiteCallAudit passes, and vanished-row
operator-path tests. The F1/F2/F4 regressions were each confirmed failing against
the pre-fix code. Suites: ConfigurationDatabase 369, AuditLog 378, SiteCallAudit
66, NotificationOutbox 152 — all green, solution builds with 0 warnings.
This commit is contained in:
Joseph Doherty
2026-08-14 23:46:28 -04:00
parent b1de9dfdd4
commit 5d075f1374
30 changed files with 1042 additions and 126 deletions
@@ -674,6 +674,164 @@ public class SiteCallAuditReconciliationTests : TestKit
client.Release();
}
/// <summary>
/// An injected repository is ONE instance — typically wrapping one
/// <c>DbContext</c> — shared by the mailbox handlers and the off-mailbox
/// reconciliation/purge passes, and <c>DbContext</c> forbids concurrent
/// operations. Every call the actor makes through an injected repository must
/// therefore be serialized, so a drain's upserts never overlap an ingest
/// upsert arriving on the mailbox. (Production is unaffected: each message and
/// each pass resolves its own scope, hence its own context.)
/// </summary>
[Fact]
public async Task InjectedRepository_IsNeverCalledConcurrently_ByDrainAndMailbox()
{
var siteId = "siteBusy";
var sites = new StaticEnumerator(new SiteEntry(siteId, "http://siteBusy:8083"));
// One page of rows for the drain to upsert, each call held open long
// enough that a concurrent mailbox upsert would land inside it.
var pulled = Enumerable.Range(0, 6)
.Select(_ => NewRow(TrackedOperationId.New(), siteId))
.ToArray();
var client = new OneBatchThenEmptyPullClient(pulled);
var repo = new ConcurrencyDetectingRepo(TimeSpan.FromMilliseconds(40));
var actor = CreateActor(sites, client, repo, FastTickOptions());
// Once the pull has been served the drain is upserting; flood the mailbox
// with ingest commands so the two writers overlap in wall-clock time.
await client.Entered.WaitAsync(TimeSpan.FromSeconds(5));
var asks = Enumerable.Range(0, 6)
.Select(_ => actor.Ask<UpsertSiteCallReply>(
new UpsertSiteCallCommand(NewRow(TrackedOperationId.New(), siteId)),
TimeSpan.FromSeconds(10)))
.ToArray();
await Task.WhenAll(asks);
Assert.All(asks, ask => Assert.True(ask.Result.Accepted));
// The drain's own upserts must have run in the same window.
AwaitAssert(
() => Assert.True(repo.UpsertCount >= 12, $"expected both writers to have run; saw {repo.UpsertCount}"),
TimeSpan.FromSeconds(5));
Assert.Equal(1, repo.MaxObservedConcurrency);
}
/// <summary>
/// Serves one page of rows on the first pull and nothing afterwards, so the
/// drain has real upsert work to do and then settles.
/// </summary>
private sealed class OneBatchThenEmptyPullClient : IPullSiteCallsClient
{
private readonly SiteCall[] _rows;
private readonly TaskCompletionSource _entered =
new(TaskCreationOptions.RunContinuationsAsynchronously);
private int _callCount;
public OneBatchThenEmptyPullClient(SiteCall[] rows) => _rows = rows;
public Task Entered => _entered.Task;
public Task<PullSiteCallsResponse> PullAsync(
string siteId, DateTime sinceUtc, string? afterId, int batchSize, CancellationToken ct)
{
var first = Interlocked.Increment(ref _callCount) == 1;
_entered.TrySetResult();
return Task.FromResult(new PullSiteCallsResponse(
first ? _rows : Array.Empty<SiteCall>(), MoreAvailable: false));
}
}
/// <summary>
/// Records the peak number of overlapping repository calls. Each call is held
/// open briefly so an overlap, if the actor allows one, is observed rather
/// than missed by timing luck.
/// </summary>
private sealed class ConcurrencyDetectingRepo : ISiteCallAuditRepository
{
private readonly TimeSpan _hold;
private int _inFlight;
private int _maxObserved;
private int _upsertCount;
public ConcurrencyDetectingRepo(TimeSpan hold) => _hold = hold;
public int MaxObservedConcurrency => Volatile.Read(ref _maxObserved);
public int UpsertCount => Volatile.Read(ref _upsertCount);
public async Task UpsertAsync(SiteCall siteCall, CancellationToken ct = default)
{
Interlocked.Increment(ref _upsertCount);
await TrackAsync().ConfigureAwait(false);
}
public async Task<SiteCall?> GetAsync(TrackedOperationId id, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return null;
}
public async Task<IReadOnlyList<SiteCall>> QueryAsync(
SiteCallQueryFilter filter, SiteCallPaging paging, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return Array.Empty<SiteCall>();
}
public async Task<int> PurgeTerminalAsync(DateTime olderThanUtc, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return 0;
}
public async Task<SiteCallKpiSnapshot> ComputeKpisAsync(
DateTime stuckCutoff, DateTime intervalSince, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return new SiteCallKpiSnapshot(0, 0, 0, 0, null, 0);
}
public async Task<IReadOnlyList<SiteCallSiteKpiSnapshot>> ComputePerSiteKpisAsync(
DateTime stuckCutoff, DateTime intervalSince, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return Array.Empty<SiteCallSiteKpiSnapshot>();
}
public async Task<IReadOnlyList<SiteCallNodeKpiSnapshot>> ComputePerNodeKpisAsync(
DateTime stuckCutoff, DateTime intervalSince, CancellationToken ct = default)
{
await TrackAsync().ConfigureAwait(false);
return Array.Empty<SiteCallNodeKpiSnapshot>();
}
private async Task TrackAsync()
{
var current = Interlocked.Increment(ref _inFlight);
// Monotonic max without a lock.
int seen;
while (current > (seen = Volatile.Read(ref _maxObserved))
&& Interlocked.CompareExchange(ref _maxObserved, current, seen) != seen)
{
// Another thread moved the max; re-read and retry.
}
try
{
await Task.Delay(_hold).ConfigureAwait(false);
}
finally
{
Interlocked.Decrement(ref _inFlight);
}
}
}
/// <summary>
/// <see cref="BlockingPullClient"/> that also counts invocations, so a test
/// can prove no second pass started while the first was blocked.