Bound the trace log's fault RATE, not its lifetime total — a spent budget silenced the wedge

src/MeshWeaver.Documentation/Data/Architecture/DebuggingNativeCrashes.md

@@ -39,6 +39,24 @@ It arrives inside the **`testResults-shard<N>`** artifact under `collected-logs/
 alongside `_meshweaver-test-trace.log` and `_meshweaver-memory-delta.log`. **Retention is 15 days** —
 pull it before it expires.
 
+### 🚨 Ask the trace log whether it is complete before you reason from it
+
+`_meshweaver-test-trace.log` carries `[FAULT]` records — exception type, message and stack for
+everything logged at `Warning` or above with an exception. Its fault records are **rate-bounded**
+(100 per 10 s per process), so a storming process has records missing, and reasoning from an
+absence in a truncated log is how you conclude the wrong thing. The log always says when that
+happened:
+
+```bash
+grep FAULT-BUDGET collected-logs/_meshweaver-test-trace.log
+```
+
+Nothing back ⇒ every fault this process logged is in the file. Otherwise each hit names the
+running count of suppressed records, and a `resuming fault records after suppressing N` line
+states exactly how many were lost in that gap. A **budget never silences a later fault** — the
+window refills, so the fault next to a wedge is written even if an earlier storm saturated the
+allowance (issue #982).
+
 ```bash
 # find the shard artifact (the crashing shard's is the big one — the others are ~0MB)
 gh api repos/Systemorph/MeshWeaver/actions/runs/<RUN_ID>/artifacts \

src/MeshWeaver.Fixture/FaultRecordBudget.cs

