diff --git a/docs/agent/decision-engine.md b/docs/agent/decision-engine.md index 1eb3b854..20b0664d 100644 --- a/docs/agent/decision-engine.md +++ b/docs/agent/decision-engine.md @@ -128,6 +128,15 @@ user-ESP Install-intent apps are still pending (IME logs "Completed user session *pass*, not once per session — sessions 14690fc2/6cb01530). The reducer stays free of app-pending guards; adapters sanitize evidence before it becomes a signal. +**Zero user-targeted apps** (sessions 81daa77f/75d6ae8e): IME never writes its +"Completed user session" line at all when the user has no assigned apps — its zero-app +branch returns first — so fact 3 was unreachable by construction and every such device +fell through to the backstop. `IME-USER-SESSION-ZERO-APPS` reads the line IME *does* +write there and posts the same signal, guarded to the AccountSetup phase. The event +carries an `evidence` field (`zero_user_apps_enumerated` vs `user_session_completed`) +naming which observation carried the completion. See +[zero-user-apps-completion-gate.md](zero-user-apps-completion-gate.md). + ## Completion attempt sites and sequence Completion can be attempted from whichever fact arrives last: `HelloResolved`, @@ -166,6 +175,11 @@ advisory backstop. All routes converge on `CompleteThroughFinalizingOrDefer`: scheduler contract) dead-ends as `realmjoin_timeout_stale_superseded_by_rearm`. The idle case (detected, no deployment activity ever) times out at 60 min unchanged, and phase 200/210 activity never extends. + A closed gate also outranks the 30-minute `AdvisoryCompletion` backstop: that + handler re-arms (trigger suffix `:CompletionGateHolding`) instead of failing while + the RealmJoin gate is closed *and* its own deadline is still armed, because the gate + carries a bounded resolution of its own. Before this, the shorter timer always won — + session 75d6ae8e was failed 2 min after its 25th successful RealmJoin package. 2. `Finalizing` stage + ~5 s `FinalizingGrace` deadline. 3. Grace fires → `Completed`, `EnrollmentComplete` outcome, `enrollment_complete` timeline event with full audit payload. diff --git a/docs/agent/index.md b/docs/agent/index.md index 3049af2c..01fa8534 100644 --- a/docs/agent/index.md +++ b/docs/agent/index.md @@ -7,6 +7,7 @@ How the on-device agent works: * [Logs, Persistence & Crash Recovery](logs-and-persistence.md) - every persisted file and why it exists; signal log vs spool; snapshot/journal; the replay-based recovery flow and quarantine. * [Diagnostics Package](diagnostics-package.md) - what the diagnostics ZIP contains: the built-in section catalog shared with the portal (Shared `DiagnosticsBuiltInSections`, served by GET diagnostics/paths), the RealmJoin Watcher and Device Preparation collection gates, why built-ins bypass the configured-path guards, global ∪ tenant path dedup, caps and the package manifest. * [Hello Wizard Un-Skip](hello-wizard-unskip.md) - why a single "WHfB disabled" policy read never decides completion: the HelloWizardStarted signal (prevention + cure) and the HelloTracker confirmation second read. +* [Zero User-Targeted Apps](zero-user-apps-completion-gate.md) - why a user with no targeted Intune apps starved every user-phase completion path (IME never writes its "Completed user session" line in the zero-app branch), and why a completion gate that is still holding the session must outrank the 30-minute backstop. * [Autopilot ZTD Diagnostics](autopilot-ztd-diagnostics.md) - Windows' own diagnostic surfaces for the profile-download flow: ModernDeployment event IDs (807/815/164/...), the Diagnostics\Autopilot registry key, deployment-service endpoints, and the known-issue error-code map. * [MDM Reboot Coalescing](mdm-reboot-coalescing.md) - attributing the mid-ESP coalesced reboot ("second sign-in") to the device-assigned policy URIs that forced it: aggregated 2800 observations (neutral, flush-time watermark) + ANALYZE-ESP-005 gated on an actually-observed reboot. * [Power-State Watcher](power-state-watcher.md) - live AC↔battery transitions and 50/30/15% downward threshold crossings via a WMI push subscription (no polling): power_state_change semantics (latch/debounce/cap, never armed without a battery) and the single-condition analyze rules ANALYZE-DEV-009/-010 on top. diff --git a/docs/agent/zero-user-apps-completion-gate.md b/docs/agent/zero-user-apps-completion-gate.md new file mode 100644 index 00000000..4a33b1c4 --- /dev/null +++ b/docs/agent/zero-user-apps-completion-gate.md @@ -0,0 +1,136 @@ +--- +type: Concept +title: Zero User-Targeted Apps — the starved user-phase completion gate +description: Why a device with no user-targeted Intune apps could never satisfy the IME user-session gate, how that turned into a 30-minute esp_exit_without_completion_evidence false positive on a third of one tenant's enrollments, and the two fixes — reading the line IME actually writes in its zero-app branch, and refusing to fail a session while a completion gate is deliberately holding it. +resource: /src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime +tags: + - agent + - ime + - esp + - completion + - realmjoin + - false-positive +timestamp: 2026-08-25 +--- + +# Summary + +A Classic user-driven enrollment whose user has **zero targeted Intune Win32 apps** could not +produce the evidence every user-phase completion path required. The session parked, and the +30-minute `advisory_completion` backstop resolved it as +`enrollment_failed: esp_exit_without_completion_evidence` — while the user was at a working +desktop, Windows Hello was provisioned, and RealmJoin was still installing packages. + +One tenant hit this on **10 of 30 enrollments in a week**. Every one of them was a false +positive; the devices were healthy in Intune and RealmJoin. + +# The starvation chain + +The IME writes `Completed user session N, userId: …` at the end of a user-session processing +pass. `IME-USER-SESSION-COMPLETED` matches it and the adapter posts +`ImeUserSessionCompleted`, which sets `DecisionState.ImeUserSessionCompletedUtc`. + +But the IME never reaches that statement when the user has no assigned apps. Decompiled IME +`1.104.102.0`, `Win32AppPlugIn/ApplicationPoller.cs`: + +```csharp +if (!appPolicies.Any()) +{ + AppWorkloadLog.TraceInformation($"[Win32App] Get 0 apps for user session {user.RDSSessionId}, user id = {user.IntuneId}"); + RegisterApplicationsInIfInESP(sender, user, delegate { + espLockInProcessor.AttemptToLockInApplications(user, new List()); + }); + continue; // skips the "Completed user session" statement below +} +``` + +Identical shape in `1.97.107.0`, `1.83.107.0`, `1.80.132.0`. With that fact missing, every door +out of the user phase is shut at once: + +| Path | Requirement | Why it is dead | +|---|---|---| +| `ShouldTransitionToAwaitingHello` arm A | `AccountSetupProvisioningSucceededUtc` | ESP registry froze at `AccountSetup: 1 of 5`; neither `categorySucceeded` nor the all-subcategories fallback can ever hold | +| arm B | `SkipUserEsp` | Full ESP, not a skip-user flow | +| arm C | `IsImeUserSessionGenuine` | needs the missing IME fact | +| arm D | `EnrollmentMode.DevicePreparation` | Autopilot v1, not WDP | +| `MaybeSynthesizeAccountSetupCompleteFromSettledUserApps` | `AreUserEspAppsSettled` | returned `false` on an empty app list | +| `HandleAdvisoryCompletionDeadlineFired` conjunction | `imeUserSessionGenuine \|\| isObservationAdvisory` | both false | + +The last row is the one that produced the verdict: the backstop that exists to resolve a +dead-end resolved it as a failure. + +`AreUserEspAppsSettled` deserves its own note. Its "at least one required app" rule is +deliberately conservative — an empty list normally means *the phase just cleared* or *apps have +not surfaced yet*. But it made **zero apps**, the most settled state possible, indistinguishable +from *unknown*, and there was no evidence available to tell them apart. + +# Fix 1 — read the line IME does write + +`IME-USER-SESSION-ZERO-APPS` matches the zero-app line and routes it through the **same** +`OnUserSessionCompleted` callback. Downstream this genuinely *is* a completed user session, so +the adapter's pending-apps deferral and its fire-once flag apply unchanged. + +This is not a weakened gate — it is IME's own verdict. The zero-app branch locks the ESP in with +an *empty* application list, and the sibling emit site in `AppWorkloadAbstraction.ExecuteUserCheckIn` +returns `ProviderResult.ProvisioningComplete` straight after logging it. All three emit sites are +user-session-scoped (`user.RDSSessionId`, `user.IntuneId`); none is device-scoped. + +Guards that stay in force: + +* **Phase guard** — the observation only fires while the tracker is in `AccountSetup`. Firing + earlier would burn the adapter's fire-once flag on a pre-sign-in (defaultuser0) timestamp that + `IsImeUserSessionGenuine` (`>= AccountSetupEnteredUtc`) can never accept. An observation made + before the phase was known is remembered and replayed on the transition into it, because IME + writes its check-in lines independently of when the agent first parses the phase marker. +* **Engine guards unchanged** — arm C still requires a post-AccountSetup final ESP exit *and* a + DAD-validated real-user desktop. +* `AreUserEspAppsSettled` returns `true` for an empty list **only** with this explicit + observation — never for a merely empty list. + +# Fix 2 — do not fail while a completion gate is holding + +An independent defect, and the decisive one for the affected tenant. `advisory_completion` runs +for 30 minutes. The RealmJoin completion gate blocks completion until phase 110 and carries its +*own* bounded resolution: 60 minutes from detection, re-armed on deployment activity, hard-capped +at 4 hours. The shorter timer always won. + +Session `75d6ae8e` installed **25 RealmJoin packages successfully inside the window**, the last +one 2 minutes before the failure, while the engine's own `completion_waiting` still read +`waiting on: realmjoin_resolution`. + +`HandleAdvisoryCompletionDeadlineFired` now re-arms instead of failing when the RealmJoin gate is +closed *and* its deadline is still armed, emitting `completion_waiting` with trigger +`DeadlineFired:advisory_completion:CompletionGateHolding`. + +Convergence comes from the gate itself: `Resolved`, `FirstDeploymentIncomplete` and `Timeout` all +set `RealmJoinFacts.Outcome`, which opens `RealmJoinGateOpen` and stops the guard applying. +Requiring the gate's deadline to still be armed keeps a gate that can no longer resolve itself +from parking the session; `AgentMaxLifetimeMinutes` bounds it regardless. + +# Timeline evidence + +`ime_user_session_completed` carries an `evidence` field so the basis of the verdict is legible +without the diagnostics archive: + +* `user_session_completed` — IME wrote its completion line and no required app was pending. +* `zero_user_apps_enumerated` — IME reported zero targeted apps; the user phase had nothing to + enforce. + +No new event type: the fact is the same, only the observation behind it differs. + +# Deployment + +The pattern ships through the config API and reaches existing agents without a rebuild; an agent +that does not know the `userSessionZeroApps` action logs one Debug line and ignores it. The +*behaviour* needs an agent release. Sessions already stamped `Failed` are not reclassified — the +backend mirrors the agent verdict (`VerdictPaths.AgentFailed`) and has no independent judgement +here by design. + +# Citations + +* `rules/ime-log-patterns/IME-USER-SESSION-ZERO-APPS.json` +* `src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs` — `HandleUserSessionZeroApps`, the phase replay in `HandleEspPhaseDetected` +* `src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs` — `AreUserEspAppsSettled` +* `src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs` — `EmitUserSessionCompleted`, evidence labels +* `src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Edge.cs` — `HandleAdvisoryCompletionDeadlineFired` +* [decision-engine.md](decision-engine.md), [post-reboot-completion-recovery.md](post-reboot-completion-recovery.md) diff --git a/docs/index.md b/docs/index.md index 1c140072..b1f21422 100644 --- a/docs/index.md +++ b/docs/index.md @@ -25,6 +25,7 @@ https://docs.autopilotmonitor.com (separate repository). * [Gather Rule Debug Log](agent/gather-rule-debug-log.md) - EnableGatherRuleDebugLog (ConfigVersion 36): the per-tenant local trace file that explains every gather-rule evaluation decision — scope skips, on_change suppression, empty collector results, logparser position/parse-mode outcomes — for rules that produce no timeline events. * [MDM Reboot Coalescing](agent/mdm-reboot-coalescing.md) - Attributing the mid-ESP coalesced reboot ("second sign-in") to the device-assigned policy URIs that forced it: aggregated DM-Enterprise 2800 observations (neutral, flush-time watermark) + the ANALYZE-ESP-005 advisory gated on an actually-observed reboot. * [ESP Completion Starvation — the sits-d Cloud-PC complex](agent/post-reboot-completion-recovery.md) - Why a SkipUser=true flow (no user ESP page → no Shell-Core 62407, no AccountSetup registry) left the completion gate satisfied but never evaluated — five Cloud PCs idled six hours at "waiting on: hello_resolution" — and the fix: the observed skip stands in for the final-exit evidence in the IME user-session completion attempt. Plus the two adjacent defects fixed alongside: the edge-only user-apps-settled synthesis (now level-triggered) and the never-wired Shell-Core restart replay (now Hello-wizard-only, with the reasoning why a replayed 62407 must never reach the reducer). +* [Zero User-Targeted Apps — the starved user-phase completion gate](agent/zero-user-apps-completion-gate.md) - Why a device with no user-targeted Intune apps could never satisfy the IME user-session gate — IME skips its "Completed user session" line entirely in the zero-app branch — turning the 30-minute completion backstop into `esp_exit_without_completion_evidence` on a third of one tenant's enrollments, with the user at the desktop and RealmJoin still installing. The two fixes: read the line IME does write (IME-USER-SESSION-ZERO-APPS), and never fail a session while a completion gate with its own armed deadline is deliberately holding it. * [Secure Boot CA-2023 Detection](agent/secureboot-ca2023-detection.md) - Why ANALYZE-SEC-001 v3 reads the UEFI db/KEK variables directly instead of trusting the SecureBoot\Servicing registry, and how the one-sided uefiCa2023FirmwareConfirmed marker plus a not_exists precondition give absence-tolerant suppression across old and new agents. * [Continue-Anyway Observation Mode](agent/continue-anyway-observation.md) - EnableEspContinueAnywayObservation (ConfigVersion 37, operator-set): Device-phase ESP terminal failures on Continue-Anyway profiles get a bounded 60-min observation instead of an immediate hard fail; the DAD-validated real-user desktop + Hello gate detect the true end, the session completes Succeeded + EspSoftFailure (amber "with issues" badge), expiry un-defangs to the original esp_terminal_failure. * [CMTrace Time Resolution](agent/cmtrace-time-resolution.md) - Converting bias-less CMTrace local times to UTC without trusting any process's timezone belief: per-line self-anchoring on the 15-minute offset grid for provably fresh lines, uniform marked reader-zone fallback for backlog, and the provenance vocabulary (bias / line-anchored / reader-zone-fallback) that keeps every event re-derivable. diff --git a/docs/log.md b/docs/log.md index 9963383a..c2db8b8d 100644 --- a/docs/log.md +++ b/docs/log.md @@ -1,5 +1,9 @@ # Log +## 2026-08-25 + +* **New**: `agent/zero-user-apps-completion-gate.md` — a Classic enrollment whose user has zero targeted Intune Win32 apps could not produce the evidence any user-phase completion path required: IME's zero-app branch (`ApplicationPoller`, verified against decompiled 1.104.102.0 and three older builds) `continue`s before its `Completed user session` statement, so `ImeUserSessionCompletedUtc` stayed null, all four arms of `ShouldTransitionToAwaitingHello` were dead, and the 30-min `advisory_completion` backstop resolved the session as `esp_exit_without_completion_evidence` — with a DAD-validated desktop, Hello provisioned and RealmJoin still installing. One tenant: 10 of 30 enrollments in a week, all false positives. Two fixes. (1) New pattern `IME-USER-SESSION-ZERO-APPS` reads the line IME *does* write and routes it through the same `OnUserSessionCompleted` callback, guarded to the AccountSetup phase and replayed if the observation predates the phase marker; `AreUserEspAppsSettled` now accepts an empty app list only with that explicit observation. (2) `HandleAdvisoryCompletionDeadlineFired` re-arms instead of failing while the RealmJoin gate is closed and its own deadline is still armed — session 75d6ae8e installed 25 RealmJoin packages inside the window, the last 2 min before the failure. `ime_user_session_completed` gains an `evidence` field (`zero_user_apps_enumerated` / `user_session_completed`); no new event type. The pattern reaches existing agents via the config API (an unknown action is a Debug line), the behaviour needs an agent release. + ## 2026-08-24 * **Change**: `DeviceAssociationValidator` / `SecurityValidator` — the DevPrep association shadow now logs one line per real Graph lookup instead of one per request (`DeviceAssociationResult.ServedFromCache`, `AsCacheHit()` copies rather than marking the shared cached instance), the same gate the cert-device-binding shadow uses. Measured: one enrollment produced 263 identical lines off a handful of calls. Status of that preview, for the record: the `/beta/deviceManagement/tenantAssociatedDevices` endpoint answers (6 calls, all HTTP 200, `transient=False`), but every result so far is `matched=False` from a single Autopilot **v1** device — which is the correct answer for a device that was never part of a Device Preparation policy. The matching itself is therefore still unproven, and the endpoint remains undocumented in both v1.0 and beta Graph reference, so it is not a basis for enforcement. diff --git a/rules/dist/ime-log-patterns.json b/rules/dist/ime-log-patterns.json index c2253f65..eca8c654 100644 --- a/rules/dist/ime-log-patterns.json +++ b/rules/dist/ime-log-patterns.json @@ -675,6 +675,14 @@ "description": "Detects when IME completes a user session, indicating enrollment has finished for that user.", "enabled": true }, + { + "patternId": "IME-USER-SESSION-ZERO-APPS", + "category": "always", + "pattern": "\\[Win32App\\] Get 0 apps for user session (?\\d+), user id = (?[a-f0-9\\-]+)", + "action": "userSessionZeroApps", + "description": "Detects when IME enumerated a user session and found zero targeted Win32 apps. IME then skips its 'Completed user session' line entirely (the zero-app branch in ApplicationPoller continues before that log statement), so this line is the only evidence that user-phase enforcement finished on a device with no user-targeted apps. Treated as equivalent to a completed user session.", + "enabled": true + }, { "patternId": "IME-WIN32-STATE-1", "category": "currentPhase", diff --git a/rules/ime-log-patterns/IME-USER-SESSION-ZERO-APPS.json b/rules/ime-log-patterns/IME-USER-SESSION-ZERO-APPS.json new file mode 100644 index 00000000..e3dafd3c --- /dev/null +++ b/rules/ime-log-patterns/IME-USER-SESSION-ZERO-APPS.json @@ -0,0 +1,9 @@ +{ + "$schema": "../schema/ime-log-pattern.schema.json", + "patternId": "IME-USER-SESSION-ZERO-APPS", + "category": "always", + "pattern": "\\[Win32App\\] Get 0 apps for user session (?\\d+), user id = (?[a-f0-9\\-]+)", + "action": "userSessionZeroApps", + "description": "Detects when IME enumerated a user session and found zero targeted Win32 apps. IME then skips its 'Completed user session' line entirely (the zero-app branch in ApplicationPoller continues before that log statement), so this line is the only evidence that user-phase enforcement finished on a device with no user-targeted apps. Treated as equivalent to a completed user session.", + "enabled": true +} diff --git a/rules/schema/ime-log-pattern.schema.json b/rules/schema/ime-log-pattern.schema.json index 41494941..4e555e1f 100644 --- a/rules/schema/ime-log-pattern.schema.json +++ b/rules/schema/ime-log-pattern.schema.json @@ -63,6 +63,7 @@ "imeImpersonation", "imeTokenFailure", "enrollmentCompleted", + "userSessionZeroApps", "updateDoTelemetry", "scriptStarted", "scriptContext", diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerZeroUserAppsTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerZeroUserAppsTests.cs new file mode 100644 index 00000000..40d180cd --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerZeroUserAppsTests.cs @@ -0,0 +1,199 @@ +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 +{ + /// + /// Sessions 81daa77f / 75d6ae8e (2026-08-25) — zero user-targeted apps starved every + /// user-phase completion probe. The IME zero-app branch returns before it writes the + /// "Completed user session" line, so a device whose user has no targeted Win32 apps never + /// produced the evidence IsImeUserSessionGenuine requires, and the AdvisoryCompletion + /// window failed the enrollment 30 minutes later — with the user at the desktop, Hello + /// provisioned and RealmJoin still installing. + /// + /// IME-USER-SESSION-ZERO-APPS reads the line IME does write in that branch and routes it + /// through the same callback. + /// + /// + public sealed class ImeLogTrackerZeroUserAppsTests + { + // Mirrors rules/ime-log-patterns/IME-USER-SESSION-ZERO-APPS.json. The JSON itself is + // pinned against a real IME line by BuiltInRulesTests in the backend suite. + private const string ZeroAppsPattern = + @"\[Win32App\] Get 0 apps for user session (?\d+), user id = (?[a-f0-9\-]+)"; + + private const string EspPhasePattern = + @"\[Win32App\] (?:In|The) EspPhase: (?\w+)"; + + private const string ZeroAppsLine = + "[Win32App] Get 0 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"; + + private static ImeLogTracker BuildTracker(TempDirectory tmp) => + new ImeLogTracker( + logFolder: tmp.Path, + patterns: new List + { + new ImeLogPattern + { + PatternId = "IME-USER-SESSION-ZERO-APPS", + Category = "always", + Pattern = ZeroAppsPattern, + Action = "userSessionZeroApps", + }, + new ImeLogPattern + { + PatternId = "IME-ESP-PHASE", + Category = "always", + Pattern = EspPhasePattern, + Action = "espPhaseDetected", + }, + }, + logger: new AgentLogger(tmp.Path, AgentLogLevel.Info)); + + [Fact] + public void ZeroApps_line_during_user_phase_fires_user_session_completed() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + var fired = 0; + tracker.OnUserSessionCompleted = () => fired++; + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + + Assert.Equal(1, fired); + Assert.True(tracker.UserSessionZeroAppsObserved); + } + + [Fact] + public void ZeroApps_line_before_user_phase_does_not_fire() + { + // Firing here would burn the adapter fire-once flag on a pre-sign-in timestamp that + // IsImeUserSessionGenuine (>= AccountSetupEnteredUtc) can never accept. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + var fired = 0; + tracker.OnUserSessionCompleted = () => fired++; + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: DeviceSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + + Assert.Equal(0, fired); + Assert.True(tracker.UserSessionZeroAppsObserved); + } + + [Fact] + public void ZeroApps_observed_early_is_replayed_on_the_user_phase_transition() + { + // IME writes its check-in lines independently of when the agent first parses the ESP + // phase marker, so the evidence can legitimately arrive first. Dropping it would + // leave a zero-app device with no completion evidence at all. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + var fired = 0; + tracker.OnUserSessionCompleted = () => fired++; + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: DeviceSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + Assert.Equal(0, fired); + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + + Assert.Equal(1, fired); + } + + [Fact] + public void Repeated_user_phase_matches_do_not_replay_again() + { + // IME re-emits the phase string as it re-evaluates app sets. Only a real transition + // replays; the adapter fire-once flag is the outer guard, but the tracker must not + // spam the callback either. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + var fired = 0; + tracker.OnUserSessionCompleted = () => fired++; + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: DeviceSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + + Assert.Equal(1, fired); + } + + [Fact] + public void Nonzero_app_count_lines_do_not_match_the_pattern() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + var fired = 0; + tracker.OnUserSessionCompleted = () => fired++; + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + + tracker.ProcessLogMessageForTest( + "[Win32App] Get 3 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"); + tracker.ProcessLogMessageForTest( + "[Win32App] Get 10 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"); + + Assert.Equal(0, fired); + Assert.False(tracker.UserSessionZeroAppsObserved); + } + + [Fact] + public void AreUserEspAppsSettled_true_after_zero_apps_observation() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + + Assert.True(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void AreUserEspAppsSettled_stays_false_on_an_empty_list_without_the_observation() + { + // Mutation proof for the branch above: an empty live list on its own still means + // "phase just cleared / apps not surfaced yet", never vacuously settled. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void AreUserEspAppsSettled_false_outside_the_user_phase_even_after_the_observation() + { + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: DeviceSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + + Assert.True(tracker.UserSessionZeroAppsObserved); + Assert.False(tracker.AreUserEspAppsSettled()); + } + + [Fact] + public void GetPendingRequiredUserEspInstallApps_is_empty_for_a_zero_app_user_session() + { + // The adapter deferral probe must not park the signal when there is nothing to wait + // for — otherwise the zero-app path would starve exactly like the old one. + using var tmp = new TempDirectory(); + var tracker = BuildTracker(tmp); + + tracker.ProcessLogMessageForTest("[Win32App] In EspPhase: AccountSetup"); + tracker.ProcessLogMessageForTest(ZeroAppsLine); + + Assert.Empty(tracker.GetPendingRequiredUserEspInstallApps()); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterUserSessionGateTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterUserSessionGateTests.cs index c8dd2f6d..b3ae227b 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterUserSessionGateTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterUserSessionGateTests.cs @@ -163,5 +163,45 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted)); Assert.Single(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted)); } + + // ==================================================== zero-app evidence label ==== + + [Fact] + public void Zero_app_user_session_labels_the_evidence_on_signal_and_timeline() + { + // Sessions 81daa77f / 75d6ae8e: with no user-targeted apps IME never writes its + // "Completed user session" line at all, so the verdict rests on a different + // observation. Whoever reads the timeline later must be able to tell which. + using var f = new ImeLogTrackerAdapterFixture(); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + f.Tracker.SeedCurrentPhaseForTesting("AccountSetup"); + f.Tracker.SeedUserSessionZeroAppsForTesting(); + + adapter.TriggerUserSessionCompletedFromTest(); + + Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted)); + var evt = Assert.Single(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted)); + Assert.Equal( + ImeLogTrackerAdapter.EvidenceZeroUserApps, + evt.Payload!["evidence"]); + } + + [Fact] + public void Ordinary_user_session_completion_keeps_the_default_evidence_label() + { + // Mutation proof for the branch above. + using var f = new ImeLogTrackerAdapterFixture(); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + f.Tracker.SeedCurrentPhaseForTesting("AccountSetup"); + AddApp(f.Tracker, "app-done", AppIntent.Install, AppInstallationState.Installed); + + adapter.TriggerUserSessionCompletedFromTest(); + + var evt = Assert.Single(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted)); + Assert.Equal( + ImeLogTrackerAdapter.EvidenceUserSessionCompleted, + evt.Payload!["evidence"]); + } + } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index 66aac593..6d181b53 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -1042,6 +1042,56 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// internal string LastEspPhaseDetected => _lastEspPhaseDetected; + /// + /// True while the user-scope ESP phase is the tracker's current phase. Every user-phase + /// probe and the zero-apps evidence gate on this — outside AccountSetup the IME lines + /// belong to the device phase or the pre-sign-in (defaultuser0) frame. + /// + private bool IsUserEspPhaseActive => + string.Equals(_lastEspPhaseDetected, "AccountSetup", StringComparison.OrdinalIgnoreCase); + + /// + /// True once IME reported zero targeted Win32 apps for a user session while the user ESP + /// phase was active. Read by the adapter to label the evidence behind + /// ime_user_session_completed. + /// + internal bool UserSessionZeroAppsObserved => _userSessionZeroAppsObserved; + + /// + /// IME-USER-SESSION-ZERO-APPS: IME enumerated the user session and found no targeted + /// Win32 apps. Its zero-app branch then continues past the "Completed user + /// session" log statement, so this line is the only completion evidence such a device + /// ever produces — and IME itself treats the same condition as finished + /// (ProviderResult.ProvisioningComplete in the user check-in path, and an ESP + /// lock-in with an empty application list in the poller path). + /// + /// Deliberately routed through rather than a + /// separate callback: downstream this IS a completed user session, and the adapter's + /// pending-apps deferral plus its fire-once flag then apply unchanged. + /// + /// + /// Phase guard: firing before AccountSetup would burn the adapter's fire-once flag on a + /// pre-sign-in timestamp that IsImeUserSessionGenuine can never accept. The + /// observation is remembered instead and replayed by + /// on the transition into the user phase. + /// + /// + private void HandleUserSessionZeroApps() + { + _userSessionZeroAppsObserved = true; + + if (!IsUserEspPhaseActive) + { + _logger.Debug( + "ImeLogTracker: zero-app user session observed before the user ESP phase " + + $"(current phase: {_lastEspPhaseDetected ?? "(none)"}) - deferring until AccountSetup"); + return; + } + + _logger.Info("ImeLogTracker: user session enumerated with zero targeted apps - treating as user session completed"); + OnUserSessionCompleted?.Invoke(); + } + private void HandleEspPhaseDetected(string espPhaseString) { // Validate phase and get its ordinal for forward-only enforcement @@ -1120,6 +1170,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime ActivatePatterns(logPhaseIsCurrentPhase); OnEspPhaseChanged?.Invoke(espPhaseString); + + // Replay a zero-app user session observed before this phase was known. IME logs its + // check-in lines independently of when the agent first parses the ESP phase marker, + // so the evidence can legitimately arrive first; without this the only completion + // evidence a zero-app device produces would be dropped on the floor. + if (isFirstOrChangedPhase && IsUserEspPhaseActive && _userSessionZeroAppsObserved) + { + _logger.Info("ImeLogTracker: replaying zero-app user session evidence observed before the user ESP phase"); + OnUserSessionCompleted?.Invoke(); + } } private void HandleEspTrackStatus(Match match) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs index b6d87ae5..fdb57dd1 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs @@ -387,6 +387,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime OnUserSessionCompleted?.Invoke(); break; + case "usersessionzeroapps": + // IME found no targeted user apps — its zero-app branch skips the + // "Completed user session" line, so this is the equivalent evidence. + HandleUserSessionZeroApps(); + break; + case "updatestateinstalled": if (!string.IsNullOrEmpty(id)) UpdateStateWithCallback(id, AppInstallationState.Installed); 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 b1e07599..56bbb9a9 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 @@ -129,6 +129,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private CancellationTokenSource _cts; private bool _allAppsCompletedFired; + // Sticky: IME enumerated a user session and reported ZERO targeted Win32 apps + // (IME-USER-SESSION-ZERO-APPS). IME's zero-app branch returns before it writes the + // "Completed user session" line, so on a device with no user-targeted apps that line + // never appears and every user-phase completion probe would starve forever. This flag + // IS the user-phase completion evidence for that shape. Set only while the user ESP + // phase is active, or replayed on the transition into it. + private bool _userSessionZeroAppsObserved; + // State persistence: saves tracker state to disk so agent restart continues // from the exact log position without re-parsing or re-building ignore lists. private readonly ImeTrackerStatePersistence _statePersistence; @@ -341,6 +349,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime _lastEspPhaseDetected = phaseName; } + /// + /// Test-only seam: marks the zero-targeted-apps user session as observed without driving + /// the IME-USER-SESSION-ZERO-APPS pattern through a log line. The pattern-to-flag path + /// itself is covered end-to-end by ImeLogTrackerZeroUserAppsTests. + /// + internal void SeedUserSessionZeroAppsForTesting() + { + _userSessionZeroAppsObserved = true; + } + /// /// Returns a deduped union of phase-snapshotted apps plus the live /// (current phase). Live entries win on Id collision. @@ -395,11 +413,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime { try { - if (!string.Equals(_lastEspPhaseDetected, "AccountSetup", StringComparison.OrdinalIgnoreCase)) + if (!IsUserEspPhaseActive) return false; var apps = new List(_packageStates); - if (apps.Count == 0) return false; + + // Zero user-targeted apps is the MOST settled state there is, but the + // conservative "at least one required app" rule below reads it as "not + // settled" and starves the AccountSetup synthesis. Only an explicit IME + // observation lifts that — never a merely empty list, which also means + // "phase just cleared" or "apps not surfaced yet". + if (apps.Count == 0) + return _userSessionZeroAppsObserved; var sawRequired = false; foreach (var pkg in apps) @@ -746,6 +771,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime _currentPhaseOrder = state.CurrentPhaseOrder; _lastEspPhaseDetected = state.LastEspPhaseDetected; _allAppsCompletedFired = state.AllAppsCompletedFired; + _userSessionZeroAppsObserved = state.UserSessionZeroAppsObserved; _logPhaseIsCurrentPhase = state.LogPhaseIsCurrentPhase; // Restore seen app IDs @@ -861,6 +887,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime CurrentPhaseOrder = _currentPhaseOrder, LastEspPhaseDetected = _lastEspPhaseDetected, AllAppsCompletedFired = _allAppsCompletedFired, + UserSessionZeroAppsObserved = _userSessionZeroAppsObserved, LogPhaseIsCurrentPhase = _logPhaseIsCurrentPhase, SeenAppIds = _seenAppIds.ToList(), IgnoreList = _packageStates.IgnoreList.ToList(), diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs index 70c6647d..08248f70 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeTrackerStatePersistence.cs @@ -109,6 +109,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime public int CurrentPhaseOrder { get; set; } public string LastEspPhaseDetected { get; set; } public bool AllAppsCompletedFired { get; set; } + + /// + /// IME reported zero targeted Win32 apps for a user session. Absent in state files + /// written before this field existed — deserializing to false there is correct: the + /// tracker simply re-observes the line on the next IME check-in. + /// + public bool UserSessionZeroAppsObserved { get; set; } public bool LogPhaseIsCurrentPhase { get; set; } public List SeenAppIds { get; set; } public List IgnoreList { get; set; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index d3e9837b..49de9df1 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -56,6 +56,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters { private const string SourceLabel = "ImeLogTracker"; + /// Timeline label: IME wrote its "Completed user session" line and no required user-scope app was pending. + internal const string EvidenceUserSessionCompleted = "user_session_completed"; + + /// Timeline label: IME reported zero targeted apps for the user session, so it never wrote a + /// "Completed user session" line at all. The user phase had nothing to enforce. + internal const string EvidenceZeroUserApps = "zero_user_apps_enumerated"; + private readonly ImeLogTracker _tracker; private readonly ISignalIngressSink _ingress; private readonly IClock _clock; @@ -591,9 +598,24 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + // Which observation carried the completion. The zero-app variant matters to whoever + // reads the timeline later: the verdict then rests on IME reporting that this user + // had no targeted apps at all, not on watching enforcement finish. + var zeroApps = _tracker.UserSessionZeroAppsObserved; + var evidenceLabel = zeroApps ? EvidenceZeroUserApps : EvidenceUserSessionCompleted; + var summary = zeroApps + ? "IME enumerated the user session with zero targeted apps" + : "IME user session completed (no required user-scope apps pending)"; + var message = zeroApps + ? "IME enumerated the user session with zero targeted apps - no user-phase enforcement to wait for" + : "IME user session completed"; + var derivationInputs = new Dictionary(StringComparer.Ordinal) { - ["detectionSource"] = "IME log pattern (UserSessionCompleted)", + ["detectionSource"] = zeroApps + ? "IME log pattern (UserSessionZeroApps)" + : "IME log pattern (UserSessionCompleted)", + ["evidence"] = evidenceLabel, }; TagDerivedTimestamp(derivationInputs, derivedFromClock, rawSourceTs); @@ -604,12 +626,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters evidence: new Evidence( kind: EvidenceKind.Derived, identifier: "ime-log-tracker-v1", - summary: "IME user session completed (no required user-scope apps pending)", + summary: summary, derivationInputs: derivationInputs)); var data = new Dictionary(StringComparer.Ordinal) { ["detectedAt"] = now.ToString("o"), + ["evidence"] = evidenceLabel, }; var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) @@ -619,12 +642,12 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters _post.Emit( eventType: SharedEventTypes.ImeUserSessionCompleted, source: SourceLabel, - message: "IME user session completed", + message: message, data: data, occurredAtUtc: now); // PR3-D4: terminal-ish lifecycle marker — INFO so it's visible at the default level. - _logger?.Info($"ImeAdapter: user session completed -> posting ImeUserSessionCompleted (patternId={patternId ?? "(none)"})"); + _logger?.Info($"ImeAdapter: user session completed ({evidenceLabel}) -> posting ImeUserSessionCompleted (patternId={patternId ?? "(none)"})"); } /// diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/AdvisoryCompletionGateHoldingTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/AdvisoryCompletionGateHoldingTests.cs new file mode 100644 index 00000000..4184877e --- /dev/null +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/AdvisoryCompletionGateHoldingTests.cs @@ -0,0 +1,242 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using AutopilotMonitor.DecisionCore.State; +using Xunit; + +namespace AutopilotMonitor.DecisionCore.Tests +{ + /// + /// Sessions 81daa77f / 75d6ae8e (2026-08-25) — the 30-min advisory_completion window + /// overran a completion gate that was deliberately holding the session. The RealmJoin gate + /// blocks completion until phase 110 and carries its own bounded resolution (60 min from + /// detection, re-armed on deployment activity, hard-capped at 4 h), so on every device whose + /// first deployment outlives 30 minutes the enrollment was failed while the engine own + /// completion_waiting still read "waiting on: realmjoin_resolution". 75d6ae8e + /// installed 25 RealmJoin packages successfully inside the window, the last one 2 min before + /// the failure; the customer tenant hit this on 10 of 30 enrollments in one week. + /// + /// The guard re-arms while the gate holds. Convergence comes from the gate itself: Resolved, + /// FirstDeploymentIncomplete and Timeout all set RealmJoinFacts.Outcome, which opens + /// RealmJoinGateOpen and stops the guard applying. + /// + /// + public sealed class AdvisoryCompletionGateHoldingTests + { + private static readonly DateTime T0 = new DateTime(2026, 8, 25, 6, 10, 0, DateTimeKind.Utc); + + private static DecisionSignal MakeSignal( + long ordinal, + DecisionSignalKind kind, + DateTime occurredAtUtc, + IReadOnlyDictionary? payload = null) + { + return new DecisionSignal( + sessionSignalOrdinal: ordinal, + sessionTraceOrdinal: ordinal, + kind: kind, + kindSchemaVersion: 1, + occurredAtUtc: occurredAtUtc, + sourceOrigin: "test", + evidence: new Evidence(EvidenceKind.Synthetic, $"{kind}-{ordinal}", "test"), + payload: payload); + } + + private static DecisionSignal DeadlineFired(long ordinal, DateTime occurredAtUtc, string deadlineName) => + MakeSignal(ordinal, DecisionSignalKind.DeadlineFired, occurredAtUtc, + new Dictionary { [SignalPayloadKeys.Deadline] = deadlineName }); + + private static ActiveDeadline? FindDeadline(DecisionState state, string name) => + state.Deadlines.FirstOrDefault(d => d.Name == name); + + private static DecisionEffect SingleTimelineEffect(DecisionStep step, string eventType) => + step.Effects.Single(e => + e.Kind == DecisionEffectKind.EmitEventTimelineEntry + && e.Parameters != null + && e.Parameters.TryGetValue("eventType", out var et) + && et == eventType); + + /// + /// Replays the shape both field sessions shared: Classic user-driven, full ESP, Hello + /// policy enabled, AccountSetup entered, then a guard-blocked post-AccountSetup ESP exit + /// (Shell-Core 62407, "Exiting page normally", errorCode 0) that arms the 30-min window. + /// The ESP registry froze at "1 of 5" and the device had zero user-targeted Intune apps, + /// so no arm of ShouldTransitionToAwaitingHello could ever open. + /// + private static DecisionState SetupEspExitDeadEnd(DecisionEngine engine) + { + var state = DecisionState.CreateInitial("sess-81daa77f", "tenant-81daa77f", T0); + state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0)).NewState; + state = engine.Reduce(state, MakeSignal( + 5, DecisionSignalKind.EspConfigDetected, T0.AddMinutes(1), + new Dictionary + { + [SignalPayloadKeys.SkipUserEsp] = "false", + [SignalPayloadKeys.SkipDeviceEsp] = "false", + [SignalPayloadKeys.EspAllowContinueAnyway] = "false", + })).NewState; + state = engine.Reduce(state, MakeSignal( + 10, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(2), + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })).NewState; + state = engine.Reduce(state, MakeSignal( + 20, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(2.5), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + + // Guard-blocked post-AccountSetup exit — arms advisory_completion at exit + 30 min. + state = engine.Reduce(state, MakeSignal(30, DecisionSignalKind.EspExiting, T0.AddMinutes(3))).NewState; + Assert.NotNull(FindDeadline(state, DeadlineNames.AdvisoryCompletion)); + Assert.Null(state.Outcome); + return state; + } + + /// Desktop (DAD-validated real user), RealmJoin detected, Hello provisioned. + private static DecisionState AddDesktopRealmJoinAndHello(DecisionEngine engine, DecisionState state) + { + state = engine.Reduce(state, MakeSignal(40, DecisionSignalKind.DesktopArrived, T0.AddMinutes(3.5))).NewState; + state = engine.Reduce(state, MakeSignal( + 50, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(6), + new Dictionary { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "0" })).NewState; + state = engine.Reduce(state, MakeSignal( + 60, DecisionSignalKind.HelloResolved, T0.AddMinutes(14), + new Dictionary { [SignalPayloadKeys.HelloOutcome] = "Success" })).NewState; + return state; + } + + // ==================================================== the gate-holding guard ==== + + [Fact] + public void DeadlineFired_WhileRealmJoinGateHolds_RearmsInsteadOfFailing() + { + var engine = new DecisionEngine(); + var state = SetupEspExitDeadEnd(engine); + state = AddDesktopRealmJoinAndHello(engine, state); + + // Preconditions: the gate is closed and owns an armed deadline of its own. + Assert.False(DecisionEngine.RealmJoinGateOpen(state)); + Assert.NotNull(FindDeadline(state, DeadlineNames.RealmJoinTimeout)); + + var fireAt = T0.AddMinutes(33); + var step = engine.Reduce(state, DeadlineFired(70, fireAt, DeadlineNames.AdvisoryCompletion)); + + Assert.True(step.Transition.Taken); + Assert.Null(step.NewState.Outcome); + Assert.NotEqual(SessionStage.Failed, step.NewState.Stage); + + var rearmed = FindDeadline(step.NewState, DeadlineNames.AdvisoryCompletion); + Assert.NotNull(rearmed); + Assert.Equal(fireAt.AddMinutes(30), rearmed!.DueAtUtc); + + var schedule = step.Effects.Single(e => e.Kind == DecisionEffectKind.ScheduleDeadline); + Assert.Equal(DeadlineNames.AdvisoryCompletion, schedule.Deadline!.Name); + + var waiting = SingleTimelineEffect(step, "completion_waiting"); + Assert.Contains("CompletionGateHolding", waiting.Parameters!["trigger"]); + Assert.Contains("realmjoin_resolution", waiting.Parameters!["missingPrerequisites"]); + Assert.Equal(rearmed.DueAtUtc.ToString("o"), waiting.Parameters!["resolutionDeadlineDueAtUtc"]); + } + + [Fact] + public void Session81daa77f_RealmJoinResolvesAfterTheWindow_CompletesInsteadOfFailing() + { + // End-to-end proof against the real field shape: before this guard the session was + // stamped Failed at exit+30 min with esp_exit_without_completion_evidence, 34 min + // before the RealmJoin gate would have released it. + var engine = new DecisionEngine(); + var state = SetupEspExitDeadEnd(engine); + state = AddDesktopRealmJoinAndHello(engine, state); + + var fired = engine.Reduce(state, DeadlineFired(70, T0.AddMinutes(33), DeadlineNames.AdvisoryCompletion)); + Assert.Null(fired.NewState.Outcome); + + // RealmJoin reaches phase 110 — the gate opens and the session completes. + var resolved = engine.Reduce(fired.NewState, MakeSignal( + 80, DecisionSignalKind.RealmJoinResolved, T0.AddMinutes(50), + new Dictionary { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "110" })); + + Assert.Equal(SessionStage.Finalizing, resolved.NewState.Stage); + Assert.Equal("Resolved", resolved.NewState.RealmJoinFacts.Outcome!.Value); + + var grace = FindDeadline(resolved.NewState, DeadlineNames.FinalizingGrace); + Assert.NotNull(grace); + var completed = engine.Reduce(resolved.NewState, + DeadlineFired(90, grace!.DueAtUtc, DeadlineNames.FinalizingGrace)); + Assert.Equal(SessionStage.Completed, completed.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentComplete, completed.NewState.Outcome); + } + + // ============================================================== convergence ==== + + [Fact] + public void DeadlineFired_AfterTheGateOpened_ResolvesNormallyAgain() + { + // Convergence proof: the guard is not an escape hatch. Once RealmJoin timed out the + // gate is open, the guard stops applying, and a session with no completion evidence + // fails exactly as before. + var engine = new DecisionEngine(); + var state = SetupEspExitDeadEnd(engine); + state = engine.Reduce(state, MakeSignal( + 50, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(6), + new Dictionary { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "0" })).NewState; + + var rjDeadline = FindDeadline(state, DeadlineNames.RealmJoinTimeout); + Assert.NotNull(rjDeadline); + state = engine.Reduce(state, + DeadlineFired(60, rjDeadline!.DueAtUtc, DeadlineNames.RealmJoinTimeout)).NewState; + + Assert.True(DecisionEngine.RealmJoinGateOpen(state)); + Assert.Null(FindDeadline(state, DeadlineNames.RealmJoinTimeout)); + + // No desktop, no Hello, no IME evidence — the genuine dead-end shape. + var step = engine.Reduce(state, + DeadlineFired(70, T0.AddMinutes(80), DeadlineNames.AdvisoryCompletion)); + + Assert.Equal(SessionStage.Failed, step.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentFailed, step.NewState.Outcome); + var failed = SingleTimelineEffect(step, "enrollment_failed"); + Assert.Equal("esp_exit_without_completion_evidence", failed.Parameters!["reason"]); + } + + // =========================================================== mutation proofs ==== + + [Fact] + public void DeadlineFired_WithoutRealmJoin_StillFails() + { + // The guard must key on an actually-held gate, never on the absence of evidence. + var engine = new DecisionEngine(); + var state = SetupEspExitDeadEnd(engine); + + var step = engine.Reduce(state, + DeadlineFired(70, T0.AddMinutes(33), DeadlineNames.AdvisoryCompletion)); + + Assert.Equal(SessionStage.Failed, step.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentFailed, step.NewState.Outcome); + var failed = SingleTimelineEffect(step, "enrollment_failed"); + Assert.Equal("esp_exit_without_completion_evidence", failed.Parameters!["reason"]); + } + + [Fact] + public void DeadlineFired_GateClosedButItsDeadlineNoLongerArmed_StillFails() + { + // A gate that can no longer resolve itself must not park the session forever. The + // hand-built state drops only the RealmJoin deadline, leaving the gate closed. + var engine = new DecisionEngine(); + var state = SetupEspExitDeadEnd(engine); + state = AddDesktopRealmJoinAndHello(engine, state); + + var builder = state.ToBuilder(); + builder.CancelDeadline(DeadlineNames.RealmJoinTimeout); + state = builder.Build(); + + Assert.False(DecisionEngine.RealmJoinGateOpen(state)); + Assert.Null(FindDeadline(state, DeadlineNames.RealmJoinTimeout)); + + var step = engine.Reduce(state, + DeadlineFired(70, T0.AddMinutes(33), DeadlineNames.AdvisoryCompletion)); + + Assert.Equal(SessionStage.Failed, step.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentFailed, step.NewState.Outcome); + } + } +} diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/BuiltInRulesTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/BuiltInRulesTests.cs index d6cfa65e..1276920c 100644 --- a/src/Backend/AutopilotMonitor.Functions.Tests/BuiltInRulesTests.cs +++ b/src/Backend/AutopilotMonitor.Functions.Tests/BuiltInRulesTests.cs @@ -1,3 +1,4 @@ +using System.Text.RegularExpressions; using AutopilotMonitor.Functions.Services; using AutopilotMonitor.Shared.Models; @@ -172,7 +173,7 @@ public class BuiltInRulesTests "policiesDiscovered", "ignoreCompletedApp", "imeAgentVersion", "espTrackStatus", "updateName", "updateWin32AppState", "cancelStuckAndSetCurrent", "imeSessionChange", "imeImpersonation", "imeTokenFailure", - "enrollmentCompleted", "updateDoTelemetry", "scriptStarted", + "enrollmentCompleted", "userSessionZeroApps", "updateDoTelemetry", "scriptStarted", "scriptContext", "scriptExitCode", "scriptOutput", "scriptCompleted", "resetPlatformScriptContext", "healthScriptResult", "healthScriptDetectionResult", @@ -201,4 +202,38 @@ public class BuiltInRulesTests $"Pattern {pattern.PatternId} has invalid category '{pattern.Category}'"); } } + + /// + /// Sessions 81daa77f / 75d6ae8e (2026-08-25). IME writes this line and then returns before + /// its "Completed user session" statement, so on a device with no user-targeted Win32 apps + /// it is the ONLY evidence that user-phase enforcement finished. The exact wording is + /// pinned here against the real IME line (verified against decompiled IME 1.104.102.0, + /// ApplicationPoller and AppWorkloadAbstraction) because a silent drift would bring back + /// the 30-min esp_exit_without_completion_evidence false positive with no test failing. + /// + [Fact] + public void BuiltInImeLogPatterns_ZeroUserAppsPattern_MatchesTheRealImeLine() + { + var pattern = Assert.Single( + BuiltInImeLogPatterns.GetAll(), + p => p.PatternId == "IME-USER-SESSION-ZERO-APPS"); + + Assert.Equal("userSessionZeroApps", pattern.Action); + Assert.Equal("always", pattern.Category); + + var regex = new Regex(pattern.Pattern, RegexOptions.CultureInvariant); + + var real = "[Win32App] Get 0 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"; + var match = regex.Match(real); + Assert.True(match.Success, "zero-app user session line must match"); + Assert.Equal("1", match.Groups["sessionId"].Value); + Assert.Equal("4a1ba5db-44ed-4e69-8477-47ed88e76020", match.Groups["userId"].Value); + + // Must not swallow a session that DOES have apps — that would fabricate completion + // evidence while enforcement is still running. + Assert.DoesNotMatch(regex, + "[Win32App] Get 3 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"); + Assert.DoesNotMatch(regex, + "[Win32App] Get 10 apps for user session 1, user id = 4a1ba5db-44ed-4e69-8477-47ed88e76020"); + } } diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Edge.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Edge.cs index 5508839f..b67e9ebd 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Edge.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Edge.cs @@ -431,6 +431,16 @@ namespace AutopilotMonitor.DecisionCore.Engine internal static bool HasAdvisoryCompletionDeadline(DecisionState state) => FindAdvisoryCompletionDeadline(state) != null; + /// True when a deadline with the given name is currently armed. + internal static bool HasDeadline(DecisionState state, string name) + { + foreach (var d in state.Deadlines) + { + if (d.Name == name) return true; + } + return false; + } + /// The armed deadline, or null. internal static ActiveDeadline? FindAdvisoryCompletionDeadline(DecisionState state) { @@ -912,6 +922,61 @@ namespace AutopilotMonitor.DecisionCore.Engine return new DecisionStep(neverObservedState, neverObservedTransition, neverObservedEffects.ToArray()); } + // Completion-gate guard (sessions 81daa77f / 75d6ae8e, 2026-08-25) — a completion + // gate that is deliberately holding this session must not be overrun by this + // window. The RealmJoin gate blocks completion until phase 110, and it carries its + // own bounded resolution: 60 min from detection, re-armed on deployment activity, + // hard-capped at 4 h. This 30-min window is simply shorter, so on every device + // whose RealmJoin first deployment outlives it the session was failed while the + // engine's own `completion_waiting` still read "waiting on: realmjoin_resolution" + // — 75d6ae8e installed 25 RealmJoin packages successfully inside the window, the + // last one 2 min before the failure. Re-arm and let the gate's own deadline decide. + // + // Convergent: the gate resolves itself either way (Resolved / FirstDeploymentIncomplete + // / Timeout all set RealmJoinFacts.Outcome, which opens RealmJoinGateOpen), after + // which this guard stops applying and the next fire resolves the session normally. + // Requiring the gate's deadline to still be armed keeps a gate that can no longer + // resolve itself from parking the session forever; AgentMaxLifetimeMinutes bounds + // it regardless. + if (!RealmJoinGateOpen(state) && HasDeadline(state, DeadlineNames.RealmJoinTimeout)) + { + var gateRearmedDeadline = BuildAdvisoryCompletionDeadline(state, signal); + builder.AddDeadline(gateRearmedDeadline); + + var gateTrigger = $"DeadlineFired:{DeadlineNames.AdvisoryCompletion}:CompletionGateHolding"; + var gateRearmedState = builder.Build(); + var gateRearmedTransition = BuildTakenTransition( + before: state, + signal: signal, + toStage: state.Stage, + nextStepIndex: nextStep, + trigger: gateTrigger); + + // Same deliberate dedupe bypass as the enforcement-progress re-arm: the missing + // set is unchanged since arming, but the new due-time is exactly what an + // operator debugging the session needs. Bounded to one per window. + var gateRearmedEffects = new[] + { + new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: gateRearmedDeadline), + new DecisionEffect( + DecisionEffectKind.EmitEventTimelineEntry, + parameters: new Dictionary + { + ["eventType"] = SharedConstants.EventTypes.CompletionWaiting, + ["source"] = "DecisionEngine", + ["severity"] = "Info", + ["immediateUpload"] = "false", + ["message"] = "Completion resolution window re-armed: a completion gate is still holding the session", + ["missingPrerequisites"] = string.Join(",", BuildMissingCompletionPrerequisites(state)), + ["trigger"] = gateTrigger, + ["stage"] = state.Stage.ToString(), + ["resolutionDeadlineDueAtUtc"] = gateRearmedDeadline.DueAtUtc.ToString("o"), + }), + }; + + return new DecisionStep(gateRearmedState, gateRearmedTransition, gateRearmedEffects); + } + // Conjunction not met — the session is failed. The two arming variants carry // distinct context (see method doc): the advisory variant un-defangs the original // ESP failure; the esp-exit variant never had an ESP failure, so it gets its own