fix(agent): IME per-line matching budget counts Regex.Match time only — the wall-clock window also held the match handlers and scheduler stalls, and session 946ccbd6 (Hyper-V guest, 5–10 s process-wide stalls, 1 MB log, no line over 5 KB) broke it twice on genuine lines and silently skipped their remaining patterns; ime_pattern_hits is Debug severity (operator/backend signal, hidden from the default timeline — the IME Tracker card and the ingest fold read it regardless); the session page's IME Tracker card moves to the right column under Hardware

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-10-24 04:32:32 +00:00 · 2026-08-30 16:00:28 +02:00
parent 4f021852ee
commit 74902bf185
8 changed files with 99 additions and 50 deletions
@@ -73,10 +73,15 @@ completion) queue behind that work — a monitoring blackout during the enrollme
  capped prefix opens a CMTrace entry without closing it, the existing `skippingDroppedEntry`
  mechanism skips the entry's continuation lines instead of raw-matching them; a line that
  opens a *new* entry always ends the skip and is processed itself.
-* **Per-line matching budget.** `MatchLine` runs all active patterns under a 2 s Stopwatch
-  budget; a pattern that times out is skipped and counted, and once the budget is spent the
-  remaining patterns are skipped for that line (matches already handled stand). No genuine line
-  comes near it — the budget exists for unanchored custom patterns and hostile input.
+* **Per-line matching budget.** `MatchLine` runs all active patterns under a 2 s budget that
+  sums only the time spent inside `Regex.Match` on that line; a pattern that times out is
+  skipped and counted, and once the budget is spent the remaining patterns are skipped for that
+  line (matches already handled stand). No genuine line comes near it — the budget exists for
+  unanchored custom patterns and hostile input. It is deliberately not the wall-clock across
+  the pattern loop: that window also holds the match handlers (signal ingress, match-log
+  append) and scheduler stalls, and session 946ccbd6 (2026-08-30, Hyper-V guest with 5–10 s
+  process-wide stalls, 1 MB log, no line over 5 KB) broke the wall-clock budget twice on
+  genuine lines and skipped their remaining patterns.
 * **Held-back tails.** An unterminated tail at EOF (a physical line without `\n`, or a
  multiline entry without `]LOG]!>`) is normally the writer mid-write. Instead of dropping it
  (and raw-matching its remainder next pass) the bookmark stays at the entry start. The hold
@@ -41,7 +41,9 @@ idle/stall clocks (`SignalActivityClassifier`).
  the whole session via the persisted histogram) the handler emits `ime_pattern_hits`:
  `hits` = every ENABLED pattern ID → match count, zeros included, plus the health counters and
  `imeVersion` (IME's own "Agent version is:" line). Only sessions with a terminal run report —
-  crashes/kills are outside the denominator by construction.
+  crashes/kills are outside the denominator by construction. Severity is Debug: the event is an
+  operator/backend signal, hidden from the default session timeline; the session page's
+  "IME Tracker" card and the ingest fold read it regardless of severity.
 * **Ingest.** `EventIngestProcessor` hands the event to `ImePatternHealthService` fire-and-forget:
  IDs are filtered against `BuiltInImeLogPatterns.BuiltInPatternIds` (a device may only claim an
  ID; tenant custom IDs never reach the global table), the version must pass
@@ -1,5 +1,9 @@
 # Log

+## 2026-08-30 (10)
+
+* **Update**: `agent/ime-log-tracker-matching-budget.md` — the per-line budget sums only `Regex.Match` time; the previous wall-clock window also counted match handlers and scheduler stalls and broke twice on genuine lines of a stalled Hyper-V guest (session 946ccbd6). `backend/ime-pattern-health.md` — `ime_pattern_hits` is Debug severity (operator signal, hidden from the default timeline; the IME Tracker card and the ingest fold read it regardless). The session page's "IME Tracker" card moved to the right column.
+
 ## 2026-08-30 (9)

 * **New**: `backend/ime-pattern-health.md` — the pattern-drift loop: `ImeTrackerHealth` counters + per-pattern histogram in the agent (restart-safe via `ImeTrackerState`), `ime_*` keys in `agent_metrics_snapshot`, one-shot `ime_tracker_degraded` Warning, session-end `ime_pattern_hits` (every enabled pattern, zeros included, `imeVersion`), backend `ImePatternStats` (PK = IME version, batch upsert, permanent), `ImePatternDriftEvaluator` (baseline = biggest version ≥100 sessions, expected = ≥0.8 hit rate, drift = 0 hits in ≥25 sessions, once per cell) → `ImePatternDriftSuspected` ops event, `GET metrics/ime-pattern-health` (GlobalReadOrAdmin), web section `admin/metrics/ime-pattern-health` + session-page "IME Tracker" rows, MCP `get_ime_pattern_health`. Registered in `index.md`.
@@ -139,6 +139,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
            Assert.Equal(1, fired); // the persisted flag suppressed the second emission
        }

