From d3abbacd9044d2f5699f96a4876c585e47502fd7 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 11 Jun 2026 12:26:36 +0200 Subject: [PATCH] fix(agent-v2): complete Classic sessions when a skipped user-ESP app starves the AccountSetup gate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Session caa6cf50: a policy-skipped user-ESP app leaves the ESP registry's Apps subcategory permanently inProgress, so Windows never writes AccountSetupCategory.Status.categorySucceeded before tearing down the ESP page. Both registry-driven AccountSetupProvisioningComplete paths (normal + all-subcategories fallback) starve, ShouldTransitionToAwaitingHello never opens, and the session stalls after 60 min despite a successful enrollment (esp_exiting + desktop_arrived + helloPolicy=false all recorded). Fix, in three parts: - ImeLogTracker.AreUserEspAppsSettled(): conservative probe — true only in AccountSetup phase with >=1 required app, all required apps terminal (Installed/Skipped/Postponed) and zero errors. Exposed via ImeLogHost. - EspAndHelloTracker: on every Shell-Core exit forward, fire-once synthesis of AccountSetupProvisioningComplete when the probe reports settled, plus an esp_provisioning_status observability event (fallbackReason=esp_exited_user_apps_settled_category_unresolved). Wired through a new optional userEspAppsSettledProbe ctor param; DefaultComponentFactory connects it to ImeLogHost via closure. - HandleAccountSetupProvisioningCompleteV1: deferred-completion parity. When the strong gate arrives last (Win11 ordering: explorer.exe runs under the User-ESP page, so Desktop arrives before the final exit) and Hello is resolved or policy-disabled, complete through Finalizing with HelloOutcome="Skipped" instead of parking in AwaitingHello until HelloSafety stamps a misleading "Timeout" 300 s later. Sessions with failed or in-flight user apps keep the existing conservative stall behaviour. DecisionCore 366/366, V2.Core 1321/1321 green. Co-Authored-By: Claude Fable 5 --- ...lloTrackerUserAppsSettledSynthesisTests.cs | 163 ++++++++++++ .../ImeLogTrackerUserEspAppsSettledTests.cs | 142 +++++++++++ .../Enrollment/Ime/ImeLogTracker.cs | 61 +++++ .../SystemSignals/EspAndHelloTracker.cs | 94 ++++++- .../Orchestration/DefaultComponentFactory.cs | 10 +- .../Orchestration/Hosts/EspAndHelloHost.cs | 6 +- .../Orchestration/Hosts/ImeLogHost.cs | 9 + ...icGateStarvationDeferredCompletionTests.cs | 236 ++++++++++++++++++ .../Engine/DecisionEngine.Shared.cs | 39 +++ 9 files changed, 754 insertions(+), 6 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerUserEspAppsSettledTests.cs create mode 100644 src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassicGateStarvationDeferredCompletionTests.cs diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs new file mode 100644 index 00000000..debc3a89 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs @@ -0,0 +1,163 @@ +using System; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Agent.V2.Core.SignalAdapters; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring +{ + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11) — coordinator-side synthesis tests. + /// When a Shell-Core normal exit (62407) is forwarded while the injected IME probe reports + /// "all tracked user-ESP apps terminal (0 failed)", must + /// raise AccountSetupProvisioningComplete as alternative gate evidence — because a + /// policy-skipped user-ESP app leaves the registry's Apps subcategory permanently + /// inProgress and both registry-driven paths (normal + fallback) starve. + /// + public sealed class EspAndHelloTrackerUserAppsSettledSynthesisTests + { + private static readonly DateTime Fixed = new DateTime(2026, 6, 11, 8, 0, 2, DateTimeKind.Utc); + + private sealed class Fixture : IDisposable + { + public TempDirectory Tmp { get; } = new TempDirectory(); + public AgentLogger Logger { get; } + public FakeSignalIngressSink Ingress { get; } = new FakeSignalIngressSink(); + public FakeSignalIngressSink TrackerPostSink { get; } = new FakeSignalIngressSink(); + public VirtualClock Clock { get; } = new VirtualClock(Fixed); + + public Fixture() { Logger = new AgentLogger(Tmp.Path, AgentLogLevel.Debug); } + + public EspAndHelloTracker BuildCoordinator(Func settledProbe) + { + return new EspAndHelloTracker( + sessionId: "S1", + tenantId: "T1", + post: new InformationalEventPost(TrackerPostSink, Clock), + logger: Logger, + skipConfigProbe: () => ((bool?)false, (bool?)false), + accountSetupActivityProbe: () => true, + userEspAppsSettledProbe: settledProbe); + } + + public void Dispose() { Tmp.Dispose(); } + } + + [Fact] + public void EspExited_withSettledUserApps_raises_AccountSetupProvisioningComplete_after_EspExiting() + { + using var f = new Fixture(); + using var coordinator = f.BuildCoordinator(() => true); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + + // Signal order matters: EspExiting first (records EspFinalExitUtc), then the + // synthesized gate signal (deferred-promote path reads the recorded fact). + Assert.Equal(2, f.Ingress.Posted.Count); + Assert.Equal(DecisionSignalKind.EspExiting, f.Ingress.Posted[0].Kind); + Assert.Equal(DecisionSignalKind.AccountSetupProvisioningComplete, f.Ingress.Posted[1].Kind); + Assert.True(coordinator.UserAppsSettledSynthesisFiredForTest); + + // Observability: the coordinator emits an esp_provisioning_status informational + // event so session-debug can see WHY the gate opened without registry confirmation. + var info = Assert.Single(f.TrackerPostSink.Posted); + Assert.Equal(DecisionSignalKind.InformationalEvent, info.Kind); + Assert.Equal("esp_provisioning_status", info.Payload![SignalPayloadKeys.EventType]); + // EnrollmentEvent.Data flows through the typed sidecar (plan §1.3), not the string payload. + var data = Assert.IsAssignableFrom>(info.TypedPayload); + Assert.Equal("esp_exited_user_apps_settled_category_unresolved", data["fallbackReason"]); + } + + [Fact] + public void EspExited_withUnsettledUserApps_forwards_EspExiting_only() + { + using var f = new Fixture(); + using var coordinator = f.BuildCoordinator(() => false); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + + var posted = Assert.Single(f.Ingress.Posted); + Assert.Equal(DecisionSignalKind.EspExiting, posted.Kind); + Assert.False(coordinator.UserAppsSettledSynthesisFiredForTest); + Assert.Empty(f.TrackerPostSink.Posted); + } + + [Fact] + public void Synthesis_fires_once_across_multiple_exits() + { + using var f = new Fixture(); + using var coordinator = f.BuildCoordinator(() => true); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + coordinator.TriggerEspExitedForTest(Fixed.AddSeconds(30)); + + // Two EspExiting forwards (no dedup by design), exactly one synthesized gate signal. + Assert.Equal(2, f.Ingress.Posted.Count(p => p.Kind == DecisionSignalKind.EspExiting)); + Assert.Equal(1, f.Ingress.Posted.Count(p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete)); + Assert.Single(f.TrackerPostSink.Posted); + } + + [Fact] + public void Synthesis_becomes_eligible_on_a_later_exit_when_apps_settle_in_between() + { + // Exit #1 fires while user apps are still in flight (probe false) — no synthesis. + // Apps settle, exit #2 fires — synthesis must trigger on the later exit. + using var f = new Fixture(); + var settled = false; + using var coordinator = f.BuildCoordinator(() => settled); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + Assert.DoesNotContain(f.Ingress.Posted, p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete); + + settled = true; + coordinator.TriggerEspExitedForTest(Fixed.AddMinutes(10)); + + Assert.Equal(1, f.Ingress.Posted.Count(p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete)); + } + + [Fact] + public void ThrowingProbe_is_swallowed_and_EspExiting_still_forwards() + { + using var f = new Fixture(); + using var coordinator = f.BuildCoordinator(() => throw new InvalidOperationException("probe boom")); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + + var posted = Assert.Single(f.Ingress.Posted); + Assert.Equal(DecisionSignalKind.EspExiting, posted.Kind); + Assert.False(coordinator.UserAppsSettledSynthesisFiredForTest); + } + + [Fact] + public void DefaultProbe_never_synthesizes() + { + // Single-tracker wiring scenarios construct the coordinator without the probe — + // the default must preserve prior behaviour (no synthesis, ever). + using var f = new Fixture(); + using var coordinator = new EspAndHelloTracker( + sessionId: "S1", + tenantId: "T1", + post: new InformationalEventPost(f.TrackerPostSink, f.Clock), + logger: f.Logger, + skipConfigProbe: () => ((bool?)false, (bool?)false), + accountSetupActivityProbe: () => true); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + + var posted = Assert.Single(f.Ingress.Posted); + Assert.Equal(DecisionSignalKind.EspExiting, posted.Kind); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerUserEspAppsSettledTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerUserEspAppsSettledTests.cs new file mode 100644 index 00000000..111cc5e7 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerUserEspAppsSettledTests.cs @@ -0,0 +1,142 @@ +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 +{ + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11) — IME-side probe semantics. + /// must be conservative: it only returns + /// true when the tracker is in the AccountSetup phase AND the live (current-phase) + /// package list contains at least one required app, all required apps are terminal + /// (Installed / Skipped / Postponed), and no tracked app is in Error. + /// + public sealed class ImeLogTrackerUserEspAppsSettledTests + { + private static ImeLogTracker BuildTracker(TempDirectory tmp) => + new ImeLogTracker( + logFolder: tmp.Path, + patterns: new List(), + logger: new AgentLogger(tmp.Path, AgentLogLevel.Info)); + + private static AppPackageState AddApp( + ImeLogTracker tracker, + string id, + AppIntent intent, + AppInstallationState state) + { + var pkg = tracker.PackageStates.GetPackage(id, createIfNotFound: true); + pkg.UpdateIntent(intent); + if (state == AppInstallationState.Installed) + { + // Installed requires DownloadingOrInstallingSeen, else UpdateState auto-downgrades + // to Skipped (inverse-detection handling). Walk the real lifecycle. + pkg.UpdateState(AppInstallationState.Installing); + } + if (state != AppInstallationState.Unknown) + { + pkg.UpdateState(state); + } + return pkg; + } + + [Fact] + public void False_outside_AccountSetup_phase() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("DeviceSetup"); + AddApp(tracker, "app-1", AppIntent.Install, AppInstallationState.Installed); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void False_when_phase_never_detected() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + AddApp(tracker, "app-1", AppIntent.Install, AppInstallationState.Installed); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void False_when_no_apps_tracked_in_current_phase() + { + // The live list is cleared on the DeviceSetup→AccountSetup transition; an empty list + // (user apps not yet surfaced) must read as "not settled", never vacuously true — + // otherwise the first intermediate esp_exiting would open the gate prematurely. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void False_while_a_required_app_is_still_in_flight() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(tracker, "app-skipped", AppIntent.Install, AppInstallationState.Skipped); + AddApp(tracker, "app-installing", AppIntent.Install, AppInstallationState.Installing); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void False_when_any_app_failed() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(tracker, "app-ok", AppIntent.Install, AppInstallationState.Installed); + AddApp(tracker, "app-failed", AppIntent.Install, AppInstallationState.Error); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void False_when_only_intent_unknown_apps_are_tracked() + { + // Intent never parsed → too weak as completion evidence; stay conservative. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(tracker, "app-unknown-intent", AppIntent.Unknown, AppInstallationState.Skipped); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void True_when_all_required_user_apps_are_terminal_with_zero_failures() + { + // The caa6cf50 shape: one app policy-skipped (the registry's Apps subcategory + // therefore never reaches "succeeded"), one app installed. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(tracker, "gsa-test", AppIntent.Install, AppInstallationState.Skipped); + AddApp(tracker, "teamviewer", AppIntent.Install, AppInstallationState.Installed); + + Assert.True(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void True_with_postponed_apps_counts_as_terminal() + { + // Postponed = IME deferred the install past ESP; the ESP page will not wait for it. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(tracker, "app-postponed", AppIntent.Install, AppInstallationState.Postponed); + + Assert.True(tracker.AreUserEspAppsSettled()); + } + } +} 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 6a109d84..6ccf7ad6 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 @@ -201,6 +201,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime _phasePackageSnapshots[phaseName] = new List(apps); } + /// + /// Test-only seam: sets the tracker's current detected ESP phase without driving the + /// IME-ESP-PHASE regex pattern through a real log file. Production code never calls + /// this — the phase is set by HandleEspPhaseDetected from live pattern matches + /// (or restored from persisted state). Used by AreUserEspAppsSettled tests. + /// + internal void SeedCurrentPhaseForTesting(string phaseName) + { + _lastEspPhaseDetected = phaseName; + } + /// /// Returns a deduped union of phase-snapshotted apps plus the live /// (current phase). Live entries win on Id collision. @@ -229,6 +240,56 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return result; } + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11): returns true when the + /// tracker's current ESP phase is AccountSetup AND every tracked user-phase app has + /// reached a terminal state (Installed / Skipped / Postponed) with zero errors. + /// + /// Used by EspAndHelloTracker as alternative evidence for the strong + /// post-AccountSetup completion gate: when a user-ESP app is policy-skipped, Windows + /// never flips the registry's Apps subcategory to succeeded and never writes + /// AccountSetupCategory.Status.categorySucceeded before tearing down the ESP + /// page — the registry-driven AccountSetupProvisioningComplete (and its + /// all-subcategories fallback) can then never fire. IME's own app tracking is the + /// independent evidence that AccountSetup app enforcement actually finished. + /// + /// + /// Conservative by construction: requires at least one required (Install/Uninstall + /// intent) app in the live current-phase list — an empty list (phase just cleared, or + /// apps not yet surfaced) or intent-unknown-only tracking returns false. Any + /// app in returns false. May be called + /// from the Shell-Core event-log watcher thread while the polling thread mutates the + /// list — any race-induced exception is swallowed and reported as "not settled". + /// + /// + public bool AreUserEspAppsSettled() + { + try + { + if (!string.Equals(_lastEspPhaseDetected, "AccountSetup", StringComparison.OrdinalIgnoreCase)) + return false; + + var apps = new List(_packageStates); + if (apps.Count == 0) return false; + + var sawRequired = false; + foreach (var pkg in apps) + { + if (pkg == null) continue; + if (pkg.IsError) return false; + if (!pkg.IsRequired) continue; + sawRequired = true; + if (!pkg.IsCompleted) return false; + } + return sawRequired; + } + catch (Exception ex) + { + _logger.Debug($"ImeLogTracker: AreUserEspAppsSettled probe threw: {ex.Message}"); + return false; + } + } + /// /// Promotes every app currently in to /// , stamping diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs index a6d5af57..68c08046 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs @@ -1,6 +1,8 @@ using System; +using System.Collections.Generic; using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Shared; using AutopilotMonitor.Shared.Models; namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals @@ -37,6 +39,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private readonly int[] _modernDeploymentHarmlessEventIds; private readonly Func<(bool? skipUser, bool? skipDevice)> _skipConfigProbe; private readonly Func _accountSetupActivityProbe; + private readonly Func _userEspAppsSettledProbe; + + // Session caa6cf50 gate-starvation fix (2026-06-11) — fire-once guard for the + // user-ESP-apps-settled AccountSetup synthesis (see MaybeSynthesizeAccountSetupComplete). + private bool _userAppsSettledSynthesisFired; private HelloTracker _helloTracker; private ShellCoreTracker _shellCoreTracker; @@ -187,7 +194,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals string stateDirectory = null, int[] modernDeploymentHarmlessEventIds = null, Func<(bool? skipUser, bool? skipDevice)> skipConfigProbe = null, - Func accountSetupActivityProbe = null) + Func accountSetupActivityProbe = null, + Func userEspAppsSettledProbe = null) { _sessionId = sessionId ?? throw new ArgumentNullException(nameof(sessionId)); _tenantId = tenantId ?? throw new ArgumentNullException(nameof(tenantId)); @@ -206,6 +214,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // Test seam: allow injection of a fake AccountSetup-activity probe. Production uses // the provisioning tracker's live registry-derived flag. _accountSetupActivityProbe = accountSetupActivityProbe ?? (() => _provisioningTracker?.HasAccountSetupActivity == true); + // Session caa6cf50 gate-starvation fix: IME-side "all tracked user-ESP apps terminal" + // probe (wired to ImeLogHost.AreUserEspAppsSettled by DefaultComponentFactory). + // Defaults to "not settled" so single-tracker wiring scenarios keep prior behaviour. + _userEspAppsSettledProbe = userEspAppsSettledProbe ?? (() => false); } // ===================================================================== @@ -561,9 +573,85 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // this path is NOT filtered by IsIntermediateDeviceEspExit — the reducer-side // ShouldTransitionToAwaitingHello guard decides whether HelloSafety arms. LastEventOccurredAtUtc = args?.OccurredAtUtc; - try { EspExited?.Invoke(this, args); } - catch (Exception ex) { _logger.Error("Error forwarding EspExited", ex); } + try + { + try { EspExited?.Invoke(this, args); } + catch (Exception ex) { _logger.Error("Error forwarding EspExited", ex); } + + // Session caa6cf50 gate-starvation fix: a Shell-Core normal exit while IME's + // user-ESP app tracking is fully settled is alternative evidence that + // AccountSetup completed. Raised AFTER the EspExited forward so the reducer + // records EspFinalExitUtc first and the deferred-promote path in + // HandleAccountSetupProvisioningCompleteV1 takes over. + MaybeSynthesizeAccountSetupCompleteFromSettledUserApps(); + } finally { LastEventOccurredAtUtc = null; } } + + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11). When a user-ESP app is + /// policy-skipped by IME, Windows leaves the ESP registry's Apps subcategory stuck at + /// inProgress ("Apps (N of M installed)") and never writes + /// AccountSetupCategory.Status.categorySucceeded before tearing down the ESP page + /// — after the page exits those values are never updated again. Both registry-driven + /// paths + /// (normal + all-subcategories fallback) are then permanently starved, the reducer's + /// strong post-AccountSetup gate never opens, and the session stalls despite a fully + /// successful enrollment. + /// + /// This synthesis accepts the equivalent evidence pair instead: Shell-Core 62407 normal + /// exit (the caller) + all tracked user-ESP apps terminal with zero failures (the + /// injected IME probe). Fire-once; the registry path's tracker-level dedup and the + /// adapter's fire-once flag make a duplicate raise benign either way. Never fires while + /// any user-phase app is failed or still in flight — those sessions keep today's + /// conservative stall behaviour. + /// + /// + private void MaybeSynthesizeAccountSetupCompleteFromSettledUserApps() + { + if (_userAppsSettledSynthesisFired) return; + + bool settled; + try { settled = _userEspAppsSettledProbe(); } + catch (Exception ex) + { + _logger.Debug($"EspAndHelloTracker: user-ESP-apps-settled probe threw: {ex.Message}"); + return; + } + if (!settled) return; + + _userAppsSettledSynthesisFired = true; + _logger.Warning( + "EspAndHelloTracker: ESP exited normally with all tracked user-ESP apps terminal (0 failed) " + + "but AccountSetupCategory.Status never confirmed categorySucceeded — treating AccountSetup as complete " + + "(user-apps-settled synthesis)"); + + _post.Emit(new EnrollmentEvent + { + SessionId = _sessionId, + TenantId = _tenantId, + EventType = Constants.EventTypes.EspProvisioningStatus, + Severity = EventSeverity.Warning, + Source = "EspAndHelloTracker", + Phase = EnrollmentPhase.Unknown, + Message = "ESP provisioning status: AccountSetup — ESP page exited normally and all tracked " + + "user-ESP apps reached a terminal state (0 failed) but categorySucceeded was never " + + "confirmed by Windows — treating as complete (user-apps-settled synthesis)", + Data = new Dictionary + { + { "category", "AccountSetup" }, + { "categorySucceeded", "in_progress" }, + { "fallbackApplied", true }, + { "fallbackReason", "esp_exited_user_apps_settled_category_unresolved" }, + } + }); + + try { AccountSetupProvisioningComplete?.Invoke(this, EventArgs.Empty); } + catch (Exception ex) { _logger.Error("AccountSetupProvisioningComplete handler failed (user-apps-settled synthesis)", ex); } + } + + // Test seam for the user-apps-settled synthesis — drives OnEspExited with the live + // handler signature, mirroring TriggerEspExitedForTest's contract. + internal bool UserAppsSettledSynthesisFiredForTest => _userAppsSettledSynthesisFired; } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index b90b0b61..b0d34f0b 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -102,6 +102,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // ----- Kernel hosts (always-on; they produce decision signals) -------------------- + // Session caa6cf50 gate-starvation fix: the EspAndHelloTracker's user-ESP-apps-settled + // probe reads the IME log host, which is constructed further down. Same closure-over- + // local pattern as realmJoinHost below — null until assigned, and the probe only fires + // on esp_exiting events long after Start. + ImeLogHost? imeLogHostRef = null; + var espAndHelloHost = new EspAndHelloHost( sessionId: sessionId, tenantId: tenantId, @@ -114,7 +120,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration modernDeploymentBackfillEnabled: collectors.ModernDeploymentBackfillEnabled, modernDeploymentBackfillLookbackMinutes: collectors.ModernDeploymentBackfillLookbackMinutes, modernDeploymentHarmlessEventIds: collectors.ModernDeploymentHarmlessEventIds, - stateDirectory: _stateDirectory); + stateDirectory: _stateDirectory, + userEspAppsSettledProbe: () => imeLogHostRef?.AreUserEspAppsSettled() == true); hosts.Add(espAndHelloHost); // Hybrid User-Driven completion-gap fix (2026-05-01): the AadJoinHost notifies @@ -202,6 +209,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration simulationMode: simulationMode, simulationSpeedFactor: _agentConfig.ReplaySpeedFactor); hosts.Add(imeLogHost); + imeLogHostRef = imeLogHost; if (collectors.StallProbeEnabled) { 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 6d144538..e90f5885 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/EspAndHelloHost.cs @@ -60,7 +60,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration bool modernDeploymentBackfillEnabled, int modernDeploymentBackfillLookbackMinutes, int[]? modernDeploymentHarmlessEventIds, - string stateDirectory) + string stateDirectory, + Func? userEspAppsSettledProbe = null) { if (ingress == null) throw new ArgumentNullException(nameof(ingress)); if (clock == null) throw new ArgumentNullException(nameof(clock)); @@ -76,7 +77,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration modernDeploymentBackfillEnabled: modernDeploymentBackfillEnabled, modernDeploymentBackfillLookbackMinutes: modernDeploymentBackfillLookbackMinutes, stateDirectory: stateDirectory, - modernDeploymentHarmlessEventIds: modernDeploymentHarmlessEventIds); + modernDeploymentHarmlessEventIds: modernDeploymentHarmlessEventIds, + userEspAppsSettledProbe: userEspAppsSettledProbe); _tracker.WhiteGloveCompleted += OnTrackerWhiteGloveCompleted; _tracker.DeviceSetupProvisioningComplete += OnTrackerDeviceSetupProvisioningComplete; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs index 409d1dca..08df1ff6 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs @@ -51,6 +51,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration /// internal ImeLogTracker Tracker => _tracker; + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11) — bridge for the + /// EspAndHelloTracker user-ESP-apps-settled probe. True when the tracker's + /// current ESP phase is AccountSetup and every tracked user-phase app is terminal + /// (installed/skipped/postponed, zero errors). See + /// . + /// + public bool AreUserEspAppsSettled() => _tracker.AreUserEspAppsSettled(); + /// /// c117946b debrief (2026-05-12) — bridge for the EnrollmentTerminationHandler /// pre-hook to promote apps still in diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassicGateStarvationDeferredCompletionTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassicGateStarvationDeferredCompletionTests.cs new file mode 100644 index 00000000..a50690cc --- /dev/null +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassicGateStarvationDeferredCompletionTests.cs @@ -0,0 +1,236 @@ +using System; +using System.Collections.Generic; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using AutopilotMonitor.DecisionCore.State; +using AutopilotMonitor.Shared.Models; +using Xunit; + +namespace AutopilotMonitor.DecisionCore.Tests +{ + /// + /// Session caa6cf50 gate-starvation fix (2026-06-11). Production sequence: Classic-v1 + + /// Hello-disabled on Win11, where explorer.exe runs underneath the User-ESP page so + /// DesktopArrived lands BEFORE the final EspExiting. A policy-skipped user-ESP app left + /// the registry's Apps subcategory permanently inProgress, so the registry-driven + /// AccountSetupProvisioningComplete never fired and the session stalled with all + /// completion facts in place (espFinalExit + desktop + helloPolicy=false) but the strong + /// gate closed. + /// + /// The agent-side half of the fix synthesises AccountSetupProvisioningComplete from + /// "Shell-Core normal exit + all tracked user-ESP apps terminal (0 failed)". These tests + /// cover the reducer-side half: HandleAccountSetupProvisioningCompleteV1's deferred + /// path must mirror the live-ordering completion checks when the strong gate arrives LAST — + /// completing through Finalizing instead of parking in AwaitingHello until HelloSafety + /// stamps a misleading HelloOutcome="Timeout" 300 s later. + /// + /// + public sealed class ClassicGateStarvationDeferredCompletionTests + { + private static readonly DateTime T0 = new DateTime(2026, 6, 11, 7, 36, 0, DateTimeKind.Utc); + + [Fact] + public void GateArrivesLast_HelloDisabled_DesktopAlreadyArrived_completes_through_Finalizing() + { + // Replay of session caa6cf50's signal ordering: + // DeviceSetup → Hello policy disabled → AccountSetup → EspExiting (gate closed, fact + // only) → DesktopArrived (fast-path blocked by gate) → EspExiting (final, still + // blocked) → synthesized AccountSetupProvisioningComplete → MUST complete. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine); + + // Sanity: all completion facts in place, but the session is parked (the bug shape). + Assert.NotNull(state.EspFinalExitUtc); + Assert.NotNull(state.DesktopArrivedUtc); + Assert.False(state.HelloPolicyEnabled!.Value); + Assert.Null(state.HelloResolvedUtc); + Assert.Null(state.AccountSetupProvisioningSucceededUtc); + Assert.Equal(SessionStage.EspAccountSetup, state.Stage); + Assert.Empty(state.Deadlines); + + var step = engine.Reduce(state, MakeSignal(20, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24).AddSeconds(10), null)); + + // Deferred completion: Finalizing in one step, synthetic HelloOutcome="Skipped". + Assert.Equal(SessionStage.Finalizing, step.NewState.Stage); + Assert.Null(step.NewState.Outcome); // EnrollmentComplete deferred to FinalizingGrace + Assert.Equal("Skipped", step.NewState.HelloOutcome!.Value); + Assert.NotNull(step.NewState.HelloResolvedUtc); + Assert.NotNull(step.NewState.AccountSetupProvisioningSucceededUtc); + + // No HelloSafety armed — we went straight to Finalizing, not AwaitingHello. + Assert.DoesNotContain(step.NewState.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + Assert.Contains(step.NewState.Deadlines, d => d.Name == DeadlineNames.FinalizingGrace); + Assert.Contains(step.Effects, + e => e.Kind == DecisionEffectKind.EmitEventTimelineEntry + && e.Parameters != null + && e.Parameters.TryGetValue("eventType", out var et) && et == "phase_transition" + && e.Parameters.TryGetValue("phase", out var ph) && ph == nameof(EnrollmentPhase.FinalizingSetup)); + + // FinalizingGrace fires → terminal enrollment_complete. + var afterGrace = engine.Reduce( + step.NewState, + MakeSignal(21, DecisionSignalKind.DeadlineFired, T0.AddMinutes(24).AddSeconds(15), + new Dictionary { [SignalPayloadKeys.Deadline] = DeadlineNames.FinalizingGrace })); + + Assert.Equal(SessionStage.Completed, afterGrace.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentComplete, afterGrace.NewState.Outcome); + Assert.Contains(afterGrace.Effects, + e => e.Kind == DecisionEffectKind.EmitEventTimelineEntry + && e.Parameters != null + && e.Parameters.TryGetValue("eventType", out var et) && et == "enrollment_complete"); + } + + [Fact] + public void GateArrivesLast_HelloAlreadyResolved_DesktopAlreadyArrived_completes_without_overwriting_outcome() + { + // Hello resolved earlier (e.g. wizard observed) but the strong gate arrived last. + // The deferred path must complete and keep the real HelloOutcome. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine, includeHelloPolicy: false); + state = engine.Reduce(state, MakeSignal(15, DecisionSignalKind.HelloResolved, T0.AddMinutes(23), + new Dictionary { [SignalPayloadKeys.HelloOutcome] = "completed" })).NewState; + + // HelloResolved with Desktop already in routes to Finalizing only when the gate is + // open — which it is not yet, so HandleHelloResolvedV1's both-prerequisites branch + // already fired Finalizing... verify the actual stage first. + // NOTE: HandleHelloResolvedV1 does not consult ShouldTransitionToAwaitingHello — with + // desktop already arrived it completes directly. That ordering therefore never needed + // this fix; assert it as documentation of the boundary. + Assert.Equal(SessionStage.Finalizing, state.Stage); + } + + [Fact] + public void GateArrivesLast_DesktopNotYetArrived_keeps_existing_DeferredPromote_to_AwaitingHello() + { + // Regression guard: without DesktopArrived the deferred path must keep promoting to + // AwaitingHello + arm HelloSafety exactly as before this fix. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine, includeDesktop: false); + Assert.Null(state.DesktopArrivedUtc); + + var step = engine.Reduce(state, MakeSignal(20, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24), null)); + + Assert.Equal(SessionStage.AwaitingHello, step.NewState.Stage); + Assert.Null(step.NewState.HelloResolvedUtc); + Assert.Contains(step.NewState.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + Assert.DoesNotContain(step.NewState.Deadlines, d => d.Name == DeadlineNames.FinalizingGrace); + } + + [Fact] + public void GateArrivesLast_HelloPolicyUnknown_DesktopArrived_stays_pessimistic_AwaitingHello() + { + // HelloPolicyEnabled == null → the deferred path must NOT synthesise "Skipped"; + // promote to AwaitingHello and let the Hello wizard / HelloSafety resolve it. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine, includeHelloPolicy: false); + Assert.Null(state.HelloPolicyEnabled); + Assert.NotNull(state.DesktopArrivedUtc); + + var step = engine.Reduce(state, MakeSignal(20, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24), null)); + + Assert.Equal(SessionStage.AwaitingHello, step.NewState.Stage); + Assert.Null(step.NewState.HelloResolvedUtc); + Assert.Null(step.NewState.HelloOutcome); + Assert.Contains(step.NewState.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + } + + [Fact] + public void GateArrivesLast_HelloPolicyEnabled_DesktopArrived_stays_pessimistic_AwaitingHello() + { + // HelloPolicyEnabled == true → the real Hello wizard is expected; no synthesis. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine, helloEnabled: true); + Assert.True(state.HelloPolicyEnabled!.Value); + + var step = engine.Reduce(state, MakeSignal(20, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24), null)); + + Assert.Equal(SessionStage.AwaitingHello, step.NewState.Stage); + Assert.Null(step.NewState.HelloResolvedUtc); + Assert.Contains(step.NewState.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + } + + [Fact] + public void DuplicateGateSignal_after_completion_path_is_a_noop_bookkeeping_step() + { + // The adapter dedupes, but a replayed duplicate must not double-complete: the fact is + // already recorded, so shouldPromote (first-record guard) rejects and the signal + // becomes bookkeeping only. + var engine = new DecisionEngine(); + var state = ProgressToBlockedPostExitState(engine); + state = engine.Reduce(state, MakeSignal(20, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24), null)).NewState; + Assert.Equal(SessionStage.Finalizing, state.Stage); + + var dup = engine.Reduce(state, MakeSignal(21, DecisionSignalKind.AccountSetupProvisioningComplete, + T0.AddMinutes(24).AddSeconds(2), null)); + + Assert.Equal(SessionStage.Finalizing, dup.NewState.Stage); + // Exactly one FinalizingGrace deadline; no second phase_transition effect. + Assert.Single(dup.NewState.Deadlines, d => d.Name == DeadlineNames.FinalizingGrace); + Assert.DoesNotContain(dup.Effects, + e => e.Kind == DecisionEffectKind.EmitEventTimelineEntry); + } + + // ====================================================================== test helpers + + /// + /// Drives the engine into session caa6cf50's blocked shape: Classic AccountSetup entered, + /// Hello policy fact (configurable), EspExiting recorded but guard-rejected (gate closed), + /// DesktopArrived recorded but fast-path-rejected. Stage stays EspAccountSetup with no + /// active deadlines. + /// + private static DecisionState ProgressToBlockedPostExitState( + DecisionEngine engine, + bool includeHelloPolicy = true, + bool helloEnabled = false, + bool includeDesktop = true) + { + var state = DecisionState.CreateInitial("sess-caa6cf50", "tenant-e46bc88e", T0); + state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0, null)).NewState; + state = engine.Reduce(state, MakeSignal(1, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })).NewState; + if (includeHelloPolicy) + { + state = engine.Reduce(state, MakeSignal(2, DecisionSignalKind.HelloPolicyDetected, T0.AddMinutes(1).AddSeconds(5), + new Dictionary { [SignalPayloadKeys.HelloEnabled] = helloEnabled ? "true" : "false" })).NewState; + } + state = engine.Reduce(state, MakeSignal(3, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(12), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + // First esp_exiting (Device→Account handoff per Shell-Core 62407) — gate closed, fact only. + state = engine.Reduce(state, MakeSignal(4, DecisionSignalKind.EspExiting, T0.AddMinutes(13), null)).NewState; + Assert.Equal(SessionStage.EspAccountSetup, state.Stage); + if (includeDesktop) + { + // Desktop arrives during User-ESP (Win11: explorer.exe under the ESP page) — + // Hello-disabled fast-path blocked by the closed strong gate. + state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.DesktopArrived, T0.AddMinutes(16), null)).NewState; + Assert.NotEqual(SessionStage.Finalizing, state.Stage); + } + // Final esp_exiting — still blocked (gate evidence never came from the registry). + state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.EspExiting, T0.AddMinutes(24), null)).NewState; + Assert.Equal(SessionStage.EspAccountSetup, state.Stage); + return state; + } + + private static DecisionSignal MakeSignal( + long ordinal, + DecisionSignalKind kind, + DateTime occurredAtUtc, + IReadOnlyDictionary? payload) + { + return new DecisionSignal( + sessionSignalOrdinal: ordinal, + sessionTraceOrdinal: ordinal, + kind: kind, + kindSchemaVersion: 1, + occurredAtUtc: occurredAtUtc, + sourceOrigin: "test", + evidence: new Evidence(EvidenceKind.Synthetic, $"test-{kind}-{ordinal}", $"synthetic {kind}"), + payload: payload); + } + } +} diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs index 5b36099b..56241703 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs @@ -796,6 +796,45 @@ namespace AutopilotMonitor.DecisionCore.Engine return new DecisionStep(newState, transition, Array.Empty()); } + // Deferred-completion parity (session caa6cf50 fix, 2026-06-11): when the strong gate + // arrives LAST — after both EspExiting and DesktopArrived already landed (the Win11 + // Classic ordering where explorer.exe runs underneath the User-ESP page, so Desktop + // "arrives" before the final exit) — promoting to AwaitingHello would park the session + // until HelloSafety stamps a misleading HelloOutcome="Timeout" 300 s later. Mirror the + // completion checks the live-ordering handlers perform instead: + // * Hello already resolved → both prerequisites in → Finalizing (HandleDesktopArrivedV1 + // helloAlreadyResolved branch). + // * Hello policy explicitly disabled → synthesise HelloOutcome="Skipped" → Finalizing + // (HandleDesktopArrivedV1 Hello-disabled fast-path; its strong-gate arm is satisfied + // by the very fact this signal records). + // HelloPolicyEnabled == null keeps the pessimistic AwaitingHello promotion below. + var desktopAlreadyArrived = state.DesktopArrivedUtc != null; + if (desktopAlreadyArrived + && (state.HelloResolvedUtc != null || state.HelloPolicyEnabled?.Value == false)) + { + if (state.HelloResolvedUtc == null) + { + builder.HelloResolvedUtc = new SignalFact(signal.OccurredAtUtc, signal.SessionSignalOrdinal); + builder.HelloOutcome = new SignalFact("Skipped", signal.SessionSignalOrdinal); + } + + var helloSafetyCancelEffect = BuildHelloSafetyCancelEffectIfArmed(state); + if (helloSafetyCancelEffect != null) + { + builder.CancelDeadline(DeadlineNames.HelloSafety); + } + + return CompleteThroughFinalizingOrDefer( + state: state, + signal: signal, + preparedBuilder: builder, + nextStepIndex: nextStep, + trigger: nameof(DecisionSignalKind.AccountSetupProvisioningComplete) + ":DeferredCompletion", + leadingEffects: helloSafetyCancelEffect != null + ? new[] { helloSafetyCancelEffect } + : null); + } + // Mirror of HandleEspExitingV1's promote branch, using this signal's instant as // the deadline base. EffectiveDeadlineBase still floors at AgentBootUtc to keep // the replay-safety guarantee.