From 1eb13e30b2a41bb93793f50151eae1f6022ce2c3 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 3 Jul 2026 10:33:47 +0200 Subject: [PATCH] fix(agent-v2): persist platform-script dedup markers across restarts (H1, L1, L10) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- ...meLogTrackerScriptStatePersistenceTests.cs | 154 ++++++++++++++++++ .../Enrollment/Ime/ImeLogTracker.Handlers.cs | 49 +++++- .../Enrollment/Ime/ImeLogTracker.cs | 57 +++++++ .../Ime/ImeTrackerStatePersistence.cs | 13 ++ .../SignalAdapters/ImeLogTrackerAdapter.cs | 5 +- 5 files changed, 269 insertions(+), 9 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs new file mode 100644 index 00000000..33fa5221 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs @@ -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 +{ + /// + /// 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). + /// + public sealed class ImeLogTrackerScriptStatePersistenceTests + { + private static ImeLogTracker BuildTracker(TempDirectory tmp, out List emitted) + { + var captured = new List(); + emitted = captured; + var tracker = new ImeLogTracker( + logFolder: tmp.Path, + patterns: new List(), + logger: new AgentLogger(tmp.Path, AgentLogLevel.Info), + 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 + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index e8a3b10f..5c601c79 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -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 /// Test seam: inject a pending platform script as if AgentExecutor.log had reported /// its start + exit code, without an IME PS-SCRIPT-RESULT line. - internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null) + 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; } /// Test seam: simulate the authoritative IME PS-SCRIPT-RESULT path for a platform - /// script (same code as minus regex extraction). - internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result) + /// script (same code as minus regex extraction). + /// stands in for the CMTrace timestamp of the + /// PS-SCRIPT-RESULT line (production reads it via ). + 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; } /// diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs index 409c4c67..fcdabc23 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs @@ -134,6 +134,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private readonly Dictionary _healthScriptStartTimes = new Dictionary(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 _scriptTimeoutSuspectedPosted = + new HashSet(StringComparer.OrdinalIgnoreCase); + + /// + /// Claims the one-shot script_timeout_suspected 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. + /// + 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) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs index d2939019..70c6647d 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs @@ -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> 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 PlatformScriptResultEmitted { get; set; } + public List PendingPlatformScripts { get; set; } + public List ScriptTimeoutSuspectedPosted { get; set; } } public class PackageStateData diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index 426d546c..e4fcf5e8 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -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 _scriptTimeoutSuspectedPosted = new HashSet(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;