fix(backend): agent-silence sweep must compare clock frames it owns

LastEventAt is the maximum AGENT-supplied event timestamp and therefore lives in
the device clock frame. The silence sweep compared it against a server-derived
cutoff, mixing two frames.

Measured over 11,068 sessions: 26 carry a genuine CMTrace timezone skew on their
IME-derived events, from -17 h to +1 h (a further 27 carry plain device-clock
offsets). At -17 h a live agent looks silent the moment it starts and is marked
Stalled with a customer-visible "Agent silent for 1020min"; at +1 h the sweep is
blind for an hour.

Adds SessionSummary.LastIngestAt, stamped from the server clock in
IncrementSessionEventCountAsync — reaching that method IS contact from the agent,
so it is written unconditionally rather than gated on latestEventTimestamp.

The sweep's server-side filter now spans both frames (LastIngestAt lt X or
LastEventAt lt X): filtering on LastIngestAt alone would silently drop every row
written before the field existed, because Table Storage does not match a filter
against a missing property. The authoritative decision moves into
ServerFrameLastContact() (LastIngestAt ?? LastEventAt ?? StartedAt) and is applied
in both stages — before the Stalled marker and in the stage-2 alive guard.

Deliberately not mirrored into SessionsIndex: the sweep reads Sessions, and the
index manifest is pinned bidirectionally by tests.

shared-manifests.json + .generated.ts regenerated — SharedManifestParityTests is
the drift brake and correctly went red on the new field.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-08-20 13:12:49 +02:00
parent 5f00124a86
commit bbc7a1d8b2
7 changed files with 151 additions and 5 deletions
@@ -0,0 +1,75 @@
using System;
using AutopilotMonitor.Functions.Services;
using AutopilotMonitor.Shared.Models;
using Xunit;
namespace AutopilotMonitor.Functions.Tests
{
/// <summary>
/// Pins the clock-frame contract of the agent-silence sweep.
///
/// <para>
/// <c>LastEventAt</c> 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. <c>LastIngestAt</c> is stamped from the server clock on every ingest
/// and is the only value such a comparison may use.
/// </para>
/// </summary>
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));
}
}
}
@@ -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.
/// </summary>
/// <summary>
/// Last contact with the agent, expressed in the SERVER clock frame — the only value a
/// server-derived cutoff may legitimately be compared against.
/// <para>
/// Preference order:
/// <list type="number">
/// <item><c>LastIngestAt</c> — stamped from the server clock on every ingest. Authoritative.</item>
/// <item><c>LastEventAt</c> — device frame; used only for rows written before
/// <c>LastIngestAt</c> existed, so the rollout has no blind window. Carries the device's
/// clock error and any CMTrace timezone skew.</item>
/// <item><c>StartedAt</c> — last resort when a session has no event stamp at all.</item>
/// </list>
/// </para>
/// 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.
/// </summary>
/// <remarks>internal (not private) purely as a unit-test seam — it is a pure function
/// over its argument, pinned by <c>MaintenanceServerFrameLastContactTests</c>.</remarks>
internal static DateTime ServerFrameLastContact(SessionSummary session)
=> session.LastIngestAt ?? session.LastEventAt ?? session.StartedAt;
}
}
@@ -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<TableEntity>(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<SessionSummary>();
@@ -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,
@@ -349,6 +349,21 @@ namespace AutopilotMonitor.Shared.Models
/// </summary>
public DateTime? LastEventAt { get; set; }
/// <summary>
/// SERVER-side time of the most recent event ingest for this session.
/// <para>
/// <see cref="LastEventAt"/> 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.
/// </para>
/// Null for sessions that predate this field — callers MUST fall back to
/// <see cref="LastEventAt"/> so rollout has no blind window.
/// </summary>
public DateTime? LastIngestAt { get; set; }
/// <summary>
/// Whether this session used WhiteGlove (Pre-Provisioning).
/// Set when a whiteglove_complete event is processed.
@@ -264,6 +264,10 @@ export const SHARED_MANIFEST = {
"name": "lastEventAt",
"optional": true
},
{
"name": "lastIngestAt",
"optional": true
},
{
"name": "isPreProvisioned",
"optional": false
@@ -260,6 +260,10 @@
"name": "lastEventAt",
"optional": true
},
{
"name": "lastIngestAt",
"optional": true
},
{
"name": "isPreProvisioned",
"optional": false