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:
Oliver Kieselbach
2026-04-29 19:00:39 +02:00
parent f14c426a20
commit 57b0557558
4 changed files with 87 additions and 6 deletions
@@ -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 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(
tenantId, sessionId, SessionStatus.Failed,
failureReason: failureReason,
failureSource: failureSource,
completedAt: DateTime.UtcNow);
failureSource: failureSource);
_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
/// recounted here — avoiding an expensive full-partition scan on every status change.
/// </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)
{
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
@@ -1031,8 +1037,10 @@ namespace AutopilotMonitor.Functions.Services
// Set completion time if succeeded or failed
if (status == SessionStatus.Succeeded || status == SessionStatus.Failed)
{
// Use the provided completedAt timestamp (from event) if available, otherwise use current time
var effectiveCompletedAt = EnsureUtc(completedAt ?? DateTime.UtcNow);
var effectiveCompletedAt = EnsureUtc(ResolveCompletionTimestamp(
completedAt,
session.GetDateTimeOffset("LastEventAt")?.UtcDateTime,
DateTime.UtcNow));
update["CompletedAt"] = effectiveCompletedAt;
// 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)
{
var effectiveCompletedAt = EnsureUtc(completedAt ?? DateTime.UtcNow);
var effectiveCompletedAt = EnsureUtc(ResolveCompletionTimestamp(
completedAt,
freshSession.GetDateTimeOffset("LastEventAt")?.UtcDateTime,
DateTime.UtcNow));
forceUpdate["CompletedAt"] = effectiveCompletedAt;
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>
/// Computes the effective duration for dashboard display.
/// For WhiteGlove Part 2 InProgress sessions: Part 1 stored duration + (now - ResumedAt).