chore(submodule): fleet baseline for the IME overwrite fix (40.7 % fallback before, 0 % after) and the P6 todo

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPollTimingTests.cs

@@ -0,0 +1,95 @@
+using System.Collections.Generic;
+using System.Threading;
+using System.Threading.Tasks;
+using AutopilotMonitor.Agent.V2.Core.Logging;
+using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
+using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
+using AutopilotMonitor.Shared.Models;
+using Xunit;
+
+namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
+{
+    /// <summary>
+    /// The poll loop's timing maxima (session c3ecb568: the loop was not scheduled for 26 s at
+    /// 100 % VM CPU and nothing in the telemetry could show it): the longest pass and the
+    /// longest pause between two passes, on a monotonic clock, restart-safe like the other
+    /// health counters.
+    /// </summary>
+    public sealed class ImeLogTrackerPollTimingTests
+    {
+        /// <summary>Monotonic readings the tracker takes at the start and the end of every pass.</summary>
+        private sealed class Clock
+        {
+            private readonly Queue<long> _readings = new Queue<long>();
+            public void Enqueue(params long[] ms) { foreach (var m in ms) _readings.Enqueue(m); }
+            public long Next() => _readings.Dequeue();
+        }
+
+        private static ImeLogTracker Build(TempDirectory tmp, Clock clock)
+        {
+            var tracker = new ImeLogTracker(tmp.Path, new List<ImeLogPattern>(), new AgentLogger(tmp.Path, AgentLogLevel.Info), stateDirectory: tmp.Path);
+            tracker.MonotonicMillisProvider = clock.Next;
+            return tracker;
+        }
+
+        [Fact]
+        public async Task Longest_pass_and_longest_pause_are_kept_as_session_maxima()
+        {
+            using var tmp = new TempDirectory();
+            var clock = new Clock();
+            var tracker = Build(tmp, clock);
+
+            // Pass 1 takes 30 ms; the loop is not scheduled again for 26.1 s; pass 2 takes 10 ms,
+            // pass 3 follows after the normal 100 ms.
+            clock.Enqueue(0, 30, 26130, 26140, 26240, 26245);
+            await tracker.RunPollPassAsync(CancellationToken.None);
+            await tracker.RunPollPassAsync(CancellationToken.None);
+            await tracker.RunPollPassAsync(CancellationToken.None);
+
+            var health = tracker.GetHealthSnapshot();
+            Assert.Equal(30, health.PassMaxMs);
+            Assert.Equal(26100, health.PassGapMaxMs);
+            tracker.Dispose();
+        }
+
+        [Fact]
+        public void A_fresh_tracker_reports_zero()
+        {
+            using var tmp = new TempDirectory();
+            var tracker = Build(tmp, new Clock());
+
+            var health = tracker.GetHealthSnapshot();
+            Assert.Equal(0, health.PassMaxMs);
+            Assert.Equal(0, health.PassGapMaxMs);
+            tracker.Dispose();
+        }
+
+        [Fact]
+        public async Task Maxima_survive_a_restart_and_are_never_lowered()
+        {
+            using var tmp = new TempDirectory();
+            var clock = new Clock();
+            var tracker1 = Build(tmp, clock);
+            clock.Enqueue(0, 40, 5140, 5150);
+            await tracker1.RunPollPassAsync(CancellationToken.None);
+            await tracker1.RunPollPassAsync(CancellationToken.None);
+            tracker1.SaveStateForTest();
+            tracker1.Dispose();
+
+            var tracker2 = Build(tmp, clock);
+            tracker2.LoadStateForTest();
+            Assert.Equal(40, tracker2.GetHealthSnapshot().PassMaxMs);
+            Assert.Equal(5100, tracker2.GetHealthSnapshot().PassGapMaxMs);
+
+            // The first pass after a restart has no pause to measure; a calmer session afterwards
+            // never lowers what the session already saw.
+            clock.Enqueue(6000, 6010, 6110, 6115);
+            await tracker2.RunPollPassAsync(CancellationToken.None);
+            await tracker2.RunPollPassAsync(CancellationToken.None);
+            var health = tracker2.GetHealthSnapshot();
+            Assert.Equal(40, health.PassMaxMs);
+            Assert.Equal(5100, health.PassGapMaxMs);
+            tracker2.Dispose();
+        }
+    }
+}

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs

