mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
session lifecycle: reliable end-detection for all deployment scenarios
Multi-signal enrollment completion with 3 independent paths: - IME pattern (existing), ESP final exit + Hello (composite), Desktop arrival + Hello (no-ESP/WDP v2) ESP failure detection: terminal failures emit enrollment_failed immediately, recoverable failures (ESPProgress_Timeout) get 1-min grace period with recovery cancellation on ESP phase change. Agent max lifetime timer (6h default, configurable per-tenant) as safety net against zombie agents. Desktop arrival detector polls explorer.exe with WMI owner validation. Enrollment state persistence for crash recovery. Completion check events with full state machine snapshot for observability. Backend maintenance interval reduced from daily to every 2 hours. ConfigVersion 12 → 13. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
@@ -145,6 +145,13 @@ namespace AutopilotMonitor.Agent.Core.Configuration
|
||||
/// </summary>
|
||||
public int AuthFailureTimeoutMinutes { get; set; } = 0;
|
||||
|
||||
/// <summary>
|
||||
/// Maximum agent lifetime in minutes. Safety net to prevent zombie agents.
|
||||
/// The agent emits enrollment_failed with failureType "agent_timeout" when this expires.
|
||||
/// 0 = disabled (no lifetime limit). Default: 360 (6 hours).
|
||||
/// </summary>
|
||||
public int AgentMaxLifetimeMinutes { get; set; } = 360;
|
||||
|
||||
/// <summary>
|
||||
/// Whether diagnostics upload is configured for this tenant.
|
||||
/// When true, the agent requests a short-lived upload URL from the backend just before uploading.
|
||||
|
||||
+183
@@ -0,0 +1,183 @@
|
||||
using System;
|
||||
using System.Diagnostics;
|
||||
using System.Management;
|
||||
using System.Threading;
|
||||
using AutopilotMonitor.Agent.Core.Logging;
|
||||
|
||||
namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
{
|
||||
/// <summary>
|
||||
/// Detects when a real user desktop becomes available (explorer.exe under a non-system user).
|
||||
/// Fires DesktopArrived event exactly once per agent lifetime.
|
||||
/// Used for enrollment completion in no-ESP scenarios (WDP v2, ESP disabled) and
|
||||
/// as a backup signal for AccountSetup phase correction.
|
||||
/// </summary>
|
||||
public class DesktopArrivalDetector : IDisposable
|
||||
{
|
||||
private readonly AgentLogger _logger;
|
||||
private Timer _pollingTimer;
|
||||
private bool _desktopArrived;
|
||||
private const int PollingIntervalSeconds = 30;
|
||||
|
||||
/// <summary>
|
||||
/// System/service account names that should NOT be considered real users.
|
||||
/// </summary>
|
||||
private static readonly string[] ExcludedUserNames =
|
||||
{
|
||||
"SYSTEM",
|
||||
"LOCAL SERVICE",
|
||||
"NETWORK SERVICE",
|
||||
"DefaultUser0",
|
||||
"DefaultUser1",
|
||||
"defaultuser0",
|
||||
"defaultuser1"
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// Fired exactly once when a real user desktop is detected (explorer.exe under a real user).
|
||||
/// </summary>
|
||||
public event EventHandler DesktopArrived;
|
||||
|
||||
public DesktopArrivalDetector(AgentLogger logger)
|
||||
{
|
||||
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
|
||||
}
|
||||
|
||||
public void Start()
|
||||
{
|
||||
_logger.Info("DesktopArrivalDetector: starting (polling every 30s)");
|
||||
_pollingTimer = new Timer(
|
||||
PollForDesktop,
|
||||
null,
|
||||
TimeSpan.FromSeconds(5), // Initial check after 5s
|
||||
TimeSpan.FromSeconds(PollingIntervalSeconds));
|
||||
}
|
||||
|
||||
public void Stop()
|
||||
{
|
||||
_pollingTimer?.Dispose();
|
||||
_pollingTimer = null;
|
||||
}
|
||||
|
||||
private void PollForDesktop(object state)
|
||||
{
|
||||
if (_desktopArrived)
|
||||
return;
|
||||
|
||||
try
|
||||
{
|
||||
var explorerProcesses = Process.GetProcessesByName("explorer");
|
||||
foreach (var proc in explorerProcesses)
|
||||
{
|
||||
try
|
||||
{
|
||||
// Session 0 = SYSTEM session, skip
|
||||
if (proc.SessionId == 0)
|
||||
continue;
|
||||
|
||||
var owner = GetProcessOwner(proc.Id);
|
||||
if (owner == null)
|
||||
continue;
|
||||
|
||||
// Check against exclusion list
|
||||
if (IsExcludedUser(owner))
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: explorer.exe PID {proc.Id} owned by excluded user '{owner}' — skipping");
|
||||
continue;
|
||||
}
|
||||
|
||||
// Real user desktop detected
|
||||
_desktopArrived = true;
|
||||
_logger.Info($"DesktopArrivalDetector: real user desktop detected (explorer.exe PID {proc.Id}, session {proc.SessionId}, user '{owner}')");
|
||||
|
||||
// Stop polling
|
||||
_pollingTimer?.Dispose();
|
||||
_pollingTimer = null;
|
||||
|
||||
try { DesktopArrived?.Invoke(this, EventArgs.Empty); } catch { }
|
||||
return;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: error checking explorer.exe PID {proc.Id}: {ex.Message}");
|
||||
}
|
||||
finally
|
||||
{
|
||||
proc.Dispose();
|
||||
}
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: polling error: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Gets the owner of a process using WMI (Win32_Process.GetOwner).
|
||||
/// Returns "DOMAIN\User" or "User" string, or null on failure.
|
||||
/// </summary>
|
||||
private string GetProcessOwner(int processId)
|
||||
{
|
||||
try
|
||||
{
|
||||
using (var searcher = new ManagementObjectSearcher(
|
||||
$"SELECT * FROM Win32_Process WHERE ProcessId = {processId}"))
|
||||
{
|
||||
foreach (ManagementObject obj in searcher.Get())
|
||||
{
|
||||
var outParams = new object[2];
|
||||
var result = (uint)obj.InvokeMethod("GetOwner", outParams);
|
||||
if (result == 0)
|
||||
{
|
||||
var user = outParams[0]?.ToString();
|
||||
var domain = outParams[1]?.ToString();
|
||||
return string.IsNullOrEmpty(domain) ? user : $"{domain}\\{user}";
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: WMI GetOwner failed for PID {processId}: {ex.Message}");
|
||||
}
|
||||
|
||||
return null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Returns true if the user name matches any excluded system/service account.
|
||||
/// Handles both "User" and "DOMAIN\User" formats.
|
||||
/// Also matches the pattern DefaultUser* (case-insensitive).
|
||||
/// </summary>
|
||||
private static bool IsExcludedUser(string fullUserName)
|
||||
{
|
||||
if (string.IsNullOrEmpty(fullUserName))
|
||||
return true;
|
||||
|
||||
// Extract just the username part (after backslash if present)
|
||||
var userName = fullUserName;
|
||||
var backslashIndex = fullUserName.LastIndexOf('\\');
|
||||
if (backslashIndex >= 0 && backslashIndex < fullUserName.Length - 1)
|
||||
userName = fullUserName.Substring(backslashIndex + 1);
|
||||
|
||||
// Check exact matches
|
||||
foreach (var excluded in ExcludedUserNames)
|
||||
{
|
||||
if (string.Equals(userName, excluded, StringComparison.OrdinalIgnoreCase))
|
||||
return true;
|
||||
}
|
||||
|
||||
// Check DefaultUser* pattern
|
||||
if (userName.StartsWith("DefaultUser", StringComparison.OrdinalIgnoreCase))
|
||||
return true;
|
||||
|
||||
return false;
|
||||
}
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Stop();
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -42,10 +42,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
private bool _espExitDetected = false;
|
||||
private bool _helloWizardStarted = false;
|
||||
private bool _whiteGloveDetected = false;
|
||||
private string _detectedEspFailureType; // set during Shell-Core event processing, consumed after event emission
|
||||
private readonly object _stateLock = new object();
|
||||
|
||||
private readonly int _helloWaitTimeoutSeconds;
|
||||
private const int HelloCompletionTimeoutSeconds = 1500;
|
||||
private const int HelloCompletionTimeoutSeconds = 300;
|
||||
private const int BackfillLookbackMinutes = 5;
|
||||
|
||||
/// <summary>
|
||||
@@ -66,6 +67,18 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
/// </summary>
|
||||
public event EventHandler WhiteGloveCompleted;
|
||||
|
||||
/// <summary>
|
||||
/// Fired when an ESP failure is detected (ESPProgress_Failure, _Timeout, _Abort, WhiteGlove_Failed, etc.).
|
||||
/// The string argument is the structured failure type (e.g. "ESPProgress_Failure", "ESPProgress_Timeout").
|
||||
/// </summary>
|
||||
public event EventHandler<string> EspFailureDetected;
|
||||
|
||||
/// <summary>
|
||||
/// Outcome of Hello provisioning. Set when Hello resolves (via events, timeout, or not configured).
|
||||
/// Values: "completed", "timeout", "not_configured", "wizard_not_started", null (not yet resolved).
|
||||
/// </summary>
|
||||
public string HelloOutcome { get; private set; }
|
||||
|
||||
private const string EventLogChannel = "Microsoft-Windows-User Device Registration/Admin";
|
||||
private const string ShellCoreEventLogChannel = "Microsoft-Windows-Shell-Core/Operational";
|
||||
|
||||
@@ -503,6 +516,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
}
|
||||
|
||||
_isHelloCompleted = true;
|
||||
HelloOutcome = "completed";
|
||||
StopHelloCompletionTimerLocked();
|
||||
return true;
|
||||
}
|
||||
@@ -649,10 +663,12 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
|| description.Contains("WhiteGlove_Failed", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("WhiteGlove_Failure", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
var failureType = ExtractEspFailureType(description);
|
||||
eventType = "esp_failure";
|
||||
severity = EventSeverity.Error;
|
||||
message = "ESP (Enrollment Status Page) reported a failure";
|
||||
_logger.Warning("ESP failure detected via Shell-Core event 62407");
|
||||
message = $"ESP (Enrollment Status Page) reported a failure: {failureType}";
|
||||
_logger.Warning($"ESP failure detected via Shell-Core event 62407: {failureType}");
|
||||
_detectedEspFailureType = failureType;
|
||||
}
|
||||
else if (System.Text.RegularExpressions.Regex.IsMatch(description, @"OOBE_ESP.*Exiting", System.Text.RegularExpressions.RegexOptions.IgnoreCase))
|
||||
{
|
||||
@@ -728,6 +744,20 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
}
|
||||
catch { }
|
||||
}
|
||||
|
||||
// Fire EspFailureDetected if this was an ESP failure event.
|
||||
// Must happen AFTER the event has been emitted above so the
|
||||
// esp_failure event is in the spool before the agent potentially shuts down.
|
||||
if (eventType == "esp_failure" && _detectedEspFailureType != null)
|
||||
{
|
||||
var failureType = _detectedEspFailureType;
|
||||
_detectedEspFailureType = null;
|
||||
try
|
||||
{
|
||||
EspFailureDetected?.Invoke(this, failureType);
|
||||
}
|
||||
catch { }
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -797,6 +827,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
_logger.Info("Hello policy not detected as enabled — assuming Hello is not configured or was skipped");
|
||||
|
||||
_isHelloCompleted = true;
|
||||
HelloOutcome = "not_configured";
|
||||
StopHelloCompletionTimerLocked();
|
||||
|
||||
// Emit event for tracking
|
||||
@@ -913,6 +944,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
|
||||
_logger.Warning($"Hello completion timeout ({HelloCompletionTimeoutSeconds}s) expired after wizard start without terminal event");
|
||||
_isHelloCompleted = true;
|
||||
HelloOutcome = _helloWizardStarted ? "timeout" : "wizard_not_started";
|
||||
StopHelloCompletionTimerLocked();
|
||||
|
||||
_onEventCollected(new EnrollmentEvent
|
||||
@@ -942,6 +974,89 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Extracts a structured failure type from the Shell-Core event description.
|
||||
/// E.g. "ESPProgress_Failure", "ESPProgress_Timeout", "WhiteGlove_Failed".
|
||||
/// </summary>
|
||||
private static string ExtractEspFailureType(string description)
|
||||
{
|
||||
// Known failure type keywords to search for in order of specificity
|
||||
string[] knownTypes = {
|
||||
"ESPProgress_Failure",
|
||||
"ESPProgress_Failed",
|
||||
"ESPProgress_Timeout",
|
||||
"ESPProgress_Abort",
|
||||
"WhiteGlove_Failed",
|
||||
"WhiteGlove_Failure"
|
||||
};
|
||||
|
||||
foreach (var type in knownTypes)
|
||||
{
|
||||
if (description.Contains(type, StringComparison.OrdinalIgnoreCase))
|
||||
return type;
|
||||
}
|
||||
|
||||
return "Unknown_ESP_Failure";
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Backfills recent ESP exit and failure events from Shell-Core log on startup.
|
||||
/// Secondary recovery mechanism when state persistence is unavailable.
|
||||
/// </summary>
|
||||
public void BackfillRecentEspExitEvents()
|
||||
{
|
||||
try
|
||||
{
|
||||
var lookbackMs = BackfillLookbackMinutes * 60 * 1000;
|
||||
var query = new EventLogQuery(
|
||||
ShellCoreEventLogChannel,
|
||||
PathType.LogName,
|
||||
$"*[System[(EventID=62407) and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]");
|
||||
|
||||
using (var reader = new EventLogReader(query))
|
||||
{
|
||||
for (EventRecord record = reader.ReadEvent(); record != null; record = reader.ReadEvent())
|
||||
{
|
||||
using (record)
|
||||
{
|
||||
var description = record.FormatDescription() ?? "";
|
||||
|
||||
// Check for ESP exit
|
||||
if (System.Text.RegularExpressions.Regex.IsMatch(description, @"OOBE_ESP.*Exiting", System.Text.RegularExpressions.RegexOptions.IgnoreCase))
|
||||
{
|
||||
lock (_stateLock)
|
||||
{
|
||||
if (!_espExitDetected)
|
||||
{
|
||||
_espExitDetected = true;
|
||||
_logger.Info("Backfill: ESP exit event found in recent Shell-Core logs");
|
||||
try { FinalizingSetupPhaseTriggered?.Invoke(this, "esp_exiting"); } catch { }
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// Check for ESP failures
|
||||
if (description.Contains("ESPProgress_Failure", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("ESPProgress_Failed", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("ESPProgress_Timeout", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("ESPProgress_Abort", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("WhiteGlove_Failed", StringComparison.OrdinalIgnoreCase)
|
||||
|| description.Contains("WhiteGlove_Failure", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
var failureType = ExtractEspFailureType(description);
|
||||
_logger.Info($"Backfill: ESP failure event found in recent Shell-Core logs: {failureType}");
|
||||
try { EspFailureDetected?.Invoke(this, failureType); } catch { }
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Warning($"ESP exit/failure event backfill failed: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
private void BackfillRecentTerminalHelloEvents()
|
||||
{
|
||||
try
|
||||
|
||||
@@ -65,6 +65,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
|
||||
private int _collectorIdleTimeoutMinutes = 15;
|
||||
private Timer _idleCheckTimer;
|
||||
|
||||
// Desktop arrival detection (no-ESP scenarios)
|
||||
private DesktopArrivalDetector _desktopArrivalDetector;
|
||||
|
||||
// Agent max lifetime safety net
|
||||
private Timer _maxLifetimeTimer;
|
||||
private readonly DateTime _agentStartTimeUtc = DateTime.UtcNow;
|
||||
private bool _enrollmentTerminalEventSeen;
|
||||
|
||||
// Auth failure circuit breaker
|
||||
private int _consecutiveAuthFailures = 0;
|
||||
private DateTime? _firstAuthFailureTime = null;
|
||||
@@ -407,6 +415,27 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
|
||||
);
|
||||
_enrollmentTracker.Start();
|
||||
}
|
||||
|
||||
// Desktop arrival detector — detects real user desktop for no-ESP completion
|
||||
_desktopArrivalDetector = new DesktopArrivalDetector(_logger);
|
||||
_desktopArrivalDetector.DesktopArrived += OnDesktopArrived;
|
||||
_desktopArrivalDetector.Start();
|
||||
|
||||
// Agent max lifetime safety net — prevents zombie agents
|
||||
var maxLifetimeMinutes = collectors?.AgentMaxLifetimeMinutes ?? _configuration.AgentMaxLifetimeMinutes;
|
||||
if (maxLifetimeMinutes > 0)
|
||||
{
|
||||
_maxLifetimeTimer = new Timer(
|
||||
MaxLifetimeTimerCallback,
|
||||
null,
|
||||
TimeSpan.FromMinutes(maxLifetimeMinutes),
|
||||
Timeout.InfiniteTimeSpan);
|
||||
_logger.Info($"Agent max lifetime timer armed: {maxLifetimeMinutes} min");
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Info("Agent max lifetime timer disabled (0)");
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -422,6 +451,16 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
|
||||
_idleCheckTimer?.Dispose();
|
||||
_idleCheckTimer = null;
|
||||
|
||||
_maxLifetimeTimer?.Dispose();
|
||||
_maxLifetimeTimer = null;
|
||||
|
||||
if (_desktopArrivalDetector != null)
|
||||
{
|
||||
_desktopArrivalDetector.DesktopArrived -= OnDesktopArrived;
|
||||
_desktopArrivalDetector.Dispose();
|
||||
_desktopArrivalDetector = null;
|
||||
}
|
||||
|
||||
_performanceCollector?.Stop();
|
||||
_performanceCollector?.Dispose();
|
||||
_performanceCollector = null;
|
||||
@@ -435,6 +474,67 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
|
||||
_enrollmentTracker = null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Fires when the agent max lifetime expires. Emits enrollment_failed with failureType "agent_timeout".
|
||||
/// The normal shutdown path (EmitEvent → enrollment_failed) handles everything from here.
|
||||
/// </summary>
|
||||
private void MaxLifetimeTimerCallback(object state)
|
||||
{
|
||||
if (_enrollmentTerminalEventSeen)
|
||||
{
|
||||
_logger.Debug("Max lifetime timer fired but terminal event already seen — ignoring");
|
||||
return;
|
||||
}
|
||||
|
||||
var uptimeMinutes = (DateTime.UtcNow - _agentStartTimeUtc).TotalMinutes;
|
||||
_logger.Warning($"Agent max lifetime expired after {uptimeMinutes:F0} minutes — emitting enrollment_failed");
|
||||
|
||||
EmitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _configuration.SessionId,
|
||||
TenantId = _configuration.TenantId,
|
||||
EventType = "enrollment_failed",
|
||||
Severity = EventSeverity.Error,
|
||||
Source = "MonitoringService",
|
||||
Phase = EnrollmentPhase.Complete,
|
||||
Message = $"Agent max lifetime expired ({uptimeMinutes:F0} min) — enrollment did not complete in time",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "failureType", "agent_timeout" },
|
||||
{ "failureSource", "max_lifetime_timer" },
|
||||
{ "agentUptimeMinutes", Math.Round(uptimeMinutes, 1) }
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Fires when DesktopArrivalDetector detects explorer.exe under a real user.
|
||||
/// Emits desktop_arrived event for the timeline and notifies EnrollmentTracker.
|
||||
/// </summary>
|
||||
private void OnDesktopArrived(object sender, EventArgs e)
|
||||
{
|
||||
if (_enrollmentTerminalEventSeen)
|
||||
{
|
||||
_logger.Debug("Desktop arrived but terminal event already seen — ignoring");
|
||||
return;
|
||||
}
|
||||
|
||||
// Emit informational event for the timeline (shows when user desktop appeared)
|
||||
EmitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _configuration.SessionId,
|
||||
TenantId = _configuration.TenantId,
|
||||
EventType = "desktop_arrived",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "DesktopArrivalDetector",
|
||||
Phase = EnrollmentPhase.Unknown,
|
||||
Message = "User desktop detected (explorer.exe under real user)"
|
||||
});
|
||||
|
||||
// Notify EnrollmentTracker — it decides whether this triggers completion
|
||||
_enrollmentTracker?.NotifyDesktopArrived();
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Returns true for events generated by periodic timers (not real enrollment activity)
|
||||
/// </summary>
|
||||
@@ -878,6 +978,15 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
|
||||
_sessionPersistence.SaveSequence(evt.Sequence);
|
||||
}
|
||||
|
||||
// Cancel max lifetime timer on terminal events
|
||||
if (evt.EventType == "whiteglove_complete" ||
|
||||
evt.EventType == "enrollment_complete" ||
|
||||
evt.EventType == "enrollment_failed")
|
||||
{
|
||||
_enrollmentTerminalEventSeen = true;
|
||||
_maxLifetimeTimer?.Change(Timeout.Infinite, Timeout.Infinite);
|
||||
}
|
||||
|
||||
// Check if this is a phase transition
|
||||
bool isPhaseTransition = false;
|
||||
if (evt.Phase != _lastPhase)
|
||||
|
||||
+118
@@ -0,0 +1,118 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using AutopilotMonitor.Agent.Core.Logging;
|
||||
using Newtonsoft.Json;
|
||||
|
||||
namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
{
|
||||
/// <summary>
|
||||
/// Handles persistence of EnrollmentTracker state to disk (JSON serialization).
|
||||
/// Enables crash-recovery: after agent restart, completion signals already seen
|
||||
/// (ESP exit, desktop arrival, etc.) are restored so the enrollment can complete.
|
||||
/// Pattern follows ImeTrackerStatePersistence.
|
||||
/// </summary>
|
||||
public class EnrollmentStatePersistence
|
||||
{
|
||||
private readonly string _stateDirectory;
|
||||
private readonly string _stateFilePath;
|
||||
private readonly AgentLogger _logger;
|
||||
|
||||
public EnrollmentStatePersistence(string stateDirectory, AgentLogger logger)
|
||||
{
|
||||
_stateDirectory = Environment.ExpandEnvironmentVariables(stateDirectory);
|
||||
_stateFilePath = Path.Combine(_stateDirectory, "enrollment-state.json");
|
||||
_logger = logger;
|
||||
}
|
||||
|
||||
public string StateFilePath => _stateFilePath;
|
||||
|
||||
/// <summary>
|
||||
/// Loads persisted state from disk. Returns null if no state file exists or on error.
|
||||
/// </summary>
|
||||
public EnrollmentStateData Load()
|
||||
{
|
||||
if (!File.Exists(_stateFilePath))
|
||||
{
|
||||
_logger.Info("EnrollmentStatePersistence: no persisted state found (fresh enrollment)");
|
||||
return null;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
var json = File.ReadAllText(_stateFilePath);
|
||||
var state = JsonConvert.DeserializeObject<EnrollmentStateData>(json);
|
||||
if (state == null)
|
||||
{
|
||||
_logger.Warning("EnrollmentStatePersistence: persisted state file was empty or invalid");
|
||||
return null;
|
||||
}
|
||||
return state;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Warning($"EnrollmentStatePersistence: failed to load persisted state, starting fresh: {ex.Message}");
|
||||
return null;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Persists tracker state to disk as JSON (atomic write via temp file).
|
||||
/// </summary>
|
||||
public void Save(EnrollmentStateData state)
|
||||
{
|
||||
try
|
||||
{
|
||||
Directory.CreateDirectory(_stateDirectory);
|
||||
var tempPath = _stateFilePath + ".tmp";
|
||||
File.WriteAllText(tempPath, JsonConvert.SerializeObject(state, Formatting.Indented));
|
||||
File.Copy(tempPath, _stateFilePath, overwrite: true);
|
||||
try { File.Delete(tempPath); } catch { }
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"EnrollmentStatePersistence: failed to save state: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Deletes persisted state file.
|
||||
/// </summary>
|
||||
public void Delete()
|
||||
{
|
||||
try
|
||||
{
|
||||
if (File.Exists(_stateFilePath))
|
||||
{
|
||||
File.Delete(_stateFilePath);
|
||||
_logger.Info("EnrollmentStatePersistence: persisted state deleted");
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"EnrollmentStatePersistence: failed to delete state file: {ex.Message}");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// ---- DTO for state serialization ----
|
||||
|
||||
public class EnrollmentStateData
|
||||
{
|
||||
public bool EspEverSeen { get; set; }
|
||||
public bool EspFinalExitSeen { get; set; }
|
||||
public bool DesktopArrived { get; set; }
|
||||
public string LastEspPhase { get; set; }
|
||||
public bool IsWaitingForHello { get; set; }
|
||||
public bool EnrollmentCompleteEmitted { get; set; }
|
||||
public string EnrollmentType { get; set; }
|
||||
|
||||
// Signal timestamps for audit trail
|
||||
public DateTime? EspFirstSeenUtc { get; set; }
|
||||
public DateTime? EspFinalExitUtc { get; set; }
|
||||
public DateTime? DesktopArrivedUtc { get; set; }
|
||||
public DateTime? HelloResolvedUtc { get; set; }
|
||||
public DateTime? ImePatternSeenUtc { get; set; }
|
||||
public List<string> SignalsSeen { get; set; } = new List<string>();
|
||||
}
|
||||
}
|
||||
@@ -35,6 +35,34 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
private bool _finalDeviceInfoCollected = false; // Ensure final device info is emitted only once
|
||||
private string _lastEmittedSummaryHash; // Track last emitted state-breakdown to avoid redundant summary events
|
||||
|
||||
// ESP failure handling (Phase 1)
|
||||
private Timer _espFailureTimer;
|
||||
private string _pendingEspFailureType;
|
||||
private const int EspFailureGracePeriodSeconds = 60;
|
||||
private static readonly HashSet<string> RecoverableEspFailureTypes = new HashSet<string>(StringComparer.OrdinalIgnoreCase)
|
||||
{
|
||||
"ESPProgress_Timeout"
|
||||
};
|
||||
|
||||
// Unified completion logic (Phase 3A)
|
||||
private bool _espEverSeen;
|
||||
private bool _espFinalExitSeen;
|
||||
private bool _enrollmentCompleteEmitted;
|
||||
private bool _desktopArrived;
|
||||
private readonly DateTime _agentStartTimeUtc = DateTime.UtcNow;
|
||||
|
||||
// Device-Only ESP detection (Phase 3C)
|
||||
private Timer _deviceOnlyEspTimer;
|
||||
private const int DeviceOnlyEspTimerMinutes = 5;
|
||||
|
||||
// State persistence for crash recovery
|
||||
private readonly EnrollmentStatePersistence _statePersistence;
|
||||
private EnrollmentStateData _stateData = new EnrollmentStateData();
|
||||
private bool _stateDirty;
|
||||
|
||||
// Completion check throttling (max 1x/min per source)
|
||||
private readonly Dictionary<string, DateTime> _lastCompletionCheckBySource = new Dictionary<string, DateTime>();
|
||||
|
||||
// Default IME log folder
|
||||
private const string DefaultImeLogFolder = @"%ProgramData%\Microsoft\IntuneManagementExtension\Logs";
|
||||
|
||||
@@ -115,8 +143,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
_espAndHelloTracker = espAndHelloTracker;
|
||||
_deviceInfoCollector = new Collectors.DeviceInfoCollector(sessionId, tenantId, emitEvent, logger);
|
||||
|
||||
// Create ImeLogTracker with state persistence directory
|
||||
// State persistence for crash recovery
|
||||
var stateDirectory = @"%ProgramData%\AutopilotMonitor\State";
|
||||
_statePersistence = new EnrollmentStatePersistence(stateDirectory, _logger);
|
||||
|
||||
// Create ImeLogTracker with state persistence directory
|
||||
_imeLogTracker = new ImeLogTracker(_imeLogFolder, _imeLogPatterns, _logger, matchLogPath: imeMatchLogPath, stateDirectory: stateDirectory);
|
||||
_imeLogTracker.SimulationMode = simulationMode;
|
||||
_imeLogTracker.SpeedFactor = speedFactor;
|
||||
@@ -137,6 +168,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
_espAndHelloTracker.HelloCompleted += OnHelloCompleted;
|
||||
_espAndHelloTracker.FinalizingSetupPhaseTriggered += OnFinalizingSetupPhaseTriggered;
|
||||
_espAndHelloTracker.WhiteGloveCompleted += OnWhiteGloveCompleted;
|
||||
_espAndHelloTracker.EspFailureDetected += OnEspFailureDetected;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -147,6 +179,9 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: starting");
|
||||
|
||||
// Load persisted state for crash recovery
|
||||
LoadState();
|
||||
|
||||
// Start IME log tracking immediately — this is the critical enrollment watcher.
|
||||
// Device info collection (WMI + registry) runs in the background so it doesn't
|
||||
// delay the ImeLogTracker from catching early enrollment events.
|
||||
@@ -198,6 +233,8 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
{
|
||||
var result = _deviceInfoCollector.CollectAll();
|
||||
_enrollmentType = result.enrollmentType;
|
||||
_stateData.EnrollmentType = _enrollmentType;
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -228,6 +265,26 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
_logger.Info($"EnrollmentTracker: ESP phase changed from '{_lastEspPhase ?? "null"}' to '{phase}'");
|
||||
_lastEspPhase = phase;
|
||||
_hasAutoSwitchedToAppsPhase = false; // Reset when ESP phase changes
|
||||
_espEverSeen = true;
|
||||
_stateData.EspEverSeen = true;
|
||||
_stateData.LastEspPhase = phase;
|
||||
if (_stateData.EspFirstSeenUtc == null)
|
||||
_stateData.EspFirstSeenUtc = DateTime.UtcNow;
|
||||
RecordSignal($"esp_phase_{phase}");
|
||||
|
||||
// ESP phase change means ESP is progressing — cancel any pending failure grace period
|
||||
CancelPendingEspFailure();
|
||||
|
||||
// Cancel device-only ESP timer if AccountSetup phase detected
|
||||
if (string.Equals(phase, "AccountSetup", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
if (_deviceOnlyEspTimer != null)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: AccountSetup detected — cancelling device-only ESP timer");
|
||||
_deviceOnlyEspTimer.Dispose();
|
||||
_deviceOnlyEspTimer = null;
|
||||
}
|
||||
}
|
||||
|
||||
// Map ESP phase to EnrollmentPhase (phase change events)
|
||||
var enrollmentPhase = EnrollmentPhase.DeviceSetup;
|
||||
@@ -358,6 +415,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
break;
|
||||
|
||||
case AppInstallationState.Installing:
|
||||
// Only emit the strategic event once when install actually starts.
|
||||
// Progress-only updates (oldState == Installing, just progress/bytes changed)
|
||||
// are skipped — same pattern as Downloading above.
|
||||
if (oldState == AppInstallationState.Installing)
|
||||
return;
|
||||
eventType = "app_install_started";
|
||||
break;
|
||||
|
||||
@@ -496,6 +558,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
private void HandleUserSessionCompleted()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: User session completed (detected from IME log)");
|
||||
_stateData.ImePatternSeenUtc = DateTime.UtcNow;
|
||||
RecordSignal("ime_pattern");
|
||||
|
||||
// User session completed successfully — cancel any pending ESP failure
|
||||
CancelPendingEspFailure();
|
||||
|
||||
// Stop summary timer if running
|
||||
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
|
||||
@@ -531,70 +598,41 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
// or when the agent is stopped/times out
|
||||
return;
|
||||
}
|
||||
|
||||
if (helloPolicyConfigured && helloCompleted)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Windows Hello provisioning has completed. Enrollment can complete.");
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: No Windows Hello policy detected. Enrollment can complete.");
|
||||
}
|
||||
}
|
||||
|
||||
// Emit enrollment completed event
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "enrollment_complete",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "ImeLogTracker",
|
||||
Phase = EnrollmentPhase.Complete,
|
||||
Message = "Autopilot enrollment completed successfully (user session completed)"
|
||||
});
|
||||
|
||||
// Write enrollment complete marker for cleanup retry detection
|
||||
WriteEnrollmentCompleteMarker();
|
||||
|
||||
// Clean up persisted tracker state so next enrollment starts fresh
|
||||
_imeLogTracker?.DeleteState();
|
||||
TryEmitEnrollmentComplete("ime_pattern");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called when Windows Hello provisioning completes (via HelloDetector event)
|
||||
/// If we were waiting for Hello, now we can mark enrollment as complete
|
||||
/// Called when Windows Hello provisioning completes (via EspAndHelloTracker event).
|
||||
/// Multiple completion paths: IME pattern was waiting for Hello, ESP final exit + Hello composite,
|
||||
/// or Desktop arrival + Hello.
|
||||
/// </summary>
|
||||
private void OnHelloCompleted(object sender, EventArgs e)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Received HelloCompleted event from HelloDetector");
|
||||
_logger.Info("EnrollmentTracker: Received HelloCompleted event from EspAndHelloTracker");
|
||||
_stateData.HelloResolvedUtc = DateTime.UtcNow;
|
||||
RecordSignal("hello_resolved");
|
||||
|
||||
if (_isWaitingForHello)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Hello provisioning completed while waiting - marking enrollment as complete now");
|
||||
_logger.Info("EnrollmentTracker: Hello provisioning completed while waiting (IME path) - marking enrollment as complete now");
|
||||
_isWaitingForHello = false;
|
||||
|
||||
// Emit enrollment completed event
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "enrollment_complete",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "EnrollmentTracker",
|
||||
Phase = EnrollmentPhase.Complete,
|
||||
Message = "Autopilot enrollment completed successfully (Hello provisioning completed)"
|
||||
});
|
||||
|
||||
// Write enrollment complete marker for cleanup retry detection
|
||||
WriteEnrollmentCompleteMarker();
|
||||
|
||||
// Clean up persisted tracker state so next enrollment starts fresh
|
||||
_imeLogTracker?.DeleteState();
|
||||
TryEmitEnrollmentComplete("ime_hello");
|
||||
}
|
||||
else if (_espFinalExitSeen)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Hello completed + ESP final exit seen — composite completion");
|
||||
TryEmitEnrollmentComplete("esp_hello_composite");
|
||||
}
|
||||
else if (_desktopArrived)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Hello completed + desktop arrived — desktop-hello completion");
|
||||
TryEmitEnrollmentComplete("desktop_hello");
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Debug("EnrollmentTracker: HelloCompleted event received but not waiting - ignoring");
|
||||
_logger.Debug("EnrollmentTracker: HelloCompleted event received but no completion trigger active yet");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -628,6 +666,96 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
// Der State wird fuer Part 2 benoetigt falls der Tracker weiterlaufen muss.
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called when an ESP failure is detected (ESPProgress_Failure, _Timeout, _Abort, WhiteGlove_Failed, etc.).
|
||||
/// Terminal failures emit enrollment_failed immediately.
|
||||
/// Recoverable failures (e.g. ESPProgress_Timeout) get a grace period before failure.
|
||||
/// </summary>
|
||||
private void OnEspFailureDetected(object sender, string failureType)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: ESP failure detected: {failureType}");
|
||||
|
||||
if (RecoverableEspFailureTypes.Contains(failureType))
|
||||
{
|
||||
// Recoverable failure — start grace period timer
|
||||
_logger.Info($"EnrollmentTracker: '{failureType}' is recoverable — starting {EspFailureGracePeriodSeconds}s grace period");
|
||||
_pendingEspFailureType = failureType;
|
||||
|
||||
// Cancel existing timer if any (e.g. second timeout event)
|
||||
_espFailureTimer?.Dispose();
|
||||
_espFailureTimer = new Timer(
|
||||
OnEspFailureGracePeriodExpired,
|
||||
null,
|
||||
TimeSpan.FromSeconds(EspFailureGracePeriodSeconds),
|
||||
TimeSpan.FromMilliseconds(-1));
|
||||
}
|
||||
else
|
||||
{
|
||||
// Terminal failure — emit enrollment_failed immediately
|
||||
_logger.Info($"EnrollmentTracker: '{failureType}' is terminal — emitting enrollment_failed immediately");
|
||||
EmitEnrollmentFailed(failureType, "esp_failure");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called when the ESP failure grace period expires without recovery.
|
||||
/// Emits enrollment_failed.
|
||||
/// </summary>
|
||||
private void OnEspFailureGracePeriodExpired(object state)
|
||||
{
|
||||
var failureType = _pendingEspFailureType ?? "unknown";
|
||||
_logger.Warning($"EnrollmentTracker: ESP failure grace period ({EspFailureGracePeriodSeconds}s) expired for '{failureType}' — emitting enrollment_failed");
|
||||
_pendingEspFailureType = null;
|
||||
|
||||
EmitEnrollmentFailed(failureType, "esp_failure_grace_expired");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Cancels any pending ESP failure grace period timer (called when recovery is detected).
|
||||
/// </summary>
|
||||
private void CancelPendingEspFailure()
|
||||
{
|
||||
if (_espFailureTimer != null)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: ESP recovery detected — cancelling pending failure for '{_pendingEspFailureType}'");
|
||||
_espFailureTimer.Dispose();
|
||||
_espFailureTimer = null;
|
||||
_pendingEspFailureType = null;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Emits an enrollment_failed event. The MonitoringService handles shutdown identically to enrollment_complete.
|
||||
/// </summary>
|
||||
private void EmitEnrollmentFailed(string failureType, string failureSource)
|
||||
{
|
||||
// Stop summary timer
|
||||
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
|
||||
_summaryTimerActive = false;
|
||||
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "enrollment_failed",
|
||||
Severity = EventSeverity.Error,
|
||||
Source = "EnrollmentTracker",
|
||||
Phase = EnrollmentPhase.Complete,
|
||||
Message = $"Autopilot enrollment failed: {failureType}",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "failureType", failureType },
|
||||
{ "failureSource", failureSource },
|
||||
{ "signalsSeen", _stateData.SignalsSeen },
|
||||
{ "agentUptimeSeconds", (DateTime.UtcNow - _agentStartTimeUtc).TotalSeconds }
|
||||
}
|
||||
});
|
||||
|
||||
// Clean up persisted tracker state
|
||||
_imeLogTracker?.DeleteState();
|
||||
_statePersistence.Delete();
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called when ESP exit or Hello wizard start is detected (via HelloDetector Shell-Core events)
|
||||
/// Triggers transition to FinalizingSetup phase
|
||||
@@ -639,10 +767,20 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
// If ESP exiting, check which phase we're in
|
||||
if (reason == "esp_exiting")
|
||||
{
|
||||
if (string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase))
|
||||
_espEverSeen = true;
|
||||
|
||||
if (string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase) || _desktopArrived)
|
||||
{
|
||||
// AccountSetup phase exiting - this is the final ESP exit, start Hello wait timer
|
||||
_logger.Info("EnrollmentTracker: AccountSetup phase exiting - enrollment nearing completion, starting Hello wait timer");
|
||||
// Final ESP exit: either AccountSetup phase detected OR desktop arrived (backup)
|
||||
var phaseInfo = string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase)
|
||||
? "AccountSetup"
|
||||
: $"{_lastEspPhase ?? "unknown"} (desktop arrival backup)";
|
||||
_logger.Info($"EnrollmentTracker: ESP final exit from {phaseInfo} — marking _espFinalExitSeen, starting Hello wait timer");
|
||||
|
||||
_espFinalExitSeen = true;
|
||||
_stateData.EspFinalExitSeen = true;
|
||||
_stateData.EspFinalExitUtc = DateTime.UtcNow;
|
||||
RecordSignal("esp_final_exit");
|
||||
|
||||
// Emit phase change event to FinalizingSetup
|
||||
_emitEvent(new EnrollmentEvent
|
||||
@@ -653,13 +791,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "EnrollmentTracker",
|
||||
Phase = EnrollmentPhase.FinalizingSetup,
|
||||
Message = "ESP phase: FinalizingSetup (AccountSetup completed, waiting for final steps)",
|
||||
Message = $"ESP phase: FinalizingSetup ({phaseInfo} completed, waiting for final steps)",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "espPhase", "FinalizingSetup" },
|
||||
{ "autoDetected", true },
|
||||
{ "triggeredBy", reason },
|
||||
{ "previousPhase", "AccountSetup" }
|
||||
{ "previousPhase", _lastEspPhase ?? "unknown" },
|
||||
{ "desktopArrivedBackup", _desktopArrived && !string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase) }
|
||||
}
|
||||
});
|
||||
|
||||
@@ -670,11 +809,16 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
}
|
||||
else
|
||||
{
|
||||
// DeviceSetup phase exiting - this is just transition to AccountSetup, not final
|
||||
_logger.Info($"EnrollmentTracker: ESP phase exiting from '{_lastEspPhase ?? "unknown"}' - intermediate transition, not starting Hello wait timer");
|
||||
// DeviceSetup phase exiting without desktop — intermediate transition (Device→Account) or device-only ESP
|
||||
_logger.Info($"EnrollmentTracker: ESP phase exiting from '{_lastEspPhase ?? "unknown"}' - intermediate transition, starting device-only ESP detection timer ({DeviceOnlyEspTimerMinutes}min)");
|
||||
|
||||
// Don't emit FinalizingSetup event yet, this is not the final exit
|
||||
// The regular esp_phase_changed event will be emitted when we detect AccountSetup phase
|
||||
// Start device-only ESP detection timer
|
||||
_deviceOnlyEspTimer?.Dispose();
|
||||
_deviceOnlyEspTimer = new Timer(
|
||||
OnDeviceOnlyEspTimerExpired,
|
||||
null,
|
||||
TimeSpan.FromMinutes(DeviceOnlyEspTimerMinutes),
|
||||
TimeSpan.FromMilliseconds(-1));
|
||||
}
|
||||
}
|
||||
else if (reason == "hello_wizard_started")
|
||||
@@ -703,6 +847,245 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
}
|
||||
}
|
||||
|
||||
// ===== State Persistence =====
|
||||
|
||||
private void LoadState()
|
||||
{
|
||||
var loaded = _statePersistence.Load();
|
||||
if (loaded == null)
|
||||
return;
|
||||
|
||||
_espEverSeen = loaded.EspEverSeen;
|
||||
_espFinalExitSeen = loaded.EspFinalExitSeen;
|
||||
_desktopArrived = loaded.DesktopArrived;
|
||||
_lastEspPhase = loaded.LastEspPhase;
|
||||
_isWaitingForHello = loaded.IsWaitingForHello;
|
||||
_enrollmentCompleteEmitted = loaded.EnrollmentCompleteEmitted;
|
||||
_enrollmentType = loaded.EnrollmentType ?? _enrollmentType;
|
||||
_stateData = loaded;
|
||||
|
||||
_logger.Info($"EnrollmentTracker: state restored — espEverSeen={_espEverSeen}, espFinalExitSeen={_espFinalExitSeen}, desktopArrived={_desktopArrived}, lastEspPhase={_lastEspPhase}, enrollmentCompleteEmitted={_enrollmentCompleteEmitted}");
|
||||
|
||||
// Restart Hello wait timer if needed after crash recovery
|
||||
if ((_desktopArrived || _espFinalExitSeen) && _espAndHelloTracker != null && !_espAndHelloTracker.IsHelloCompleted)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: restarting Hello wait timer after state recovery");
|
||||
_espAndHelloTracker.StartHelloWaitTimer();
|
||||
}
|
||||
}
|
||||
|
||||
private void RecordSignal(string signal)
|
||||
{
|
||||
if (!_stateData.SignalsSeen.Contains(signal))
|
||||
_stateData.SignalsSeen.Add(signal);
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
// ===== Unified Completion Logic =====
|
||||
|
||||
/// <summary>
|
||||
/// Central guard method for enrollment_complete emission. All completion paths route through here.
|
||||
/// An _enrollmentCompleteEmitted flag prevents double emission.
|
||||
/// Emits a throttled completion_check event on every call for observability.
|
||||
/// </summary>
|
||||
private void TryEmitEnrollmentComplete(string source)
|
||||
{
|
||||
if (_enrollmentCompleteEmitted)
|
||||
{
|
||||
_logger.Debug($"EnrollmentTracker: TryEmitEnrollmentComplete('{source}') — already emitted, skipping");
|
||||
return;
|
||||
}
|
||||
|
||||
if (string.IsNullOrEmpty(source))
|
||||
return;
|
||||
|
||||
// Hello-Check: Hello must be resolved before we can complete
|
||||
bool helloResolved = _espAndHelloTracker == null
|
||||
|| _espAndHelloTracker.IsHelloCompleted
|
||||
|| !_espAndHelloTracker.IsPolicyConfigured;
|
||||
|
||||
if (!helloResolved)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: Completion source '{source}' ready but Hello still pending — not completing yet");
|
||||
EmitCompletionCheck(source, "hello_pending", "hello_not_resolved");
|
||||
return;
|
||||
}
|
||||
|
||||
// Desktop-Arrival Gate: Only allow desktop_arrival when ESP is NOT actively running
|
||||
// WDP v2 has no ESP — skip the gate entirely
|
||||
if (source == "desktop_arrival" && _enrollmentType != "v2" && _espEverSeen && !_espFinalExitSeen)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Desktop arrived but ESP still active — not completing yet");
|
||||
EmitCompletionCheck(source, "blocked", "esp_active");
|
||||
return;
|
||||
}
|
||||
|
||||
_enrollmentCompleteEmitted = true;
|
||||
_stateData.EnrollmentCompleteEmitted = true;
|
||||
|
||||
// Stop summary timer
|
||||
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
|
||||
_summaryTimerActive = false;
|
||||
|
||||
var helloOutcome = _espAndHelloTracker?.HelloOutcome ?? "unknown";
|
||||
|
||||
var signalTimestamps = new Dictionary<string, string>();
|
||||
if (_stateData.EspFirstSeenUtc.HasValue)
|
||||
signalTimestamps["espFirstSeen"] = _stateData.EspFirstSeenUtc.Value.ToString("o");
|
||||
if (_stateData.DesktopArrivedUtc.HasValue)
|
||||
signalTimestamps["desktopArrived"] = _stateData.DesktopArrivedUtc.Value.ToString("o");
|
||||
if (_stateData.EspFinalExitUtc.HasValue)
|
||||
signalTimestamps["espFinalExit"] = _stateData.EspFinalExitUtc.Value.ToString("o");
|
||||
if (_stateData.HelloResolvedUtc.HasValue)
|
||||
signalTimestamps["helloResolved"] = _stateData.HelloResolvedUtc.Value.ToString("o");
|
||||
if (_stateData.ImePatternSeenUtc.HasValue)
|
||||
signalTimestamps["imePatternSeen"] = _stateData.ImePatternSeenUtc.Value.ToString("o");
|
||||
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "enrollment_complete",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "EnrollmentTracker",
|
||||
Phase = EnrollmentPhase.Complete,
|
||||
Message = $"Autopilot enrollment completed successfully (source: {source})",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "completionSource", source },
|
||||
{ "helloOutcome", helloOutcome },
|
||||
{ "signalsSeen", _stateData.SignalsSeen },
|
||||
{ "signalTimestamps", signalTimestamps },
|
||||
{ "agentUptimeSeconds", (DateTime.UtcNow - _agentStartTimeUtc).TotalSeconds }
|
||||
}
|
||||
});
|
||||
|
||||
// Write enrollment complete marker for cleanup retry detection
|
||||
WriteEnrollmentCompleteMarker();
|
||||
|
||||
// Clean up persisted tracker state so next enrollment starts fresh
|
||||
_imeLogTracker?.DeleteState();
|
||||
_statePersistence.Delete();
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Emits a throttled completion_check event for observability.
|
||||
/// Max 1 event per minute per source to avoid flooding.
|
||||
/// </summary>
|
||||
private void EmitCompletionCheck(string source, string result, string reason)
|
||||
{
|
||||
// Throttle: max 1x per minute per source
|
||||
var now = DateTime.UtcNow;
|
||||
if (_lastCompletionCheckBySource.TryGetValue(source, out var lastEmit) && (now - lastEmit).TotalSeconds < 60)
|
||||
return;
|
||||
_lastCompletionCheckBySource[source] = now;
|
||||
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "completion_check",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "EnrollmentTracker",
|
||||
Phase = EnrollmentPhase.Unknown,
|
||||
Message = $"Completion source '{source}' evaluated — {result}",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "source", source },
|
||||
{ "result", result },
|
||||
{ "reason", reason },
|
||||
{ "espEverSeen", _espEverSeen },
|
||||
{ "espFinalExitSeen", _espFinalExitSeen },
|
||||
{ "desktopArrived", _desktopArrived },
|
||||
{ "helloResolved", _espAndHelloTracker?.IsHelloCompleted ?? false },
|
||||
{ "helloPolicyConfigured", _espAndHelloTracker?.IsPolicyConfigured ?? false },
|
||||
{ "enrollmentType", _enrollmentType },
|
||||
{ "lastEspPhase", _lastEspPhase ?? "none" }
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called by MonitoringService when Desktop Arrival is detected (explorer.exe under a real user).
|
||||
/// Corrects phase if needed, starts Hello wait timer in no-ESP scenarios, and attempts completion.
|
||||
/// </summary>
|
||||
public void NotifyDesktopArrived()
|
||||
{
|
||||
if (_desktopArrived)
|
||||
return;
|
||||
|
||||
_desktopArrived = true;
|
||||
_stateData.DesktopArrived = true;
|
||||
_stateData.DesktopArrivedUtc = DateTime.UtcNow;
|
||||
RecordSignal("desktop_arrived");
|
||||
_logger.Info("EnrollmentTracker: Desktop arrival notified");
|
||||
|
||||
// Phase correction: If ESP was seen but AccountSetup was never detected by IME log,
|
||||
// correct the phase and emit an event for the timeline
|
||||
if (_espEverSeen && !string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
var previousPhase = _lastEspPhase ?? "unknown";
|
||||
_lastEspPhase = "AccountSetup";
|
||||
_logger.Info($"EnrollmentTracker: Desktop arrival confirmed AccountSetup phase (was: {previousPhase}) — phase corrected on timeline");
|
||||
|
||||
_emitEvent(new EnrollmentEvent
|
||||
{
|
||||
SessionId = _sessionId,
|
||||
TenantId = _tenantId,
|
||||
EventType = "esp_phase_changed",
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "DesktopArrivalDetector",
|
||||
Phase = EnrollmentPhase.AccountSetup,
|
||||
Message = $"ESP phase: AccountSetup (auto-detected from desktop arrival, was: {previousPhase})",
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
{ "espPhase", "AccountSetup" },
|
||||
{ "autoDetected", true },
|
||||
{ "correctedBy", "desktop_arrival" },
|
||||
{ "previousPhase", previousPhase }
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
// Start Hello wait timer in no-ESP or post-ESP scenarios
|
||||
// Without this, Hello would never timeout-resolve in no-ESP scenarios (WDP v2, ESP disabled)
|
||||
if (_espAndHelloTracker != null && !_espAndHelloTracker.IsHelloCompleted)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Desktop arrived with Hello pending — starting Hello wait timer");
|
||||
_espAndHelloTracker.StartHelloWaitTimer();
|
||||
}
|
||||
|
||||
TryEmitEnrollmentComplete("desktop_arrival");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Called when the device-only ESP timer expires. If no AccountSetup phase started
|
||||
/// and desktop is available, classify as device-only ESP and mark final exit.
|
||||
/// </summary>
|
||||
private void OnDeviceOnlyEspTimerExpired(object state)
|
||||
{
|
||||
// AccountSetup started meanwhile? Timer is obsolete
|
||||
if (string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
_logger.Debug("EnrollmentTracker: Device-only ESP timer expired but AccountSetup detected — ignoring");
|
||||
return;
|
||||
}
|
||||
|
||||
if (_desktopArrived)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: No AccountSetup phase after {DeviceOnlyEspTimerMinutes}min — classified as device-only ESP, desktop is active");
|
||||
_espFinalExitSeen = true;
|
||||
_stateData.EspFinalExitSeen = true;
|
||||
_stateData.EspFinalExitUtc = DateTime.UtcNow;
|
||||
RecordSignal("device_only_esp_final_exit");
|
||||
_espAndHelloTracker?.StartHelloWaitTimer();
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: No AccountSetup phase after {DeviceOnlyEspTimerMinutes}min and no desktop yet — waiting for Desktop Arrival or Lifetime Timer");
|
||||
}
|
||||
}
|
||||
|
||||
private void CollectDeviceInfoAtFinalizingSetup(string triggerReason)
|
||||
{
|
||||
if (_finalDeviceInfoCollected)
|
||||
@@ -720,6 +1103,13 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
{
|
||||
// Only emit if state-breakdown counters changed since last emission (backstop for missed events)
|
||||
EmitAppTrackingSummaryIfChanged();
|
||||
|
||||
// Periodic state save (piggybacks on the existing 30s timer)
|
||||
if (_stateDirty)
|
||||
{
|
||||
_stateDirty = false;
|
||||
_statePersistence.Save(_stateData);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -786,14 +1176,17 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
|
||||
{
|
||||
Stop();
|
||||
|
||||
// Unsubscribe from HelloDetector events
|
||||
// Unsubscribe from EspAndHelloTracker events
|
||||
if (_espAndHelloTracker != null)
|
||||
{
|
||||
_espAndHelloTracker.HelloCompleted -= OnHelloCompleted;
|
||||
_espAndHelloTracker.FinalizingSetupPhaseTriggered -= OnFinalizingSetupPhaseTriggered;
|
||||
_espAndHelloTracker.WhiteGloveCompleted -= OnWhiteGloveCompleted;
|
||||
_espAndHelloTracker.EspFailureDetected -= OnEspFailureDetected;
|
||||
}
|
||||
|
||||
_espFailureTimer?.Dispose();
|
||||
_deviceOnlyEspTimer?.Dispose();
|
||||
_summaryTimer?.Dispose();
|
||||
_imeLogTracker?.Dispose();
|
||||
}
|
||||
|
||||
@@ -23,11 +23,13 @@ namespace AutopilotMonitor.Functions.Functions
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Timer trigger: Runs daily at 2:00 AM UTC
|
||||
/// Timer trigger: Runs every 2 hours
|
||||
/// NCRONTAB format: {second} {minute} {hour} {day} {month} {day-of-week}
|
||||
/// Reduced from daily (2:00 UTC) to every 2 hours to catch stalled sessions faster.
|
||||
/// MarkStalledSessionsAsTimedOutAsync is idempotent (terminal states not overwritten).
|
||||
/// </summary>
|
||||
[Function("DailyMaintenance")]
|
||||
public async Task Run([TimerTrigger("0 0 2 * * *")] object timer)
|
||||
public async Task Run([TimerTrigger("0 0 */2 * * *")] object timer)
|
||||
{
|
||||
_logger.LogInformation("DailyMaintenance timer trigger fired");
|
||||
await _maintenanceService.RunAllAsync();
|
||||
|
||||
@@ -94,7 +94,8 @@ namespace AutopilotMonitor.Functions.Functions
|
||||
EnablePerformanceCollector = tenantConfig.EnablePerformanceCollector,
|
||||
PerformanceIntervalSeconds = tenantConfig.PerformanceCollectorIntervalSeconds,
|
||||
CollectorIdleTimeoutMinutes = adminConfig.CollectorIdleTimeoutMinutes,
|
||||
HelloWaitTimeoutSeconds = tenantConfig.HelloWaitTimeoutSeconds
|
||||
HelloWaitTimeoutSeconds = tenantConfig.HelloWaitTimeoutSeconds,
|
||||
AgentMaxLifetimeMinutes = tenantConfig.AgentMaxLifetimeMinutes ?? 360
|
||||
};
|
||||
|
||||
// Get active gather rules for this tenant (user-defined ad-hoc only)
|
||||
@@ -111,7 +112,7 @@ namespace AutopilotMonitor.Functions.Functions
|
||||
var response = req.CreateResponse(HttpStatusCode.OK);
|
||||
await response.WriteAsJsonAsync(new AgentConfigResponse
|
||||
{
|
||||
ConfigVersion = 12, // collector idle timeout: replaced MaxCollectorDurationHours with activity-aware CollectorIdleTimeoutMinutes
|
||||
ConfigVersion = 13, // session lifecycle: agent max lifetime, esp_failure → enrollment_failed, desktop arrival, multi-signal completion
|
||||
UploadIntervalSeconds = 30,
|
||||
SelfDestructOnComplete = tenantConfig.SelfDestructOnComplete ?? true,
|
||||
KeepLogFile = tenantConfig.KeepLogFile ?? false,
|
||||
|
||||
@@ -412,6 +412,17 @@ namespace AutopilotMonitor.Functions.Functions
|
||||
// Retrieve updated session data to include in SignalR messages
|
||||
var updatedSession = await _storageService.GetSessionAsync(request.TenantId, request.SessionId);
|
||||
|
||||
// Session age warning: log if session >4h old and still InProgress (observability only)
|
||||
if (updatedSession != null && updatedSession.Status == SessionStatus.InProgress)
|
||||
{
|
||||
var sessionAge = DateTime.UtcNow - updatedSession.StartedAt;
|
||||
if (sessionAge.TotalHours > 4)
|
||||
{
|
||||
_logger.LogWarning("Session {SessionId} (tenant {TenantId}) still InProgress after {Hours:F1}h — may be stuck",
|
||||
request.SessionId, request.TenantId, sessionAge.TotalHours);
|
||||
}
|
||||
}
|
||||
|
||||
// Log warning if WhiteGlove status update was not persisted despite retries and fallback.
|
||||
// Events are already stored (idempotent UpsertReplace). Do NOT return 500 here:
|
||||
// the agent retries the same batch containing whiteglove_complete, hitting the same
|
||||
|
||||
@@ -105,6 +105,10 @@ namespace AutopilotMonitor.Shared
|
||||
public const string EspUiState = "esp_ui_state";
|
||||
public const string GatherResult = "gather_result";
|
||||
public const string WhiteGloveComplete = "whiteglove_complete";
|
||||
public const string EnrollmentComplete = "enrollment_complete";
|
||||
public const string EnrollmentFailed = "enrollment_failed";
|
||||
public const string DesktopArrived = "desktop_arrived";
|
||||
public const string CompletionCheck = "completion_check";
|
||||
}
|
||||
|
||||
// -----------------------------------------------------------------------
|
||||
|
||||
@@ -162,6 +162,12 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public int HelloWaitTimeoutSeconds { get; set; } = 30;
|
||||
|
||||
/// <summary>
|
||||
/// Maximum agent lifetime in minutes. Safety net to prevent zombie agents.
|
||||
/// 0 = disabled (no lifetime limit). Default: 360 (6 hours).
|
||||
/// </summary>
|
||||
public int AgentMaxLifetimeMinutes { get; set; } = 360;
|
||||
|
||||
/// <summary>
|
||||
/// Creates default collector configuration
|
||||
/// </summary>
|
||||
|
||||
@@ -166,6 +166,12 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public int? AuthFailureTimeoutMinutes { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Maximum agent lifetime in minutes. Safety net to prevent zombie agents.
|
||||
/// null = use default (360 = 6 hours). 0 = disabled (no lifetime limit).
|
||||
/// </summary>
|
||||
public int? AgentMaxLifetimeMinutes { get; set; }
|
||||
|
||||
// ===== AGENT BEHAVIOR OVERRIDES =====
|
||||
|
||||
/// <summary>
|
||||
|
||||
Reference in New Issue
Block a user