@@ -0,0 +1,152 @@
+using System.Globalization;
+
+namespace MeshWeaver.Fixture;
+
+/// <summary>
+/// What <see cref="FaultRecordBudget.Claim"/> decided about one fault record.
+/// </summary>
+/// <param name="WriteRecord">
+/// <c>true</c> when the record itself may be written; <c>false</c> when it is suppressed.
+/// </param>
+/// <param name="Notice">
+/// A sink-level line to write when non-null — <em>before</em> the record when
+/// <paramref name="WriteRecord"/> is <c>true</c>, and <em>instead of</em> it when it is
+/// <c>false</c>. This is the only thing that keeps a suppressed stretch visible, so a caller
+/// must never drop it.
+/// </param>
+public readonly record struct FaultRecordVerdict(bool WriteRecord, string? Notice);
+
+/// <summary>
+/// The write budget for
+/// <see cref="TestTraceLog.AppendFault(string, Microsoft.Extensions.Logging.LogLevel, string, Exception)"/>
+/// — a refilling per-window
+/// allowance, not a lifetime cap.
+///
+/// <para><b>Why a rate and not a total (issue #982).</b> The hazard this bounds is a
+/// <em>storm</em>: a resubscribe loop logging a fault per iteration writes until the runner's
+/// disk fills (the 2026-07 colima ENOSPC failure mode). A storm is a property of the write
+/// RATE, so a rate is what has to be bounded. The previous design bounded the lifetime TOTAL
+/// (1000 records per process) instead, which is a different quantity and had a fatal
+/// consequence for the sink's actual job: once a busy process passed the total, EVERY later
+/// fault was dropped for the rest of the process — including the one that fires next to the
+/// wedge, which is the only record anyone ever wants. Two shard-3 processes hit that ceiling in
+/// every sampled run of #982's 17-run sample, so the sink was at its least useful exactly in
+/// the long, busy processes where a wedge is most likely.</para>
+///
+/// <para>A window budget refills, so an earlier storm can never permanently silence the sink:
+/// a fault arriving after a quiet stretch is always written. What it costs is fidelity
+/// <em>during</em> a storm — the 101st fault in a 10-second burst is dropped — and that is the
+/// right trade, because a storm's records are the same record repeated while the late,
+/// isolated fault is unique.</para>
+///
+/// <para><b>Why not keep first-N + last-N.</b> Retaining the tail means buffering it in memory
+/// and flushing at the end — but this sink exists precisely for the case where there IS no end:
+/// a shard killed by its wall-clock cap (<c>exit=124</c>) or a host dying on a signal never runs
+/// a flush. Anything not already on disk when the process dies is gone, so every record must be
+/// written eagerly, line by line. A ring buffer would trade the one property that makes this
+/// file the only diagnostic CI keeps.</para>
+///
+/// <para><b>Truncation is never silent.</b> Whenever suppression starts in a window the budget
+/// hands back a notice line carrying the running suppressed count, and the first record written
+/// after a suppressed stretch carries a second notice naming exactly how many were lost in the
+/// gap. Both are tagged <c>[FAULT-BUDGET]</c>, so <c>grep FAULT-BUDGET</c> over a collected log
+/// answers "is this file complete?" — and a process killed mid-storm leaves the entering notice
+/// as the last thing in the file rather than an unremarkable silence.</para>
+/// </summary>
+public sealed class FaultRecordBudget
+{
+    private readonly int recordsPerWindow;
+    private readonly TimeSpan window;
+    private readonly object gate = new();
+
+    private DateTime windowStart;
+    private int writtenInWindow;
+    private bool noticedInWindow;
+    private long suppressedSinceLastRecord;
+    private long suppressedTotal;
+
+    /// <summary>
+    /// Creates a budget allowing <paramref name="recordsPerWindow"/> fault records per
+    /// <paramref name="window"/>.
+    /// </summary>
+    /// <param name="recordsPerWindow">Records allowed per window; must be positive.</param>
+    /// <param name="window">The window length; must be positive.</param>
+    public FaultRecordBudget(int recordsPerWindow, TimeSpan window)
+    {
+        ArgumentOutOfRangeException.ThrowIfNegativeOrZero(recordsPerWindow);
+        ArgumentOutOfRangeException.ThrowIfLessThanOrEqual(window, TimeSpan.Zero);
+        this.recordsPerWindow = recordsPerWindow;
+        this.window = window;
+    }
+
+    /// <summary>
+    /// Total fault records this budget has suppressed. Monotonic for the life of the instance.
+    /// </summary>
+    public long SuppressedTotal
+    {
+        get { lock (gate) return suppressedTotal; }
+    }
+
+    /// <summary>
+    /// Claims the right to write one fault record at <paramref name="now"/>.
+    /// </summary>
+    /// <param name="now">
+    /// The record's timestamp. Passed in rather than read from the clock so the window
+    /// behaviour is deterministically testable without sleeping.
+    /// </param>
+    /// <returns>The verdict; see <see cref="FaultRecordVerdict"/>.</returns>
+    public FaultRecordVerdict Claim(DateTime now)
+    {
+        // A plain lock, not an async gate: this is a synchronous file-sink leaf with no await
+        // inside it, called from ILogger.Log. It is on nobody's hub scheduler.
+        lock (gate)
+        {
+            var elapsed = now - windowStart;
+            // elapsed < 0 rolls too, so a clock stepping backwards cannot freeze the window
+            // open and starve the budget for the rest of the process.
+            if (elapsed >= window || elapsed < TimeSpan.Zero)
+            {
+                windowStart = now;
+                writtenInWindow = 0;
+                noticedInWindow = false;
+            }
+
+            if (writtenInWindow < recordsPerWindow)
+            {
+                writtenInWindow++;
+                if (suppressedSinceLastRecord == 0)
+                    return new FaultRecordVerdict(true, null);
+
+                var dropped = suppressedSinceLastRecord;
+                suppressedSinceLastRecord = 0;
+                return new FaultRecordVerdict(
+                    true,
+                    $"resuming fault records after suppressing {Plural(dropped)} "
+                    + $"({suppressedTotal} suppressed in this process so far) — "
+                    + "this log is NOT a complete record of faults");
+            }
+
+            suppressedSinceLastRecord++;
+            suppressedTotal++;
+            if (noticedInWindow)
+                return new FaultRecordVerdict(false, null);
+
+            // One notice per window, not one per dropped record: enough to keep the file
+            // honest while it is storming, cheap enough that the notice can never become the
+            // storm itself.
+            noticedInWindow = true;
+            return new FaultRecordVerdict(
+                false,
+                // Invariant so the line reads identically whatever locale the runner is in —
+                // a diagnostic that changes shape by machine is a diagnostic you cannot grep.
+                $"budget of {Plural(recordsPerWindow)} per "
+                + $"{window.TotalSeconds.ToString("0.###", CultureInfo.InvariantCulture)}s "
+                + $"exhausted — suppressing further fault records until the window rolls "
+                + $"({suppressedTotal} suppressed in this process so far); "
+                + "this log is NOT a complete record of faults");
+        }
+    }
+
+    private static string Plural(long count) =>
+        count == 1 ? "1 fault record" : $"{count} fault records";
+}

