From c6ee7808f1b6f7e6b065e82519561beff07fee08 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Wed, 19 Aug 2026 17:37:40 +0200 Subject: [PATCH] fix(agent): scope the ESP-exit replay to restart recovery only MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Follow-up to the review hardening: the replay ran on EVERY agent start with a 5-minute window, first run included. On a first run there is no gap to recover — no earlier agent process existed — and a 62407 already sitting in the Shell-Core log belongs to a phase transition this agent was never meant to observe. Replaying it pushes an EspExiting into the reducer that the pre-fix agent never saw, i.e. a happy-path behaviour change for no gain. ResolveEspExitBackfillLookbackMinutes now keys the window to the previous exit type: first_run (or unknown) disables the replay entirely, clean/hard_kill/ exception_crash keep the 5-minute default because the process is back within seconds, and reboot_kill widens to "since LastBootUtc" because that gap spans the forced restart until the post-reboot logon. The result is still clamped to BackfillLookbackMaxMinutes, so policy and backstop together cannot build an unbounded event-log query. With this the happy path is byte-identical to pre-fix behaviour: on a first run nothing replays, no edge is remembered, and the deferred re-check returns on a volatile bool read. No other backfill is affected — the Hello, MDM-reboot, Windows-Update and ModernDeployment trackers each own a private backfill invoked from their own Start(), none of which this change touches. 13 policy tests including clock skew across the reboot, a missing boot timestamp and the clamp backstop. Agent V2.Core 2353, DecisionCore 533, Backend 4287. Co-Authored-By: Claude Opus 5 (1M context) --- docs/agent/post-reboot-completion-recovery.md | 21 +++- .../EspExitBackfillLookbackPolicyTests.cs | 95 +++++++++++++++++++ .../Orchestration/DefaultComponentFactory.cs | 86 ++++++++++++----- .../Orchestration/Hosts/EspAndHelloHost.cs | 15 ++- .../Runtime/AgentRuntimeHost.cs | 3 +- 5 files changed, 188 insertions(+), 32 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EspExitBackfillLookbackPolicyTests.cs diff --git a/docs/agent/post-reboot-completion-recovery.md b/docs/agent/post-reboot-completion-recovery.md index 6ea58fc7..32f7b37a 100644 --- a/docs/agent/post-reboot-completion-recovery.md +++ b/docs/agent/post-reboot-completion-recovery.md @@ -50,11 +50,22 @@ between the two is observed twice, which the design already tolerates (Shell-Cor picks the genuine post-AccountSetup one). The reverse order could drop a record, which costs the session its completion. -The fixed 5-minute lookback cannot span a reboot, so the window is now sized to the -downtime: on `previousExit=reboot_kill` the factory passes `PreviousExitSummary.LastBootUtc` -and the lookback becomes "everything since the boot that killed us", clamped to -`ShellCoreTracker.BackfillLookbackMaxMinutes` (360 — the agent's max lifetime). Every other -exit type keeps the 5-minute default. +**Scope: restart recovery only.** The replay re-reads observations the agent could not make +because no agent process was running, so it is keyed to `PreviousExitSummary.ExitType` +(`DefaultComponentFactory.ResolveEspExitBackfillLookbackMinutes`): + +| Previous exit | Lookback | Why | +|---|---|---| +| `first_run` (or unknown) | **0 — replay off** | No earlier process, no gap. A 62407 already in the log belongs to a transition this agent was never meant to observe; replaying it would push an `EspExiting` into the reducer that the pre-fix agent never saw. The happy path is therefore untouched. | +| `clean` / `hard_kill` / `exception_crash` | 5 min (default) | The process is back within seconds. | +| `reboot_kill` | since `LastBootUtc` (+1 min slack) | The gap spans the forced restart until the post-reboot logon relaunches the agent — the 5-minute default cannot reach it. | + +The result is clamped to `ShellCoreTracker.BackfillLookbackMaxMinutes` (360 — the agent's max +lifetime), so policy and backstop together can never build an unbounded event-log query. + +This is a *new* caller for existing code, not a change to any other backfill. The +Hello/MDM-reboot/Windows-Update/ModernDeployment trackers each own a private backfill called +from their own `Start()`; none of them is touched. **Newest exit wins.** Widening the window changes what the replay contains. The reader walks oldest-first and the exit branch is fire-once, so a naive record-by-record replay hands over diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EspExitBackfillLookbackPolicyTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EspExitBackfillLookbackPolicyTests.cs new file mode 100644 index 00000000..878cc5ec --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EspExitBackfillLookbackPolicyTests.cs @@ -0,0 +1,95 @@ +#nullable enable +using System; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration +{ + /// + /// The Shell-Core ESP-exit replay is RESTART RECOVERY: it re-reads observations the agent could + /// not make because no agent process was running. Two invariants matter and both are pinned + /// here, because getting either wrong is invisible until a real enrollment pays for it: + /// + /// On a first run there is no gap to recover — the replay must stay OFF so the happy + /// path behaves exactly as it did before the recovery existed. Replaying a 62407 the + /// pre-fix agent never saw would push an extra EspExiting into the reducer. + /// After a reboot_kill the gap spans the whole downtime, which the 5-minute default + /// cannot cover. + /// + /// + public sealed class EspExitBackfillLookbackPolicyTests + { + private static readonly DateTime Now = new DateTime(2026, 8, 19, 8, 43, 16, DateTimeKind.Utc); + + private static int Resolve(string? exitType, DateTime? bootUtc = null) + => DefaultComponentFactory.ResolveEspExitBackfillLookbackMinutes(exitType, bootUtc, Now); + + [Theory] + [InlineData("first_run")] + [InlineData("FIRST_RUN")] + [InlineData("")] + [InlineData(null)] + public void No_previous_run_means_no_replay(string? exitType) + { + Assert.Equal(0, Resolve(exitType)); + } + + [Fact] + public void First_run_stays_off_even_with_a_boot_timestamp() + { + // Defence in depth: LastBootUtc is only populated for hard_kill/reboot_kill, but the + // exit type — not the presence of a timestamp — is what decides. + Assert.Equal(0, Resolve("first_run", Now.AddHours(-3))); + } + + [Theory] + [InlineData("clean")] + [InlineData("hard_kill")] + [InlineData("exception_crash")] + public void An_in_place_restart_keeps_the_short_default(string exitType) + { + // The process comes back within seconds, so five minutes covers the gap comfortably. + Assert.Equal(ShellCoreTracker.BackfillLookbackMinutes, Resolve(exitType)); + } + + [Fact] + public void Reboot_kill_widens_the_window_to_the_downtime() + { + // Boot 40 min ago: everything since that boot, plus a minute of slack for the + // granularity of the event-log timestamps. + Assert.Equal(41, Resolve("reboot_kill", Now.AddMinutes(-40))); + } + + [Fact] + public void Reboot_kill_without_a_boot_timestamp_falls_back_to_the_default() + { + // GetLastBootTimeFromEventLog returns null on a reduced-privilege run. + Assert.Equal(ShellCoreTracker.BackfillLookbackMinutes, Resolve("reboot_kill")); + } + + [Fact] + public void A_downtime_shorter_than_the_default_does_not_shrink_the_window() + { + Assert.Equal(ShellCoreTracker.BackfillLookbackMinutes, Resolve("reboot_kill", Now.AddMinutes(-2))); + } + + [Fact] + public void A_boot_timestamp_in_the_future_falls_back_to_the_default() + { + // Clock skew across the reboot must not produce a negative window. + Assert.Equal(ShellCoreTracker.BackfillLookbackMinutes, Resolve("reboot_kill", Now.AddMinutes(5))); + } + + [Fact] + public void A_very_long_downtime_is_clamped_by_the_tracker() + { + // The policy may propose more than the cap; ClampLookbackMinutes is the backstop, so + // the two together can never produce an unbounded event-log query. + var proposed = Resolve("reboot_kill", Now.AddHours(-20)); + Assert.True(proposed > ShellCoreTracker.BackfillLookbackMaxMinutes); + Assert.Equal(ShellCoreTracker.BackfillLookbackMaxMinutes, + ShellCoreTracker.ClampLookbackMinutes(proposed)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index 243ca511..b243237c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -74,11 +74,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly string _stateDirectory; private readonly Persistence.StartupEventGate? _startupEventGate; + /// + /// How the previous agent run in this enrollment ended (Program.PreviousExitSummary.ExitType: + /// first_run | clean | exception_crash | hard_kill | + /// reboot_kill). Decides whether the Shell-Core ESP-exit replay runs at all — see + /// . + /// + private readonly string? _previousExitType; + /// /// OS boot time when the previous agent run was killed by a reboot (reboot_kill), - /// otherwise null. Widens the Shell-Core ESP-exit backfill so a completion signal written - /// while the agent was down is still recovered — see the backfill block in - /// . + /// otherwise null. Sizes the Shell-Core ESP-exit backfill so a completion signal written + /// while the agent was down is still recovered. /// private readonly DateTime? _previousBootUtc; @@ -89,7 +96,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration string agentVersion, string stateDirectory, Persistence.StartupEventGate? startupEventGate = null, - DateTime? previousBootUtc = null) + DateTime? previousBootUtc = null, + string? previousExitType = null) { _agentConfig = agentConfig ?? throw new ArgumentNullException(nameof(agentConfig)); _remoteConfig = remoteConfig ?? throw new ArgumentNullException(nameof(remoteConfig)); @@ -98,6 +106,47 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _stateDirectory = stateDirectory ?? throw new ArgumentNullException(nameof(stateDirectory)); _startupEventGate = startupEventGate; _previousBootUtc = previousBootUtc; + _previousExitType = previousExitType; + } + + /// + /// Lookback in minutes for the Shell-Core ESP-exit replay; 0 means "do not replay". + /// + /// The replay is a RESTART-RECOVERY mechanism: it re-reads observations the agent could not + /// make because no agent process was running. That only ever applies when a previous run + /// existed. On first_run — the happy path — it stays off, so the agent behaves + /// exactly as it did before the recovery was added. + /// + /// + /// After a reboot_kill the gap spans the whole downtime (forced restart until the + /// post-reboot logon relaunches the agent), which the 5-minute default cannot cover; the + /// window becomes "everything since the boot that killed us". Every other restart + /// (clean / hard_kill / exception_crash) keeps that default, since the process comes back + /// within seconds. + /// + /// + internal static int ResolveEspExitBackfillLookbackMinutes( + string? previousExitType, DateTime? previousBootUtc, DateTime utcNow) + { + if (string.IsNullOrEmpty(previousExitType) + || string.Equals(previousExitType, "first_run", StringComparison.OrdinalIgnoreCase)) + { + return 0; + } + + if (string.Equals(previousExitType, "reboot_kill", StringComparison.OrdinalIgnoreCase) + && previousBootUtc.HasValue) + { + var sinceBoot = utcNow - previousBootUtc.Value; + if (sinceBoot > TimeSpan.Zero) + { + var sinceBootMinutes = (int)Math.Ceiling(sinceBoot.TotalMinutes) + 1; + if (sinceBootMinutes > ShellCoreTracker.BackfillLookbackMinutes) + return sinceBootMinutes; + } + } + + return ShellCoreTracker.BackfillLookbackMinutes; } public CollectorSurfaces CreateCollectorHosts( @@ -160,27 +209,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // on esp_exiting events long after Start. ImeLogHost? imeLogHostRef = null; - // sits-d Cloud-PC fix (2026-08-19): after a mid-ESP reboot the agent is dead from the - // forced restart until the post-reboot logon re-launches it. The Shell-Core ESP exit - // that ends AccountSetup can land anywhere in that window, and the 5-minute default - // backfill is far too narrow to reach it. Widen to "everything since the boot that - // killed us" — the exit we care about is by definition after that boot. Clamped to - // ShellCoreTracker.BackfillLookbackMaxMinutes inside the tracker. - var espExitBackfillLookbackMinutes = ShellCoreTracker.BackfillLookbackMinutes; - if (_previousBootUtc.HasValue) + // sits-d Cloud-PC fix (2026-08-19), narrowed after review: the Shell-Core ESP-exit + // replay is restart recovery, so it stays OFF on a first run and the happy path keeps + // its pre-fix behaviour exactly. See ResolveEspExitBackfillLookbackMinutes. + var espExitBackfillLookbackMinutes = ResolveEspExitBackfillLookbackMinutes( + _previousExitType, _previousBootUtc, DateTime.UtcNow); + if (espExitBackfillLookbackMinutes > 0) { - var sinceBoot = DateTime.UtcNow - _previousBootUtc.Value; - if (sinceBoot > TimeSpan.Zero) - { - var sinceBootMinutes = (int)Math.Ceiling(sinceBoot.TotalMinutes) + 1; - if (sinceBootMinutes > espExitBackfillLookbackMinutes) - { - espExitBackfillLookbackMinutes = sinceBootMinutes; - logger.Info( - "DefaultComponentFactory: previous run died to a reboot — widening the Shell-Core " + - $"ESP-exit backfill to {espExitBackfillLookbackMinutes} min (since boot {_previousBootUtc.Value:o})"); - } - } + logger.Info( + $"DefaultComponentFactory: previous run ended as '{_previousExitType}' — Shell-Core " + + $"ESP-exit replay enabled with a {espExitBackfillLookbackMinutes} min lookback"); } var espAndHelloHost = new EspAndHelloHost( diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs index 0e31c330..43b54bfe 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs @@ -104,7 +104,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration } /// - /// Starts the tracker and then replays recent Shell-Core ESP-exit / Hello-wizard records. + /// Starts the tracker and then — only when this run FOLLOWS a previous one — replays + /// recent Shell-Core ESP-exit / Hello-wizard records. /// /// The backfill has existed since session 772fe502 but was never wired to a caller, so /// the Shell-Core watcher only ever saw events written AFTER . Any @@ -123,11 +124,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration /// reverse order could drop a record entirely, which costs the session its completion — /// a duplicate costs nothing. /// + /// + /// A lookback of zero disables the replay entirely. That is the FIRST run of an enrollment: + /// there is no gap to recover because no earlier agent process existed, and any 62407 + /// already in the log belongs to a phase transition that happened before this agent was + /// ever meant to observe anything. Replaying it would push an EspExiting into the + /// reducer that the pre-fix agent never saw — a happy-path behaviour change for no gain. + /// The caller (DefaultComponentFactory) owns that policy. + /// /// public void Start() { _tracker.Start(); - _tracker.BackfillRecentEspExitEvents(_espExitBackfillLookbackMinutes); + + if (_espExitBackfillLookbackMinutes > 0) + _tracker.BackfillRecentEspExitEvents(_espExitBackfillLookbackMinutes); } public void Stop() => _tracker.Stop(); diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs b/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs index 2e3a1742..ebbc824a 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs @@ -94,7 +94,8 @@ namespace AutopilotMonitor.Agent.V2.Runtime agentVersion: agentVersion, stateDirectory: stateSubdir, startupEventGate: startupEventGate, - previousBootUtc: previousBootUtc); + previousBootUtc: previousBootUtc, + previousExitType: previousExit?.ExitType); var whiteGloveSealingPatternIds = (System.Collections.Generic.IReadOnlyCollection)remoteConfig.WhiteGloveSealingPatternIds ?? Array.Empty();