@@ -336,7 +336,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         private int _unanchoredPatterns;
         private int _filesTailed;
         private long _backlogBytes;
+        // Poll-loop timing (restart-safe maxima on a monotonic clock): the longest pass and the
+        // longest pause between passes — see ImeTrackerHealth.PassMaxMs / PassGapMaxMs.
+        private long _passMaxMs;
+        private long _passGapMaxMs;
+        private long _lastPassEndMs = -1;
         private string _imeAgentVersionSeen;
+
+        /// <summary>Monotonic milliseconds for the poll-loop timing; tests substitute a counter.</summary>
+        internal Func<long> MonotonicMillisProvider { get; set; } = () => Stopwatch.GetTimestamp() * 1000 / Stopwatch.Frequency;
         private bool _trackerDegradedFired;
         private readonly Dictionary<string, int> _patternHits = new Dictionary<string, int>(StringComparer.OrdinalIgnoreCase);
 
@@ -370,6 +378,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                     OverwriteBytesReprocessed = _overwriteBytesReprocessed,
                     VerifyPasses = _verifyPasses,
                     VerifiedBytes = _verifiedBytes,
+                    PassMaxMs = _passMaxMs,
+                    PassGapMaxMs = _passGapMaxMs,
                     PatternHits = new Dictionary<string, int>(_patternHits, StringComparer.OrdinalIgnoreCase),
                 };
             }
@@ -954,18 +964,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                 {
                     try
                     {
-                        await CheckLogFilesAsync(token);
-
-                        // Platform-script completions that wait for the other file: an IME result
-                        // held for its executor end block, and the exit-code fallback for a
-                        // result IME never logged within the grace period. Runs on this same loop
-                        // thread (no locking) so it observes the buffer right after parsing.
-                        FlushPendingPlatformScriptResults(UtcNowProvider());
-
-                        // Token-failure grace window: fires only when the failure stayed
-                        // unresolved (no IME-TOKEN-SUCCESS) for the whole window. Runs after
-                        // the drain so a success later in the same batch clears first.
-                        CheckPendingTokenFailure(DateTime.UtcNow);
+                        await RunPollPassAsync(token);
                     }
                     catch (OperationCanceledException) { break; }
                     catch (Exception ex)
@@ -1006,6 +1005,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
             }, token);
         }
 
+        /// <summary>
+        /// One poll pass, timed: the file reads, then the platform-script completions that wait
+        /// for the other file (an IME result held for its executor end block, the exit-code
+        /// fallback for a result IME never logged), then the token-failure grace window — all on
+        /// this one loop thread, no locking, so the flushes observe the buffers right after
+        /// parsing. The longest pass and the longest pause since the previous pass ended are the
+        /// session's <see cref="ImeTrackerHealth.PassMaxMs"/> / <see cref="ImeTrackerHealth.PassGapMaxMs"/>.
+        /// </summary>
+        internal async Task RunPollPassAsync(CancellationToken token)
+        {
+            var startMs = MonotonicMillisProvider();
+            if (_lastPassEndMs >= 0 && startMs - _lastPassEndMs > _passGapMaxMs)
+            {
+                _passGapMaxMs = startMs - _lastPassEndMs;
+                _stateDirty = true;
+            }
+
+            await CheckLogFilesAsync(token);
+            FlushPendingPlatformScriptResults(UtcNowProvider());
+            CheckPendingTokenFailure(UtcNowProvider());
+
+            var endMs = MonotonicMillisProvider();
+            if (endMs - startMs > _passMaxMs)
+            {
+                _passMaxMs = endMs - startMs;
+                _stateDirty = true;
+            }
+            _lastPassEndMs = endMs;
+        }
+
         /// <summary>
         /// Stops the background polling task
         /// </summary>
@@ -1155,6 +1184,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                     _overwriteBytesReprocessed = state.Health.OverwriteBytesReprocessed;
                     _verifyPasses = state.Health.VerifyPasses;
                     _verifiedBytes = state.Health.VerifiedBytes;