src/MeshWeaver.Fixture/TestTraceLog.cs

@@ -13,7 +13,8 @@ namespace MeshWeaver.Fixture;
 ///
 /// <para>Two writers share it, which is why the path and the lock live here rather than
 /// on either one: <c>MonolithMeshTestBase</c>'s per-test phase trace, and
-/// <see cref="AppendFault"/> below. A second writer holding its OWN lock would interleave
+/// <see cref="AppendFault(string, LogLevel, string, Exception)"/> below.
+/// A second writer holding its OWN lock would interleave
 /// mid-line with the first and corrupt both.</para>
 /// </summary>
 public static class TestTraceLog
@@ -54,17 +55,35 @@ public static void Touch()
         try { File.AppendAllText(Path, string.Empty); } catch { /* best-effort */ }
     }
 
-    // Bound on the number of fault records this process may append. A test process that
-    // storms (a resubscribe loop logging a warning per iteration) would otherwise write
-    // the artifact until the runner's disk fills — the 2026-07 colima ENOSPC failure mode.
-    // This bounds the ARTIFACT, not the diagnosis: the first faults in a cascade are the
-    // ones that name the cause; the thousandth repeat adds nothing.
-    // Sized against measurement, not a guess: one deliberately-failing compile test
-    // (CodeEditRecompileTest.FailedCompile_…) emits 15 fault records, so a per-shard budget
-    // has to be in the thousands to still be holding the record that names a LATE fault.
-    private const int MaxFaultRecords = 1000;
+    // ── Fault-record budget ────────────────────────────────────────────────────────────
+    // Bounds the write RATE, because a storm (a resubscribe loop logging a warning per
+    // iteration filling the runner's disk — the 2026-07 colima ENOSPC failure mode) IS a
+    // rate. It deliberately does NOT bound the lifetime total: a total, once spent, silences
+    // the sink for the rest of the process and takes the late fault next to the wedge with
+    // it, which is the only record anyone ever reads (issue #982). See FaultRecordBudget for
+    // the full argument, including why keeping the tail in a ring buffer is not an option
+    // here (a process killed by `timeout` never flushes one).
+    //
+    // Sized against the #982 measurement, not a guess: a healthy shard process emits ~1500
+    // fault records across a ≤20-minute shard — order 1.3/s. 100 per 10s is ~7x that, so a
+    // healthy run never suppresses, while a genuine storm (thousands/s) is clamped to 10/s.
+    // The artifact cost is then bounded by WALL CLOCK rather than by an arbitrary total:
+    // 10 records/s x ~3 KB ≈ 1.8 MB/min, and a shard's own 20-minute cap (its projects run
+    // sequentially in one loop) puts the ceiling near 36 MB uncompressed — a few MB in the
+    // artifact at the workflow's compression-level 9.
+    private const int FaultRecordsPerWindow = 100;
+    private static readonly TimeSpan FaultWindow = TimeSpan.FromSeconds(10);
+
+    // Process-wide, and deliberately so, despite the no-static-state rule: this sink IS a
+    // per-process artifact (CI collects one file per runner) and its writers — fixture
+    // construction, teardown, and reactive continuations on background schedulers — belong to
+    // no mesh and outlive every mesh in the process. A mesh-scoped budget would reset on each
+    // test class and so would not bound a storm that spans classes, which is the hazard. It
+    // needs no Clear()-for-test-isolation hook either: the policy is exercised in tests
+    // through its own instances (FaultRecordBudget), never through this one.
+    private static readonly FaultRecordBudget FaultBudget = new(FaultRecordsPerWindow, FaultWindow);
+
     private const int MaxExceptionChars = 2500;
