whiteglove completion logic and orphan events handling

This commit is contained in:
Oliver Kieselbach
2026-04-16 20:06:28 +02:00
parent 7b8a242d44
commit 4b3db3a1cd
12 changed files with 361 additions and 9 deletions
+1
View File
@@ -116,3 +116,4 @@ scripts/Deployment/build_and_upload_release_agent_build.ps1
.dotnet-home/
.vscode/
TODO.txt
tools/orphan-analysis.py
@@ -223,7 +223,18 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Enrollment
_signalCorrelatedWhiteGloveTriggered = true;
}
_logger.Info($"EnrollmentTracker: WhiteGlove pre-provisioning completed (source: {sender?.GetType().Name ?? "unknown"})");
var wgSource = sender?.GetType().Name ?? "unknown";
_logger.Info($"EnrollmentTracker: WhiteGlove pre-provisioning completed (source: {wgSource})");
// Emit decision process before the terminal event
EmitDecisionProcess("whiteglove_complete", wgSource, "pending_part1", new List<string>
{
$"trigger={wgSource}",
(_espAndHelloTracker?.HasSaveWhiteGloveSuccessResult ?? false) ? "registry_confirmed" : "registry_not_confirmed",
(_espAndHelloTracker?.IsWhiteGloveStartDetected ?? false) ? "event509_seen" : "event509_not_seen",
_aadJoinedWithUser ? "user_joined" : "no_user_joined",
_fooUserDetected ? "foouser_detected" : "no_foouser"
});
// Stop summary timer — no more app tracking needed
_summaryTimer?.Change(System.Threading.Timeout.Infinite, System.Threading.Timeout.Infinite);
@@ -548,6 +559,15 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Enrollment
/// </summary>
private void EmitEnrollmentFailed(string failureType, string failureSource)
{
// Emit decision process before the terminal event
EmitDecisionProcess("enrollment_failed", failureSource, failureType, new List<string>
{
$"failure_type={failureType}",
$"failure_source={failureSource}",
_espEverSeen ? $"esp_seen(finalExit={_espFinalExitSeen})" : "esp_not_seen",
_desktopArrived ? "desktop_arrived" : "desktop_not_arrived"
});
// Stop timers
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
_summaryTimerActive = false;
@@ -1096,8 +1116,46 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Enrollment
return;
}
// GUARD 4: WhiteGlove Part 1 redirect.
// If SaveWhiteGloveSuccessResult=succeeded (hard WG signal from ESP registry) but no real
// user has joined yet, this is WG Part 1 — the device is pre-provisioned and waiting for
// a user. Redirect to whiteglove_complete (Pending) instead of enrollment_complete (Succeeded).
// This catches WG Part 1 with SkipUser=False where ShellCore WhiteGlove_Success doesn't fire.
bool wgSuccessResult = _espAndHelloTracker?.HasSaveWhiteGloveSuccessResult ?? false;
if (wgSuccessResult && !_aadJoinedWithUser && !desktopArrived)
{
_logger.Info($"EnrollmentTracker: all guards passed but SaveWhiteGloveSuccessResult=succeeded " +
$"with no user joined and no desktop arrived — redirecting to WhiteGlove Part 1 " +
$"(source={source}, aadJoinedWithUser={_aadJoinedWithUser}, desktopArrived={desktopArrived})");
EmitDecisionProcess("whiteglove_complete", source, "redirected_wg_part1", new List<string>
{
$"original_source={source}",
"save_whiteglove_succeeded=true",
"aad_joined_with_user=false",
"desktop_arrived=false",
"redirect: enrollment_complete -> whiteglove_complete"
});
OnWhiteGloveCompleted(this, EventArgs.Empty);
ShadowProcessTrigger("whiteglove_complete");
return;
}
_logger.Info($"EnrollmentTracker: all guards passed for source '{source}' — emitting enrollment_complete");
// Emit decision process before the terminal event
EmitDecisionProcess("enrollment_complete", source, "succeeded", new List<string>
{
$"source={source}",
helloResolved ? "hello_resolved" : "hello_bypassed",
espEverSeen ? $"esp_seen(finalExit={espFinalExitSeen})" : "esp_not_seen",
desktopArrived ? "desktop_arrived" : "desktop_not_arrived",
isDeviceOnly ? "device_only" : "user_driven",
_isHybridJoin ? "hybrid_join" : "aad_join",
wgSuccessResult ? "wg_registry_succeeded" : "no_wg_registry"
});
// Stop timers
_summaryTimer?.Change(Timeout.Infinite, Timeout.Infinite);
_summaryTimerActive = false;
@@ -1229,6 +1287,95 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Enrollment
});
}
/// <summary>
/// Emits a decision_process_completion event immediately before a terminal event
/// (enrollment_complete, whiteglove_complete, enrollment_failed).
/// Contains the full state machine snapshot, all signal timestamps, and the decision chain
/// that led to the outcome — enabling post-hoc analysis without reconstructing from individual events.
/// </summary>
private void EmitDecisionProcess(string terminalEvent, string source, string outcome,
List<string> decisionChain = null)
{
Dictionary<string, object> data;
lock (_stateLock)
{
// Full state machine snapshot
data = new Dictionary<string, object>
{
// Decision metadata
{ "terminalEvent", terminalEvent },
{ "completionSource", source },
{ "outcome", outcome },
{ "decisionChain", decisionChain ?? new List<string>() },
// Core state variables
{ "enrollmentType", _enrollmentType },
{ "autopilotMode", _autopilotMode?.ToString() ?? "unknown" },
{ "skipUserStatusPage", _skipUserStatusPage?.ToString() ?? "unknown" },
{ "skipDeviceStatusPage", _skipDeviceStatusPage?.ToString() ?? "unknown" },
{ "isHybridJoin", _isHybridJoin },
{ "isSelfDeploying", IsSelfDeploying },
{ "isDeviceOnlyDeployment", IsDeviceOnlyDeployment },
// ESP state
{ "espEverSeen", _espEverSeen },
{ "espFinalExitSeen", _espFinalExitSeen },
{ "lastEspPhase", _lastEspPhase ?? "none" },
// Desktop & Hello state
{ "desktopArrived", _desktopArrived },
{ "helloResolved", _espAndHelloTracker?.IsHelloCompleted ?? false },
{ "helloPolicyConfigured", _espAndHelloTracker?.IsPolicyConfigured ?? false },
{ "helloOutcome", _espAndHelloTracker?.HelloOutcome ?? "unknown" },
// WhiteGlove signals
{ "whiteGloveStartDetected", _espAndHelloTracker?.IsWhiteGloveStartDetected ?? false },
{ "saveWhiteGloveSuccessResult", _espAndHelloTracker?.HasSaveWhiteGloveSuccessResult ?? false },
{ "fooUserDetected", _fooUserDetected },
{ "aadJoinedWithUser", _aadJoinedWithUser },
// Signal audit trail with timestamps
{ "signalsSeen", new List<string>(_stateData.SignalsSeen) },
// Agent context
{ "agentUptimeSeconds", (DateTime.UtcNow - _agentStartTimeUtc).TotalSeconds },
{ "enrollmentCompleteAlreadyEmitted", _enrollmentCompleteEmitted },
{ "whiteGloveAlreadyTriggered", _signalCorrelatedWhiteGloveTriggered }
};
// Signal timestamps
var ts = new Dictionary<string, string>();
if (_stateData.EspFirstSeenUtc.HasValue)
ts["espFirstSeen"] = _stateData.EspFirstSeenUtc.Value.ToString("o");
if (_stateData.DesktopArrivedUtc.HasValue)
ts["desktopArrived"] = _stateData.DesktopArrivedUtc.Value.ToString("o");
if (_stateData.EspFinalExitUtc.HasValue)
ts["espFinalExit"] = _stateData.EspFinalExitUtc.Value.ToString("o");
if (_stateData.HelloResolvedUtc.HasValue)
ts["helloResolved"] = _stateData.HelloResolvedUtc.Value.ToString("o");
if (_stateData.ImePatternSeenUtc.HasValue)
ts["imePatternSeen"] = _stateData.ImePatternSeenUtc.Value.ToString("o");
if (_stateData.DeviceSetupProvisioningCompleteUtc.HasValue)
ts["deviceSetupProvisioningComplete"] = _stateData.DeviceSetupProvisioningCompleteUtc.Value.ToString("o");
data["signalTimestamps"] = ts;
}
_emitEvent(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = "decision_process_completion",
Severity = EventSeverity.Info,
Source = "EnrollmentTracker",
Phase = EnrollmentPhase.Unknown,
Message = $"Decision: {terminalEvent} via {source} — {outcome}",
ImmediateUpload = true,
Data = data
});
_logger.Info($"EnrollmentTracker: decision_process_completion emitted — {terminalEvent} via {source} ({outcome})");
}
/// <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.
@@ -375,8 +375,14 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
() => _enrollmentTerminalEventSeen,
_previousExitType, _lastBootTimeUtc, _agentStartTimeUtc);
// Register session with backend
RegisterSessionAsync().Wait();
// Register session with backend — must succeed before collectors start
var registrationSucceeded = RegisterSessionAsync().GetAwaiter().GetResult();
if (!registrationSucceeded)
{
_logger.Error("=== SESSION REGISTRATION FAILED — collectors will NOT start to prevent orphaned events ===");
return;
}
// Check if admin already terminated this session before we restarted
if (!string.IsNullOrEmpty(_pendingAdminAction))
@@ -1128,7 +1134,11 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
// Session registration
// ──────────────────────────────────────────────────────────────────
private async Task RegisterSessionAsync()
/// <summary>
/// Registers the session with the backend. Returns true on success, false on final failure.
/// On failure, collectors MUST NOT be started to prevent orphaned events.
/// </summary>
private async Task<bool> RegisterSessionAsync()
{
const int maxAttempts = 5;
@@ -1187,7 +1197,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
_logger,
_agentVersion).ConfigureAwait(false);
return;
return true;
}
_logger.Warning($"Session registration failed: {response.Message}");
@@ -1196,7 +1206,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
{
_logger.Error($"Session registration authentication failed: {ex.Message}");
_uploadOrchestrator.HandleAuthFailure(ex.StatusCode);
return;
return false;
}
catch (Exception ex)
{
@@ -1207,7 +1217,7 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
_ = _emergencyReporter.TrySendAsync(
AgentErrorType.RegisterSessionFailed,
ex.Message);
return;
return false;
}
}
@@ -1215,6 +1225,8 @@ namespace AutopilotMonitor.Agent.Core.Monitoring.Runtime
_logger.Info($"Retrying session registration in {delaySeconds}s");
await Task.Delay(delaySeconds * 1000);
}
return false;
}
// ──────────────────────────────────────────────────────────────────
@@ -1 +1 @@
1017
1022
@@ -244,5 +244,10 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
return 0;
}
}
public Task<List<OrphanedEventSession>> GetOrphanedEventSessionsAsync(TimeSpan gracePeriod)
=> _storage.GetOrphanedEventSessionsAsync(gracePeriod);
public Task DeleteEventSessionIndexEntryAsync(string tenantId, string sessionId)
=> _storage.DeleteEventSessionIndexEntryAsync(tenantId, sessionId);
}
}
@@ -652,6 +652,65 @@ namespace AutopilotMonitor.Functions.Services
_logger.LogError(ex, "OpsEvents cleanup failed");
}
}
/// <summary>
/// Detects and cleans up orphaned events — events stored in the Events table
/// whose session no longer exists in the Sessions table.
/// Uses the EventSessionIndex side-table for efficient detection (no full Events scan).
/// Grace period: 24 hours to protect against register+ingest race conditions.
/// </summary>
private async Task CleanupOrphanedEventsAsync()
{
try
{
_logger.LogInformation("Starting orphaned events cleanup...");
var sw = Stopwatch.StartNew();
var orphans = await _maintenanceRepo.GetOrphanedEventSessionsAsync(TimeSpan.FromHours(24));
if (orphans.Count == 0)
{
_logger.LogInformation("No orphaned events found");
return;
}
_logger.LogWarning("Found {Count} orphaned event sessions, cleaning up...", orphans.Count);
int totalEventsDeleted = 0;
int sessionsCleanedUp = 0;
foreach (var orphan in orphans)
{
try
{
var deletedEvents = await _maintenanceRepo.DeleteSessionEventsAsync(orphan.TenantId, orphan.SessionId);
await _maintenanceRepo.DeleteEventSessionIndexEntryAsync(orphan.TenantId, orphan.SessionId);
totalEventsDeleted += deletedEvents;
sessionsCleanedUp++;
_logger.LogInformation(
"Cleaned orphan: TenantId={TenantId}, SessionId={SessionId}, Events={Events}",
orphan.TenantId, orphan.SessionId, deletedEvents);
}
catch (Exception ex)
{
_logger.LogError(ex, "Failed to cleanup orphan: TenantId={TenantId}, SessionId={SessionId}",
orphan.TenantId, orphan.SessionId);
}
}
sw.Stop();
_logger.LogInformation(
"Orphaned events cleanup completed in {Ms}ms: {Sessions} sessions, {Events} events deleted",
sw.ElapsedMilliseconds, sessionsCleanedUp, totalEventsDeleted);
await _opsEventService.RecordOrphanEventsCleanedAsync(sessionsCleanedUp, totalEventsDeleted);
}
catch (Exception ex)
{
_logger.LogError(ex, "Orphaned events cleanup failed");
}
}
}
}
@@ -109,6 +109,7 @@ namespace AutopilotMonitor.Functions.Services
await CleanupOldDataAsync();
await CleanupOldDistressReportsAsync();
await CleanupOldOpsEventsAsync();
await CleanupOrphanedEventsAsync();
await CheckAgentBlobStorageAsync();
await RecomputePlatformStatsAsync();
@@ -60,6 +60,11 @@ namespace AutopilotMonitor.Functions.Services
$"Cleaned up {deletedCount} ops events older than {retentionDays} days",
null, "System.Maintenance", new { deletedCount, retentionDays });
public Task RecordOrphanEventsCleanedAsync(int orphanSessions, int totalEventsDeleted)
=> WriteAsync(OpsEventCategory.Maintenance, "OrphanEventsCleaned", OpsEventSeverity.Warning,
$"Cleaned {totalEventsDeleted} orphaned events across {orphanSessions} sessions",
null, "System.Maintenance", new { orphanSessions, totalEventsDeleted });
// ── Security ───────────────────────────────────────────────────────────
public Task RecordDeviceBlockedAsync(string tenantId, string serialNumber, string reason, string blockedBy)
@@ -624,5 +624,85 @@ namespace AutopilotMonitor.Functions.Services
return true; // Assume empty on error → trigger backfill
}
}
// ===== ORPHAN EVENT DETECTION =====
/// <summary>
/// Scans EventSessionIndex, checks each entry against the Sessions table,
/// and returns entries where no session exists and LastIngestAt is older than the grace period.
/// </summary>
public async Task<List<OrphanedEventSession>> GetOrphanedEventSessionsAsync(TimeSpan gracePeriod)
{
var orphans = new List<OrphanedEventSession>();
var cutoff = DateTime.UtcNow - gracePeriod;
try
{
var indexClient = _tableServiceClient.GetTableClient(Constants.TableNames.EventSessionIndex);
var sessionsClient = _tableServiceClient.GetTableClient(Constants.TableNames.Sessions);
await foreach (var entity in indexClient.QueryAsync<TableEntity>())
{
var tenantId = entity.PartitionKey;
var sessionId = entity.RowKey;
var lastIngestAt = entity.GetDateTimeOffset("LastIngestAt")?.UtcDateTime ?? DateTime.MinValue;
var eventCount = entity.GetInt32("EventCount") ?? 0;
// Grace period: skip recent entries (race condition protection)
if (lastIngestAt > cutoff)
continue;
// Check if session exists
try
{
var session = await sessionsClient.GetEntityIfExistsAsync<TableEntity>(tenantId, sessionId, select: new[] { "PartitionKey" });
if (!session.HasValue)
{
orphans.Add(new OrphanedEventSession
{
TenantId = tenantId,
SessionId = sessionId,
LastIngestAt = lastIngestAt,
EventCount = eventCount
});
}
}
catch (RequestFailedException)
{
// 404 = session doesn't exist → orphan
orphans.Add(new OrphanedEventSession
{
TenantId = tenantId,
SessionId = sessionId,
LastIngestAt = lastIngestAt,
EventCount = eventCount
});
}
}
}
catch (Exception ex)
{
_logger.LogError(ex, "Failed to scan EventSessionIndex for orphans");
}
return orphans;
}
public async Task DeleteEventSessionIndexEntryAsync(string tenantId, string sessionId)
{
try
{
var indexClient = _tableServiceClient.GetTableClient(Constants.TableNames.EventSessionIndex);
await indexClient.DeleteEntityAsync(tenantId, sessionId);
}
catch (RequestFailedException ex) when (ex.Status == 404)
{
// Already deleted, ignore
}
catch (Exception ex)
{
_logger.LogWarning(ex, "Failed to delete EventSessionIndex entry for {TenantId}/{SessionId}", tenantId, sessionId);
}
}
}
}
@@ -586,6 +586,28 @@ namespace AutopilotMonitor.Functions.Services
}
}
// Update EventSessionIndex (side-table for orphan detection)
// Fire-and-forget upsert — one write per ingest call, no read needed
if (storedEvents.Count > 0)
{
try
{
var firstEvent = storedEvents[0];
var indexClient = _tableServiceClient.GetTableClient(Constants.TableNames.EventSessionIndex);
var indexEntity = new TableEntity(firstEvent.TenantId, firstEvent.SessionId)
{
["LastIngestAt"] = DateTimeOffset.UtcNow,
["EventCount"] = storedEvents.Count // Will be overwritten on each upsert (not cumulative — acceptable for orphan detection)
};
await indexClient.UpsertEntityAsync(indexEntity, TableUpdateMode.Merge);
}
catch (Exception ex)
{
// Non-critical — don't fail event ingestion if index update fails
_logger.LogWarning(ex, "Failed to update EventSessionIndex");
}
}
return storedEvents;
}
@@ -333,6 +333,9 @@ namespace AutopilotMonitor.Shared
// IME version history (permanent archive, survives data retention)
public const string ImeVersionHistory = "ImeVersionHistory";
// Lightweight index of sessions that have events (for orphan detection)
public const string EventSessionIndex = "EventSessionIndex";
/// <summary>
/// Returns all table names for initialization
/// </summary>
@@ -373,7 +376,8 @@ namespace AutopilotMonitor.Shared
UserUsageLog,
OpsEvents,
ImeVersionHistory,
RuleStats
RuleStats,
EventSessionIndex
};
}
}
@@ -37,10 +37,26 @@ namespace AutopilotMonitor.Shared.DataAccess
Task<int> CleanupGhostSessionIndexEntriesAsync();
Task<bool> IsSessionIndexEmptyAsync();
// --- Orphan Event Detection ---
/// <summary>
/// Returns EventSessionIndex entries whose session no longer exists in the Sessions table
/// and whose last ingest is older than the grace period.
/// </summary>
Task<List<OrphanedEventSession>> GetOrphanedEventSessionsAsync(TimeSpan gracePeriod);
Task DeleteEventSessionIndexEntryAsync(string tenantId, string sessionId);
// --- Tenant Offboarding ---
Task<Dictionary<string, int>> DeleteAllTenantDataAsync(string tenantId);
}
public class OrphanedEventSession
{
public string TenantId { get; set; } = string.Empty;
public string SessionId { get; set; } = string.Empty;
public DateTime LastIngestAt { get; set; }
public int EventCount { get; set; }
}
public class AuditLogEntry
{
public string Id { get; set; } = string.Empty;