Merge branch 'worktree-agent-a6a0dffcb93fa5007' into arch-review-remediation

This commit is contained in:
Joseph Doherty
2026-08-14 23:43:03 -04:00
10 changed files with 626 additions and 42 deletions
@@ -260,14 +260,24 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
}
/// <summary>
/// Commits a drained batch of pending events in one transaction. All-or-nothing per
/// batch: <c>site_events</c> ids are freshly minted GUIDs per <see cref="LogEventAsync"/>
/// call (no cross-call replay/de-dup concern the way <c>SqliteAuditWriter</c> has), so
/// unlike that reference there is no per-row duplicate-key swallow here — any failure
/// rolls back the whole batch and faults every event in it. <c>site_events</c> is a
/// CDC-replicated table (LocalDb Phase 1); its capture triggers fire per row on INSERT
/// same as before, so batching the commit changes only how many rows land per
/// transaction, not per-row trigger/replication behavior.
/// Commits a drained batch of pending events in one transaction, falling back to
/// row-by-row inserts if that transaction fails.
///
/// <para>The batch is the fast path: one transaction amortises SQLite's fsync/journal cost
/// across the whole drain. But a batch is all-or-nothing, so before the fallback existed a
/// SINGLE unwritable row (an oversized <c>details</c> payload, a constraint/trigger reject)
/// faulted all ~<see cref="WriteBatchSize"/> of its innocent neighbours and inflated
/// <see cref="FailedWriteCount"/> — the health metric — by the same factor. The rollback
/// is therefore followed by a per-row retry: one poison row costs exactly one row, the
/// rest still land, and the failure count stays truthful. Row-by-row is the degraded
/// path only — it is entered solely after a batch has already failed.</para>
///
/// <para><c>site_events</c> ids are freshly minted GUIDs per <see cref="LogEventAsync"/>
/// call (no cross-call replay/de-dup concern the way <c>SqliteAuditWriter</c> has), so a
/// re-insert during the fallback cannot duplicate a row the rolled-back batch had already
/// written. <c>site_events</c> is a CDC-replicated table (LocalDb Phase 1); its capture
/// triggers fire per row on INSERT either way, so neither shape changes
/// trigger/replication behavior.</para>
/// </summary>
private void FlushBatch(IReadOnlyList<PendingEvent> batch)
{
@@ -283,10 +293,7 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
{
using var cmd = connection.CreateCommand();
cmd.Transaction = transaction;
cmd.CommandText = """
INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details)
VALUES ($id, $timestamp, $event_type, $severity, $instance_id, $source, $message, $details)
""";
cmd.CommandText = InsertEventSql;
var pId = cmd.Parameters.Add("$id", SqliteType.Text);
var pTimestamp = cmd.Parameters.Add("$timestamp", SqliteType.Text);
var pEventType = cmd.Parameters.Add("$event_type", SqliteType.Text);
@@ -327,16 +334,21 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
if (failure is not null)
{
// A write failure must be observable. Count every event in the failed
// batch (Health Monitoring reads FailedWriteCount) and fault each
// caller's Task instead of silently discarding the exception.
Interlocked.Add(ref _failedWriteCount, batch.Count);
_logger.LogError(failure, "Failed to record {Count} event(s) in batch (sqlite {SqliteError})",
batch.Count, DescribeSqliteError(failure));
foreach (var pending in batch)
if (batch.Count == 1)
{
pending.Completion.TrySetException(failure);
// Nothing to isolate — retrying the single row would fail identically.
Interlocked.Increment(ref _failedWriteCount);
_logger.LogError(failure, "Failed to record 1 event (sqlite {SqliteError})",
DescribeSqliteError(failure));
batch[0].Completion.TrySetException(failure);
return;
}
// Degraded path: isolate the failure instead of charging the whole batch for it.
_logger.LogWarning(failure,
"Batch insert of {Count} site event(s) failed (sqlite {SqliteError}); retrying row by row",
batch.Count, DescribeSqliteError(failure));
FlushRowByRow(batch);
return;
}
@@ -352,8 +364,7 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
// WithConnection returns false only when the logger has been
// disposed mid-drain; none of the batch was persisted. Fault every
// Task instead of reporting false success for a dropped event.
var disposedEx = new ObjectDisposedException(nameof(SiteEventLogger),
"Event could not be recorded: the event logger was disposed before the write completed.");
var disposedEx = DisposedMidWrite();
foreach (var pending in batch)
{
pending.Completion.TrySetException(disposedEx);
@@ -361,16 +372,111 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
}
}
/// <summary>
/// Re-inserts a failed batch one row at a time, each in its own implicit transaction, so a
/// single unwritable event costs exactly one event: its own Task faults and it alone is
/// counted in <see cref="FailedWriteCount"/>, while every other row in the batch still
/// lands and completes successfully. Only reached from <see cref="FlushBatch"/> after the
/// batched transaction has already rolled back.
/// </summary>
/// <param name="batch">The rolled-back batch to retry row by row.</param>
private void FlushRowByRow(IReadOnlyList<PendingEvent> batch)
{
var failed = 0;
foreach (var pending in batch)
{
Exception? rowFailure = null;
bool written;
try
{
written = WithConnection(connection =>
{
using var cmd = connection.CreateCommand();
cmd.CommandText = InsertEventSql;
cmd.Parameters.AddWithValue("$id", pending.Id);
cmd.Parameters.AddWithValue("$timestamp", pending.Timestamp);
cmd.Parameters.AddWithValue("$event_type", pending.EventType);
cmd.Parameters.AddWithValue("$severity", pending.Severity);
cmd.Parameters.AddWithValue("$instance_id", (object?)pending.InstanceId ?? DBNull.Value);
cmd.Parameters.AddWithValue("$source", pending.Source);
cmd.Parameters.AddWithValue("$message", pending.Message);
cmd.Parameters.AddWithValue("$details", (object?)pending.Details ?? DBNull.Value);
cmd.ExecuteNonQuery();
});
}
catch (Exception ex)
{
rowFailure = ex;
written = false;
}
if (written)
{
pending.Completion.TrySetResult();
continue;
}
failed++;
if (rowFailure is null)
{
// Disposed mid-fallback; the remaining rows will take this path too.
pending.Completion.TrySetException(DisposedMidWrite());
continue;
}
_logger.LogError(rowFailure,
"Failed to record event from {Source} on row-by-row retry (sqlite {SqliteError})",
pending.Source, DescribeSqliteError(rowFailure));
pending.Completion.TrySetException(rowFailure);
}
if (failed > 0)
{
// Health Monitoring reads FailedWriteCount: only the rows that could not be
// written are counted, so the metric measures poison rows, not batch size.
Interlocked.Add(ref _failedWriteCount, failed);
}
}
/// <summary>
/// The exception a pending event's Task is faulted with when the logger was disposed
/// before its write could complete. A fresh instance per call so each faulted Task carries
/// its own stack.
/// </summary>
/// <returns>The exception to fault the pending event with.</returns>
private static ObjectDisposedException DisposedMidWrite() =>
new(nameof(SiteEventLogger),
"Event could not be recorded: the event logger was disposed before the write completed.");
/// <summary>
/// The single INSERT shared by the batched fast path and the row-by-row fallback, so the
/// two shapes can never drift in column list or ordering.
/// </summary>
private const string InsertEventSql = """
INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details)
VALUES ($id, $timestamp, $event_type, $severity, $instance_id, $source, $message, $details)
""";
/// <summary>
/// Stops accepting new events, drains the write queue, and disposes the SQLite connection.
/// </summary>
/// <remarks>
/// <c>_disposed</c> is deliberately NOT set in the first lock block. Completing
/// the channel writer is the whole shutdown signal: <see cref="LogEventAsync"/> observes it
/// (<c>TryWrite</c> returns false) and the writer loop drains what is already buffered
/// before exiting. Flipping <c>_disposed</c> up front would make <see cref="WithConnection"/>
/// return false for every remaining <see cref="FlushBatch"/>, so a graceful shutdown would
/// discard the entire queued backlog — the very events (shutdown diagnostics) most worth
/// keeping. It flips only after the loop has fully drained, where it guards the window
/// between drain and connection close. Mirrors <c>SqliteAuditWriter.DisposeAsync</c>.
/// </remarks>
public void Dispose()
{
Task? writerLoop = null;
Task? writerLoop;
lock (_writeLock)
{
if (_disposed) return;
_disposed = true;
// Stop accepting new events and let the writer loop drain.
_writeQueue.Writer.TryComplete();
writerLoop = _writerLoop;
@@ -390,6 +496,8 @@ public class SiteEventLogger : ISiteEventLogger, IDisposable
lock (_writeLock)
{
if (_disposed) return;
_disposed = true;
_connection.Dispose();
}
}
@@ -526,6 +526,18 @@ public class ScriptActor : ReceiveActor, IWithTimers
/// but the script body runs on the bounded set of dedicated threads, so blocking script
/// I/O is contained there and cannot starve the shared .NET thread pool. No per-run child
/// actor is created.</para>
///
/// <para>The cap governs NEW work only (<paramref name="callDepth"/> 0 — trigger-driven
/// runs and depth-0 Ask calls). A nested <c>CallScript</c> is exempt: the calling run is
/// itself still counted in <see cref="_runsInFlight"/> while it awaits its callee (the
/// slot is released only by <see cref="ScriptExecutionCompleted"/>, sent after the body
/// returns), and a script calling ITSELF routes back to this same actor — so counting the
/// nested launch against the cap would refuse legitimate self-recursion at depth
/// <see cref="SiteRuntimeOptions.MaxConcurrentRunsPerScript"/> with a misleading "shed",
/// making <see cref="SiteRuntimeOptions.MaxScriptCallDepth"/> — the limit that actually
/// owns this path, enforced in <c>ScriptRuntimeContext.CallScript</c> — unreachable.
/// Nested depth is bounded by MaxScriptCallDepth instead, which is what the cap would
/// otherwise be doing badly.</para>
/// </summary>
private void SpawnExecution(
IReadOnlyDictionary<string, object?>? parameters,
@@ -534,7 +546,7 @@ public class ScriptActor : ReceiveActor, IWithTimers
string correlationId,
Guid? parentExecutionId = null)
{
if (_runsInFlight >= _options.MaxConcurrentRunsPerScript)
if (callDepth == 0 && _runsInFlight >= _options.MaxConcurrentRunsPerScript)
{
ShedRun(replyTo, correlationId);
return;
@@ -604,8 +616,10 @@ public class ScriptActor : ReceiveActor, IWithTimers
/// <see cref="SiteRuntimeOptions.MaxConcurrentRunsPerScript"/> runs are already in flight.
/// The four already queued/running are kept — they are closest to their own deadlines and
/// already charged against them — so nothing is ever reordered. A trigger-driven run is
/// simply not launched; an Ask-based <c>CallScript</c> gets an explicit error so a nested
/// call or inbound-API route fails fast rather than hanging to its Ask timeout.
/// simply not launched; a depth-0 Ask (an inbound-API route, or a <c>CallScript</c> from
/// an unrelated script's run) gets an explicit error so the caller fails fast rather than
/// hanging to its Ask timeout. Nested (<c>callDepth &gt; 0</c>) launches never reach here —
/// see <see cref="SpawnExecution"/>.
/// </summary>
private void ShedRun(IActorRef replyTo, string correlationId)
{
@@ -289,11 +289,18 @@ public sealed class ScriptExecutionScheduler : TaskScheduler, IDisposable
if (Volatile.Read(ref worker.RunStamp) != observedRunStamp) return WorkerDetachOutcome.NotRunning;
if (Volatile.Read(ref worker.Detached) != 0) return WorkerDetachOutcome.NotRunning;
// Bound: never hold more than 2x threads (N wedged + N live).
if (_detachedLive >= _configuredCount) return WorkerDetachOutcome.AtCap;
// Bound: never hold more than 2x threads (N wedged + N live). Volatile read —
// the decrement side runs outside _growLock (see below).
if (Volatile.Read(ref _detachedLive) >= _configuredCount) return WorkerDetachOutcome.AtCap;
Volatile.Write(ref worker.Detached, 1);
_detachedLive++;
// Interlocked, NOT ++: the matching decrement in WorkerLoop is lock-free (the
// exiting worker never touches _growLock), so a plain read-modify-write here can
// lose that concurrent decrement. The drift is upward-only and permanent — the
// gauge over-reports and TryDetachWorker starts returning AtCap while real
// capacity is available. The surrounding sequence keeps the lock; only this one
// field is shared with a lock-free writer.
Interlocked.Increment(ref _detachedLive);
_configuredCount--; // the detached worker no longer counts towards the pool …
GrowTo(1); // … and GrowTo puts the count back by starting its replacement.
return WorkerDetachOutcome.Detached;
@@ -16,10 +16,18 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
///
/// <para>Lock-free: each script's counters are a small class of <c>long</c> fields mutated
/// via <see cref="Interlocked"/>, reached through a <see cref="ConcurrentDictionary{TKey,TValue}"/>
/// that <see cref="FlushAsync"/> atomically swaps out (<see cref="Interlocked.Exchange"/>) so a
/// concurrent increment either lands in the snapshot being flushed or the fresh one that
/// replaces it — never lost, never double-counted, and the flush never blocks a recording
/// call (or vice versa).</para>
/// that <see cref="FlushAsync"/> atomically swaps out (<see cref="Interlocked.Exchange"/>), so
/// the flush never blocks a recording call (or vice versa).</para>
///
/// <para>Accounting is BEST-EFFORT, not exact. A recorder that has already resolved its
/// <see cref="Counters"/> object from the pre-swap dictionary can increment it after the swap
/// has snapshotted it, so that increment lands in a window that has already been summarised
/// and is never reported. These are operational volume counters for one interval row, not a
/// ledger: an occasional count landing in neither window is acceptable, and nothing
/// downstream reconciles totals across intervals. What IS guaranteed is that a count is never
/// double-reported (each <see cref="Counters"/> instance is summarised by exactly one flush)
/// and that runs spanning a flush boundary — started in window N, completed in N+1 — still
/// emit their completion, because the flush filter admits a completion-only entry.</para>
/// </summary>
public sealed class ScriptRunSummaryRecorder
{
@@ -99,8 +107,8 @@ public sealed class ScriptRunSummaryRecorder
}
/// <summary>
/// Snapshots and resets the accumulated counters, then — if any script ran, failed, or
/// timed out during the interval — emits ONE aggregate "script" Info site event
/// Snapshots and resets the accumulated counters, then — if any script started, completed,
/// failed, or timed out during the interval — emits ONE aggregate "script" Info site event
/// summarizing the window. An interval with zero activity emits no row (the standby,
/// which never runs scripts, therefore never produces a summary row naturally).
/// </summary>
@@ -119,8 +127,13 @@ public sealed class ScriptRunSummaryRecorder
ref _counters,
new ConcurrentDictionary<(string InstanceName, string ScriptName), Counters>());
// Completed > 0 is admitted on its own: a run that started in window N and finished in
// N+1 records its completion against a FRESH counters object whose Started is 0, so
// filtering on Started/Failed/TimedOut alone would silently drop that completion (and,
// with it, the run's duration) from every summary row that could ever carry it.
var entries = snapshot
.Where(kvp => kvp.Value.Started > 0 || kvp.Value.Failed > 0 || kvp.Value.TimedOut > 0)
.Where(kvp => kvp.Value.Started > 0 || kvp.Value.Completed > 0 ||
kvp.Value.Failed > 0 || kvp.Value.TimedOut > 0)
.ToList();
if (entries.Count == 0)