mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 05:00:07 +00:00
Compare commits
5 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 65842b87bf | |||
| b323c52364 | |||
| 321a6efc81 | |||
| 5ecb2a998b | |||
| bb6df93b51 |
+1
-1
Submodule .claude/commands updated: 6664a314aa...cb96a972a0
+1
-1
Submodule internal updated: 6f5d27936a...aa57d83ea0
+12
-2
@@ -486,8 +486,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
|
||||
// The platform result arrives without any end block ever becoming visible.
|
||||
// The platform result arrives without any end block ever becoming visible: held for
|
||||
// the grace, then emitted — the detection's exit code 3 must not stand in.
|
||||
h.Tracker.ProcessLogMessageForTest(ResultLine);
|
||||
Assert.Empty(h.Completed);
|
||||
h.Now = h.Now.Add(ImeLogTracker.PlatformScriptEndBlockGrace);
|
||||
h.Tracker.FlushPendingPlatformScriptResults(h.Now);
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Null(script.ExitCode);
|
||||
@@ -515,13 +519,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
await h.Pass();
|
||||
h.Now = h.Now.AddMilliseconds(100);
|
||||
await h.Pass();
|
||||
Assert.Equal(1, h.Health.OverwriteRewinds);
|
||||
|
||||
// Recovered on the IME side alone (this harness has no AgentExecutor.log): held for
|
||||
// the end block, emitted without an exit code after the grace.
|
||||
Assert.Empty(h.Completed);
|
||||
h.Now = h.Now.Add(ImeLogTracker.PlatformScriptEndBlockGrace);
|
||||
h.Tracker.FlushPendingPlatformScriptResults(h.Now);
|
||||
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(PlatformId, script.PolicyId);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal("ime_policy_result", script.ResultSource);
|
||||
Assert.Equal("User", script.RunContext);
|
||||
Assert.Equal(1, h.Health.OverwriteRewinds);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+5
-1
@@ -111,9 +111,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
tracker.ProcessLogMessageForTest("Powershell exit code is 0");
|
||||
tracker.ProcessLogMessageForTest("write output done. output = [Compliant] No Classic Teams found, error = ");
|
||||
|
||||
// Authoritative IME result for the PLATFORM script (keyed by policyId).
|
||||
// Authoritative IME result for the PLATFORM script (keyed by policyId). Its own end
|
||||
// block never comes here, so the result is held until the shutdown flush — which must
|
||||
// not pick up the remediation's exit/output either.
|
||||
tracker.ProcessLogMessageForTest(
|
||||
$"[PowerShell] User Id = 00000000-0000-0000-0000-000000000000, Policy id = {PlatformId}, policy result = Failed");
|
||||
Assert.Empty(emitted);
|
||||
tracker.FlushPendingPlatformScriptResults(System.DateTime.UtcNow, force: true);
|
||||
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal(PlatformId, script.PolicyId);
|
||||
|
||||
+11
-11
@@ -39,7 +39,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt, stdout: "Script start.\nScript end.");
|
||||
|
||||
// Well past the grace window — should emit.
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal("dece354a", script.PolicyId);
|
||||
@@ -60,11 +60,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
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));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(5));
|
||||
Assert.Empty(emitted);
|
||||
|
||||
// Past the grace window — emit.
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
|
||||
@@ -78,7 +78,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
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);
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
@@ -92,7 +92,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
tracker.SeedPendingPlatformScriptForTesting("bad5c0de", exitCode: 1, exitObservedAtUtc: observedAt);
|
||||
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal(1, script.ExitCode);
|
||||
@@ -109,7 +109,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
// 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);
|
||||
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
|
||||
|
||||
Assert.Empty(emitted);
|
||||
}
|
||||
@@ -122,7 +122,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc);
|
||||
|
||||
tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt);
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
Assert.Single(emitted);
|
||||
|
||||
// IME finally logs its PS-SCRIPT-RESULT line — must NOT produce a second event.
|
||||
@@ -138,7 +138,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc);
|
||||
|
||||
tracker.SeedPendingPlatformScriptForTesting("dece354a", exitCode: 0, exitObservedAtUtc: observedAt);
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(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.
|
||||
@@ -156,14 +156,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
// Run 1 of policy X — fallback emits.
|
||||
tracker.SeedPendingPlatformScriptForTesting("policyX", exitCode: 0, exitObservedAtUtc: firstRun);
|
||||
tracker.FlushStalePlatformScriptResults(firstRun.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(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));
|
||||
tracker.FlushPendingPlatformScriptResults(secondRun.AddSeconds(20));
|
||||
Assert.Equal(2, emitted.Count);
|
||||
}
|
||||
|
||||
@@ -182,7 +182,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
Assert.Equal("ime_policy_result", script.ResultSource);
|
||||
|
||||
// Later fallback pass must find nothing pending → no duplicate.
|
||||
tracker.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
}
|
||||
|
||||
+308
@@ -0,0 +1,308 @@
|
||||
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
|
||||
{
|
||||
/// <summary>
|
||||
/// The IME result waits for its executor end block (session e7f3c910): PS-SCRIPT-RESULT can
|
||||
/// reach the tracker before the AgentExecutor.log end block of the same run — an overwritten
|
||||
/// block is recovered one pass after the result that triggers the ledger check, the
|
||||
/// AgentExecutor.log read of a pass may precede the exit line by milliseconds, or the poll
|
||||
/// loop stalled. Emitting at once lost the exit code and, when the late start line reopened
|
||||
/// the slot, produced a fallback duplicate 15 s later.
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerResultHoldTests
|
||||
{
|
||||
private static readonly DateTime T0 = new DateTime(2026, 9, 10, 22, 13, 35, DateTimeKind.Utc);
|
||||
|
||||
private sealed class Harness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
public ImeLogTracker Tracker { get; private set; }
|
||||
public DateTime Now { get; set; } = T0;
|
||||
public List<ScriptExecutionState> Completed { get; } = new List<ScriptExecutionState>();
|
||||
public List<ScriptStartedInfo> Started { get; } = new List<ScriptStartedInfo>();
|
||||
|
||||
public Harness() { Tracker = Build(); }
|
||||
|
||||
private ImeLogTracker Build()
|
||||
{
|
||||
var t = new ImeLogTracker(_tmp.Path, new List<ImeLogPattern>(), new AgentLogger(_tmp.Path, AgentLogLevel.Info), stateDirectory: _tmp.Path);
|
||||
t.UtcNowProvider = () => Now;
|
||||
t.OnScriptCompleted = s => Completed.Add(s);
|
||||
t.OnScriptStarted = s => Started.Add(s);
|
||||
return t;
|
||||
}
|
||||
|
||||
/// <summary>Agent restart over the same state directory.</summary>
|
||||
public void Restart()
|
||||
{
|
||||
Tracker.SaveStateForTest();
|
||||
Tracker.Dispose();
|
||||
Tracker = Build();
|
||||
Tracker.LoadStateForTest();
|
||||
}
|
||||
|
||||
/// <summary>A start line (IME "Script file … is generated" or the executor's argument line) with its source timestamp.</summary>
|
||||
public void Start(string id, DateTime lineTs)
|
||||
{
|
||||
Tracker.LastMatchedLogTimestamp = lineTs;
|
||||
Tracker.NextTestEntry();
|
||||
Tracker.HandlePlatformScriptStarted(id);
|
||||
}
|
||||
|
||||
public void Result(string id, DateTime lineTs, string result = "Success")
|
||||
=> Tracker.CompletePlatformScriptFromImeResultForTesting(id, result, lineTs);
|
||||
|
||||
public void Exit(string id, DateTime lineTs, int exitCode = 0)
|
||||
=> Tracker.RecordPlatformScriptExitCodeForTesting(id, exitCode, lineTs);
|
||||
|
||||
/// <summary>The end-of-pass flush at the harness clock.</summary>
|
||||
public void Flush(bool force = false) => Tracker.FlushPendingPlatformScriptResults(Now, force);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Result_before_the_end_block_is_held_and_emits_once_with_the_exit_code()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("376ee51a", T0);
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("376ee51a", T0.AddSeconds(2));
|
||||
Assert.Empty(h.Completed);
|
||||
h.Now = T0.AddSeconds(2.1);
|
||||
h.Flush();
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
// The end block surfaces on the next pass (ledger rewind or plain read lag).
|
||||
h.Exit("376ee51a", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(2.2);
|
||||
h.Flush();
|
||||
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal("ime_policy_result", script.ResultSource);
|
||||
Assert.Equal(T0.AddSeconds(2), script.ResultObservedAtUtc);
|
||||
Assert.Equal("PS-SCRIPT-RESULT", script.ResultPatternId);
|
||||
Assert.Equal(T0, script.StartedAtUtc);
|
||||
|
||||
// Nothing fires twice: later passes, a repeated result line, the 15 s fallback window.
|
||||
h.Now = T0.AddSeconds(30);
|
||||
h.Flush();
|
||||
h.Result("376ee51a", T0.AddSeconds(2));
|
||||
Assert.Single(h.Completed);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Result_with_the_end_block_already_read_emits_at_once()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("847da54e", T0);
|
||||
h.Exit("847da54e", T0.AddSeconds(2.3));
|
||||
h.Now = T0.AddSeconds(2.31);
|
||||
h.Result("847da54e", T0.AddSeconds(2.31));
|
||||
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
Assert.Null(script.ResultHeldSinceUtc);
|
||||
Assert.Equal(T0.AddSeconds(2.31), script.ResultObservedAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Held_result_emits_without_exit_code_after_the_grace()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("784fcaf5", T0);
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("784fcaf5", T0.AddSeconds(2));
|
||||
|
||||
h.Now = T0.AddSeconds(2).Add(ImeLogTracker.PlatformScriptEndBlockGrace).AddMilliseconds(-100);
|
||||
h.Flush();
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
h.Now = T0.AddSeconds(2).Add(ImeLogTracker.PlatformScriptEndBlockGrace);
|
||||
h.Flush();
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Null(script.ExitCode);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal("ime_policy_result", script.ResultSource);
|
||||
|
||||
// An exit line surfacing after the emit is dropped — no second event, no fallback.
|
||||
h.Exit("784fcaf5", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(40);
|
||||
h.Flush();
|
||||
Assert.Single(h.Completed);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Shutdown_flush_emits_a_held_result_at_once()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("a52e4f47", T0);
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("a52e4f47", T0.AddSeconds(2), "Failed");
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
h.Flush(force: true);
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal("Failed", script.Result);
|
||||
Assert.Null(script.ExitCode);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Late_start_line_of_an_emitted_run_opens_no_new_run()
|
||||
{
|
||||
// Session e7f3c910, 376ee51a: the result was emitted, THEN the executor's start and
|
||||
// exit lines of the same run were read (a 2 s poll stall) — the start opened a second
|
||||
// slot and the exit code became a fallback duplicate 15 s later.
|
||||
using var h = new Harness();
|
||||
h.Start("376ee51a", T0);
|
||||
h.Exit("376ee51a", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("376ee51a", T0.AddSeconds(2));
|
||||
Assert.Single(h.Completed);
|
||||
Assert.Single(h.Started);
|
||||
|
||||
h.Start("376ee51a", T0.AddMilliseconds(300));
|
||||
Assert.Single(h.Started);
|
||||
h.Exit("376ee51a", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(30);
|
||||
h.Flush();
|
||||
Assert.Single(h.Completed);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Start_line_newer_than_the_emitted_result_is_the_next_run()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("338d9434", T0);
|
||||
h.Exit("338d9434", T0.AddSeconds(1));
|
||||
h.Now = T0.AddSeconds(1);
|
||||
h.Result("338d9434", T0.AddSeconds(1));
|
||||
Assert.Single(h.Completed);
|
||||
|
||||
// IME re-runs the policy after the user signed in.
|
||||
h.Start("338d9434", T0.AddMinutes(7));
|
||||
Assert.Equal(2, h.Started.Count);
|
||||
h.Exit("338d9434", T0.AddMinutes(7).AddSeconds(3));
|
||||
h.Now = T0.AddMinutes(7).AddSeconds(3);
|
||||
h.Result("338d9434", T0.AddMinutes(7).AddSeconds(3));
|
||||
Assert.Equal(2, h.Completed.Count);
|
||||
Assert.Equal(T0.AddMinutes(7), h.Completed[1].StartedAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Newer_start_line_closes_a_held_result_and_starts_the_next_run()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("c81b8053", T0);
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("c81b8053", T0.AddSeconds(2));
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
// The end block never surfaced before the policy ran again.
|
||||
h.Start("c81b8053", T0.AddSeconds(4));
|
||||
var first = Assert.Single(h.Completed);
|
||||
Assert.Null(first.ExitCode);
|
||||
Assert.Equal(T0, first.StartedAtUtc);
|
||||
Assert.Equal(2, h.Started.Count);
|
||||
|
||||
h.Exit("c81b8053", T0.AddSeconds(6));
|
||||
h.Now = T0.AddSeconds(6);
|
||||
h.Result("c81b8053", T0.AddSeconds(6));
|
||||
Assert.Equal(2, h.Completed.Count);
|
||||
Assert.Equal(0, h.Completed[1].ExitCode);
|
||||
Assert.Equal(T0.AddSeconds(4), h.Completed[1].StartedAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Result_without_a_start_takes_the_recovered_start_line_and_end_block()
|
||||
{
|
||||
// Both the start block and the end block were hidden when the result arrived; the
|
||||
// ledger rewind the result triggers brings both back on the next pass.
|
||||
using var h = new Harness();
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("d39eeef3", T0.AddSeconds(2));
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
h.Start("d39eeef3", T0);
|
||||
Assert.Empty(h.Started);
|
||||
h.Exit("d39eeef3", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(2.2);
|
||||
h.Flush();
|
||||
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(T0, script.StartedAtUtc);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Held_result_survives_a_restart()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("832e27bc", T0);
|
||||
h.Now = T0.AddSeconds(2);
|
||||
h.Result("832e27bc", T0.AddSeconds(2));
|
||||
h.Restart();
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
h.Exit("832e27bc", T0.AddSeconds(1.99));
|
||||
h.Now = T0.AddSeconds(2.5);
|
||||
h.Flush();
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
Assert.Equal(T0.AddSeconds(2), script.ResultObservedAtUtc);
|
||||
Assert.Equal("PS-SCRIPT-RESULT", script.ResultPatternId);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Emitted_marker_keeps_the_run_timestamp_across_a_restart()
|
||||
{
|
||||
using var h = new Harness();
|
||||
h.Start("89b3cbcd", T0);
|
||||
h.Exit("89b3cbcd", T0.AddSeconds(1));
|
||||
h.Now = T0.AddSeconds(1);
|
||||
h.Result("89b3cbcd", T0.AddSeconds(1));
|
||||
h.Restart();
|
||||
|
||||
h.Start("89b3cbcd", T0.AddMilliseconds(500)); // late line of the emitted run
|
||||
Assert.Single(h.Started);
|
||||
h.Start("89b3cbcd", T0.AddMinutes(5)); // the next run
|
||||
Assert.Equal(2, h.Started.Count);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Marker_list_from_an_older_state_file_still_dedups()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var persistence = new ImeTrackerStatePersistence(tmp.Path, new AgentLogger(tmp.Path, AgentLogLevel.Info));
|
||||
persistence.Save(new ImeTrackerStateData { PlatformScriptResultEmitted = new List<string> { "policyZ" } });
|
||||
|
||||
var completed = new List<ScriptExecutionState>();
|
||||
var started = new List<ScriptStartedInfo>();
|
||||
var tracker = new ImeLogTracker(tmp.Path, new List<ImeLogPattern>(), new AgentLogger(tmp.Path, AgentLogLevel.Info), stateDirectory: tmp.Path);
|
||||
tracker.OnScriptCompleted = s => completed.Add(s);
|
||||
tracker.OnScriptStarted = s => started.Add(s);
|
||||
tracker.LoadStateForTest();
|
||||
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyZ", "Success", T0);
|
||||
Assert.Empty(completed);
|
||||
|
||||
// Without a timestamp on the marker every start line is a new run, as before.
|
||||
tracker.LastMatchedLogTimestamp = T0;
|
||||
tracker.HandlePlatformScriptStarted("policyZ");
|
||||
Assert.Single(started);
|
||||
}
|
||||
}
|
||||
}
|
||||
+9
-5
@@ -41,7 +41,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
// Run 1: exit code seen, shutdown force-flush emits the fallback completion.
|
||||
var tracker1 = BuildTracker(tmp, out var emitted1);
|
||||
tracker1.SeedPendingPlatformScriptForTesting("policyA", exitCode: 0, exitObservedAtUtc: observedAt);
|
||||
tracker1.FlushStalePlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
tracker1.FlushPendingPlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
Assert.Single(emitted1);
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
@@ -68,7 +68,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
// Restarted tracker continues the grace window instead of dropping the script.
|
||||
var tracker2 = BuildTracker(tmp, out var emitted2);
|
||||
tracker2.LoadStateForTest();
|
||||
tracker2.FlushStalePlatformScriptResults(observedAt.AddSeconds(20));
|
||||
tracker2.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
|
||||
var script = Assert.Single(emitted2);
|
||||
Assert.Equal("policyB", script.PolicyId);
|
||||
@@ -84,7 +84,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
var tracker1 = BuildTracker(tmp, out _);
|
||||
tracker1.SeedPendingPlatformScriptForTesting("policyC", exitCode: 0, exitObservedAtUtc: observedAt);
|
||||
tracker1.FlushStalePlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
tracker1.FlushPendingPlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
// Restart, then a genuine RE-RUN of the same policy (fresh start clears the marker).
|
||||
@@ -109,8 +109,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
tracker.LoadStateForTest(); // must not throw
|
||||
|
||||
// Degrades to pre-fix behavior: no markers restored, normal emission works.
|
||||
// Degrades to pre-fix behavior: no markers restored, normal emission works (the
|
||||
// result waits for its end block until the shutdown flush).
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyD", "Success");
|
||||
tracker.FlushPendingPlatformScriptResults(DateTime.UtcNow, force: true);
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
|
||||
@@ -128,8 +130,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyE", "Failed", run2Start.AddMinutes(-5));
|
||||
Assert.Empty(emitted);
|
||||
|
||||
// Run 2's own result (newer than its start) still emits normally.
|
||||
// Run 2's own result (newer than its start) still emits normally — held for the end
|
||||
// block until the shutdown flush, since none is seeded here.
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyE", "Success", run2Start.AddMinutes(2));
|
||||
tracker.FlushPendingPlatformScriptResults(run2Start.AddMinutes(2), force: true);
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal(run2Start, script.StartedAtUtc);
|
||||
|
||||
+2
@@ -247,6 +247,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
|
||||
f.Tracker.LastMatchedLogTimestamp = ClockNow;
|
||||
f.Tracker.CompletePlatformScriptFromImeResultForTesting("beef7777", "Success", ClockNow);
|
||||
// No end block is seeded — the held result goes out with the shutdown flush.
|
||||
f.Tracker.FlushPendingPlatformScriptResults(f.Clock.UtcNow, force: true);
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
// Without the hardening the slot kept the 7-day-old start: the duration would have
|
||||
|
||||
+49
@@ -0,0 +1,49 @@
|
||||
using System;
|
||||
using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
{
|
||||
/// <summary>
|
||||
/// A held platform-script completion (IME result read before the executor end block) is
|
||||
/// emitted at the end of a later pass, when the tracker's "last matched" line is an unrelated
|
||||
/// one — the event stays bound to the result line's timestamp and pattern.
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerAdapterResultHoldTests
|
||||
{
|
||||
private static readonly DateTime ClockNow = new DateTime(2026, 9, 10, 22, 13, 40, DateTimeKind.Utc);
|
||||
|
||||
[Fact]
|
||||
public void Held_completion_is_bound_to_the_result_line_not_to_the_last_matched_one()
|
||||
{
|
||||
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var startTs = ClockNow.AddSeconds(-95);
|
||||
var resultTs = ClockNow.AddSeconds(-3);
|
||||
|
||||
f.Tracker.LastMatchedLogTimestamp = startTs;
|
||||
f.Tracker.HandlePlatformScriptStarted("376ee51a");
|
||||
|
||||
f.Tracker.LastMatchedLogTimestamp = resultTs;
|
||||
f.Tracker.LastMatchedPatternId = "PS-SCRIPT-RESULT";
|
||||
f.Tracker.CompletePlatformScriptFromImeResultForTesting("376ee51a", "Success", resultTs);
|
||||
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptCompleted));
|
||||
|
||||
// Other lines were matched before the end block was read and the pass ended.
|
||||
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddSeconds(-1);
|
||||
f.Tracker.LastMatchedPatternId = "IME-DOWNLOADING";
|
||||
f.Tracker.RecordPlatformScriptExitCodeForTesting("376ee51a", 0, resultTs.AddMilliseconds(-8));
|
||||
f.Tracker.FlushPendingPlatformScriptResults(f.Clock.UtcNow);
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal(resultTs, info.OccurredAtUtc);
|
||||
Assert.Equal("PS-SCRIPT-RESULT", info.Payload!["patternId"]);
|
||||
Assert.Equal("0", info.Payload["exitCode"]);
|
||||
Assert.Equal("ime_policy_result", info.Payload["resultSource"]);
|
||||
Assert.Equal("92.00", info.Payload["durationSeconds"]);
|
||||
}
|
||||
}
|
||||
}
|
||||
+192
-129
@@ -222,15 +222,6 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// PowerShell script tracking handlers
|
||||
// -----------------------------------------------------------------------
|
||||
|
||||
// Returns the platform-script accumulator that owns the entry being processed, or null.
|
||||
// Health-script (remediation) state is no longer tracked line-by-line — the HS-NEW-RESULT
|
||||
// pattern delivers the full pre-detection / remediation / post-detection JSON in one shot
|
||||
// via HandleHealthScriptResult. The platform branch keeps its line-by-line accumulator
|
||||
// because PS-* patterns (PS-SCRIPT-CONTEXT / PS-SCRIPT-EXITCODE / PS-AGENT-OUTPUT / …) still
|
||||
// arrive across multiple log lines; ownership is by file position (see
|
||||
// ImeLogTracker.Overwrite.cs), never by which script happened to start last.
|
||||
private ScriptExecutionState GetCurrentPlatformScript() => ResolvePlatformScriptForCurrentEntry();
|
||||
|
||||
private void HandleScriptStarted(Match match, Dictionary<string, string> parameters)
|
||||
{
|
||||
var id = match.Groups["id"]?.Value;
|
||||
@@ -277,27 +268,59 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// a regex Match).
|
||||
internal void HandlePlatformScriptStarted(string id, string source = null)
|
||||
{
|
||||
// Stale-slot hardening (session eaf3d8c4): a replayed start line from a previous
|
||||
// enrollment whose matching result never appeared (script was mid-run when that
|
||||
// enrollment ended) leaves a pending slot with a days-old StartedAtUtc. When the
|
||||
// same policy genuinely re-runs now, the fresh start must begin a NEW execution —
|
||||
// otherwise the ancient start pairs with the fresh completion and the duration
|
||||
// lies. > 24 h mirrors the adapter's source-timestamp staleness clamp.
|
||||
var currentStartTs = LastMatchedLogTimestamp ?? DateTime.UtcNow;
|
||||
if (_pendingPlatformScripts.TryGetValue(id, out var pendingSlot)
|
||||
&& pendingSlot.StartedAtUtc.HasValue
|
||||
&& currentStartTs - pendingSlot.StartedAtUtc.Value > TimeSpan.FromHours(24))
|
||||
var currentStartTs = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
|
||||
// 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
|
||||
// files are read in turn (AgentExecutor.log first, but a script's exit line and IME's
|
||||
// result line are 8–30 ms apart), a ledger rewind recovered the block, or the poll
|
||||
// loop stalled (session e7f3c910: the late line opened a second slot, cleared the
|
||||
// emitted-marker and turned the exit code that followed into a fallback duplicate
|
||||
// 15 s later). It owns the lines behind it in its file and opens nothing. Strictly
|
||||
// older: a start line at the result's own timestamp is the next run (source lines
|
||||
// never tie; a low-resolution clock in a test may).
|
||||
if (_platformScriptResultEmitted.TryGetValue(id, out var emittedResultTs) && currentStartTs < emittedResultTs)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: discarding stale pending platform-script slot for {id} (started {pendingSlot.StartedAtUtc:o})");
|
||||
_pendingPlatformScripts.Remove(id);
|
||||
RecordInvocationMarker(id, isClose: false);
|
||||
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;
|
||||
}
|
||||
|
||||
if (_pendingPlatformScripts.TryGetValue(id, out var pendingSlot))
|
||||
{
|
||||
if (pendingSlot.StartedAtUtc.HasValue && currentStartTs - pendingSlot.StartedAtUtc.Value > TimeSpan.FromHours(24))
|
||||
{
|
||||
// Stale-slot hardening (session eaf3d8c4): a replayed start line from a previous
|
||||
// enrollment whose matching result never appeared (script was mid-run when that
|
||||
// enrollment ended) leaves a pending slot with a days-old StartedAtUtc. When the
|
||||
// same policy genuinely re-runs now, the fresh start must begin a NEW execution —
|
||||
// otherwise the ancient start pairs with the fresh completion and the duration
|
||||
// lies. > 24 h mirrors the adapter's source-timestamp staleness clamp.
|
||||
_logger.Debug($"ImeLogTracker: discarding stale pending platform-script slot for {id} (started {pendingSlot.StartedAtUtc:o})");
|
||||
_pendingPlatformScripts.Remove(id);
|
||||
}
|
||||
else if (pendingSlot.Result != null && pendingSlot.ResultObservedAtUtc.HasValue && currentStartTs >= pendingSlot.ResultObservedAtUtc.Value)
|
||||
{
|
||||
// The held run is over — a start line at or after its result is the next run.
|
||||
// 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 (!pendingSlot.StartedAtUtc.HasValue)
|
||||
{
|
||||
// The slot was opened by its result while the start block was still hidden;
|
||||
// the recovered start line dates the run.
|
||||
pendingSlot.StartedAtUtc = currentStartTs;
|
||||
_stateDirty = true;
|
||||
}
|
||||
}
|
||||
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.
|
||||
// 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
|
||||
{
|
||||
@@ -325,13 +348,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
// 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; platform-script lines feed _pendingPlatformScripts.
|
||||
// single-slot _pendingHealthScript (the HS-NEW-RESULT JSON delivers the full cycle in one
|
||||
// shot; the slot only enriches the early HS-COMPLIANCE signal). Platform-script lines feed
|
||||
// _pendingPlatformScripts, and the slot that owns a line is decided by file position (see
|
||||
// ImeLogTracker.Overwrite.cs), never by which script happened to start last.
|
||||
private ScriptExecutionState GetCurrentScriptForLineUpdate(Dictionary<string, string> parameters)
|
||||
=> GetCurrentScriptForLineUpdate(parameters, out _);
|
||||
|
||||
// ownerPolicyId names the platform script that owns the line by file position even when
|
||||
// its pending slot is gone (the completion was already emitted); null for health-script
|
||||
// lines and for lines no platform invocation owns.
|
||||
private ScriptExecutionState GetCurrentScriptForLineUpdate(Dictionary<string, string> parameters, out string ownerPolicyId)
|
||||
{
|
||||
var scriptType = parameters != null && parameters.TryGetValue("scriptType", out var st) ? st : null;
|
||||
return string.Equals(scriptType, "remediation", StringComparison.OrdinalIgnoreCase)
|
||||
? _pendingHealthScript
|
||||
: GetCurrentPlatformScript();
|
||||
if (string.Equals(scriptType, "remediation", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
ownerPolicyId = null;
|
||||
return _pendingHealthScript;
|
||||
}
|
||||
return ResolvePlatformScriptForCurrentEntry(out ownerPolicyId);
|
||||
}
|
||||
|
||||
// AgentExecutor.exe hosts platform scripts (…\Policies\Scripts\<id>.ps1) as well as
|
||||
@@ -384,24 +419,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var exitCodeStr = match.Groups["exitCode"]?.Value;
|
||||
if (string.IsNullOrEmpty(exitCodeStr) || !int.TryParse(exitCodeStr, out var exitCode)) return;
|
||||
|
||||
var script = GetCurrentScriptForLineUpdate(parameters);
|
||||
var script = GetCurrentScriptForLineUpdate(parameters, out var ownerPolicyId);
|
||||
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}");
|
||||
}
|
||||
ApplyExitCode(script, exitCode, LastMatchedLogTimestamp ?? UtcNowProvider());
|
||||
else if (ownerPolicyId != null)
|
||||
_logger.Debug($"ImeLogTracker: exit code {exitCode} belongs to platform script {ownerPolicyId}, whose completion was already emitted — dropped");
|
||||
// An exit code means the executor just wrote its end block and IME is about to
|
||||
// write the result — both land at a stale stream position when another process
|
||||
// appended meanwhile. Check the ledgers on the next pass.
|
||||
RequestOverwriteCheck();
|
||||
}
|
||||
|
||||
private void ApplyExitCode(ScriptExecutionState script, int exitCode, DateTime observedAtUtc)
|
||||
{
|
||||
script.ExitCode = exitCode;
|
||||
// Stamp when we learned the script's exit code so the deadline-based fallback
|
||||
// (FlushPendingPlatformScriptResults) 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 = observedAtUtc;
|
||||
_logger.Debug($"ImeLogTracker: script exit code {exitCode} for {script.PolicyId}");
|
||||
}
|
||||
|
||||
private void HandleScriptOutput(Match match, Dictionary<string, string> parameters)
|
||||
{
|
||||
var outputType = parameters != null && parameters.TryGetValue("outputType", out var ot) ? ot : null;
|
||||
@@ -448,20 +488,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (string.IsNullOrEmpty(id)) return;
|
||||
|
||||
// Dedup: the deadline-based fallback (FlushStalePlatformScriptResults) may already have
|
||||
CompletePlatformScriptFromImeResult(id, result, LastMatchedLogTimestamp, LastMatchedPatternId);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The authoritative IME <c>PS-SCRIPT-RESULT</c> line of a platform script. Emits at once
|
||||
/// when the executor end block (exit code, output) has been read already — the normal
|
||||
/// order of the two files — and otherwise holds the completion: the end block reaches the
|
||||
/// tracker after the result whenever a concurrent writer overwrote it (the check this
|
||||
/// result triggers recovers it one pass later), when the AgentExecutor.log read of a pass
|
||||
/// simply preceded the exit line by a few milliseconds, or when the poll loop stalled.
|
||||
/// Emitting immediately lost the exit code in all three cases and, once the late start
|
||||
/// line reopened the slot, produced a fallback duplicate (session e7f3c910).
|
||||
/// <see cref="FlushPendingPlatformScriptResults"/> emits the held completion.
|
||||
/// </summary>
|
||||
internal void CompletePlatformScriptFromImeResult(string policyId, string result, DateTime? resultLineTimestampUtc, string patternId)
|
||||
{
|
||||
// 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.Contains(id))
|
||||
if (_platformScriptResultEmitted.ContainsKey(policyId))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {id} PS-SCRIPT-RESULT arrived after fallback emit — skipping duplicate");
|
||||
_pendingPlatformScripts.Remove(id);
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} PS-SCRIPT-RESULT arrived after fallback emit — skipping duplicate");
|
||||
_pendingPlatformScripts.Remove(policyId);
|
||||
return;
|
||||
}
|
||||
|
||||
// Merge with pending AgentExecutor data if available
|
||||
if (_pendingPlatformScripts.TryGetValue(id, out var script))
|
||||
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
|
||||
@@ -471,10 +527,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// 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
|
||||
&& LastMatchedLogTimestamp.HasValue
|
||||
&& LastMatchedLogTimestamp.Value < script.StartedAtUtc.Value)
|
||||
&& resultLineTimestampUtc.HasValue
|
||||
&& resultLineTimestampUtc.Value < script.StartedAtUtc.Value)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {id} result predates the current run's start — stale result from a previous run, skipping");
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} result predates the current run's start — stale result from a previous run, skipping");
|
||||
return;
|
||||
}
|
||||
}
|
||||
@@ -482,28 +538,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
script = new ScriptExecutionState
|
||||
{
|
||||
PolicyId = id,
|
||||
PolicyId = policyId,
|
||||
ScriptType = "platform"
|
||||
};
|
||||
_pendingPlatformScripts[policyId] = script;
|
||||
}
|
||||
|
||||
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);
|
||||
script.ResultObservedAtUtc = resultLineTimestampUtc ?? UtcNowProvider();
|
||||
script.ResultPatternId = patternId;
|
||||
_stateDirty = true;
|
||||
|
||||
if (script.ExitCode.HasValue)
|
||||
{
|
||||
EmitPlatformScriptResult(script);
|
||||
}
|
||||
else
|
||||
{
|
||||
script.ResultHeldSinceUtc = UtcNowProvider();
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} result={result} seen before its executor end block — holding the completion up to {PlatformScriptEndBlockGrace.TotalSeconds:F0}s for the exit code");
|
||||
}
|
||||
// The result block is IME's first write after the script wait — the executor's end
|
||||
// block in the other file may have landed behind the bookmark at the same time.
|
||||
RequestOverwriteCheck();
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The one emit path for platform-script completions (IME result, held result, exit-code
|
||||
/// fallback): event, emitted-marker with the run's source timestamp, slot closed.
|
||||
/// </summary>
|
||||
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)}");
|
||||
EmitScriptEvent(script);
|
||||
_platformScriptResultEmitted[script.PolicyId] = script.ResultObservedAtUtc ?? script.ExitObservedAtUtc ?? UtcNowProvider();
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Grace period after a platform script's AgentExecutor exit code is observed before
|
||||
/// <see cref="FlushStalePlatformScriptResults"/> emits a completion from that exit code.
|
||||
/// <see cref="FlushPendingPlatformScriptResults"/> emits a completion from that exit code.
|
||||
/// IME logs its authoritative <c>PS-SCRIPT-RESULT</c> line within ~1 s of exit; when it
|
||||
/// is missing after 15 s it was hidden by a concurrent writer (the ledger check in
|
||||
/// <c>ImeLogTracker.Overwrite.cs</c> recovers that line) or the enrollment ended before
|
||||
@@ -512,41 +588,61 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private static readonly TimeSpan PlatformScriptResultGrace = TimeSpan.FromSeconds(15);
|
||||
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// How long an IME result waits for the executor end block of its run before the
|
||||
/// completion goes out without an exit code. An overwritten end block surfaces on the
|
||||
/// pass after the result (100 ms, the result triggers the ledger check); a stalled poll
|
||||
/// loop was measured at 2 s (session e7f3c910, VM at 100 % CPU). Well below the 15 s
|
||||
/// exit-code fallback, and the event keeps the result line's timestamp — only its
|
||||
/// delivery waits.
|
||||
/// </summary>
|
||||
private readonly HashSet<string> _platformScriptResultEmitted =
|
||||
new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
internal static readonly TimeSpan PlatformScriptEndBlockGrace = TimeSpan.FromSeconds(5);
|
||||
|
||||
/// <summary>
|
||||
/// Emits a <c>script_completed</c>/<c>script_failed</c> for every pending platform script
|
||||
/// that has a known AgentExecutor exit code but whose IME <c>PS-SCRIPT-RESULT</c> line has
|
||||
/// not arrived within <see cref="PlatformScriptResultGrace"/>. Without this, scripts that
|
||||
/// completed shortly before the agent terminates are silently dropped (the
|
||||
/// <c>_pendingPlatformScripts</c> 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 <c>resultSource=agentexecutor_fallback</c> so the data is honest
|
||||
/// about its provenance.
|
||||
/// <para>
|
||||
/// Runs on the single-threaded polling loop (no locking needed, same as the handlers).
|
||||
/// <paramref name="force"/> bypasses the grace check for the final pass on shutdown.
|
||||
/// </para>
|
||||
/// Platform scripts already emitted (via the authoritative PS-SCRIPT-RESULT path or the
|
||||
/// exit-code fallback), keyed by policy id with the source timestamp of the emitted run
|
||||
/// (the result line, or the exit line for a fallback emit). Guards against double emission
|
||||
/// when both paths fire for the same script, and tells a late start line of the emitted
|
||||
/// run from the start of the next run.
|
||||
/// </summary>
|
||||
internal void FlushStalePlatformScriptResults(DateTime nowUtc, bool force = false)
|
||||
private readonly Dictionary<string, DateTime> _platformScriptResultEmitted =
|
||||
new Dictionary<string, DateTime>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// End-of-pass emit for pending platform scripts, two cases:
|
||||
/// <list type="bullet">
|
||||
/// <item>A held IME result (<see cref="ScriptExecutionState.ResultHeldSinceUtc"/>) goes
|
||||
/// 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>
|
||||
/// </list>
|
||||
/// 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;
|
||||
|
||||
List<string> toRemove = null;
|
||||
foreach (var kv in _pendingPlatformScripts)
|
||||
var fallbackEmitted = false;
|
||||
foreach (var script in _pendingPlatformScripts.Values.ToList())
|
||||
{
|
||||
var script = kv.Value;
|
||||
|
||||
// Already emitted by the authoritative path — just drop the stale buffer entry.
|
||||
if (_platformScriptResultEmitted.Contains(script.PolicyId))
|
||||
if (_platformScriptResultEmitted.ContainsKey(script.PolicyId))
|
||||
{
|
||||
(toRemove ??= new List<string>()).Add(kv.Key);
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
_stateDirty = true;
|
||||
continue;
|
||||
}
|
||||
|
||||
if (script.Result != null)
|
||||
{
|
||||
if (script.ExitCode.HasValue)
|
||||
EmitPlatformScriptResult(script, "executor end block read after the result");
|
||||
else if (force || !script.ResultHeldSinceUtc.HasValue || nowUtc - script.ResultHeldSinceUtc.Value >= PlatformScriptEndBlockGrace)
|
||||
EmitPlatformScriptResult(script, $"no executor end block within {PlatformScriptEndBlockGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)}");
|
||||
continue;
|
||||
}
|
||||
|
||||
@@ -561,27 +657,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
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<string>()).Add(kv.Key);
|
||||
EmitPlatformScriptResult(script,
|
||||
$"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)} — emitted from AgentExecutor exit code {script.ExitCode.Value} (fallback)");
|
||||
fallbackEmitted = true;
|
||||
}
|
||||
|
||||
if (toRemove != null)
|
||||
{
|
||||
// The flush can fire on a quiet polling cycle (grace expiry with no new log
|
||||
// lines), where nothing else marks state dirty — the emitted-markers must reach
|
||||
// the state file before a restart or the restarted tracker re-emits (H1).
|
||||
_stateDirty = true;
|
||||
foreach (var key in toRemove)
|
||||
_pendingPlatformScripts.Remove(key);
|
||||
RequestOverwriteCheck();
|
||||
}
|
||||
// The fallback is an end signal like the others: the result line it stood in for
|
||||
// may sit overwritten behind the bookmark of the other file.
|
||||
if (fallbackEmitted) RequestOverwriteCheck();
|
||||
}
|
||||
|
||||
/// <summary>Test seam: inject a pending platform script as if AgentExecutor.log had reported
|
||||
@@ -604,42 +687,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
RecordInvocationMarker(policyId, isClose: false);
|
||||
}
|
||||
|
||||
/// <summary>Test seam: simulate the authoritative IME PS-SCRIPT-RESULT path for a platform
|
||||
/// script (same code as <see cref="HandleScriptCompleted"/> minus regex extraction).
|
||||
/// <paramref name="resultLineTimestampUtc"/> stands in for the CMTrace timestamp of the
|
||||
/// PS-SCRIPT-RESULT line (production reads it via <see cref="LastMatchedLogTimestamp"/>).</summary>
|
||||
/// <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
|
||||
/// via <see cref="LastMatchedLogTimestamp"/>, the fallback here).</summary>
|
||||
internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result, DateTime? resultLineTimestampUtc = null)
|
||||
{
|
||||
if (string.IsNullOrEmpty(policyId)) return;
|
||||
CompletePlatformScriptFromImeResult(policyId, result, resultLineTimestampUtc ?? LastMatchedLogTimestamp, "PS-SCRIPT-RESULT");
|
||||
}
|
||||
|
||||
if (_platformScriptResultEmitted.Contains(policyId))
|
||||
{
|
||||
_pendingPlatformScripts.Remove(policyId);
|
||||
return;
|
||||
}
|
||||
|
||||
/// <summary>Test seam: the AgentExecutor exit-code line of a pending platform script (the
|
||||
/// production handler minus regex extraction and positional ownership).</summary>
|
||||
internal void RecordPlatformScriptExitCodeForTesting(string policyId, int exitCode, DateTime observedAtUtc)
|
||||
{
|
||||
if (_pendingPlatformScripts.TryGetValue(policyId, out var script))
|
||||
{
|
||||
// Mirror of HandleScriptCompleted's stale-result guard: a result older than the
|
||||
// pending slot's start belongs to a previous run of the same policy.
|
||||
if (script.StartedAtUtc.HasValue
|
||||
&& resultLineTimestampUtc.HasValue
|
||||
&& resultLineTimestampUtc.Value < script.StartedAtUtc.Value)
|
||||
{
|
||||
return;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
script = new ScriptExecutionState { PolicyId = policyId, ScriptType = "platform" };
|
||||
}
|
||||
|
||||
script.Result = result;
|
||||
script.ResultSource = "ime_policy_result";
|
||||
EmitScriptEvent(script);
|
||||
_platformScriptResultEmitted.Add(policyId);
|
||||
_pendingPlatformScripts.Remove(policyId);
|
||||
_stateDirty = true;
|
||||
ApplyExitCode(script, exitCode, observedAtUtc);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
+8
-2
@@ -380,9 +380,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (!isClose && policyId != null) _lastPlatformMarker = marker;
|
||||
}
|
||||
|
||||
/// <summary>The pending platform script that owns the entry being processed, or null.</summary>
|
||||
private ScriptExecutionState ResolvePlatformScriptForCurrentEntry()
|
||||
/// <summary>
|
||||
/// The pending platform script that owns the entry being processed, or null.
|
||||
/// <paramref name="ownerPolicyId"/> names the owning platform script even when its slot is
|
||||
/// gone (completion already emitted); null when no platform invocation owns the entry.
|
||||
/// </summary>
|
||||
private ScriptExecutionState ResolvePlatformScriptForCurrentEntry(out string ownerPolicyId)
|
||||
{
|
||||
ownerPolicyId = null;
|
||||
InvocationMarker marker = null;
|
||||
List<InvocationMarker> list = null;
|
||||
if (_currentSourceFileName != null && _currentEntryOffset >= 0 && _invocationMarkers.TryGetValue(_currentSourceFileName, out list))
|
||||
@@ -401,6 +406,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (marker == null && (list == null || list.Count == 0)) marker = _lastPlatformMarker;
|
||||
if (marker == null || marker.IsClose || marker.PolicyId == null) return null;
|
||||
|
||||
ownerPolicyId = marker.PolicyId;
|
||||
ScriptExecutionState state;
|
||||
return _pendingPlatformScripts.TryGetValue(marker.PolicyId, out state) ? state : null;
|
||||
}
|
||||
|
||||
+19
-11
@@ -956,11 +956,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
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
|
||||
// Platform-script completions that wait for the other file: an IME result
|
||||
// held for its executor end block, and the exit-code fallback for a
|
||||
// result IME never logged within the grace period. Runs on this same loop
|
||||
// thread (no locking) so it observes the buffer right after parsing.
|
||||
FlushStalePlatformScriptResults(DateTime.UtcNow);
|
||||
FlushPendingPlatformScriptResults(UtcNowProvider());
|
||||
|
||||
// Token-failure grace window: fires only when the failure stayed
|
||||
// unresolved (no IME-TOKEN-SUCCESS) for the whole window. Runs after
|
||||
@@ -988,10 +988,11 @@ 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); }
|
||||
// Final pass: force-flush any platform script still waiting for the other file
|
||||
// (a held IME result, or an exit code whose IME result is still pending).
|
||||
// Best-effort — emits only while callbacks are still wired (i.e. the adapter
|
||||
// hasn't been disposed).
|
||||
try { FlushPendingPlatformScriptResults(UtcNowProvider(), force: true); }
|
||||
catch (Exception ex) { _logger.Warning($"ImeLogTracker: shutdown script flush failed: {ex.Message}"); }
|
||||
|
||||
// Final state save on shutdown
|
||||
@@ -1103,10 +1104,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// (the in-memory marker set started empty). Old state files have null here —
|
||||
// degrades to the pre-fix behavior, no crash.
|
||||
_platformScriptResultEmitted.Clear();
|
||||
if (state.PlatformScriptResultEmitted != null)
|
||||
if (state.PlatformScriptResultEmittedAt != null)
|
||||
{
|
||||
foreach (var kv in state.PlatformScriptResultEmittedAt)
|
||||
_platformScriptResultEmitted[kv.Key] = kv.Value;
|
||||
}
|
||||
else if (state.PlatformScriptResultEmitted != null)
|
||||
{
|
||||
// State files from before the marker carried the run's timestamp: the dedup
|
||||
// works as before, the late-start-line guard never fires for these runs.
|
||||
foreach (var id in state.PlatformScriptResultEmitted)
|
||||
_platformScriptResultEmitted.Add(id);
|
||||
_platformScriptResultEmitted[id] = DateTime.MinValue;
|
||||
}
|
||||
|
||||
_pendingPlatformScripts.Clear();
|
||||
@@ -1197,7 +1205,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
// H1 (delta review 2026-07-02): platform-script dedup markers + pending buffer
|
||||
// must survive restarts — see the LoadState comment for the duplicate scenario.
|
||||
PlatformScriptResultEmitted = _platformScriptResultEmitted.ToList(),
|
||||
PlatformScriptResultEmittedAt = new Dictionary<string, DateTime>(_platformScriptResultEmitted, StringComparer.OrdinalIgnoreCase),
|
||||
PendingPlatformScripts = _pendingPlatformScripts.Values.ToList(),
|
||||
ScriptTimeoutSuspectedPosted = _scriptTimeoutSuspectedPosted.ToList(),
|
||||
};
|
||||
|
||||
+7
@@ -142,7 +142,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// continues its grace window after the restart instead of being silently dropped.
|
||||
// ScriptExecutionState is a plain DTO, serialized directly (no mapping layer needed).
|
||||
// All three are null on state files from before this fix — LoadState treats null as empty.
|
||||
// Read-only migration input: state files written before the marker carried the run's
|
||||
// source timestamp (agents up to 2.0.1458). Never written any more.
|
||||
[JsonProperty(NullValueHandling = NullValueHandling.Ignore)]
|
||||
public List<string> PlatformScriptResultEmitted { get; set; }
|
||||
// Policy id → source timestamp of the emitted run (its result line; the exit line for a
|
||||
// fallback emit): the dedup marker plus the reference that tells a late start line of
|
||||
// that run from the start of the next one.
|
||||
public Dictionary<string, DateTime> PlatformScriptResultEmittedAt { get; set; }
|
||||
public List<ScriptExecutionState> PendingPlatformScripts { get; set; }
|
||||
public List<string> ScriptTimeoutSuspectedPosted { get; set; }
|
||||
|
||||
|
||||
+24
-1
@@ -61,11 +61,34 @@ public class ScriptExecutionState
|
||||
/// <summary>
|
||||
/// UTC timestamp at which the AgentExecutor.log exit-code line for this platform script was
|
||||
/// observed. Drives the deadline check in
|
||||
/// <see cref="ImeLogTracker.FlushStalePlatformScriptResults"/> — set only on the platform path
|
||||
/// <see cref="ImeLogTracker.FlushPendingPlatformScriptResults"/> — set only on the platform path
|
||||
/// (PS-AGENT exit code); null until an exit code is seen.
|
||||
/// </summary>
|
||||
public System.DateTime? ExitObservedAtUtc { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Source (CMTrace) timestamp of the IME <c>PS-SCRIPT-RESULT</c> line that delivered
|
||||
/// <see cref="Result"/> (platform scripts, <c>ime_policy_result</c> only). The emitted event is
|
||||
/// bound to it — the emit may happen passes later (see <see cref="ResultHeldSinceUtc"/>), when
|
||||
/// the tracker's "last matched" line is an unrelated one. Also the reference a later start line
|
||||
/// of the same policy is compared against: a start older than the emitted result is the late
|
||||
/// start line of that run, not a new run.
|
||||
/// </summary>
|
||||
public System.DateTime? ResultObservedAtUtc { get; set; }
|
||||
|
||||
/// <summary>Pattern id of the line that delivered <see cref="Result"/> (surfaced as <c>patternId</c> on the event).</summary>
|
||||
public string ResultPatternId { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Wall-clock time (agent UTC) at which the IME result was seen while the executor end block
|
||||
/// (exit code, stdout, stderr) had not been read yet. The tracker holds the emit until the end
|
||||
/// block arrives — an overwritten block surfaces one pass later through the ledger rewind that
|
||||
/// the result itself triggers, and the AgentExecutor.log read can simply lag behind the IME log
|
||||
/// read — or until <c>ImeLogTracker.PlatformScriptEndBlockGrace</c> elapsed. Null when the
|
||||
/// result was not held.
|
||||
/// </summary>
|
||||
public System.DateTime? ResultHeldSinceUtc { get; set; }
|
||||
|
||||
/// <summary>"True" or "False" compliance result (remediation detection / post-detection only).</summary>
|
||||
public string ComplianceResult { get; set; }
|
||||
|
||||
|
||||
@@ -1254,23 +1254,25 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
if (!string.IsNullOrEmpty(script.Stdout)) data["stdout"] = script.Stdout!;
|
||||
if (!string.IsNullOrEmpty(script.Stderr)) data["stderr"] = script.Stderr!;
|
||||
|
||||
// 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.
|
||||
// A platform-script completion is bound to the script's own line, not to the tracker's
|
||||
// "last matched" one: the exit-code fallback emits a grace period after its exit line,
|
||||
// and an IME result held for its executor end block emits at the end of a later pass —
|
||||
// by then LastMatched* name an unrelated line. The fallback carries no patternId (no
|
||||
// line delivered its result). Health scripts carry neither stamp and stay on the last
|
||||
// matched line, which IS their result line.
|
||||
var isFallback = string.Equals(script.ResultSource, "agentexecutor_fallback", StringComparison.Ordinal);
|
||||
if (!isFallback)
|
||||
{
|
||||
var patternId = _tracker.LastMatchedPatternId;
|
||||
var patternId = script.ResultPatternId ?? _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);
|
||||
var sourceTs = isFallback ? script.ExitObservedAtUtc : script.ResultObservedAtUtc;
|
||||
var now = sourceTs.HasValue
|
||||
? ResolveOccurredAt(sourceTs, out derivedFromClock, out rawSourceTs)
|
||||
: ResolveOccurredAt(out derivedFromClock, out rawSourceTs);
|
||||
|
||||
// Historic replay (a previous enrollment's log) — do not emit at all. The early
|
||||
// return also skips MaybeEmitBootstrapDetected / MaybeEmitScriptTimeoutSuspected,
|
||||
|
||||
@@ -132,7 +132,7 @@ describe('buildSessionCoverage — IME log tracker', () => {
|
||||
ev('ime_tracker_degraded', 50, { file: 'AppWorkload.log', lineBudgetBreaks: 1, regexTimeouts: 0, oversizedLines: 0 }),
|
||||
ev('ime_pattern_hits', 900, { linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1 }, { severity: 'Debug' }),
|
||||
]);
|
||||
expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1 });
|
||||
expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 12000, lineBudgetBreaks: 7, regexTimeouts: 2, oversizedLines: 1, overwriteRewinds: null, overwriteBytesReprocessed: null });
|
||||
expect(c.gaps[0]).toContain('skipped the remaining patterns on 7 line(s)');
|
||||
expect(c.gaps[0]).toContain('gave up on 2 line(s) after a regex timeout');
|
||||
expect(c.gaps[0]).toContain('dropped 1 oversized line(s)');
|
||||
@@ -143,9 +143,30 @@ describe('buildSessionCoverage — IME log tracker', () => {
|
||||
ev('agent_started', 0),
|
||||
ev('ime_pattern_hits', 900, { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0 }),
|
||||
]);
|
||||
expect(c.imeTracker).toEqual({ degraded: false, sessionTotals: { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0 } });
|
||||
expect(c.imeTracker).toEqual({ degraded: false, sessionTotals: { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: null, overwriteBytesReprocessed: null } });
|
||||
expect(c.gaps).toEqual([]);
|
||||
});
|
||||
|
||||
it('reports re-read overwritten log blocks as recovered data — a note, never a gap or degradation', () => {
|
||||
// Agents ≥ 2.0.1458: IME processes overwrite each other's bytes in AgentExecutor.log and
|
||||
// IntuneManagementExtension.log; the tracker re-reads the changed blocks and counts them.
|
||||
const c = buildSessionCoverage(SESSION, [
|
||||
ev('agent_started', 0),
|
||||
ev('ime_pattern_hits', 900, { linesRead: 8957, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 6, overwriteBytesReprocessed: 5120 }, { severity: 'Debug' }),
|
||||
]);
|
||||
expect(c.imeTracker.degraded).toBe(false);
|
||||
expect(c.imeTracker.sessionTotals).toEqual({ linesRead: 8957, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 6, overwriteBytesReprocessed: 5120 });
|
||||
expect(c.imeTracker.note).toBe('6 log block(s) a concurrent IME process had overwritten were re-read (5 KB) — script results and exit codes in them are complete, not missing.');
|
||||
expect(c.gaps).toEqual([]);
|
||||
});
|
||||
|
||||
it('adds no note when nothing was overwritten or the agent predates the counter', () => {
|
||||
const c = buildSessionCoverage(SESSION, [
|
||||
ev('agent_started', 0),
|
||||
ev('ime_pattern_hits', 900, { linesRead: 800, lineBudgetBreaks: 0, regexTimeouts: 0, oversizedLines: 0, overwriteRewinds: 0, overwriteBytesReprocessed: 0 }),
|
||||
]);
|
||||
expect(c.imeTracker.note).toBeUndefined();
|
||||
});
|
||||
});
|
||||
|
||||
describe('buildSessionCoverage — collectors, upload, disk', () => {
|
||||
|
||||
@@ -46,6 +46,7 @@ export const COVERAGE_EVENT_FIELDS =
|
||||
'data.bootToAgentStartSeconds,data.agentUptimeSeconds,data.outcome,data.note,' +
|
||||
'data.earliestRejectedSourceTimestamp,' +
|
||||
'data.file,data.firstSkippedPattern,data.lineBudgetBreaks,data.regexTimeouts,data.oversizedLines,data.unanchoredPatterns,data.linesRead,' +
|
||||
'data.overwriteRewinds,data.overwriteBytesReprocessed,' +
|
||||
'data.collector,data.reason,data.errorType,' +
|
||||
'data.pendingItemCount,data.pendingBytes,data.kind,data.itemCount,data.disk_free_gb,' +
|
||||
'data.truncated,data.includedFiles,data.includedBytes,data.skippedFiles,data.skippedByReason,data.problemsByKind,' +
|
||||
@@ -87,7 +88,15 @@ export interface ImeTrackerCoverage {
|
||||
lineBudgetBreaks: number | null;
|
||||
regexTimeouts: number | null;
|
||||
oversizedLines: number | null;
|
||||
/**
|
||||
* Times the tracker re-read a log block a concurrent IME process had written over bytes
|
||||
* it had already read (agents ≥ 2.0.1458). Recovered data — never a gap and not degradation.
|
||||
*/
|
||||
overwriteRewinds: number | null;
|
||||
overwriteBytesReprocessed: number | null;
|
||||
};
|
||||
/** Present when overwriteRewinds > 0: says in words that those blocks were recovered, not lost. */
|
||||
note?: string;
|
||||
}
|
||||
|
||||
export interface CollectorDegradation {
|
||||
@@ -276,8 +285,20 @@ export function buildSessionCoverage(
|
||||
lineBudgetBreaks: num(hits.data?.lineBudgetBreaks),
|
||||
regexTimeouts: num(hits.data?.regexTimeouts),
|
||||
oversizedLines: num(hits.data?.oversizedLines),
|
||||
overwriteRewinds: num(hits.data?.overwriteRewinds),
|
||||
overwriteBytesReprocessed: num(hits.data?.overwriteBytesReprocessed),
|
||||
}
|
||||
: undefined;
|
||||
// IME processes append to AgentExecutor.log and IntuneManagementExtension.log with independent
|
||||
// stream positions and overwrite each other; the tracker re-reads what changed. That is
|
||||
// recovered data — it must never read as a gap or as a degraded tracker.
|
||||
const rewinds = sessionTotals?.overwriteRewinds ?? 0;
|
||||
const overwriteNote =
|
||||
rewinds > 0
|
||||
? `${rewinds} log block(s) a concurrent IME process had overwritten were re-read` +
|
||||
`${sessionTotals?.overwriteBytesReprocessed ? ` (${Math.round(sessionTotals.overwriteBytesReprocessed / 1024)} KB)` : ''}` +
|
||||
' — script results and exit codes in them are complete, not missing.'
|
||||
: undefined;
|
||||
let imeTracker: ImeTrackerCoverage;
|
||||
if (degradedEv) {
|
||||
imeTracker = {
|
||||
@@ -309,6 +330,7 @@ export function buildSessionCoverage(
|
||||
} else {
|
||||
imeTracker = { degraded: false, ...(sessionTotals ? { sessionTotals } : {}) };
|
||||
}
|
||||
if (overwriteNote) imeTracker.note = overwriteNote;
|
||||
|
||||
// ── Collectors ──────────────────────────────────────────────────────────────
|
||||
const collectors: CollectorDegradation[] = [];
|
||||
|
||||
@@ -220,6 +220,10 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session
|
||||
];
|
||||
const imeSkipParts = imeSkipCounters.filter(([, v]) => Number(v) > 0).map(([k, v]) => `${v} ${k}`);
|
||||
const imeSkips = imeSkipParts.length;
|
||||
// Log blocks a concurrent Intune process wrote over after the agent had read them, re-read by
|
||||
// the agent (agents ≥ 2.0.1458). Recovered data — shown apart from "Skipped work" on purpose.
|
||||
const imeOverwriteRewinds = patternHits?.overwriteRewinds ?? imeTracker?.ime_overwrite_rewinds;
|
||||
const imeOverwriteBytes = Number(patternHits?.overwriteBytesReprocessed ?? imeTracker?.ime_overwrite_bytes_reprocessed ?? 0);
|
||||
const apiLatencyMs = session?.avgApiLatencyMs ?? 0;
|
||||
const hasConnectivity = apiLatencyMs > 0 || bandwidthEstimate || metricsSnapshot;
|
||||
|
||||
@@ -676,6 +680,17 @@ export default function DeviceDetailsCard({ events, latestAgentVersion, session
|
||||
? "Matching was cut short on some log lines — pattern coverage may be incomplete for this session. Nothing to fix on your side; use Report Session if the stats look wrong."
|
||||
: undefined}
|
||||
/>
|
||||
{imeOverwriteRewinds !== undefined && (
|
||||
<DetailRow
|
||||
label="Overwritten log blocks recovered"
|
||||
value={Number(imeOverwriteRewinds) > 0
|
||||
? `${Number(imeOverwriteRewinds)}${imeOverwriteBytes > 0 ? ` (${formatBytesCompact(imeOverwriteBytes)} re-read)` : ""}`
|
||||
: "none"}
|
||||
title={Number(imeOverwriteRewinds) > 0
|
||||
? "Intune processes wrote over log lines the agent had already read; the agent re-read them, so script results and exit codes in those blocks are complete. Nothing to fix on your side."
|
||||
: undefined}
|
||||
/>
|
||||
)}
|
||||
{(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) !== undefined && Number(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns) > 0 && (
|
||||
<DetailRow label="Unanchored patterns" value={String(patternHits?.unanchoredPatterns ?? imeTracker?.ime_unanchored_patterns)} />
|
||||
)}
|
||||
|
||||
Reference in New Issue
Block a user