diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/MaintenanceServerFrameLastContactTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/MaintenanceServerFrameLastContactTests.cs new file mode 100644 index 00000000..78a51e33 --- /dev/null +++ b/src/Backend/AutopilotMonitor.Functions.Tests/MaintenanceServerFrameLastContactTests.cs @@ -0,0 +1,75 @@ +using System; +using AutopilotMonitor.Functions.Services; +using AutopilotMonitor.Shared.Models; +using Xunit; + +namespace AutopilotMonitor.Functions.Tests +{ + /// + /// Pins the clock-frame contract of the agent-silence sweep. + /// + /// + /// LastEventAt is the maximum AGENT-supplied event timestamp and therefore lives in the + /// device clock frame — it carries the device's clock error and, for CMTrace-derived events, + /// the writing process's timezone belief. Field measurement over 11k sessions found skews from + /// -17 h to +1 h. Comparing that against a server-derived silence cutoff marked live agents + /// Stalled ("Agent silent for 1020min") and left genuinely silent ones undetected for the + /// duration of the skew. LastIngestAt is stamped from the server clock on every ingest + /// and is the only value such a comparison may use. + /// + /// + public class MaintenanceServerFrameLastContactTests + { + private static readonly DateTime Now = new(2026, 08, 20, 12, 00, 00, DateTimeKind.Utc); + + private static SessionSummary Session(DateTime? lastIngestAt, DateTime? lastEventAt, DateTime startedAt) + => new() { LastIngestAt = lastIngestAt, LastEventAt = lastEventAt, StartedAt = startedAt }; + + [Fact] + public void PrefersServerFrameIngestStamp_OverDeviceFrameEventStamp() + { + var s = Session(lastIngestAt: Now.AddMinutes(-1), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-2)); + Assert.Equal(Now.AddMinutes(-1), MaintenanceService.ServerFrameLastContact(s)); + } + + [Fact] + public void NegativeSkew_DoesNotLookSilent_WhenIngestIsFresh() + { + // The exact field shape: IME-derived events landed 17 h in the past, so LastEventAt is + // far behind the 2 h silence cutoff while the agent is demonstrably still reporting. + var silenceCutoff = Now.AddHours(-2); + var s = Session(lastIngestAt: Now.AddSeconds(-30), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-1)); + + Assert.True(MaintenanceService.ServerFrameLastContact(s) > silenceCutoff, + "a session whose ingest stamp is 30 s old must never be classified as agent-silent"); + } + + [Fact] + public void PositiveSkew_DoesNotMaskSilence_WhenIngestIsStale() + { + // Mirror case: a +1 h skew pushes LastEventAt into the future, which previously made the + // sweep blind for an hour. The server frame still sees the silence. + var silenceCutoff = Now.AddHours(-2); + var s = Session(lastIngestAt: Now.AddHours(-3), lastEventAt: Now.AddHours(1), startedAt: Now.AddHours(-4)); + + Assert.True(MaintenanceService.ServerFrameLastContact(s) < silenceCutoff, + "a session with no ingest for 3 h must be detected as silent regardless of a future-dated event stamp"); + } + + [Fact] + public void FallsBackToEventStamp_OnRowsPredatingTheIngestStamp() + { + // Rollout safety: rows written before LastIngestAt existed must keep the old behaviour + // rather than dropping out of the sweep entirely. + var s = Session(lastIngestAt: null, lastEventAt: Now.AddHours(-3), startedAt: Now.AddHours(-5)); + Assert.Equal(Now.AddHours(-3), MaintenanceService.ServerFrameLastContact(s)); + } + + [Fact] + public void FallsBackToStartedAt_WhenNoEventStampExists() + { + var s = Session(lastIngestAt: null, lastEventAt: null, startedAt: Now.AddHours(-4)); + Assert.Equal(Now.AddHours(-4), MaintenanceService.ServerFrameLastContact(s)); + } + } +} diff --git a/src/Backend/AutopilotMonitor.Functions/Services/MaintenanceService.cs b/src/Backend/AutopilotMonitor.Functions/Services/MaintenanceService.cs index 1d52e83a..23aefab1 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/MaintenanceService.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/MaintenanceService.cs @@ -351,8 +351,16 @@ namespace AutopilotMonitor.Functions.Services int silentMarked = 0; foreach (var silent in silentSessions) { - var lastEventAt = silent.LastEventAt ?? silent.StartedAt; - var silentMinutes = (int)(now - lastEventAt).TotalMinutes; + // The query is a permissive two-frame pre-filter; the decision is made + // here on the SERVER frame. LastEventAt carries the device clock and, + // for IME-derived events, a timezone skew (field-measured: -17 h to + // +1 h). Trusting it marks a live agent Stalled — and puts a bogus + // "silent for 1020min" in front of the customer. + var lastContactAt = ServerFrameLastContact(silent); + if (lastContactAt > silenceCutoff) + continue; // provably alive on the server clock + + var silentMinutes = (int)(now - lastContactAt).TotalMinutes; await _sessionRepo.UpdateSessionStatusAsync( silent.TenantId, silent.SessionId, @@ -409,7 +417,7 @@ namespace AutopilotMonitor.Functions.Services // legitimately exceed SessionTimeoutHours) and must never be terminalized here // — without this, an actively-installing 6h enrollment could be classified // Incomplete mid-run purely because it outlived the 5h window. - if (session.LastEventAt.HasValue && session.LastEventAt.Value > silenceCutoff) + if (ServerFrameLastContact(session) > silenceCutoff) continue; // Fast path: an AwaitingUser session still inside the grace window needs no @@ -774,5 +782,26 @@ namespace AutopilotMonitor.Functions.Services /// Aggregates metrics for any missed days in the last 7 days, plus yesterday. /// Checks the UsageMetrics table for existing snapshots to avoid re-aggregation. /// + + /// + /// Last contact with the agent, expressed in the SERVER clock frame — the only value a + /// server-derived cutoff may legitimately be compared against. + /// + /// Preference order: + /// + /// LastIngestAt — stamped from the server clock on every ingest. Authoritative. + /// LastEventAt — device frame; used only for rows written before + /// LastIngestAt existed, so the rollout has no blind window. Carries the device's + /// clock error and any CMTrace timezone skew. + /// StartedAt — last resort when a session has no event stamp at all. + /// + /// + /// Mixing the two frames is what let a live agent be marked Stalled: a session whose + /// IME-derived events were skewed -17 h looked silent for 17 hours the moment it started. + /// + /// internal (not private) purely as a unit-test seam — it is a pure function + /// over its argument, pinned by MaintenanceServerFrameLastContactTests. + internal static DateTime ServerFrameLastContact(SessionSummary session) + => session.LastIngestAt ?? session.LastEventAt ?? session.StartedAt; } } diff --git a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Maintenance.cs b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Maintenance.cs index 5217deaf..0a564cd9 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Maintenance.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Maintenance.cs @@ -698,9 +698,19 @@ namespace AutopilotMonitor.Functions.Services var silenceCutoffStr = silenceCutoff.ToString("yyyy-MM-ddTHH:mm:ss"); var hardCutoffStr = hardCutoff.ToString("yyyy-MM-ddTHH:mm:ss"); + + // Candidate pre-filter across BOTH clock frames, deliberately permissive: + // LastIngestAt is the server frame (authoritative, but absent on rows written + // before it existed), LastEventAt the device frame (always present, but carries + // the device's clock error and any CMTrace timezone skew). An OR keeps a session + // in the candidate set when EITHER frame looks silent; the caller then makes the + // authoritative call on the server frame. Filtering on LastIngestAt alone would + // silently drop every pre-rollout row, since Table Storage does not match a + // filter against a missing property. var filter = $"PartitionKey eq '{tenantId}' " + $"and Status eq 'InProgress' " + - $"and LastEventAt lt datetime'{silenceCutoffStr}Z' " + + $"and (LastIngestAt lt datetime'{silenceCutoffStr}Z' " + + $"or LastEventAt lt datetime'{silenceCutoffStr}Z') " + $"and (StartedAt ge datetime'{hardCutoffStr}Z' or ResumedAt ge datetime'{hardCutoffStr}Z')"; var query = tableClient.QueryAsync(filter: filter); @@ -772,7 +782,7 @@ namespace AutopilotMonitor.Functions.Services var select = new[] { "PartitionKey", "RowKey", "Status", "StartedAt", "ResumedAt", "LastEventAt", - "SerialNumber", "IsPreProvisioned" + "LastIngestAt", "SerialNumber", "IsPreProvisioned" }; var sessions = new List(); diff --git a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Sessions.cs b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Sessions.cs index 7159c16e..284e3ebf 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Sessions.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.Sessions.cs @@ -2338,6 +2338,14 @@ namespace AutopilotMonitor.Functions.Services update["LastEventAt"] = EnsureUtc(latestEventTimestamp.Value); } + // Server-frame ingest stamp. Reaching this method means a batch was just + // received, so "now" on the SERVER clock is the honest answer to "when did we + // last hear from this agent". LastEventAt above cannot answer that — it carries + // the device's clock frame and its timezone skew. Written unconditionally (not + // guarded by latestEventTimestamp) because an empty-timestamp batch is still + // contact from the agent. + update["LastIngestAt"] = EnsureUtc(DateTime.UtcNow); + // Increment script execution counters if (platformScriptIncrement > 0) { @@ -3147,6 +3155,7 @@ namespace AutopilotMonitor.Functions.Services // null as "CustomerSas" for back-compat. DiagnosticsBlobDestination = entity.GetString("DiagnosticsBlobDestination"), LastEventAt = SafeGetDateTime(entity, "LastEventAt"), + LastIngestAt = SafeGetDateTime(entity, "LastIngestAt"), IsPreProvisioned = entity.GetBoolean("IsPreProvisioned") ?? false, IsHybridJoin = entity.GetBoolean("IsHybridJoin") ?? false, IsSelfDeployingProfile = entity.GetBoolean("IsSelfDeployingProfile") ?? false, diff --git a/src/Shared/AutopilotMonitor.Shared/Models/SessionApiModels.cs b/src/Shared/AutopilotMonitor.Shared/Models/SessionApiModels.cs index ea39b92f..ec2b0b3b 100644 --- a/src/Shared/AutopilotMonitor.Shared/Models/SessionApiModels.cs +++ b/src/Shared/AutopilotMonitor.Shared/Models/SessionApiModels.cs @@ -349,6 +349,21 @@ namespace AutopilotMonitor.Shared.Models /// public DateTime? LastEventAt { get; set; } + /// + /// SERVER-side time of the most recent event ingest for this session. + /// + /// lives in the DEVICE clock frame (it is the maximum + /// agent-supplied event timestamp). Comparing it against a server-derived cutoff mixes + /// two clock frames: a device whose clock runs slow — or one whose IME-derived events + /// carry a timezone skew — is judged silent far too early or not at all (measured in the + /// field: skews from -17 h to +1 h, see tasks/todo.md). This field is stamped from the + /// server clock on every ingest, so silence detection can compare like with like. + /// + /// Null for sessions that predate this field — callers MUST fall back to + /// so rollout has no blind window. + /// + public DateTime? LastIngestAt { get; set; } + /// /// Whether this session used WhiteGlove (Pre-Provisioning). /// Set when a whiteglove_complete event is processed. diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts index aaf294fd..1f09d5bd 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts @@ -264,6 +264,10 @@ export const SHARED_MANIFEST = { "name": "lastEventAt", "optional": true }, + { + "name": "lastIngestAt", + "optional": true + }, { "name": "isPreProvisioned", "optional": false diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.json b/src/Web/autopilot-monitor-web/utils/shared-manifests.json index eaa6cd15..0ab339aa 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.json +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.json @@ -260,6 +260,10 @@ "name": "lastEventAt", "optional": true }, + { + "name": "lastIngestAt", + "optional": true + }, { "name": "isPreProvisioned", "optional": false