-    private static int _faultRecordsWritten;
 
     /// <summary>
     /// Appends one fault record — level, category, message and the exception's full
@@ -78,19 +97,53 @@ public static void Touch()
     /// active, which is exactly the wedge case. That is why the recurring compile abort
     /// of issue #890 was undiagnosable: the framework logged the exception object with
     /// its stack, and every sink that carried the stack was invisible to CI.</para>
+    ///
+    /// <para>Records are rate-bounded by <see cref="FaultRecordBudget"/>, so a storming process
+    /// has some suppressed — but never a late one, and never silently: each suppressed stretch
+    /// is announced in the file by a <c>[FAULT-BUDGET]</c> line carrying the count, so
+    /// <c>grep FAULT-BUDGET</c> answers "is this log complete?".</para>
     /// </summary>
     /// <param name="category">The logger category name.</param>
     /// <param name="level">The record's severity.</param>
     /// <param name="message">The formatted log message.</param>
     /// <param name="exception">The exception whose type and stack to record.</param>
     public static void AppendFault(string category, LogLevel level, string message, Exception exception)
+        => AppendFault(FaultBudget, DateTime.UtcNow, category, level, message, exception);
+
+    /// <summary>
+    /// The <see cref="AppendFault(string, LogLevel, string, Exception)"/> body with its budget
+    /// and clock supplied — the seam tests use to exercise suppression deterministically
+    /// against their OWN <see cref="FaultRecordBudget"/>, without sleeping and without
+    /// spending the process's real budget (which would suppress a genuine fault logged later
+    /// in the same run).
+    /// </summary>
+    /// <param name="budget">The budget to claim from.</param>
+    /// <param name="now">The record's timestamp.</param>
+    /// <param name="category">The logger category name.</param>
+    /// <param name="level">The record's severity.</param>
+    /// <param name="message">The formatted log message.</param>
+    /// <param name="exception">The exception whose type and stack to record.</param>
+    public static void AppendFault(
+        FaultRecordBudget budget,
+        DateTime now,
+        string category,
+        LogLevel level,
+        string message,
+        Exception exception)
     {
-        var written = Interlocked.Increment(ref _faultRecordsWritten);
-        if (written > MaxFaultRecords)
+        var verdict = budget.Claim(now);
+
+        // The notice is what stops a truncated log from reading like a complete one, so it is
+        // written whether or not the record itself survives — and it is tagged so a reader can
+        // answer "did this file lose anything?" with one grep.
+        var notice = verdict.Notice is null
+            ? null
+            : $"{now:HH:mm:ss.fff} pid={Environment.ProcessId} [FAULT-BUDGET] {verdict.Notice}";
+
+        if (!verdict.WriteRecord)
         {
-            if (written == MaxFaultRecords + 1)
-                Append($"{DateTime.UtcNow:HH:mm:ss.fff} pid={Environment.ProcessId} [FAULT] "
-                    + $"further fault records suppressed after {MaxFaultRecords} in this process");
+            if (notice is not null)
+                Append(notice);
             return;
         }
 
@@ -101,7 +154,14 @@ public static void AppendFault(string category, LogLevel level, string message,
         // pid on the header line for the same reason the phase trace carries it: every
         // test project in a shard appends to this one file, and a core dump is named
         // dotnet-<pid>.dmp.
-        Append($"{DateTime.UtcNow:HH:mm:ss.fff} pid={Environment.ProcessId} [FAULT] "
-            + $"[{level}] [{category}] {message}{Environment.NewLine}{detail}");
+        var record = $"{now:HH:mm:ss.fff} pid={Environment.ProcessId} [FAULT] "
+            + $"[{level}] [{category}] {message}{Environment.NewLine}{detail}";
+
+        // ONE Append, so the notice and the record it explains cannot be split. Append releases
+        // the file lock per call and every test host in the shard writes to this file, so two
+        // calls would let another writer land between them — and a "resuming after suppressing
+        // N" line stranded from the record that resumed reintroduces exactly the ambiguity this
+        // whole change exists to remove.
+        Append(notice is null ? record : notice + Environment.NewLine + record);
     }
 }