+                    _passMaxMs = state.Health.PassMaxMs;
+                    _passGapMaxMs = state.Health.PassGapMaxMs;
                 }
                 if (state.PatternHits != null)
                 {
@@ -1228,6 +1259,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                     OverwriteBytesReprocessed = _overwriteBytesReprocessed,
                     VerifyPasses = _verifyPasses,
                     VerifiedBytes = _verifiedBytes,
+                    PassMaxMs = _passMaxMs,
+                    PassGapMaxMs = _passGapMaxMs,
                 };
                 state.PatternHits = new Dictionary<string, int>(_patternHits, StringComparer.OrdinalIgnoreCase);
             }

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerHealth.cs

@@ -63,6 +63,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         /// <summary>Bytes re-read for verification, guard-zone checks included — the cost of the overwrite detection.</summary>
         public long VerifiedBytes { get; set; }
 
+        /// <summary>
+        /// Longest single poll pass this session (one <c>CheckLogFilesAsync</c> plus the
+        /// flushes), milliseconds on a monotonic clock. A pass spends its time in the file
+        /// reads, the ledger verifications and the regex matching; the fleet baseline is well
+        /// under 100 ms.
+        /// </summary>
+        public long PassMaxMs { get; set; }
+
+        /// <summary>
+        /// Longest pause between the end of one poll pass and the start of the next this
+        /// session, milliseconds. The loop sleeps 100 ms between passes and saves its state now
+        /// and then; anything far above that is the loop not being scheduled — session c3ecb568
+        /// lost 26 s this way at 100 % VM CPU while the rest of the agent kept running. Late
+        /// reading, not lost data: every event keeps its log line's own timestamp, and a
+        /// result read before its executor end block waits for it.
+        /// </summary>
+        public long PassGapMaxMs { get; set; }
+
         /// <summary>Match count per enabled pattern ID — every enabled pattern is present, zeros included.</summary>
         public IReadOnlyDictionary<string, int> PatternHits { get; set; }
 

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs

@@ -177,6 +177,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
         public long OverwriteBytesReprocessed { get; set; }
         public long VerifyPasses { get; set; }
         public long VerifiedBytes { get; set; }
+        // Poll-loop timing maxima (null-defaulting on older state files).
+        public long PassMaxMs { get; set; }
+        public long PassGapMaxMs { get; set; }
     }
 
     public class PackageStateData

src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Telemetry/Periodic/AgentSelfMetricsCollector.cs

@@ -213,6 +213,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
                         data["ime_overwrite_bytes_reprocessed"] = health.OverwriteBytesReprocessed;
                         data["ime_verify_passes"] = health.VerifyPasses;
                         data["ime_verified_bytes"] = health.VerifiedBytes;
+                        data["ime_pass_max_ms"] = health.PassMaxMs;
+                        data["ime_pass_gap_max_ms"] = health.PassGapMaxMs;
                     }
                 }
                 catch (Exception ex)

src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs

@@ -588,6 +588,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
                     ["overwriteBytesReprocessed"] = health.OverwriteBytesReprocessed,
                     ["verifyPasses"] = health.VerifyPasses,
                     ["verifiedBytes"] = health.VerifiedBytes,
+                    ["passMaxMs"] = health.PassMaxMs,
+                    ["passGapMaxMs"] = health.PassGapMaxMs,
                     ["agentVersion"] = _agentVersion ?? string.Empty,
                 };
                 if (!string.IsNullOrEmpty(health.ImeAgentVersion))

src/McpServer/autopilot-monitor-mcp/src/__tests__/session-coverage.test.ts

@@ -132,7 +132,7 @@ describe('buildSessionCoverage — IME log tracker', () => {
       ev('ime_tracker_degraded', 50, { file: 'AppWorkload.log', lineBudgetBreaks: 1, regexTimeouts: 0, oversizedLines: 0 }),
       ev('ime_pattern_hits', 900, { linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1 }, { severity: 'Debug' }),
     ]);
