mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 21:19:38 +00:00
fix(backend): anchor admin-marked CompletedAt on LastEventAt, not UtcNow
Admin "Mark as Succeeded/Failed", rule-engine terminal failures, and the maintenance auto-fail path all called UpdateSessionStatusAsync without a completedAt, falling through to DateTime.UtcNow. DurationSeconds was then (click-time − earliestEvent), which on session fe5d7153-… inflated a real ~7min enrollment to 29min on the dashboard list and Avg. Duration card. The session detail page silently masked the bug because it recomputes duration client-side from events. Fix: extract ResolveCompletionTimestamp helper that prefers the caller- supplied value, then falls back to the session's LastEventAt, and only to UtcNow when the session never emitted events. Use the helper at both write sites in TableStorageService.Sessions, and stop passing the bogus DateTime.UtcNow from RuleEngine.TryMarkSessionFailedFromRuleAsync so the fallback can take effect there too. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -1 +1 @@
|
|||||||
456
|
457
|
||||||
|
|||||||
@@ -0,0 +1,56 @@
|
|||||||
|
using AutopilotMonitor.Functions.Services;
|
||||||
|
|
||||||
|
namespace AutopilotMonitor.Functions.Tests;
|
||||||
|
|
||||||
|
/// <summary>
|
||||||
|
/// Regression cover for the duration-inflation bug observed on session
|
||||||
|
/// fe5d7153-1e0c-4ff9-812b-2531ff77bed3 (DurationSeconds=1729 vs. real ~415s).
|
||||||
|
/// Root cause: admin-marked terminals + rule-engine + maintenance auto-fail used
|
||||||
|
/// <c>DateTime.UtcNow</c> as <c>CompletedAt</c> when the agent never sent an
|
||||||
|
/// enrollment_complete event. The dashboard list/avg consumed the inflated stored
|
||||||
|
/// duration; the session detail page silently masked the bug by recomputing from
|
||||||
|
/// events client-side.
|
||||||
|
/// </summary>
|
||||||
|
public class SessionCompletionTimestampTests
|
||||||
|
{
|
||||||
|
private static readonly DateTime LastEvent = new(2026, 4, 29, 10, 59, 30, DateTimeKind.Utc);
|
||||||
|
private static readonly DateTime Now = new(2026, 4, 29, 11, 21, 27, DateTimeKind.Utc);
|
||||||
|
private static readonly DateTime AgentEvt = new(2026, 4, 29, 10, 58, 16, DateTimeKind.Utc);
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public void ResolveCompletionTimestamp_prefers_caller_supplied_completion_event()
|
||||||
|
{
|
||||||
|
// Agent ingest path: CompletionEvent.Timestamp is authoritative — never overridden.
|
||||||
|
var resolved = TableStorageService.ResolveCompletionTimestamp(AgentEvt, LastEvent, Now);
|
||||||
|
Assert.Equal(AgentEvt, resolved);
|
||||||
|
}
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public void ResolveCompletionTimestamp_falls_back_to_LastEventAt_when_completedAt_null()
|
||||||
|
{
|
||||||
|
// Admin "Mark as Succeeded" / rule-engine / maintenance auto-fail paths pass
|
||||||
|
// completedAt: null. Without this fallback, DurationSeconds would inflate to
|
||||||
|
// (button-click − earliestEvent) instead of (lastEvent − earliestEvent).
|
||||||
|
var resolved = TableStorageService.ResolveCompletionTimestamp(null, LastEvent, Now);
|
||||||
|
Assert.Equal(LastEvent, resolved);
|
||||||
|
}
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public void ResolveCompletionTimestamp_falls_back_to_now_when_session_has_no_events()
|
||||||
|
{
|
||||||
|
// Pathological case: terminal flip on a session that never emitted any event.
|
||||||
|
// No better anchor exists, so wall-clock is the sane last-resort.
|
||||||
|
var resolved = TableStorageService.ResolveCompletionTimestamp(null, null, Now);
|
||||||
|
Assert.Equal(Now, resolved);
|
||||||
|
}
|
||||||
|
|
||||||
|
[Fact]
|
||||||
|
public void ResolveCompletionTimestamp_does_not_override_explicit_completedAt_with_lastEvent()
|
||||||
|
{
|
||||||
|
// Even if LastEventAt > completedAt (out-of-order ingest), explicit completedAt
|
||||||
|
// wins. Reordering would silently shift DurationSeconds without a code change.
|
||||||
|
var late = LastEvent.AddMinutes(5);
|
||||||
|
var resolved = TableStorageService.ResolveCompletionTimestamp(AgentEvt, late, Now);
|
||||||
|
Assert.Equal(AgentEvt, resolved);
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -203,11 +203,14 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
var failureSource = $"rule:{rule.RuleId}";
|
var failureSource = $"rule:{rule.RuleId}";
|
||||||
var failureReason = $"Rule: {rule.Title}";
|
var failureReason = $"Rule: {rule.Title}";
|
||||||
|
|
||||||
|
// No completedAt: rule firing is decoupled from real-time session activity
|
||||||
|
// (analysis can run minutes after the last event), so UtcNow would inflate
|
||||||
|
// DurationSeconds. Letting UpdateSessionStatusAsync fall back to LastEventAt
|
||||||
|
// anchors duration on when the session actually went silent.
|
||||||
await _sessionRepo.UpdateSessionStatusAsync(
|
await _sessionRepo.UpdateSessionStatusAsync(
|
||||||
tenantId, sessionId, SessionStatus.Failed,
|
tenantId, sessionId, SessionStatus.Failed,
|
||||||
failureReason: failureReason,
|
failureReason: failureReason,
|
||||||
failureSource: failureSource,
|
failureSource: failureSource);
|
||||||
completedAt: DateTime.UtcNow);
|
|
||||||
|
|
||||||
_logger.LogWarning($"Session {sessionId} marked as failed by rule {rule.RuleId} ('{rule.Title}')");
|
_logger.LogWarning($"Session {sessionId} marked as failed by rule {rule.RuleId} ('{rule.Title}')");
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -950,6 +950,12 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
/// Event count is maintained atomically by IncrementSessionEventCountAsync and is not
|
/// Event count is maintained atomically by IncrementSessionEventCountAsync and is not
|
||||||
/// recounted here — avoiding an expensive full-partition scan on every status change.
|
/// recounted here — avoiding an expensive full-partition scan on every status change.
|
||||||
/// </summary>
|
/// </summary>
|
||||||
|
/// <param name="completedAt">
|
||||||
|
/// Authoritative completion timestamp from the triggering event (e.g. CompletionEvent.Timestamp).
|
||||||
|
/// When null — admin-marked terminals, rule-engine, maintenance auto-fail — the writer falls
|
||||||
|
/// back to the session's LastEventAt and only to UtcNow as a last resort, so DurationSeconds
|
||||||
|
/// reflects when the session went silent rather than when the operator clicked the button.
|
||||||
|
/// </param>
|
||||||
public async Task<bool> UpdateSessionStatusAsync(string tenantId, string sessionId, SessionStatus status, EnrollmentPhase? currentPhase = null, string? failureReason = null, DateTime? completedAt = null, DateTime? earliestEventTimestamp = null, DateTime? latestEventTimestamp = null, bool? isPreProvisioned = null, bool? isUserDriven = null, DateTime? resumedAt = null, DateTime? stalledAt = null, bool clearStalledAt = false, bool clearFailureReason = false, string? failureSource = null, string? adminMarkedAction = null)
|
public async Task<bool> UpdateSessionStatusAsync(string tenantId, string sessionId, SessionStatus status, EnrollmentPhase? currentPhase = null, string? failureReason = null, DateTime? completedAt = null, DateTime? earliestEventTimestamp = null, DateTime? latestEventTimestamp = null, bool? isPreProvisioned = null, bool? isUserDriven = null, DateTime? resumedAt = null, DateTime? stalledAt = null, bool clearStalledAt = false, bool clearFailureReason = false, string? failureSource = null, string? adminMarkedAction = null)
|
||||||
{
|
{
|
||||||
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
||||||
@@ -1031,8 +1037,10 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
// Set completion time if succeeded or failed
|
// Set completion time if succeeded or failed
|
||||||
if (status == SessionStatus.Succeeded || status == SessionStatus.Failed)
|
if (status == SessionStatus.Succeeded || status == SessionStatus.Failed)
|
||||||
{
|
{
|
||||||
// Use the provided completedAt timestamp (from event) if available, otherwise use current time
|
var effectiveCompletedAt = EnsureUtc(ResolveCompletionTimestamp(
|
||||||
var effectiveCompletedAt = EnsureUtc(completedAt ?? DateTime.UtcNow);
|
completedAt,
|
||||||
|
session.GetDateTimeOffset("LastEventAt")?.UtcDateTime,
|
||||||
|
DateTime.UtcNow));
|
||||||
update["CompletedAt"] = effectiveCompletedAt;
|
update["CompletedAt"] = effectiveCompletedAt;
|
||||||
|
|
||||||
// Check if this is a WhiteGlove session with a stored Part 1 duration
|
// Check if this is a WhiteGlove session with a stored Part 1 duration
|
||||||
@@ -1240,7 +1248,10 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
|
|
||||||
if (status == SessionStatus.Succeeded || status == SessionStatus.Failed)
|
if (status == SessionStatus.Succeeded || status == SessionStatus.Failed)
|
||||||
{
|
{
|
||||||
var effectiveCompletedAt = EnsureUtc(completedAt ?? DateTime.UtcNow);
|
var effectiveCompletedAt = EnsureUtc(ResolveCompletionTimestamp(
|
||||||
|
completedAt,
|
||||||
|
freshSession.GetDateTimeOffset("LastEventAt")?.UtcDateTime,
|
||||||
|
DateTime.UtcNow));
|
||||||
forceUpdate["CompletedAt"] = effectiveCompletedAt;
|
forceUpdate["CompletedAt"] = effectiveCompletedAt;
|
||||||
|
|
||||||
var freshIsPreProvisioned = freshSession.GetBoolean("IsPreProvisioned") ?? false;
|
var freshIsPreProvisioned = freshSession.GetBoolean("IsPreProvisioned") ?? false;
|
||||||
@@ -1848,6 +1859,17 @@ namespace AutopilotMonitor.Functions.Services
|
|||||||
};
|
};
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/// <summary>
|
||||||
|
/// Resolves the timestamp recorded as <c>CompletedAt</c> when a session transitions to
|
||||||
|
/// Succeeded/Failed. Caller-supplied <paramref name="completedAt"/> wins (agent CompletionEvent);
|
||||||
|
/// otherwise falls back to the last observed event time so admin-marked terminals,
|
||||||
|
/// rule-engine, and maintenance auto-fail anchor on when the session actually went
|
||||||
|
/// silent rather than on the click/tick time. Caller is responsible for normalizing the
|
||||||
|
/// returned value to UTC kind via <c>EnsureUtc</c> before persisting.
|
||||||
|
/// </summary>
|
||||||
|
internal static DateTime ResolveCompletionTimestamp(DateTime? completedAt, DateTime? lastEventAt, DateTime nowUtc)
|
||||||
|
=> completedAt ?? lastEventAt ?? nowUtc;
|
||||||
|
|
||||||
/// <summary>
|
/// <summary>
|
||||||
/// Computes the effective duration for dashboard display.
|
/// Computes the effective duration for dashboard display.
|
||||||
/// For WhiteGlove Part 2 InProgress sessions: Part 1 stored duration + (now - ResumedAt).
|
/// For WhiteGlove Part 2 InProgress sessions: Part 1 stored duration + (now - ResumedAt).
|
||||||
|
|||||||
Reference in New Issue
Block a user