diff --git a/.claude/commands b/.claude/commands index cb96a972..13cfe49e 160000 --- a/.claude/commands +++ b/.claude/commands @@ -1 +1 @@ -Subproject commit cb96a972a06141d3387811777dfdef19878afb26 +Subproject commit 13cfe49e35707f3b14d5762af7a264db8e3590cb diff --git a/internal b/internal index 631b7d54..9fff74b0 160000 --- a/internal +++ b/internal @@ -1 +1 @@ -Subproject commit 631b7d540452d94cf260bfa1c77eaf05f03ece2d +Subproject commit 9fff74b09eea5074f2c5880183e4741761f86296 diff --git a/rules/dist/analyze-rules.json b/rules/dist/analyze-rules.json index ab52e2ee..6557d4a3 100644 --- a/rules/dist/analyze-rules.json +++ b/rules/dist/analyze-rules.json @@ -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 -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", diff --git a/rules/dist/ime-log-patterns.json b/rules/dist/ime-log-patterns.json index d466a31e..6f1d3350 100644 --- a/rules/dist/ime-log-patterns.json +++ b/rules/dist/ime-log-patterns.json @@ -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+-(?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 = (?-?\\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", diff --git a/rules/ime-log-patterns/HS-INVOCATION.json b/rules/ime-log-patterns/HS-INVOCATION.json new file mode 100644 index 00000000..d1fd8409 --- /dev/null +++ b/rules/ime-log-patterns/HS-INVOCATION.json @@ -0,0 +1,9 @@ +{ + "$schema": "../schema/ime-log-pattern.schema.json", + "patternId": "HS-INVOCATION", + "category": "always", + "pattern": "^\"[^\"]{0,260}\\\\agentexecutor\\.exe\"\\s+-(?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 +} diff --git a/rules/ime-log-patterns/PS-SCRIPT-EXITCODE.json b/rules/ime-log-patterns/PS-SCRIPT-EXITCODE.json deleted file mode 100644 index 15a59c6a..00000000 --- a/rules/ime-log-patterns/PS-SCRIPT-EXITCODE.json +++ /dev/null @@ -1,9 +0,0 @@ -{ - "$schema": "../schema/ime-log-pattern.schema.json", - "patternId": "PS-SCRIPT-EXITCODE", - "category": "always", - "pattern": "^Powershell execution is done, exitCode = (?-?\\d+)", - "action": "scriptExitCode", - "description": "Captures the PowerShell exit code when script execution completes in the IME log.", - "enabled": true -} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptContaminationTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptContaminationTests.cs index 11266ca8..a759f760 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptContaminationTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptContaminationTests.cs @@ -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 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 emitted) { var captured = new List(); @@ -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(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); + } } } 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 fdfb4ca1..a2c77928 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 @@ -871,11 +871,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// _activePatterns → ). Lets unit tests drive the /// script / app handlers deterministically without writing CMTrace files or spinning the /// poller. populates the entry timestamp some - /// handlers read via . + /// handlers read via . + /// 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. /// - 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. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs index 74600ab2..ae053c76 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Overwrite.cs @@ -348,6 +348,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private readonly Dictionary> _invocationMarkers = new Dictionary>(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 _platformMarkerFiles = new HashSet(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); + } } /// @@ -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 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 /// Same effect as an end signal: both multi-writer ledgers are verified on the next pass. internal void RequestOverwriteCheckForTest() => RequestOverwriteCheck(); + /// What a rollover of the file does to its invocation markers. + internal void ClearInvocationMarkersForTest(string fileName) => InvalidateInvocationMarkersFrom(fileName, 0); + internal int LedgerEntryCountForTest(string fileName) { FileLedger ledger;