Compare commits

...

9 Commits

Author SHA1 Message Date
Oliver Kieselbach 5a62714dc2 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>
2026-09-11 03:46:37 +02:00
Oliver Kieselbach c930d18f1e feat(agent,mcp): the IME log tracker's poll-loop pauses become measurable — longest pass and longest gap between passes as session maxima in agent_metrics_snapshot, ime_pattern_hits and the MCP coverage block (B-wr4)
Test-VM session c3ecb568 (2.0.1460): the tracker loop was not scheduled for 26 s at 100 %
VM CPU while the rest of the agent kept running; five results were read before their
executor end blocks — held and completed correctly (D-247) — and nothing in the fleet
telemetry could have shown the pause (ime_backlog_bytes is an instantaneous value).

- ImeLogTracker.RunPollPassAsync hosts the loop body (file reads, the pending-completion
  flush, the token-failure window) and times it on a monotonic clock (MonotonicMillisProvider,
  Stopwatch in production): PassMaxMs = longest single pass (time INSIDE — reads, ledger
  verification, regex), PassGapMaxMs = longest pause between the end of one pass and the
  start of the next (the 100 ms delay, SaveState and any scheduling delay). Restart-safe
  like the other health counters (TrackerHealthData); ImeTrackerHealth carries both.
- agent_metrics_snapshot: ime_pass_max_ms / ime_pass_gap_max_ms; ime_pattern_hits:
  passMaxMs / passGapMaxMs.
- MCP session coverage: sessionTotals.passMaxMs / passGapMaxMs, and from 5 s on a note that
  says the lines were read late, not lost — every event keeps its log line's timestamp; the
  overwrite note and the pause note join when both apply.
- Tests: ImeLogTrackerPollTimingTests (maxima over three passes with a fake clock, fresh
  tracker at zero, restart keeps and never lowers them); MCP coverage tests for the note
  threshold. Agent suite 2941 green, solution build 0 warnings, MCP tsc clean.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-11 03:41:43 +02:00
Oliver Kieselbach 583c81c9a8 chore(submodule): IME overwrite fix verified in the field (2.0.1460, five held results), B-pd2/B-2rs closed, B-wr4 opened
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-11 03:26:40 +02:00
Oliver Kieselbach 483ec8b8e0 Merge branch 'main' of https://github.com/okieselbach/AutopilotMonitor 2026-09-11 02:55:29 +02:00
Oliver Kieselbach 328446864a chore(submodule): todo for P5 of the IME overwrite fix
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-11 02:53:02 +02:00
Oliver Kieselbach 106480ef52 fix(agent,rules): health-script lines never feed a platform-script slot — PS-SCRIPT-EXITCODE deleted, HS-INVOCATION opens an unowned invocation in the IME log, the no-marker fallback stays within files platform runs open in (D-248)
Test-VM session 24dc69d1 (2.0.1459) had the overwrite geometry the result hold (D-247)
was built for, yet the hold never fired: "Powershell execution is done, exitCode = 0" —
written by IME's health-script worker (AgentCommon ScriptWorker) to both
IntuneManagementExtension.log and HealthScripts.log — was read as PS-SCRIPT-EXITCODE and
attributed to the pending platform script c81b8053 1.2 s before its executor even started
(IME-log marker: the last PS-SCRIPT-GENERATED; HealthScripts.log: the no-marker fallback to
the last platform start). The completion went out at the result line with the foreign exit
code, and the run's own end block, recovered 150 ms later by the rewind, was dropped as
already emitted. Both codes were 0 by luck; a failing health script would have turned a
succeeded platform script into script_failed. The worker's launch line flipped the pending
script's context the same way (338d9434, twice in one run).

- rules: PS-SCRIPT-EXITCODE deleted — the line is health-script-only (3 hits = 3 cycles,
  platform scripts never produce it), HS-EXITCODE already carries the value, and a line that
  lands inside a parallel platform run's window cannot be attributed by position.
  HS-INVOCATION (new): the worker's command line `"…\agentexecutor.exe"  -remediationScript`
  (identical from IME 1.104.102 to 1.105.152) as agentInvocationArgument of a non-powershell
  kind — the launch line it writes next stays with that invocation. Both take effect on the
  next reseed for every agent from 2.0.1458 on.
- tracker: a file without markers resolves to the platform run in flight only when a
  platform run has ever opened in that file (IntuneManagementExtension.log after a rollover,
  AgentExecutor.log); HealthScripts.log and the app logs never qualify. Test seams:
  ProcessLogMessageForTest takes the source file, ClearInvocationMarkersForTest.
