mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 05:00:07 +00:00
fix(agent-v2): persist platform-script dedup markers across restarts (H1, L1, L10)
Delta-review 2026-07-02 findings: - H1: shutdown force-flush emits an agentexecutor_fallback completion, but the emitted-marker set and pending buffer were memory-only. After a restart the tracker parsed IME`s later-written PS-SCRIPT-RESULT line fresh and emitted a duplicate script_completed. Persist both in ImeTrackerStateData (null-safe for old state files); pending scripts continue their grace window after a restart instead of being dropped. - L1: stale-result guard — a PS-SCRIPT-RESULT older than the pending slot`s StartedAtUtc belongs to a previous run of the same policy; drop it instead of merging run 1`s result into run 2`s slot (which also swallowed run 2`s genuine result via the emitted-marker). - L10: script_timeout_suspected one-shot dedup moved from the adapter`s in-memory set to tracker state (TryClaimScriptTimeoutSuspected), so the Warning stays one-shot across stall restarts. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
+154
@@ -0,0 +1,154 @@
|
||||
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>
|
||||
/// H1 (delta review 2026-07-02): the platform-script emission markers and pending buffer must
|
||||
/// survive an agent restart. Field scenario: the shutdown pass force-flushes a fallback
|
||||
/// completion, the agent restarts (stall restarts run up to ~88× per session), IME writes its
|
||||
/// authoritative PS-SCRIPT-RESULT line after the flush — the restarted tracker parses that
|
||||
/// line fresh (it lies beyond the persisted file position) and, without the persisted marker,
|
||||
/// emitted a duplicate script_completed. Also covers the stale-result guard (L1) and the
|
||||
/// restart-safe script_timeout_suspected claim (L10).
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerScriptStatePersistenceTests
|
||||
{
|
||||
private static ImeLogTracker BuildTracker(TempDirectory tmp, out List<ScriptExecutionState> emitted)
|
||||
{
|
||||
var captured = new List<ScriptExecutionState>();
|
||||
emitted = captured;
|
||||
var tracker = new ImeLogTracker(
|
||||
logFolder: tmp.Path,
|
||||
patterns: new List<ImeLogPattern>(),
|
||||
logger: new AgentLogger(tmp.Path, AgentLogLevel.Info),
|
||||
stateDirectory: tmp.Path);
|
||||
tracker.OnScriptCompleted = s => captured.Add(s);
|
||||
return tracker;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Fallback_marker_survives_restart_and_dedupes_late_ime_result()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var observedAt = new DateTime(2026, 7, 3, 9, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
// 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);
|
||||
Assert.Single(emitted1);
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
// Restart: IME's PS-SCRIPT-RESULT line for the SAME execution arrives now.
|
||||
var tracker2 = BuildTracker(tmp, out var emitted2);
|
||||
tracker2.LoadStateForTest();
|
||||
tracker2.CompletePlatformScriptFromImeResultForTesting("policyA", "Success");
|
||||
|
||||
Assert.Empty(emitted2); // was a duplicate before the fix
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Pending_script_survives_restart_and_flushes_after_grace()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var observedAt = new DateTime(2026, 7, 3, 9, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
// Exit code observed but neither flushed nor resolved before the agent died.
|
||||
var tracker1 = BuildTracker(tmp, out var emitted1);
|
||||
tracker1.SeedPendingPlatformScriptForTesting("policyB", exitCode: 3, exitObservedAtUtc: observedAt);
|
||||
tracker1.SaveStateForTest();
|
||||
Assert.Empty(emitted1);
|
||||
|
||||
// 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));
|
||||
|
||||
var script = Assert.Single(emitted2);
|
||||
Assert.Equal("policyB", script.PolicyId);
|
||||
Assert.Equal("Failed", script.Result);
|
||||
Assert.Equal("agentexecutor_fallback", script.ResultSource);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Fresh_start_after_restart_still_clears_restored_marker()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var observedAt = new DateTime(2026, 7, 3, 9, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
var tracker1 = BuildTracker(tmp, out _);
|
||||
tracker1.SeedPendingPlatformScriptForTesting("policyC", exitCode: 0, exitObservedAtUtc: observedAt);
|
||||
tracker1.FlushStalePlatformScriptResults(observedAt.AddSeconds(1), force: true);
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
// Restart, then a genuine RE-RUN of the same policy (fresh start clears the marker).
|
||||
var tracker2 = BuildTracker(tmp, out var emitted2);
|
||||
tracker2.LoadStateForTest();
|
||||
tracker2.SeedPendingPlatformScriptForTesting("policyC", exitCode: 0, exitObservedAtUtc: observedAt.AddMinutes(10));
|
||||
tracker2.CompletePlatformScriptFromImeResultForTesting("policyC", "Success", observedAt.AddMinutes(11));
|
||||
|
||||
var script = Assert.Single(emitted2);
|
||||
Assert.Equal("ime_policy_result", script.ResultSource);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Old_state_file_without_script_fields_loads_clean()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
|
||||
// Persist a state file from "before the fix" (fields null).
|
||||
var persistence = new ImeTrackerStatePersistence(tmp.Path, new AgentLogger(tmp.Path, AgentLogLevel.Info));
|
||||
persistence.Save(new ImeTrackerStateData { CurrentPhaseOrder = 2 });
|
||||
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
tracker.LoadStateForTest(); // must not throw
|
||||
|
||||
// Degrades to pre-fix behavior: no markers restored, normal emission works.
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyD", "Success");
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Stale_result_older_than_current_run_start_is_dropped()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var run2Start = new DateTime(2026, 7, 3, 10, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
// Run 2 is live (fresh slot with its start stamped)…
|
||||
tracker.SeedPendingPlatformScriptForTesting("policyE", exitCode: null, exitObservedAtUtc: null, startedAtUtc: run2Start);
|
||||
|
||||
// …when run 1's late PS-SCRIPT-RESULT (older than run 2's start) finally arrives.
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyE", "Failed", run2Start.AddMinutes(-5));
|
||||
Assert.Empty(emitted);
|
||||
|
||||
// Run 2's own result (newer than its start) still emits normally.
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyE", "Success", run2Start.AddMinutes(2));
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal(run2Start, script.StartedAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Script_timeout_claim_is_one_shot_and_survives_restart()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
|
||||
var tracker1 = BuildTracker(tmp, out _);
|
||||
Assert.True(tracker1.TryClaimScriptTimeoutSuspected("policyF"));
|
||||
Assert.False(tracker1.TryClaimScriptTimeoutSuspected("policyF")); // in-lifetime dedup
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
var tracker2 = BuildTracker(tmp, out _);
|
||||
tracker2.LoadStateForTest();
|
||||
Assert.False(tracker2.TryClaimScriptTimeoutSuspected("policyF")); // cross-restart dedup
|
||||
Assert.True(tracker2.TryClaimScriptTimeoutSuspected("policyG")); // other policies unaffected
|
||||
}
|
||||
}
|
||||
}
|
||||
+44
-5
@@ -370,7 +370,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
|
||||
// Merge with pending AgentExecutor data if available
|
||||
if (!_pendingPlatformScripts.TryGetValue(id, out var script))
|
||||
if (_pendingPlatformScripts.TryGetValue(id, 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
|
||||
&& LastMatchedLogTimestamp.HasValue
|
||||
&& LastMatchedLogTimestamp.Value < script.StartedAtUtc.Value)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {id} result predates the current run's start — stale result from a previous run, skipping");
|
||||
return;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
script = new ScriptExecutionState
|
||||
{
|
||||
@@ -387,6 +404,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
EmitScriptEvent(script);
|
||||
_platformScriptResultEmitted.Add(id);
|
||||
_pendingPlatformScripts.Remove(id);
|
||||
_stateDirty = true;
|
||||
if (string.Equals(_lastPlatformScriptPolicyId, id, StringComparison.OrdinalIgnoreCase))
|
||||
_lastPlatformScriptPolicyId = null;
|
||||
}
|
||||
@@ -464,6 +482,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
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);
|
||||
@@ -475,7 +497,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)
|
||||
internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null, DateTime? startedAtUtc = 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.
|
||||
@@ -487,13 +509,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
ExitCode = exitCode,
|
||||
ExitObservedAtUtc = exitObservedAtUtc,
|
||||
Stdout = stdout,
|
||||
StartedAtUtc = startedAtUtc,
|
||||
};
|
||||
_lastPlatformScriptPolicyId = policyId;
|
||||
}
|
||||
|
||||
/// <summary>Test seam: simulate the authoritative IME PS-SCRIPT-RESULT path for a platform
|
||||
/// script (same code as <see cref="HandleScriptCompleted"/> minus regex extraction).</summary>
|
||||
internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result)
|
||||
/// 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>
|
||||
internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result, DateTime? resultLineTimestampUtc = null)
|
||||
{
|
||||
if (string.IsNullOrEmpty(policyId)) return;
|
||||
|
||||
@@ -505,8 +530,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return;
|
||||
}
|
||||
|
||||
if (!_pendingPlatformScripts.TryGetValue(policyId, out var script))
|
||||
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";
|
||||
@@ -515,6 +553,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_pendingPlatformScripts.Remove(policyId);
|
||||
if (string.Equals(_lastPlatformScriptPolicyId, policyId, StringComparison.OrdinalIgnoreCase))
|
||||
_lastPlatformScriptPolicyId = null;
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -134,6 +134,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private readonly Dictionary<string, DateTime> _healthScriptStartTimes =
|
||||
new Dictionary<string, DateTime>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// Restart-safe dedup for the adapter's one-shot script_timeout_suspected Warning.
|
||||
// Owned by the tracker (not the adapter) solely so it rides the persisted state file —
|
||||
// an in-memory set re-emits the Warning after every stall restart once the position
|
||||
// bookmark is lost and the failing script's log tail is reprocessed.
|
||||
private readonly HashSet<string> _scriptTimeoutSuspectedPosted =
|
||||
new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Claims the one-shot <c>script_timeout_suspected</c> emission for a policy. Returns
|
||||
/// false when a prior claim exists — including one restored from persisted state after
|
||||
/// an agent restart, which is the whole point of routing the adapter's dedup through
|
||||
/// the tracker.
|
||||
/// </summary>
|
||||
public bool TryClaimScriptTimeoutSuspected(string policyId)
|
||||
{
|
||||
if (string.IsNullOrEmpty(policyId)) return false;
|
||||
if (!_scriptTimeoutSuspectedPosted.Add(policyId)) return false;
|
||||
_stateDirty = true;
|
||||
return true;
|
||||
}
|
||||
|
||||
private const int MaxScriptOutputLength = 2048;
|
||||
private const int MaxMultiLineBufferLines = 100;
|
||||
|
||||
@@ -631,6 +652,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
}
|
||||
|
||||
// H1 (delta review 2026-07-02): restore platform-script emission markers + pending
|
||||
// buffer. Without these, the shutdown force-flush emits a fallback completion, the
|
||||
// restarted tracker resumes past the persisted position, and IME's later-written
|
||||
// PS-SCRIPT-RESULT line for the same execution emits a SECOND script_completed
|
||||
// (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)
|
||||
{
|
||||
foreach (var id in state.PlatformScriptResultEmitted)
|
||||
_platformScriptResultEmitted.Add(id);
|
||||
}
|
||||
|
||||
_pendingPlatformScripts.Clear();
|
||||
if (state.PendingPlatformScripts != null)
|
||||
{
|
||||
foreach (var pending in state.PendingPlatformScripts)
|
||||
{
|
||||
if (!string.IsNullOrEmpty(pending?.PolicyId))
|
||||
_pendingPlatformScripts[pending.PolicyId] = pending;
|
||||
}
|
||||
}
|
||||
|
||||
_scriptTimeoutSuspectedPosted.Clear();
|
||||
if (state.ScriptTimeoutSuspectedPosted != null)
|
||||
{
|
||||
foreach (var id in state.ScriptTimeoutSuspectedPosted)
|
||||
_scriptTimeoutSuspectedPosted.Add(id);
|
||||
}
|
||||
|
||||
// Re-activate patterns based on restored phase state
|
||||
ActivatePatterns(_logPhaseIsCurrentPhase, force: true);
|
||||
|
||||
@@ -669,6 +720,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
kv => kv.Key,
|
||||
kv => kv.Value.Select(ToPackageStateData).ToList(),
|
||||
StringComparer.Ordinal),
|
||||
|
||||
// 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(),
|
||||
PendingPlatformScripts = _pendingPlatformScripts.Values.ToList(),
|
||||
ScriptTimeoutSuspectedPosted = _scriptTimeoutSuspectedPosted.ToList(),
|
||||
};
|
||||
|
||||
// Store file positions by filename only (log folder is known)
|
||||
|
||||
+13
@@ -125,6 +125,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// added — LoadState handles that as "no snapshots" and the in-memory dict stays empty
|
||||
// (degrades gracefully back to the live _packageStates view).
|
||||
public Dictionary<string, List<PackageStateData>> PhasePackageSnapshots { get; set; }
|
||||
|
||||
// H1 (delta review 2026-07-02): platform-script completion dedup must survive agent
|
||||
// restarts. The shutdown pass force-flushes fallback completions from AgentExecutor exit
|
||||
// codes; IME's authoritative PS-SCRIPT-RESULT line is often written AFTER that flush and
|
||||
// lies beyond the persisted file position, so the restarted tracker parses it fresh —
|
||||
// without the persisted marker set it would emit a duplicate script_completed. The
|
||||
// pending buffer rides along so a script whose exit code was seen but not yet flushed
|
||||
// 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.
|
||||
public List<string> PlatformScriptResultEmitted { get; set; }
|
||||
public List<ScriptExecutionState> PendingPlatformScripts { get; set; }
|
||||
public List<string> ScriptTimeoutSuspectedPosted { get; set; }
|
||||
}
|
||||
|
||||
public class PackageStateData
|
||||
|
||||
@@ -91,9 +91,6 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// bootstrap marker line. Lets MCP report "which device runs which bootstrap version".
|
||||
private bool _bootstrapDetectedPosted;
|
||||
|
||||
// Platform scripts already flagged with script_timeout_suspected (dedup per policyId).
|
||||
private readonly HashSet<string> _scriptTimeoutSuspectedPosted = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// A platform script whose observed run duration reaches this is treated as having hit the
|
||||
// IME script-execution timeout (default ~30 min). 25 min leaves headroom below 30 so clock
|
||||
// jitter / the agent's late replay window can't miss it, while staying well above any
|
||||
@@ -911,7 +908,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
var duration = completionUtc - script.StartedAtUtc.Value;
|
||||
if (duration < ScriptTimeoutSuspectedThreshold) return;
|
||||
|
||||
if (!_scriptTimeoutSuspectedPosted.Add(script.PolicyId)) return; // dedup per policyId
|
||||
if (!_tracker.TryClaimScriptTimeoutSuspected(script.PolicyId)) return; // restart-safe dedup per policyId (persisted tracker state)
|
||||
|
||||
var culture = System.Globalization.CultureInfo.InvariantCulture;
|
||||
var shortId = script.PolicyId.Length >= 8 ? script.PolicyId.Substring(0, 8) : script.PolicyId;
|
||||
|
||||
Reference in New Issue
Block a user