From 9a0211e17fb0554bc3dbca82d749895e6a625313 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 19 Jun 2026 16:32:10 +0200 Subject: [PATCH] fix(agent): emit platform-script completion from AgentExecutor exit code when IME result is late MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit V2 emitted script_completed for platform scripts ONLY on the IME PS-SCRIPT-RESULT line (IntuneManagementExtension.log). The AgentExecutor.log exit code + stdout merely filled _pendingPlatformScripts and never emitted on their own. IME logs its policy result after its batch-send to the service, so scripts that finish shortly before the (often short) Autopilot enrollment ends were silently dropped — the buffer is neither persisted nor flushed on dispose. Field-confirmed on session d1da052d: 4 platform scripts ran, only the long-running one (whose IME result was logged in time) reached the backend. Add a deadline-based fallback in the live polling loop: a pending platform script with a known exit code but no PS-SCRIPT-RESULT within a 15s grace is emitted from the exit code (0 -> Success, else Failed), tagged resultSource=agentexecutor_fallback so the provenance is honest. A force pass runs on shutdown. Dedup via _platformScriptResultEmitted prevents a double emit when the authoritative result arrives after the fallback; a fresh scriptStarted clears the marker so IME re-evaluations/retries of the same policy emit again. The fallback event binds to the script's own exit timestamp (not the last-matched line) and omits the stale patternId. Reuses script_completed/script_failed (no new event type, no ConfigVersion bump, no MCP catalog change). V2-only; legacy V1 agent unchanged. 1516/1516 V2.Core tests green. Co-Authored-By: Claude Opus 4.8 (1M context) --- ...meLogTrackerPlatformScriptFallbackTests.cs | 189 ++++++++++++++++++ ...meLogTrackerAdapterSourceTimestampTests.cs | 57 ++++++ .../Enrollment/Ime/ImeLogTracker.Handlers.cs | 154 ++++++++++++++ .../Enrollment/Ime/ImeLogTracker.cs | 12 ++ .../Enrollment/Ime/ScriptExecutionState.cs | 19 ++ .../SignalAdapters/ImeLogTrackerAdapter.cs | 38 +++- 6 files changed, 465 insertions(+), 4 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptFallbackTests.cs diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptFallbackTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptFallbackTests.cs new file mode 100644 index 00000000..7f16d7be --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptFallbackTests.cs @@ -0,0 +1,189 @@ +using System; +using System.Collections.Generic; +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 +{ + /// + /// Regression cover for the AgentExecutor exit-code fallback: platform scripts that complete + /// (exit code captured from AgentExecutor.log) but whose authoritative IME PS-SCRIPT-RESULT + /// line never arrives before the deadline must still surface a completion event — otherwise a + /// device that ran N platform scripts in quick succession surfaces only the one that happened + /// to get its IME result logged in time (field bug, session d1da052d…). + /// + public sealed class ImeLogTrackerPlatformScriptFallbackTests + { + private static ImeLogTracker BuildTracker(TempDirectory tmp, out List emitted) + { + var captured = new List(); + emitted = captured; + var tracker = new ImeLogTracker( + logFolder: tmp.Path, + patterns: new List(), + logger: new AgentLogger(tmp.Path, AgentLogLevel.Info)); + tracker.OnScriptCompleted = s => captured.Add(s); + return tracker; + } + + [Fact] + public void Fallback_emits_completion_when_ime_result_never_arrives() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt, stdout: "Script start.\nScript end."); + + // Well past the grace window — should emit. + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + + var script = Assert.Single(emitted); + Assert.Equal("dece354a", script.PolicyId); + Assert.Equal("platform", script.ScriptType); + Assert.Equal(0, script.ExitCode); + Assert.Equal("Success", script.Result); + Assert.Equal("agentexecutor_fallback", script.ResultSource); + Assert.Equal("Script start.\nScript end.", script.Stdout); + } + + [Fact] + public void Fallback_holds_until_grace_period_elapses() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("60b43a2e", exitCode: 0, exitObservedAtUtc: observedAt); + + // Inside the grace window — IME might still log its result; do not emit yet. + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(5)); + Assert.Empty(emitted); + + // Past the grace window — emit. + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + Assert.Single(emitted); + } + + [Fact] + public void Force_flush_ignores_grace_period() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("846cea22", exitCode: 0, exitObservedAtUtc: observedAt); + + // Shutdown flush right after exit — grace not elapsed, but force emits anyway. + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(1), force: true); + + Assert.Single(emitted); + } + + [Fact] + public void Nonzero_exit_code_emits_failed_result() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("bad5c0de", exitCode: 1, exitObservedAtUtc: observedAt); + + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + + var script = Assert.Single(emitted); + Assert.Equal(1, script.ExitCode); + Assert.Equal("Failed", script.Result); + Assert.Equal("agentexecutor_fallback", script.ResultSource); + } + + [Fact] + public void Script_without_exit_code_is_not_emitted() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + + // Started but no exit code yet → still running, must not be emitted even on force flush. + tracker.SeedPendingPlatformScriptForTesting("running", exitCode: null, exitObservedAtUtc: null); + + tracker.FlushStalePlatformScriptResults(DateTime.UtcNow, force: true); + + Assert.Empty(emitted); + } + + [Fact] + public void Real_ime_result_after_fallback_does_not_double_emit() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt); + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + Assert.Single(emitted); + + // IME finally logs its PS-SCRIPT-RESULT line — must NOT produce a second event. + tracker.CompletePlatformScriptFromImeResultForTesting("dece354a", "Success"); + Assert.Single(emitted); + } + + [Fact] + public void Fallback_event_carries_script_exit_timestamp_for_emit() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt); + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + + // The exit-observed timestamp must travel on the emitted state so the adapter can bind + // the event to it instead of an unrelated "last matched" line parsed during the grace. + var script = Assert.Single(emitted); + Assert.Equal(observedAt, script.ExitObservedAtUtc); + Assert.Equal("agentexecutor_fallback", script.ResultSource); + } + + [Fact] + public void Same_policy_can_emit_again_after_a_fresh_run() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var firstRun = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + // Run 1 of policy X — fallback emits. + tracker.SeedPendingPlatformScriptForTesting("policyX", exitCode: 0, exitObservedAtUtc: firstRun); + tracker.FlushStalePlatformScriptResults(firstRun.AddSeconds(20)); + Assert.Single(emitted); + + // Run 2 of the SAME policy later in the same agent lifetime (IME re-evaluation / retry) + // must NOT be deduped away — the fresh start clears the prior emitted-marker. + var secondRun = firstRun.AddMinutes(30); + tracker.SeedPendingPlatformScriptForTesting("policyX", exitCode: 0, exitObservedAtUtc: secondRun); + tracker.FlushStalePlatformScriptResults(secondRun.AddSeconds(20)); + Assert.Equal(2, emitted.Count); + } + + [Fact] + public void Ime_result_before_fallback_wins_and_fallback_is_noop() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp, out var emitted); + var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc); + + tracker.SeedPendingPlatformScriptForTesting("35ed39d9", exitCode: 0, exitObservedAtUtc: observedAt); + + // Authoritative result arrives in time (healthy path). + tracker.CompletePlatformScriptFromImeResultForTesting("35ed39d9", "Success"); + var script = Assert.Single(emitted); + Assert.Equal("ime_policy_result", script.ResultSource); + + // Later fallback pass must find nothing pending → no duplicate. + tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20)); + Assert.Single(emitted); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs index c22185bb..d4b5f019 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs @@ -132,6 +132,63 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters Assert.Equal(sourceTs.ToString("o"), info.Payload!["completedAt"]); } + [Fact] + public void ScriptCompleted_fallback_binds_to_exit_timestamp_and_drops_stale_patternId() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + // The exit-code fallback emits up to a grace period after the script's exit line, by + // which point an UNRELATED later line is the "last matched" one. The fallback event must + // bind to the script's own exit timestamp and must NOT inherit the stale patternId. + var exitAt = ClockNow.AddMinutes(-3); + f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-1); // unrelated later line + f.Tracker.LastMatchedPatternId = "UNRELATED-LATER-PATTERN"; + + adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState + { + PolicyId = "dece354a", + ScriptType = "platform", + ExitCode = 0, + Result = "Success", + ResultSource = "agentexecutor_fallback", + ExitObservedAtUtc = exitAt, + }); + + var info = f.InfoEvent(SharedEventTypes.ScriptCompleted); + Assert.Equal(exitAt, info.OccurredAtUtc); + Assert.False(info.Payload!.ContainsKey("patternId")); + Assert.Equal("agentexecutor_fallback", info.Payload["resultSource"]); + } + + [Fact] + public void ScriptCompleted_authoritative_path_keeps_patternId_and_last_matched_timestamp() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + // Regression guard: the normal IME-result path is unchanged — it still uses the + // last-matched timestamp + patternId (the PS-SCRIPT-RESULT line that drove the emit). + var sourceTs = ClockNow.AddMinutes(-2); + f.Tracker.LastMatchedLogTimestamp = sourceTs; + f.Tracker.LastMatchedPatternId = "PS-SCRIPT-RESULT"; + + adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState + { + PolicyId = "35ed39d9", + ScriptType = "platform", + ExitCode = 0, + Result = "Success", + ResultSource = "ime_policy_result", + ExitObservedAtUtc = ClockNow.AddMinutes(-30), // present but must be ignored on this path + }); + + var info = f.InfoEvent(SharedEventTypes.ScriptCompleted); + Assert.Equal(sourceTs, info.OccurredAtUtc); + Assert.Equal("PS-SCRIPT-RESULT", info.Payload!["patternId"]); + Assert.Equal("ime_policy_result", info.Payload["resultSource"]); + } + [Fact] public void WhiteGloveSealingPattern_uses_source_log_timestamp() { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index 0b9bd3b8..51cdf0df 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -206,6 +206,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // Platform script: AgentExecutor.log entries create/enrich, IME log entries also create if (!_pendingPlatformScripts.ContainsKey(id)) { + // A fresh start for this policy (no pending entry) begins a NEW execution. + // Clear any emitted-marker from a prior run so IME re-evaluations / retries of + // the same platform-script policy within one agent lifetime are not silently + // deduped away. Within a single run the start always precedes exit/result, so + // this never clears the current run's own marker. + _platformScriptResultEmitted.Remove(id); _pendingPlatformScripts[id] = new ScriptExecutionState { PolicyId = id, @@ -254,6 +260,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime if (script != null) { script.ExitCode = exitCode; + // Stamp when we learned the script's exit code so the deadline-based fallback + // (FlushStalePlatformScriptResults) can fire if IME never logs its authoritative + // PS-SCRIPT-RESULT line in time. Prefer the source CMTrace timestamp (already + // UTC-normalized by the parser) so replayed log content is dated correctly. + if (string.Equals(script.ScriptType, "platform", StringComparison.OrdinalIgnoreCase)) + script.ExitObservedAtUtc = LastMatchedLogTimestamp ?? DateTime.UtcNow; _logger.Debug($"ImeLogTracker: script exit code {exitCode} for {script.PolicyId}"); } } @@ -304,6 +316,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime if (string.IsNullOrEmpty(id)) return; + // Dedup: the deadline-based fallback (FlushStalePlatformScriptResults) may already have + // emitted this script from its AgentExecutor exit code because IME's authoritative + // PS-SCRIPT-RESULT line arrived late. The fallback carries the same exit code + stdout, + // so re-emitting here would duplicate the timeline entry and inflate counts. Drop the + // now-redundant pending entry and skip. + if (_platformScriptResultEmitted.Contains(id)) + { + _logger.Debug($"ImeLogTracker: platform script {id} PS-SCRIPT-RESULT arrived after fallback emit — skipping duplicate"); + _pendingPlatformScripts.Remove(id); + if (string.Equals(_lastPlatformScriptPolicyId, id, StringComparison.OrdinalIgnoreCase)) + _lastPlatformScriptPolicyId = null; + return; + } + // Merge with pending AgentExecutor data if available if (!_pendingPlatformScripts.TryGetValue(id, out var script)) { @@ -315,15 +341,143 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime } script.Result = result; + script.ResultSource = "ime_policy_result"; _logger.Info($"ImeLogTracker: platform script completed: {id}, result={result}, exit={script.ExitCode}"); EmitScriptEvent(script); + _platformScriptResultEmitted.Add(id); _pendingPlatformScripts.Remove(id); if (string.Equals(_lastPlatformScriptPolicyId, id, StringComparison.OrdinalIgnoreCase)) _lastPlatformScriptPolicyId = null; } + /// + /// Grace period after a platform script's AgentExecutor exit code is observed before + /// emits a completion from that exit code. + /// IME logs its authoritative PS-SCRIPT-RESULT line within ~1 s of exit on healthy + /// reporting cycles, so 15 s lets the normal path win virtually always — the fallback is a + /// true safety net for the case where IME has not flushed its batch-send to the Microsoft + /// service before the (often short) Autopilot enrollment ends and the agent terminates. + /// + private static readonly TimeSpan PlatformScriptResultGrace = TimeSpan.FromSeconds(15); + + /// + /// Policy IDs of platform scripts already emitted (via either the authoritative + /// PS-SCRIPT-RESULT path or the exit-code fallback). Guards against double emission when + /// both fire for the same script. + /// + private readonly HashSet _platformScriptResultEmitted = + new HashSet(StringComparer.OrdinalIgnoreCase); + + /// + /// Emits a script_completed/script_failed for every pending platform script + /// that has a known AgentExecutor exit code but whose IME PS-SCRIPT-RESULT line has + /// not arrived within . Without this, scripts that + /// completed shortly before the agent terminates are silently dropped (the + /// _pendingPlatformScripts buffer is neither persisted nor flushed on dispose), so a + /// device that ran N platform scripts could surface only the long-running one that happened + /// to get its IME result logged in time. Result is derived from the exit code (0 → Success, + /// else Failed) and tagged resultSource=agentexecutor_fallback so the data is honest + /// about its provenance. + /// + /// Runs on the single-threaded polling loop (no locking needed, same as the handlers). + /// bypasses the grace check for the final pass on shutdown. + /// + /// + internal void FlushStalePlatformScriptResults(DateTime nowUtc, bool force = false) + { + if (_pendingPlatformScripts.Count == 0) return; + + List toRemove = null; + foreach (var kv in _pendingPlatformScripts) + { + var script = kv.Value; + + // Already emitted by the authoritative path — just drop the stale buffer entry. + if (_platformScriptResultEmitted.Contains(script.PolicyId)) + { + (toRemove ??= new List()).Add(kv.Key); + continue; + } + + // No exit code yet → the script is still running; nothing to emit. + if (!script.ExitCode.HasValue) continue; + + if (!force) + { + if (!script.ExitObservedAtUtc.HasValue) continue; + if (nowUtc - script.ExitObservedAtUtc.Value < PlatformScriptResultGrace) continue; + } + + script.Result = script.ExitCode.Value == 0 ? "Success" : "Failed"; + script.ResultSource = "agentexecutor_fallback"; + + _logger.Info( + $"ImeLogTracker: platform script {script.PolicyId} result not seen within " + + $"{PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? " (shutdown flush)" : "")} — " + + $"emitting from AgentExecutor exit code {script.ExitCode.Value} (fallback)"); + + EmitScriptEvent(script); + _platformScriptResultEmitted.Add(script.PolicyId); + (toRemove ??= new List()).Add(kv.Key); + } + + if (toRemove != null) + { + foreach (var key in toRemove) + { + _pendingPlatformScripts.Remove(key); + if (string.Equals(_lastPlatformScriptPolicyId, key, StringComparison.OrdinalIgnoreCase)) + _lastPlatformScriptPolicyId = null; + } + } + } + + /// Test seam: inject a pending platform script as if AgentExecutor.log had reported + /// its start + exit code, without an IME PS-SCRIPT-RESULT line. + internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null) + { + // Mirrors a fresh execution start: a new run clears any prior emitted-marker (see + // HandleScriptStarted) so re-runs of the same policy within one lifetime emit again. + _platformScriptResultEmitted.Remove(policyId); + _pendingPlatformScripts[policyId] = new ScriptExecutionState + { + PolicyId = policyId, + ScriptType = "platform", + ExitCode = exitCode, + ExitObservedAtUtc = exitObservedAtUtc, + Stdout = stdout, + }; + _lastPlatformScriptPolicyId = policyId; + } + + /// Test seam: simulate the authoritative IME PS-SCRIPT-RESULT path for a platform + /// script (same code as minus regex extraction). + internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result) + { + if (string.IsNullOrEmpty(policyId)) return; + + if (_platformScriptResultEmitted.Contains(policyId)) + { + _pendingPlatformScripts.Remove(policyId); + if (string.Equals(_lastPlatformScriptPolicyId, policyId, StringComparison.OrdinalIgnoreCase)) + _lastPlatformScriptPolicyId = null; + return; + } + + if (!_pendingPlatformScripts.TryGetValue(policyId, out var script)) + script = new ScriptExecutionState { PolicyId = policyId, ScriptType = "platform" }; + + script.Result = result; + script.ResultSource = "ime_policy_result"; + EmitScriptEvent(script); + _platformScriptResultEmitted.Add(policyId); + _pendingPlatformScripts.Remove(policyId); + if (string.Equals(_lastPlatformScriptPolicyId, policyId, StringComparison.OrdinalIgnoreCase)) + _lastPlatformScriptPolicyId = null; + } + /// /// Parses the IME [HS] new result = {…} JSON and emits one to three /// events covering the pre-detection, diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs index 8f113750..c3be5808 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs @@ -486,6 +486,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime try { await CheckLogFilesAsync(token); + + // Safety net: emit completions for platform scripts whose AgentExecutor + // exit code we already have but whose authoritative IME PS-SCRIPT-RESULT + // line never arrived within the grace period. Runs on this same loop + // thread (no locking) so it observes the buffer right after parsing. + FlushStalePlatformScriptResults(DateTime.UtcNow); } catch (OperationCanceledException) { break; } catch (Exception ex) @@ -508,6 +514,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime try { await Task.Delay(_pollingIntervalMs, token); } catch (OperationCanceledException) { break; } } + // Final pass: force-flush any platform script that completed within the last grace + // window before shutdown (exit code known, IME result still pending). Best-effort — + // emits only while callbacks are still wired (i.e. the adapter hasn't been disposed). + try { FlushStalePlatformScriptResults(DateTime.UtcNow, force: true); } + catch (Exception ex) { _logger.Warning($"ImeLogTracker: shutdown script flush failed: {ex.Message}"); } + // Final state save on shutdown if (_stateDirty) { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs index 7df55034..952288df 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs @@ -33,6 +33,25 @@ public class ScriptExecutionState /// "Success" or "Failed" (platform scripts). public string Result { get; set; } + /// + /// Provenance of for platform scripts: + /// "ime_policy_result" — authoritative PS-SCRIPT-RESULT line from + /// IntuneManagementExtension.log; "agentexecutor_fallback" — derived from the + /// AgentExecutor.log exit code because IME never logged its policy-result line before the + /// deadline (short Autopilot enrollments end inside IME's batch-send gap). Surfaced as + /// resultSource on the emitted event so the UI/MCP can flag fallback-grounded results. + /// Null for health scripts and for events emitted before this field existed. + /// + public string ResultSource { get; set; } + + /// + /// UTC timestamp at which the AgentExecutor.log exit-code line for this platform script was + /// observed. Drives the deadline check in + /// — set only on the platform path + /// (PS-AGENT exit code); null until an exit code is seen. + /// + public System.DateTime? ExitObservedAtUtc { get; set; } + /// "True" or "False" compliance result (remediation detection / post-detection only). public string ComplianceResult { get; set; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index 56ff5d9e..c6b29a0c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -262,8 +262,19 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters /// /// private DateTime ResolveOccurredAt(out bool derivedFromClock, out DateTime? rawSourceTimestamp) + => ResolveOccurredAt(null, out derivedFromClock, out rawSourceTimestamp); + + /// + /// Overload that prefers an explicit source timestamp over + /// . Used by the platform-script + /// exit-code fallback: the fallback emit happens up to a grace period after the script's + /// exit line was parsed, by which point an unrelated later log line may be the "last + /// matched" one — so the fallback passes the script's own exit-observed timestamp here to + /// keep the event on the correct point of the timeline. Same staleness/skew clamp applies. + /// + private DateTime ResolveOccurredAt(DateTime? sourceTsOverride, out bool derivedFromClock, out DateTime? rawSourceTimestamp) { - rawSourceTimestamp = _tracker.LastMatchedLogTimestamp; + rawSourceTimestamp = sourceTsOverride ?? _tracker.LastMatchedLogTimestamp; if (rawSourceTimestamp.HasValue) { // CMTrace log timestamps from IME are emitted in UTC, but DateTimeKind may @@ -794,6 +805,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (script.ExitCode.HasValue) data["exitCode"] = script.ExitCode.Value.ToString(culture); if (!string.IsNullOrEmpty(script.RunContext)) data["runContext"] = script.RunContext!; if (!string.IsNullOrEmpty(script.Result)) data["result"] = script.Result!; + // Provenance of the result: "ime_policy_result" (authoritative IME PS-SCRIPT-RESULT) vs + // "agentexecutor_fallback" (derived from the AgentExecutor exit code because IME never + // logged its result line before the deadline). Lets the UI/MCP flag fallback-grounded + // platform-script completions. Platform scripts only — null for health scripts. + if (!string.IsNullOrEmpty(script.ResultSource)) data["resultSource"] = script.ResultSource!; if (!string.IsNullOrEmpty(script.ComplianceResult)) data["complianceResult"] = script.ComplianceResult!; if (script.RemediationStatus.HasValue) data["remediationStatus"] = script.RemediationStatus.Value.ToString(culture); if (script.TargetType.HasValue) data["targetType"] = script.TargetType.Value.ToString(culture); @@ -801,10 +817,24 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (!string.IsNullOrEmpty(script.ErrorDetails)) data["errorDetails"] = script.ErrorDetails!; if (!string.IsNullOrEmpty(script.Stdout)) data["stdout"] = script.Stdout!; if (!string.IsNullOrEmpty(script.Stderr)) data["stderr"] = script.Stderr!; - var patternId = _tracker.LastMatchedPatternId; - if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; - var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + // The exit-code fallback emits asynchronously to log parsing, so the tracker's + // "last matched" pattern/timestamp belong to an unrelated later line. Bind the event to + // the script's own exit-observed timestamp and omit the misleading patternId instead. + var isFallback = string.Equals(script.ResultSource, "agentexecutor_fallback", StringComparison.Ordinal); + if (!isFallback) + { + var patternId = _tracker.LastMatchedPatternId; + if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + } + + bool derivedFromClock; + DateTime? rawSourceTs; + DateTime now; + if (isFallback && script.ExitObservedAtUtc.HasValue) + now = ResolveOccurredAt(script.ExitObservedAtUtc, out derivedFromClock, out rawSourceTs); + else + now = ResolveOccurredAt(out derivedFromClock, out rawSourceTs); TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); var label = IsRemediation(script.ScriptType) ? "Remediation script" : "Platform script";