mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
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:
+75
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user