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-10-24 04:32:32 +00:00 · 2026-09-11 02:52:43 +02:00
parent 6657c6b9c0
commit 106480ef52
9 changed files with 167 additions and 31 deletions
@@ -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",
@@ -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);
+        }
    }
 }
@@ -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;