+        [Fact]
+        public async Task Handler_time_does_not_count_against_the_line_budget()
+        {
+            // Session 946ccbd6: a stalled Hyper-V guest spent >2 s between two patterns of one
+            // genuine line and the wall-clock budget skipped the rest of the line. The budget
+            // bounds Regex.Match time only — a slow handler on an early pattern must leave the
+            // later patterns of the same line running and must not count as skipped work.
+            using var h = new Harness();
+            h.Tracker.OnPatternMatched = id => { if (id == "T-MARK") Thread.Sleep(2300); };
+            h.Append(Entry("marker 1 loose 1") + "\n");
+            await h.Pass();
+
+            var health = h.Tracker.GetHealthSnapshot();
+            Assert.Equal(1, health.PatternHits["T-MARK"]);
+            Assert.Equal(1, health.PatternHits["T-LOOSE"]); // ordered after T-MARK — still matched
+            Assert.Equal(0, health.BudgetBreaks);
+            Assert.False(health.HasSkippedWork);
+        }
+
        [Fact]
        public void Ime_agent_version_is_captured_from_the_pattern_action()
        {
@@ -341,14 +341,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
        /// pattern that times out is skipped (counted); once the aggregate budget is spent the
        /// remaining patterns are skipped for this line (counted, first skipped ID recorded) —
        /// matches already handled on this line stand.
+        /// <para>
+        /// The budget is the SUM of the time spent inside <c>Regex.Match</c> on this line — the
+        /// cost the budget exists to bound (hostile input × unanchored custom patterns). It is
+        /// deliberately not the wall-clock from the first to the last pattern: that window also
+        /// contains the match handlers (signal ingress, match-log append, state writes) and
+        /// whatever the scheduler does to this thread in between. Session 946ccbd6 (2026-08-30)
+        /// recorded two budget breaks on a 1 MB `AppWorkload.log` with no line over 5 KB — the
+        /// Hyper-V guest had stalled the whole process for 5–10 s mid-line — and each break
+        /// silently skipped the remaining patterns of a genuine line.
+        /// </para>
        /// </summary>
        private void MatchLine(string filePath, string line, string messageToMatch, CmTraceLogEntry entry, PassStats stats)
        {
-            var started = Stopwatch.GetTimestamp();
+            long matchTicks = 0;
            for (var i = 0; i < _activePatterns.Count; i++)
            {
                var pattern = _activePatterns[i];
-                if (Stopwatch.GetTimestamp() - started > LineMatchBudgetTicks)
+                if (matchTicks > LineMatchBudgetTicks)
                {
                    stats.BudgetBreaks++;
                    _budgetBreaks++;
@@ -356,22 +366,28 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
                    return;
                }

+                Match match;
+                var matchStarted = Stopwatch.GetTimestamp();
                try
                {
-                    var match = pattern.Regex.Match(messageToMatch);
-                    if (match.Success)
-                    {
-                        RecordPatternHit(pattern.PatternId);
-                        WriteMatchLog(filePath, line, pattern.PatternId);
-                        HandlePatternMatch(pattern, match, messageToMatch, entry);
-                    }
+                    match = pattern.Regex.Match(messageToMatch);
                }
                catch (RegexMatchTimeoutException)
                {
+                    matchTicks += Stopwatch.GetTimestamp() - matchStarted;
                    stats.RegexTimeouts++;
                    _regexTimeouts++;
                    if (_timeoutLoggedPatternIds.Add(pattern.PatternId))
                        _logger.Debug($"ImeLogTracker: regex timeout for pattern '{pattern.PatternId}' (message length {messageToMatch.Length}) — skipped; further timeouts of this pattern are only counted");
+                    continue;
+                }
+                matchTicks += Stopwatch.GetTimestamp() - matchStarted;
+
+                if (match.Success)
+                {
+                    RecordPatternHit(pattern.PatternId);
+                    WriteMatchLog(filePath, line, pattern.PatternId);
+                    HandlePatternMatch(pattern, match, messageToMatch, entry);
                }
            }
        }
@@ -544,7 +544,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
        /// <summary>
        /// Emits <c>ime_pattern_hits</c>: per-pattern match counts for every enabled IME log
        /// pattern (zeros included — "active but never matched" IS the drift signal) plus the
-        /// tracker's cumulative health counters. Best-effort like the app summary.
+        /// tracker's cumulative health counters. Best-effort like the app summary. Debug
+        /// severity: it is an operator/backend signal, not something a tenant admin acts on —
+        /// the default timeline hides it, the session page's IME Tracker card and the backend
+        /// fold still read it.
        /// </summary>
        private void EmitImePatternHits()
        {
@@ -590,7 +593,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination
                    SessionId = _configuration.SessionId,
                    TenantId = _configuration.TenantId,
                    EventType = Constants.EventTypes.ImePatternHits,
-                    Severity = EventSeverity.Info,
+                    Severity = EventSeverity.Debug,
                    Source = "EnrollmentTerminationHandler",
                    Phase = EnrollmentPhase.Unknown,
                    Message = $"IME pattern hits: {matchedPatterns}/{health.PatternHits.Count} patterns matched, {health.EntriesMatched} matches over {health.LinesRead} lines" +
@@ -439,7 +439,7 @@ namespace AutopilotMonitor.Shared
            public const string RegistryAppBaseline       = "registry_app_baseline";     // Info, one-shot at agent start (only when non-empty): summary of the Win32Apps state that PREDATES this agent run. Closes the WDP pre-agent gap — DPP-policy apps install in Batch 1 before the bootstrap-script agent exists, so their outcomes live only in this baseline (typed payload capped at 50 apps).
            public const string AppStateReconciliation    = "app_state_reconciliation";  // Warning, once per app, immediate upload: registry terminal outcome (settled >= 90 s) diverges from the IME-log-derived app state — the built-in log-pattern drift alarm (registry = truth, logs = narrative).
            public const string ImeTrackerDegraded        = "ime_tracker_degraded";      // Warning, one-shot per session, immediate upload: a log-tracker pass skipped work (oversized lines dropped, regex timeouts, per-line budget breaks). Expected value in the fleet is "never" — any occurrence means hostile or malformed input in the IME Logs folder.
-            public const string ImePatternHits            = "ime_pattern_hits";          // Info, once per session at termination: per-pattern match counts for every enabled IME log pattern (zeros included) + tracker health counters. Backend aggregates per IME version (ImePatternStats) — the pattern-drift signal.
+            public const string ImePatternHits            = "ime_pattern_hits";          // Debug (operator signal, hidden from the default timeline), once per session at termination: per-pattern match counts for every enabled IME log pattern (zeros included) + tracker health counters. Backend aggregates per IME version (ImePatternStats) — the pattern-drift signal.
            public const string ImeUserSessionCompleted   = "ime_user_session_completed";
            public const string DoTelemetry               = "do_telemetry";
            public const string AllAppsCompleted          = "all_apps_completed";
@@ -387,38 +387,6 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session
              </DetailSection>
            )}