-    expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1, overwriteRewinds: null, overwriteBytesReprocessed: null });
+    expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1, overwriteRewinds: null, overwriteBytesReprocessed: null, passMaxMs: null, passGapMaxMs: null });
     expect(c.gaps[0]).toContain('skipped the remaining patterns on 7 line(s)');
     expect(c.gaps[0]).toContain('gave up on 2 line(s) after a regex timeout');
     expect(c.gaps[0]).toContain('dropped 1 oversized line(s)');
@@ -143,7 +143,7 @@ describe('buildSessionCoverage — IME log tracker', () => {
       ev('agent_started', 0),
       ev('ime_pattern_hits', 900, { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0 }),
     ]);
-    expect(c.imeTracker).toEqual({ degraded: false, sessionTotals: { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: null, overwriteBytesReprocessed: null } });
+    expect(c.imeTracker).toEqual({ degraded: false, sessionTotals: { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: null, overwriteBytesReprocessed: null, passMaxMs: null, passGapMaxMs: null } });
     expect(c.gaps).toEqual([]);
   });
 
@@ -155,7 +155,7 @@ describe('buildSessionCoverage — IME log tracker', () => {
       ev('ime_pattern_hits', 900, { linesRead: 8957, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 6, overwriteBytesReprocessed: 5120 }, { severity: 'Debug' }),
     ]);
     expect(c.imeTracker.degraded).toBe(false);
-    expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 8957, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 6, overwriteBytesReprocessed: 5120 });
+    expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 8957, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 6, overwriteBytesReprocessed: 5120, passMaxMs: null, passGapMaxMs: null });
     expect(c.imeTracker.note).toBe('6 log block(s) a concurrent IME process had overwritten were re-read (5 KB) — script results and exit codes in them are complete, not missing.');
     expect(c.gaps).toEqual([]);
   });
@@ -167,6 +167,32 @@ describe('buildSessionCoverage — IME log tracker', () => {
     ]);
     expect(c.imeTracker.note).toBeUndefined();
   });
