Compare commits

...

3 Commits

Author SHA1 Message Date
Oliver Kieselbach d88d4a143b bump pointer: internal (D-318, concept docs, plan platform-script-retry-pairing, B-gc8)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
2026-10-04 18:29:50 +02:00
Oliver Kieselbach 913dfa13fe One platform run per executor start; IME results pair with the run that started last before them, the fallback judges by IME's rule (D-318)
IME re-runs a failed platform script on later check-ins, and the agent's first pass reads all of
AgentExecutor.log before the IME log, so several runs of one policy shared one slot: the first IME
result took the LAST run's exit code and output (session eff1b413: the bootstrap script "Failed
(exit 0)" with the stdout of its successful retry), every later result went out without an end
block. The exit-code fallback said Success for exit 0 with stderr and Failed for exit 1 without,
which IME never does.

- A later timestamped executor start parks the previous run of its policy (persisted, max 64); an
  IME result pairs with the run of its policy and user that started last before the result line;
  earlier parked runs of the same user resolve then, so emits keep run order.
- Invocation markers carry the run id; the emitted marker only rises; no dedup path deletes a live
  run; a parked emit never takes the later run's D-316 register entry.
- Fallback: Success exactly when the stderr is empty, the exit code only when no stderr line was
  read; "write output done … error =" replaces the "error from script" snapshot, empty stdout too.

