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
2026-03-03 23:12:26 +01:00
parent 4e55b612f2
commit 82919d4791
12 changed files with 1022 additions and 67 deletions
@@ -145,6 +145,13 @@ namespace AutopilotMonitor.Agent.Core.Configuration
/// </summary> /// </summary>
public int AuthFailureTimeoutMinutes { get; set; } = 0; 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> /// <summary>
/// Whether diagnostics upload is configured for this tenant. /// Whether diagnostics upload is configured for this tenant.
/// When true, the agent requests a short-lived upload URL from the backend just before uploading. /// When true, the agent requests a short-lived upload URL from the backend just before uploading.
@@ -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 _espExitDetected = false;
private bool _helloWizardStarted = false; private bool _helloWizardStarted = false;
private bool _whiteGloveDetected = 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 object _stateLock = new object();
private readonly int _helloWaitTimeoutSeconds; private readonly int _helloWaitTimeoutSeconds;
private const int HelloCompletionTimeoutSeconds = 1500; private const int HelloCompletionTimeoutSeconds = 300;
private const int BackfillLookbackMinutes = 5; private const int BackfillLookbackMinutes = 5;
/// <summary> /// <summary>
@@ -66,6 +67,18 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
/// </summary> /// </summary>
public event EventHandler WhiteGloveCompleted; 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 EventLogChannel = "Microsoft-Windows-User Device Registration/Admin";
private const string ShellCoreEventLogChannel = "Microsoft-Windows-Shell-Core/Operational"; private const string ShellCoreEventLogChannel = "Microsoft-Windows-Shell-Core/Operational";
@@ -503,6 +516,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
} }
_isHelloCompleted = true; _isHelloCompleted = true;
HelloOutcome = "completed";
StopHelloCompletionTimerLocked(); StopHelloCompletionTimerLocked();
return true; return true;
} }
@@ -649,10 +663,12 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
|| description.Contains("WhiteGlove_Failed", StringComparison.OrdinalIgnoreCase) || description.Contains("WhiteGlove_Failed", StringComparison.OrdinalIgnoreCase)
|| description.Contains("WhiteGlove_Failure", StringComparison.OrdinalIgnoreCase)) || description.Contains("WhiteGlove_Failure", StringComparison.OrdinalIgnoreCase))
{ {
var failureType = ExtractEspFailureType(description);
eventType = "esp_failure"; eventType = "esp_failure";
severity = EventSeverity.Error; severity = EventSeverity.Error;
message = "ESP (Enrollment Status Page) reported a failure"; message = $"ESP (Enrollment Status Page) reported a failure: {failureType}";
_logger.Warning("ESP failure detected via Shell-Core event 62407"); _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)) 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 { } 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) 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"); _logger.Info("Hello policy not detected as enabled — assuming Hello is not configured or was skipped");
_isHelloCompleted = true; _isHelloCompleted = true;
HelloOutcome = "not_configured";
StopHelloCompletionTimerLocked(); StopHelloCompletionTimerLocked();
// Emit event for tracking // 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"); _logger.Warning($"Hello completion timeout ({HelloCompletionTimeoutSeconds}s) expired after wizard start without terminal event");
_isHelloCompleted = true; _isHelloCompleted = true;
HelloOutcome = _helloWizardStarted ? "timeout" : "wizard_not_started";
StopHelloCompletionTimerLocked(); StopHelloCompletionTimerLocked();
_onEventCollected(new EnrollmentEvent _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() private void BackfillRecentTerminalHelloEvents()
{ {
try try
@@ -65,6 +65,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
private int _collectorIdleTimeoutMinutes = 15; private int _collectorIdleTimeoutMinutes = 15;
private Timer _idleCheckTimer; 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 // Auth failure circuit breaker
private int _consecutiveAuthFailures = 0; private int _consecutiveAuthFailures = 0;
private DateTime? _firstAuthFailureTime = null; private DateTime? _firstAuthFailureTime = null;
@@ -407,6 +415,27 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
); );
_enrollmentTracker.Start(); _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) catch (Exception ex)
{ {
@@ -422,6 +451,16 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
_idleCheckTimer?.Dispose(); _idleCheckTimer?.Dispose();
_idleCheckTimer = null; _idleCheckTimer = null;
_maxLifetimeTimer?.Dispose();
_maxLifetimeTimer = null;
if (_desktopArrivalDetector != null)
{
_desktopArrivalDetector.DesktopArrived -= OnDesktopArrived;
_desktopArrivalDetector.Dispose();
_desktopArrivalDetector = null;
}
_performanceCollector?.Stop(); _performanceCollector?.Stop();
_performanceCollector?.Dispose(); _performanceCollector?.Dispose();
_performanceCollector = null; _performanceCollector = null;
@@ -435,6 +474,67 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
_enrollmentTracker = null; _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> /// <summary>
/// Returns true for events generated by periodic timers (not real enrollment activity) /// Returns true for events generated by periodic timers (not real enrollment activity)
/// </summary> /// </summary>
@@ -878,6 +978,15 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
_sessionPersistence.SaveSequence(evt.Sequence); _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 // Check if this is a phase transition
bool isPhaseTransition = false; bool isPhaseTransition = false;
if (evt.Phase != _lastPhase) if (evt.Phase != _lastPhase)
@@ -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 bool _finalDeviceInfoCollected = false; // Ensure final device info is emitted only once
private string _lastEmittedSummaryHash; // Track last emitted state-breakdown to avoid redundant summary events 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 // Default IME log folder
private const string DefaultImeLogFolder = @"%ProgramData%\Microsoft\IntuneManagementExtension\Logs"; private const string DefaultImeLogFolder = @"%ProgramData%\Microsoft\IntuneManagementExtension\Logs";
@@ -115,8 +143,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
_espAndHelloTracker = espAndHelloTracker; _espAndHelloTracker = espAndHelloTracker;
_deviceInfoCollector = new Collectors.DeviceInfoCollector(sessionId, tenantId, emitEvent, logger); _deviceInfoCollector = new Collectors.DeviceInfoCollector(sessionId, tenantId, emitEvent, logger);
// Create ImeLogTracker with state persistence directory // State persistence for crash recovery
var stateDirectory = @"%ProgramData%\AutopilotMonitor\State"; 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 = new ImeLogTracker(_imeLogFolder, _imeLogPatterns, _logger, matchLogPath: imeMatchLogPath, stateDirectory: stateDirectory);
_imeLogTracker.SimulationMode = simulationMode; _imeLogTracker.SimulationMode = simulationMode;
_imeLogTracker.SpeedFactor = speedFactor; _imeLogTracker.SpeedFactor = speedFactor;
@@ -137,6 +168,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
_espAndHelloTracker.HelloCompleted += OnHelloCompleted; _espAndHelloTracker.HelloCompleted += OnHelloCompleted;
_espAndHelloTracker.FinalizingSetupPhaseTriggered += OnFinalizingSetupPhaseTriggered; _espAndHelloTracker.FinalizingSetupPhaseTriggered += OnFinalizingSetupPhaseTriggered;
_espAndHelloTracker.WhiteGloveCompleted += OnWhiteGloveCompleted; _espAndHelloTracker.WhiteGloveCompleted += OnWhiteGloveCompleted;
_espAndHelloTracker.EspFailureDetected += OnEspFailureDetected;
} }
} }
@@ -147,6 +179,9 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
{ {
_logger.Info("EnrollmentTracker: starting"); _logger.Info("EnrollmentTracker: starting");
// Load persisted state for crash recovery
LoadState();
// Start IME log tracking immediately — this is the critical enrollment watcher. // Start IME log tracking immediately — this is the critical enrollment watcher.
// Device info collection (WMI + registry) runs in the background so it doesn't // Device info collection (WMI + registry) runs in the background so it doesn't
// delay the ImeLogTracker from catching early enrollment events. // delay the ImeLogTracker from catching early enrollment events.
@@ -198,6 +233,8 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
{ {
var result = _deviceInfoCollector.CollectAll(); var result = _deviceInfoCollector.CollectAll();
_enrollmentType = result.enrollmentType; _enrollmentType = result.enrollmentType;
_stateData.EnrollmentType = _enrollmentType;
_stateDirty = true;
} }
/// <summary> /// <summary>
@@ -228,6 +265,26 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
_logger.Info($"EnrollmentTracker: ESP phase changed from '{_lastEspPhase ?? "null"}' to '{phase}'"); _logger.Info($"EnrollmentTracker: ESP phase changed from '{_lastEspPhase ?? "null"}' to '{phase}'");
_lastEspPhase = phase; _lastEspPhase = phase;
_hasAutoSwitchedToAppsPhase = false; // Reset when ESP phase changes _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) // Map ESP phase to EnrollmentPhase (phase change events)
var enrollmentPhase = EnrollmentPhase.DeviceSetup; var enrollmentPhase = EnrollmentPhase.DeviceSetup;
@@ -358,6 +415,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
break; break;
case AppInstallationState.Installing: 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"; eventType = "app_install_started";
break; break;
@@ -496,6 +558,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
private void HandleUserSessionCompleted() private void HandleUserSessionCompleted()
{ {
_logger.Info("EnrollmentTracker: User session completed (detected from IME log)"); _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 // Stop summary timer if running
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite); _summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
@@ -531,70 +598,41 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
// or when the agent is stopped/times out // or when the agent is stopped/times out
return; 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 TryEmitEnrollmentComplete("ime_pattern");
_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();
} }
/// <summary> /// <summary>
/// Called when Windows Hello provisioning completes (via HelloDetector event) /// Called when Windows Hello provisioning completes (via EspAndHelloTracker event).
/// If we were waiting for Hello, now we can mark enrollment as complete /// Multiple completion paths: IME pattern was waiting for Hello, ESP final exit + Hello composite,
/// or Desktop arrival + Hello.
/// </summary> /// </summary>
private void OnHelloCompleted(object sender, EventArgs e) 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) 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; _isWaitingForHello = false;
TryEmitEnrollmentComplete("ime_hello");
// Emit enrollment completed event }
_emitEvent(new EnrollmentEvent else if (_espFinalExitSeen)
{ {
SessionId = _sessionId, _logger.Info("EnrollmentTracker: Hello completed + ESP final exit seen — composite completion");
TenantId = _tenantId, TryEmitEnrollmentComplete("esp_hello_composite");
EventType = "enrollment_complete", }
Severity = EventSeverity.Info, else if (_desktopArrived)
Source = "EnrollmentTracker", {
Phase = EnrollmentPhase.Complete, _logger.Info("EnrollmentTracker: Hello completed + desktop arrived — desktop-hello completion");
Message = "Autopilot enrollment completed successfully (Hello provisioning completed)" TryEmitEnrollmentComplete("desktop_hello");
});
// Write enrollment complete marker for cleanup retry detection
WriteEnrollmentCompleteMarker();
// Clean up persisted tracker state so next enrollment starts fresh
_imeLogTracker?.DeleteState();
} }
else 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. // 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> /// <summary>
/// Called when ESP exit or Hello wizard start is detected (via HelloDetector Shell-Core events) /// Called when ESP exit or Hello wizard start is detected (via HelloDetector Shell-Core events)
/// Triggers transition to FinalizingSetup phase /// 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 ESP exiting, check which phase we're in
if (reason == "esp_exiting") 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 // Final ESP exit: either AccountSetup phase detected OR desktop arrived (backup)
_logger.Info("EnrollmentTracker: AccountSetup phase exiting - enrollment nearing completion, starting Hello wait timer"); 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 // Emit phase change event to FinalizingSetup
_emitEvent(new EnrollmentEvent _emitEvent(new EnrollmentEvent
@@ -653,13 +791,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
Severity = EventSeverity.Info, Severity = EventSeverity.Info,
Source = "EnrollmentTracker", Source = "EnrollmentTracker",
Phase = EnrollmentPhase.FinalizingSetup, 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> Data = new Dictionary<string, object>
{ {
{ "espPhase", "FinalizingSetup" }, { "espPhase", "FinalizingSetup" },
{ "autoDetected", true }, { "autoDetected", true },
{ "triggeredBy", reason }, { "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 else
{ {
// DeviceSetup phase exiting - this is just transition to AccountSetup, not final // DeviceSetup phase exiting without desktop — intermediate transition (Device→Account) or device-only ESP
_logger.Info($"EnrollmentTracker: ESP phase exiting from '{_lastEspPhase ?? "unknown"}' - intermediate transition, not starting Hello wait timer"); _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 // Start device-only ESP detection timer
// The regular esp_phase_changed event will be emitted when we detect AccountSetup phase _deviceOnlyEspTimer?.Dispose();
_deviceOnlyEspTimer = new Timer(
OnDeviceOnlyEspTimerExpired,
null,
TimeSpan.FromMinutes(DeviceOnlyEspTimerMinutes),
TimeSpan.FromMilliseconds(-1));
} }
} }
else if (reason == "hello_wizard_started") 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) private void CollectDeviceInfoAtFinalizingSetup(string triggerReason)
{ {
if (_finalDeviceInfoCollected) 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) // Only emit if state-breakdown counters changed since last emission (backstop for missed events)
EmitAppTrackingSummaryIfChanged(); EmitAppTrackingSummaryIfChanged();
// Periodic state save (piggybacks on the existing 30s timer)
if (_stateDirty)
{
_stateDirty = false;
_statePersistence.Save(_stateData);
}
} }
/// <summary> /// <summary>
@@ -786,14 +1176,17 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
{ {
Stop(); Stop();
// Unsubscribe from HelloDetector events // Unsubscribe from EspAndHelloTracker events
if (_espAndHelloTracker != null) if (_espAndHelloTracker != null)
{ {
_espAndHelloTracker.HelloCompleted -= OnHelloCompleted; _espAndHelloTracker.HelloCompleted -= OnHelloCompleted;
_espAndHelloTracker.FinalizingSetupPhaseTriggered -= OnFinalizingSetupPhaseTriggered; _espAndHelloTracker.FinalizingSetupPhaseTriggered -= OnFinalizingSetupPhaseTriggered;
_espAndHelloTracker.WhiteGloveCompleted -= OnWhiteGloveCompleted; _espAndHelloTracker.WhiteGloveCompleted -= OnWhiteGloveCompleted;
_espAndHelloTracker.EspFailureDetected -= OnEspFailureDetected;
} }
_espFailureTimer?.Dispose();
_deviceOnlyEspTimer?.Dispose();
_summaryTimer?.Dispose(); _summaryTimer?.Dispose();
_imeLogTracker?.Dispose(); _imeLogTracker?.Dispose();
} }
@@ -23,11 +23,13 @@ namespace AutopilotMonitor.Functions.Functions
} }
/// <summary> /// <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} /// 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> /// </summary>
[Function("DailyMaintenance")] [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"); _logger.LogInformation("DailyMaintenance timer trigger fired");
await _maintenanceService.RunAllAsync(); await _maintenanceService.RunAllAsync();
@@ -94,7 +94,8 @@ namespace AutopilotMonitor.Functions.Functions
EnablePerformanceCollector = tenantConfig.EnablePerformanceCollector, EnablePerformanceCollector = tenantConfig.EnablePerformanceCollector,
PerformanceIntervalSeconds = tenantConfig.PerformanceCollectorIntervalSeconds, PerformanceIntervalSeconds = tenantConfig.PerformanceCollectorIntervalSeconds,
CollectorIdleTimeoutMinutes = adminConfig.CollectorIdleTimeoutMinutes, 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) // 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); var response = req.CreateResponse(HttpStatusCode.OK);
await response.WriteAsJsonAsync(new AgentConfigResponse 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, UploadIntervalSeconds = 30,
SelfDestructOnComplete = tenantConfig.SelfDestructOnComplete ?? true, SelfDestructOnComplete = tenantConfig.SelfDestructOnComplete ?? true,
KeepLogFile = tenantConfig.KeepLogFile ?? false, KeepLogFile = tenantConfig.KeepLogFile ?? false,
@@ -412,6 +412,17 @@ namespace AutopilotMonitor.Functions.Functions
// Retrieve updated session data to include in SignalR messages // Retrieve updated session data to include in SignalR messages
var updatedSession = await _storageService.GetSessionAsync(request.TenantId, request.SessionId); 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. // Log warning if WhiteGlove status update was not persisted despite retries and fallback.
// Events are already stored (idempotent UpsertReplace). Do NOT return 500 here: // Events are already stored (idempotent UpsertReplace). Do NOT return 500 here:
// the agent retries the same batch containing whiteglove_complete, hitting the same // 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 EspUiState = "esp_ui_state";
public const string GatherResult = "gather_result"; public const string GatherResult = "gather_result";
public const string WhiteGloveComplete = "whiteglove_complete"; 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> /// </summary>
public int HelloWaitTimeoutSeconds { get; set; } = 30; 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> /// <summary>
/// Creates default collector configuration /// Creates default collector configuration
/// </summary> /// </summary>
@@ -166,6 +166,12 @@ namespace AutopilotMonitor.Shared.Models
/// </summary> /// </summary>
public int? AuthFailureTimeoutMinutes { get; set; } 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 ===== // ===== AGENT BEHAVIOR OVERRIDES =====
/// <summary> /// <summary>