+
+  it('reports a poll-loop pause of 5 s or more as late reading — a note, never a gap', () => {
+    // Session c3ecb568: the tracker loop was not scheduled for 26 s at 100 % VM CPU; the lines
+    // written meanwhile were read afterwards with their own timestamps intact.
+    const c = buildSessionCoverage(SESSION, [
+      ev('agent_started', 0),
+      ev('ime_pattern_hits', 900, { linesRead: 8422, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 11, overwriteBytesReprocessed: 1725, passMaxMs: 180, passGapMaxMs: 26100 }, { severity: 'Debug' }),
+    ]);
+    expect(c.imeTracker.degraded).toBe(false);
+    expect(c.imeTracker.sessionTotals?.passGapMaxMs).toBe(26100);
+    expect(c.imeTracker.note).toBe(
+      '11 log block(s) a concurrent IME process had overwritten were re-read (2 KB) — script results and exit codes in them are complete, not missing. '
+      + 'The IME log tracker paused for up to 26 s (longest pass 0.2 s, longest gap between passes 26.1 s)'
+      + " — lines written meanwhile were read late, not lost: every event keeps its log line's own timestamp.",
+    );
+    expect(c.gaps).toEqual([]);
+  });
+
+  it('stays silent about poll timing below the 5 s threshold', () => {
+    const c = buildSessionCoverage(SESSION, [
+      ev('agent_started', 0),
+      ev('ime_pattern_hits', 900, { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 0, overwriteBytesReprocessed: 0, passMaxMs: 4999, passGapMaxMs: 800 }),
+    ]);
+    expect(c.imeTracker.sessionTotals?.passMaxMs).toBe(4999);
+    expect(c.imeTracker.note).toBeUndefined();
+  });
 });
 
 describe('buildSessionCoverage — collectors, upload, disk', () => {

src/McpServer/autopilot-monitor-mcp/src/session-coverage.ts

@@ -46,7 +46,7 @@ export const COVERAGE_EVENT_FIELDS =
   'data.bootToAgentStartSeconds,data.agentUptimeSeconds,data.outcome,data.note,' +
   'data.earliestRejectedSourceTimestamp,' +
   'data.file,data.firstSkippedPattern,data.lineBudgetBreaks,data.regexTimeouts,data.oversizedLines,data.unanchoredPatterns,data.linesRead,' +
-  'data.overwriteRewinds,data.overwriteBytesReprocessed,' +
+  'data.overwriteRewinds,data.overwriteBytesReprocessed,data.passMaxMs,data.passGapMaxMs,' +
   'data.collector,data.reason,data.errorType,' +
   'data.pendingItemCount,data.pendingBytes,data.kind,data.itemCount,data.disk_free_gb,' +
   'data.truncated,data.includedFiles,data.includedBytes,data.skippedFiles,data.skippedByReason,data.problemsByKind,' +
@@ -94,8 +94,18 @@ export interface ImeTrackerCoverage {
      */
     overwriteRewinds: number | null;
     overwriteBytesReprocessed: number | null;
+    /**
+     * Longest poll pass and longest pause between two passes, ms (agents after 2.0.1460). The
+     * loop sleeps 100 ms between passes; a pause of seconds means it was not scheduled — lines
+     * written meanwhile were read late, never lost (every event keeps its log line's timestamp).
+     */
+    passMaxMs: number | null;
+    passGapMaxMs: number | null;
   };
-  /** Present when overwriteRewinds > 0: says in words that those blocks were recovered, not lost. */
+  /**
+   * Present when overwriteRewinds > 0 or the poll loop paused for 5 s or longer: says in words
+   * that those blocks were recovered / those lines were read late — not lost.
+   */
   note?: string;
 }
 
@@ -287,6 +297,8 @@ export function buildSessionCoverage(
         oversizedLines: num(hits.data?.oversizedLines),
         overwriteRewinds: num(hits.data?.overwriteRewinds),
         overwriteBytesReprocessed: num(hits.data?.overwriteBytesReprocessed),
+        passMaxMs: num(hits.data?.passMaxMs),
+        passGapMaxMs: num(hits.data?.passGapMaxMs),
       }
     : undefined;
   // IME processes append to AgentExecutor.log and IntuneManagementExtension.log with independent
@@ -299,6 +311,19 @@ export function buildSessionCoverage(
         `${sessionTotals?.overwriteBytesReprocessed ? ` (${Math.round(sessionTotals.overwriteBytesReprocessed / 1024)} KB)` : ''}` +
         ' — script results and exit codes in them are complete, not missing.'
       : undefined;
+  // The poll loop sleeps 100 ms between passes; a pause of seconds (session c3ecb568: 26 s at
+  // 100 % VM CPU while the rest of the agent ran) delays the reading of every log line written
+  // meanwhile. Late, not lost: events keep their log line's timestamp and a result read before
+  // its executor end block waits for it — a note, never a gap.
+  const stallNoteMs = 5_000;
+  const passMaxMs = sessionTotals?.passMaxMs ?? 0;
+  const passGapMaxMs = sessionTotals?.passGapMaxMs ?? 0;
+  const stallNote =
+    Math.max(passMaxMs, passGapMaxMs) >= stallNoteMs
+      ? `The IME log tracker paused for up to ${Math.round(Math.max(passMaxMs, passGapMaxMs) / 1000)} s` +
+        ` (longest pass ${(passMaxMs / 1000).toFixed(1)} s, longest gap between passes ${(passGapMaxMs / 1000).toFixed(1)} s)` +
+        " — lines written meanwhile were read late, not lost: every event keeps its log line's own timestamp."
+      : undefined;
   let imeTracker: ImeTrackerCoverage;
   if (degradedEv) {
     imeTracker = {
@@ -330,7 +355,8 @@ export function buildSessionCoverage(
   } else {
     imeTracker = { degraded: false, ...(sessionTotals ? { sessionTotals } : {}) };
   }
-  if (overwriteNote) imeTracker.note = overwriteNote;
+  const notes = [overwriteNote, stallNote].filter((n): n is string => !!n);
+  if (notes.length > 0) imeTracker.note = notes.join(' ');
 
   // ── Collectors ──────────────────────────────────────────────────────────────
   const collectors: CollectorDegradation[] = [];