Backfill replays fail on the old code; nine mutation proofs; agent suite 3,416 green.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
2026-10-04 18:29:33 +02:00
Oliver Kieselbach 51345718c6 bump pointer: internal (D-316/D-317 released, agent 2.0.1475; B-qrz narrowed to the field verify)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
2026-10-04 15:46:47 +02:00
10 changed files with 696 additions and 66 deletions
@@ -0,0 +1,336 @@
using System;
using System.IO;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
{
/// <summary>
/// B-96m: IME re-runs a failed platform script on later check-ins, so AgentExecutor.log can hold several runs of one
/// policy before the tracker has read IME's result of the first — always on the agent's first pass (the agent starts
/// mid-enrollment and reads all of AgentExecutor.log before IntuneManagementExtension.log), after a restart, and
/// whenever a result line surfaces late. With one slot per policy the second executor start reused the first run's
/// slot and its end block overwrote the first one: the first IME result went out with the LAST run's exit code and
/// output (session eff1b413: the bootstrap script "Failed (exit 0)" with the stdout of its successful retry), every
/// later result without an end block. These tests pin one run per executor start, each IME result paired with the
/// run of its policy that started last before it, each run carrying its own end block.
/// </summary>
public sealed partial class ImeLogTrackerOverwriteRewindTests
{
private const string RetryPolicyId = "4c2d8e1a-7b3f-4a9e-8d21-6f0b5c3e9a74";
private const string RetryUser = "00000000-0000-0000-0000-000000000000";
private static string ImeEntryAt(string time, string message)
=> $"<![LOG[{message}]LOG]!><time=\"{time}\" date=\"9-10-2026\" component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"12\" file=\"\">\r\n";
/// <summary>One executor run's start block: banner, the platform argument line, paths, launch.</summary>
private static string RunStart(string time, string pid, string policyId = RetryPolicyId, string userId = RetryUser)
{
var path = $@"{ImeDir}\Policies\Scripts\{userId}_{policyId}.ps1";
var results = $@"{ImeDir}\Policies\Results\{userId}_{policyId}";
return ExecutorBanner(time)
+ EntryAt(time, $"Adding argument powershell with value {path} to the named argument list.")
+ EntryAt(time, "Powershell option gets invoked")
+ EntryAt(time, path)
+ EntryAt(time, results + ".output")
+ EntryAt(time, results + ".error")
+ EntryAt(time, results + ".timeout")
+ ExecutorLaunch(time, path, pid);
}
/// <summary>
/// One executor run's end block in AgentExecutor's order. "error from script =" logs the stderr buffer before the
/// output readers finished (<paramref name="stderrSnapshot"/>); "write output done" logs the final texts, the
/// error part being exactly the error file IME judges.
/// </summary>
private static string RunEnd(string time, int exitCode, string stdout, string stderr, string? stderrSnapshot = null)
=> EntryAt(time, $"Powershell exit code is {exitCode}")
+ EntryAt(time, $"length of out={stdout.Length}")
+ EntryAt(time, $"length of error={stderr.Length}")
+ EntryAt(time, "error from script =" + (stderrSnapshot ?? stderr))
+ EntryAt(time, exitCode == 0 ? "Powershell script is successfully executed." : "Powershell script is failed to execute")
+ EntryAt(time, $"write output done. output = {stdout}, error = {stderr}")
+ EntryAt(time, "Revert Wow64FsRedirection")
+ EntryAt(time, "Agent executor completed.");
private static string ImeRunStart(string time, string policyId = RetryPolicyId, string userId = RetryUser)
=> ImeEntryAt(time, $@"Script file {ImeDir}\Policies\Scripts\{userId}_{policyId}.ps1 is generated.");
private static string ImeRunResult(string time, string result, string policyId = RetryPolicyId, string userId = RetryUser)
=> ImeEntryAt(time, $"[PowerShell] User Id = {userId}, Policy id = {policyId}, policy result = {result}");
private static void AppendImeLog(Harness h, string text)
=> File.AppendAllText(Path.Combine(Path.GetDirectoryName(h.LogPath)!, "IntuneManagementExtension.log"), text, new UTF8Encoding(false));
/// <summary>Result | exit | stdout | stderr — readable in an assertion failure; "-" no exit code, "~" never read.</summary>
private static string Shape(ScriptExecutionState s)
=> $"{s.Result}|{(s.ExitCode.HasValue ? s.ExitCode.Value.ToString() : "-")}|{s.Stdout ?? "~"}|{s.Stderr ?? "~"}";
/// <summary>
/// Two poll passes as the agent runs them (read the files, then the flushes), the second past the result hold:
/// a result missing its end block goes out by then.
/// </summary>
private static async Task PassAndSettle(Harness h)
{
await h.Tracker.RunPollPassAsync(default);
h.Now = h.Now.AddSeconds(6);
await h.Tracker.RunPollPassAsync(default);
}
[Fact]
public async Task First_pass_pairs_each_ime_result_with_the_end_block_of_its_own_run()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
// IME's first run and two retries on later check-ins, all written before the agent started.
h.Append(RunStart("12:00:10.0000000", "1001") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
+ RunStart("12:10:10.0000000", "1002") + RunEnd("12:10:12.0000000", 1, "Run B output", "")
+ RunStart("12:20:10.0000000", "1003") + RunEnd("12:20:12.0000000", 0, "Run C output", ""));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success")
+ ImeRunStart("12:20:08.0000000") + ImeRunResult("12:20:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|1||Run A failed", "Success|1|Run B output|", "Success|0|Run C output|" },
h.Completed.Select(Shape).ToArray());
Assert.All(h.Completed, s => Assert.Equal("ime_policy_result", s.ResultSource));
Assert.True(h.Completed[0].StartedAtUtc < h.Completed[1].StartedAtUtc && h.Completed[1].StartedAtUtc < h.Completed[2].StartedAtUtc);
Assert.Equal(3, h.Completed.Select(s => s.RunId).Distinct().Count());
}
[Fact]
public async Task Retry_of_the_bootstrap_script_never_lends_its_success_output_to_the_failed_first_attempt()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "2001") + RunEnd("12:00:20.0000000", 1, "attempt 1: download failed", "Invoke-WebRequest : The remote name could not be resolved")
+ RunStart("12:10:10.0000000", "2002") + RunEnd("12:10:20.0000000", 0, "===== Bootstrap Completed Successfully =====", ""));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:20.1000000", "Failed")
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:20.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[]
{
"Failed|1|attempt 1: download failed|Invoke-WebRequest : The remote name could not be resolved",
"Success|0|===== Bootstrap Completed Successfully =====|",
}, h.Completed.Select(Shape).ToArray());
}
[Fact]
public async Task Run_killed_at_the_timeout_reports_failed_without_the_next_runs_end_block()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
// IME killed the first executor after 1800 s: its start block is all AgentExecutor.log holds of it.
h.Append(RunStart("12:00:10.0000000", "3001")
+ RunStart("12:40:10.0000000", "3002") + RunEnd("12:40:12.0000000", 0, "Run B output", ""));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:30:10.5000000", "Failed")
+ ImeRunStart("12:40:08.0000000") + ImeRunResult("12:40:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|-|~|~", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
}
[Fact]
public async Task Run_whose_result_never_surfaced_falls_back_on_imes_rule_before_the_next_run()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "4001") + RunEnd("12:00:12.0000000", 0, "Run A output", "Run A wrote an error")
+ RunStart("12:10:10.0000000", "4002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
// Run A's result line was lost; run B's is there.
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|0|Run A output|Run A wrote an error", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
Assert.Equal(new[] { "agentexecutor_fallback", "ime_policy_result" }, h.Completed.Select(s => s.ResultSource).ToArray());
}
[Fact]
public async Task Run_in_flight_survives_the_emit_of_the_run_before_it()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "5001") + RunEnd("12:00:12.0000000", 0, "Run A output", "")
+ RunStart("12:10:10.0000000", "5002"));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Success") + ImeRunStart("12:10:08.0000000"));
await PassAndSettle(h);
h.Now = h.Now.AddSeconds(30);
await h.Pass();
// Run B ends minutes later.
h.Append(RunEnd("12:10:40.0000000", 0, "Run B output", ""));
AppendImeLog(h, ImeRunResult("12:10:40.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Success|0|Run A output|", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
}
[Fact]
public async Task Shutdown_between_the_two_logs_flushes_each_run_with_its_own_end_block()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "6001") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
+ RunStart("12:10:10.0000000", "6002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
// The pass is cancelled after AgentExecutor.log; the shutdown flush follows.
await h.Pass();
h.Tracker.FlushPendingPlatformScriptResults(h.Now, force: true);
h.Restart();
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
await PassAndSettle(h);
// Each run went out with its own block and IME's verdict on it; the results read after the restart are
// the same runs and change nothing.
Assert.Equal(new[] { "Failed|1||Run A failed", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
Assert.All(h.Completed, s => Assert.Equal("agentexecutor_fallback", s.ResultSource));
}
[Fact]
public async Task End_block_line_recovered_after_the_next_run_started_stays_with_its_own_run()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "7001"));
var exitLineAt = h.Length;
h.Append(RunEnd("12:00:12.0000000", 1, "", "Run A failed")
+ RunStart("12:10:10.0000000", "7002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
await h.Pass();
// A stale writer rewrites run A's exit line in place: the ledger check re-reads it behind run B's start.
h.Overwrite(exitLineAt, EntryAt("12:00:12.0000000", "Powershell exit code is 7"));
h.Tracker.RequestOverwriteCheckForTest();
h.Now = h.Now.AddSeconds(2);
await h.Pass();
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|7||Run A failed", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
}
[Fact]
public async Task Run_without_result_or_end_block_is_dropped_once_a_later_run_has_its_result()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "9001")
+ RunStart("12:10:10.0000000", "9002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
Assert.Equal(0, h.Tracker.ParkedPlatformScriptCountForTest);
}
[Fact]
public void Reading_the_same_executor_start_line_again_never_parks_its_run()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
var line = $@"Adding argument powershell with value {ImeDir}\Policies\Scripts\{RetryUser}_{RetryPolicyId}.ps1 to the named argument list.";
var at = T0.AddMinutes(-30);
h.Tracker.ProcessLogMessageForTest(line, at, "AgentExecutor.log");
h.Tracker.ProcessLogMessageForTest(line, at, "AgentExecutor.log");
Assert.Equal(0, h.Tracker.ParkedPlatformScriptCountForTest);
h.Tracker.ProcessLogMessageForTest(line, at.AddMinutes(10), "AgentExecutor.log");
Assert.Equal(1, h.Tracker.ParkedPlatformScriptCountForTest);
}
[Fact]
public async Task Run_without_end_block_keeps_waiting_for_its_result_across_a_shutdown()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "9101") + RunStart("12:40:10.0000000", "9102"));
await h.Pass();
h.Tracker.FlushPendingPlatformScriptResults(h.Now, force: true);
Assert.Empty(h.Completed);
h.Restart();
Assert.Equal(1, h.Tracker.ParkedPlatformScriptCountForTest);
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:30:10.5000000", "Failed"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|-|~|~" }, h.Completed.Select(Shape).ToArray());
}
[Fact]
public async Task Earlier_run_emitted_while_a_later_one_runs_never_takes_the_later_runs_register_entry()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "9201") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
+ RunStart("12:10:10.0000000", "9202"));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed") + ImeRunStart("12:10:08.0000000"));
await PassAndSettle(h);
Assert.Single(h.Completed);
// A save of this key is the latest run's, and that one is still running.
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
Assert.Equal(PlatformRunClaim.Wait, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out _));
h.Append(RunEnd("12:10:40.0000000", 0, "Run B output", ""));
AppendImeLog(h, ImeRunResult("12:10:40.1000000", "Success"));
await PassAndSettle(h);
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
Assert.Equal(PlatformRunClaim.Claimed, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out var run));
Assert.Equal(h.Completed[1].RunId, run!.RunId);
Assert.Equal("Run B output", run.Stdout);
}
[Fact]
public async Task Run_of_another_user_keeps_its_own_register_entry_when_it_waited_for_its_result()
{
const string otherUser = "2b7e5c91-3d4a-4f80-b6e2-9a1c7d3f5e08";
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "9301") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
+ RunStart("12:10:10.0000000", "9302", userId: otherUser));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
+ ImeRunStart("12:10:08.0000000", userId: otherUser));
await PassAndSettle(h);
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
Assert.Equal(PlatformRunClaim.Claimed, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out var run));
Assert.Equal(h.Completed[0].RunId, run!.RunId);
Assert.Equal(PlatformRunClaim.Wait, h.Tracker.ScriptRuns.TryClaim(otherUser, RetryPolicyId, h.Now.AddSeconds(-10), out _));
}
[Fact]
public async Task Start_line_read_again_stays_a_late_line_after_an_earlier_run_of_another_user_went_out()
{
const string otherUser = "2b7e5c91-3d4a-4f80-b6e2-9a1c7d3f5e08";
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
h.Append(RunStart("12:00:10.0000000", "9401") + RunEnd("12:00:12.0000000", 0, "Run A output", "")
+ RunStart("12:10:10.0000000", "9402", userId: otherUser) + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
// Run A's result surfaces after run B's (its line was hidden by a concurrent writer).
AppendImeLog(h, ImeRunResult("12:10:12.1000000", "Success", userId: otherUser) + ImeRunResult("12:00:12.1000000", "Success"));
await PassAndSettle(h);
Assert.Equal(new[] { "Success|0|Run B output|", "Success|0|Run A output|" }, h.Completed.Select(Shape).ToArray());
// Run B's executor start line read again (a rewind): a late line of the emitted run B, never a new run.
var started = 0;
h.Tracker.OnScriptStarted = _ => started++;
h.Tracker.ProcessLogMessageForTest(
$@"Adding argument powershell with value {ImeDir}\Policies\Scripts\{otherUser}_{RetryPolicyId}.ps1 to the named argument list.",
h.Completed[0].StartedAtUtc, "AgentExecutor.log");
Assert.Equal(0, started);
}
[Fact]
public async Task Final_stderr_of_the_end_block_replaces_the_early_snapshot_even_without_stdout()
{
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
// The snapshot was taken before the error reader finished; IME judged the full error file.
h.Append(RunStart("12:00:10.0000000", "8001") + RunEnd("12:00:12.0000000", 0, "", "Remove-AppxPackage : Cannot process argument", stderrSnapshot: ""));
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed"));
await PassAndSettle(h);
Assert.Equal(new[] { "Failed|0||Remove-AppxPackage : Cannot process argument" }, h.Completed.Select(Shape).ToArray());
}
}
}
@@ -83,8 +83,33 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.Single(emitted);
}
[Theory]
// IME's verdict is Success exactly when the error file is empty, whatever the exit code. Judged by the exit
// code, session 67ae751c showed exit 0 with the script's own stderr as Success, and 46a41a0a an exit 1 without
// stderr as Failed, a run IME reported as Success one cycle earlier.
[InlineData(0, "Invoke-WebRequest : The remote name could not be resolved", "Failed")]
[InlineData(1, "", "Success")]
[InlineData(1, " \n", "Success")]
[InlineData(0, "", "Success")]
[InlineData(1, null, "Failed")]
[InlineData(0, null, "Success")]
public void Fallback_judges_like_ime_by_the_stderr_it_read(int exitCode, string? stderr, string expected)
{
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("0d2294bf", exitCode: exitCode, exitObservedAtUtc: observedAt, stderr: stderr);
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
var script = Assert.Single(emitted);
Assert.Equal(expected, script.Result);
Assert.Equal(exitCode, script.ExitCode);
Assert.Equal("agentexecutor_fallback", script.ResultSource);
}
[Fact]
public void Nonzero_exit_code_emits_failed_result()
public void Nonzero_exit_code_without_a_stderr_line_emits_failed_result()
{
using var tmp = new TempDirectory();
var tracker = BuildTracker(tmp, out var emitted);
@@ -108,6 +108,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
var tracker = BuildTracker(tmp, out var emitted);
tracker.LoadStateForTest(); // must not throw
Assert.Equal(0, tracker.ParkedPlatformScriptCountForTest);
// Degrades to pre-fix behavior: no markers restored, normal emission works (the
// result waits for its end block until the shutdown flush).
@@ -116,6 +117,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.Single(emitted);
}
[Fact]
public void Pending_slot_from_a_state_file_without_executor_start_loads_and_completes()
{
using var tmp = new TempDirectory();
var started = new DateTime(2026, 10, 4, 9, 0, 0, DateTimeKind.Utc);
// A pending slot written by an agent before runs carried their executor start and run id.
var persistence = new ImeTrackerStatePersistence(tmp.Path, new AgentLogger(tmp.Path, AgentLogLevel.Info));
persistence.Save(new ImeTrackerStateData
{
PendingPlatformScripts = new List<ScriptExecutionState>
{
new ScriptExecutionState { PolicyId = "policyF", ScriptType = "platform", StartedAtUtc = started, ExitCode = 0, ExitObservedAtUtc = started.AddSeconds(5), Stdout = "done", Stderr = "" },
},
});
var tracker = BuildTracker(tmp, out var emitted);
tracker.LoadStateForTest();
tracker.CompletePlatformScriptFromImeResultForTesting("policyF", "Success", started.AddSeconds(6));
var script = Assert.Single(emitted);
Assert.Equal("Success", script.Result);
Assert.Equal(0, script.ExitCode);
Assert.False(string.IsNullOrEmpty(script.RunId));
}
[Fact]
public void Stale_result_older_than_current_run_start_is_dropped()
{
@@ -306,6 +306,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
var currentStartTs = LastMatchedLogTimestamp ?? UtcNowProvider();
var currentStartProvenance = CaptureLastMatchedProvenance();
var fromExecutor = string.Equals(source, "agentexecutor", StringComparison.OrdinalIgnoreCase);
// A start line older than the result this policy already emitted is the late start
// line of THAT run: its AgentExecutor block surfaced after the IME result — the two
@@ -318,7 +319,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// never tie; a low-resolution clock in a test may).
if (_platformScriptResultEmitted.TryGetValue(id, out var emittedResultTs) && currentStartTs < emittedResultTs)
{
RecordInvocationMarker(id, isClose: false);
RecordInvocationMarker(id, isClose: false, EmittedRunId);
NoteInvocationActivity();
_logger.Debug($"ImeLogTracker: platform script start line for {id} (source: {source ?? "ime"}) predates its emitted result — late line of that run, not a new one");
return;
@@ -326,7 +327,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (_pendingPlatformScripts.TryGetValue(id, out var pendingSlot))
{
if (pendingSlot.StartedAtUtc.HasValue && currentStartTs - pendingSlot.StartedAtUtc.Value > TimeSpan.FromHours(24))
if (pendingSlot.StartedAtUtc.HasValue && currentStartTs - pendingSlot.StartedAtUtc.Value > StalePlatformRunAge)
{
// Stale-slot hardening (session eaf3d8c4): a replayed start line from a previous
// enrollment whose matching result never appeared (script was mid-run when that
@@ -343,6 +344,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// Emit what the held run has; its end block did not surface in time.
EmitPlatformScriptResult(pendingSlot, "the next run of this policy started");
}
else if (fromExecutor && LastMatchedLogTimestamp.HasValue && pendingSlot.Result == null
&& pendingSlot.ExecutorStartedAtUtc.HasValue && pendingSlot.ExecutorStartedAtUtc.Value < currentStartTs)
{
// Every executor process writes its start line once: a later one is the next run
// (IME re-runs a failed script on a later check-in), whose end block must not
// overwrite this one's. This run waits for its IME result — on the first pass
// AgentExecutor.log is read in full before the IME log (session eff1b413).
ParkPlatformRun(pendingSlot);
}
else if (!pendingSlot.StartedAtUtc.HasValue)
{
// The slot was opened by its result while the start block was still hidden;
@@ -351,9 +361,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
pendingSlot.StartedAtProvenance = currentStartProvenance;
_stateDirty = true;
}
if (pendingSlot.UserId == null && userId != null) pendingSlot.UserId = userId;
}
if (!_pendingPlatformScripts.ContainsKey(id))
if (_pendingPlatformScripts.TryGetValue(id, out var slot))
{
if (slot.UserId == null && userId != null) slot.UserId = userId;
if (fromExecutor && !slot.ExecutorStartedAtUtc.HasValue)
{
slot.ExecutorStartedAtUtc = currentStartTs;
_stateDirty = true;
}
}
else
{
// 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
@@ -361,18 +379,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// deduped away. A start line of the emitted run itself never reaches this point
// (the guard above), so this never clears the current run's own marker.
_platformScriptResultEmitted.Remove(id);
_pendingPlatformScripts[id] = new ScriptExecutionState
slot = new ScriptExecutionState
{
PolicyId = id,
ScriptType = "platform",
UserId = userId,
RunId = NewRunId(),
// Prefer the source CMTrace timestamp so a script that started before the
// agent launched (replayed log content) is dated to its real start, not now.
// Set only at slot creation: the start line fires twice (agentexecutor + ime
// source) but the earliest wins.
StartedAtUtc = currentStartTs,
StartedAtProvenance = currentStartProvenance,
ExecutorStartedAtUtc = fromExecutor ? currentStartTs : (DateTime?)null,
};
_pendingPlatformScripts[id] = slot;
ScriptRuns.NoteStarted(userId, id, UtcNowProvider());
// Live "running" indicator — same signal health scripts emit. Gated on slot
// creation so the duplicate start line (agentexecutor + ime source) doesn't
@@ -380,7 +401,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
try { OnScriptStarted?.Invoke(new ScriptStartedInfo { PolicyId = id, ScriptType = "platform" }); }
catch (Exception ex) { _logger.Warning($"ImeLogTracker: OnScriptStarted handler threw: {ex.Message}"); }
}
RecordInvocationMarker(id, isClose: false);
RecordInvocationMarker(id, isClose: false, LastMatchedLogTimestamp.HasValue ? RunIdOfStartLine(slot, fromExecutor, currentStartTs) : slot.RunId);
NoteInvocationActivity();
// Started lines fire twice per script (agentexecutor + ime source) and carry no
// outcome — the matching `platform script completed` line below carries result+exit
@@ -388,6 +409,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
_logger.Debug($"ImeLogTracker: platform script started: {id} (source: {source ?? "ime"})");
}
/// <summary>How long after IME's "Script file … is generated" line its executor writes its start line (about 2 s).</summary>
private static readonly TimeSpan ImeLaunchWindow = TimeSpan.FromMinutes(1);
/// <summary>
/// The run a timestamped start line belongs to, for its invocation marker. An executor start line belongs to the
/// slot unless it is older than the slot's executor start — re-read behind a later run — then to the parked run
/// it started. IME's "Script file … is generated" precedes its executor: it belongs to the live run whose
/// executor started within <see cref="ImeLaunchWindow"/> after it, else to a slot whose executor has not
/// started yet; otherwise its run is not known (yet) and the lines behind it go nowhere.
/// </summary>
private string RunIdOfStartLine(ScriptExecutionState slot, bool fromExecutor, DateTime lineTs)
{
if (fromExecutor)
{
if (!slot.ExecutorStartedAtUtc.HasValue || slot.ExecutorStartedAtUtc.Value <= lineTs) return slot.RunId;
var parked = _parkedPlatformScripts.FirstOrDefault(r =>
string.Equals(r.PolicyId, slot.PolicyId, StringComparison.OrdinalIgnoreCase) && r.ExecutorStartedAtUtc == lineTs);
return parked?.RunId ?? EmittedRunId;
}
var launched = LivePlatformRuns(slot.PolicyId)
.Where(r => r.ExecutorStartedAtUtc.HasValue && r.ExecutorStartedAtUtc.Value >= lineTs && r.ExecutorStartedAtUtc.Value - lineTs <= ImeLaunchWindow)
.OrderBy(r => r.ExecutorStartedAtUtc.Value)
.FirstOrDefault();
if (launched != null) return launched.RunId;
return slot.ExecutorStartedAtUtc.HasValue ? EmittedRunId : slot.RunId;
}
// Routes line-by-line script-data handlers (context / exitCode / output) to the right
// accumulator based on the pattern's scriptType parameter. Health-script lines feed the
// single-slot _pendingHealthScript (the HS-NEW-RESULT JSON delivers the full cycle in one
@@ -502,13 +551,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// PS-AGENT-OUTPUT captures both stdout and stderr in one pattern
var output = match.Groups["output"]?.Value;
var error = match.Groups["error"]?.Value;
var error = match.Groups["error"];
if (!string.IsNullOrEmpty(output) && !string.IsNullOrEmpty(error))
if (error != null && error.Success)
{
// Combined pattern (write output done. output = ..., error = ...)
script.Stdout = TruncateOutput(output.Trim());
script.Stderr = TruncateOutput(error.Trim());
// Combined pattern (write output done. output = ..., error = ...): both texts as
// AgentExecutor wrote them to the result files — the error part is the error file
// IME judges. The "error from script" line before it is a snapshot taken before the
// output readers finished, so this one replaces it, an empty stdout included.
script.Stdout = TruncateOutput(output?.Trim());
script.Stderr = TruncateOutput(error.Value.Trim());
}
else if (string.Equals(outputType, "stderr", StringComparison.OrdinalIgnoreCase))
{
@@ -556,49 +608,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// </summary>
internal void CompletePlatformScriptFromImeResult(string policyId, string result, DateTime? resultLineTimestampUtc, string patternId, CmTraceLineProvenance resultProvenance, string userId = null)
{
// Dedup: the deadline-based fallback (FlushPendingPlatformScriptResults) 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.ContainsKey(policyId))
// The result belongs to the run of this policy that started last before its line —
// the run in flight, or an earlier one that waits for its result while a later run
// already started (ParkPlatformRun).
var script = FindRunForResult(policyId, userId, resultLineTimestampUtc);
if (script == null)
{
_logger.Debug($"ImeLogTracker: platform script {policyId} PS-SCRIPT-RESULT arrived after fallback emit — skipping duplicate");
_pendingPlatformScripts.Remove(policyId);
return;
}
// Dedup: the deadline-based fallback (FlushPendingPlatformScriptResults) may already
// have emitted this run from its AgentExecutor end block because IME's authoritative
// PS-SCRIPT-RESULT line arrived late, or the same result line is read again.
// Re-emitting would duplicate the timeline entry and inflate counts.
if (_platformScriptResultEmitted.ContainsKey(policyId))
{
_logger.Debug($"ImeLogTracker: platform script {policyId} PS-SCRIPT-RESULT arrived after its run was emitted — skipping duplicate");
return;
}
// Merge with pending AgentExecutor data if available
if (_pendingPlatformScripts.TryGetValue(policyId, out var script))
{
// Stale-result guard: on an intra-lifetime re-run of the same policy, run 1's
// late PS-SCRIPT-RESULT can arrive after run 2's start line already created a
// fresh slot (the start clears the emitted-marker). Merging would pair run 2's
// StartedAtUtc/state with run 1's result and then drop run 2's genuine result at
// the marker check above. A result line always postdates its own run's start
// line in the source log, so a result older than the pending slot's start
// belongs to a previous run — drop it and keep the live slot intact.
if (script.StartedAtUtc.HasValue
&& resultLineTimestampUtc.HasValue
&& resultLineTimestampUtc.Value < script.StartedAtUtc.Value)
// Stale-result guard: every run of this policy in flight started after the result
// line — a result line always postdates its own run's start line in the source log,
// so it belongs to a previous run. Keep the live runs intact.
if (HasLivePlatformRun(policyId))
{
_logger.Debug($"ImeLogTracker: platform script {policyId} result predates the current run's start — stale result from a previous run, skipping");
return;
}
}
else
{
script = new ScriptExecutionState
{
PolicyId = policyId,
ScriptType = "platform",
UserId = userId,
RunId = NewRunId(),
};
_pendingPlatformScripts[policyId] = script;
ScriptRuns.NoteStarted(userId, policyId, UtcNowProvider());
}
if (script.UserId == null && userId != null) script.UserId = userId;
ResolveParkedRunsBefore(script);
script.Result = result;
script.ResultSource = "ime_policy_result";
script.ResultObservedAtUtc = resultLineTimestampUtc ?? UtcNowProvider();
@@ -627,21 +674,150 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private void EmitPlatformScriptResult(ScriptExecutionState script, string note = null)
{
_logger.Info($"ImeLogTracker: platform script completed: {script.PolicyId}, result={script.Result}, exit={script.ExitCode}{(note != null ? $" ({note})" : string.Empty)}");
if (string.IsNullOrEmpty(script.RunId)) script.RunId = Guid.NewGuid().ToString("D");
if (string.IsNullOrEmpty(script.RunId)) script.RunId = NewRunId();
EmitScriptEvent(script);
ScriptRuns.NoteEmitted(script, UtcNowProvider());
// The register keeps the latest run per (user, policy) for the registry reconciliation:
// a run that waited for its result while a later one started must not take that later
// run's entry.
if (!HasLaterLivePlatformRun(script)) ScriptRuns.NoteEmitted(script, UtcNowProvider());
// The run's source stamp, capped at the clock: a result line cannot be read before it
// was written, so a stamp ahead of the clock is a wrong zone assumption on that line
// (a rewound result resolved in the reader's zone, session 4377911b: +1 h). Left
// uncapped, the marker made the genuine NEXT run's start line read as a late line of
// this run and its result a duplicate.
// this run and its result a duplicate. Only ever raised: a run emitted after a later
// one must not move the reference back.
var runStamp = script.ResultObservedAtUtc ?? script.ExitObservedAtUtc ?? UtcNowProvider();
var nowUtc = UtcNowProvider();
_platformScriptResultEmitted[script.PolicyId] = runStamp > nowUtc ? nowUtc : runStamp;
_pendingPlatformScripts.Remove(script.PolicyId);
var stamp = runStamp > nowUtc ? nowUtc : runStamp;
if (!_platformScriptResultEmitted.TryGetValue(script.PolicyId, out var previousStamp) || stamp > previousStamp)
_platformScriptResultEmitted[script.PolicyId] = stamp;
if (_pendingPlatformScripts.TryGetValue(script.PolicyId, out var current) && ReferenceEquals(current, script))
_pendingPlatformScripts.Remove(script.PolicyId);
else
_parkedPlatformScripts.Remove(script);
_stateDirty = true;
}
private static string NewRunId() => Guid.NewGuid().ToString("D");
/// <summary>A run older than this by source time is from a previous enrollment, not a run in flight.</summary>
private static readonly TimeSpan StalePlatformRunAge = TimeSpan.FromHours(24);
private static bool SameUserOrUnknown(string a, string b)
=> a == null || b == null || string.Equals(a, b, StringComparison.OrdinalIgnoreCase);
private static DateTime StartOf(ScriptExecutionState run) => run.StartedAtUtc ?? DateTime.MinValue;
/// <summary>The runs of a policy that are not emitted yet: the earlier ones waiting for their IME result, then the one in flight.</summary>
private IEnumerable<ScriptExecutionState> LivePlatformRuns(string policyId)
{
foreach (var run in _parkedPlatformScripts)
{
if (string.Equals(run.PolicyId, policyId, StringComparison.OrdinalIgnoreCase)) yield return run;
}
if (_pendingPlatformScripts.TryGetValue(policyId, out var current)) yield return current;
}
private bool HasLivePlatformRun(string policyId) => LivePlatformRuns(policyId).Any();
/// <summary>The live run a start marker names, or null once that run was emitted.</summary>
private ScriptExecutionState FindLivePlatformRun(string policyId, string runId)
=> LivePlatformRuns(policyId).FirstOrDefault(r => string.Equals(r.RunId, runId, StringComparison.Ordinal));
private bool HasLaterLivePlatformRun(ScriptExecutionState script)
=> LivePlatformRuns(script.PolicyId).Any(r => !ReferenceEquals(r, script)
&& SameUserOrUnknown(r.UserId, script.UserId) && StartOf(r) > StartOf(script));
/// <summary>
/// The live run an IME result line belongs to: of the runs of its policy that started at or before the line,
/// the latest — one of the same IME user when there is one.
/// </summary>
private ScriptExecutionState FindRunForResult(string policyId, string userId, DateTime? resultLineTimestampUtc)
{
ScriptExecutionState sameUser = null, anyUser = null;
foreach (var run in LivePlatformRuns(policyId))
{
if (resultLineTimestampUtc.HasValue && run.StartedAtUtc.HasValue && run.StartedAtUtc.Value > resultLineTimestampUtc.Value) continue;
if (anyUser == null || StartOf(run) > StartOf(anyUser)) anyUser = run;
if (SameUserOrUnknown(run.UserId, userId) && (sameUser == null || StartOf(run) > StartOf(sameUser))) sameUser = run;
}
return sameUser ?? anyUser;
}
/// <summary>
/// Moves the run in flight aside when the next executor run of its policy starts: it keeps its own end block and
/// waits for its IME result (<see cref="FindRunForResult"/>), the exit-code fallback, or a later run's result.
/// </summary>
private void ParkPlatformRun(ScriptExecutionState run)
{
_pendingPlatformScripts.Remove(run.PolicyId);
_parkedPlatformScripts.Add(run);
_stateDirty = true;
if (_parkedPlatformScripts.Count > MaxParkedPlatformScripts)
{
var oldest = _parkedPlatformScripts.OrderBy(StartOf).First();
_logger.Warning($"ImeLogTracker: more than {MaxParkedPlatformScripts} platform runs wait for their IME result — resolving the oldest ({oldest.PolicyId}, started {oldest.StartedAtUtc:o}) now");
ResolveParkedRun(oldest, "too many runs waiting for their IME result");
}
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId}: the next executor run started before IME's result of run {run.RunId} was read — that run keeps its end block and waits for its result");
}
/// <summary>
/// Results arrive in run order: a parked run of the same IME user that started before the run a result belongs to
/// gets none any more (its result line was lost) — it goes out now, ahead of the later run.
/// </summary>
private void ResolveParkedRunsBefore(ScriptExecutionState owner)
{
if (_parkedPlatformScripts.Count == 0 || !owner.StartedAtUtc.HasValue) return;
var earlier = _parkedPlatformScripts
.Where(r => !ReferenceEquals(r, owner)
&& string.Equals(r.PolicyId, owner.PolicyId, StringComparison.OrdinalIgnoreCase)
&& SameUserOrUnknown(r.UserId, owner.UserId)
&& r.StartedAtUtc.HasValue && r.StartedAtUtc.Value < owner.StartedAtUtc.Value)
.OrderBy(StartOf)
.ToList();
foreach (var run in earlier) ResolveParkedRun(run, "a later run of this policy got its IME result first");
}
/// <summary>A parked run that will not get its IME result: out with what it has, or dropped when it has nothing.</summary>
private void ResolveParkedRun(ScriptExecutionState run, string why)
{
if (run.Result != null)
{
EmitPlatformScriptResult(run, why);
}
else if (run.ExitCode.HasValue)
{
EmitFromExecutorEndBlock(run, why);
}
else
{
_parkedPlatformScripts.Remove(run);
_stateDirty = true;
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId} run {run.RunId} has neither IME result nor executor end block — dropped ({why})");
}
}
/// <summary>
/// IME's own verdict from a run's end block: Success exactly when the error file was empty
/// (<c>IsNullOrEmpty(errorFile.Trim())</c> in IME), whatever the exit code — PowerShell returns 0 after a
/// non-terminating error and any code a script exits with. Only when the stderr line was never read does the
/// exit code stand in.
/// </summary>
internal static string ImeResultFromEndBlock(ScriptExecutionState script)
{
if (script.Stderr != null) return string.IsNullOrWhiteSpace(script.Stderr) ? "Success" : "Failed";
return script.ExitCode == 0 ? "Success" : "Failed";
}
private void EmitFromExecutorEndBlock(ScriptExecutionState script, string why)
{
script.Result = ImeResultFromEndBlock(script);
script.ResultSource = "agentexecutor_fallback";
var basis = script.Stderr == null ? $"exit code {script.ExitCode}, stderr not read" : script.Stderr.Trim().Length == 0 ? "empty stderr" : "stderr present";
EmitPlatformScriptResult(script, $"{why} — {script.Result} from the executor end block ({basis}) (fallback)");
}
/// <summary>
/// Grace period after a platform script's AgentExecutor exit code is observed before
/// <see cref="FlushPendingPlatformScriptResults"/> emits a completion from that exit code.
@@ -679,29 +855,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// out once its executor end block has been read — the block arrives within one pass, so
/// stdout/stderr are in by now — or after <see cref="PlatformScriptEndBlockGrace"/>.</item>
/// <item>A script with a known AgentExecutor exit code but no IME <c>PS-SCRIPT-RESULT</c>
/// line within <see cref="PlatformScriptResultGrace"/> is emitted from the exit code
/// (0 → Success, else Failed), tagged <c>resultSource=agentexecutor_fallback</c> so the
/// data is honest about its provenance. Without this, scripts that completed shortly
/// before the agent terminates were silently dropped.</item>
/// line within <see cref="PlatformScriptResultGrace"/> is emitted from its end block by
/// IME's own rule (<see cref="ImeResultFromEndBlock"/>), tagged
/// <c>resultSource=agentexecutor_fallback</c> so the data is honest about its provenance.
/// Without this, scripts that completed shortly before the agent terminates were silently
/// dropped.</item>
/// </list>
/// Parked runs go first, oldest first, so a policy's runs leave in run order; one without
/// result and end block keeps waiting — across a shutdown too — until a later run's result
/// resolves it or it is a day old.
/// Runs on the single-threaded polling loop (no locking needed, same as the handlers).
/// <paramref name="force"/> bypasses both grace checks for the final pass on shutdown.
/// </summary>
internal void FlushPendingPlatformScriptResults(DateTime nowUtc, bool force = false)
{
if (_pendingPlatformScripts.Count == 0) return;
if (_pendingPlatformScripts.Count == 0 && _parkedPlatformScripts.Count == 0) return;
var fallbackEmitted = false;
foreach (var script in _pendingPlatformScripts.Values.ToList())
foreach (var run in _parkedPlatformScripts.OrderBy(StartOf).ToList())
{
// Already emitted by the authoritative path — just drop the stale buffer entry.
if (_platformScriptResultEmitted.ContainsKey(script.PolicyId))
if (run.Result != null)
{
_pendingPlatformScripts.Remove(script.PolicyId);
_stateDirty = true;
if (run.ExitCode.HasValue || force || !run.ResultHeldSinceUtc.HasValue || nowUtc - run.ResultHeldSinceUtc.Value >= PlatformScriptEndBlockGrace)
EmitPlatformScriptResult(run, run.ExitCode.HasValue ? "executor end block read after the result" : $"no executor end block within {PlatformScriptEndBlockGrace.TotalSeconds:F0}s");
continue;
}
if (run.ExitCode.HasValue)
{
if (!force && (!run.ExitObservedAtUtc.HasValue || nowUtc - run.ExitObservedAtUtc.Value < PlatformScriptResultGrace)) continue;
EmitFromExecutorEndBlock(run, $"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)}");
fallbackEmitted = true;
continue;
}
if (run.StartedAtUtc.HasValue && nowUtc - run.StartedAtUtc.Value > StalePlatformRunAge)
{
_parkedPlatformScripts.Remove(run);
_stateDirty = true;
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId} run {run.RunId} waited a day without IME result or executor end block — dropped");
}
}
foreach (var script in _pendingPlatformScripts.Values.ToList())
{
if (script.Result != null)
{
if (script.ExitCode.HasValue)
@@ -720,10 +915,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (nowUtc - script.ExitObservedAtUtc.Value < PlatformScriptResultGrace) continue;
}
script.Result = script.ExitCode.Value == 0 ? "Success" : "Failed";
script.ResultSource = "agentexecutor_fallback";
EmitPlatformScriptResult(script,
$"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)} — emitted from AgentExecutor exit code {script.ExitCode.Value} (fallback)");
EmitFromExecutorEndBlock(script, $"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)}");
fallbackEmitted = true;
}
@@ -735,7 +927,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// <summary>Test seam: inject a pending platform script as if AgentExecutor.log had reported
/// its start + exit code, without an IME PS-SCRIPT-RESULT line.</summary>
internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null, DateTime? startedAtUtc = null,
CmTraceLineProvenance startedAtProvenance = null, CmTraceLineProvenance exitProvenance = null)
CmTraceLineProvenance startedAtProvenance = null, CmTraceLineProvenance exitProvenance = null, string stderr = 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.
@@ -744,9 +936,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
PolicyId = policyId,
ScriptType = "platform",
RunId = NewRunId(),
ExitCode = exitCode,
ExitObservedAtUtc = exitObservedAtUtc,
Stdout = stdout,
Stderr = stderr,
StartedAtUtc = startedAtUtc,
StartedAtProvenance = startedAtProvenance,
ExitProvenance = exitProvenance,
@@ -755,6 +949,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
RecordInvocationMarker(policyId, isClose: false);
}
/// <summary>Test seam: earlier runs waiting for their IME result while a later run of their policy is in flight.</summary>
internal int ParkedPlatformScriptCountForTest => _parkedPlatformScripts.Count;
/// <summary>Test seam: the authoritative IME PS-SCRIPT-RESULT path for a platform script
/// (the production handler minus regex extraction). <paramref name="resultLineTimestampUtc"/>
/// stands in for the CMTrace timestamp of the PS-SCRIPT-RESULT line (production reads it
@@ -380,11 +380,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
{
public long Offset;
public string PolicyId;
/// <summary>
/// The platform run the start line belongs to: the lines behind it go to that run while it is pending or
/// waits for its IME result, and nowhere once it was emitted — never to a later run of the same policy.
/// Null only on seeded test markers, which resolve by policy.
/// </summary>
public string RunId;
public bool IsClose;
/// <summary>Set on a writer boundary: the platform invocation it closed.</summary>
public string ClosedPolicyId;
}
/// <summary>Run id of a start line whose run was emitted already (a late line): owns its lines, matches no live run.</summary>
private const string EmittedRunId = "emitted";
private const string ExecutorLogFileName = "AgentExecutor.log";
private readonly Dictionary<string, List<InvocationMarker>> _invocationMarkers =
@@ -437,7 +446,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
list.Add(marker);
}
private void RecordInvocationMarker(string policyId, bool isClose)
private void RecordInvocationMarker(string policyId, bool isClose, string runId = null)
{
if (_currentEntryOffset < 0) return;
var file = _currentSourceFileName ?? TestSourceFileName;
@@ -451,6 +460,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (!isClose && policyId != null && last.ClosedPolicyId == null)
{
last.PolicyId = policyId;
last.RunId = runId;
last.IsClose = false;
_lastPlatformMarker = last;
_platformMarkerFiles.Add(file);
@@ -458,7 +468,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
return;
}
var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, IsClose = isClose };
var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, RunId = runId, IsClose = isClose };
AppendInvocationMarker(list, marker);
if (!isClose && policyId != null)
{
@@ -526,6 +536,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
if (marker == null || marker.IsClose || marker.PolicyId == null) return null;
ownerPolicyId = marker.PolicyId;
if (marker.RunId != null) return FindLivePlatformRun(marker.PolicyId, marker.RunId);
ScriptExecutionState state;
return _pendingPlatformScripts.TryGetValue(marker.PolicyId, out state) ? state : null;
}
@@ -182,6 +182,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private readonly Dictionary<string, ScriptExecutionState> _pendingPlatformScripts =
new Dictionary<string, ScriptExecutionState>(StringComparer.OrdinalIgnoreCase);
// Earlier runs of a policy whose next executor run started before IME's result of them was
// read (IME re-runs a failed script on later check-ins; the first pass reads all of
// AgentExecutor.log before the IME log). Each keeps its own end block until its result
// arrives — session eff1b413 lost that and paired the first result with the last run's block.
private readonly List<ScriptExecutionState> _parkedPlatformScripts = new List<ScriptExecutionState>();
private const int MaxParkedPlatformScripts = 64;
/// <summary>
/// The platform runs this tracker started and emitted, for the registry reconciliation that
/// checks them against IME's saved results (D-316). Shared with the registry host's thread.
@@ -1191,6 +1198,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
}
}
_parkedPlatformScripts.Clear();
if (state.ParkedPlatformScripts != null)
{
foreach (var parked in state.ParkedPlatformScripts)
{
if (!string.IsNullOrEmpty(parked?.PolicyId) && _parkedPlatformScripts.Count < MaxParkedPlatformScripts)
_parkedPlatformScripts.Add(parked);
}
}
_scriptTimeoutSuspectedPosted.Clear();
if (state.ScriptTimeoutSuspectedPosted != null)
{
@@ -1276,6 +1293,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// must survive restarts — see the LoadState comment for the duplicate scenario.
PlatformScriptResultEmittedAt = new Dictionary<string, DateTime>(_platformScriptResultEmitted, StringComparer.OrdinalIgnoreCase),
PendingPlatformScripts = _pendingPlatformScripts.Values.ToList(),
ParkedPlatformScripts = _parkedPlatformScripts.ToList(),
ScriptTimeoutSuspectedPosted = _scriptTimeoutSuspectedPosted.ToList(),
RecurringScripts = _recurringScripts.ToPersisted(),
};
@@ -151,6 +151,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// that run from the start of the next one.
public Dictionary<string, DateTime> PlatformScriptResultEmittedAt { get; set; }
public List<ScriptExecutionState> PendingPlatformScripts { get; set; }
// Earlier runs that wait for their IME result while a later run of the same policy is in
// flight; a restart between reading AgentExecutor.log and the IME log must keep them. Null on
// older state files → none.
public List<ScriptExecutionState> ParkedPlatformScripts { get; set; }
public List<string> ScriptTimeoutSuspectedPosted { get; set; }
// Recurring health-script runs collapsed per policy. Saved in the same write as
@@ -41,9 +41,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
/// Written on the tracker's poll thread, claimed on the registry host's timer thread: every member
/// locks, and nothing calls out while holding the lock.
/// <para>
/// A save belongs to the latest run of its key: IME runs a policy once per batch and saves the
/// batch after its last script, so the next run of the same key starts minutes later at the
/// earliest. A save is paired only after the tracker completed a pass that started
/// A save belongs to the latest run of its key: IME runs a policy at most once per check-in and
/// saves after reporting that check-in's batch, so the next run of the key comes with a later
/// check-in. (Overlapping check-ins can run a key twice at once; then IME itself shares the key's
/// result files and the judge's foreign verdict is the safety net.) A run that waited for its IME
/// result while a later run of its key already started is emitted without touching that later
/// run's entry. A save is paired only after the tracker completed a pass that started
/// <see cref="TrackerCatchUp"/> after the save was seen — every line written before the save, the
/// run's start among them, has been read by then, a stalled poll loop included.
/// </para>
@@ -23,11 +23,20 @@ public class ScriptExecutionState
public string UserId { get; set; }
/// <summary>
/// Identity of one emitted platform-script run, surfaced as <c>runId</c> on the event: what a
/// later <c>script_output_reconciliation</c> names when it corrects that run.
/// Identity of one platform-script run, given when its slot opens and surfaced as <c>runId</c> on
/// the event: the invocation markers bind the run's executor lines to it, and a later
/// <c>script_output_reconciliation</c> names it when it corrects that run.
/// </summary>
public string RunId { get; set; }
/// <summary>
/// Source timestamp of the run's AgentExecutor start line (<c>Adding argument powershell with
/// value …</c>). Every executor process writes that line once, so a later one for the same
/// policy starts the next run, never this one. Null until the line is read, and on state files
/// from before the field.
/// </summary>
public System.DateTime? ExecutorStartedAtUtc { get; set; }
/// <summary>
/// UTC timestamp of the script's first observed start line, taken from the source CMTrace log
/// timestamp (so it dates correctly even when the agent replays historic IME log content that