diff --git a/docs/agent/ime-log-tracker-matching-budget.md b/docs/agent/ime-log-tracker-matching-budget.md index 2e442655..91859ef7 100644 --- a/docs/agent/ime-log-tracker-matching-budget.md +++ b/docs/agent/ime-log-tracker-matching-budget.md @@ -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 diff --git a/docs/backend/ime-pattern-health.md b/docs/backend/ime-pattern-health.md index 44d3b867..8270048c 100644 --- a/docs/backend/ime-pattern-health.md +++ b/docs/backend/ime-pattern-health.md @@ -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 diff --git a/docs/log.md b/docs/log.md index 4b9979df..544d8561 100644 --- a/docs/log.md +++ b/docs/log.md @@ -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`. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerHealthTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerHealthTests.cs index d7edf13d..ae53602f 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerHealthTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerHealthTests.cs @@ -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() { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs index 1c7fb9db..675c1f1f 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs @@ -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. + /// + /// The budget is the SUM of the time spent inside Regex.Match 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. + /// /// 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); } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs index 724cb6c2..430ecd4a 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs @@ -544,7 +544,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination /// /// Emits ime_pattern_hits: 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. /// 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" + diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs index c84c6912..a1a1974d 100644 --- a/src/Shared/AutopilotMonitor.Shared/Constants.cs +++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs @@ -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"; diff --git a/src/Web/autopilot-monitor-web/app/sessions/components/DeviceDetailsCard.tsx b/src/Web/autopilot-monitor-web/app/sessions/components/DeviceDetailsCard.tsx index 99265bed..b7d20e7d 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/components/DeviceDetailsCard.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/components/DeviceDetailsCard.tsx @@ -387,38 +387,6 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session )} - {/* 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) && ( - - {imeTracker?.ime_files_tailed !== undefined && ( - - )} - {imeTracker?.ime_backlog_bytes !== undefined && ( - 0 ? formatBytesCompact(Number(imeTracker.ime_backlog_bytes)) : "0 (caught up)"} /> - )} - {(patternHits?.linesRead ?? imeTracker?.ime_lines_read) !== undefined && ( - - )} - {(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched) !== undefined && ( - - )} - {patternHits?.matchedPatterns !== undefined && patternHits?.patternCount !== undefined && ( - - )} - 0 - ? `${imeSkipParts.join(", ")} — see ime_tracker_degraded` - : "none"} - /> - {(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) !== undefined && Number(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) > 0 && ( - - )} - - )} - {/* Security */} {(bitLockerStatus || secureBootStatus || tpmStatus) && ( @@ -475,7 +443,7 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session )} - {/* Right Column: System, Autopilot Profile, Hardware */} + {/* Right Column: System, Autopilot Profile, Hardware, IME Tracker */}
{/* 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 })} )} + + {/* 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) && ( + + {imeTracker?.ime_files_tailed !== undefined && ( + + )} + {imeTracker?.ime_backlog_bytes !== undefined && ( + 0 ? formatBytesCompact(Number(imeTracker.ime_backlog_bytes)) : "0 (caught up)"} /> + )} + {(patternHits?.linesRead ?? imeTracker?.ime_lines_read) !== undefined && ( + + )} + {(patternHits?.entriesMatched ?? imeTracker?.ime_entries_matched) !== undefined && ( + + )} + {patternHits?.matchedPatterns !== undefined && patternHits?.patternCount !== undefined && ( + + )} + 0 + ? `${imeSkipParts.join(", ")} — see ime_tracker_degraded` + : "none"} + /> + {(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) !== undefined && Number(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) > 0 && ( + + )} + + )}
)}