-            {/* IME log tracker health: queue depth + skip counters from the periodic snapshot,
-                session totals from the terminal ime_pattern_hits event. Skip counters are
-                expected to be 0 — any other value is a reason to look at the client log. */}
-            {(imeTracker || patternHits) && (
-              <DetailSection title="IME Tracker">
-                {imeTracker?.ime_files_tailed !== undefined && (
-                  <DetailRow label="Log files tailed" value={String(imeTracker.ime_files_tailed)} />
-                )}
-                {imeTracker?.ime_backlog_bytes !== undefined && (
-                  <DetailRow label="Unread backlog" value={Number(imeTracker.ime_backlog_bytes) > 0 ? formatBytesCompact(Number(imeTracker.ime_backlog_bytes)) : "0 (caught up)"} />
-                )}
-                {(patternHits?.linesRead ?? imeTracker?.ime_lines_read) !== undefined && (
-                  <DetailRow label="Lines read" value={Number(patternHits?.linesRead ?? imeTracker?.ime_lines_read).toLocaleString()} />
-                )}
-                {(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched) !== undefined && (
-                  <DetailRow label="Pattern matches" value={Number(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched).toLocaleString()} />
-                )}
-                {patternHits?.matchedPatterns !== undefined && patternHits?.patternCount !== undefined && (
-                  <DetailRow label="Patterns matched" value={`${patternHits.matchedPatterns} / ${patternHits.patternCount}`} />
-                )}
-                <DetailRow
-                  label="Skipped work"
-                  value={imeSkips > 0
-                    ? `${imeSkipParts.join(", ")} — see ime_tracker_degraded`
-                    : "none"}
-                />
-                {(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) !== undefined && Number(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) > 0 && (
-                  <DetailRow label="Unanchored patterns" value={String(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns)} />
-                )}
-              </DetailSection>
-            )}
-
            {/* Security */}
            {(bitLockerStatus || secureBootStatus || tpmStatus) && (
              <DetailSection title="Security">
@@ -475,7 +443,7 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session
            )}
          </div>