- tests: ImeLogTrackerPlatformScriptContaminationTests +5 with the session's real lines —
  the worker's exit line pre-fills nothing, its launch line flips no context, HealthScripts.log
  lines resolve to no platform script, the context line after an IME-log rollover still finds
  the run in flight, and no shipped pattern reads the worker's exit line.
- rules/dist regenerated (node rules/scripts/combine.js); analyze-rules.json catches up with
  ANALYZE-OFFICE-001 1.1.1 (6657c6b9 was committed without its dist).

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-11 02:52:43 +02:00
github-actions[bot] d3a45f958d chore: regenerate rules/dist + generated TS from individual files 2026-09-11 00:29:54 +00:00
Oliver Kieselbach 6657c6b9c0 fix(rules): ANALYZE-OFFICE-001 explains what the detector actually reports
office_install_failed is emitted only for an error code in the C2R INSTALL scenario; a window without on-disk proof ends silently. The old text described a StreamingFinished-based failure and attributed the early "done" of the built-in app type to IME, which never sees Office CSP installs. Text only, version 1.1.1.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-11 02:28:12 +02:00
Oliver Kieselbach 6c5e2fd921 chore(submodule): IME overwrite plan closed as RELEASED after the 2.0.1459 test-VM run
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-11 02:04:14 +02:00
18 changed files with 394 additions and 53 deletions
+4 -4
View File
@@ -2,10 +2,10 @@
"$schema": "../schema/analyze-rule.schema.json",
"ruleId": "ANALYZE-OFFICE-001",
"title": "Microsoft 365 Apps Install Failed",
"description": "Detects when the Microsoft 365 Apps (Office Click-to-Run) background install did not reach completion. The V2 OfficeInstallDetector watches the C2R client directly (registry + process) and emits office_install_failed when the install scenario was abandoned (worker gone and streaming never finished) or a C2R failure code was observed. This catches Office failures that the Intune integrated app type hides, because IME reports the app done within 1-2 minutes while C2R keeps installing in the background.",
"description": "Detects when the Microsoft 365 Apps (Office Click-to-Run) install failed. The V2 OfficeInstallDetector watches the C2R client directly (registry, Delivery Optimization, process) and emits office_install_failed when the C2R INSTALL scenario records an error code. Completion is proven by the core Office binaries on disk; an install window that closes without that proof ends silently, never as a failure. This catches Office failures the deployment status hides: the Intune built-in app type is marked done once the configuration is delivered, and a Win32 or RealmJoin package once its installer exits, while C2R keeps installing in the background.",
"severity": "warning",
"category": "apps",
"version": "1.1.0",
"version": "1.1.1",
"enabled": true,
"evaluateOn": [
"enrollment_end",
@@ -39,12 +39,12 @@
}
],
"confidenceThreshold": 40,
"explanation": "The Microsoft 365 Apps (Office Click-to-Run) install did not finish.\n\nThe OfficeInstallDetector watches the C2R client directly and reports the real background install lifecycle. The Intune \"integrated\" Microsoft 365 Apps app type only pushes the configuration XML and starts the C2R bootstrapper, so IME marks the app done within 1-2 minutes while C2R keeps streaming and laying down the product for several more minutes. This event means C2R activity ended (the OfficeC2RClient worker exited and the install scenario cleared) without the StreamingFinished flag being set, or a C2R failure code was observed.\n\nReview the office_install_failed event payload: `products`, `channel`, `phase`, `streamingFinished`, `errorCode` (best-effort — may be empty) and `durationSeconds`.",
"explanation": "The Microsoft 365 Apps (Office Click-to-Run) install failed.\n\nThe OfficeInstallDetector watches the C2R client directly and reports the real install lifecycle, however it was started. The Intune built-in Microsoft 365 Apps app type delivers the configuration through the Office CSP and lets the device start C2R; a Win32 or RealmJoin package runs the Office Deployment Tool. Either way the deployment is marked done before C2R has finished laying down the product. This event means C2R recorded an error code in its INSTALL scenario before the core Office apps were on disk.\n\nReview the office_install_failed event payload: `products`, `channel`, `errorCode`, `errorSource` (the C2R registry value that carried the code) and `durationSeconds`.",
"remediation": [
{
"title": "Investigate the Office C2R install failure",
"steps": [
"Open the office_install_failed event and review products, channel, phase, streamingFinished and errorCode",
"Open the office_install_failed event and review products, channel, errorCode and errorSource",
"Check the Click-to-Run logs on the device (%windir%\\Temp and %temp%, files named <MachineName>-yyyymmdd-nnnn.log) for the failing operation",
"Verify the device had network reachability to the Office CDN / Microsoft Connected Cache during the enrollment window",
"Confirm the Intune Microsoft 365 Apps app configuration (products, channel, architecture) matches what the device can install",
+4 -4
View File
@@ -3246,10 +3246,10 @@
{
"ruleId": "ANALYZE-OFFICE-001",
"title": "Microsoft 365 Apps Install Failed",
"description": "Detects when the Microsoft 365 Apps (Office Click-to-Run) background install did not reach completion. The V2 OfficeInstallDetector watches the C2R client directly (registry + process) and emits office_install_failed when the install scenario was abandoned (worker gone and streaming never finished) or a C2R failure code was observed. This catches Office failures that the Intune integrated app type hides, because IME reports the app done within 1-2 minutes while C2R keeps installing in the background.",
"description": "Detects when the Microsoft 365 Apps (Office Click-to-Run) install failed. The V2 OfficeInstallDetector watches the C2R client directly (registry, Delivery Optimization, process) and emits office_install_failed when the C2R INSTALL scenario records an error code. Completion is proven by the core Office binaries on disk; an install window that closes without that proof ends silently, never as a failure. This catches Office failures the deployment status hides: the Intune built-in app type is marked done once the configuration is delivered, and a Win32 or RealmJoin package once its installer exits, while C2R keeps installing in the background.",
"severity": "warning",
"category": "apps",
"version": "1.1.0",
"version": "1.1.1",
"enabled": true,
"evaluateOn": [
"enrollment_end",
@@ -3283,12 +3283,12 @@
}
],
"confidenceThreshold": 40,
"explanation": "The Microsoft 365 Apps (Office Click-to-Run) install did not finish.\n\nThe OfficeInstallDetector watches the C2R client directly and reports the real background install lifecycle. The Intune \"integrated\" Microsoft 365 Apps app type only pushes the configuration XML and starts the C2R bootstrapper, so IME marks the app done within 1-2 minutes while C2R keeps streaming and laying down the product for several more minutes. This event means C2R activity ended (the OfficeC2RClient worker exited and the install scenario cleared) without the StreamingFinished flag being set, or a C2R failure code was observed.\n\nReview the office_install_failed event payload: `products`, `channel`, `phase`, `streamingFinished`, `errorCode` (best-effort — may be empty) and `durationSeconds`.",
"explanation": "The Microsoft 365 Apps (Office Click-to-Run) install failed.\n\nThe OfficeInstallDetector watches the C2R client directly and reports the real install lifecycle, however it was started. The Intune built-in Microsoft 365 Apps app type delivers the configuration through the Office CSP and lets the device start C2R; a Win32 or RealmJoin package runs the Office Deployment Tool. Either way the deployment is marked done before C2R has finished laying down the product. This event means C2R recorded an error code in its INSTALL scenario before the core Office apps were on disk.\n\nReview the office_install_failed event payload: `products`, `channel`, `errorCode`, `errorSource` (the C2R registry value that carried the code) and `durationSeconds`.",
"remediation": [
{
"title": "Investigate the Office C2R install failure",
"steps": [
"Open the office_install_failed event and review products, channel, phase, streamingFinished and errorCode",
"Open the office_install_failed event and review products, channel, errorCode and errorSource",
"Check the Click-to-Run logs on the device (%windir%\\Temp and %temp%, files named <MachineName>-yyyymmdd-nnnn.log) for the failing operation",
"Verify the device had network reachability to the Office CDN / Microsoft Connected Cache during the enrollment window",
"Confirm the Intune Microsoft 365 Apps app configuration (products, channel, architecture) matches what the device can install",
+8 -8
View File
@@ -34,6 +34,14 @@
"description": "Captures the exit code of a health-script execution. Feeds the early-signal slot consumed by HS-COMPLIANCE so the user sees the real exit code (not just the inferred 0/1) before HS-NEW-RESULT arrives.",
"enabled": true
},
{
"patternId": "HS-INVOCATION",
"category": "always",
"pattern": "^\"[^\"]{0,260}\\\\agentexecutor\\.exe\"\\s+-(?<kind>remediationScript)\\s",
"action": "agentInvocationArgument",
"description": "The IME service's command line for a health-script executor, written by the health-script worker to IntuneManagementExtension.log and HealthScripts.log right before 'Launch powershell executor in ... session'. Opens an invocation that owns nothing, so the launch line the same worker writes next never sets the context of the platform script whose run is in flight in the IME log. The platform-script command line ('-powershell') does not match.",
"enabled": true
},
{
"patternId": "HS-NEW-RESULT",
"category": "always",
@@ -724,14 +732,6 @@
"description": "Captures whether a PowerShell script runs in machine (System) or user session context.",
"enabled": true
},
{
"patternId": "PS-SCRIPT-EXITCODE",
"category": "always",
"pattern": "^Powershell execution is done, exitCode = (?<exitCode>-?\\d+)",
"action": "scriptExitCode",
"description": "Captures the PowerShell exit code when script execution completes in the IME log.",
"enabled": true
},
{
"patternId": "PS-SCRIPT-GENERATED",
"category": "always",
@@ -0,0 +1,9 @@
{
"$schema": "../schema/ime-log-pattern.schema.json",
"patternId": "HS-INVOCATION",
"category": "always",
"pattern": "^\"[^\"]{0,260}\\\\agentexecutor\\.exe\"\\s+-(?<kind>remediationScript)\\s",
"action": "agentInvocationArgument",
"description": "The IME service's command line for a health-script executor, written by the health-script worker to IntuneManagementExtension.log and HealthScripts.log right before 'Launch powershell executor in ... session'. Opens an invocation that owns nothing, so the launch line the same worker writes next never sets the context of the platform script whose run is in flight in the IME log. The platform-script command line ('-powershell') does not match.",
"enabled": true
}
@@ -1,9 +0,0 @@
{
"$schema": "../schema/ime-log-pattern.schema.json",
"patternId": "PS-SCRIPT-EXITCODE",
"category": "always",
"pattern": "^Powershell execution is done, exitCode = (?<exitCode>-?\\d+)",
"action": "scriptExitCode",
"description": "Captures the PowerShell exit code when script execution completes in the IME log.",
"enabled": true
}
@@ -36,8 +36,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
// silently passing against a stale inline copy.
private static readonly string[] RequiredPatternIds =
{
"PS-AGENT-INVOCATION", "PS-AGENT-SCRIPT-START", "PS-AGENT-EXITCODE",
"PS-AGENT-OUTPUT", "PS-SCRIPT-RESULT",
"PS-AGENT-INVOCATION", "PS-AGENT-ARG", "PS-AGENT-SCRIPT-START", "PS-AGENT-EXITCODE",
"PS-AGENT-OUTPUT", "PS-AGENT-COMPLETED", "PS-SCRIPT-GENERATED", "PS-SCRIPT-CONTEXT",
"PS-SCRIPT-RESULT", "HS-INVOCATION",
};
private static List<ImeLogPattern> ScriptPatterns()
@@ -83,6 +84,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
private const string RemediationStartLine =
@"Adding argument remediationScript with value C:\Windows\IMECache\HealthScripts\446f0450-d0ee-404c-8dc0-a74123bde31f_1\detect.ps1 to the named argument list.";
private const string ImeLog = "IntuneManagementExtension.log";
private const string HealthLog = "HealthScripts.log";
private const string ExecutorLog = "AgentExecutor.log";
private const string PlatformGeneratedLine =
@"Script file C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_c3e0124c-4936-4bfd-afcc-c7fe1d84d104.ps1 is generated";
private static readonly string PlatformResultLine =
$"[PowerShell] User Id = 00000000-0000-0000-0000-000000000000, Policy id = {PlatformId}, policy result = Success";
// The health-script worker (IME AgentCommon ScriptWorker) writes its command line, the launch
// line and the exit line to IntuneManagementExtension.log AND HealthScripts.log — session
// 24dc69d1 (IME 1.105.152.0), where the exit line pre-filled a pending platform script's exit
// code and the launch line its context.
private const string HealthScriptCommandLine =
@"""C:\Program Files (x86)\Microsoft Intune Management Extension\agentexecutor.exe"" -remediationScript """"C:\WINDOWS\IMECache\HealthScripts\446f0450-d0ee-404c-8dc0-a74123bde31f_1\detect.ps1"""" ""C:\WINDOWS\IMECache\HealthScripts\446f0450-d0ee-404c-8dc0-a74123bde31f_1\detect.ps1.result"" 60";
private const string HealthScriptExitLine = "Powershell execution is done, exitCode = 5";
private static ImeLogTracker BuildTracker(TempDirectory tmp, out List<ScriptExecutionState> emitted)
{
var captured = new List<ScriptExecutionState>();
@@ -149,5 +168,100 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.Equal(0, script.ExitCode);
Assert.Equal("Hello from c3e0124c", script.Stdout);
}
// -----------------------------------------------------------------------
// Health-script lines never feed a platform slot (session 24dc69d1)
// -----------------------------------------------------------------------
[Fact]
public void No_shipped_pattern_reads_the_health_script_workers_exit_line()
{
// "Powershell execution is done, exitCode = N" is the health-script worker's line only;
// as PS-SCRIPT-EXITCODE (no scriptType) it pre-filled the exit code of whichever platform
// script was pending, which then emitted without waiting for its own end block.
foreach (var file in Directory.GetFiles(FindRulesPatternDir(), "*.json"))
{
var pattern = JsonConvert.DeserializeObject<ImeLogPattern>(File.ReadAllText(file))!;
Assert.False(System.Text.RegularExpressions.Regex.IsMatch(HealthScriptExitLine, pattern.Pattern),
$"{pattern.PatternId} matches the health-script worker's exit line");
}
}
[Fact]
public void Health_script_exit_line_in_the_ime_log_never_pre_fills_the_platform_slot()
{
using var tmp = new TempDirectory();
var tracker = BuildTracker(tmp, out var emitted);
tracker.ProcessLogMessageForTest(PlatformGeneratedLine, sourceFileName: ImeLog);
// A health script that ran in parallel finishes: its exit line lands inside the platform
// run's window (c81b8053 had "exit code 0" before its executor even started).
tracker.ProcessLogMessageForTest(HealthScriptExitLine, sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest(PlatformResultLine, sourceFileName: ImeLog);
// No exit code of its own → held for the end block, never emitted with the health script's 5.
Assert.Empty(emitted);
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
var script = Assert.Single(emitted);
Assert.Null(script.ExitCode);
Assert.Equal("Success", script.Result);
}
[Fact]
public void Health_script_launch_line_in_the_ime_log_does_not_flip_the_platform_context()
{
using var tmp = new TempDirectory();
var tracker = BuildTracker(tmp, out var emitted);
tracker.ProcessLogMessageForTest(PlatformGeneratedLine, sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest("Launch powershell executor in user session", sourceFileName: ImeLog);
// The health-script worker launches its executor while the platform script runs: its
// command line opens an invocation that owns nothing, so its launch line stays there.
tracker.ProcessLogMessageForTest(HealthScriptCommandLine, sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest("Launch powershell executor in machine session", sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest(PlatformResultLine, sourceFileName: ImeLog);
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
var script = Assert.Single(emitted);
Assert.Equal("User", script.RunContext);
}
[Fact]
public void Lines_from_the_health_scripts_log_never_resolve_to_a_platform_script()
{
using var tmp = new TempDirectory();
var tracker = BuildTracker(tmp, out var emitted);
tracker.ProcessLogMessageForTest("ExecutorLog AgentExecutor gets invoked", sourceFileName: ExecutorLog);
tracker.ProcessLogMessageForTest(PlatformStartLine, sourceFileName: ExecutorLog);
// HealthScripts.log never carries a platform marker — the run in flight is not the
// fallback owner of the lines there.
tracker.ProcessLogMessageForTest("Launch powershell executor in machine session", sourceFileName: HealthLog);
tracker.ProcessLogMessageForTest(PlatformResultLine, sourceFileName: ImeLog);
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
var script = Assert.Single(emitted);
Assert.Null(script.RunContext);
}
[Fact]
public void Context_line_after_an_ime_log_rollover_still_finds_the_run_in_flight()
{
using var tmp = new TempDirectory();
var tracker = BuildTracker(tmp, out var emitted);
tracker.ProcessLogMessageForTest(PlatformGeneratedLine, sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest("ExecutorLog AgentExecutor gets invoked", sourceFileName: ExecutorLog);
tracker.ProcessLogMessageForTest(PlatformStartLine, sourceFileName: ExecutorLog);
// IME rolls the log over between its two lines: the fresh file has no markers, but
// platform runs open there — the run in flight still owns the context line.
tracker.ClearInvocationMarkersForTest(ImeLog);
tracker.ProcessLogMessageForTest("Launch powershell executor in user session", sourceFileName: ImeLog);
tracker.ProcessLogMessageForTest(PlatformResultLine, sourceFileName: ImeLog);
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
var script = Assert.Single(emitted);
Assert.Equal("User", script.RunContext);
}
}
}
@@ -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();
}
}
}
@@ -871,11 +871,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <c>_activePatterns</c> → <see cref="HandlePatternMatch"/>). Lets unit tests drive the
/// script / app handlers deterministically without writing CMTrace files or spinning the
/// poller. <paramref name="sourceTimestampUtc"/> populates the entry timestamp some
/// handlers read via <see cref="LastMatchedLogTimestamp"/>.
/// handlers read via <see cref="LastMatchedLogTimestamp"/>. <paramref name="sourceFileName"/>
/// names the log the line comes from — positional ownership is per file — and stays in
/// effect for later calls; omitted, the line lands in the test file.
/// </summary>
internal void ProcessLogMessageForTest(string message, DateTime? sourceTimestampUtc = null)
internal void ProcessLogMessageForTest(string message, DateTime? sourceTimestampUtc = null, string sourceFileName = null)
{
if (string.IsNullOrEmpty(message)) return;
if (sourceFileName != null) _currentSourceFileName = sourceFileName;
NextTestEntry();
// The test seam hands in an already-resolved UTC instant, so it takes the same route a
// writer-declared bias does: TimestampUtc set, no zone left to guess.
@@ -348,6 +348,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private readonly Dictionary<string, List<InvocationMarker>> _invocationMarkers =
new Dictionary<string, List<InvocationMarker>>(StringComparer.OrdinalIgnoreCase);
private InvocationMarker _lastPlatformMarker;
// Files a platform run has opened in (PS-AGENT-SCRIPT-START in AgentExecutor.log,
// PS-SCRIPT-GENERATED in IntuneManagementExtension.log). Survives a rollover of the
// file's markers: the fallback below is meant for exactly that file.
private readonly HashSet<string> _platformMarkerFiles = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
private long _testEntryOrdinal;
private void RecordInvocationMarker(string policyId, bool isClose)
@@ -370,6 +374,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
last.PolicyId = policyId;
last.IsClose = false;
_lastPlatformMarker = last;
_platformMarkerFiles.Add(file);
}
return;
}
@@ -377,7 +382,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (list.Count >= MaxInvocationMarkersPerFile) list.RemoveAt(0);
var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, IsClose = isClose };
list.Add(marker);
if (!isClose && policyId != null) _lastPlatformMarker = marker;
if (!isClose && policyId != null)
{
_lastPlatformMarker = marker;
_platformMarkerFiles.Add(file);
}
}
/// <summary>
@@ -388,9 +397,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private ScriptExecutionState ResolvePlatformScriptForCurrentEntry(out string ownerPolicyId)
{
ownerPolicyId = null;
var file = _currentSourceFileName ?? TestSourceFileName;
InvocationMarker marker = null;
List<InvocationMarker> list = null;
if (_currentSourceFileName != null && _currentEntryOffset >= 0 && _invocationMarkers.TryGetValue(_currentSourceFileName, out list))
if (_currentEntryOffset >= 0 && _invocationMarkers.TryGetValue(file, out list))
{
for (var i = list.Count - 1; i >= 0; i--)
{
@@ -402,8 +412,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
}
}
// A file without any marker (a context line after a rotation): the last platform start wins.
if (marker == null && (list == null || list.Count == 0)) marker = _lastPlatformMarker;
// A file without any marker resolves to the platform run in flight only when platform
// runs open in that file at all — IntuneManagementExtension.log right after a rollover
// cleared its markers, AgentExecutor.log likewise. HealthScripts.log and the app logs
// never carry a platform marker: their launch and exit lines belong to health scripts
// and detection scripts, never to the platform script that happens to be pending
// (session 24dc69d1: the health-script worker's exit line pre-filled a platform slot's
// exit code, its launch line the slot's context).
if (marker == null && (list == null || list.Count == 0) && _platformMarkerFiles.Contains(file)) marker = _lastPlatformMarker;
if (marker == null || marker.IsClose || marker.PolicyId == null) return null;
ownerPolicyId = marker.PolicyId;
@@ -455,6 +471,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <summary>Same effect as an end signal: both multi-writer ledgers are verified on the next pass.</summary>
internal void RequestOverwriteCheckForTest() => RequestOverwriteCheck();
/// <summary>What a rollover of the file does to its invocation markers.</summary>
internal void ClearInvocationMarkersForTest(string fileName) => InvalidateInvocationMarkersFrom(fileName, 0);
internal int LedgerEntryCountForTest(string fileName)
{
FileLedger ledger;
@@ -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);
}
@@ -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; }
@@ -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
@@ -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)
@@ -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))
@@ -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', () => {
@@ -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[] = [];