mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 20:53:06 +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;
|
int silentMarked = 0;
|
||||||
foreach (var silent in silentSessions)
|
foreach (var silent in silentSessions)
|
||||||
{
|
{
|
||||||
var lastEventAt = silent.LastEventAt ?? silent.StartedAt;
|
// The query is a permissive two-frame pre-filter; the decision is made
|
||||||
var silentMinutes = (int)(now - lastEventAt).TotalMinutes;
|
// 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(
|
await _sessionRepo.UpdateSessionStatusAsync(
|
||||||
silent.TenantId,
|
silent.TenantId,
|
||||||
silent.SessionId,
|
silent.SessionId,
|
||||||
@@ -409,7 +417,7 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
// legitimately exceed SessionTimeoutHours) and must never be terminalized here
|
// legitimately exceed SessionTimeoutHours) and must never be terminalized here
|
||||||
// — without this, an actively-installing 6h enrollment could be classified
|
// — without this, an actively-installing 6h enrollment could be classified
|
||||||
// Incomplete mid-run purely because it outlived the 5h window.
|
// Incomplete mid-run purely because it outlived the 5h window.
|
||||||
if (session.LastEventAt.HasValue && session.LastEventAt.Value > silenceCutoff)
|
if (ServerFrameLastContact(session) > silenceCutoff)
|
||||||
continue;
|
continue;
|
||||||
|
|
||||||
// Fast path: an AwaitingUser session still inside the grace window needs no
|
// 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.
|
/// Aggregates metrics for any missed days in the last 7 days, plus yesterday.
|
||||||
/// Checks the UsageMetrics table for existing snapshots to avoid re-aggregation.
|
/// Checks the UsageMetrics table for existing snapshots to avoid re-aggregation.
|
||||||
/// </summary>
|
/// </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 silenceCutoffStr = silenceCutoff.ToString("yyyy-MM-ddTHH:mm:ss");
|
||||||
var hardCutoffStr = hardCutoff.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}' " +
|
var filter = $"PartitionKey eq '{tenantId}' " +
|
||||||
$"and Status eq 'InProgress' " +
|
$"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')";
|
$"and (StartedAt ge datetime'{hardCutoffStr}Z' or ResumedAt ge datetime'{hardCutoffStr}Z')";
|
||||||
|
|
||||||
var query = tableClient.QueryAsync<TableEntity>(filter: filter);
|
var query = tableClient.QueryAsync<TableEntity>(filter: filter);
|
||||||
@@ -772,7 +782,7 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
var select = new[]
|
var select = new[]
|
||||||
{
|
{
|
||||||
"PartitionKey", "RowKey", "Status", "StartedAt", "ResumedAt", "LastEventAt",
|
"PartitionKey", "RowKey", "Status", "StartedAt", "ResumedAt", "LastEventAt",
|
||||||
"SerialNumber", "IsPreProvisioned"
|
"LastIngestAt", "SerialNumber", "IsPreProvisioned"
|
||||||
};
|
};
|
||||||
|
|
||||||
var sessions = new List<SessionSummary>();
|
var sessions = new List<SessionSummary>();
|
||||||
|
|||||||
@@ -2338,6 +2338,14 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
update["LastEventAt"] = EnsureUtc(latestEventTimestamp.Value);
|
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
|
// Increment script execution counters
|
||||||
if (platformScriptIncrement > 0)
|
if (platformScriptIncrement > 0)
|
||||||
{
|
{
|
||||||
@@ -3147,6 +3155,7 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
// null as "CustomerSas" for back-compat.
|
// null as "CustomerSas" for back-compat.
|
||||||
DiagnosticsBlobDestination = entity.GetString("DiagnosticsBlobDestination"),
|
DiagnosticsBlobDestination = entity.GetString("DiagnosticsBlobDestination"),
|
||||||
LastEventAt = SafeGetDateTime(entity, "LastEventAt"),
|
LastEventAt = SafeGetDateTime(entity, "LastEventAt"),
|
||||||
|
LastIngestAt = SafeGetDateTime(entity, "LastIngestAt"),
|
||||||
IsPreProvisioned = entity.GetBoolean("IsPreProvisioned") ?? false,
|
IsPreProvisioned = entity.GetBoolean("IsPreProvisioned") ?? false,
|
||||||
IsHybridJoin = entity.GetBoolean("IsHybridJoin") ?? false,
|
IsHybridJoin = entity.GetBoolean("IsHybridJoin") ?? false,
|
||||||
IsSelfDeployingProfile = entity.GetBoolean("IsSelfDeployingProfile") ?? false,
|
IsSelfDeployingProfile = entity.GetBoolean("IsSelfDeployingProfile") ?? false,
|
||||||
|
|||||||
@@ -349,6 +349,21 @@ namespace AutopilotMonitor.Shared.Models
|
|||||||
/// </summary>
|
/// </summary>
|
||||||
public DateTime? LastEventAt { get; set; }
|
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>
|
/// <summary>
|
||||||
/// Whether this session used WhiteGlove (Pre-Provisioning).
|
/// Whether this session used WhiteGlove (Pre-Provisioning).
|
||||||
/// Set when a whiteglove_complete event is processed.
|
/// Set when a whiteglove_complete event is processed.
|
||||||
|
|||||||
@@ -264,6 +264,10 @@ export const SHARED_MANIFEST = {
|
|||||||
"name": "lastEventAt",
|
"name": "lastEventAt",
|
||||||
"optional": true
|
"optional": true
|
||||||
},
|
},
|
||||||
|
{
|
||||||
|
"name": "lastIngestAt",
|
||||||
|
"optional": true
|
||||||
|
},
|
||||||
{
|
{
|
||||||
"name": "isPreProvisioned",
|
"name": "isPreProvisioned",
|
||||||
"optional": false
|
"optional": false
|
||||||
|
|||||||
@@ -260,6 +260,10 @@
|
|||||||
"name": "lastEventAt",
|
"name": "lastEventAt",
|
||||||
"optional": true
|
"optional": true
|
||||||
},
|
},
|
||||||
|
{
|
||||||
|
"name": "lastIngestAt",
|
||||||
|
"optional": true
|
||||||
|
},
|
||||||
{
|
{
|
||||||
"name": "isPreProvisioned",
|
"name": "isPreProvisioned",
|
||||||
"optional": false
|
"optional": false
|
||||||
|
|||||||
Reference in New Issue
Block a user