-          {/* Right Column: System, Autopilot Profile, Hardware */}
+          {/* Right Column: System, Autopilot Profile, Hardware, IME Tracker */}
          <div className="flex-1 flex flex-col gap-6">
            {/* System */}
            {(estimatedBootTime || agentStarted?.agentVersion || imeVersion || realmJoinInfo?.productVersion || aadJoinStatus?.joinType || deviceLocation?.country || deviceLocation?.Country || deviceLocation?.timezone || deviceLocation?.Timezone) && (
@@ -668,6 +636,38 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session
                })}
              </DetailSection>
            )}
+
+            {/* IME log tracker health: queue depth + skip counters from the periodic snapshot,
+                session totals from the terminal ime_pattern_hits event. Skip counters are
+                expected to be 0 — any other value is a reason to look at the client log. */}
+            {(imeTracker || patternHits) && (
+              <DetailSection title="IME Tracker">
+                {imeTracker?.ime_files_tailed !== undefined && (
+                  <DetailRow label="Log files tailed" value={String(imeTracker.ime_files_tailed)} />
+                )}
+                {imeTracker?.ime_backlog_bytes !== undefined && (
+                  <DetailRow label="Unread backlog" value={Number(imeTracker.ime_backlog_bytes) > 0 ? formatBytesCompact(Number(imeTracker.ime_backlog_bytes)) : "0 (caught up)"} />
+                )}
+                {(patternHits?.linesRead ?? imeTracker?.ime_lines_read) !== undefined && (
+                  <DetailRow label="Lines read" value={Number(patternHits?.linesRead ?? imeTracker?.ime_lines_read).toLocaleString()} />
+                )}
+                {(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched) !== undefined && (
+                  <DetailRow label="Pattern matches" value={Number(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched).toLocaleString()} />
+                )}
+                {patternHits?.matchedPatterns !== undefined && patternHits?.patternCount !== undefined && (
+                  <DetailRow label="Patterns matched" value={`${patternHits.matchedPatterns} / ${patternHits.patternCount}`} />
+                )}
+                <DetailRow
+                  label="Skipped work"
+                  value={imeSkips > 0
+                    ? `${imeSkipParts.join(", ")} — see ime_tracker_degraded`
+                    : "none"}
+                />
+                {(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) !== undefined && Number(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) > 0 && (
+                  <DetailRow label="Unanchored patterns" value={String(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns)} />
+                )}
+              </DetailSection>
+            )}
          </div>
        </div>
      )}