diff --git a/docs/agent/post-reboot-completion-recovery.md b/docs/agent/post-reboot-completion-recovery.md index 05fdde0f..6ea58fc7 100644 --- a/docs/agent/post-reboot-completion-recovery.md +++ b/docs/agent/post-reboot-completion-recovery.md @@ -56,6 +56,14 @@ 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. +**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 +the *first* match — with a downtime-sized window that is the intermediate +DeviceSetup→AccountSetup exit, and the final post-AccountSetup exit is then swallowed by the +fire-once guard. `ReplayBackfillRecords` therefore buffers the batch and lets only the newest +exit-matching record through the exit branch; ESP failures and the Hello-wizard rail keep +replaying chronologically, exactly as before. + ## Defect 2 — the synthesis was edge-triggered `MaybeSynthesizeAccountSetupCompleteFromSettledUserApps()` ran **only** from `OnEspExited`. @@ -72,11 +80,35 @@ uses). Every terminal app transition gives the synthesis another look. This adds **no new completion path**. The gate conditions are unchanged — real ESP exit, every required user-ESP app terminal, zero failures. The re-check only grants the existing, -deliberately conservative check a second opportunity. Two guards keep it cheap and safe: +deliberately conservative check a second opportunity. Three guards keep it cheap and safe: the fire-once claim is an `Interlocked.CompareExchange` (the re-check runs on the IME log -thread, the edge on the Shell-Core watcher thread), and the re-check path suppresses +thread, the edge on the Shell-Core watcher thread); the re-check path suppresses `app_install_starved` emission so the one-shot warning does not become a per-transition -stream. +stream; and the edge itself is gated. + +**Only a confirmed post-AccountSetup exit may be remembered.** Shell-Core raises 62407 at +every ESP phase transition. Remembering the DeviceSetup→AccountSetup one would let the +deferred re-check open the strong AccountSetup gate the moment the last user app settles — +while the AccountSetup page is still up and its other subcategories are still running, i.e. +a premature success. `IsConfirmedPostAccountSetupExit()` demands positive evidence and is +deliberately stricter than the existing `IsIntermediateDeviceEspExit()` forward guard: + +| Evidence | Meaning | +|---|---| +| provisioning tracker reports AccountSetup activity | the page that just tore down is the AccountSetup one | +| `SkipUser == true` | the profile has no user ESP; the Device-ESP exit **is** the final one | + +Anything else — including an unknown `SkipUser` — counts as *not confirmed*. The asymmetry is +intentional: erring strict costs at worst the pre-fix behaviour (the session stalls), while +erring loose costs a premature `Succeeded`, which nothing downstream can take back. + +**The re-check must also run after the IME state restore.** `ImeLogTracker.Start()` restores +the persisted package states via `LoadState()` and raises no `OnAppStateChanged` for them, and +`ImeLogHost` starts *after* `EspAndHelloHost` (pinned by +`DefaultComponentFactoryOrderingTests`). So on a restart the ESP-exit replay runs against an +empty app list. `ImeLogHost` takes an `onStateRestored` callback — wired in the factory to the +re-check — which covers the sharpest case of all: apps already terminal *before* the reboot, +with only the final exit lost to the downtime. # Examples diff --git a/docs/log.md b/docs/log.md index d3375d88..25fe92bd 100644 --- a/docs/log.md +++ b/docs/log.md @@ -2,7 +2,7 @@ ## 2026-08-19 -* **New**: `agent/post-reboot-completion-recovery.md` — a forced mid-ESP reboot (DeviceGuard/DmaGuard) used to cost the session its AccountSetup completion permanently. Two defects: `ShellCoreTracker.BackfillRecentEspExitEvents()` existed but had no caller, so every agent restart dropped an ESP exit (62407) written while it was down; and the user-apps-settled synthesis was edge-triggered on `EspExited` only, so apps settling afterwards never re-opened the gate. `EspAndHelloHost.Start()` now backfills with a lookback sized to the downtime (`previousExit=reboot_kill` → since `LastBootUtc`, clamped to 360 min), and `ReevaluateUserAppsSettledSynthesis()` is chained into `ImeLogTracker.OnAppStateChanged`. No new completion path — the gate conditions are unchanged. Evidence: sits-d Cloud PCs, five `Incomplete` sessions on healthy devices, two of them at `138/138 apps, 0 failed`. +* **New**: `agent/post-reboot-completion-recovery.md` — a forced mid-ESP reboot (DeviceGuard/DmaGuard) used to cost the session its AccountSetup completion permanently. Two defects: `ShellCoreTracker.BackfillRecentEspExitEvents()` existed but had no caller, so every agent restart dropped an ESP exit (62407) written while it was down; and the user-apps-settled synthesis was edge-triggered on `EspExited` only, so apps settling afterwards never re-opened the gate. `EspAndHelloHost.Start()` now backfills with a lookback sized to the downtime (`previousExit=reboot_kill` → since `LastBootUtc`, clamped to 360 min), and `ReevaluateUserAppsSettledSynthesis()` is chained into `ImeLogTracker.OnAppStateChanged`. No new completion path — the gate conditions are unchanged. Evidence: sits-d Cloud PCs, five `Incomplete` sessions on healthy devices, two of them at `138/138 apps, 0 failed`. Hardened after review: only a **confirmed** post-AccountSetup exit may be remembered as the edge (`IsConfirmedPostAccountSetupExit` — AccountSetup activity seen, or `SkipUser == true`; unknown counts as not confirmed), the replay hands over the **newest** exit rather than the oldest (the widened window holds the intermediate one too), and `ImeLogHost` re-triggers the check after its silent `LoadState()` because it starts after `EspAndHelloHost`. * **Update**: `rules/analyze-rule-triggers.md` — `on_event:session_stalled` documented as an established interim trigger for the never-terminal stuck session (one emission per session, no throttle needed). `ANALYZE-ESP-005` carries it: both its conditions are monotonic and it has no terminal precondition, and it fires at confidence 95 on the sits-d stalled stream. `ANALYZE-APP-015` deliberately does NOT — it is the worked example of the terminal-precondition trap (lint 1) — and `ANALYZE-ESP-001` does not either, because its `phase_duration` gate on a still-open phase is unverified mid-run. New `ANALYZE-APP-016` ("Required Apps Never Started — ESP Apps Gate Starved") turns the existing `app_install_starved` events into a customer-facing finding and, unlike `ANALYZE-APP-015`, fires even when the session succeeded — session `3b9291aa` was recorded `Succeeded` with 99 required apps that never started installing. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs index bf429069..dcf26f6e 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EspAndHelloTrackerUserAppsSettledSynthesisTests.cs @@ -35,14 +35,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring public Fixture() { Logger = new AgentLogger(Tmp.Path, AgentLogLevel.Debug); } public EspAndHelloTracker BuildCoordinator(Func settledProbe) + => BuildCoordinator(settledProbe, accountSetupActivityProbe: () => true, skipUserEsp: false); + + /// + /// Codex review P1 (2026-08-19): the remembered exit edge is gated on positive evidence + /// that the exit is post-AccountSetup, so these two probes decide whether the deferred + /// re-check may fire at all. + /// + public EspAndHelloTracker BuildCoordinator( + Func settledProbe, + Func accountSetupActivityProbe, + bool? skipUserEsp) { return new EspAndHelloTracker( sessionId: "S1", tenantId: "T1", post: new InformationalEventPost(TrackerPostSink, Clock), logger: Logger, - skipConfigProbe: () => ((bool?)false, (bool?)false), - accountSetupActivityProbe: () => true, + skipConfigProbe: () => (skipUserEsp, (bool?)false), + accountSetupActivityProbe: accountSetupActivityProbe, userEspAppsSettledProbe: settledProbe); } @@ -224,6 +235,90 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring Assert.Single(f.TrackerPostSink.Posted); } + // ------------------------------------------------------------------------------ + // Codex review P1 (2026-08-19): Shell-Core raises 62407 at EVERY ESP phase transition. + // Remembering the intermediate DeviceSetup→AccountSetup exit would let the deferred + // re-check open the strong AccountSetup gate as soon as the last user app settles — + // while the AccountSetup page is still up and its other subcategories still running. + // ------------------------------------------------------------------------------ + + [Fact] + public void Intermediate_device_exit_is_not_remembered_as_the_edge() + { + using var f = new Fixture(); + var settled = false; + // Classic user-driven enrollment (SkipUser=false) that has NOT reached AccountSetup: + // this 62407 is the DeviceSetup→AccountSetup transition, not the final exit. + using var coordinator = f.BuildCoordinator( + () => settled, accountSetupActivityProbe: () => false, skipUserEsp: false); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + + // Apps settle afterwards — the level is reached, but the edge was never a valid one. + settled = true; + for (var i = 0; i < 10; i++) coordinator.ReevaluateUserAppsSettledSynthesis(); + + Assert.DoesNotContain(f.Ingress.Posted, p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete); + Assert.False(coordinator.UserAppsSettledSynthesisFiredForTest); + Assert.Empty(f.TrackerPostSink.Posted); + } + + [Fact] + public void Unknown_skip_user_is_treated_as_unconfirmed() + { + // Erring strict costs at worst today's stall; erring loose costs a premature Succeeded. + using var f = new Fixture(); + var settled = false; + using var coordinator = f.BuildCoordinator( + () => settled, accountSetupActivityProbe: () => false, skipUserEsp: null); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + settled = true; + coordinator.ReevaluateUserAppsSettledSynthesis(); + + Assert.False(coordinator.UserAppsSettledSynthesisFiredForTest); + } + + [Fact] + public void Skip_user_profile_confirms_the_device_exit_as_final() + { + // SkipUser=true means there is no user ESP at all — the Device-ESP exit IS the final + // one and no second exit is coming, so the edge is legitimately remembered. + using var f = new Fixture(); + var settled = false; + using var coordinator = f.BuildCoordinator( + () => settled, accountSetupActivityProbe: () => false, skipUserEsp: true); + using var adapter = new EspAndHelloTrackerAdapter(coordinator, f.Ingress, f.Clock); + + coordinator.TriggerEspExitedForTest(Fixed); + settled = true; + coordinator.ReevaluateUserAppsSettledSynthesis(); + + Assert.Equal(1, f.Ingress.Posted.Count(p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete)); + } + + [Fact] + public void Account_setup_activity_confirms_the_edge_for_the_deferred_recheck() + { + // The real reboot shape: AccountSetup activity is visible in the registry, the final + // exit lands, the apps settle a moment later. + using var f = new Fixture(); + var settled = false; + using var coordinator = f.BuildCoordinator( + () => settled, accountSetupActivityProbe: () => true, skipUserEsp: false); + 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.ReevaluateUserAppsSettledSynthesis(); + + Assert.Equal(1, f.Ingress.Posted.Count(p => p.Kind == DecisionSignalKind.AccountSetupProvisioningComplete)); + } + [Fact] public void Reevaluate_stays_silent_while_apps_are_still_unsettled() { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/ShellCoreTrackerEspExitBackfillTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/ShellCoreTrackerEspExitBackfillTests.cs index 2a8c369a..59099eb0 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/ShellCoreTrackerEspExitBackfillTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/ShellCoreTrackerEspExitBackfillTests.cs @@ -163,6 +163,93 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring Assert.Equal(0, exits); } + // ------------------------------------------------------------------------------ + // Codex review P1 (2026-08-19): the reader walks oldest-first and the exit branch is + // fire-once, so a naive replay hands over the FIRST match. With the downtime-sized + // lookback the window routinely holds the intermediate DeviceSetup→AccountSetup exit + // AND the final one — and the first match is the wrong edge, with the right one + // swallowed by the fire-once guard. + // ------------------------------------------------------------------------------ + + [Fact] + public void Replay_hands_over_the_newest_esp_exit_not_the_oldest() + { + using var tmp = new TempDirectory(); + using var tracker = MakeTracker(tmp, new VirtualClock(ClockNow)); + + var exits = new List(); + tracker.EspExited += (_, args) => exits.Add(args.OccurredAtUtc); + + var intermediate = ClockNow.AddMinutes(-40); // DeviceSetup → AccountSetup + var final = ClockNow.AddMinutes(-9); // AccountSetup → End (the one we need) + + tracker.ReplayBackfillRecords(new List<(int, string, DateTime)> + { + (ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExitDescription, intermediate), + (ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExitDescription, final), + }); + + var raised = Assert.Single(exits); + Assert.Equal(final, raised); + } + + [Fact] + public void Replay_keeps_chronological_order_for_non_exit_records() + { + // Only the exit branch is newest-wins; the Hello-wizard rail and ESP failures must + // keep replaying exactly as before, oldest-first. + using var tmp = new TempDirectory(); + using var tracker = MakeTracker(tmp, new VirtualClock(ClockNow)); + + var order = new List(); + tracker.HelloWizardStarted += (_, args) => order.Add($"wizard:{args.OccurredAtUtc:HH:mm}"); + tracker.EspExited += (_, args) => order.Add($"exit:{args.OccurredAtUtc:HH:mm}"); + + const string aadHello = "CloudExperienceHost web app activity started. CXID: 'AADHello'."; + tracker.ReplayBackfillRecords(new List<(int, string, DateTime)> + { + (ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExitDescription, ClockNow.AddMinutes(-40)), + (ShellCoreTracker.EventId_ShellCore_WebAppStarted, aadHello, ClockNow.AddMinutes(-20)), + (ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExitDescription, ClockNow.AddMinutes(-9)), + }); + + // Wizard replays at its own position; the exit fires once, for the newest record. + Assert.Equal(new[] { "wizard:" + ClockNow.AddMinutes(-20).ToString("HH:mm"), + "exit:" + ClockNow.AddMinutes(-9).ToString("HH:mm") }, order); + } + + [Fact] + public void Replay_of_a_single_exit_is_unchanged() + { + using var tmp = new TempDirectory(); + using var tracker = MakeTracker(tmp, new VirtualClock(ClockNow)); + + var exits = new List(); + tracker.EspExited += (_, args) => exits.Add(args.OccurredAtUtc); + + var only = ClockNow.AddMinutes(-11); + tracker.ReplayBackfillRecords(new List<(int, string, DateTime)> + { + (ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExitDescription, only), + }); + + Assert.Equal(only, Assert.Single(exits)); + } + + [Fact] + public void Replay_of_an_empty_batch_is_a_no_op() + { + using var tmp = new TempDirectory(); + using var tracker = MakeTracker(tmp, new VirtualClock(ClockNow)); + + var exits = 0; + tracker.EspExited += (_, __) => exits++; + + tracker.ReplayBackfillRecords(new List<(int, string, DateTime)>()); + + Assert.Equal(0, exits); + } + [Theory] [InlineData(0, 1)] [InlineData(-42, 1)] diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/DefaultComponentFactoryOrderingTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/DefaultComponentFactoryOrderingTests.cs index 8ae349a6..71309cc6 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/DefaultComponentFactoryOrderingTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/DefaultComponentFactoryOrderingTests.cs @@ -118,6 +118,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration hosts, "AadJoinHost wires its onRealUserJoined callback to the already-constructed DesktopArrivalHost."); + // Codex review P2 (2026-08-19): EspAndHelloHost.Start() replays the Shell-Core + // ESP exit, but ImeLogTracker only restores its persisted app states in its own + // Start() — which happens later. Pin the order that makes ImeLogHost's + // onStateRestored nudge necessary, so a future reshuffle either keeps the nudge + // meaningful or fails here loudly. + AssertBefore( + hosts, + "the ESP-exit replay runs before the IME app-state restore, which is why " + + "ImeLogHost re-triggers the user-apps-settled synthesis after LoadState."); + // Closure-latch sanity (factory lines ~139/297): the EspAndHelloHost probes close // over the ImeLogHost reference, which is assigned during the same factory call — // the host must therefore exist in the returned list. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/ImeLogHostStateRestoredCallbackTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/ImeLogHostStateRestoredCallbackTests.cs new file mode 100644 index 00000000..f825c538 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/ImeLogHostStateRestoredCallbackTests.cs @@ -0,0 +1,72 @@ +#nullable enable +using System; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration +{ + /// + /// Codex review P2 (2026-08-19) — starts AFTER EspAndHelloHost, + /// and ImeLogTracker.Start() restores the persisted package states silently (LoadState + /// raises no OnAppStateChanged). On an agent restart the Shell-Core ESP-exit replay + /// therefore runs against an empty app list. Without the post-restore nudge the exact reboot + /// case the completion recovery exists for — apps already terminal BEFORE the reboot, only the + /// final exit lost to the downtime — would still never complete. + /// + public sealed class ImeLogHostStateRestoredCallbackTests : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + + public void Dispose() => _tmp.Dispose(); + + private ImeLogHost CreateHost(Action? onStateRestored) + => new ImeLogHost( + sessionId: "s", + tenantId: "t", + logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info), + ingress: new FakeSignalIngressSink(), + clock: new VirtualClock(new DateTime(2026, 8, 19, 8, 43, 16, DateTimeKind.Utc)), + imeLogPathOverride: _tmp.Path, + imeMatchLogPath: null, + imePatterns: null, + stateDirectory: _tmp.Path, + whiteGloveSealingPatternIds: null, + onStateRestored: onStateRestored); + + [Fact] + public void Start_invokes_the_state_restored_callback_exactly_once() + { + var calls = 0; + using var host = CreateHost(() => calls++); + + host.Start(); + try { Assert.Equal(1, calls); } + finally { host.Stop(); } + } + + [Fact] + public void A_throwing_callback_does_not_break_host_start() + { + // Fail-soft like every other co-wired callback in the orchestration layer: a broken + // re-check must never take the IME log host — the session's primary signal source — + // down with it. + using var host = CreateHost(() => throw new InvalidOperationException("recheck boom")); + + var ex = Record.Exception(() => host.Start()); + try { Assert.Null(ex); } + finally { host.Stop(); } + } + + [Fact] + public void No_callback_is_a_valid_configuration() + { + using var host = CreateHost(null); + + var ex = Record.Exception(() => host.Start()); + try { Assert.Null(ex); } + finally { host.Stop(); } + } + } +} 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 1d3261a1..b938ae70 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 @@ -52,11 +52,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // guard concurrently (Shell-Core watcher thread + IME log thread). private int _userAppsSettledSynthesisFired; - // sits-d Cloud-PC fix (2026-08-19) — set once a Shell-Core normal ESP exit has been - // observed (live OR backfill). The synthesis needs two facts: the ESP exit is an EDGE - // that happens once, the settled user-ESP apps are a LEVEL that may only be reached - // minutes later. Recording the edge lets ReevaluateUserAppsSettledSynthesis re-check - // the level afterwards instead of losing the completion for the rest of the session. + // sits-d Cloud-PC fix (2026-08-19) — set once a CONFIRMED post-AccountSetup Shell-Core + // exit has been observed (live OR backfill). The synthesis needs two facts: the ESP exit + // is an EDGE that happens once, the settled user-ESP apps are a LEVEL that may only be + // reached minutes later. Recording the edge lets ReevaluateUserAppsSettledSynthesis + // re-check the level afterwards instead of losing the completion for the rest of the + // session. + // + // Codex review P1 (2026-08-19): "confirmed" is load-bearing. Shell-Core raises 62407 at + // EVERY ESP phase transition, DeviceSetup→AccountSetup included. Remembering that + // intermediate exit would let the deferred re-check open the strong AccountSetup gate the + // moment the last user app settles — while the AccountSetup page is still up and its other + // subcategories are still running. See IsConfirmedPostAccountSetupExit. private volatile bool _espExitObserved; // Liveness plan PR3 — one-shot-per-appId dedupe for app_install_starved emissions. @@ -578,6 +585,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals return skipUser == false; } + /// + /// Codex review P1 (2026-08-19) — may THIS esp_exiting be remembered as the edge the + /// deferred user-apps-settled re-check builds on? + /// + /// Deliberately STRICTER than !IsIntermediateDeviceEspExit(): that helper forwards + /// on an unknown SkipUser (forwarding a signal early is cheap), whereas remembering the + /// wrong edge here can open a completion gate minutes later with no second chance to take + /// it back. So this one demands positive evidence and treats "unknown" as "not confirmed": + /// + /// + /// the provisioning tracker has seen AccountSetup activity — the page that just + /// tore down is demonstrably the AccountSetup one; or + /// SkipUser is explicitly true — the profile has no user ESP at all, so the + /// Device-ESP exit IS the final one and no second exit is coming. + /// + /// + /// Erring strict costs at worst today's behaviour (the session stalls as it did before the + /// fix); erring loose costs a premature Succeeded, which is unrecoverable. + /// + /// + private bool IsConfirmedPostAccountSetupExit() + { + bool accountSetupSeen; + try { accountSetupSeen = _accountSetupActivityProbe(); } + catch (Exception ex) + { + _logger.Debug($"EspAndHelloTracker: account-setup-activity probe threw: {ex.Message}"); + accountSetupSeen = false; + } + if (accountSetupSeen) return true; + + return GetSkipUserEspCached() == true; + } + private bool? GetSkipUserEspCached() { lock (_skipConfigLock) @@ -718,8 +759,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals catch (Exception ex) { _logger.Error("Error forwarding EspExited", ex); } // Record the edge BEFORE the synthesis attempt so a later app-state change can - // re-run it even when the apps are not settled yet at this instant. - _espExitObserved = true; + // re-run it even when the apps are not settled yet at this instant — but ONLY for + // an exit we can positively place after AccountSetup. The immediate attempt below + // is deliberately left ungated: it keeps its pre-existing behaviour exactly. + if (IsConfirmedPostAccountSetupExit()) + _espExitObserved = true; // Session caa6cf50 gate-starvation fix: a Shell-Core normal exit while IME's // user-ESP app tracking is fully settled is alternative evidence that diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs index 0a0a0b94..a95050d7 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs @@ -391,6 +391,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals PathType.LogName, $"*[System[(EventID=62404 or EventID=62407) and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]"); + var records = new List<(int Id, string Description, DateTime OccurredAtUtc)>(); using (var reader = new EventLogReader(query)) { for (EventRecord record = reader.ReadEvent(); record != null; record = reader.ReadEvent()) @@ -402,10 +403,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // (EspAndHelloTrackerAdapter) can stamp signals with the source time // rather than collapsing to wall-clock-now. var timestamp = (record.TimeCreated ?? DateTime.UtcNow).ToUniversalTime(); - HandleBackfillRecord(record.Id, description, timestamp); + records.Add((record.Id, description, timestamp)); } } } + + ReplayBackfillRecords(records); } catch (Exception ex) { @@ -413,6 +416,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals } } + /// + /// Codex review P1 (2026-08-19) — replays a chronological batch of Shell-Core records. + /// + /// The reader walks oldest-first and the ESP-exit branch is fire-once, so a naive + /// record-by-record replay hands the FIRST match downstream. With the downtime-sized + /// lookback the window routinely holds both the intermediate DeviceSetup→AccountSetup exit + /// and the final post-AccountSetup one — and the first match is the intermediate one, i.e. + /// exactly the wrong edge, with the right one swallowed by the fire-once guard. + /// + /// + /// So: everything is replayed in chronological order (ESP failures and the Hello-wizard + /// rail keep their existing semantics verbatim), but only the NEWEST exit-matching record + /// is allowed through the exit branch. Internal for direct testing without an event log. + /// + /// + internal void ReplayBackfillRecords( + IReadOnlyList<(int Id, string Description, DateTime OccurredAtUtc)> records) + { + if (records == null || records.Count == 0) return; + + var lastExitIndex = -1; + for (var i = 0; i < records.Count; i++) + { + if (EspExitingPattern.IsMatch(records[i].Description ?? "")) + lastExitIndex = i; + } + + for (var i = 0; i < records.Count; i++) + { + var record = records[i]; + HandleBackfillRecord( + record.Id, + record.Description ?? "", + record.OccurredAtUtc, + allowEspExit: i == lastExitIndex); + } + } + /// /// Internal backfill record handler — extracted for testability and to keep the /// backfill loop free of direct event-processing logic. The @@ -420,7 +461,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals /// (record.TimeCreated); subscribers read it via /// during their synchronous event handler. /// - internal void HandleBackfillRecord(int eventId, string description, DateTime occurredAtUtc) + internal void HandleBackfillRecord( + int eventId, string description, DateTime occurredAtUtc, bool allowEspExit = true) { if (eventId == EventId_ShellCore_WebAppStarted) { @@ -452,7 +494,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals return; } - if (EspExitingPattern.IsMatch(description)) + if (allowEspExit && EspExitingPattern.IsMatch(description)) { bool shouldNotify = false; lock (_stateLock) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index a7b39ec5..243ca511 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -339,7 +339,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration stateDirectory: _stateDirectory, whiteGloveSealingPatternIds: whiteGloveSealingPatternIds, simulationMode: simulationMode, - simulationSpeedFactor: _agentConfig.ReplaySpeedFactor); + simulationSpeedFactor: _agentConfig.ReplaySpeedFactor, + // Codex review P2 (2026-08-19): the IME tracker restores its persisted app states + // inside Start(), silently (LoadState raises no OnAppStateChanged). This host starts + // AFTER EspAndHelloHost, so the Shell-Core ESP-exit replay has already run against + // an empty app list. Nudge the synthesis once the restored level is in place — + // otherwise the exact reboot case (apps terminal BEFORE the reboot, only the final + // exit lost to the downtime) still never completes. + onStateRestored: () => espAndHelloHost.ReevaluateUserAppsSettledSynthesis()); hosts.Add(imeLogHost); imeLogHostRef = imeLogHost; 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 d4889554..43882016 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/ImeLogHost.cs @@ -18,6 +18,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly ImeLogTracker _tracker; private readonly ImeProcessWatcher _processWatcher; + private readonly Action? _onStateRestored; private readonly ImeLogTrackerAdapter _adapter; private readonly AgentLogger _logger; private int _disposed; @@ -96,9 +97,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration string stateDirectory, IReadOnlyCollection? whiteGloveSealingPatternIds, bool simulationMode = false, - double simulationSpeedFactor = 50) + double simulationSpeedFactor = 50, + Action? onStateRestored = null) { _logger = logger; + _onStateRestored = onStateRestored; var logFolder = string.IsNullOrEmpty(imeLogPathOverride) ? DefaultImeLogFolder : imeLogPathOverride!; var expandedMatchLogPath = string.IsNullOrEmpty(imeMatchLogPath) ? null @@ -128,10 +131,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration _processWatcher = new ImeProcessWatcher(sessionId, tenantId, processWatcherPost, logger); } + /// + /// Codex review P2 (2026-08-19) — restores the persisted + /// package states (LoadState) and does NOT raise OnAppStateChanged for them. This + /// host is started AFTER EspAndHelloHost, so on an agent restart the Shell-Core + /// ESP-exit replay runs against an empty app list and synthesises nothing — and without a + /// nudge here nothing would ever re-check, which is precisely the reboot case the + /// completion recovery exists for (apps already terminal before the reboot, only the final + /// exit lost to the downtime). fires once, after the + /// restore, so the deferred synthesis gets its look at the restored level. + /// public void Start() { _tracker.Start(); _processWatcher.Start(); + + try { _onStateRestored?.Invoke(); } + catch (Exception ex) { _logger.Warning($"ImeLogHost: onStateRestored callback threw: {ex.Message}"); } } public void Stop()