From f607e21c13040ef1fceedaa7b4ac7a1bf9525cfc Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 4 Sep 2026 21:12:56 +0200 Subject: [PATCH] agent+rules: Hybrid Join user affinity from the IME user token; IME backlog eras anchored by the bootstrap record MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit hybrid_login_pending now measures the absence of a real-user desktop after a reboot (cancelled by the DesktopArrivalDetector or a real JoinInfo user), is never armed on WhiteGlove devices (resume marker, Part-2 flag, .part1- archive) and reports the JoinInfo placeholder as a fact only — on a Hybrid join the AD sign-in never replaces it. New EntraUserAffinityDetector: armed at the real-user desktop on Hybrid devices, the first IME-TOKEN-SUCCESS line after the desktop posts ime_user_token_acquired; ten minutes without one post entra_user_affinity_pending with the IME token-failure codes. ImeLogTracker exposes raw per-line token callbacks past the historic-replay gate; HelloTracker surfaces User Device Registration 304/305 as device_registration_event. ANALYZE-ID-004 v2.0.0 keys on those events (event_type not_exists gained a branch), GATHER-DEVICE-006 follows, GATHER-DEVICE-007/008 collect the Entra operational log. Constants + MCP catalog gain the five types (D-072), the guard test learns the multi-line OnTraceEvent shape, gather_* outputs pass the MCP filter gate by prefix. CMTrace: ImeLogEraPreScan/CmTraceEraTable anchor the backlog era that holds the bootstrap execution record against the Deployed install marker (0.13-0.36 s in the field), whole era or nothing, sibling files by local time; origin era-anchored. Backend phase_duration/app_install_duration refuse a reader-zone-fallback endpoint. Decisions D-190, D-191. Session a7140f98. Co-Authored-By: Claude Fable 5.1 --- internal | 2 +- rules/analyze/ANALYZE-ID-004.json | 33 +- rules/dist/analyze-rules.json | 37 +- rules/dist/gather-rules.json | 56 ++- rules/gather/GATHER-DEVICE-006.json | 8 +- rules/gather/GATHER-DEVICE-007.json | 21 + rules/gather/GATHER-DEVICE-008.json | 21 + rules/schema/analyze-rule.schema.json | 2 +- .../EventTypeConstantGuardTests.cs | 93 +++-- .../EntraUserAffinityDetectorTests.cs | 236 +++++++++++ .../HelloTrackerImmediateUploadTests.cs | 21 + .../HybridLoginPendingDetectorTests.cs | 52 +++ .../Monitoring/Ime/ImeLogEraPreScanTests.cs | 215 ++++++++++ .../Ime/ImeLogTrackerEraAnchoringTests.cs | 171 ++++++++ .../ImeLogTrackerTokenLineCallbackTests.cs | 115 ++++++ .../Enrollment/Ime/CmTraceEraTable.cs | 157 ++++++++ .../Enrollment/Ime/CmTraceOffsetCalibrator.cs | 10 + .../Enrollment/Ime/ImeLogEraPreScan.cs | 316 +++++++++++++++ .../Ime/ImeLogTracker.LogProcessing.cs | 40 ++ .../Enrollment/Ime/ImeLogTracker.cs | 80 ++++ .../SystemSignals/AadJoinWatcher.cs | 11 + .../SystemSignals/DesktopArrivalDetector.cs | 4 +- .../EntraUserAffinityDetector.cs | 232 +++++++++++ .../Enrollment/SystemSignals/HelloTracker.cs | 22 +- .../HybridLoginPendingDetector.cs | 69 +++- .../Orchestration/DefaultComponentFactory.cs | 16 +- .../Orchestration/EnrollmentOrchestrator.cs | 8 + .../Orchestration/Hosts/AadJoinHost.cs | 71 +++- .../Orchestration/StateArchiver.cs | 25 +- .../Security/DeploymentMarker.cs | 48 +++ .../SignalAdapters/ImeLogTrackerAdapter.cs | 8 + .../Program.InstallMode.cs | 6 +- .../Runtime/AgentRuntimeHost.cs | 21 +- .../HybridUserAffinityRuleTests.cs | 228 +++++++++++ .../RuleEngineDurationProvenanceTests.cs | 374 ++++++++++++++++++ .../RuleEngineEvaluateOnTests.cs | 6 +- .../RuleEngineEventTypeNotExistsTests.cs | 92 +++++ .../RuleEngine.ConditionEvaluators.cs | 86 +++- .../src/__tests__/auto-exhaust.test.ts | 34 ++ .../src/resource-catalog.ts | 46 ++- .../src/rule-authoring-guide.ts | 8 +- .../src/rule-authoring.generated.ts | 2 +- .../src/tools/sessions.ts | 3 + .../AutopilotMonitor.Shared/Constants.cs | 19 +- .../Logging/CmTraceLogParser.cs | 8 +- .../lib/timeProvenance.ts | 2 +- .../utils/shared-manifests.generated.ts | 5 + .../utils/shared-manifests.json | 5 + 48 files changed, 3013 insertions(+), 132 deletions(-) create mode 100644 rules/gather/GATHER-DEVICE-007.json create mode 100644 rules/gather/GATHER-DEVICE-008.json create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EntraUserAffinityDetectorTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogEraPreScanTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerEraAnchoringTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerTokenLineCallbackTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceEraTable.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogEraPreScan.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EntraUserAffinityDetector.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Security/DeploymentMarker.cs create mode 100644 src/Backend/AutopilotMonitor.Functions.Tests/HybridUserAffinityRuleTests.cs create mode 100644 src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs create mode 100644 src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEventTypeNotExistsTests.cs diff --git a/internal b/internal index 241c398f..9f75da24 160000 --- a/internal +++ b/internal @@ -1 +1 @@ -Subproject commit 241c398fdb2d1f23fffd5e42de6830beeb5a214c +Subproject commit 9f75da246a3662fa23a9b96237997159195432f4 diff --git a/rules/analyze/ANALYZE-ID-004.json b/rules/analyze/ANALYZE-ID-004.json index cf3dbd90..402175be 100644 --- a/rules/analyze/ANALYZE-ID-004.json +++ b/rules/analyze/ANALYZE-ID-004.json @@ -2,14 +2,14 @@ "$schema": "../schema/analyze-rule.schema.json", "ruleId": "ANALYZE-ID-004", "title": "Hybrid Sign-In Never Establishes Entra User Affinity", - "description": "On a hybrid-joined device the real user reached the desktop, but the Autopilot provisioning placeholder stayed active in JoinInfo and the agent repeatedly reported the hybrid sign-in as overdue. The user session never establishes Entra user affinity (no PRT), so the Account Setup ESP re-runs on every logon and the enrollment never completes.", + "description": "On a hybrid-joined device the real user reached the desktop, but the Intune Management Extension never acquired a Microsoft Entra user token for that user within the wait window — repeatedly across reboots when the warning recurs. Without a user token the signed-in user has no Entra user affinity: user-targeted apps and policies cannot apply, Windows Hello for Business cannot provision, and with a user ESP the Account Setup page re-runs on every logon.", "severity": "high", "category": "identity", - "version": "1.2.0", + "version": "2.0.0", "author": "Autopilot Monitor", "enabled": true, "trigger": "correlation", - "evaluateOn": ["enrollment_end", "on_event:hybrid_login_pending"], + "evaluateOn": ["enrollment_end", "on_event:entra_user_affinity_pending"], "baseConfidence": 60, "confidenceThreshold": 75, "preconditions": [ @@ -17,14 +17,14 @@ "source": "event_data", "eventType": "enrollment_complete", "operator": "not_exists", - "description": "Suppress when the session eventually completed — a single overdue-login warning followed by a successful sign-in is normal hybrid latency, not a broken affinity." + "description": "Suppress when the session eventually completed — a single pending-affinity warning followed by a successful token acquisition is hybrid latency, not a broken affinity." } ], "conditions": [ { - "signal": "hybrid_login_overdue", + "signal": "user_affinity_pending", "source": "event_type", - "eventType": "hybrid_login_pending", + "eventType": "entra_user_affinity_pending", "operator": "exists", "value": "", "required": true @@ -38,28 +38,27 @@ "required": true }, { - "signal": "placeholder_still_active", + "signal": "no_user_token", "source": "event_type", - "eventType": "aad_placeholder_user_detected", - "operator": "exists", + "eventType": "ime_user_token_acquired", + "operator": "not_exists", "value": "", - "required": false + "required": true } ], "confidenceFactors": [ - { "signal": "hybrid_login_pending", "condition": "count >= 2", "weight": 20 }, - { "signal": "hybrid_login_pending", "condition": "count >= 3", "weight": 10 }, - { "signal": "aad_placeholder_user_detected", "condition": "count >= 3", "weight": 10 } + { "signal": "entra_user_affinity_pending", "condition": "count >= 2", "weight": 20 }, + { "signal": "entra_user_affinity_pending", "condition": "count >= 3", "weight": 10 } ], - "explanation": "A real user signed in and reached the desktop, but the device kept reporting the **Autopilot provisioning placeholder** as the active identity in JoinInfo and the hybrid sign-in as **overdue** — across multiple reboots. This means the signed-in user never established **Microsoft Entra user affinity** (no Primary Refresh Token), so:\n\n- the Account Setup ESP page re-appears on every logon,\n- user-targeted required apps and policies cannot settle,\n- the enrollment never reaches completion.\n\nAfter this many hours this is not normal Entra Connect sync latency — something is structurally preventing the user (or the computer object) from registering:\n\n- the computer object's `userCertificate` attribute is not syncing to Entra ID (sync scope / OU filtering),\n- the signing-in user is not synced, or their UPN does not match a verified Entra domain,\n- the device has no line of sight to a domain controller **at logon time**, so the hybrid PRT flow cannot finish,\n- time skew or a proxy blocking `login.microsoftonline.com` / `enterpriseregistration.windows.net` from the user context.\n\nA frequent variant: the user's **first sign-in happens without domain-controller reachability** — for example when a pre-logon VPN tunnel (GlobalProtect, Always On VPN, Zscaler ZPA) is not established yet at the logon screen. Windows falls back to cached credentials, the hybrid PRT flow silently never runs, and later reboots do not fix it — sessions in this state typically show repeated reboots and network flapping while the placeholder identity stays active.\n\nA visible side effect: **the Windows Hello for Business wizard never appears**, because Hello provisioning requires an Entra user token (PRT). Hello is a downstream symptom here, not the cause.", + "explanation": "**What was measured.** A real user signed in and reached the desktop (`desktop_arrived`), and by the end of the agent's wait window the Intune Management Extension (IME) had still not acquired a **Microsoft Entra user token** for that user (`entra_user_affinity_pending`). That event lists the IME token error codes observed after the desktop (`tokenFailureCodes`) and how often the acquisition failed (`tokenFailureCount`). Each agent run reports this at most once, so a second or third occurrence means the same outcome across reboots — that repetition is what raises the confidence of this finding. No `ime_user_token_acquired` event followed in this session.\n\n**Why this means no user affinity.** IME's user check-in acquires the user token through the Windows web account manager (WAM), which needs the signed-in user's Entra identity — the Primary Refresh Token (PRT) that a hybrid sign-in establishes at logon. When that PRT was never issued, every token request fails and the user has **no Entra user affinity** on this device. Consequences:\n\n- user-targeted required apps and policies cannot apply,\n- Windows Hello for Business cannot provision (it requires a user token),\n- with a user ESP the Account Setup page re-appears on every logon instead of completing.\n\n**What this diagnosis does not use.** The Autopilot provisioning placeholder in JoinInfo (`aad_placeholder_user_detected`) is not part of this finding — on hybrid devices it can stay present through a perfectly healthy sign-in. Likewise, `dsregcmd /status` collected by the agent runs as SYSTEM and shows only the **device** join state; the per-user PRT state is visible only when the command runs as the signed-in user.\n\n**Typical causes** — something structurally prevents the user (or the computer object) from registering:\n\n- the computer object's `userCertificate` attribute is not syncing to Entra ID (sync scope / OU filtering),\n- the signing-in user is not synced, or their UPN does not match a verified Entra domain,\n- the device has no line of sight to a domain controller **at logon time**, so the hybrid PRT flow cannot finish,\n- time skew or a proxy blocking `login.microsoftonline.com` / `enterpriseregistration.windows.net` from the user context.\n\nA frequent variant: the user's **first sign-in happens without domain-controller reachability** — for example when a pre-logon VPN tunnel (GlobalProtect, Always On VPN, Zscaler ZPA) is not established yet at the logon screen. Windows falls back to cached credentials, the hybrid PRT flow silently never runs, and later reboots do not fix it.\n\nThe `device_registration_event` entries in the timeline (User Device Registration events 304/305) carry the OS-side record of the failed registration; the error codes in `entra_user_affinity_pending` carry the token side. A missing Windows Hello for Business wizard is a downstream symptom here, not the cause.", "remediation": [ { "title": "Verify user affinity on the device", "steps": [ "Sign in as the affected user and run: dsregcmd /status — under 'SSO State' the value AzureAdPrt must be YES. NO means the user has no Entra token and this diagnosis is confirmed.", - "Also check 'Device State': AzureAdJoined = YES and DomainJoined = YES are expected for hybrid join.", - "Check Event Viewer: Applications and Services Logs > Microsoft > Windows > User Device Registration > Admin for PRT / registration errors (e.g. event 304/305/362).", - "Enable the gather rules 'Collect dsregcmd join status' so future sessions capture this state automatically." + "Also check 'Device State': AzureAdJoined = YES and DomainJoined = YES are expected for hybrid join — they prove the device join only, not the user's registration.", + "Check Event Viewer: Applications and Services Logs > Microsoft > Windows > User Device Registration > Admin for PRT / registration errors (e.g. event 304/305/362). The device_registration_event entries (304/305) in the session timeline carry the same OS-side failure record.", + "Enable the gather rule GATHER-DEVICE-006 (dsregcmd /status at the moment of the finding — device state only, the agent runs as SYSTEM). GATHER-DEVICE-007 and GATHER-DEVICE-008 (Microsoft-Windows-AAD/Operational events 1098 and 1097 at the same moment) are on by default." ] }, { diff --git a/rules/dist/analyze-rules.json b/rules/dist/analyze-rules.json index 34ff5ae7..164d3f42 100644 --- a/rules/dist/analyze-rules.json +++ b/rules/dist/analyze-rules.json @@ -2940,16 +2940,16 @@ { "ruleId": "ANALYZE-ID-004", "title": "Hybrid Sign-In Never Establishes Entra User Affinity", - "description": "On a hybrid-joined device the real user reached the desktop, but the Autopilot provisioning placeholder stayed active in JoinInfo and the agent repeatedly reported the hybrid sign-in as overdue. The user session never establishes Entra user affinity (no PRT), so the Account Setup ESP re-runs on every logon and the enrollment never completes.", + "description": "On a hybrid-joined device the real user reached the desktop, but the Intune Management Extension never acquired a Microsoft Entra user token for that user within the wait window — repeatedly across reboots when the warning recurs. Without a user token the signed-in user has no Entra user affinity: user-targeted apps and policies cannot apply, Windows Hello for Business cannot provision, and with a user ESP the Account Setup page re-runs on every logon.", "severity": "high", "category": "identity", - "version": "1.2.0", + "version": "2.0.0", "author": "Autopilot Monitor", "enabled": true, "trigger": "correlation", "evaluateOn": [ "enrollment_end", - "on_event:hybrid_login_pending" + "on_event:entra_user_affinity_pending" ], "baseConfidence": 60, "confidenceThreshold": 75, @@ -2958,14 +2958,14 @@ "source": "event_data", "eventType": "enrollment_complete", "operator": "not_exists", - "description": "Suppress when the session eventually completed — a single overdue-login warning followed by a successful sign-in is normal hybrid latency, not a broken affinity." + "description": "Suppress when the session eventually completed — a single pending-affinity warning followed by a successful token acquisition is hybrid latency, not a broken affinity." } ], "conditions": [ { - "signal": "hybrid_login_overdue", + "signal": "user_affinity_pending", "source": "event_type", - "eventType": "hybrid_login_pending", + "eventType": "entra_user_affinity_pending", "operator": "exists", "value": "", "required": true @@ -2979,40 +2979,35 @@ "required": true }, { - "signal": "placeholder_still_active", + "signal": "no_user_token", "source": "event_type", - "eventType": "aad_placeholder_user_detected", - "operator": "exists", + "eventType": "ime_user_token_acquired", + "operator": "not_exists", "value": "", - "required": false + "required": true } ], "confidenceFactors": [ { - "signal": "hybrid_login_pending", + "signal": "entra_user_affinity_pending", "condition": "count >= 2", "weight": 20 }, { - "signal": "hybrid_login_pending", - "condition": "count >= 3", - "weight": 10 - }, - { - "signal": "aad_placeholder_user_detected", + "signal": "entra_user_affinity_pending", "condition": "count >= 3", "weight": 10 } ], - "explanation": "A real user signed in and reached the desktop, but the device kept reporting the **Autopilot provisioning placeholder** as the active identity in JoinInfo and the hybrid sign-in as **overdue** — across multiple reboots. This means the signed-in user never established **Microsoft Entra user affinity** (no Primary Refresh Token), so:\n\n- the Account Setup ESP page re-appears on every logon,\n- user-targeted required apps and policies cannot settle,\n- the enrollment never reaches completion.\n\nAfter this many hours this is not normal Entra Connect sync latency — something is structurally preventing the user (or the computer object) from registering:\n\n- the computer object's `userCertificate` attribute is not syncing to Entra ID (sync scope / OU filtering),\n- the signing-in user is not synced, or their UPN does not match a verified Entra domain,\n- the device has no line of sight to a domain controller **at logon time**, so the hybrid PRT flow cannot finish,\n- time skew or a proxy blocking `login.microsoftonline.com` / `enterpriseregistration.windows.net` from the user context.\n\nA frequent variant: the user's **first sign-in happens without domain-controller reachability** — for example when a pre-logon VPN tunnel (GlobalProtect, Always On VPN, Zscaler ZPA) is not established yet at the logon screen. Windows falls back to cached credentials, the hybrid PRT flow silently never runs, and later reboots do not fix it — sessions in this state typically show repeated reboots and network flapping while the placeholder identity stays active.\n\nA visible side effect: **the Windows Hello for Business wizard never appears**, because Hello provisioning requires an Entra user token (PRT). Hello is a downstream symptom here, not the cause.", + "explanation": "**What was measured.** A real user signed in and reached the desktop (`desktop_arrived`), and by the end of the agent's wait window the Intune Management Extension (IME) had still not acquired a **Microsoft Entra user token** for that user (`entra_user_affinity_pending`). That event lists the IME token error codes observed after the desktop (`tokenFailureCodes`) and how often the acquisition failed (`tokenFailureCount`). Each agent run reports this at most once, so a second or third occurrence means the same outcome across reboots — that repetition is what raises the confidence of this finding. No `ime_user_token_acquired` event followed in this session.\n\n**Why this means no user affinity.** IME's user check-in acquires the user token through the Windows web account manager (WAM), which needs the signed-in user's Entra identity — the Primary Refresh Token (PRT) that a hybrid sign-in establishes at logon. When that PRT was never issued, every token request fails and the user has **no Entra user affinity** on this device. Consequences:\n\n- user-targeted required apps and policies cannot apply,\n- Windows Hello for Business cannot provision (it requires a user token),\n- with a user ESP the Account Setup page re-appears on every logon instead of completing.\n\n**What this diagnosis does not use.** The Autopilot provisioning placeholder in JoinInfo (`aad_placeholder_user_detected`) is not part of this finding — on hybrid devices it can stay present through a perfectly healthy sign-in. Likewise, `dsregcmd /status` collected by the agent runs as SYSTEM and shows only the **device** join state; the per-user PRT state is visible only when the command runs as the signed-in user.\n\n**Typical causes** — something structurally prevents the user (or the computer object) from registering:\n\n- the computer object's `userCertificate` attribute is not syncing to Entra ID (sync scope / OU filtering),\n- the signing-in user is not synced, or their UPN does not match a verified Entra domain,\n- the device has no line of sight to a domain controller **at logon time**, so the hybrid PRT flow cannot finish,\n- time skew or a proxy blocking `login.microsoftonline.com` / `enterpriseregistration.windows.net` from the user context.\n\nA frequent variant: the user's **first sign-in happens without domain-controller reachability** — for example when a pre-logon VPN tunnel (GlobalProtect, Always On VPN, Zscaler ZPA) is not established yet at the logon screen. Windows falls back to cached credentials, the hybrid PRT flow silently never runs, and later reboots do not fix it.\n\nThe `device_registration_event` entries in the timeline (User Device Registration events 304/305) carry the OS-side record of the failed registration; the error codes in `entra_user_affinity_pending` carry the token side. A missing Windows Hello for Business wizard is a downstream symptom here, not the cause.", "remediation": [ { "title": "Verify user affinity on the device", "steps": [ "Sign in as the affected user and run: dsregcmd /status — under 'SSO State' the value AzureAdPrt must be YES. NO means the user has no Entra token and this diagnosis is confirmed.", - "Also check 'Device State': AzureAdJoined = YES and DomainJoined = YES are expected for hybrid join.", - "Check Event Viewer: Applications and Services Logs > Microsoft > Windows > User Device Registration > Admin for PRT / registration errors (e.g. event 304/305/362).", - "Enable the gather rules 'Collect dsregcmd join status' so future sessions capture this state automatically." + "Also check 'Device State': AzureAdJoined = YES and DomainJoined = YES are expected for hybrid join — they prove the device join only, not the user's registration.", + "Check Event Viewer: Applications and Services Logs > Microsoft > Windows > User Device Registration > Admin for PRT / registration errors (e.g. event 304/305/362). The device_registration_event entries (304/305) in the session timeline carry the same OS-side failure record.", + "Enable the gather rule GATHER-DEVICE-006 (dsregcmd /status at the moment of the finding — device state only, the agent runs as SYSTEM). GATHER-DEVICE-007 and GATHER-DEVICE-008 (Microsoft-Windows-AAD/Operational events 1098 and 1097 at the same moment) are on by default." ] }, { diff --git a/rules/dist/gather-rules.json b/rules/dist/gather-rules.json index 12f860f3..f29ce610 100644 --- a/rules/dist/gather-rules.json +++ b/rules/dist/gather-rules.json @@ -130,16 +130,16 @@ }, { "ruleId": "GATHER-DEVICE-006", - "title": "Collect dsregcmd join status on overdue hybrid sign-in", - "description": "Runs dsregcmd /status the moment the agent reports a hybrid sign-in as overdue (hybrid_login_pending), capturing the Entra join and registration state at exactly the point where the problem is detected. Complements GATHER-DEVICE-001 (snapshot on entering Account Setup). Note: the agent runs as SYSTEM, so the output shows device join state — the per-user SSO/PRT state still requires running dsregcmd as the signed-in user.", + "title": "Collect dsregcmd join status on pending user affinity", + "description": "Runs dsregcmd /status the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending), capturing the device join and registration state at exactly the point where ANALYZE-ID-004 draws its evidence. Complements GATHER-DEVICE-001 (snapshot on entering Account Setup). Note: the agent runs as SYSTEM, so the output shows device join state — the per-user SSO/PRT state still requires running dsregcmd as the signed-in user.", "category": "device", - "version": "1.0.0", + "version": "1.1.0", "author": "Autopilot Monitor", "enabled": false, "collectorType": "command_allowlisted", "target": "dsregcmd /status", "trigger": "on_event", - "triggerEventType": "hybrid_login_pending", + "triggerEventType": "entra_user_affinity_pending", "outputEventType": "gather_dsregcmd_status", "outputSeverity": "Info", "tags": [ @@ -149,6 +149,54 @@ "hybrid" ] }, + { + "ruleId": "GATHER-DEVICE-007", + "title": "Collect Entra operational log on pending user affinity (event 1098)", + "description": "Collects the most recent Entra token-broker operational events with ID 1098 from Microsoft-Windows-AAD/Operational the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending). Captures the OS-side token-broker record at exactly the point where ANALYZE-ID-004 draws its evidence. The event log collector filters on one event ID per rule; GATHER-DEVICE-008 collects event 1097 from the same channel.", + "category": "device", + "version": "1.0.0", + "author": "Autopilot Monitor", + "enabled": true, + "collectorType": "eventlog", + "target": "Microsoft-Windows-AAD/Operational", + "parameters": { + "eventId": "1098", + "maxEntries": "20" + }, + "trigger": "on_event", + "triggerEventType": "entra_user_affinity_pending", + "outputEventType": "gather_aad_operational_events", + "outputSeverity": "Warning", + "tags": [ + "device", + "entra", + "hybrid" + ] + }, + { + "ruleId": "GATHER-DEVICE-008", + "title": "Collect Entra operational log on pending user affinity (event 1097)", + "description": "Collects the most recent Entra token-broker operational events with ID 1097 from Microsoft-Windows-AAD/Operational the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending). Captures the OS-side token-broker record at exactly the point where ANALYZE-ID-004 draws its evidence. The event log collector filters on one event ID per rule; GATHER-DEVICE-007 collects event 1098 from the same channel.", + "category": "device", + "version": "1.0.0", + "author": "Autopilot Monitor", + "enabled": true, + "collectorType": "eventlog", + "target": "Microsoft-Windows-AAD/Operational", + "parameters": { + "eventId": "1097", + "maxEntries": "20" + }, + "trigger": "on_event", + "triggerEventType": "entra_user_affinity_pending", + "outputEventType": "gather_aad_operational_events", + "outputSeverity": "Warning", + "tags": [ + "device", + "entra", + "hybrid" + ] + }, { "ruleId": "GATHER-ENROLL-001", "title": "MDM enrollment diagnostic events", diff --git a/rules/gather/GATHER-DEVICE-006.json b/rules/gather/GATHER-DEVICE-006.json index d87a78cc..9ef5ceb4 100644 --- a/rules/gather/GATHER-DEVICE-006.json +++ b/rules/gather/GATHER-DEVICE-006.json @@ -1,16 +1,16 @@ { "$schema": "../schema/gather-rule.schema.json", "ruleId": "GATHER-DEVICE-006", - "title": "Collect dsregcmd join status on overdue hybrid sign-in", - "description": "Runs dsregcmd /status the moment the agent reports a hybrid sign-in as overdue (hybrid_login_pending), capturing the Entra join and registration state at exactly the point where the problem is detected. Complements GATHER-DEVICE-001 (snapshot on entering Account Setup). Note: the agent runs as SYSTEM, so the output shows device join state — the per-user SSO/PRT state still requires running dsregcmd as the signed-in user.", + "title": "Collect dsregcmd join status on pending user affinity", + "description": "Runs dsregcmd /status the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending), capturing the device join and registration state at exactly the point where ANALYZE-ID-004 draws its evidence. Complements GATHER-DEVICE-001 (snapshot on entering Account Setup). Note: the agent runs as SYSTEM, so the output shows device join state — the per-user SSO/PRT state still requires running dsregcmd as the signed-in user.", "category": "device", - "version": "1.0.0", + "version": "1.1.0", "author": "Autopilot Monitor", "enabled": false, "collectorType": "command_allowlisted", "target": "dsregcmd /status", "trigger": "on_event", - "triggerEventType": "hybrid_login_pending", + "triggerEventType": "entra_user_affinity_pending", "outputEventType": "gather_dsregcmd_status", "outputSeverity": "Info", "tags": ["device", "entra", "join", "hybrid"] diff --git a/rules/gather/GATHER-DEVICE-007.json b/rules/gather/GATHER-DEVICE-007.json new file mode 100644 index 00000000..6231e576 --- /dev/null +++ b/rules/gather/GATHER-DEVICE-007.json @@ -0,0 +1,21 @@ +{ + "$schema": "../schema/gather-rule.schema.json", + "ruleId": "GATHER-DEVICE-007", + "title": "Collect Entra operational log on pending user affinity (event 1098)", + "description": "Collects the most recent Entra token-broker operational events with ID 1098 from Microsoft-Windows-AAD/Operational the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending). Captures the OS-side token-broker record at exactly the point where ANALYZE-ID-004 draws its evidence. The event log collector filters on one event ID per rule; GATHER-DEVICE-008 collects event 1097 from the same channel.", + "category": "device", + "version": "1.0.0", + "author": "Autopilot Monitor", + "enabled": true, + "collectorType": "eventlog", + "target": "Microsoft-Windows-AAD/Operational", + "parameters": { + "eventId": "1098", + "maxEntries": "20" + }, + "trigger": "on_event", + "triggerEventType": "entra_user_affinity_pending", + "outputEventType": "gather_aad_operational_events", + "outputSeverity": "Warning", + "tags": ["device", "entra", "hybrid"] +} diff --git a/rules/gather/GATHER-DEVICE-008.json b/rules/gather/GATHER-DEVICE-008.json new file mode 100644 index 00000000..6b3fc25f --- /dev/null +++ b/rules/gather/GATHER-DEVICE-008.json @@ -0,0 +1,21 @@ +{ + "$schema": "../schema/gather-rule.schema.json", + "ruleId": "GATHER-DEVICE-008", + "title": "Collect Entra operational log on pending user affinity (event 1097)", + "description": "Collects the most recent Entra token-broker operational events with ID 1097 from Microsoft-Windows-AAD/Operational the moment the agent reports that the signed-in user still has no Entra user token (entra_user_affinity_pending). Captures the OS-side token-broker record at exactly the point where ANALYZE-ID-004 draws its evidence. The event log collector filters on one event ID per rule; GATHER-DEVICE-007 collects event 1098 from the same channel.", + "category": "device", + "version": "1.0.0", + "author": "Autopilot Monitor", + "enabled": true, + "collectorType": "eventlog", + "target": "Microsoft-Windows-AAD/Operational", + "parameters": { + "eventId": "1097", + "maxEntries": "20" + }, + "trigger": "on_event", + "triggerEventType": "entra_user_affinity_pending", + "outputEventType": "gather_aad_operational_events", + "outputSeverity": "Warning", + "tags": ["device", "entra", "hybrid"] +} diff --git a/rules/schema/analyze-rule.schema.json b/rules/schema/analyze-rule.schema.json index f0337db2..b408a44d 100644 --- a/rules/schema/analyze-rule.schema.json +++ b/rules/schema/analyze-rule.schema.json @@ -168,7 +168,7 @@ }, "source": { "type": "string", - "description": "Source of the signal.", + "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from an IME-log timestamp whose sourceOffsetOrigin is reader-zone-fallback (writer timezone unknown to the agent): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback.", "enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation", "clock_skew"] }, "skewMetric": { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/EventTypeConstantGuardTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/EventTypeConstantGuardTests.cs index 1a85951b..17de37a3 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/EventTypeConstantGuardTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/EventTypeConstantGuardTests.cs @@ -34,6 +34,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests new Regex("\\[\"eventType\"\\]\\s*=\\s*\"([a-z][a-z0-9_]*)\"", RegexOptions.Compiled), }; + // Multi-line callback shape (2026-09-04, D-072 gap): `OnTraceEvent?.Invoke(` at the end + // of one line, the event-type literal alone on the NEXT line. The single-line patterns + // above never saw `desktop_real_user_detected` / `desktop_excluded_user` this way. + private static readonly Regex InvokeOpener = new Regex("\\.Invoke\\(\\s*$", RegexOptions.Compiled); + private static readonly Regex BareLiteralLine = new Regex("^\\s*\"([a-z][a-z0-9_]*)\"\\s*,?\\s*$", RegexOptions.Compiled); + // The reducer/param key name itself ("eventType") and the like are not event types. private static readonly HashSet NotEventTypes = new(StringComparer.Ordinal) { @@ -59,33 +65,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests Assert.True(Directory.Exists(full), $"V2 source dir not found: {full}"); foreach (var file in EnumerateSourceFiles(full)) - { - var lines = File.ReadAllLines(file); - for (int i = 0; i < lines.Length; i++) - { - var line = lines[i]; - var trimmed = line.TrimStart(); - - // Skip comments and const DEFINITIONS (Constants/DeadlineNames key names etc.). - if (trimmed.StartsWith("//") || trimmed.StartsWith("*") || trimmed.StartsWith("///")) - continue; - if (line.Contains("const ")) continue; - - foreach (var pattern in EmitPatterns) - { - foreach (Match m in pattern.Matches(line)) - { - var literal = m.Groups[1].Value; - if (NotEventTypes.Contains(literal)) continue; - if (!known.Contains(literal)) - { - offenders.Add( - $"{Path.GetFileName(file)}:{i + 1} \"{literal}\" -> {line.Trim()}"); - } - } - } - } - } + offenders.AddRange(FindOffenders(Path.GetFileName(file), File.ReadAllLines(file), known)); } Assert.True( @@ -95,6 +75,65 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests string.Join("\n ", offenders)); } + [Fact] + public void Guard_detects_multiline_Invoke_literal() + { + // Mutation proof for the multi-line shape: a synthetic emit site with an unknown + // literal on the line after `OnTraceEvent?.Invoke(` must be reported; the same + // shape with a known type must not. + var known = new HashSet(StringComparer.Ordinal) { "desktop_arrived" }; + string[] bad = + { + " OnTraceEvent?.Invoke(", + " \"desktop_not_a_real_type\",", + " $\"Real user desktop detected\",", + }; + string[] good = + { + " OnTraceEvent?.Invoke(", + " \"desktop_arrived\",", + }; + + var offender = Assert.Single(FindOffenders("X.cs", bad, known)); + Assert.Contains("desktop_not_a_real_type", offender); + Assert.Empty(FindOffenders("X.cs", good, known)); + } + + private static List FindOffenders(string fileName, string[] lines, HashSet known) + { + var offenders = new List(); + for (int i = 0; i < lines.Length; i++) + { + var line = lines[i]; + var trimmed = line.TrimStart(); + + // Skip comments and const DEFINITIONS (Constants/DeadlineNames key names etc.). + if (trimmed.StartsWith("//") || trimmed.StartsWith("*") || trimmed.StartsWith("///")) + continue; + if (line.Contains("const ")) continue; + + foreach (var pattern in EmitPatterns) + { + foreach (Match m in pattern.Matches(line)) + Check(m.Groups[1].Value, line, i); + } + + if (i > 0 && InvokeOpener.IsMatch(lines[i - 1])) + { + var bare = BareLiteralLine.Match(line); + if (bare.Success) Check(bare.Groups[1].Value, line, i); + } + } + return offenders; + + void Check(string literal, string line, int index) + { + if (NotEventTypes.Contains(literal)) return; + if (!known.Contains(literal)) + offenders.Add($"{fileName}:{index + 1} \"{literal}\" -> {line.Trim()}"); + } + } + /// All string-const values declared on . private static HashSet KnownEventTypes() { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EntraUserAffinityDetectorTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EntraUserAffinityDetectorTests.cs new file mode 100644 index 00000000..6e82fa95 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/EntraUserAffinityDetectorTests.cs @@ -0,0 +1,236 @@ +#nullable enable +using System; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring +{ + /// + /// Entra user affinity after the real-user desktop (2026-09-04, session a7140f98). The + /// contracts that matter: arm only on Hybrid devices and only at the desktop; the first + /// IME user-token line AFTER the desktop cancels and posts ime_user_token_acquired; + /// token lines from before the desktop (device phase) are ignored; the timer posts + /// entra_user_affinity_pending with the failure codes seen since the desktop; both + /// emissions are single-shot per process. + /// + public sealed class EntraUserAffinityDetectorTests + { + private static readonly DateTime Fixed = new DateTime(2026, 9, 4, 13, 54, 6, DateTimeKind.Utc); + + private sealed class Fixture : IDisposable + { + public TempDirectory Tmp { get; } = new TempDirectory(); + public AgentLogger Logger { get; } + public FakeSignalIngressSink Ingress { get; } = new FakeSignalIngressSink(); + public VirtualClock Clock { get; } = new VirtualClock(Fixed); + public InformationalEventPost Post { get; } + public bool Hybrid { get; set; } = true; + public bool PlaceholderActive { get; set; } = true; + + public Fixture() + { + Logger = new AgentLogger(Tmp.Path, AgentLogLevel.Info); + Post = new InformationalEventPost(Ingress, Clock); + } + + public EntraUserAffinityDetector Build() => new EntraUserAffinityDetector( + Post, Logger, + isHybridJoinProbe: () => Hybrid, + placeholderActiveProbe: () => PlaceholderActive, + delay: TimeSpan.FromMinutes(10), + utcNow: () => Clock.UtcNow); + + public void Dispose() => Tmp.Dispose(); + } + + private static FakeSignalIngressSink.PostedSignal? Find(FakeSignalIngressSink ingress, string eventType) => + ingress.Posted.FirstOrDefault(p => + p.Kind == DecisionSignalKind.InformationalEvent + && p.Payload != null + && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et == eventType); + + [Fact] + public void Desktop_on_hybrid_device_arms() + { + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + + Assert.True(d.IsArmedForTest); + } + + [Fact] + public void Desktop_on_non_hybrid_device_does_not_arm() + { + using var f = new Fixture { Hybrid = false }; + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.TriggerFromTest(); + + Assert.False(d.IsArmedForTest); + Assert.Null(Find(f.Ingress, SharedEventTypes.EntraUserAffinityPending)); + } + + [Fact] + public void Timer_without_token_emits_pending_with_failure_codes() + { + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.NotifyTokenFailureLine("3399548929", f.Clock.UtcNow.AddMinutes(1)); + d.NotifyTokenFailureLine("3399548929", f.Clock.UtcNow.AddMinutes(3)); + d.NotifyTokenFailureLine("3400073247", f.Clock.UtcNow.AddMinutes(5)); + f.Clock.Advance(TimeSpan.FromMinutes(10)); + d.TriggerFromTest(); + + var pending = Find(f.Ingress, SharedEventTypes.EntraUserAffinityPending); + Assert.NotNull(pending); + Assert.Equal("Warning", pending!.Payload![SignalPayloadKeys.Severity]); + Assert.Equal("true", pending.Payload[SignalPayloadKeys.ImmediateUpload]); + Assert.Equal("EntraUserAffinityDetector", pending.Payload[SignalPayloadKeys.Source]); + Assert.Equal("10", pending.Payload["delayMinutes"]); + Assert.Equal("timer_fired", pending.Payload["reason"]); + Assert.Equal("3", pending.Payload["tokenFailureCount"]); + Assert.Equal("3399548929,3400073247", pending.Payload["tokenFailureCodes"]); + Assert.Equal("true", pending.Payload["placeholderActive"]); + Assert.Equal("10.0", pending.Payload["minutesSinceDesktop"]); + Assert.True(d.HasFiredForTest); + Assert.Null(Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)); + } + + [Fact] + public void Token_after_desktop_cancels_and_posts_token_acquired() + { + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.NotifyTokenFailureLine("3399548929", f.Clock.UtcNow.AddSeconds(30)); + var tokenAt = f.Clock.UtcNow.AddMinutes(3.7); + d.NotifyUserTokenAcquired(tokenAt); + f.Clock.Advance(TimeSpan.FromMinutes(10)); + d.TriggerFromTest(); + + var acquired = Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired); + Assert.NotNull(acquired); + Assert.Equal("Info", acquired!.Payload![SignalPayloadKeys.Severity]); + Assert.Equal("3.7", acquired.Payload["minutesAfterDesktop"]); + Assert.Equal("1", acquired.Payload["tokenFailuresBeforeSuccess"]); + Assert.Equal(tokenAt, acquired.OccurredAtUtc); + Assert.True(d.TokenAcquiredPostedForTest); + Assert.False(d.HasFiredForTest); + Assert.Null(Find(f.Ingress, SharedEventTypes.EntraUserAffinityPending)); + } + + [Fact] + public void Token_lines_from_before_the_desktop_are_ignored() + { + // Device-phase token lines ("Failed to get AAD token" is routine there; a success + // can be the device check-in) must neither count nor cancel — the 2-min tolerance + // only covers the desktop poll interval. + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.NotifyUserTokenAcquired(f.Clock.UtcNow.AddMinutes(-20)); + d.NotifyTokenFailureLine("3399548929", f.Clock.UtcNow.AddMinutes(-15)); + f.Clock.Advance(TimeSpan.FromMinutes(10)); + d.TriggerFromTest(); + + Assert.Null(Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)); + var pending = Find(f.Ingress, SharedEventTypes.EntraUserAffinityPending); + Assert.NotNull(pending); + Assert.Equal("0", pending!.Payload!["tokenFailureCount"]); + Assert.Equal(string.Empty, pending.Payload["tokenFailureCodes"]); + } + + [Fact] + public void Token_within_desktop_poll_tolerance_counts_as_after_desktop() + { + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.NotifyUserTokenAcquired(f.Clock.UtcNow.AddSeconds(-90)); + + Assert.NotNull(Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)); + Assert.Equal("0.0", Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)!.Payload!["minutesAfterDesktop"]); + } + + [Fact] + public void Token_without_arm_is_ignored() + { + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyUserTokenAcquired(f.Clock.UtcNow); + + Assert.Null(Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)); + } + + [Fact] + public void Pending_fires_once_and_a_late_token_still_resolves_it_once() + { + // A token that arrives AFTER the warning is the most useful thing the timeline can + // show ("affinity came late") and lets the backend rule drop the finding — so it is + // posted, but like the warning only once per process. + using var f = new Fixture(); + using var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.NotifyRealUserDesktop(); + f.Clock.Advance(TimeSpan.FromMinutes(10)); + d.TriggerFromTest(); + d.TriggerFromTest(); + d.NotifyUserTokenAcquired(f.Clock.UtcNow); + d.NotifyUserTokenAcquired(f.Clock.UtcNow.AddMinutes(1)); + + Assert.Single(f.Ingress.Posted, p => + p.Payload != null && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et == SharedEventTypes.EntraUserAffinityPending); + Assert.Single(f.Ingress.Posted, p => + p.Payload != null && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et == SharedEventTypes.ImeUserTokenAcquired); + Assert.Equal("10.0", Find(f.Ingress, SharedEventTypes.ImeUserTokenAcquired)!.Payload!["minutesAfterDesktop"]); + } + + [Fact] + public void Hybrid_probe_throwing_does_not_arm() + { + using var f = new Fixture(); + using var d = new EntraUserAffinityDetector( + f.Post, f.Logger, + isHybridJoinProbe: () => throw new InvalidOperationException("registry"), + utcNow: () => f.Clock.UtcNow); + + d.NotifyRealUserDesktop(); + + Assert.False(d.IsArmedForTest); + } + + [Fact] + public void Dispose_after_arm_does_not_throw_and_blocks_emission() + { + using var f = new Fixture(); + var d = f.Build(); + + d.NotifyRealUserDesktop(); + d.Dispose(); + d.TriggerFromTest(); + + Assert.Null(Find(f.Ingress, SharedEventTypes.EntraUserAffinityPending)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HelloTrackerImmediateUploadTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HelloTrackerImmediateUploadTests.cs index 3453b3a9..e1e4cbed 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HelloTrackerImmediateUploadTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HelloTrackerImmediateUploadTests.cs @@ -73,6 +73,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring Assert.Equal("true", info.Payload![SignalPayloadKeys.ImmediateUpload]); } + [Theory] + [InlineData(304, "join phase")] + [InlineData(305, "authentication phase")] + public void ProcessHelloEvent_304_305_emit_device_registration_event_with_immediate_upload(int eventId, string phaseLabel) + { + // Hybrid affinity companion (2026-09-04): UDR 304/305 ride the already-armed + // watcher and surface as device_registration_event — a Warning, flushed at once, + // and never a Hello completion. + using var f = new Fixture(); + + f.Tracker.ProcessHelloEvent(eventId, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: false); + + var info = f.InfoEvent("device_registration_event"); + Assert.Equal("Warning", info.Payload![SignalPayloadKeys.Severity]); + Assert.Equal("true", info.Payload[SignalPayloadKeys.ImmediateUpload]); + Assert.Contains(phaseLabel, info.Payload[SignalPayloadKeys.Message]); + Assert.DoesNotContain(f.Ingress.Posted, p => + p.Payload != null && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et.StartsWith("hello_provisioning")); + } + [Fact] public void ProcessHelloEvent_358_willlaunch_is_suppressed() { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HybridLoginPendingDetectorTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HybridLoginPendingDetectorTests.cs index 5ea0dfc1..0532e2f7 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HybridLoginPendingDetectorTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/HybridLoginPendingDetectorTests.cs @@ -194,6 +194,58 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring Assert.NotNull(FindHybridLoginPending(f.Ingress)); } + // ============================================================================ + // Real-user desktop cancel path (2026-09-04, session a7140f98) + // ============================================================================ + + [Fact] + public void Real_user_desktop_after_Arm_cancels_emission() + { + using var f = new Fixture(); + using var detector = new HybridLoginPendingDetector(f.Watcher, f.Post, f.Logger); + + detector.Arm(); + detector.NotifyRealUserDesktop(); + detector.TriggerFromTest(); + + Assert.True(detector.IsCancelledByDesktopForTest); + Assert.False(detector.HasFiredForTest); + Assert.Null(FindHybridLoginPending(f.Ingress)); + } + + [Fact] + public void Real_user_desktop_before_Arm_short_circuits_Arm() + { + // The DAD first poll runs seconds after start; the arm request comes from the + // runtime host slightly later. A desktop seen first must make the arm a no-op. + using var f = new Fixture(); + using var detector = new HybridLoginPendingDetector(f.Watcher, f.Post, f.Logger); + + detector.NotifyRealUserDesktop(); + detector.Arm(); + detector.TriggerFromTest(); + + Assert.False(detector.IsArmedForTest); + Assert.Null(FindHybridLoginPending(f.Ingress)); + } + + [Fact] + public void Emission_reports_desktop_absence_and_placeholder_as_fact() + { + using var f = new Fixture(); + using var detector = new HybridLoginPendingDetector(f.Watcher, f.Post, f.Logger); + + detector.Arm(); + detector.TriggerFromTest(); + + var info = FindHybridLoginPending(f.Ingress); + Assert.NotNull(info); + Assert.Equal("false", info!.Payload!["realUserDesktopSeen"]); + Assert.Equal("false", info.Payload["placeholderActive"]); // watcher never saw JoinInfo in this fixture + Assert.Contains("no real-user desktop", info.Payload[SignalPayloadKeys.Message]); + Assert.DoesNotContain("placeholder still active", info.Payload[SignalPayloadKeys.Message]); + } + // ============================================================================ // Lifecycle / Dispose // ============================================================================ diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogEraPreScanTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogEraPreScanTests.cs new file mode 100644 index 00000000..099ef83c --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogEraPreScanTests.cs @@ -0,0 +1,215 @@ +#nullable enable +using System; +using System.Collections.Generic; +using System.IO; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime +{ + /// + /// Backlog era anchoring (2026-09-04, session a7140f98). The property under test: the + /// bootstrap execution record — stdout in AgentExecutor.log, policy result in the service + /// log — measured against the install marker anchors exactly the era it sits in; a SKIP + /// re-run, a missing marker, an MSI bootstrap and an off-grid residual anchor nothing; the + /// anchor never crosses an "EMS Agent Started" boundary; sibling files join by local time + /// only while the service eras are unambiguous. + /// + public sealed class ImeLogEraPreScanTests + { + private static readonly DateTime Deployed = new DateTime(2026, 9, 4, 13, 31, 49, 100, DateTimeKind.Utc); + private static readonly TimeSpan Pacific = TimeSpan.FromHours(-7); + private static readonly TimeSpan Eastern = TimeSpan.FromHours(-4); + private const string PolicyId = "93d9df23-1111-2222-3333-444455556666"; + + private static string Entry(string message, DateTime utcInstant, TimeSpan writerOffset) + { + var local = utcInstant + writerOffset; + return $""; + } + + private static string ScriptStart(DateTime utc, TimeSpan offset) => + Entry($@"Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_{PolicyId}.ps1", utc, offset); + + private static string BootstrapStdout(DateTime utc, TimeSpan offset, string tail = "===== Bootstrap Completed Successfully =====") => + Entry("write output done. output = ===== Autopilot Monitor Bootstrap Started =====\nBootstrap script version: v2.0\nAgent install mode completed successfully\n" + tail + ", error = ", utc, offset); + + private static string PolicyResult(DateTime utc, TimeSpan offset, string policyId = PolicyId) => + Entry($"[PowerShell] User Id = 00000000-0000-0000-0000-000000000000, Policy id = {policyId}, policy result = Success", utc, offset); + + private static string ServiceStarted(DateTime utc, TimeSpan offset) => Entry("EMS Agent Started", utc, offset); + + private sealed class Fixture : IDisposable + { + public TempDirectory Tmp { get; } = new TempDirectory(); + private readonly List _inputs = new List(); + + public string Write(string fileName, params string[] entries) + { + var path = Path.Combine(Tmp.Path, fileName); + File.WriteAllText(path, string.Join(Environment.NewLine, entries) + Environment.NewLine); + _inputs.Add(new ImeLogEraPreScan.ScanInput(path, 0)); + return path; + } + + public long OffsetOfLine(string fileName, int lineIndex) + { + // Entries are written line by line; the byte offset of entry N is the sum of the + // preceding lines (CRLF-agnostic through Environment.NewLine). + var path = Path.Combine(Tmp.Path, fileName); + var lines = File.ReadAllLines(path); + long offset = 0; + for (var i = 0; i < lineIndex; i++) + offset += System.Text.Encoding.UTF8.GetByteCount(lines[i]) + Environment.NewLine.Length; + return offset; + } + + public CmTraceEraTable Build(DateTime? deployed) => + ImeLogEraPreScan.Build(_inputs, deployed, ImeLogTracker.MaxEntryBytes, null); + + public void Dispose() => Tmp.Dispose(); + } + + [Fact] + public void Bootstrap_record_anchors_service_era_and_executor_block_only_within_their_boundaries() + { + using var f = new Fixture(); + f.Write("AgentExecutor.log", + ScriptStart(Deployed.AddSeconds(-20), Pacific), + BootstrapStdout(Deployed.AddMilliseconds(200), Pacific), + Entry("Adding argument powershell with value C:\\x\\Policies\\Scripts\\u_aaaaaaaa-0000-0000-0000-000000000000.ps1", Deployed.AddMinutes(5), Pacific), + Entry("write output done. output = other script, error = ", Deployed.AddMinutes(5).AddSeconds(2), Pacific)); + f.Write("IntuneManagementExtension.log", + Entry("In EspPhase: DeviceSetup", Deployed.AddMinutes(-1), Pacific), // line 0, era 0 + PolicyResult(Deployed.AddMilliseconds(260), Pacific), // line 1, anchor + Entry("In EspPhase: DeviceSetup", Deployed.AddMinutes(10), Pacific), // line 2, era 0 + ServiceStarted(Deployed.AddMinutes(20), Eastern), // line 3, era 1 (post-boot, new zone) + Entry("Successfully get the token", Deployed.AddMinutes(21), Eastern)); // line 4, era 1 + + var table = f.Build(Deployed); + + Assert.Equal(2, table.AnchoredEraCount); + Assert.False(table.TransferAmbiguous); + + // Service era 0: every offset before "EMS Agent Started" resolves to the Pacific offset. + Assert.True(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 0), out var off0, out var kind0)); + Assert.Equal(Pacific, off0); + Assert.Equal(ImeLogEraPreScan.AnchorKindBootstrapPolicyResult, kind0); + Assert.True(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 2), out var off2, out _)); + Assert.Equal(Pacific, off2); + + // Era 1 has no anchor of its own — the Pacific anchor must not leak across the boundary. + Assert.False(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 3), out _, out _)); + Assert.False(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 4), out _, out _)); + + // Executor: only the bootstrap execution block is anchored, not the next script's block. + Assert.True(table.TryResolveByOffset("AgentExecutor.log", f.OffsetOfLine("AgentExecutor.log", 0), out var offX, out var kindX)); + Assert.Equal(Pacific, offX); + Assert.Equal(ImeLogEraPreScan.AnchorKindBootstrapStdout, kindX); + Assert.False(table.TryResolveByOffset("AgentExecutor.log", f.OffsetOfLine("AgentExecutor.log", 5), out _, out _)); + + // Transfer for in-process sibling files: a local time inside era 0's range resolves, + // one inside era 1's range does not. + Assert.True(table.TryResolveByLocalTime(Deployed.AddMinutes(5) + Pacific, out var offT, out var kindT)); + Assert.Equal(Pacific, offT); + Assert.EndsWith("/service-era-transfer", kindT); + Assert.False(table.TryResolveByLocalTime(Deployed.AddMinutes(25) + Eastern, out _, out _)); + } + + [Fact] + public void Without_deployed_marker_nothing_is_anchored() + { + using var f = new Fixture(); + f.Write("AgentExecutor.log", ScriptStart(Deployed.AddSeconds(-20), Pacific), BootstrapStdout(Deployed.AddMilliseconds(200), Pacific)); + f.Write("IntuneManagementExtension.log", PolicyResult(Deployed.AddMilliseconds(260), Pacific)); + + var table = f.Build(null); + + Assert.Equal(0, table.AnchoredEraCount); + } + + [Fact] + public void Msi_bootstrap_without_stdout_record_anchors_nothing() + { + // The MSI runner never passes through AgentExecutor; without the policy id the + // service log's result lines cannot be told apart from any other script's. + using var f = new Fixture(); + f.Write("AgentExecutor.log", Entry("Adding argument powershell with value C:\\x\\Policies\\Scripts\\u_aaaaaaaa-0000-0000-0000-000000000000.ps1", Deployed.AddMinutes(3), Pacific)); + f.Write("IntuneManagementExtension.log", PolicyResult(Deployed.AddMilliseconds(260), Pacific)); + + var table = f.Build(Deployed); + + Assert.Equal(0, table.AnchoredEraCount); + } + + [Fact] + public void Skip_rerun_record_is_never_offered_and_first_record_off_grid_anchors_nothing() + { + // The install run is the FIRST bootstrap record; a SKIP re-run 15 minutes later + // would round onto the grid with zero residual and anchor a wrong offset. + using var f = new Fixture(); + f.Write("AgentExecutor.log", + ScriptStart(Deployed.AddMinutes(-9), Pacific), + BootstrapStdout(Deployed.AddMinutes(-8), Pacific), // first record: residual 8 min → rejected + ScriptStart(Deployed.AddMinutes(15).AddSeconds(-2), Pacific), + BootstrapStdout(Deployed.AddMinutes(15), Pacific)); // would be a perfect (wrong) grid hit + f.Write("IntuneManagementExtension.log", + PolicyResult(Deployed.AddMinutes(-8), Pacific), + PolicyResult(Deployed.AddMinutes(15), Pacific)); + + var table = f.Build(Deployed); + + Assert.Equal(0, table.AnchoredEraCount); + } + + [Fact] + public void Service_era_continues_across_a_log_rotation() + { + using var f = new Fixture(); + f.Write("AgentExecutor.log", ScriptStart(Deployed.AddSeconds(-20), Pacific), BootstrapStdout(Deployed.AddMilliseconds(200), Pacific)); + f.Write("IntuneManagementExtension-20260904-133000.log", + PolicyResult(Deployed.AddMilliseconds(260), Pacific), + Entry("In EspPhase: DeviceSetup", Deployed.AddMinutes(2), Pacific)); + f.Write("IntuneManagementExtension.log", + Entry("In EspPhase: DeviceSetup", Deployed.AddMinutes(12), Pacific), // same process, rotated file + ServiceStarted(Deployed.AddMinutes(20), Eastern)); + + var table = f.Build(Deployed); + + Assert.True(table.TryResolveByOffset("IntuneManagementExtension.log", 0, out var off, out _)); + Assert.Equal(Pacific, off); + Assert.False(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 1), out _, out _)); + } + + [Fact] + public void Overlapping_service_era_local_ranges_disable_the_transfer() + { + // A westward zone change between two service starts makes era 1 start "before" + // era 0 in local time; the sibling-file transfer must refuse rather than guess. + using var f = new Fixture(); + f.Write("AgentExecutor.log", ScriptStart(Deployed.AddSeconds(-20), TimeSpan.FromHours(2)), BootstrapStdout(Deployed.AddMilliseconds(200), TimeSpan.FromHours(2))); + f.Write("IntuneManagementExtension.log", + ServiceStarted(Deployed.AddMinutes(-30), TimeSpan.FromHours(2)), + PolicyResult(Deployed.AddMilliseconds(260), TimeSpan.FromHours(2)), + ServiceStarted(Deployed.AddMinutes(20), TimeSpan.FromHours(-7))); + + var table = f.Build(Deployed); + + Assert.True(table.TransferAmbiguous); + Assert.False(table.TryResolveByLocalTime(Deployed.AddMinutes(5) + TimeSpan.FromHours(2), out _, out _)); + // Offset-based lookup is unaffected. + Assert.True(table.TryResolveByOffset("IntuneManagementExtension.log", f.OffsetOfLine("IntuneManagementExtension.log", 1), out var off, out _)); + Assert.Equal(TimeSpan.FromHours(2), off); + } + + [Fact] + public void Deployment_marker_parses_roundtrip_utc() + { + Assert.Equal(Deployed, AutopilotMonitor.Agent.V2.Core.Security.DeploymentMarker.Parse("2026-09-04T13:31:49.1000000Z")); + Assert.Null(AutopilotMonitor.Agent.V2.Core.Security.DeploymentMarker.Parse("")); + Assert.Null(AutopilotMonitor.Agent.V2.Core.Security.DeploymentMarker.Parse("not a date")); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerEraAnchoringTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerEraAnchoringTests.cs new file mode 100644 index 00000000..9c0bad46 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerEraAnchoringTests.cs @@ -0,0 +1,171 @@ +#nullable enable +using System; +using System.Collections.Generic; +using System.IO; +using System.Threading; +using System.Threading.Tasks; +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 +{ + /// + /// End-to-end through the tracker: a restart/first-sight backlog whose pre-reboot era was + /// written under the OOBE default zone (a7140f98: Pacific) while the agent believes the + /// zone Windows set later (Eastern). With the bootstrap record anchoring that era, every + /// pre-reboot line resolves to its true instant with origin era-anchored; the + /// post-reboot era without an anchor keeps the marked fallback; in-process sibling files + /// join by local time; a fresh pass still self-anchors per line. + /// + public sealed class ImeLogTrackerEraAnchoringTests + { + private static readonly DateTime Deployed = new DateTime(2026, 9, 4, 13, 31, 49, 100, DateTimeKind.Utc); + private static readonly TimeSpan Pacific = TimeSpan.FromHours(-7); + private static readonly TimeSpan Eastern = TimeSpan.FromHours(-4); + private const string PolicyId = "93d9df23-1111-2222-3333-444455556666"; + + private static List Patterns() => new List + { + new ImeLogPattern + { + PatternId = "T-ALL", Category = "always", Enabled = true, + Pattern = @"marker (?\d+)", + Action = "noop", + Parameters = new Dictionary(), + }, + }; + + private static string Entry(string message, DateTime utcInstant, TimeSpan writerOffset) + { + var local = utcInstant + writerOffset; + return $""; + } + + private sealed class Harness : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + public ImeLogTracker Tracker { get; } + public DateTime Now { get; set; } = Deployed.AddMinutes(30); + public List<(string Message, DateTime? Ts, CmTraceOffsetOrigin Origin, int? Offset, string Anchor)> Resolved { get; } = + new List<(string, DateTime?, CmTraceOffsetOrigin, int?, string)>(); + + public Harness() + { + Tracker = new ImeLogTracker( + logFolder: _tmp.Path, + patterns: Patterns(), + logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info)); + Tracker.UtcNowProvider = () => Now; + Tracker.DeployedUtcProvider = () => Deployed; + Tracker.OnPatternMatched += _ => Resolved.Add(( + Tracker.LastMatchedPatternId ?? string.Empty, + Tracker.LastMatchedLogTimestamp, + Tracker.LastMatchedSourceOffsetOrigin, + Tracker.LastMatchedSourceOffsetMinutes, + Tracker.LastMatchedEraAnchorKind)); + } + + public void Append(string fileName, params string[] lines) + => File.AppendAllText(Path.Combine(_tmp.Path, fileName), string.Join(Environment.NewLine, lines) + Environment.NewLine); + + public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None); + + public void Dispose() + { + Tracker.Dispose(); + _tmp.Dispose(); + } + } + + [Fact] + public async Task Backlog_lines_of_the_bootstrap_era_resolve_through_the_anchor_and_the_next_era_stays_on_fallback() + { + using var h = new Harness(); + h.Append("AgentExecutor.log", + Entry($@"Adding argument powershell with value C:\x\Policies\Scripts\u_{PolicyId}.ps1", Deployed.AddSeconds(-20), Pacific), + Entry("write output done. output = ===== Autopilot Monitor Bootstrap Started =====\n===== Bootstrap Completed Successfully =====, error = ", Deployed.AddMilliseconds(200), Pacific), + Entry("marker 10", Deployed.AddSeconds(1), Pacific)); + h.Append("IntuneManagementExtension.log", + Entry("marker 1", Deployed.AddMinutes(-1), Pacific), + Entry($"[PowerShell] User Id = 00000000-0000-0000-0000-000000000000, Policy id = {PolicyId}, policy result = Success", Deployed.AddMilliseconds(260), Pacific), + Entry("marker 2", Deployed.AddMinutes(10), Pacific), + Entry("EMS Agent Started", Deployed.AddMinutes(20), Eastern), + Entry("marker 3", Deployed.AddMinutes(21), Eastern)); + h.Append("AppWorkload.log", + Entry("marker 4", Deployed.AddMinutes(5), Pacific), + Entry("marker 5", Deployed.AddMinutes(25), Eastern)); + + h.Tracker.PreScanEras(); + await h.Pass(); // first sight: backlog, never fresh + + var byMarker = new Dictionary(); + foreach (var r in h.Resolved) byMarker[r.Message] = r; + Assert.Equal(6, h.Resolved.Count); + + // Marker text is the pattern id (T-ALL) — index by resolution order instead. + var r1 = h.Resolved[0]; // AgentExecutor marker 10 (files sort: AgentExecutor < AppWorkload < IntuneManagementExtension) + Assert.Equal(CmTraceOffsetOrigin.EraAnchored, r1.Origin); + Assert.Equal(Deployed.AddSeconds(1), r1.Ts); + Assert.Equal(-420, r1.Offset); + Assert.Equal(ImeLogEraPreScan.AnchorKindBootstrapStdout, r1.Anchor); + + var r4 = h.Resolved[1]; // AppWorkload marker 4 — transfer by local time into the service era + Assert.Equal(CmTraceOffsetOrigin.EraAnchored, r4.Origin); + Assert.Equal(Deployed.AddMinutes(5), r4.Ts); + Assert.EndsWith("/service-era-transfer", r4.Anchor); + + var r5 = h.Resolved[2]; // AppWorkload marker 5 — post-boot era, unanchored + Assert.Equal(CmTraceOffsetOrigin.None, r5.Origin); + Assert.Equal(string.Empty, r5.Anchor); + + var rm1 = h.Resolved[3]; // IME marker 1 + Assert.Equal(CmTraceOffsetOrigin.EraAnchored, rm1.Origin); + Assert.Equal(Deployed.AddMinutes(-1), rm1.Ts); + Assert.Equal(ImeLogEraPreScan.AnchorKindBootstrapPolicyResult, rm1.Anchor); + + var rm2 = h.Resolved[4]; // IME marker 2 + Assert.Equal(CmTraceOffsetOrigin.EraAnchored, rm2.Origin); + Assert.Equal(Deployed.AddMinutes(10), rm2.Ts); + + var rm3 = h.Resolved[5]; // IME marker 3 — after "EMS Agent Started", no anchor + Assert.Equal(CmTraceOffsetOrigin.None, rm3.Origin); + } + + [Fact] + public async Task Fresh_lines_still_self_anchor_after_the_pre_scan() + { + using var h = new Harness(); + h.Append("IntuneManagementExtension.log", Entry("marker 1", h.Now, Eastern)); + h.Tracker.PreScanEras(); + await h.Pass(); + + h.Now = h.Now.AddSeconds(10); + var writtenAt = h.Now.AddMilliseconds(-80); + h.Append("IntuneManagementExtension.log", Entry("marker 2", writtenAt, Eastern)); + await h.Pass(); + + var last = h.Resolved[h.Resolved.Count - 1]; + Assert.Equal(CmTraceOffsetOrigin.LineAnchored, last.Origin); + Assert.Equal(writtenAt, last.Ts); + Assert.Equal(string.Empty, last.Anchor); + } + + [Fact] + public async Task Without_marker_the_backlog_keeps_the_reader_zone_fallback() + { + using var h = new Harness(); + h.Tracker.DeployedUtcProvider = () => null; + h.Append("IntuneManagementExtension.log", Entry("marker 1", Deployed.AddMinutes(-1), Pacific)); + h.Tracker.PreScanEras(); + await h.Pass(); + + Assert.Single(h.Resolved); + Assert.Equal(CmTraceOffsetOrigin.None, h.Resolved[0].Origin); + Assert.Equal(0, h.Tracker.EraTable.AnchoredEraCount); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerTokenLineCallbackTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerTokenLineCallbackTests.cs new file mode 100644 index 00000000..6b88b912 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerTokenLineCallbackTests.cs @@ -0,0 +1,115 @@ +using System; +using System.Collections.Generic; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Shared.Models; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime +{ + /// + /// Raw per-line token callbacks for the Entra user-affinity detector (2026-09-04). + /// OnUserTokenAcquired fires on EVERY IME-TOKEN-SUCCESS line — independent of the + /// phase-change dedup that swallows the second AccountSetup detection — and + /// OnTokenFailureLine on every failure line; both honour the historic-replay gate. + /// + public sealed class ImeLogTrackerTokenLineCallbackTests + { + private static readonly DateTime Now = new DateTime(2026, 9, 4, 14, 0, 0, DateTimeKind.Utc); + + private static List Patterns() => new List + { + new ImeLogPattern + { + PatternId = "IME-TOKEN-SUCCESS", Category = "always", Enabled = true, + Pattern = "^Successfully get the token", + Action = "espPhaseDetected", + Parameters = new Dictionary { ["phase"] = "AccountSetup" }, + }, + new ImeLogPattern + { + PatternId = "IME-TOKEN-FAILURE", Category = "always", Enabled = true, + Pattern = @"^Failed to get AAD token\..*?errorCode = (?.*?)$", + Action = "imeTokenFailure", + Parameters = new Dictionary(), + }, + }; + + private static ImeLogTracker Build(TempDirectory tmp) + { + var tracker = new ImeLogTracker( + logFolder: tmp.Path, + patterns: Patterns(), + logger: new AgentLogger(tmp.Path, AgentLogLevel.Info)); + tracker.UtcNowProvider = () => Now; + return tracker; + } + + private const string Success = "Successfully get the token with client id fc0f3af4-6835-4174-b806-f7db311fd2f3 and resource id 26a4ae64-5862-427f-a9b0-044e62572a4f"; + private const string Failure = "Failed to get AAD token. len = 34 using client id fc0f3af4-6835-4174-b806-f7db311fd2f3 and resource id 26a4ae64-5862-427f-a9b0-044e62572a4f, errorCode = 3399548929"; + + [Fact] + public void Every_token_success_line_invokes_callback_even_when_phase_is_deduplicated() + { + using var tmp = new TempDirectory(); + using var tracker = Build(tmp); + var tokens = new List(); + tracker.OnUserTokenAcquired = ts => tokens.Add(ts); + + // The phase-change dedup lives in the adapter (AccountSetup is emitted once); + // the raw token callback must fire for BOTH lines regardless. + tracker.ProcessLogMessageForTest(Success, Now.AddMinutes(-6)); + tracker.ProcessLogMessageForTest(Success, Now.AddMinutes(-2)); + + Assert.Equal(2, tokens.Count); + Assert.Equal(Now.AddMinutes(-6), tokens[0]); + Assert.Equal(Now.AddMinutes(-2), tokens[1]); + } + + [Fact] + public void Every_failure_line_invokes_callback_with_error_code() + { + using var tmp = new TempDirectory(); + using var tracker = Build(tmp); + var failures = new List<(string code, DateTime? ts)>(); + tracker.OnTokenFailureLine = (code, ts) => failures.Add((code, ts)); + + tracker.ProcessLogMessageForTest(Failure, Now.AddMinutes(-5)); + tracker.ProcessLogMessageForTest(Failure, Now.AddMinutes(-4)); + + Assert.Equal(2, failures.Count); + Assert.All(failures, f => Assert.Equal("3399548929", f.code)); + Assert.Equal(Now.AddMinutes(-5), failures[0].ts); + } + + [Fact] + public void Historic_replay_lines_do_not_invoke_either_callback() + { + using var tmp = new TempDirectory(); + using var tracker = Build(tmp); + var tokens = 0; + var failures = 0; + tracker.OnUserTokenAcquired = _ => tokens++; + tracker.OnTokenFailureLine = (_, __) => failures++; + + tracker.ProcessLogMessageForTest(Success, Now.AddDays(-3)); + tracker.ProcessLogMessageForTest(Failure, Now.AddDays(-3)); + + Assert.Equal(0, tokens); + Assert.Equal(0, failures); + } + + [Fact] + public void Callback_exception_does_not_break_the_drain() + { + using var tmp = new TempDirectory(); + using var tracker = Build(tmp); + tracker.OnUserTokenAcquired = _ => throw new InvalidOperationException("boom"); + tracker.OnTokenFailureLine = (_, __) => throw new InvalidOperationException("boom"); + + tracker.ProcessLogMessageForTest(Success, Now.AddMinutes(-1)); + tracker.ProcessLogMessageForTest(Failure, Now.AddMinutes(-1)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceEraTable.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceEraTable.cs new file mode 100644 index 00000000..da0d4fcb --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceEraTable.cs @@ -0,0 +1,157 @@ +#nullable enable +using System; +using System.Collections.Generic; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime +{ + /// + /// A writer era: the stretch of log written by ONE process lifetime, i.e. under one + /// timezone belief. For the IME service family (IntuneManagementExtension*.log) an era + /// starts at an "EMS Agent Started" entry and may continue across a log rotation into the + /// next file; for AgentExecutor.log every script execution is its own short-lived process + /// and therefore its own era. An era carries an offset only when an anchor inside it was + /// matched against an instant the agent knows in UTC (). + /// + internal sealed class CmTraceEra + { + /// File segments (file name → [start, end) byte range) that belong to this era, in write order. + public List Segments { get; } = new List(); + + /// Local time of the era's first entry as written (null for a leading era whose start predates the scanned region). + public DateTime? StartLocal { get; set; } + + /// Local time of the next era's first entry (null for the last era). + public DateTime? EndLocal { get; set; } + + /// The writer's UTC offset (local = UTC + offset) when anchored. + public TimeSpan? Offset { get; set; } + + /// What established ("bootstrap-policy-result", "bootstrap-stdout", …). + public string? AnchorKind { get; set; } + + public bool IsAnchored => Offset.HasValue; + } + + internal sealed class CmTraceEraSegment + { + public CmTraceEraSegment(string fileName, long startOffset, long endOffset) + { + FileName = fileName; + StartOffset = startOffset; + EndOffset = endOffset; + } + + public string FileName { get; } + public long StartOffset { get; } + /// long.MaxValue while the era is still open in this file. + public long EndOffset { get; set; } + + public bool Contains(string fileName, long offset) => + string.Equals(FileName, fileName, StringComparison.OrdinalIgnoreCase) + && offset >= StartOffset && offset < EndOffset; + } + + /// + /// Era lookup for backlog lines (2026-09-04, session a7140f98). Two lookups: + /// + /// — the line's own file and byte offset + /// (IME service family and AgentExecutor.log: eras are byte ranges). + /// — transfer for files written by the + /// SAME process as the IME service log but without their own era marker (AppWorkload.log, + /// AppActionProcessor.log: plugins hosted in IntuneManagementExtension.exe, verified in the + /// decompiled build). Within one process every file shares the zone belief, so a local + /// timestamp places the line in the service era whose local range contains it. Disabled + /// entirely when the service eras' local ranges are not monotonic (a westward zone change + /// between two service starts makes the ranges overlap) — ambiguity must never anchor. + /// + /// Everything not resolvable here stays on the marked reader-zone fallback; a partially + /// corrected era is never produced because an anchor applies to a whole era or not at all. + /// + internal sealed class CmTraceEraTable + { + private readonly List _offsetEras = new List(); + private readonly List _serviceEras = new List(); + private bool _transferAmbiguous; + + public IReadOnlyList ServiceEras => _serviceEras; + public bool TransferAmbiguous => _transferAmbiguous; + public int AnchoredEraCount + { + get + { + var n = 0; + foreach (var e in _offsetEras) if (e.IsAnchored) n++; + return n; + } + } + + /// Register an era addressable by (file, offset). Service eras also take part in the local-time transfer. + public void Add(CmTraceEra era, bool isServiceEra) + { + _offsetEras.Add(era); + if (isServiceEra) _serviceEras.Add(era); + } + + /// Call once after all service eras are added: validates the local ranges used by the transfer. + public void Seal() + { + _transferAmbiguous = false; + DateTime? previousStart = null; + foreach (var era in _serviceEras) + { + if (!era.StartLocal.HasValue) continue; + if (previousStart.HasValue && era.StartLocal.Value <= previousStart.Value) + { + _transferAmbiguous = true; + break; + } + previousStart = era.StartLocal; + } + } + + public bool TryResolveByOffset(string fileName, long offset, out TimeSpan writerOffset, out string anchorKind) + { + writerOffset = TimeSpan.Zero; + anchorKind = string.Empty; + if (string.IsNullOrEmpty(fileName) || offset < 0) return false; + + foreach (var era in _offsetEras) + { + if (!era.IsAnchored) continue; + foreach (var seg in era.Segments) + { + if (seg.Contains(fileName, offset)) + { + writerOffset = era.Offset!.Value; + anchorKind = era.AnchorKind ?? string.Empty; + return true; + } + } + } + return false; + } + + public bool TryResolveByLocalTime(DateTime localTimestamp, out TimeSpan writerOffset, out string anchorKind) + { + writerOffset = TimeSpan.Zero; + anchorKind = string.Empty; + if (_transferAmbiguous) return false; + + var local = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified); + foreach (var era in _serviceEras) + { + if (!era.IsAnchored) continue; + // A leading era with unknown start covers everything before its end. + var afterStart = !era.StartLocal.HasValue || local >= era.StartLocal.Value; + var beforeEnd = !era.EndLocal.HasValue || local < era.EndLocal.Value; + if (afterStart && beforeEnd) + { + writerOffset = era.Offset!.Value; + anchorKind = era.AnchorKind + "/service-era-transfer"; + return true; + } + } + return false; + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs index 7b7ad7da..f1a39728 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs @@ -27,6 +27,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// . /// LineAnchored = 3, + + /// + /// A backlog line resolved through its writer ERA: the stretch of log written by one + /// process lifetime, anchored by an entry inside that era whose UTC instant the agent + /// knows exactly (the install marker vs. the IME's own record of the bootstrap script's + /// result — a few hundred milliseconds apart). An anchor applies to a whole era or not + /// at all, never across an "EMS Agent Started" boundary. See ImeLogEraPreScan + /// (2026-09-04, session a7140f98). + /// + EraAnchored = 4, } /// diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogEraPreScan.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogEraPreScan.cs new file mode 100644 index 00000000..04a24a99 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogEraPreScan.cs @@ -0,0 +1,316 @@ +#nullable enable +using System; +using System.Collections.Generic; +using System.IO; +using System.Text; +using System.Text.RegularExpressions; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Shared.Logging; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime +{ + /// + /// Builds the for the backlog the tracker is about to read + /// (2026-09-04, session a7140f98: the IME service wrote the whole device-ESP era under the + /// OOBE default zone, Windows moved the zone before the agent started, and the restart + /// replay put every pre-reboot line three hours early — a 20-minute DeviceSetup became a + /// "blocking app timeout"). + /// + /// Backlog lines can never self-anchor (their age would round onto the offset grid), so an + /// era needs an entry whose UTC instant is known independently. The one such entry every + /// platform-script bootstrap leaves behind is the bootstrap script's own execution: the + /// install marker (HKLM\SOFTWARE\AutopilotMonitor\Deployed, UTC) is written + /// milliseconds before the script exits, and the IME logs that exit twice — AgentExecutor.log + /// records the script's stdout ("Bootstrap Completed Successfully"), and the service log + /// records "[PowerShell] … Policy id = <bootstrap>, policy result = …". Field measurement + /// (4 sessions, 2026-09-04): 0.13–0.28 s between marker and stdout record, 0.02–0.08 s more to + /// the service record — against a 15-minute grid with a 2-minute residual guard. + /// + /// + /// Rules that keep this sound: only the FIRST bootstrap record of each file is offered (a + /// SKIP re-run minutes later could round onto the grid); the residual guard is + /// ; an anchor applies to the whole + /// era between two "EMS Agent Started" entries (service) or one script execution + /// (AgentExecutor) and never beyond; nothing is anchored without a marker (MSI bootstrap, + /// replay tooling). Everything else stays on the marked reader-zone fallback. + /// + /// + internal static class ImeLogEraPreScan + { + internal const string AnchorKindBootstrapStdout = "bootstrap-stdout"; + internal const string AnchorKindBootstrapPolicyResult = "bootstrap-policy-result"; + + private const string ServiceStartedPrefix = "EMS Agent Started"; + private const string ExecutorScriptStartPrefix = "Adding argument powershell with value "; + private const string ExecutorOutputPrefix = "write output done."; + private const string BootstrapInstallRunMarker = "Bootstrap Completed Successfully"; + private const string BootstrapInstallRunMarkerAlt = "Agent install mode completed successfully"; + + private static readonly Regex ExecutorScriptPolicyId = new Regex( + @"Policies\\Scripts\\[a-z0-9\-]+_(?[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12})\.ps1", + RegexOptions.Compiled | RegexOptions.IgnoreCase, TimeSpan.FromSeconds(1)); + + private static readonly Regex ServicePolicyResult = new Regex( + @"^\[PowerShell\] User Id = [a-f0-9\-]+, Policy id = (?[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}), policy result = ", + RegexOptions.Compiled | RegexOptions.IgnoreCase, TimeSpan.FromSeconds(1)); + + private const int MaxEntryLines = 100; + + public sealed class ScanInput + { + public ScanInput(string filePath, long startOffset) + { + FilePath = filePath; + StartOffset = startOffset; + } + + public string FilePath { get; } + public long StartOffset { get; } + } + + public static bool IsServiceLogFile(string fileName) => + fileName.StartsWith("IntuneManagementExtension", StringComparison.OrdinalIgnoreCase) + || fileName.StartsWith("_IntuneManagementExtension", StringComparison.OrdinalIgnoreCase); + + public static bool IsExecutorLogFile(string fileName) => + fileName.StartsWith("AgentExecutor", StringComparison.OrdinalIgnoreCase); + + /// Files written in-process by the IME service without an era marker of their own (transfer by local time). + public static bool IsServiceHostedFile(string fileName) => + fileName.StartsWith("AppWorkload", StringComparison.OrdinalIgnoreCase) + || fileName.StartsWith("AppActionProcessor", StringComparison.OrdinalIgnoreCase); + + /// + /// Scan the given files (sort order = write order; archived before current) from their + /// start offsets to EOF and return the era table. Never throws; a file that cannot be + /// read contributes no eras. + /// + public static CmTraceEraTable Build( + IReadOnlyList files, + DateTime? deployedUtc, + int maxEntryBytes, + AgentLogger? logger) + { + var table = new CmTraceEraTable(); + if (!deployedUtc.HasValue) + { + logger?.Info("ImeLogEraPreScan: no Deployed marker — backlog eras stay on the reader-zone fallback"); + return table; + } + + string? bootstrapPolicyId = null; + + // AgentExecutor first: it is where the bootstrap policy id becomes known. + foreach (var input in files) + { + if (!IsExecutorLogFile(Path.GetFileName(input.FilePath))) continue; + try { ScanExecutorFile(input, deployedUtc.Value, maxEntryBytes, table, ref bootstrapPolicyId, logger); } + catch (Exception ex) { logger?.Debug($"ImeLogEraPreScan: {Path.GetFileName(input.FilePath)} skipped: {ex.Message}"); } + } + + var serviceFiles = new List(); + foreach (var input in files) + if (IsServiceLogFile(Path.GetFileName(input.FilePath))) serviceFiles.Add(input); + + try { ScanServiceFiles(serviceFiles, deployedUtc.Value, maxEntryBytes, table, bootstrapPolicyId, logger); } + catch (Exception ex) { logger?.Debug($"ImeLogEraPreScan: service scan aborted: {ex.Message}"); } + + table.Seal(); + + logger?.Info( + $"ImeLogEraPreScan: {table.AnchoredEraCount} anchored era(s), {table.ServiceEras.Count} service era(s), " + + $"bootstrapPolicyId={(bootstrapPolicyId ?? "(unknown)")}, transfer={(table.TransferAmbiguous ? "ambiguous-disabled" : "enabled")}"); + return table; + } + + private static void ScanExecutorFile( + ScanInput input, DateTime deployedUtc, int maxEntryBytes, CmTraceEraTable table, + ref string? bootstrapPolicyId, AgentLogger? logger) + { + var fileName = Path.GetFileName(input.FilePath); + CmTraceEra? current = null; + string? currentPolicyId = null; + var anchored = false; + + foreach (var e in ReadEntries(input, maxEntryBytes)) + { + if (e.Message.StartsWith(ExecutorScriptStartPrefix, StringComparison.Ordinal)) + { + if (current != null) current.Segments[0].EndOffset = e.Offset; + current = new CmTraceEra(); + current.Segments.Add(new CmTraceEraSegment(fileName, e.Offset, long.MaxValue)); + current.StartLocal = e.HasTimestamp ? e.LocalTimestamp : (DateTime?)null; + table.Add(current, isServiceEra: false); + var m = ExecutorScriptPolicyId.Match(e.Message); + currentPolicyId = m.Success ? m.Groups["id"].Value : null; + continue; + } + + if (anchored || current == null || !e.HasTimestamp) continue; + if (!e.Message.StartsWith(ExecutorOutputPrefix, StringComparison.Ordinal)) continue; + if (e.Message.IndexOf(BootstrapInstallRunMarker, StringComparison.OrdinalIgnoreCase) < 0 + && e.Message.IndexOf(BootstrapInstallRunMarkerAlt, StringComparison.OrdinalIgnoreCase) < 0) + continue; + + // First bootstrap install record of this file, offered once — accepted or not. + anchored = true; + if (CmTraceOffsetCalibrator.TryMeasureOffset(e.LocalTimestamp, deployedUtc, out var offset)) + { + current.Offset = offset; + current.AnchorKind = AnchorKindBootstrapStdout; + if (bootstrapPolicyId == null) bootstrapPolicyId = currentPolicyId; + logger?.Info($"ImeLogEraPreScan: {fileName} bootstrap execution anchored at {offset} (stdout local={e.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}, policy={currentPolicyId ?? "?"})"); + } + else + { + logger?.Info($"ImeLogEraPreScan: {fileName} bootstrap stdout record rejected by the residual guard (local={e.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}, deployed={deployedUtc:HH:mm:ss}Z)"); + if (bootstrapPolicyId == null) bootstrapPolicyId = currentPolicyId; + } + } + } + + private static void ScanServiceFiles( + IReadOnlyList files, DateTime deployedUtc, int maxEntryBytes, CmTraceEraTable table, + string? bootstrapPolicyId, AgentLogger? logger) + { + if (files.Count == 0) return; + + // The leading era: whatever process was writing when the scanned region begins. + var current = new CmTraceEra(); + table.Add(current, isServiceEra: true); + var resultOffered = false; + + foreach (var input in files) + { + var fileName = Path.GetFileName(input.FilePath); + var segment = new CmTraceEraSegment(fileName, input.StartOffset, long.MaxValue); + current.Segments.Add(segment); + + foreach (var e in ReadEntries(input, maxEntryBytes)) + { + if (e.Message.StartsWith(ServiceStartedPrefix, StringComparison.Ordinal)) + { + segment.EndOffset = e.Offset; + var next = new CmTraceEra { StartLocal = e.HasTimestamp ? e.LocalTimestamp : (DateTime?)null }; + current.EndLocal = next.StartLocal; + segment = new CmTraceEraSegment(fileName, e.Offset, long.MaxValue); + next.Segments.Add(segment); + table.Add(next, isServiceEra: true); + current = next; + continue; + } + + if (resultOffered || bootstrapPolicyId == null || !e.HasTimestamp) continue; + if (!e.Message.StartsWith("[PowerShell] User Id = ", StringComparison.Ordinal)) continue; + var m = ServicePolicyResult.Match(e.Message); + if (!m.Success || !string.Equals(m.Groups["id"].Value, bootstrapPolicyId, StringComparison.OrdinalIgnoreCase)) continue; + + // First result record for the bootstrap policy, offered once. + resultOffered = true; + if (CmTraceOffsetCalibrator.TryMeasureOffset(e.LocalTimestamp, deployedUtc, out var offset)) + { + current.Offset = offset; + current.AnchorKind = AnchorKindBootstrapPolicyResult; + logger?.Info($"ImeLogEraPreScan: {fileName} service era anchored at {offset} (policy result local={e.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff})"); + } + else + { + logger?.Info($"ImeLogEraPreScan: {fileName} bootstrap policy result rejected by the residual guard (local={e.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fff}, deployed={deployedUtc:HH:mm:ss}Z)"); + } + } + + // The era continues into the next (newer) file: close this file's segment at EOF. + try { segment.EndOffset = new FileInfo(input.FilePath).Length; } catch { segment.EndOffset = long.MaxValue; } + } + + // The last era stays open in its last file. + var last = current.Segments[current.Segments.Count - 1]; + last.EndOffset = long.MaxValue; + } + + private sealed class ScannedEntry + { + public long Offset; + public bool HasTimestamp; + public DateTime LocalTimestamp; + public string Message = string.Empty; + } + + /// + /// Enumerate CMTrace entries with their file offsets. Same multiline assembly as the + /// tracker's read loop (an AgentExecutor stdout record spans many lines; the closing tag + /// carries the time); oversized or over-long entries are dropped, never partially used. + /// + private static IEnumerable ReadEntries(ScanInput input, int maxEntryBytes) + { + using (var stream = new FileStream(input.FilePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) + { + if (input.StartOffset > 0 && input.StartOffset < stream.Length) + stream.Seek(input.StartOffset, SeekOrigin.Begin); + else if (input.StartOffset >= stream.Length) + yield break; + + var reader = new BoundedLineReader(stream, maxEntryBytes); + StringBuilder? buffer = null; + var bufferLines = 0; + long entryStart = input.StartOffset; + var skipping = false; + + while (true) + { + var line = reader.ReadLineAsync(System.Threading.CancellationToken.None).GetAwaiter().GetResult(); + if (line == null) yield break; + if (buffer == null) entryStart = reader.LastLineStart; + + if (reader.LastLineTruncated) + { + buffer = null; bufferLines = 0; skipping = true; + continue; + } + + if (skipping) + { + if (line.StartsWith("")) skipping = false; + continue; + } + } + + if (buffer != null) + { + buffer.Append('\n').Append(line); + bufferLines++; + if (line.Contains("]LOG]!>")) + { + line = buffer.ToString(); + buffer = null; bufferLines = 0; + } + else if (bufferLines >= MaxEntryLines || buffer.Length >= maxEntryBytes) + { + buffer = null; bufferLines = 0; skipping = true; + continue; + } + else continue; + } + else if (line.StartsWith("")) + { + buffer = new StringBuilder(line); + bufferLines = 1; + continue; + } + + if (!CmTraceLogParser.TryParseLine(line, out var entry) || entry == null) continue; + yield return new ScannedEntry + { + Offset = entryStart, + HasTimestamp = entry.HasTimestamp && !entry.BiasMinutes.HasValue, + LocalTimestamp = entry.LocalTimestamp, + Message = entry.Message ?? string.Empty, + }; + } + } + } + } +} 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 6fe0378b..f1980241 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 @@ -263,6 +263,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // --- Normal processing (single-line or completed multiline) --- CmTraceLogEntry entry; string messageToMatch; + _currentEntryOffset = entryStart; if (CmTraceLogParser.TryParseLine(line, out entry)) { messageToMatch = entry.Message; @@ -312,6 +313,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // flagged as such. if (hadPreviousObservation && calibrationAnchor != null) CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor); + _currentEntryOffset = -1; } } catch (FileNotFoundException) { } @@ -509,6 +511,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime LastMatchedSourceOffsetMinutes = null; LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None; LastMatchedMeasuredWriterOffsetMinutes = null; + LastMatchedEraAnchorKind = string.Empty; } else { @@ -518,6 +521,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime LastMatchedSourceLocalTimestamp = entry.HasTimestamp ? entry.LocalTimestamp : (DateTime?)null; LastMatchedSourceOffsetMinutes = offsetMinutes; LastMatchedSourceOffsetOrigin = origin; + LastMatchedEraAnchorKind = origin == CmTraceOffsetOrigin.EraAnchored ? _lastEraAnchorKind : string.Empty; // Observational: what the calibrator measured for this file, distinct from what // was applied above. @@ -555,7 +559,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // Placed after the staleness gate so a success replayed from a previous // enrollment's log cannot clear a genuine current outage. if (!isStaleReplayLine && string.Equals(pattern.PatternId, "IME-TOKEN-SUCCESS", StringComparison.OrdinalIgnoreCase)) + { ClearPendingTokenFailure(); + // Raw user-token observation for the Entra user-affinity detector (2026-09-04). + // Deliberately NOT routed through espPhaseDetected: that path deduplicates once + // AccountSetup is set, so a FullESP session would never report the token that + // followed the real-user desktop. + try { OnUserTokenAcquired?.Invoke(LastMatchedLogTimestamp); } + catch (Exception ex) { _logger?.Warning($"OnUserTokenAcquired handler threw: {ex.Message}"); } + } try { @@ -617,6 +629,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime case "imetokenfailure": HandleImeTokenFailure(match.Groups["errorCode"]?.Value, message); + // Raw per-line observation (staleness already enforced above via + // AppMutatingActions) — the affinity detector counts failures after + // the real-user desktop; the grace-window Warning stays separate. + try { OnTokenFailureLine?.Invoke(match.Groups["errorCode"]?.Value, LastMatchedLogTimestamp); } + catch (Exception ex) { _logger?.Warning($"OnTokenFailureLine handler threw: {ex.Message}"); } break; case "imeimpersonation": @@ -941,6 +958,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime } } + // ERA ANCHOR (2026-09-04, session a7140f98): a backlog line whose writer era was + // anchored by the bootstrap execution record resolves through that era's offset. + // Whole era or nothing — the anchor never crosses an "EMS Agent Started" boundary, + // and in-process sibling files (AppWorkload, AppActionProcessor) join by local + // time only while the service eras' local ranges are unambiguous. See + // ImeLogEraPreScan for why this is the one anchor a backlog line can trust. + _lastEraAnchorKind = string.Empty; + if (_currentSourceFileName != null && _currentEntryOffset >= 0) + { + TimeSpan eraOffset; + string anchorKind; + var resolved = EraTable.TryResolveByOffset(_currentSourceFileName, _currentEntryOffset, out eraOffset, out anchorKind) + || (ImeLogEraPreScan.IsServiceHostedFile(_currentSourceFileName) + && EraTable.TryResolveByLocalTime(entry.LocalTimestamp, out eraOffset, out anchorKind)); + if (resolved) + { + origin = CmTraceOffsetOrigin.EraAnchored; + offsetMinutes = (int)eraOffset.TotalMinutes; + _lastEraAnchorKind = anchorKind; + return DateTime.SpecifyKind(entry.LocalTimestamp - eraOffset, DateTimeKind.Utc); + } + } + // Fallback for everything not provably fresh: assume the reader's zone, UNIFORMLY. // Wrong in absolute terms whenever the writer held a different belief, but // self-consistent — both ends of a duration are wrong by the same amount, so derived 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 f7228102..0dc54f91 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 @@ -400,6 +400,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// How that offset was arrived at — declared, measured, or neither. public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; } + /// + /// For : which anchor established the era's + /// offset ("bootstrap-policy-result", "bootstrap-stdout", with "/service-era-transfer" + /// when the line came from an in-process sibling file). Empty otherwise. + /// + public string LastMatchedEraAnchorKind { get; internal set; } = string.Empty; + + /// + /// Source of the install marker's UTC instant for the backlog era pre-scan + /// (). Defaults to the registry marker; tests inject. + /// + internal Func DeployedUtcProvider { get; set; } = Security.DeploymentMarker.TryReadDeployedUtc; + + /// Era table built by at ; empty until then. + internal CmTraceEraTable EraTable { get; private set; } = new CmTraceEraTable(); + + // Byte offset of the entry currently being resolved in the read loop (-1 outside it) — + // the key for the era lookup. Set next to _currentSourceFileName. + private long _currentEntryOffset = -1; + private string _lastEraAnchorKind = string.Empty; + /// /// The offset the calibrator MEASURED for the source file, which is not necessarily the /// one applied. @@ -425,6 +446,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // Args: errorCode (may be empty when IME logged none), raw failure line excerpt. // Fired once per distinct errorCode per tracker lifetime (see HandleImeTokenFailure). public Action OnImeTokenFailure { get; set; } + /// + /// Fires on EVERY IME-TOKEN-SUCCESS line that passes the historic-replay gate, with the + /// line's resolved UTC (null when the line carried no timestamp). Unlike + /// (deduplicated once AccountSetup is set) and unlike the + /// grace-window model behind , this is the raw observation: + /// "Successfully get the token" is IntuneTokenManager acquiring the signed-in user's token + /// through WAM, i.e. the only SYSTEM-visible proof of Entra user affinity (2026-09-04). + /// + public Action OnUserTokenAcquired { get; set; } + /// + /// Fires on EVERY IME-TOKEN-FAILURE line that passes the historic-replay gate: + /// errorCode (may be empty) and the line's resolved UTC. Raw observation — the + /// deduplicated Warning stays on . + /// + public Action OnTokenFailureLine { get; set; } // Second arg: the [DO TEL] source log line's timestamp when the DO data came from a // log line, null when the DO collector observed the completion live via polling. The // consumer must stamp poll-driven telemetry with the clock — inheriting an unrelated @@ -839,6 +875,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime ActivatePatterns(_logPhaseIsCurrentPhase, force: true); } + /// + /// Build the backlog era table from the files the first pass will read, each from the + /// position the pass will start at. Never throws — a failure leaves the table empty and + /// every backlog line on the reader-zone fallback, exactly as before. + /// + internal void PreScanEras() + { + try + { + if (!Directory.Exists(_logFolder)) return; + var inputs = new List(); + var files = new List(); + foreach (var filePath in Directory.EnumerateFiles(_logFolder)) + { + if (MatchesLogFilePattern(Path.GetFileName(filePath))) + files.Add(filePath); + } + files.Sort(StringComparer.OrdinalIgnoreCase); + foreach (var filePath in files) + { + var info = new FileInfo(filePath); + if (!info.Exists) continue; + inputs.Add(new ImeLogEraPreScan.ScanInput(filePath, _positionTracker.GetSafePosition(filePath, info.Length))); + } + + DateTime? deployedUtc = null; + try { deployedUtc = DeployedUtcProvider?.Invoke(); } + catch (Exception ex) { _logger.Debug($"ImeLogTracker: Deployed marker read failed: {ex.Message}"); } + + EraTable = ImeLogEraPreScan.Build(inputs, deployedUtc, MaxEntryBytes, _logger); + } + catch (Exception ex) + { + _logger.Warning($"ImeLogTracker: era pre-scan failed — backlog stays on the reader-zone fallback: {ex.Message}"); + EraTable = new CmTraceEraTable(); + } + } + /// /// Starts the background polling task /// @@ -851,6 +925,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // exactly where we left off — no re-parsing, no device-phase bleeding. LoadState(); + // Era anchors for the backlog the first pass is about to read (2026-09-04). Runs + // before the poll loop so every replayed line already finds its era; read-only on + // the position tracker. Replay tooling anchors nothing — its logs did not come from + // this device's bootstrap. + if (!SimulationMode) PreScanEras(); + _cts = new CancellationTokenSource(); var token = _cts.Token; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AadJoinWatcher.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AadJoinWatcher.cs index 5a004648..9c72b885 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AadJoinWatcher.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AadJoinWatcher.cs @@ -67,6 +67,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals public event EventHandler PlaceholderUserDetected; public event EventHandler AadUserJoined; + /// + /// true while a provisioning placeholder (foouser@/autopilot@) is the JoinInfo + /// user and no real user has replaced it. On a Hybrid join this stays true through the + /// whole user sign-in — the AD sign-in never touches JoinInfo — so consumers report it + /// as a fact, never as sign-in evidence (2026-09-04). + /// + internal bool PlaceholderObservedWithoutRealUser + { + get { lock (_stateLock) return _placeholderFired && !_realUserFired; } + } + public AadJoinWatcher(AgentLogger logger) { _logger = logger ?? throw new ArgumentNullException(nameof(logger)); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/DesktopArrivalDetector.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/DesktopArrivalDetector.cs index 4224014d..01f07d9d 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/DesktopArrivalDetector.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/DesktopArrivalDetector.cs @@ -234,7 +234,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals try { OnTraceEvent?.Invoke( - "desktop_excluded_user", + SharedEventTypes.DesktopExcludedUser, $"explorer.exe found but owned by excluded user '{owner}' — not a real user desktop", new Dictionary { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", owner } }); } @@ -250,7 +250,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals try { OnTraceEvent?.Invoke( - "desktop_real_user_detected", + SharedEventTypes.DesktopRealUserDetected, $"Real user desktop detected (explorer.exe PID {proc.Id}, user '[redacted]')", new Dictionary { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", "[redacted]" } }); } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EntraUserAffinityDetector.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EntraUserAffinityDetector.cs new file mode 100644 index 00000000..6445f956 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EntraUserAffinityDetector.cs @@ -0,0 +1,232 @@ +#nullable enable +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Shared.Models; +using SharedConstants = AutopilotMonitor.Shared.Constants; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals +{ + /// + /// Single-shot detector for Entra user affinity on Hybrid Azure AD Join devices + /// (2026-09-04, session a7140f98). After the real user signs in, IME acquires that user's + /// token through WAM and logs "Successfully get the token" (IntuneTokenManager, + /// IME-TOKEN-SUCCESS). That line is the only SYSTEM-visible proof that the user + /// session carries an Entra identity (PRT); a session whose user never gets one shows only + /// "Failed to get AAD token" lines after the desktop. + /// + /// Contract: arms the timer when the device is a Hybrid + /// join (probe injected by the host). The first token success stamped after the desktop + /// cancels the timer and emits ime_user_token_acquired; the timer emits + /// entra_user_affinity_pending with the failure codes observed since the desktop. + /// A token that arrives after the timer fired is still posted once — it tells the + /// timeline (and the backend rule) that affinity came late rather than never. + /// Both emissions happen at most once per agent process — a reboot starts a new process, + /// whose repeat is exactly the confidence signal the backend rule counts. Token lines older + /// than the desktop (minus a small tolerance for the 30 s desktop poll) belong to the + /// device phase and are ignored: they appear in every enrollment. + /// + /// + /// Not a decision signal. Never influences completion. The JoinInfo placeholder is reported + /// as a fact in the payload because it is NOT a login signal on a Hybrid join — the AD + /// sign-in never replaces it; only the later Entra device registration does. + /// + /// + internal sealed class EntraUserAffinityDetector : IDisposable + { + internal const int DefaultDelayMinutes = 10; + internal const string SourceLabel = "EntraUserAffinityDetector"; + /// Token lines this much older than the desktop observation still count as post-desktop. + internal static readonly TimeSpan DesktopPollTolerance = TimeSpan.FromMinutes(2); + + private readonly InformationalEventPost _post; + private readonly AgentLogger _logger; + private readonly Func _isHybridJoinProbe; + private readonly Func? _placeholderActiveProbe; + private readonly Func _utcNow; + private readonly TimeSpan _delay; + private readonly object _lock = new object(); + private readonly List _failureCodesSinceDesktop = new List(); + + private Timer? _timer; + private DateTime? _desktopObservedUtc; + private bool _armed; + private bool _fired; + private bool _tokenAcquiredPosted; + private int _failureCountSinceDesktop; + private int _disposed; + + internal EntraUserAffinityDetector( + InformationalEventPost post, + AgentLogger logger, + Func isHybridJoinProbe, + Func? placeholderActiveProbe = null, + TimeSpan? delay = null, + Func? utcNow = null) + { + _post = post ?? throw new ArgumentNullException(nameof(post)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + _isHybridJoinProbe = isHybridJoinProbe ?? throw new ArgumentNullException(nameof(isHybridJoinProbe)); + _placeholderActiveProbe = placeholderActiveProbe; + _delay = delay ?? TimeSpan.FromMinutes(DefaultDelayMinutes); + _utcNow = utcNow ?? (() => DateTime.UtcNow); + } + + /// + /// The DesktopArrivalDetector resolved explorer.exe under a real (non-placeholder, + /// non-system) user. Arms the timer on Hybrid devices; idempotent; no-op after a + /// token success or after the timer fired. + /// + public void NotifyRealUserDesktop() + { + bool hybrid; + try { hybrid = _isHybridJoinProbe(); } + catch (Exception ex) + { + _logger.Warning($"EntraUserAffinityDetector: hybrid probe threw — not arming: {ex.Message}"); + return; + } + + lock (_lock) + { + if (_disposed != 0 || _armed || _fired || _tokenAcquiredPosted) return; + if (!hybrid) + { + _logger.Debug("EntraUserAffinityDetector: real-user desktop on a non-Hybrid device — not armed"); + return; + } + + _desktopObservedUtc = _utcNow(); + _armed = true; + _logger.Info( + $"EntraUserAffinityDetector: armed at real-user desktop — will emit {SharedConstants.EventTypes.EntraUserAffinityPending} in {_delay.TotalMinutes:F0} min unless IME acquires a user token"); + _timer = new Timer(OnTimer, null, _delay, Timeout.InfiniteTimeSpan); + } + } + + /// IME-TOKEN-SUCCESS line observed; is the line's resolved time. + public void NotifyUserTokenAcquired(DateTime? lineUtc) + { + DateTime desktop; + double minutesAfterDesktop; + lock (_lock) + { + if (_disposed != 0 || !_armed || _tokenAcquiredPosted) return; + desktop = _desktopObservedUtc!.Value; + if (!IsAfterDesktop(lineUtc, desktop)) return; + + _tokenAcquiredPosted = true; + _timer?.Dispose(); + _timer = null; + minutesAfterDesktop = ((lineUtc ?? _utcNow()) - desktop).TotalMinutes; + } + + var data = new Dictionary(StringComparer.Ordinal) + { + ["minutesAfterDesktop"] = Math.Max(0, minutesAfterDesktop).ToString("F1", System.Globalization.CultureInfo.InvariantCulture), + ["tokenFailuresBeforeSuccess"] = _failureCountSinceDesktop.ToString(System.Globalization.CultureInfo.InvariantCulture), + ["isHybridJoin"] = "true", + }; + + _post.Emit( + eventType: SharedConstants.EventTypes.ImeUserTokenAcquired, + source: SourceLabel, + message: "Entra user token acquired by IME after the real-user desktop — user affinity established", + severity: EventSeverity.Info, + immediateUpload: false, + data: data, + occurredAtUtc: lineUtc); + + _logger.Info($"EntraUserAffinityDetector: user token observed {minutesAfterDesktop:F1} min after desktop — timer cancelled"); + } + + /// IME-TOKEN-FAILURE line observed; counted only when stamped after the desktop. + public void NotifyTokenFailureLine(string? errorCode, DateTime? lineUtc) + { + lock (_lock) + { + if (_disposed != 0 || !_armed || _fired || _tokenAcquiredPosted) return; + if (!IsAfterDesktop(lineUtc, _desktopObservedUtc!.Value)) return; + + _failureCountSinceDesktop++; + var code = string.IsNullOrWhiteSpace(errorCode) ? "unknown" : errorCode!.Trim(); + if (!_failureCodesSinceDesktop.Contains(code, StringComparer.OrdinalIgnoreCase)) + _failureCodesSinceDesktop.Add(code); + } + } + + public void Dispose() + { + if (Interlocked.Exchange(ref _disposed, 1) == 1) return; + lock (_lock) + { + _timer?.Dispose(); + _timer = null; + } + } + + // Test seams — same lock and state guards as the production paths. + internal void TriggerFromTest() => OnTimer(null); + internal bool IsArmedForTest { get { lock (_lock) { return _armed; } } } + internal bool HasFiredForTest { get { lock (_lock) { return _fired; } } } + internal bool TokenAcquiredPostedForTest { get { lock (_lock) { return _tokenAcquiredPosted; } } } + + private static bool IsAfterDesktop(DateTime? lineUtc, DateTime desktopUtc) + { + // A line without a timestamp cannot be placed — treat it as current (the tracker + // only hands us lines it just read), which is after the desktop by construction. + if (!lineUtc.HasValue) return true; + return lineUtc.Value >= desktopUtc - DesktopPollTolerance; + } + + private void OnTimer(object? state) + { + string codes; + int count; + double minutesSinceDesktop; + lock (_lock) + { + if (_disposed != 0 || !_armed || _fired || _tokenAcquiredPosted) return; + _fired = true; + _timer?.Dispose(); + _timer = null; + codes = string.Join(",", _failureCodesSinceDesktop); + count = _failureCountSinceDesktop; + minutesSinceDesktop = (_utcNow() - _desktopObservedUtc!.Value).TotalMinutes; + } + + var placeholderActive = "unknown"; + try + { + if (_placeholderActiveProbe != null) + placeholderActive = _placeholderActiveProbe() ? "true" : "false"; + } + catch { /* observational */ } + + var data = new Dictionary(StringComparer.Ordinal) + { + ["delayMinutes"] = ((int)_delay.TotalMinutes).ToString(System.Globalization.CultureInfo.InvariantCulture), + ["reason"] = "timer_fired", + ["minutesSinceDesktop"] = Math.Max(0, minutesSinceDesktop).ToString("F1", System.Globalization.CultureInfo.InvariantCulture), + ["tokenFailureCount"] = count.ToString(System.Globalization.CultureInfo.InvariantCulture), + ["tokenFailureCodes"] = codes, + ["placeholderActive"] = placeholderActive, + ["isHybridJoin"] = "true", + }; + + _post.Emit( + eventType: SharedConstants.EventTypes.EntraUserAffinityPending, + source: SourceLabel, + message: $"Hybrid AAD Join: {(int)_delay.TotalMinutes} min after the real-user desktop IME has not acquired an Entra user token — user affinity pending" + + (count > 0 ? $" ({count} token failure(s): {codes})" : string.Empty), + severity: EventSeverity.Warning, + immediateUpload: true, + data: data); + + _logger.Warning($"EntraUserAffinityDetector: emitted {SharedConstants.EventTypes.EntraUserAffinityPending} (failures={count}, codes={codes})"); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs index 6aad5617..21d3d424 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HelloTracker.cs @@ -36,6 +36,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals internal const int EventId_ProvisioningWillNotLaunch = 360; internal const int EventId_ProvisioningBlocked = 362; internal const int EventId_PinStatus = 376; + // Automatic device registration failed at the join / authentication phase (Hybrid Join + // affinity diagnosis, 2026-09-04). Not Hello events — they ride the same UDR watcher + // because the channel is already armed; surfaced as device_registration_event. + internal const int EventId_AutoRegistrationFailedJoin = 304; + internal const int EventId_AutoRegistrationFailedAuth = 305; internal const int EventId_HelloForBusiness_ProcessingStarted = 3024; internal const int EventId_HelloForBusiness_ProcessingStopped = 6045; @@ -47,6 +52,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private static readonly HashSet TrackedUdrEventIds = new HashSet { + EventId_AutoRegistrationFailedJoin, + EventId_AutoRegistrationFailedAuth, EventId_NgcKeyRegistered, EventId_NgcKeyRegistrationFailed, EventId_ProvisioningWillLaunch, @@ -547,7 +554,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals var query = new EventLogQuery( UdrEventLogChannel, PathType.LogName, - "*[System[(EventID=300 or EventID=301 or EventID=358 or EventID=360 or EventID=362 or EventID=376)]]"); + "*[System[(EventID=300 or EventID=301 or EventID=304 or EventID=305 or EventID=358 or EventID=360 or EventID=362 or EventID=376)]]"); _udrWatcher = new EventLogWatcher(query); _udrWatcher.EventRecordWritten += OnUdrEventRecordWritten; @@ -654,6 +661,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals message = "Windows Hello PIN status update"; break; + case EventId_AutoRegistrationFailedJoin: // 304 + case EventId_AutoRegistrationFailedAuth: // 305 + // OS-side record that the automatic device registration failed (join or + // authentication phase). Companion evidence for entra_user_affinity_pending — + // no Hello state involved, so no MarkHelloCompleted(). + eventType = Constants.EventTypes.DeviceRegistrationEvent; + severity = EventSeverity.Warning; + message = $"User Device Registration: automatic registration failed (event {eventId}, " + + (eventId == EventId_AutoRegistrationFailedJoin ? "join phase)" : "authentication phase)"); + _logger.Info($"User Device Registration failure event {eventId} observed"); + break; + default: return; } @@ -691,6 +710,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // flip state multiple times — keep batched. ImmediateUpload = shouldTriggerHelloCompleted || eventType == Constants.EventTypes.HelloProvisioningFailed + || eventType == Constants.EventTypes.DeviceRegistrationEvent }); _logger.Info($"Hello event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})"); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HybridLoginPendingDetector.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HybridLoginPendingDetector.cs index 8347a3d1..9d790244 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HybridLoginPendingDetector.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/HybridLoginPendingDetector.cs @@ -10,19 +10,27 @@ using SharedConstants = AutopilotMonitor.Shared.Constants; namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals { /// - /// Single-shot detector for the Hybrid User-Driven completion-gap (2026-05-01 trigger: - /// session e58bcfdb-3e68-4f23-a3c2-437429ca9e78). After a Hybrid AAD-Join reboot the - /// agent restarts and waits for the user to log in with their real AD/AAD account - /// (which replaces the foouser/autopilot placeholder in JoinInfo). When that login is - /// overdue the agent today goes silent until the backend 5-h watchdog fires; this - /// detector emits a hybrid_login_pending warning event after a short single-shot - /// timer so the operator sees an explicit "stuck waiting for AD login" signal in the - /// timeline. + /// Single-shot detector for the Hybrid User-Driven sign-in gap (2026-05-01 trigger: + /// session e58bcfdb-3e68-4f23-a3c2-437429ca9e78). After the Hybrid AAD-Join reboot the + /// agent restarts and waits for the user to sign in with their AD account. When nobody + /// signs in the agent goes silent until the backend watchdog fires; this detector emits a + /// hybrid_login_pending warning after a short single-shot timer so the operator sees + /// an explicit "still waiting for the sign-in" signal in the timeline. /// - /// Conditions checked at : composition root must have already - /// confirmed a) post-reboot, b) isHybridJoin == true. The detector itself only - /// owns the timer + cancel-path. No polling. - /// No periodicity. Fires at most once per agent process. + /// What it measures (rewritten 2026-09-04, session a7140f98): the ABSENCE of a real-user + /// desktop. Two cancel paths: the DesktopArrivalDetector resolving explorer.exe under a + /// real user (the actual sign-in evidence), and the AadJoinWatcher seeing a real user in + /// JoinInfo (the Entra-join flavour, where the OOBE sign-in completes the join). On a + /// Hybrid join the AD sign-in never replaces the JoinInfo placeholder — only the later + /// Entra device registration does — so the placeholder state is reported as a fact in the + /// payload, never as the reason for the warning. + /// + /// + /// Conditions checked at by the composition root: post-reboot, + /// isHybridJoin == true, and not a WhiteGlove device (a sealed device legitimately + /// waits days for its user; the session status AwaitingUser already describes that). + /// The detector owns only the timer and the cancel paths. No polling. Fires at most once + /// per agent process. /// /// internal sealed class HybridLoginPendingDetector : IDisposable @@ -40,6 +48,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private bool _armed; private bool _fired; private bool _cancelledByRealUser; + private bool _cancelledByDesktop; private int _disposed; internal HybridLoginPendingDetector( @@ -60,8 +69,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals /// /// Starts the single-shot timer. Idempotent — repeated calls after the first arm - /// are no-ops. Has no effect if the watcher already saw a real AAD user (the - /// arming was racy and the cancel won), or if the detector already fired. + /// are no-ops. Has no effect if a real-user desktop or a real AAD user was already + /// observed (the arming was racy and the cancel won), or if the detector already fired. /// public void Arm() { @@ -69,6 +78,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals { if (_disposed != 0) return; if (_armed || _fired) return; + if (_cancelledByDesktop) + { + _logger.Info("HybridLoginPendingDetector: arm requested but a real-user desktop was already observed — skipped"); + return; + } if (_cancelledByRealUser) { _logger.Info("HybridLoginPendingDetector: arm requested but real AAD user already joined — skipped"); @@ -77,12 +91,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals _armed = true; _logger.Info( - $"HybridLoginPendingDetector: armed — will emit hybrid_login_pending in {_delay.TotalMinutes:F0} min if real AAD user has not joined by then"); + $"HybridLoginPendingDetector: armed — will emit hybrid_login_pending in {_delay.TotalMinutes:F0} min if no real-user desktop appears by then"); _timer = new Timer(OnTimer, null, _delay, Timeout.InfiniteTimeSpan); } } + /// + /// The DesktopArrivalDetector resolved explorer.exe under a real user — the sign-in + /// happened. Cancels a running timer; remembered so a later is a no-op. + /// + public void NotifyRealUserDesktop() + { + lock (_lock) + { + _cancelledByDesktop = true; + if (!_armed || _fired) return; + + _timer?.Dispose(); + _timer = null; + _logger.Info("HybridLoginPendingDetector: cancelled — real-user desktop observed before timeout"); + } + } + public void Dispose() { if (Interlocked.Exchange(ref _disposed, 1) == 1) return; @@ -106,6 +137,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals internal bool IsArmedForTest { get { lock (_lock) { return _armed; } } } internal bool IsCancelledByRealUserForTest { get { lock (_lock) { return _cancelledByRealUser; } } } + internal bool IsCancelledByDesktopForTest { get { lock (_lock) { return _cancelledByDesktop; } } } internal bool HasFiredForTest { get { lock (_lock) { return _fired; } } } private void OnTimer(object? state) => EmitInternal(reason: "timer_fired"); @@ -130,23 +162,26 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // _armed guard (Codex review 2026-05-01): production is safe because the // timer is only created in Arm(), but explicit guard makes the contract // unambiguous — emission requires a deliberate Arm(), full stop. - if (!_armed || _fired || _cancelledByRealUser || _disposed != 0) return; + if (!_armed || _fired || _cancelledByRealUser || _cancelledByDesktop || _disposed != 0) return; _fired = true; _timer?.Dispose(); _timer = null; } + var placeholderActive = _watcher.PlaceholderObservedWithoutRealUser ? "true" : "false"; var data = new Dictionary(StringComparer.Ordinal) { ["delayMinutes"] = ((int)_delay.TotalMinutes).ToString(), ["reason"] = reason, ["isHybridJoin"] = "true", // armed only when composition root verified this + ["realUserDesktopSeen"] = "false", + ["placeholderActive"] = placeholderActive, }; _post.Emit( eventType: SharedConstants.EventTypes.HybridLoginPending, source: SourceLabel, - message: $"Hybrid AAD Join: {(int)_delay.TotalMinutes} min after reboot still no real AD user — login overdue (placeholder still active in JoinInfo)", + message: $"Hybrid AAD Join: {(int)_delay.TotalMinutes} min after reboot still no real-user desktop — sign-in overdue", severity: EventSeverity.Warning, immediateUpload: true, data: data); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index 7e4a0ac1..9f798b71 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -11,6 +11,7 @@ using AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime; using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office; using AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic; using AutopilotMonitor.Agent.V2.Core.Monitoring.Transport; +using AutopilotMonitor.Agent.V2.Core.Security; using AutopilotMonitor.Agent.V2.Core.SignalAdapters; using AutopilotMonitor.DecisionCore.Engine; using AutopilotMonitor.DecisionCore.Signals; @@ -312,6 +313,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // later before the detector can fire). When the real-user desktop arrives, Shift+F10 is no // longer possible, so the console watcher is stopped to avoid post-enrollment false positives. ConsoleBypassHost? consoleBypassHost = null; + // Captured likewise (assigned right after this host). The real-user desktop is the + // sign-in evidence for the Hybrid detectors: it cancels hybrid_login_pending and arms + // the Entra user-affinity timer (2026-09-04, session a7140f98). + AadJoinHost? aadJoinHostRef = null; var desktopArrivalHost = new DesktopArrivalHost( logger, ingress, @@ -326,6 +331,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // Shift+F10 works — stop the console watcher (no-op if not created / already stopped). consoleBypassHost?.StopForDesktopArrival(); + aadJoinHostRef?.NotifyRealUserDesktop(); + if (realmJoinHost == null) return; if (UserSidResolver.TryResolveSid(owner, out var sid) && !string.IsNullOrEmpty(sid)) { @@ -340,8 +347,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration var aadJoinHost = new AadJoinHost( logger, ingress, clock, - onRealUserJoined: desktopArrivalHost.RequestResetForRealUserSwitch); + onRealUserJoined: desktopArrivalHost.RequestResetForRealUserSwitch, + isHybridJoinProbe: EnrollmentRegistryDetector.DetectHybridJoin); hosts.Add(aadJoinHost); + aadJoinHostRef = aadJoinHost; // RealmJoin support is opt-in per tenant (portal toggle → AnalyzerConfiguration. // EnableRealmJoinWatcher, default off). When disabled, leave realmJoinHost null: @@ -439,6 +448,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration hosts.Add(imeLogHost); imeLogHostRef = imeLogHost; + // Entra user affinity (2026-09-04): the raw IME token lines feed the AadJoinHost's + // affinity detector. New callbacks — nothing chained before us, so direct assignment. + imeLogHost.Tracker.OnUserTokenAcquired = lineUtc => aadJoinHost.NotifyUserTokenAcquired(lineUtc); + imeLogHost.Tracker.OnTokenFailureLine = (code, lineUtc) => aadJoinHost.NotifyTokenFailureLine(code, lineUtc); + // sits-d Cloud-PC fix (2026-08-19): the user-apps-settled AccountSetup synthesis used // to run ONLY on the EspExited edge. On a tenant with a large required-app set the ESP // page exits while apps are still in flight, the single attempt misses, and nothing diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs index b113884d..a62bb572 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs @@ -258,6 +258,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration /// public bool IsWhiteGlovePart2 => _isWhiteGlovePart2; + /// + /// true when this device ever resumed a WhiteGlove Part 2 in this session — the + /// state folder holds a .part1-<ts>/ archive. Unlike + /// (this start only) it survives later reboots within + /// Part 2; see . + /// + public bool HasWhiteGlovePart1Archive => StateArchiver.HasPart1Archive(_stateDirectory); + /// /// true wenn der Start auf einen korrupten State-Segment traf und /// Snapshot + Log-Segmente nach .quarantine/{ts}/ bewegt wurden. diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/AadJoinHost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/AadJoinHost.cs index 1de89e15..b5280fc5 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/AadJoinHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/AadJoinHost.cs @@ -8,6 +8,13 @@ using AutopilotMonitor.DecisionCore.Engine; namespace AutopilotMonitor.Agent.V2.Core.Orchestration { + /// + /// Hybrid-identity host: the JoinInfo watcher plus the two single-shot detectors that + /// describe the user side of a Hybrid Azure AD Join — sign-in overdue + /// () and Entra user affinity after the sign-in + /// (). The composition root feeds it the + /// DesktopArrivalDetector's real-user observation and the ImeLogTracker's raw token lines. + /// internal sealed class AadJoinHost : ICollectorHost { public string Name => "AadJoinWatcher"; @@ -15,41 +22,87 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration private readonly AadJoinWatcher _watcher; private readonly AadJoinWatcherAdapter _adapter; private readonly HybridLoginPendingDetector _hybridLoginPendingDetector; + private readonly EntraUserAffinityDetector _userAffinityDetector; private int _disposed; public AadJoinHost( AgentLogger logger, ISignalIngressSink ingress, IClock clock, - Action? onRealUserJoined = null) + Action? onRealUserJoined = null, + Func? isHybridJoinProbe = null) { _watcher = new AadJoinWatcher(logger); _adapter = new AadJoinWatcherAdapter(_watcher, ingress, clock, onRealUserJoined: onRealUserJoined); + var post = new InformationalEventPost(ingress, clock); _hybridLoginPendingDetector = new HybridLoginPendingDetector( watcher: _watcher, - post: new InformationalEventPost(ingress, clock), + post: post, logger: logger); + _userAffinityDetector = new EntraUserAffinityDetector( + post: post, + logger: logger, + isHybridJoinProbe: isHybridJoinProbe ?? (() => false), + placeholderActiveProbe: () => _watcher.PlaceholderObservedWithoutRealUser, + utcNow: () => clock.UtcNow); } public void Start() => _watcher.Start(); public void Stop() => _watcher.Stop(); /// - /// Composition-root entry point for the Hybrid User-Driven completion-gap fix - /// (2026-05-01). Only call when both prerequisites hold: a) the prior agent process - /// was killed by an OS reboot (previousExitType=reboot_kill), b) the - /// Autopilot profile is Hybrid AAD Join (isHybridJoin=true). The detector - /// itself enforces single-shot semantics + cancel-on-real-user — repeated calls or - /// late calls after a real user joined are safe no-ops. + /// Composition-root entry point for the Hybrid User-Driven sign-in-overdue warning + /// (2026-05-01, semantics 2026-09-04). Only call when all prerequisites hold: a) the + /// prior agent process was killed by an OS reboot (previousExitType=reboot_kill), + /// b) the Autopilot profile is Hybrid AAD Join (isHybridJoin=true), c) the device + /// is not a WhiteGlove device (neither resuming Part 2 nor carrying a Part-1 archive). + /// The detector itself enforces single-shot semantics and both cancel paths — + /// repeated calls or late calls after a desktop / real user are safe no-ops. /// public void ArmHybridLoginPendingDetector() => _hybridLoginPendingDetector.Arm(); - // Test seam — exposes the detector for unit tests in the V2.Core.Tests project. + /// + /// The DesktopArrivalDetector resolved explorer.exe under a real user: cancels the + /// sign-in-overdue timer and arms the user-affinity timer (Hybrid devices only). + /// + public void NotifyRealUserDesktop() + { + try { _hybridLoginPendingDetector.NotifyRealUserDesktop(); } + catch (Exception ex) { LogCallbackFailure("HybridLoginPendingDetector.NotifyRealUserDesktop", ex); } + try { _userAffinityDetector.NotifyRealUserDesktop(); } + catch (Exception ex) { LogCallbackFailure("EntraUserAffinityDetector.NotifyRealUserDesktop", ex); } + } + + /// ImeLogTracker observed an IME-TOKEN-SUCCESS line (raw, every line). + public void NotifyUserTokenAcquired(DateTime? lineUtc) + { + try { _userAffinityDetector.NotifyUserTokenAcquired(lineUtc); } + catch (Exception ex) { LogCallbackFailure("EntraUserAffinityDetector.NotifyUserTokenAcquired", ex); } + } + + /// ImeLogTracker observed an IME-TOKEN-FAILURE line (raw, every line). + public void NotifyTokenFailureLine(string? errorCode, DateTime? lineUtc) + { + try { _userAffinityDetector.NotifyTokenFailureLine(errorCode, lineUtc); } + catch (Exception ex) { LogCallbackFailure("EntraUserAffinityDetector.NotifyTokenFailureLine", ex); } + } + + // Test seams — expose the detectors for unit tests in the V2.Core.Tests project. internal HybridLoginPendingDetector HybridLoginPendingDetectorForTest => _hybridLoginPendingDetector; + internal EntraUserAffinityDetector UserAffinityDetectorForTest => _userAffinityDetector; + + private static void LogCallbackFailure(string what, Exception ex) + { + // Host callbacks are best-effort — a detector fault must never break the caller + // (DesktopArrivalDetector poll / ImeLogTracker drain). Swallowed on purpose; the + // detectors log their own state transitions. + _ = what; _ = ex; + } public void Dispose() { if (Interlocked.Exchange(ref _disposed, 1) == 1) return; + try { _userAffinityDetector.Dispose(); } catch { } try { _hybridLoginPendingDetector.Dispose(); } catch { } try { _adapter.Dispose(); } catch { } try { _watcher.Dispose(); } catch { } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/StateArchiver.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/StateArchiver.cs index 86e6c2a7..8bf11df4 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/StateArchiver.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/StateArchiver.cs @@ -37,6 +37,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration /// public static class StateArchiver { + internal const string Part1BucketPrefix = ".part1-"; + + /// + /// true when holds at least one archived + /// .part1-<ts>/ bucket — i.e. this device already went through a WhiteGlove + /// Part-1/Part-2 resume in this session. Durable across later reboots, unlike the + /// whiteglove.complete marker (cleared on resume) and the orchestrator's + /// in-memory Part-2 flag. Used to keep sign-in-overdue warnings off pre-provisioned + /// devices that legitimately wait days for their user (2026-09-04). + /// + public static bool HasPart1Archive(string stateDirectory) + { + try + { + if (string.IsNullOrEmpty(stateDirectory) || !Directory.Exists(stateDirectory)) return false; + return Directory.GetDirectories(stateDirectory, Part1BucketPrefix + "*").Length > 0; + } + catch + { + return false; + } + } + /// /// Reducer-state segment files moved into the .part1-<ts>/ bucket on /// archive. event-sequence.json is intentionally NOT in this list — see the @@ -86,7 +109,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration if (!hasAny) return null; var stamp = utcNow().ToString("yyyyMMdd'T'HHmmssfff'Z'"); - var bucket = Path.Combine(stateDirectory, ".part1-" + stamp); + var bucket = Path.Combine(stateDirectory, Part1BucketPrefix + stamp); Directory.CreateDirectory(bucket); foreach (var name in KnownSegmentFiles) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Security/DeploymentMarker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Security/DeploymentMarker.cs new file mode 100644 index 00000000..bea53971 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Security/DeploymentMarker.cs @@ -0,0 +1,48 @@ +#nullable enable +using System; +using System.Globalization; +using Microsoft.Win32; + +namespace AutopilotMonitor.Agent.V2.Core.Security +{ + /// + /// The install-time deployment marker: HKLM\SOFTWARE\AutopilotMonitor\Deployed, an + /// ISO-8601 UTC instant written by --install right after the runtime was handed off + /// (writer: Program.InstallMode in the runtime project). It is the bootstrap script's + /// re-entry lock and — since 2026-09-04 — the one instant the agent knows in UTC that also + /// appears in the IME logs: the Intune Management Extension logs the bootstrap script's + /// result a few hundred milliseconds later, which anchors the timezone of the pre-agent log + /// era (ImeLogEraPreScan). Read-only here; never written from Core. + /// + public static class DeploymentMarker + { + public const string RegistryKeyPath = @"SOFTWARE\AutopilotMonitor"; + public const string RegistryValueName = "Deployed"; + + /// The marker's UTC instant, or null when absent or unparseable. + public static DateTime? TryReadDeployedUtc() + { + try + { + using (var key = Registry.LocalMachine.OpenSubKey(RegistryKeyPath)) + { + var raw = key?.GetValue(RegistryValueName) as string; + return Parse(raw); + } + } + catch + { + return null; + } + } + + /// Pure parse of the marker text (round-trip "O" format); exposed for tests. + public static DateTime? Parse(string? raw) + { + if (string.IsNullOrWhiteSpace(raw)) return null; + if (!DateTime.TryParse(raw, CultureInfo.InvariantCulture, DateTimeStyles.RoundtripKind, out var parsed)) + return null; + return parsed.Kind == DateTimeKind.Utc ? parsed : parsed.ToUniversalTime(); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index f621efec..57e34dde 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -464,6 +464,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (offsetMinutes.HasValue) data["sourceOffsetMinutes"] = offsetMinutes.Value.ToString(culture); + // Which era anchor the offset came from — forensics for the era-anchored origin. + var anchorKind = _tracker.LastMatchedEraAnchorKind; + if (!string.IsNullOrEmpty(anchorKind)) + data["sourceOffsetAnchor"] = anchorKind; + // Observational only — what the calibrator measured, which since the 2026-08-20 // revert is deliberately NOT what was applied. Kept separate so the two can never // be read as the same thing. @@ -489,6 +494,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters // The line anchored itself: read provably fresh, its own distance to the agent // clock (grid-rounded) was applied as the writer's offset. Era-safe per line. case CmTraceOffsetOrigin.LineAnchored: return "line-anchored"; + // A backlog line resolved through its writer era, anchored by the bootstrap + // execution record against the install marker (ImeLogEraPreScan, 2026-09-04). + case CmTraceOffsetOrigin.EraAnchored: return "era-anchored"; // The line was not provably fresh (backlog, restart catch-up, replay), so this // process's own zone was assumed — correct only if the writer happens to share it. default: return "reader-zone-fallback"; diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs b/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs index 900c86a0..917928f4 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Program.InstallMode.cs @@ -37,8 +37,10 @@ namespace AutopilotMonitor.Agent.V2 /// public static partial class Program { - internal const string DeploymentRegistryKey = @"SOFTWARE\AutopilotMonitor"; - internal const string DeploymentRegistryValue = "Deployed"; + // Shared with the Core reader (DeploymentMarker) — the marker's UTC instant anchors the + // pre-agent IME log era, so writer and reader must agree on key, value and format. + internal const string DeploymentRegistryKey = AutopilotMonitor.Agent.V2.Core.Security.DeploymentMarker.RegistryKeyPath; + internal const string DeploymentRegistryValue = AutopilotMonitor.Agent.V2.Core.Security.DeploymentMarker.RegistryValueName; internal const string BootstrapConfigFileName = "bootstrap-config.json"; internal const string AwaitEnrollmentConfigFileName = "await-enrollment.json"; private const string InstalledAgentExeName = "AutopilotMonitor.Agent.exe"; diff --git a/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs b/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs index 404e7e02..36ae383f 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2/Runtime/AgentRuntimeHost.cs @@ -494,14 +494,19 @@ namespace AutopilotMonitor.Agent.V2.Runtime { LifecycleEmitters.PostSystemRebootObserved(orchestrator.IngressSink, previousExit, logger); - // Hybrid User-Driven completion-gap fix (2026-05-01): the reboot is the - // expected switch from foouser/autopilot OOBE to the real AD account. - // If the user never logs in we go silent until the 5-h backend watchdog; - // arm a single-shot 10-min detector that emits hybrid_login_pending - // once if the AAD user join is overdue. Cancelled when AadJoinWatcher - // sees the real user. Only armed for actual Hybrid devices — non-Hybrid - // reboots don't have the placeholder→real-user flow that motivates this. - if (!isWhiteGloveResume && EnrollmentRegistryDetector.DetectHybridJoin()) + // Hybrid User-Driven sign-in gap (2026-05-01, semantics 2026-09-04): after + // the Hybrid reboot the user has to sign in with the AD account. If nobody + // does, the agent goes silent until the backend watchdog; arm a single-shot + // 10-min detector that emits hybrid_login_pending once when no real-user + // desktop appeared by then. Cancelled by the DesktopArrivalDetector (the + // sign-in evidence) or by the AadJoinWatcher seeing a real user (Entra-join + // flavour). Never on WhiteGlove devices: a sealed device legitimately waits + // days for its user, and AwaitingUser already describes that — the Part-1 + // archive check covers reboots inside Part 2 after the resume marker is gone. + if (!isWhiteGloveResume + && !orchestrator.IsWhiteGlovePart2 + && !orchestrator.HasWhiteGlovePart1Archive + && EnrollmentRegistryDetector.DetectHybridJoin()) { try { orchestrator.CollectorSurfaces?.AadJoinHost?.ArmHybridLoginPendingDetector(); } catch (Exception ex) diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/HybridUserAffinityRuleTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/HybridUserAffinityRuleTests.cs new file mode 100644 index 00000000..973adad1 --- /dev/null +++ b/src/Backend/AutopilotMonitor.Functions.Tests/HybridUserAffinityRuleTests.cs @@ -0,0 +1,228 @@ +using AutopilotMonitor.Functions.Services; +using AutopilotMonitor.Shared.DataAccess; +using AutopilotMonitor.Shared.Models; +using Microsoft.Extensions.Logging.Abstractions; +using Moq; + +namespace AutopilotMonitor.Functions.Tests; + +/// +/// ANALYZE-ID-004 v2.0.0 — pins the built-in that consumes the agent's user-affinity signal: +/// the real user reached the desktop (desktop_arrived), IME acquired no Entra user token +/// within the wait window (entra_user_affinity_pending, at most once per agent process), +/// and no ime_user_token_acquired disproves it. Repetition across reboots is the +/// confidence lever (base 60, +20 at two, threshold 75), the terminal precondition on +/// enrollment_complete stays the suppression at session end, and the v1.x evidence +/// (hybrid_login_pending, the JoinInfo placeholder) must no longer fire the rule. +/// +public class HybridUserAffinityRuleTests +{ + private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890"; + private const string SessionId = "77777777-8888-9999-aaaa-bbbbbbbbbbbb"; + + private static AnalyzeRule Rule() => BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-ID-004"); + + [Fact] + public void ANALYZE_ID_004_v2_shape_is_pinned() + { + var rule = Rule(); + Assert.Equal("2.0.0", rule.Version); + Assert.True(rule.Enabled); + Assert.Equal("high", rule.Severity); + Assert.False(rule.MarkSessionAsFailedDefault); + Assert.Equal(75, rule.ConfidenceThreshold); + Assert.Contains("on_event:entra_user_affinity_pending", rule.EvaluateOn!); + Assert.DoesNotContain("on_event:hybrid_login_pending", rule.EvaluateOn!); + + // The old evidence is gone from every rule surface — trigger, conditions and factors. + Assert.DoesNotContain(rule.Conditions, c => c.EventType is "hybrid_login_pending" or "aad_placeholder_user_detected"); + Assert.DoesNotContain(rule.ConfidenceFactors, f => f.Signal is "hybrid_login_pending" or "aad_placeholder_user_detected"); + + var noToken = Assert.Single(rule.Conditions, c => c.Signal == "no_user_token"); + Assert.Equal("event_type", noToken.Source); + Assert.Equal("ime_user_token_acquired", noToken.EventType); + Assert.Equal("not_exists", noToken.Operator); + Assert.True(noToken.Required); + } + + [Fact] + public async Task Fires_when_affinity_is_pending_twice_and_no_token_was_acquired() + { + var events = new List + { + DesktopArrived(sequence: 10), + AffinityPending(sequence: 20), + AffinityPending(sequence: 30), // second agent process after a reboot + }; + + var outcome = await RunAsync(Rule(), events); + + var result = Assert.Single(outcome.Results); + Assert.Equal("ANALYZE-ID-004", result.RuleId); + Assert.True(result.ConfidenceScore >= 75, $"confidence {result.ConfidenceScore} below threshold"); + Assert.Equal(80, result.ConfidenceScore); // base 60 + count >= 2 + + // The absence condition carries its own evidence so the matched-condition map is + // complete for the UI, not just the two presence signals. + Assert.True(result.MatchedConditions.ContainsKey("user_affinity_pending")); + Assert.True(result.MatchedConditions.ContainsKey("user_desktop_reached")); + Assert.True(result.MatchedConditions.ContainsKey("no_user_token")); + } + + [Fact] + public async Task Three_pending_warnings_reach_confidence_90() + { + var events = new List + { + DesktopArrived(sequence: 10), + AffinityPending(sequence: 20), + AffinityPending(sequence: 30), + AffinityPending(sequence: 40), + }; + + var outcome = await RunAsync(Rule(), events); + + var result = Assert.Single(outcome.Results); + Assert.Equal(90, result.ConfidenceScore); // base 60 + 20 + 10 + } + + [Fact] + public async Task Does_not_fire_on_a_single_pending_warning() + { + // One agent process without a token is hybrid latency until it repeats: 60 < 75. + var events = new List + { + DesktopArrived(sequence: 10), + AffinityPending(sequence: 20), + }; + + var outcome = await RunAsync(Rule(), events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task Does_not_fire_when_a_user_token_was_acquired() + { + // A token success after the desktop disproves the diagnosis even when the warning + // repeated (e.g. the first two processes stalled, the third one got the PRT). + var events = new List + { + DesktopArrived(sequence: 10), + AffinityPending(sequence: 20), + AffinityPending(sequence: 30), + Event("ime_user_token_acquired", sequence: 40, new Dictionary + { + ["minutesAfterDesktop"] = 3, + ["tokenFailuresBeforeSuccess"] = 4, + ["isHybridJoin"] = true, + }), + }; + + var outcome = await RunAsync(Rule(), events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task Is_skipped_by_the_precondition_when_the_enrollment_completed() + { + var events = new List + { + DesktopArrived(sequence: 10), + AffinityPending(sequence: 20), + AffinityPending(sequence: 30), + Event("enrollment_complete", sequence: 40, new Dictionary()), + }; + + var outcome = await RunAsync(Rule(), events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task Does_not_fire_on_the_v1_evidence_alone() + { + // hybrid_login_pending now means "no real-user desktop yet"; together with the placeholder + // it was the v1.x evidence and must not satisfy v2 — even at the old confidence-raising count. + var events = new List + { + DesktopArrived(sequence: 10), + Event("hybrid_login_pending", sequence: 20, HybridLoginPendingData()), + Event("hybrid_login_pending", sequence: 30, HybridLoginPendingData()), + Event("hybrid_login_pending", sequence: 40, HybridLoginPendingData()), + Event("aad_placeholder_user_detected", sequence: 50, new Dictionary()), + Event("aad_placeholder_user_detected", sequence: 60, new Dictionary()), + Event("aad_placeholder_user_detected", sequence: 70, new Dictionary()), + }; + + var outcome = await RunAsync(Rule(), events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task Does_not_fire_without_a_real_user_desktop() + { + // The agent only arms the detector after the desktop, but the rule must not rely on that: + // two pending warnings without desktop_arrived are not this diagnosis. + var events = new List + { + AffinityPending(sequence: 20), + AffinityPending(sequence: 30), + }; + + var outcome = await RunAsync(Rule(), events); + Assert.Empty(outcome.Results); + } + + // ===== Event builders — mirror the agent emit shapes ===== + + private static EnrollmentEvent DesktopArrived(int sequence) => + Event("desktop_arrived", sequence, new Dictionary()); + + private static EnrollmentEvent AffinityPending(int sequence) => + Event("entra_user_affinity_pending", sequence, new Dictionary + { + ["delayMinutes"] = 10, + ["reason"] = "no_user_token_after_desktop", + ["minutesSinceDesktop"] = 10, + ["tokenFailureCount"] = 4, + ["tokenFailureCodes"] = "0xCAA2000C", + ["placeholderActive"] = true, + ["isHybridJoin"] = true, + }); + + private static Dictionary HybridLoginPendingData() => new() + { + ["delayMinutes"] = 10, + ["reason"] = "no_real_user_desktop", + ["isHybridJoin"] = true, + ["realUserDesktopSeen"] = false, + ["placeholderActive"] = true, + }; + + private static EnrollmentEvent Event(string eventType, int sequence, Dictionary data) => new() + { + EventId = Guid.NewGuid().ToString(), + TenantId = TenantId, + SessionId = SessionId, + EventType = eventType, + Timestamp = DateTime.UtcNow.AddMinutes(sequence), + Sequence = sequence, + Data = data, + }; + + private static async Task RunAsync(AnalyzeRule rule, List events) + { + var ruleRepo = new Mock(); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List { rule }); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List()); + ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny())).ReturnsAsync(new Dictionary()); + ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny(), It.IsAny())).ReturnsAsync(new List()); + + var sessionRepo = new Mock(); + sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny())).ReturnsAsync(events); + + var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger.Instance); + var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger.Instance); + + return await engine.AnalyzeSessionAsync(TenantId, SessionId); + } +} diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs new file mode 100644 index 00000000..985bd8cc --- /dev/null +++ b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs @@ -0,0 +1,374 @@ +using AutopilotMonitor.Functions.Services; +using AutopilotMonitor.Shared.DataAccess; +using AutopilotMonitor.Shared.Models; +using Microsoft.Extensions.Logging.Abstractions; +using Moq; + +namespace AutopilotMonitor.Functions.Tests; + +/// +/// Timestamp provenance in the duration evaluators (phase_duration, app_install_duration). +/// IME-log-derived events carry data.sourceOffsetOrigin; reader-zone-fallback +/// means the agent assumed its own timezone for the log writer, so the Timestamp can be hours +/// off. A duration with such an endpoint is not measurable: the condition is false with a +/// provenance reason. Other origins and agent-native events (no tag) stay measurable. +/// Field case: a 20-minute DeviceSetup rendered as 3 h 22 min fired ANALYZE-ESP-001 (high). +/// +public class RuleEngineDurationProvenanceTests +{ + private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890"; + private const string SessionId = "77777777-8888-9999-aaaa-bbbbbbbbbbbb"; + private const string Fallback = "reader-zone-fallback"; + private const string LineAnchored = "line-anchored"; + + private static readonly DateTime T0 = new(2026, 9, 1, 13, 30, 0, DateTimeKind.Utc); + + // ===== phase_duration ===== + + [Theory] + [InlineData(Fallback)] + [InlineData("Reader-Zone-Fallback")] // origin compare is case-insensitive + public async Task PhaseDuration_StartWithFallbackProvenance_IsNotMeasurable(string origin) + { + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, origin), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, LineAnchored), + }; + + var (dry, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), events); + + Assert.Equal(RuleDryRunVerdict.RequiredConditionNotMet, dry.Verdict); + var condition = Assert.Single(dry.Conditions); + Assert.False(condition.Matched); + var evidence = AsDict(condition.Evidence!); + Assert.Contains("not measurable", AsString(evidence["reason"])); + Assert.Contains("start timestamp derived from reader-zone fallback", AsString(evidence["reason"])); + Assert.Equal(Fallback, AsString(evidence["timestampProvenance"])); + Assert.Equal("start", AsString(evidence["provenanceEndpoint"])); + Assert.Equal(events[0].EventId, AsString(evidence["eventId"])); + Assert.Equal(10L, Convert.ToInt64(evidence["sequence"])); + } + + [Fact] + public async Task PhaseDuration_EndWithFallbackProvenance_IsNotMeasurable() + { + // The end of a phase is the NEXT esp_phase_changed of any phase — its provenance counts too. + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, LineAnchored), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, Fallback), + }; + + var (dry, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), events); + + var condition = Assert.Single(dry.Conditions); + Assert.False(condition.Matched); + var evidence = AsDict(condition.Evidence!); + Assert.Contains("end timestamp derived from reader-zone fallback", AsString(evidence["reason"])); + Assert.Equal(Fallback, AsString(evidence["timestampProvenance"])); + Assert.Equal("end", AsString(evidence["provenanceEndpoint"])); + Assert.Equal(events[1].EventId, AsString(evidence["provenanceEventId"])); + Assert.Equal(events[0].EventId, AsString(evidence["eventId"])); // the phase event stays the anchor + } + + [Theory] + [InlineData(LineAnchored)] + [InlineData("bias")] + [InlineData("calibrated")] + [InlineData("era-anchored")] // backlog line resolved through its anchored writer era (agent 2026-09-04) + public async Task PhaseDuration_TrustedProvenanceOnBothEnds_IsComputed(string origin) + { + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, origin), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, origin), + }; + + var (dry, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + var evidence = AsDict(condition.Evidence!); + Assert.Equal(3 * 3600d, Convert.ToDouble(evidence["durationSeconds"])); + Assert.Equal(events[1].EventId, AsString(evidence["phaseEndEventId"])); + Assert.False(evidence.ContainsKey("timestampProvenance")); + } + + [Fact] + public async Task PhaseDuration_NoProvenanceAtAll_IsComputed() + { + // Agent-native events carry no sourceOffsetOrigin — nothing to distrust. + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, origin: null), + PhaseEvent("AccountSetup", T0.AddMinutes(20), 20, origin: null), + }; + + var (dry, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + Assert.Equal(20 * 60d, Convert.ToDouble(AsDict(condition.Evidence!)["durationSeconds"])); + } + + [Fact] + public async Task PhaseDuration_OpenPhase_OnlyTheStartProvenanceMatters() + { + // No next phase event: the end is "now" and has no provenance. A trusted start measures, + // a fallback start does not. + var trusted = new List { PhaseEvent("DeviceSetup", DateTime.UtcNow.AddMinutes(-5), 10, LineAnchored) }; + var (dryTrusted, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), trusted); + var trustedCondition = Assert.Single(dryTrusted.Conditions); + Assert.True(trustedCondition.Matched); + Assert.Equal("(still active)", AsString(AsDict(trustedCondition.Evidence!)["phaseEndEventId"])); + + var fallback = new List { PhaseEvent("DeviceSetup", DateTime.UtcNow.AddMinutes(-5), 10, Fallback) }; + var (dryFallback, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), fallback); + var fallbackCondition = Assert.Single(dryFallback.Conditions); + Assert.False(fallbackCondition.Matched); + Assert.Equal("start", AsString(AsDict(fallbackCondition.Evidence!)["provenanceEndpoint"])); + } + + // ===== app_install_duration ===== + + [Fact] + public async Task AppInstallDuration_StartWithFallbackProvenance_IsNotMeasurable() + { + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, Fallback), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, LineAnchored), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + Assert.Equal(RuleDryRunVerdict.RequiredConditionNotMet, dry.Verdict); + var condition = Assert.Single(dry.Conditions); + Assert.False(condition.Matched); + var evidence = AsDict(condition.Evidence!); + Assert.Contains("app install duration not measurable: start timestamp derived from reader-zone fallback", AsString(evidence["reason"])); + Assert.Equal(Fallback, AsString(evidence["timestampProvenance"])); + Assert.Equal("start", AsString(evidence["provenanceEndpoint"])); + Assert.Equal(events[0].EventId, AsString(evidence["provenanceEventId"])); + Assert.Equal(events[1].EventId, AsString(evidence["eventId"])); // completion stays the anchor + Assert.Equal(20L, Convert.ToInt64(evidence["sequence"])); + } + + [Fact] + public async Task AppInstallDuration_EndWithFallbackProvenance_IsNotMeasurable() + { + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, LineAnchored), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, Fallback), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + var condition = Assert.Single(dry.Conditions); + Assert.False(condition.Matched); + var evidence = AsDict(condition.Evidence!); + Assert.Equal("end", AsString(evidence["provenanceEndpoint"])); + Assert.Equal(Fallback, AsString(evidence["timestampProvenance"])); + } + + [Fact] + public async Task AppInstallDuration_TrustedProvenance_IsComputed() + { + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, LineAnchored), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, LineAnchored), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + Assert.Equal(3600d, Convert.ToDouble(AsDict(condition.Evidence!)["durationSeconds"])); + } + + [Fact] + public async Task AppInstallDuration_NoProvenance_IsComputed() + { + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, origin: null), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, origin: null), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + Assert.True(Assert.Single(dry.Conditions).Matched); + } + + [Fact] + public async Task AppInstallDuration_UnmeasurablePairDoesNotHideAMeasurableOne() + { + // The fallback pair is skipped, not fatal: another app with trusted endpoints still matches. + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, Fallback), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, LineAnchored), + AppEvent("app_install_started", "app-b", T0.AddHours(1), 30, LineAnchored), + AppEvent("app_install_completed", "app-b", T0.AddHours(2), 40, LineAnchored), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + Assert.Equal("app-b", AsString(AsDict(condition.Evidence!)["appId"])); + } + + // ===== Rule level: ANALYZE-ESP-001 from rules/dist ===== + + [Fact] + public async Task ANALYZE_ESP_001_does_not_fire_on_a_reader_zone_fallback_DeviceSetup() + { + // The field case: DeviceSetup start read under the wrong writer zone sits 3 h before the + // next (correctly anchored) phase event although the real phase lasted ~20 minutes. + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-ESP-001"); + Assert.True(rule.Enabled); + + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, Fallback), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, LineAnchored), + }; + + var outcome = await RunBuiltInAsync(rule, events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task ANALYZE_ESP_001_fires_on_the_same_span_when_line_anchored() + { + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-ESP-001"); + + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, LineAnchored), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, LineAnchored), + }; + + var outcome = await RunBuiltInAsync(rule, events); + + var result = Assert.Single(outcome.Results); + Assert.Equal("ANALYZE-ESP-001", result.RuleId); + Assert.True(result.ConfidenceScore >= rule.ConfidenceThreshold); + var matched = AsDict(result.MatchedConditions["esp_stalled"]); + Assert.Equal(3 * 3600d, Convert.ToDouble(matched["durationSeconds"])); + } + + // ===== Event builders — mirror the ImeLogTrackerAdapter emit shape ===== + + private static EnrollmentEvent PhaseEvent(string phase, DateTime timestamp, long sequence, string? origin) + => ImeEvent("esp_phase_changed", timestamp, sequence, origin, new Dictionary { ["espPhase"] = phase }); + + private static EnrollmentEvent AppEvent(string eventType, string appId, DateTime timestamp, long sequence, string? origin) + => ImeEvent(eventType, timestamp, sequence, origin, new Dictionary { ["appId"] = appId, ["appName"] = appId }); + + private static EnrollmentEvent ImeEvent(string eventType, DateTime timestamp, long sequence, string? origin, Dictionary data) + { + if (origin != null) + { + data["sourceLocalTs"] = timestamp.ToString("yyyy-MM-ddTHH:mm:ss.fffffff"); + data["sourceOffsetOrigin"] = origin; + data["sourceOffsetMinutes"] = "-240"; + } + return new EnrollmentEvent + { + EventId = Guid.NewGuid().ToString(), + TenantId = TenantId, + SessionId = SessionId, + EventType = eventType, + Timestamp = timestamp, + Sequence = sequence, + Source = origin != null ? "ImeLogTracker" : "Agent", + Data = data, + }; + } + + // ===== Rules ===== + + private static AnalyzeRule PhaseRule(string phase) => new() + { + RuleId = "ANALYZE-TEST-PHASE", + Title = "Phase duration draft", + Severity = "warning", + Category = "esp", + IsBuiltIn = false, + BaseConfidence = 50, + ConfidenceThreshold = 40, + Conditions = new List + { + new() + { + Signal = "esp_stalled", Source = "phase_duration", EventType = "esp_phase_changed", + DataField = "espPhase", Operator = "equals", Value = phase, Required = true, + }, + }, + Explanation = "Phase {{phase}} lasted {{durationFormatted}}.", + }; + + private static AnalyzeRule AppDurationRule(int minSeconds) => new() + { + RuleId = "ANALYZE-TEST-APPDUR", + Title = "App install duration draft", + Severity = "warning", + Category = "apps", + IsBuiltIn = false, + BaseConfidence = 50, + ConfidenceThreshold = 40, + Conditions = new List + { + new() + { + Signal = "slow_install", Source = "app_install_duration", + Operator = "gt", Value = minSeconds.ToString(), Required = true, + }, + }, + Explanation = "App {{appName}} took {{durationFormatted}}.", + }; + + // ===== Harness ===== + + private static Dictionary AsDict(object o) + { + if (o is Dictionary d) return d; + throw new InvalidOperationException($"Expected Dictionary, got {o?.GetType().Name ?? "null"}"); + } + + private static string AsString(object o) => o?.ToString() ?? string.Empty; + + private static async Task<(RuleDryRun dry, Mock sessionRepo, Mock ruleRepo)> DryRunAsync( + AnalyzeRule rule, List events) + { + var ruleRepo = new Mock(); + var sessionRepo = new Mock(); + sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny())).ReturnsAsync(events); + var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger.Instance); + var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger.Instance); + var dry = await engine.DryRunRuleAsync(TenantId, SessionId, rule); + return (dry, sessionRepo, ruleRepo); + } + + private static async Task RunBuiltInAsync(AnalyzeRule rule, List events) + { + var ruleRepo = new Mock(); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List { rule }); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List()); + ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny())).ReturnsAsync(new Dictionary()); + ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny(), It.IsAny())).ReturnsAsync(new List()); + + var sessionRepo = new Mock(); + sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny())).ReturnsAsync(events); + + var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger.Instance); + var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger.Instance); + + return await engine.AnalyzeSessionAsync(TenantId, SessionId); + } +} diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEvaluateOnTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEvaluateOnTests.cs index f884f12d..b792e087 100644 --- a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEvaluateOnTests.cs +++ b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEvaluateOnTests.cs @@ -320,8 +320,10 @@ public class RuleEngineEvaluateOnTests // Pins the JSON → model deserialization of evaluateOn end-to-end through the // embedded catalog (rules/dist/analyze-rules.json). var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-ID-004"); - Assert.Equal(new List { "enrollment_end", "on_event:hybrid_login_pending" }, rule.EvaluateOn); - // Interim safety: the rule must not fire on a single overdue-login signal — the + // v2.0.0: the interim trigger is the agent's user-affinity signal (real-user desktop seen, + // IME acquired no Entra user token), no longer hybrid_login_pending (desktop absence). + Assert.Equal(new List { "enrollment_end", "on_event:entra_user_affinity_pending" }, rule.EvaluateOn); + // Interim safety: the rule must not fire on a single pending-affinity signal — the // threshold has to require the repetition factors (base 60 + count>=2 → 80). Assert.True(rule.ConfidenceThreshold > rule.BaseConfidence, "ANALYZE-ID-004 must be repetition-gated to stay interim-safe"); diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEventTypeNotExistsTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEventTypeNotExistsTests.cs new file mode 100644 index 00000000..4c56b9b9 --- /dev/null +++ b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineEventTypeNotExistsTests.cs @@ -0,0 +1,92 @@ +using AutopilotMonitor.Functions.Services; +using AutopilotMonitor.Shared.DataAccess; +using AutopilotMonitor.Shared.Models; +using Microsoft.Extensions.Logging.Abstractions; +using Moq; + +namespace AutopilotMonitor.Functions.Tests; + +/// +/// Pins the absence gate on event_type conditions: not_exists without a +/// dataField matches when no event of that type occurs in the session and is disproved by +/// a single such event. Before this branch an absent type always evaluated false, so a required +/// "must not have happened" condition could never be expressed (ANALYZE-ID-004 v2 relies on it). +/// The dataField variant keeps its historical meaning (some event of the type has an empty field) +/// and is not touched here. +/// +public class RuleEngineEventTypeNotExistsTests +{ + private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890"; + private const string SessionId = "12121212-3434-5656-7878-909090909090"; + + [Fact] + public async Task Not_exists_matches_when_the_event_type_is_absent() + { + var events = new List { Event("marker_seen", 1) }; + + var outcome = await RunAsync(Rule(), events); + + var result = Assert.Single(outcome.Results); + var evidence = Assert.IsType>(result.MatchedConditions["disproof_absent"]); + Assert.Equal("disproof", evidence["eventType"]); + Assert.Equal(0, evidence["count"]); + } + + [Fact] + public async Task A_single_event_of_the_type_vetoes_a_required_not_exists() + { + var events = new List { Event("marker_seen", 1), Event("disproof", 2) }; + + var outcome = await RunAsync(Rule(), events); + + Assert.Empty(outcome.Results); + } + + private static AnalyzeRule Rule() => new() + { + // Custom-namespace rule: a built-in ID outside the live catalog is hidden by the + // sunset filter in AnalyzeRuleService (IsBuiltIn defaults to true). + RuleId = "ANALYZE-CUSTOM-001", + IsBuiltIn = false, + Title = "not_exists absence gate", + Severity = "info", + Category = "device", + Enabled = true, + Trigger = "correlation", + BaseConfidence = 80, + ConfidenceThreshold = 50, + Conditions = new List + { + new() { Signal = "marker", Source = "event_type", EventType = "marker_seen", Operator = "exists", Value = "", Required = true }, + new() { Signal = "disproof_absent", Source = "event_type", EventType = "disproof", Operator = "not_exists", Value = "", Required = true }, + }, + }; + + private static EnrollmentEvent Event(string eventType, int sequence) => new() + { + EventId = Guid.NewGuid().ToString(), + TenantId = TenantId, + SessionId = SessionId, + EventType = eventType, + Timestamp = DateTime.UtcNow.AddMinutes(sequence), + Sequence = sequence, + Data = new Dictionary(), + }; + + private static async Task RunAsync(AnalyzeRule rule, List events) + { + var ruleRepo = new Mock(); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List { rule }); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List()); + ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny())).ReturnsAsync(new Dictionary()); + ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny(), It.IsAny())).ReturnsAsync(new List()); + + var sessionRepo = new Mock(); + sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny())).ReturnsAsync(events); + + var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger.Instance); + var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger.Instance); + + return await engine.AnalyzeSessionAsync(TenantId, SessionId); + } +} diff --git a/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs b/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs index e6037ae6..657b1a0f 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs @@ -110,6 +110,23 @@ namespace AutopilotMonitor.Functions.Services { var matchingEvents = events.Where(e => MatchesEventType(e, condition.EventType)).ToList(); + // Absence gate: not_exists without a dataField matches when NO event of that type occurs + // in the session (the same presence semantics as the precondition gate). A single event + // of that type disproves the condition — as a required condition it vetoes the rule + // (e.g. ime_user_token_acquired disproving ANALYZE-ID-004). + if (string.IsNullOrEmpty(condition.DataField) + && string.Equals(condition.Operator, "not_exists", StringComparison.OrdinalIgnoreCase)) + { + if (matchingEvents.Any()) + return (false, "event type present"); + + return (true, new Dictionary + { + ["eventType"] = condition.EventType, + ["count"] = 0 + }); + } + if (!matchingEvents.Any()) return (false, "no matching events"); @@ -474,16 +491,26 @@ namespace AutopilotMonitor.Functions.Services // Calculate how long this phase lasted DateTime phaseEnd; string? phaseEndEventId = null; + EnrollmentEvent? phaseEndEvent = null; if (i + 1 < phaseEvents.Count) { - phaseEnd = phaseEvents[i + 1].Timestamp; - phaseEndEventId = phaseEvents[i + 1].EventId; + phaseEndEvent = phaseEvents[i + 1]; + phaseEnd = phaseEndEvent.Timestamp; + phaseEndEventId = phaseEndEvent.EventId; } else { - phaseEnd = DateTime.UtcNow; // Phase is still active + phaseEnd = DateTime.UtcNow; // Phase is still active — the end carries no provenance } + // A duration is only as good as the weaker of its two endpoints: a reader-zone + // fallback timestamp can be hours off, which turned a 20-minute DeviceSetup into a + // 3 h "ESP Blocking App Timeout" (ANALYZE-ESP-001). + if (HasReaderZoneFallbackTimestamp(evt)) + return (false, UnmeasurableDurationEvidence("phase duration", "start", evt, evt)); + if (phaseEndEvent != null && HasReaderZoneFallbackTimestamp(phaseEndEvent)) + return (false, UnmeasurableDurationEvidence("phase duration", "end", evt, phaseEndEvent)); + var durationSeconds = (phaseEnd - evt.Timestamp).TotalSeconds; return (true, new Dictionary @@ -511,6 +538,38 @@ namespace AutopilotMonitor.Functions.Services return $"{ts.Seconds}s"; } + // ===== Timestamp provenance of CMTrace-derived events ===== + // IME-log-derived events (esp_phase_changed, app_install_*, …) carry data.sourceOffsetOrigin: + // "bias" | "calibrated" | "line-anchored" | "reader-zone-fallback". The last one means the + // agent could not determine the log writer's timezone and assumed its own, so the + // Timestamp may be off by whole hours. Agent-native events carry no tag and are trusted. + + /// Data key written by the agent's IME log adapter for CMTrace-derived events. + internal const string SourceOffsetOriginField = "sourceOffsetOrigin"; + /// Origin value that makes a timestamp unusable for an elapsed-duration measurement. + internal const string ReaderZoneFallbackOrigin = "reader-zone-fallback"; + + private static bool HasReaderZoneFallbackTimestamp(EnrollmentEvent evt) + => string.Equals(GetDataFieldValue(evt, SourceOffsetOriginField), ReaderZoneFallbackOrigin, StringComparison.OrdinalIgnoreCase); + + /// + /// Non-match evidence for a duration whose ("start" | "end") + /// timestamp is a reader-zone fallback. is the event the evaluator + /// normally reports as its match (eventId/sequence), the endpoint + /// event carrying the fallback tag. + /// + private static Dictionary UnmeasurableDurationEvidence( + string what, string endpoint, EnrollmentEvent anchor, EnrollmentEvent offender) + => new() + { + ["reason"] = $"{what} not measurable: {endpoint} timestamp derived from reader-zone fallback", + ["timestampProvenance"] = ReaderZoneFallbackOrigin, + ["provenanceEndpoint"] = endpoint, + ["provenanceEventId"] = offender.EventId ?? string.Empty, + ["eventId"] = anchor.EventId ?? string.Empty, + ["sequence"] = anchor.Sequence, + }; + private bool EvaluateConfidenceFactor(ConfidenceFactor factor, List events, Dictionary matchedConditions) { if (string.IsNullOrEmpty(factor.Condition)) @@ -574,7 +633,7 @@ namespace AutopilotMonitor.Functions.Services return string.Equals(evt.EventType, eventType, StringComparison.OrdinalIgnoreCase); } - private string? GetDataFieldValue(EnrollmentEvent evt, string dataField) + private static string? GetDataFieldValue(EnrollmentEvent evt, string dataField) { if (evt.Data == null || string.IsNullOrEmpty(dataField)) return null; @@ -785,6 +844,11 @@ namespace AutopilotMonitor.Functions.Services .Where(e => completionEventTypes.Contains(e.EventType ?? string.Empty)) .ToList(); + // First pair skipped because one endpoint is a reader-zone fallback timestamp (see + // HasReaderZoneFallbackTimestamp). Other apps stay measurable; the skip only becomes + // the reported reason when nothing else matched. + Dictionary? unmeasurable = null; + foreach (var completionEvent in completionEvents) { var appId = GetDataFieldValue(completionEvent, "appId"); @@ -803,6 +867,17 @@ namespace AutopilotMonitor.Functions.Services if (startEvent == null) continue; + if (HasReaderZoneFallbackTimestamp(startEvent)) + { + unmeasurable ??= UnmeasurableDurationEvidence("app install duration", "start", completionEvent, startEvent); + continue; + } + if (HasReaderZoneFallbackTimestamp(completionEvent)) + { + unmeasurable ??= UnmeasurableDurationEvidence("app install duration", "end", completionEvent, completionEvent); + continue; + } + var durationSeconds = Math.Max(0, (completionEvent.Timestamp - startEvent.Timestamp).TotalSeconds); if (!MatchesOperator(durationSeconds.ToString(), condition.Operator, condition.Value)) @@ -823,6 +898,9 @@ namespace AutopilotMonitor.Functions.Services }); } + if (unmeasurable != null) + return (false, unmeasurable); + return (false, "no app install duration matched"); } diff --git a/src/McpServer/autopilot-monitor-mcp/src/__tests__/auto-exhaust.test.ts b/src/McpServer/autopilot-monitor-mcp/src/__tests__/auto-exhaust.test.ts index 81beec7f..ea276728 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/__tests__/auto-exhaust.test.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/__tests__/auto-exhaust.test.ts @@ -10,6 +10,8 @@ import { describe, it, expect } from 'vitest'; import { scanUntilMatch } from '../client.js'; import { isKnownEventType, + isGatherOutputEventType, + isFilterableEventType, assertKnownEventType, assertKnownDevicePropertyKeys, eventTypePrefixOf, @@ -157,6 +159,38 @@ describe('event-type validation', () => { // "app_install_fialed" shares the "app" token → at least one suggestion surfaces. expect(() => assertKnownEventType('app_install_fialed')).toThrow(/Did you mean/); }); + + it('accepts the hybrid user-affinity types added to the catalog', () => { + for (const t of ['desktop_real_user_detected', 'desktop_excluded_user', 'ime_user_token_acquired', 'entra_user_affinity_pending', 'device_registration_event']) { + expect(isKnownEventType(t), t).toBe(true); + expect(() => assertKnownEventType(t)).not.toThrow(); + } + }); + + it('lets gather-rule output types through the filter gate without cataloguing them', () => { + // Built-in and tenant-authored outputEventType values are rule data, never catalogued. + for (const t of ['gather_dsregcmd_status', 'gather_custom_anything']) { + expect(isGatherOutputEventType(t), t).toBe(true); + expect(isFilterableEventType(t), t).toBe(true); + expect(() => assertKnownEventType(t)).not.toThrow(); + // The strict predicate stays strict: rule-validation uses it as "is a built-in type". + expect(isKnownEventType(t), t).toBe(false); + } + // Catalogued code-emitted gather_* lifecycle types are known AND filterable. + expect(isKnownEventType('gather_result')).toBe(true); + expect(isFilterableEventType('gather_result')).toBe(true); + }); + + it('requires a non-empty suffix after the gather_ prefix', () => { + expect(isGatherOutputEventType('gather_')).toBe(false); + expect(isFilterableEventType('gather_')).toBe(false); + expect(() => assertKnownEventType('gather_')).toThrow(/event_types catalog/); + }); + + it('still rejects a typo that only resembles the gather_ prefix', () => { + expect(isFilterableEventType('gathre_dsregcmd_status')).toBe(false); + expect(() => assertKnownEventType('gathre_dsregcmd_status')).toThrow(/Unknown eventType "gathre_dsregcmd_status" — it is not in the event_types catalog/); + }); }); describe('deviceProperties key validation', () => { diff --git a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts index 87bbcb26..9967b21e 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts @@ -18,6 +18,8 @@ import { // in __tests__/event-types-drift.test.ts, which reads Constants.cs and asserts // (all catalog values ∪ INTERNAL_EVENT_TYPES) === the C# const values. When the // agent adds a new event type to Constants.EventTypes, add it to a group here too. +// Gather-rule output types ("gather_dsregcmd_status", ...) are rule data, not code-emitted +// types, and stay OUT of the catalog on purpose — see isGatherOutputEventType below. export const EVENT_TYPES_CATALOG = { phase_events: [ 'phase_transition', @@ -44,6 +46,10 @@ export const EVENT_TYPES_CATALOG = { 'desktop_detector_started', 'desktop_detector_first_poll', 'desktop_detector_no_candidate', + // DesktopArrivalDetector owner-resolution trace: which explorer.exe owner was seen on + // the way to desktop_arrived — a real user, or an excluded system/placeholder identity. + 'desktop_real_user_detected', + 'desktop_excluded_user', 'oobe_state_completed', ], whiteglove_events: [ @@ -122,7 +128,17 @@ export const EVENT_TYPES_CATALOG = { identity_events: [ 'aad_placeholder_user_detected', 'aad_user_joined_observed', + // Hybrid: 10 min after a reboot still no real-user desktop — the sign-in is overdue. + // Measures desktop absence only; the JoinInfo placeholder is a fact in the payload, not evidence. 'hybrid_login_pending', + // Entra user affinity after the real-user desktop: IME acquired the signed-in user's token + // (Info, established) vs. still none after the delay (Warning, pending, carrying the IME + // token-failure codes observed since the desktop). + 'ime_user_token_acquired', + 'entra_user_affinity_pending', + // User Device Registration/Admin 304/305: automatic hybrid device registration failed at + // the join / authentication phase (Warning) — the OS-side failure record on the timeline. + 'device_registration_event', ], realmjoin_events: [ 'realmjoin_detected', @@ -352,6 +368,27 @@ export function isKnownEventType(s: string): boolean { return EVENT_TYPE_SET.has(s); } +/** + * Gather-rule output types (`outputEventType`, e.g. "gather_dsregcmd_status") are rule + * DATA — built-in and tenant-authored — not code-emitted types, so they are deliberately + * NOT catalogued: D-072 scopes the catalog to `Constants.EventTypes`, and the C# guard + * test excludes gather outputs for the same reason. They are real events on the wire + * nonetheless, so the filter gate lets any `gather_`-prefixed type (with a non-empty + * suffix) through — the same "a valid prefix passes even when the full key is + * uncatalogued" stance as assertKnownDevicePropertyKeys. Kept apart from + * isKnownEventType, whose strict "is a built-in type" meaning rule-validation relies + * on for its outputEventType collision check. + */ +const GATHER_OUTPUT_PREFIX = 'gather_'; +export function isGatherOutputEventType(s: string): boolean { + return s.startsWith(GATHER_OUTPUT_PREFIX) && s.length > GATHER_OUTPUT_PREFIX.length; +} + +/** True if `s` is accepted as an eventType filter: catalogued, internal, or a gather-rule output. */ +export function isFilterableEventType(s: string): boolean { + return isKnownEventType(s) || isGatherOutputEventType(s); +} + /** * Every catalogued deviceProperties key, flattened across event-type groups * (excluding the `_usage` doc block). This is a CURATED subset — not exhaustive — @@ -378,12 +415,13 @@ function suggestEventTypes(input: string): string[] { } /** - * Throws a descriptive Error if `eventType` is not a known type. The thrown - * message routes through the tools' `toolError` handler so the model gets an - * actionable correction instead of a misleading empty result. + * Throws a descriptive Error if `eventType` is neither a known type nor a + * gather-rule output (see isFilterableEventType). The thrown message routes + * through the tools' `toolError` handler so the model gets an actionable + * correction instead of a misleading empty result. */ export function assertKnownEventType(eventType: string): void { - if (isKnownEventType(eventType)) return; + if (isFilterableEventType(eventType)) return; const suggestions = suggestEventTypes(eventType); const hint = suggestions.length > 0 ? ` Did you mean: ${suggestions.join(', ')}?` : ''; throw new Error( diff --git a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts index e4874bea..15450785 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts @@ -162,12 +162,16 @@ export const RULE_AUTHORING_GUIDE = { phase_duration: 'Match a phase (eventType=esp_phase_changed, dataField=espPhase, operator=equals, ' + 'value=); the evidence carries durationSeconds. Combine with a confidenceFactor ' + - '"phase_duration > N" for the actual duration check.', + '"phase_duration > N" for the actual duration check. The condition is false (reason ' + + '"not measurable", evidence timestampProvenance=reader-zone-fallback) when the phase start ' + + 'or the next phase event is an IME-log event whose sourceOffsetOrigin is reader-zone-fallback ' + + '— that timestamp can be hours off, so no duration is derived from it.', app_install_duration: 'Compare app install duration in seconds (operator gt/lt/gte/lte, value=seconds). ' + 'Attempt-scoped: pairs each completion with the LATEST app_install_started before it ' + '(sequence order), so an IME re-evaluation pass an hour earlier does not inflate the ' + - 'value — same semantics as the apps dashboard since 2026-08.', + 'value — same semantics as the apps dashboard since 2026-08. A start/completion pair with a ' + + 'reader-zone-fallback sourceOffsetOrigin on either side is skipped as not measurable.', event_correlation: 'Join two event types over a shared field: eventType + correlateEventType + joinField, ' + 'optional timeWindowSeconds, optional eventAFilterField/-Operator/-Value to pre-filter the ' + diff --git a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts index 09b555c2..bb324abf 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts @@ -431,7 +431,7 @@ export const ANALYZE_RULE_SCHEMA: Record = { }, "source": { "type": "string", - "description": "Source of the signal.", + "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from an IME-log timestamp whose sourceOffsetOrigin is reader-zone-fallback (writer timezone unknown to the agent): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback.", "enum": [ "event_type", "event_data", diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts index 65f858c3..3e748a66 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts @@ -39,6 +39,9 @@ export const KEY_EVENT_TYPES = new Set([ 'agent_started', 'agent_shutdown', 'agent_shutting_down', 'agent_trace', 'script_started', 'script_completed', 'script_failed', 'historic_ime_replay_detected', 'vulnerability_report', 'system_sleep_episode', + // Info-level counterpart of entra_user_affinity_pending (Warning — admitted by severity): + // one line per agent run that disproves the hybrid affinity diagnosis, so it must key-rank. + 'ime_user_token_acquired', ]); // Phase-defining events promoted to the top of the triage timeline. Module-level // (not handler-local) so the same drift test can validate it. diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs index fa2efcdc..dd161b08 100644 --- a/src/Shared/AutopilotMonitor.Shared/Constants.cs +++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs @@ -368,6 +368,9 @@ namespace AutopilotMonitor.Shared public const string DesktopDetectorStarted = "desktop_detector_started"; // 1x on Start() / ResetForRealUserSwitch() public const string DesktopDetectorFirstPoll = "desktop_detector_first_poll"; // 1x after first PollForDesktop() completes public const string DesktopDetectorNoCandidate = "desktop_detector_no_candidate"; // 1x after threshold polls without resolution (configurable) + // DAD owner-resolution trace (single-rail, own EventTypes since 2026-05-15; consts since 2026-09-04 — D-072). + public const string DesktopRealUserDetected = "desktop_real_user_detected"; // explorer.exe owned by a real (non-placeholder, non-system) user + public const string DesktopExcludedUser = "desktop_excluded_user"; // explorer.exe owned by an excluded identity (system / defaultuser / placeholder), 1x // 1x when WinRT SystemSetupInfo.OutOfBoxExperienceState flips InProgress->Completed, // sampled on the DAD 30s poll. Observational only (no decision-engine involvement) — // an owner-independent desktop corroboration for sessions where WTS+WMI owner @@ -519,7 +522,21 @@ namespace AutopilotMonitor.Shared // Hybrid User-Driven enrollment observability (V2 — Hybrid completion gaps, 2026-05-01). // Pure observability — never consumed by the DecisionEngine, no DecisionSignalKind wired up. public const string AadPlaceholderUserDetected = "aad_placeholder_user_detected"; // foouser@/autopilot@ first appearance in JoinInfo - public const string HybridLoginPending = "hybrid_login_pending"; // Hybrid: 10 min after reboot still placeholder, real AD login overdue + // Hybrid: 10 min after a reboot still no real-user desktop — the sign-in is overdue. Measures + // desktop absence only (2026-09-04, session a7140f98): on a Hybrid join the AD sign-in never + // replaces the JoinInfo placeholder, so the placeholder is reported as a fact, not as evidence. + public const string HybridLoginPending = "hybrid_login_pending"; + // Entra user affinity after the real-user desktop (2026-09-04). IME acquires the signed-in + // user's token through WAM ("Successfully get the token", IntuneTokenManager) — that line is + // the only SYSTEM-visible proof that the user session has an Entra identity (PRT). The + // counterpart fires when no such token follows the desktop within the delay; the payload + // carries the IME token-failure codes observed since the desktop. Observability only. + public const string ImeUserTokenAcquired = "ime_user_token_acquired"; // Info, 1x per agent run: first IME user-token success after the real-user desktop + public const string EntraUserAffinityPending = "entra_user_affinity_pending"; // Warning, 1x per agent run: N min after the real-user desktop still no IME user token + // User Device Registration/Admin 304/305 (automatic registration failed at join / + // authentication phase) — surfaced so the hybrid affinity diagnosis has the OS-side + // failure record on the timeline instead of sending the operator to Event Viewer. + public const string DeviceRegistrationEvent = "device_registration_event"; // Real-user join — companion to AadPlaceholderUserDetected. The DecisionEngine consumes // these as DecisionSignalKind only (HandleAadUserJoinedLateV1 is observation-only and diff --git a/src/Shared/AutopilotMonitor.Shared/Logging/CmTraceLogParser.cs b/src/Shared/AutopilotMonitor.Shared/Logging/CmTraceLogParser.cs index 802755ac..aa6a1ff0 100644 --- a/src/Shared/AutopilotMonitor.Shared/Logging/CmTraceLogParser.cs +++ b/src/Shared/AutopilotMonitor.Shared/Logging/CmTraceLogParser.cs @@ -170,7 +170,13 @@ namespace AutopilotMonitor.Shared.Logging // A writer-declared bias is authoritative — it is the writer telling us its own // offset, which is exactly the fact we otherwise have to measure. - // GetTimeZoneInformation convention: UTC = local + bias. + // GetTimeZoneInformation convention: UTC = local + bias. This is what the native + // ConfigMgr client writes (a CET client logs "-60"); PowerShell loggers built on + // the DMTF SWbemDateTime offset write the opposite sign ("+060" for CET). No line + // with a suffix reached the fleet in 30 days of IME-derived events (39k events, + // 2026-09-04), so the convention is pinned by this comment and the parser test, + // not by field data; a line read with the wrong sign lands hours in the future + // and is caught by the adapter's future-skew clamp. DateTime? timestampUtc = null; if (hasTimestamp && biasMinutes.HasValue) { diff --git a/src/Web/autopilot-monitor-web/lib/timeProvenance.ts b/src/Web/autopilot-monitor-web/lib/timeProvenance.ts index 24479db3..274c8587 100644 --- a/src/Web/autopilot-monitor-web/lib/timeProvenance.ts +++ b/src/Web/autopilot-monitor-web/lib/timeProvenance.ts @@ -18,7 +18,7 @@ export interface TimeProvenance { sourceLocalTs: string | null; /** UTC offset in minutes that was APPLIED to resolve the timestamp. */ sourceOffsetMinutes: number | null; - /** How the applied offset was obtained: "bias" | "line-anchored" | "reader-zone-fallback" | retired "calibrated". */ + /** How the applied offset was obtained: "bias" | "line-anchored" | "era-anchored" | "reader-zone-fallback" | retired "calibrated". */ sourceOffsetOrigin: string | null; /** * Observational per-file measurement from the writer's own UTC lines — NOT the applied diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts index 70b4bce1..20945a79 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts @@ -398,7 +398,10 @@ export const SHARED_MANIFEST = { "desktop_detector_first_poll", "desktop_detector_no_candidate", "desktop_detector_started", + "desktop_excluded_user", + "desktop_real_user_detected", "device_location", + "device_registration_event", "diagnostics_collecting", "diagnostics_upload_failed", "diagnostics_uploaded", @@ -412,6 +415,7 @@ export const SHARED_MANIFEST = { "enrollment_summary_shown", "enrollment_type_detected", "enrollment_type_mismatch", + "entra_user_affinity_pending", "error_detected", "esp_apps_failure_correlation", "esp_appx_failure_analysis", @@ -457,6 +461,7 @@ export const SHARED_MANIFEST = { "ime_token_failure", "ime_tracker_degraded", "ime_user_session_completed", + "ime_user_token_acquired", "ingress_backpressure", "integrity_bypass_analysis", "keep_awake_engaged", diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.json b/src/Web/autopilot-monitor-web/utils/shared-manifests.json index 56aba868..4f16a1f8 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.json +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.json @@ -394,7 +394,10 @@ "desktop_detector_first_poll", "desktop_detector_no_candidate", "desktop_detector_started", + "desktop_excluded_user", + "desktop_real_user_detected", "device_location", + "device_registration_event", "diagnostics_collecting", "diagnostics_upload_failed", "diagnostics_uploaded", @@ -408,6 +411,7 @@ "enrollment_summary_shown", "enrollment_type_detected", "enrollment_type_mismatch", + "entra_user_affinity_pending", "error_detected", "esp_apps_failure_correlation", "esp_appx_failure_analysis", @@ -453,6 +457,7 @@ "ime_token_failure", "ime_tracker_degraded", "ime_user_session_completed", + "ime_user_token_acquired", "ingress_backpressure", "integrity_bypass_analysis", "keep_awake_engaged",