fixed startedAt

fixed bootstrapper ps script
enhanced HelloDetector
This commit is contained in:
Oliver Kieselbach
2026-02-12 21:01:05 +01:00
parent d9ae3e00f6
commit eca8aceead
8 changed files with 353 additions and 47 deletions
@@ -49,7 +49,6 @@ param(
$AgentBasePath = "$env:ProgramData\AutopilotMonitor"
$AgentBinPath = "$AgentBasePath\Agent"
$AgentConfigPath = "$AgentBasePath\Config"
$AgentRulesPath = "$AgentBasePath\Rules"
$AgentSpoolPath = "$AgentBasePath\Spool"
$AgentLogsPath = "$AgentBasePath\Logs"
$TaskName = "AutopilotMonitor-Agent"
@@ -59,7 +58,6 @@ $LogFile = "$AgentLogsPath\Bootstrap.log"
New-Item -Path $AgentBasePath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
New-Item -Path $AgentBinPath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
New-Item -Path $AgentConfigPath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
New-Item -Path $AgentRulesPath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
New-Item -Path $AgentSpoolPath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
New-Item -Path $AgentLogsPath -ItemType Directory -Force -ErrorAction SilentlyContinue | Out-Null
@@ -129,6 +129,14 @@ namespace AutopilotMonitor.Agent.Core.Configuration
/// </summary>
public double SimulationSpeedFactor { get; set; } = 50;
/// <summary>
/// Wait time in seconds after ESP exit before marking Hello as skipped.
/// When ESP exits, we wait this duration for Hello wizard to start (event 62404).
/// Default: 30 seconds (reasonable for systems under load).
/// If Hello wizard starts within this window, we continue waiting for Hello completion (300/301).
/// </summary>
public int HelloWaitTimeoutSeconds { get; set; } = 30;
/// <summary>
/// Validates the configuration
/// </summary>
@@ -12,12 +12,16 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
/// Monitors the "Microsoft-Windows-User Device Registration/Admin" event log channel
/// and checks registry for WHfB policy configuration.
///
/// Key Event IDs:
/// Key Event IDs (User Device Registration/Admin):
/// 358 - Prerequisites passed, provisioning will be launched
/// 360 - Prerequisites failed, provisioning will NOT be launched
/// 360 - Prerequisites failed, provisioning will NOT be launched (SNAPSHOT ONLY - not terminal)
/// 362 - Provisioning blocked
/// 300 - NGC key registered successfully (Hello provisioned)
/// 301 - NGC key registration failed
///
/// Key Event IDs (Microsoft-Windows-Shell-Core/Operational):
/// 62404 - CloudExperienceHost Web App Activity Started (CXID: 'AADHello' or 'NGC' - Hello wizard started)
/// 62407 - CloudExperienceHost Web App Event 2 (CommercialOOBE_ESPProgress_Page_Exiting - ESP exit)
/// </summary>
public class HelloDetector : IDisposable
{
@@ -26,24 +30,38 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
private readonly string _tenantId;
private readonly Action<EnrollmentEvent> _onEventCollected;
private System.Diagnostics.Eventing.Reader.EventLogWatcher _watcher;
private System.Diagnostics.Eventing.Reader.EventLogWatcher _shellCoreWatcher;
private System.Threading.Timer _policyCheckTimer;
private System.Threading.Timer _helloWaitTimer;
private bool _isPolicyConfigured = false;
private bool _isHelloCompleted = false;
private bool _espExitDetected = false;
private bool _helloWizardStarted = false;
private readonly object _stateLock = new object();
private readonly int _helloWaitTimeoutSeconds;
/// <summary>
/// Callback invoked when Hello provisioning completes (successfully, failed, skipped, or blocked)
/// Callback invoked when Hello provisioning completes (successfully or failed)
/// Based on events 300/301 only, NOT on event 360 (which is just a snapshot)
/// </summary>
public event EventHandler HelloCompleted;
/// <summary>
/// Callback invoked when ESP exit or Hello wizard start is detected
/// Triggers transition to FinalizingSetup phase
/// </summary>
public event EventHandler<string> FinalizingSetupPhaseTriggered;
private const string EventLogChannel = "Microsoft-Windows-User Device Registration/Admin";
private const string ShellCoreEventLogChannel = "Microsoft-Windows-Shell-Core/Operational";
// WHfB policy registry paths
private const string CspPolicyBasePath = @"SOFTWARE\Microsoft\Policies\PassportForWork";
private const string GpoPolicyPath = @"SOFTWARE\Policies\Microsoft\PassportForWork";
// Tracked event IDs
// Tracked event IDs (User Device Registration)
private const int EventId_NgcKeyRegistered = 300;
private const int EventId_NgcKeyRegistrationFailed = 301;
private const int EventId_ProvisioningWillLaunch = 358;
@@ -51,6 +69,10 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
private const int EventId_ProvisioningBlocked = 362;
private const int EventId_PinStatus = 376;
// Tracked event IDs (Shell-Core/Operational)
private const int EventId_ShellCore_WebAppStarted = 62404;
private const int EventId_ShellCore_WebAppEvent = 62407;
private static readonly HashSet<int> TrackedEventIds = new HashSet<int>
{
EventId_NgcKeyRegistered,
@@ -61,12 +83,19 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
EventId_PinStatus
};
public HelloDetector(string sessionId, string tenantId, Action<EnrollmentEvent> onEventCollected, AgentLogger logger)
private static readonly HashSet<int> TrackedShellCoreEventIds = new HashSet<int>
{
EventId_ShellCore_WebAppStarted,
EventId_ShellCore_WebAppEvent
};
public HelloDetector(string sessionId, string tenantId, Action<EnrollmentEvent> onEventCollected, AgentLogger logger, int helloWaitTimeoutSeconds = 30)
{
_sessionId = sessionId ?? throw new ArgumentNullException(nameof(sessionId));
_tenantId = tenantId ?? throw new ArgumentNullException(nameof(tenantId));
_onEventCollected = onEventCollected ?? throw new ArgumentNullException(nameof(onEventCollected));
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_helloWaitTimeoutSeconds = helloWaitTimeoutSeconds;
}
/// <summary>
@@ -92,16 +121,19 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
// Check if WHfB policy is configured initially
CheckHelloPolicy();
// Start periodic policy check (every 30 seconds) to detect policy arriving later via MDM
// Start periodic policy check to detect policy arriving later via MDM
_policyCheckTimer = new System.Threading.Timer(
_ => CheckHelloPolicy(),
null,
TimeSpan.FromSeconds(30),
TimeSpan.FromSeconds(30)
TimeSpan.FromSeconds(30), // Initial delay before first check (to allow policies to apply during enrollment)
TimeSpan.FromSeconds(30) // Subsequent checks every 15 seconds
);
// Subscribe to User Device Registration event log
StartEventLogWatcher();
// Subscribe to Shell-Core/Operational event log for ESP exit and Hello wizard detection
StartShellCoreEventLogWatcher();
}
public void Stop()
@@ -122,6 +154,21 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
}
}
// Stop Hello wait timer
if (_helloWaitTimer != null)
{
try
{
_helloWaitTimer.Dispose();
_helloWaitTimer = null;
}
catch (Exception ex)
{
_logger.Error("Error stopping Hello wait timer", ex);
}
}
// Stop User Device Registration watcher
if (_watcher != null)
{
try
@@ -136,6 +183,22 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
_logger.Error("Error stopping Hello detector watcher", ex);
}
}
// Stop Shell-Core/Operational watcher
if (_shellCoreWatcher != null)
{
try
{
_shellCoreWatcher.Enabled = false;
_shellCoreWatcher.EventRecordWritten -= OnShellCoreEventRecordWritten;
_shellCoreWatcher.Dispose();
_shellCoreWatcher = null;
}
catch (Exception ex)
{
_logger.Error("Error stopping Shell-Core event watcher", ex);
}
}
}
private void CheckHelloPolicy()
@@ -333,12 +396,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
case EventId_ProvisioningWillNotLaunch: // 360
eventType = "hello_provisioning_skipped";
severity = EventSeverity.Warning;
message = "Windows Hello for Business provisioning skipped - prerequisites not met";
// Mark Hello as completed (terminal event - skipped counts as completed)
lock (_stateLock) { _isHelloCompleted = true; }
_logger.Info("Windows Hello provisioning COMPLETED (skipped)");
// Trigger HelloCompleted event for EnrollmentTracker
try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch { }
message = "Windows Hello for Business provisioning prerequisites not met (snapshot only, not terminal)";
// DO NOT mark Hello as completed - event 360 is just a snapshot and can change
// DO NOT trigger HelloCompleted event
// Wait for actual terminal events: 300 (success), 301 (failed), or ESP exit + timeout
_logger.Info("Windows Hello provisioning prerequisites not met (snapshot, not terminal)");
break;
case EventId_ProvisioningBlocked: // 362
@@ -370,7 +432,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
EventType = eventType,
Severity = severity,
Source = "HelloDetector",
Phase = EnrollmentPhase.FinalizingSetup,
Phase = EnrollmentPhase.Unknown, // Phase will be determined by EnrollmentTracker based on context
Message = message,
Data = new Dictionary<string, object>
{
@@ -388,6 +450,219 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Collectors
}
}
private void StartShellCoreEventLogWatcher()
{
try
{
// Watch for ESP exit and Hello wizard start events in Shell-Core/Operational log
var query = new EventLogQuery(
ShellCoreEventLogChannel,
PathType.LogName,
"*[System[TimeCreated[timediff(@SystemTime) <= 1000]]]"
);
_shellCoreWatcher = new System.Diagnostics.Eventing.Reader.EventLogWatcher(query);
_shellCoreWatcher.EventRecordWritten += OnShellCoreEventRecordWritten;
_shellCoreWatcher.Enabled = true;
_logger.Info($"Started watching: {ShellCoreEventLogChannel}");
}
catch (EventLogNotFoundException)
{
_logger.Warning($"Event log not found: {ShellCoreEventLogChannel} (normal if not on a real device)");
}
catch (Exception ex)
{
_logger.Error($"Failed to start Shell-Core event log watcher", ex);
}
}
private void OnShellCoreEventRecordWritten(object sender, EventRecordWrittenEventArgs e)
{
if (e.EventRecord == null)
return;
try
{
var record = e.EventRecord;
var eventId = record.Id;
if (!TrackedShellCoreEventIds.Contains(eventId))
return;
var description = record.FormatDescription() ?? $"Event ID {eventId}";
string eventType;
EventSeverity severity = EventSeverity.Info;
string message;
bool triggerFinalizingSetup = false;
string finalizingSetupReason = null;
switch (eventId)
{
case EventId_ShellCore_WebAppStarted: // 62404
// Check if this is AADHello or NGC (Hello wizard started)
if (description.Contains("AADHello") || description.Contains("'NGC'"))
{
eventType = "hello_wizard_started";
message = "Windows Hello wizard started (CloudExperienceHost)";
triggerFinalizingSetup = true;
finalizingSetupReason = "hello_wizard_started";
lock (_stateLock)
{
_helloWizardStarted = true;
// Stop the hello wait timer if running (Hello wizard appeared within timeout)
if (_helloWaitTimer != null)
{
_helloWaitTimer.Dispose();
_helloWaitTimer = null;
_logger.Info($"Hello wizard started within {_helloWaitTimeoutSeconds}s timeout - stopping wait timer");
}
}
_logger.Info("Windows Hello wizard started - detected via Shell-Core event 62404");
}
else
{
// Not Hello-related, ignore
return;
}
break;
case EventId_ShellCore_WebAppEvent: // 62407
// Check if this is ESP exit event
// Use robust pattern: OOBE_ESP*Exit* instead of full string CommercialOOBE_ESPProgress_Page_Exiting
if (System.Text.RegularExpressions.Regex.IsMatch(description, @"OOBE_ESP.*Exit", System.Text.RegularExpressions.RegexOptions.IgnoreCase))
{
eventType = "esp_exiting";
message = "ESP (Enrollment Status Page) is exiting - enrollment nearing completion";
triggerFinalizingSetup = true;
finalizingSetupReason = "esp_exiting";
lock (_stateLock)
{
_espExitDetected = true;
// Start timer to wait for Hello wizard to start
_logger.Info($"ESP exit detected - starting {_helloWaitTimeoutSeconds}s wait timer for Hello wizard");
_helloWaitTimer = new System.Threading.Timer(
OnHelloWaitTimeout,
null,
TimeSpan.FromSeconds(_helloWaitTimeoutSeconds),
TimeSpan.FromMilliseconds(-1) // One-shot timer
);
}
_logger.Info("ESP exit detected - detected via Shell-Core event 62407");
}
else
{
// Not ESP exit, ignore
return;
}
break;
default:
return;
}
_onEventCollected(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
Timestamp = record.TimeCreated ?? DateTime.UtcNow,
EventType = eventType,
Severity = severity,
Source = "HelloDetector",
Phase = EnrollmentPhase.Unknown, // Let EnrollmentTracker decide phase
Message = message,
Data = new Dictionary<string, object>
{
{ "windowsEventId", eventId },
{ "providerName", record.ProviderName ?? "" },
{ "description", description },
{ "eventLogChannel", ShellCoreEventLogChannel }
}
});
_logger.Info($"Shell-Core event detected: {eventType} (EventID {eventId})");
// Trigger FinalizingSetup phase transition
if (triggerFinalizingSetup)
{
try
{
FinalizingSetupPhaseTriggered?.Invoke(this, finalizingSetupReason);
}
catch { }
}
}
catch (Exception ex)
{
_logger.Error("Error processing Shell-Core event record", ex);
}
}
/// <summary>
/// Called when the Hello wait timer expires after ESP exit.
/// If Hello wizard hasn't started by now, we assume it's not configured or was skipped.
/// Mark Hello as completed so enrollment can proceed.
/// </summary>
private void OnHelloWaitTimeout(object state)
{
lock (_stateLock)
{
if (_helloWizardStarted)
{
// Hello wizard already started, this timeout is obsolete
_logger.Debug("Hello wait timeout fired but wizard already started - ignoring");
return;
}
if (_isHelloCompleted)
{
// Hello already completed via events 300/301 - timeout is obsolete
_logger.Debug("Hello wait timeout fired but Hello already completed - ignoring");
return;
}
// Timeout expired without Hello wizard starting
_logger.Info($"Hello wait timeout ({_helloWaitTimeoutSeconds}s) expired without Hello wizard starting");
_logger.Info("Assuming Hello is not configured or was skipped - marking as completed");
_isHelloCompleted = true;
// Emit event for tracking
_onEventCollected(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = "hello_wait_timeout",
Severity = EventSeverity.Info,
Source = "HelloDetector",
Phase = EnrollmentPhase.Unknown,
Message = $"Hello wizard did not start within {_helloWaitTimeoutSeconds}s after ESP exit - assuming not configured",
Data = new Dictionary<string, object>
{
{ "timeoutSeconds", _helloWaitTimeoutSeconds },
{ "espExitDetected", _espExitDetected }
}
});
// Trigger HelloCompleted so enrollment can proceed
try
{
HelloCompleted?.Invoke(this, EventArgs.Empty);
}
catch (Exception ex)
{
_logger.Error("Error invoking HelloCompleted from timeout", ex);
}
}
}
public void Dispose()
{
Stop();
@@ -172,7 +172,8 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Core
_configuration.SessionId,
_configuration.TenantId,
EmitEvent,
_logger
_logger,
_configuration.HelloWaitTimeoutSeconds
);
_helloDetector.Start();
@@ -105,6 +105,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
if (_helloDetector != null)
{
_helloDetector.HelloCompleted += OnHelloCompleted;
_helloDetector.FinalizingSetupPhaseTriggered += OnFinalizingSetupPhaseTriggered;
}
}
@@ -781,33 +782,13 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
// Emit final summary
EmitAppTrackingSummary();
// Note: Phase transition to FinalizingSetup is now handled by Shell-Core events
// (ESP exit or Hello wizard start) for more robust detection.
// We no longer automatically transition here when apps complete.
if (_lastEspPhase != null)
{
_logger.Info($"EnrollmentTracker: All apps completed while in phase '{_lastEspPhase}'");
// When all user apps complete during AccountSetup, transition to FinalizingSetup.
// This signals the progress portal that app installation is done and
// we're now waiting for final ESP steps (e.g. Windows Hello provisioning).
if (string.Equals(_lastEspPhase, "AccountSetup", StringComparison.OrdinalIgnoreCase))
{
_logger.Info("EnrollmentTracker: User apps completed - transitioning to FinalizingSetup phase");
_emitEvent(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = "esp_phase_changed",
Severity = EventSeverity.Info,
Source = "EnrollmentTracker",
Phase = EnrollmentPhase.FinalizingSetup,
Message = "ESP phase: FinalizingSetup (all user apps completed, waiting for final steps)",
Data = new Dictionary<string, object>
{
{ "espPhase", "FinalizingSetup" },
{ "autoDetected", true },
{ "previousPhase", "AccountSetup" }
}
});
}
_logger.Info("EnrollmentTracker: Waiting for ESP exit or Hello wizard events to transition to FinalizingSetup");
}
}
@@ -919,6 +900,33 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
}
}
/// <summary>
/// Called when ESP exit or Hello wizard start is detected (via HelloDetector Shell-Core events)
/// Triggers transition to FinalizingSetup phase
/// </summary>
private void OnFinalizingSetupPhaseTriggered(object sender, string reason)
{
_logger.Info($"EnrollmentTracker: FinalizingSetup phase triggered - reason: {reason}");
// Emit phase change event to FinalizingSetup
_emitEvent(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = "esp_phase_changed",
Severity = EventSeverity.Info,
Source = "EnrollmentTracker",
Phase = EnrollmentPhase.FinalizingSetup,
Message = $"ESP phase: FinalizingSetup (triggered by {reason})",
Data = new Dictionary<string, object>
{
{ "espPhase", "FinalizingSetup" },
{ "autoDetected", true },
{ "triggeredBy", reason }
}
});
}
private void SummaryTimerCallback(object state)
{
if (_imeLogTracker?.PackageStates?.CountAll > 0)
@@ -950,10 +958,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Tracking
{
Stop();
// Unsubscribe from HelloDetector event
// Unsubscribe from HelloDetector events
if (_helloDetector != null)
{
_helloDetector.HelloCompleted -= OnHelloCompleted;
_helloDetector.FinalizingSetupPhaseTriggered -= OnFinalizingSetupPhaseTriggered;
}
_summaryTimer?.Dispose();
@@ -205,7 +205,8 @@ namespace AutopilotMonitor.Functions.Functions
await _storageService.IncrementSessionEventCountAsync(
request.TenantId,
request.SessionId,
processedCount
processedCount,
earliestEventTimestamp
);
}
@@ -434,7 +434,7 @@ namespace AutopilotMonitor.Functions.Services
/// Increments the session event count without touching status or phase fields.
/// Uses Merge mode to safely handle concurrent updates.
/// </summary>
public async Task IncrementSessionEventCountAsync(string tenantId, string sessionId, int increment)
public async Task IncrementSessionEventCountAsync(string tenantId, string sessionId, int increment, DateTime? earliestEventTimestamp = null)
{
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
SecurityValidator.EnsureValidGuid(sessionId, nameof(sessionId));
@@ -454,6 +454,17 @@ namespace AutopilotMonitor.Functions.Services
{
["EventCount"] = currentCount + increment
};
// Update StartedAt if an earlier event timestamp is provided
if (earliestEventTimestamp.HasValue)
{
var currentStartedAt = entity.Value.GetDateTimeOffset("StartedAt")?.UtcDateTime ?? DateTime.MaxValue;
if (earliestEventTimestamp.Value < currentStartedAt)
{
update["StartedAt"] = earliestEventTimestamp.Value;
}
}
await tableClient.UpdateEntityAsync(update, entity.Value.ETag, TableUpdateMode.Merge);
return;
}
@@ -1264,8 +1264,11 @@ function DeviceDetailsCard({ events }: { events: EnrollmentEvent[] }) {
// Extract device detail events
const getEventData = (eventType: string): Record<string, any> | null => {
const evt = events.find(e => e.eventType === eventType);
return evt?.data ?? null;
// Find the NEWEST event of this type (last occurrence) to get the most recent state
const matchingEvents = events.filter(e => e.eventType === eventType);
if (matchingEvents.length === 0) return null;
const latestEvent = matchingEvents[matchingEvents.length - 1];
return latestEvent?.data ?? null;
};
// Helper to check if IP is IPv6