From 14b185db352f9a95ff50d809fcccd39bd7d58a46 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 10 Sep 2026 01:05:16 +0200 Subject: [PATCH] fix(agent,engine,web): a deadline decision is stamped with the firing clock, never the due time (D-238) A HelloSafety deadline due during Modern Standby fired after wake but was stamped with its due time, so enrollment_complete and CompletedAt landed inside the sleep window: the Network Timeline drew "Completed" in the middle of the Asleep block and three views named three different standby durations. - OnDeadlineFired posts OccurredAtUtc = FiredAtUtc and carries the due time under SignalPayloadKeys.DeadlineDueAtUtc; the stale-fire guards (RealmJoin re-arm, SelfDeploying guard C) identify the incarnation via DecisionEngine.DeadlineDueAtUtc, which falls back to the signal time for pre-key signal logs. - SignalSerializer renders Date-tokenized payload strings as ISO-8601 round-trip text instead of the culture-formatted JValue.ToString() (a replayed deadlineDueAtUtc came back as "4/20/2026 9:55:00 AM"). - Web: the Session Info standby note is clipped to the same window as the duration next to it (lib/standby.ts) and printed with seconds, matching the attribution chip. Tests: DeadlineFireTimeStampTests (late HelloSafety fire, guard C, RealmJoin re-arm, helper fallback), SerializationTests date-like payload round-trip, EnrollmentOrchestratorTests late fire, lib/__tests__/standby.test.ts. Co-Authored-By: Claude Fable 5.1 --- internal | 2 +- .../EnrollmentOrchestratorTests.cs | 36 ++++ .../Orchestration/DeadlineFiredEventArgs.cs | 9 +- .../Orchestration/EnrollmentOrchestrator.cs | 12 +- .../DeadlineFireTimeStampTests.cs | 192 ++++++++++++++++++ .../SerializationTests.cs | 31 +++ .../Engine/DeadlineNames.cs | 9 + .../Engine/DecisionEngine.RealmJoin.cs | 7 +- .../Engine/DecisionEngine.SelfDeploying.cs | 9 +- .../Engine/DecisionEngine.Shared.cs | 21 ++ .../Engine/DecisionEngine.WhiteGlove.cs | 8 +- .../Serialization/SignalSerializer.cs | 22 +- .../sessions/components/SessionInfoCard.tsx | 13 +- .../sessions/hooks/useSessionDerivedData.ts | 38 ++-- .../lib/__tests__/standby.test.ts | 61 ++++++ src/Web/autopilot-monitor-web/lib/standby.ts | 41 ++++ 16 files changed, 459 insertions(+), 52 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.DecisionCore.Tests/DeadlineFireTimeStampTests.cs create mode 100644 src/Web/autopilot-monitor-web/lib/__tests__/standby.test.ts create mode 100644 src/Web/autopilot-monitor-web/lib/standby.ts diff --git a/internal b/internal index 2f4d12b8..aecb8467 160000 --- a/internal +++ b/internal @@ -1 +1 @@ -Subproject commit 2f4d12b8df1192f1d5ba40b416086818c77f6e79 +Subproject commit aecb8467c4c99a3526ed83a3dda237a04fdc9073 diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EnrollmentOrchestratorTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EnrollmentOrchestratorTests.cs index 396e4573..14822ce3 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EnrollmentOrchestratorTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/EnrollmentOrchestratorTests.cs @@ -265,6 +265,42 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration sut.Stop(); } + [Fact] + public void Deadline_fired_late_is_stamped_with_the_firing_clock_and_carries_its_due_time() + { + // A deadline that was due while the device slept (or the agent was down) fires only + // afterwards. The signal must carry the firing clock as OccurredAtUtc — that time + // stamps every effect of the step, and a due time inside the outage would place the + // verdict there — while the due time travels in the payload for the stale-fire guards. + using var rig = new EnrollmentOrchestratorRig(At); + var sut = rig.Build(); + sut.Start(); + + var dueAt = At.AddMinutes(-5); + var scheduler = GetScheduler(sut); + scheduler.Schedule(new ActiveDeadline( + name: "hello_safety", + dueAtUtc: dueAt, + firesSignalKind: DecisionSignalKind.DeadlineFired, + firesPayload: new Dictionary { [SignalPayloadKeys.Deadline] = "hello_safety" })); + + var signalLog = GetSignalLog(sut); + Assert.True(SpinWait.SpinUntil(() => ContainsDeadlineFired(signalLog), 3000)); + + DecisionSignal? fired = null; + foreach (var sig in signalLog.ReadAll()) + { + if (sig.Kind == DecisionSignalKind.DeadlineFired) { fired = sig; break; } + } + Assert.NotNull(fired); + Assert.Equal(At, fired!.OccurredAtUtc); + Assert.NotNull(fired.Payload); + Assert.Equal("hello_safety", fired.Payload![SignalPayloadKeys.Deadline]); + Assert.Equal(dueAt.ToString("O"), fired.Payload[SignalPayloadKeys.DeadlineDueAtUtc]); + + sut.Stop(); + } + // ========================================================================= Quarantine [Fact] diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DeadlineFiredEventArgs.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DeadlineFiredEventArgs.cs index a4e24dfe..0033a8ce 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DeadlineFiredEventArgs.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DeadlineFiredEventArgs.cs @@ -9,9 +9,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration /// /// The orchestrator consumes this event and translates it into a synthetic /// DeadlineFired- - /// whose OccurredAtUtc equals the deadline's , - /// not the wall-clock firing time — so replay stays deterministic even if the agent - /// restarts long after the deadline has passed. + /// whose OccurredAtUtc is — the moment the agent actually + /// decided — and whose payload carries the deadline's . + /// A timer that was due during Modern Standby or a reboot fires only afterwards; stamping + /// the due time instead would date the verdict into the outage. /// /// public sealed class DeadlineFiredEventArgs : EventArgs @@ -24,7 +25,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration public ActiveDeadline Deadline { get; } - /// Wall-clock time the event was raised. For observability; does NOT influence the signal's OccurredAtUtc. + /// Wall-clock time the timer fired; becomes the signal's OccurredAtUtc. public DateTime FiredAtUtc { get; } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs index a62bb572..b2d4a618 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs @@ -1,6 +1,7 @@ #nullable enable using System; using System.Collections.Generic; +using System.Globalization; using System.IO; using System.Threading; using System.Threading.Tasks; @@ -1159,7 +1160,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration var evidence = new Evidence( kind: EvidenceKind.Synthetic, identifier: e.Deadline.Name, - summary: $"deadline '{e.Deadline.Name}' fired at {e.Deadline.DueAtUtc:O}"); + summary: $"deadline '{e.Deadline.Name}' due {e.Deadline.DueAtUtc:O} fired at {e.FiredAtUtc:O}"); // The reducer reads the deadline name under SignalPayloadKeys.Deadline // (see HandleDeadlineFiredV1 in DecisionEngine.Shared). Forward the @@ -1180,10 +1181,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration payload[SignalPayloadKeys.Deadline] = e.Deadline.Name; } - // OccurredAtUtc = DueAtUtc (not firedAt) — replay-determinism per DeadlineFiredEventArgs doc. + // OccurredAtUtc = the firing clock, never DueAtUtc: every effect of the resulting + // step (phase_transition, enrollment_complete) is stamped with the signal time, and a + // due time that passed during Modern Standby or a reboot would place the verdict + // inside the outage. The due time travels in the payload for the stale-fire guards. + payload[SignalPayloadKeys.DeadlineDueAtUtc] = e.Deadline.DueAtUtc.ToString("O", CultureInfo.InvariantCulture); + _ingress.Post( kind: DecisionSignalKind.DeadlineFired, - occurredAtUtc: e.Deadline.DueAtUtc, + occurredAtUtc: e.FiredAtUtc, sourceOrigin: "DeadlineScheduler", evidence: evidence, payload: payload); diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/DeadlineFireTimeStampTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/DeadlineFireTimeStampTests.cs new file mode 100644 index 00000000..2c3729e5 --- /dev/null +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/DeadlineFireTimeStampTests.cs @@ -0,0 +1,192 @@ +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using AutopilotMonitor.DecisionCore.State; +using Xunit; + +namespace AutopilotMonitor.DecisionCore.Tests +{ + /// + /// A DeadlineFired signal is stamped with the wall-clock firing time, not the due + /// time: a deadline due during Modern Standby or a reboot fires only afterwards, and every + /// effect of the resulting step (phase_transition, enrollment_complete) inherits the signal + /// time — a due-time stamp would date the verdict into the outage (session ac5660b8, + /// "Completed" drawn inside the Asleep block). The due time travels in the payload under + /// for the stale-fire guards that identify + /// the deadline incarnation; without the key they fall back to the signal time (pre-key + /// signal logs, where the two were equal by contract). + /// + public sealed class DeadlineFireTimeStampTests + { + private static readonly DateTime T0 = new DateTime(2026, 9, 9, 6, 31, 0, DateTimeKind.Utc); + + private static DecisionSignal MakeSignal( + long ordinal, + DecisionSignalKind kind, + DateTime occurredAtUtc, + IReadOnlyDictionary? payload = null) => + new DecisionSignal( + sessionSignalOrdinal: ordinal, + sessionTraceOrdinal: ordinal, + kind: kind, + kindSchemaVersion: 1, + occurredAtUtc: occurredAtUtc, + sourceOrigin: "test", + evidence: new Evidence(EvidenceKind.Synthetic, $"t-{kind}-{ordinal}", $"synthetic {kind}"), + payload: payload); + + /// What the host posts: name plus due time, OccurredAtUtc = firing clock. + private static Dictionary FiredPayload(string deadlineName, DateTime dueAtUtc) => + new Dictionary + { + [SignalPayloadKeys.Deadline] = deadlineName, + [SignalPayloadKeys.DeadlineDueAtUtc] = dueAtUtc.ToString("O", CultureInfo.InvariantCulture), + }; + + // ============================================================== helper + + [Fact] + public void DeadlineDueAtUtc_reads_the_payload_and_falls_back_to_the_signal_time() + { + var due = T0.AddMinutes(5); + var fired = T0.AddMinutes(9); + + var withKey = MakeSignal(1, DecisionSignalKind.DeadlineFired, fired, FiredPayload(DeadlineNames.HelloSafety, due)); + Assert.Equal(due, DecisionEngine.DeadlineDueAtUtc(withKey)); + Assert.Equal(DateTimeKind.Utc, DecisionEngine.DeadlineDueAtUtc(withKey).Kind); + + var withoutKey = MakeSignal(2, DecisionSignalKind.DeadlineFired, fired, + new Dictionary { [SignalPayloadKeys.Deadline] = DeadlineNames.HelloSafety }); + Assert.Equal(fired, DecisionEngine.DeadlineDueAtUtc(withoutKey)); + + var garbage = MakeSignal(3, DecisionSignalKind.DeadlineFired, fired, + new Dictionary { [SignalPayloadKeys.DeadlineDueAtUtc] = "not-a-time" }); + Assert.Equal(fired, DecisionEngine.DeadlineDueAtUtc(garbage)); + } + + // ============================================================== Classic: standby at the Hello prompt + + [Fact] + public void Late_HelloSafety_fire_stamps_the_resolution_and_the_grace_window_from_the_firing_clock() + { + // Session ac5660b8 shape: ESP exits, the user leaves the device at the Hello prompt, it + // enters Modern Standby, HelloSafety is due during the sleep and fires ~3 min late after + // wake. The Hello timeout fact, the Finalizing step and the FinalizingGrace due time must + // all sit at the firing clock — never inside the sleep window. + var engine = new DecisionEngine(); + var state = DecisionState.CreateInitial("sess-standby", "tenant", T0); + state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0)).NewState; + state = engine.Reduce(state, MakeSignal(1, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + state = engine.Reduce(state, MakeSignal(2, DecisionSignalKind.AccountSetupProvisioningComplete, T0.AddMinutes(2))).NewState; + state = engine.Reduce(state, MakeSignal(3, DecisionSignalKind.DesktopArrived, T0.AddMinutes(3))).NewState; + + var espExit = T0.AddMinutes(6).AddSeconds(50.2144855); + state = engine.Reduce(state, MakeSignal(4, DecisionSignalKind.EspExiting, espExit)).NewState; + var helloSafety = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + Assert.Equal(espExit.AddSeconds(300), helloSafety.DueAtUtc); + + // Timer fires after wake, 2m 54s past due. + var firedAt = helloSafety.DueAtUtc.AddSeconds(174); + var finalizing = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.DeadlineFired, firedAt, + FiredPayload(DeadlineNames.HelloSafety, helloSafety.DueAtUtc))); + + Assert.True(finalizing.Transition.Taken); + Assert.Equal(SessionStage.Finalizing, finalizing.NewState.Stage); + Assert.Equal("Timeout", finalizing.NewState.HelloOutcome!.Value); + Assert.Equal(firedAt, finalizing.NewState.HelloResolvedUtc!.Value); + + var grace = Assert.Single(finalizing.NewState.Deadlines, d => d.Name == DeadlineNames.FinalizingGrace); + Assert.Equal(firedAt.AddSeconds(5), grace.DueAtUtc); + + // The chained grace fires on time and completes; nothing carries the old due time. + var completed = engine.Reduce(finalizing.NewState, MakeSignal(6, DecisionSignalKind.DeadlineFired, grace.DueAtUtc, + FiredPayload(DeadlineNames.FinalizingGrace, grace.DueAtUtc))); + Assert.Equal(SessionStage.Completed, completed.NewState.Stage); + Assert.Equal(SessionOutcome.EnrollmentComplete, completed.NewState.Outcome); + Assert.Contains(completed.Effects, e => + e.Kind == DecisionEffectKind.EmitEventTimelineEntry + && e.Parameters != null + && e.Parameters.TryGetValue("eventType", out var et) && et == "enrollment_complete"); + } + + // ============================================================== SelfDeploying guard C + + [Fact] + public void SelfDeploying_guard_C_matches_the_incarnation_by_payload_due_time_not_by_firing_clock() + { + var engine = new DecisionEngine(); + var state = DecisionState.CreateInitial("sd-late", "t", T0); + state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0)).NewState; + state = engine.Reduce(state, MakeSignal(1, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })).NewState; + state = engine.Reduce(state, MakeSignal(2, DecisionSignalKind.DeviceSetupProvisioningComplete, T0.AddMinutes(3))).NewState; + var armed = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.DeviceOnlyEspDetection); + Assert.Equal(T0.AddMinutes(8), armed.DueAtUtc); + + // A stale fire of an OLDER incarnation (due T+5) arriving late: dead-end, deadline kept. + var stale = engine.Reduce(state, MakeSignal(3, DecisionSignalKind.DeadlineFired, T0.AddMinutes(12), + FiredPayload(DeadlineNames.DeviceOnlyEspDetection, T0.AddMinutes(5)))); + Assert.False(stale.Transition.Taken); + Assert.Equal("device_only_esp_detection_stale_due_at_mismatch", stale.Transition.DeadEndReason); + Assert.Single(stale.NewState.Deadlines, d => d.Name == DeadlineNames.DeviceOnlyEspDetection); + + // The real fire, 4 min late (standby), carries the armed due time: terminal. + var real = engine.Reduce(stale.NewState, MakeSignal(4, DecisionSignalKind.DeadlineFired, T0.AddMinutes(12), + FiredPayload(DeadlineNames.DeviceOnlyEspDetection, armed.DueAtUtc))); + Assert.True(real.Transition.Taken); + Assert.Equal(SessionStage.Completed, real.NewState.Stage); + } + + // ============================================================== RealmJoin re-arm guard + + [Fact] + public void RealmJoin_rearm_guard_compares_the_payload_due_time_not_the_firing_clock() + { + var engine = new DecisionEngine(); + var state = DecisionState.CreateInitial("rj-late", "t", T0); + state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0)).NewState; + state = engine.Reduce(state, MakeSignal(1, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })).NewState; + state = engine.Reduce(state, MakeSignal(2, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(2), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + state = engine.Reduce(state, MakeSignal(3, DecisionSignalKind.EspExiting, T0.AddMinutes(3))).NewState; + state = engine.Reduce(state, MakeSignal(4, DecisionSignalKind.HelloResolved, T0.AddMinutes(4), + new Dictionary { [SignalPayloadKeys.HelloOutcome] = "Success" })).NewState; + state = engine.Reduce(state, MakeSignal(5, DecisionSignalKind.RealmJoinDetected, T0.AddMinutes(5), + new Dictionary { [DecisionEngine.RealmJoinPayloadKeys.DeploymentPhase] = "100" })).NewState; + state = engine.Reduce(state, MakeSignal(6, DecisionSignalKind.DesktopArrived, T0.AddMinutes(6))).NewState; + var first = Assert.Single(state.Deadlines, d => d.Name == DeadlineNames.RealmJoinTimeout); + + // Simulate the activity-based re-arm: the armed incarnation is now due later. + var rearmedDue = first.DueAtUtc.AddMinutes(25); + var rearmed = state.ToBuilder() + .CancelDeadline(DeadlineNames.RealmJoinTimeout) + .AddDeadline(new ActiveDeadline( + name: DeadlineNames.RealmJoinTimeout, + dueAtUtc: rearmedDue, + firesSignalKind: DecisionSignalKind.DeadlineFired, + firesPayload: new Dictionary { [SignalPayloadKeys.Deadline] = DeadlineNames.RealmJoinTimeout })) + .Build(); + + // The OLD incarnation's fire arrives late — after the re-armed due time on the clock. + // Only the payload due time identifies it as superseded. + var firedAt = rearmedDue.AddMinutes(1); + var stale = engine.Reduce(rearmed, MakeSignal(7, DecisionSignalKind.DeadlineFired, firedAt, + FiredPayload(DeadlineNames.RealmJoinTimeout, first.DueAtUtc))); + Assert.False(stale.Transition.Taken); + Assert.Equal("realmjoin_timeout_stale_superseded_by_rearm", stale.Transition.DeadEndReason); + Assert.Null(stale.NewState.RealmJoinFacts.Outcome); + + // The re-armed incarnation's own fire, same firing clock: timeout is applied. + var real = engine.Reduce(stale.NewState, MakeSignal(8, DecisionSignalKind.DeadlineFired, firedAt, + FiredPayload(DeadlineNames.RealmJoinTimeout, rearmedDue))); + Assert.True(real.Transition.Taken); + Assert.Equal("Timeout", real.NewState.RealmJoinFacts.Outcome!.Value); + Assert.Equal(SessionStage.Finalizing, real.NewState.Stage); + } + } +} diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/SerializationTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/SerializationTests.cs index cb464725..14232f03 100644 --- a/src/Agent/AutopilotMonitor.DecisionCore.Tests/SerializationTests.cs +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/SerializationTests.cs @@ -54,6 +54,37 @@ namespace AutopilotMonitor.DecisionCore.Tests Assert.Equal("AccountSetup", roundtripped.Payload!["phase"]); } + [Fact] + public void SignalSerializer_roundtrip_keeps_date_like_payload_strings_verbatim() + { + // The shared reader tokenizes ISO-8601 strings as dates; the string dictionaries must + // still come back as the round-trip text the writer produced, never culture-formatted + // (the DeadlineFired due time is parsed back with the "o" format on replay). + var due = new DateTime(2026, 4, 20, 9, 55, 0, DateTimeKind.Utc); + var original = new DecisionSignal( + sessionSignalOrdinal: 7, + sessionTraceOrdinal: 7, + kind: DecisionSignalKind.DeadlineFired, + kindSchemaVersion: 1, + occurredAtUtc: due.AddMinutes(5), + sourceOrigin: "DeadlineScheduler", + evidence: new Evidence( + kind: EvidenceKind.Synthetic, + identifier: "hello_safety", + summary: "deadline fired", + derivationInputs: new Dictionary { ["armedAt"] = "2026-04-20T09:50:00.0000000Z" }), + payload: new Dictionary + { + ["deadline"] = "hello_safety", + ["deadlineDueAtUtc"] = due.ToString("O"), + }); + + var roundtripped = SignalSerializer.Deserialize(SignalSerializer.Serialize(original)); + + Assert.Equal("2026-04-20T09:55:00.0000000Z", roundtripped.Payload!["deadlineDueAtUtc"]); + Assert.Equal("2026-04-20T09:50:00.0000000Z", roundtripped.Evidence.DerivationInputs!["armedAt"]); + } + [Fact] public void SignalSerializer_Deserialize_MissingEvidence_throws() { diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DeadlineNames.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DeadlineNames.cs index 60ed8cc4..34ebcc48 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DeadlineNames.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DeadlineNames.cs @@ -86,6 +86,15 @@ namespace AutopilotMonitor.DecisionCore.Engine /// On DeadlineFired: the deadline name from . public const string Deadline = "deadline"; + /// + /// On DeadlineFired: the deadline's as an + /// ISO-8601 round-trip string. The signal's OccurredAtUtc is the time the timer + /// actually fired (which trails the due time after standby or an agent restart); stale-fire + /// guards that must identify the deadline incarnation read this key via + /// DecisionEngine.DeadlineDueAtUtc. + /// + public const string DeadlineDueAtUtc = "deadlineDueAtUtc"; + /// On EspPhaseChanged: the raw phase name as observed by the collector. public const string EspPhase = "phase"; diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.RealmJoin.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.RealmJoin.cs index 8323605b..32e41eb3 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.RealmJoin.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.RealmJoin.cs @@ -252,10 +252,11 @@ namespace AutopilotMonitor.DecisionCore.Engine // Third staleness shape (introduced with the activity-based extension): the fire // belongs to an OLDER deadline incarnation that a re-arm has since replaced — - // recognizable because the armed deadline is due LATER than this fire - // (OccurredAtUtc = DueAtUtc per the scheduler contract). Without this guard the + // recognizable because the armed deadline is due LATER than the due time this fire + // belongs to (payload, see DeadlineDueAtUtc — never the signal time, which is the + // firing clock and trails the due time after standby). Without this guard the // stale fire would evaluate the timeout/extension decision ahead of schedule. - var supersededByRearm = armedDeadline != null && armedDeadline.DueAtUtc > signal.OccurredAtUtc; + var supersededByRearm = armedDeadline != null && armedDeadline.DueAtUtc > DeadlineDueAtUtc(signal); if (alreadyResolvedOrTimedOut || armedDeadline == null || supersededByRearm) { diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.SelfDeploying.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.SelfDeploying.cs index e904e4af..3fdeffad 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.SelfDeploying.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.SelfDeploying.cs @@ -255,10 +255,11 @@ namespace AutopilotMonitor.DecisionCore.Engine // --- Stale-fire guard C: DueAtUtc mismatch --- // Cancel-then-rearm race: an old DeadlineFired (from a deadline incarnation that was // replaced by a later HandleDeviceSetupProvisioningCompleteV1 arming) is processed - // after the rearm. DeadlineScheduler posts OccurredAtUtc == deadline.DueAtUtc, so the - // OLD fire carries the OLD DueAtUtc. Dead-end WITHOUT cancelling the active deadline - // (the whole point is to keep the new one for its real fire). - if (activeDeadline.DueAtUtc != signal.OccurredAtUtc) + // after the rearm. The fire carries the due time of the incarnation it belongs to + // (payload, see DeadlineDueAtUtc), so the OLD fire carries the OLD DueAtUtc. Dead-end + // WITHOUT cancelling the active deadline (the whole point is to keep the new one for + // its real fire). + if (activeDeadline.DueAtUtc != DeadlineDueAtUtc(signal)) { var bookkept = BumpStepBookkeeping(state, signal); var transition = BuildDeadEndTransition( diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs index 42fd24cb..f1ad597c 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs @@ -1013,6 +1013,27 @@ namespace AutopilotMonitor.DecisionCore.Engine return signal.OccurredAtUtc; } + /// + /// The due time of the deadline a DeadlineFired signal belongs to. The host stamps the + /// signal with the wall-clock firing time (after Modern Standby or an agent restart that + /// trails the due time by minutes) and carries the due time under + /// ; stale-fire guards compare THIS against + /// the armed , never the signal time. Falls back to + /// signal.OccurredAtUtc for signal logs written before the key existed, where the + /// two were equal by contract. + /// + internal static DateTime DeadlineDueAtUtc(DecisionSignal signal) + { + if (signal.Payload != null + && signal.Payload.TryGetValue(SignalPayloadKeys.DeadlineDueAtUtc, out var raw) + && DateTime.TryParseExact(raw, "o", System.Globalization.CultureInfo.InvariantCulture, + System.Globalization.DateTimeStyles.RoundtripKind, out var due)) + { + return due.Kind == DateTimeKind.Utc ? due : due.ToUniversalTime(); + } + return signal.OccurredAtUtc; + } + /// /// Determine the user-visible enrollment phase implied by an ESP phase-change signal. /// Plan §2.3 phase-fact mapping. Populated in M3.1 as Classic handlers come online. diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs index e694a69b..8678af4e 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs @@ -282,11 +282,9 @@ namespace AutopilotMonitor.DecisionCore.Engine if (!reachedTerminal) { - // The DeadlineFired signal carries DueAtUtc as OccurredAtUtc, so for a tick - // armed in the current run this is already current-clock-equivalent. The - // EffectiveDeadlineBase guard still fires correctly across restart, where - // a stale DueAtUtc from the prior run could otherwise re-arm the next tick - // in the past. + // The DeadlineFired signal carries the wall-clock firing time, so the next tick + // is armed relative to now — also after a late fire (standby). The + // EffectiveDeadlineBase guard still floors a replayed fire at boot. var rearm = BuildClassifierTickDeadline(EffectiveDeadlineBase(state, signal)); builder.AddDeadline(rearm); effects.Add(new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: rearm)); diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Serialization/SignalSerializer.cs b/src/Shared/AutopilotMonitor.DecisionCore/Serialization/SignalSerializer.cs index b8d6f314..064af299 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Serialization/SignalSerializer.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Serialization/SignalSerializer.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Globalization; using AutopilotMonitor.DecisionCore.Signals; using Newtonsoft.Json; using Newtonsoft.Json.Linq; @@ -46,7 +47,7 @@ namespace AutopilotMonitor.DecisionCore.Serialization var d = new Dictionary(); foreach (var prop in diObj.Properties()) { - d[prop.Name] = prop.Value?.ToString() ?? string.Empty; + d[prop.Name] = StringValue(prop.Value); } derivationInputs = d; } @@ -64,7 +65,7 @@ namespace AutopilotMonitor.DecisionCore.Serialization var p = new Dictionary(); foreach (var prop in payloadObj.Properties()) { - p[prop.Name] = prop.Value?.ToString() ?? string.Empty; + p[prop.Name] = StringValue(prop.Value); } payload = p; } @@ -112,6 +113,23 @@ namespace AutopilotMonitor.DecisionCore.Serialization typedPayload: typedPayload); } + /// + /// String-dictionary values (Payload, DerivationInputs) verbatim. The shared reader + /// tokenizes an ISO-8601 string as a Date (DateParseHandling.DateTime), and + /// JValue.ToString() would then render it in the current culture — a replayed + /// deadlineDueAtUtc came back as "4/20/2026 9:55:00 AM". Render a Date token as + /// the round-trip text the writer produced. + /// + private static string StringValue(JToken? token) + { + if (token is JValue jv && jv.Type == JTokenType.Date && jv.Value is DateTime dt) + { + var utc = dt.Kind == DateTimeKind.Local ? dt.ToUniversalTime() : DateTime.SpecifyKind(dt, DateTimeKind.Utc); + return utc.ToString("O", CultureInfo.InvariantCulture); + } + return token?.ToString() ?? string.Empty; + } + private static T ParseEnum(string? raw, T fallback) where T : struct, Enum { if (string.IsNullOrEmpty(raw)) return fallback; diff --git a/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx b/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx index 16934b92..7abe8137 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx @@ -4,6 +4,7 @@ import { useState } from "react"; import { Session } from "@/types"; import { SessionStatusBadge } from "@/components/SessionStatusBadge"; import FailureSnapshotBlock from "./FailureSnapshotBlock"; +import { formatDuration } from "@/lib/formatting"; interface SessionInfoCardProps { session: Session; @@ -12,16 +13,10 @@ interface SessionInfoCardProps { isGatherRulesSession: boolean; ntpOffset?: { offsetSeconds: number; ntpServer?: string } | null; configMgrDetected?: { ccmVersion?: string; ccmServiceState?: string; siteCode?: string; confidenceScore?: number } | null; - /** Total observed sleep/standby seconds (system_sleep_episode ground truth) — explains an inflated wall-clock duration. */ + /** Sleep/standby seconds inside the enrollment window (system_sleep_episode ground truth) — explains an inflated wall-clock duration. */ standbySeconds?: number | null; } -// Compact duration for the standby note: "56m", "1h 2m". -function formatStandby(seconds: number): string { - if (seconds >= 3600) return `${Math.floor(seconds / 3600)}h ${Math.floor((seconds % 3600) / 60)}m`; - return `${Math.max(1, Math.round(seconds / 60))}m`; -} - export default function SessionInfoCard({ session, enrollmentDuration, displayStatus, isGatherRulesSession, ntpOffset, configMgrDetected, standbySeconds }: SessionInfoCardProps) { const lastContactTooltip = session.lastEventAt ? `Last contact: ${new Date(session.lastEventAt).toLocaleString([], { dateStyle: "short", timeStyle: "medium" })}` @@ -72,9 +67,9 @@ export default function SessionInfoCard({ session, enrollmentDuration, displaySt {enrollmentDuration ?? `${Math.round((session.durationSeconds ?? 0) / 60)} min`} - {" "}· 🌙 {formatStandby(standbySeconds)} standby + {" "}· 🌙 {formatDuration(standbySeconds)} standby ) : ( diff --git a/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts b/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts index 307cd93d..fb7b9595 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts +++ b/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts @@ -5,6 +5,7 @@ import { EnrollmentEvent, Session } from "@/types"; import { V1_PHASE_NAMES, V2_PHASE_NAMES, V1_PHASE_ORDER, V2_PHASE_ORDER } from "../utils/phaseConstants"; import { detectSkipUserStatusPage } from "../utils/espConfig"; import { computeWhiteGloveDurations, computeWhiteGloveSplitSequence, groupEventsByPhase } from "../utils/eventHelpers"; +import { sumStandbySeconds } from "@/lib/standby"; interface PhaseGrouping { eventsByPhase: Record; @@ -138,7 +139,7 @@ export function useSessionDerivedData( // agent started — environment observation, not enrollment activity — and would drag the // start toward pre-enrollment OOBE idle time (mirrors the backend anchor eligibility; // field case d0c5b672). - const enrollmentDurationFromEvents = useMemo(() => { + const enrollmentWindow = useMemo(() => { const activityEvents = events.filter(e => e.source !== "SystemTimelineWatcher"); if (activityEvents.length === 0) return null; const timestamps = activityEvents.map(e => new Date(e.timestamp).getTime()); @@ -147,11 +148,16 @@ export function useSessionDerivedData( const endTime = completeEvent ? new Date(completeEvent.timestamp).getTime() : Math.max(...timestamps); - const durationSec = Math.round((endTime - firstEventTime) / 1000); + return { startMs: firstEventTime, endMs: endTime }; + }, [events]); + + const enrollmentDurationFromEvents = useMemo(() => { + if (!enrollmentWindow) return null; + const durationSec = Math.round((enrollmentWindow.endMs - enrollmentWindow.startMs) / 1000); if (durationSec < 60) return `${durationSec}s`; if (durationSec < 3600) return `${Math.floor(durationSec / 60)}m ${durationSec % 60}s`; return `${Math.floor(durationSec / 3600)}h ${Math.floor((durationSec % 3600) / 60)}m`; - }, [events]); + }, [enrollmentWindow]); // Last moment the agent reported anything — the end of the observation window, in the // device clock frame the event timestamps share. Deliberately NOT the enrollment duration @@ -171,24 +177,14 @@ export function useSessionDerivedData( return max; }, [events, sessionLastEventAt]); - // Total observed sleep/standby seconds (system_sleep_episode ground truth). The wall-clock - // duration deliberately keeps the pause — this number tells the story next to it ("1h 20m, - // 56m of it standby"). Dedup on enteredAt: the same episode can be observed twice (agent - // restart re-backfills it from a different event-log record). - const standbySeconds = useMemo(() => { - const seenEpisodes = new Set(); - let total = 0; - for (const e of events) { - if (e.eventType !== "system_sleep_episode" || !e.data) continue; - const duration = Number(e.data.durationSeconds); - if (!Number.isFinite(duration) || duration <= 0) continue; - const enteredAt = typeof e.data.enteredAt === "string" ? e.data.enteredAt : `seq-${e.sequence}`; - if (seenEpisodes.has(enteredAt)) continue; - seenEpisodes.add(enteredAt); - total += duration; - } - return total > 0 ? Math.round(total) : null; - }, [events]); + // Sleep/standby seconds inside the enrollment window above (system_sleep_episode ground + // truth). The wall-clock duration deliberately keeps the pause — this number tells the story + // next to it ("1h 20m, 56m of it standby") and is clipped to the same window so the two agree + // with the time-attribution chip; sleep after the verdict is not enrollment time. + const standbySeconds = useMemo( + () => sumStandbySeconds(events, enrollmentWindow?.startMs ?? null, enrollmentWindow?.endMs ?? null), + [events, enrollmentWindow], + ); const phaseNamesMap = session?.enrollmentType === "v2" ? V2_PHASE_NAMES : V1_PHASE_NAMES; const phaseOrder = session?.enrollmentType === "v2" ? V2_PHASE_ORDER : V1_PHASE_ORDER; diff --git a/src/Web/autopilot-monitor-web/lib/__tests__/standby.test.ts b/src/Web/autopilot-monitor-web/lib/__tests__/standby.test.ts new file mode 100644 index 00000000..50d27356 --- /dev/null +++ b/src/Web/autopilot-monitor-web/lib/__tests__/standby.test.ts @@ -0,0 +1,61 @@ +import { describe, expect, it } from "vitest"; +import type { EnrollmentEvent } from "@/types"; +import { sumStandbySeconds } from "../standby"; + +const T = (iso: string) => Date.parse(iso); + +function sleepEpisode(seq: number, enteredAt: string, exitedAt: string, durationSeconds: number): EnrollmentEvent { + return { + eventType: "system_sleep_episode", + source: "SystemTimelineWatcher", + timestamp: exitedAt, + sequence: seq, + message: "Device exited Modern Standby", + data: { kind: "modern_standby", enteredAt, exitedAt, durationSeconds }, + } as unknown as EnrollmentEvent; +} + +describe("sumStandbySeconds", () => { + // Session ac5660b8: asleep 06:40:28.69–06:45:19.03 (290 s), enrollment window ends 06:42:55.21. + const episode = sleepEpisode(163, "2026-09-09T06:40:28.6907161Z", "2026-09-09T06:45:19.0307161Z", 290); + const windowStart = T("2026-09-09T06:32:46.772Z"); + const completedAt = T("2026-09-09T06:42:55.2144855Z"); + + it("clips an episode that straddles the end of the window", () => { + expect(sumStandbySeconds([episode], windowStart, completedAt)).toBe(147); + }); + + it("counts the whole episode when it lies inside the window", () => { + expect(sumStandbySeconds([episode], windowStart, T("2026-09-09T06:45:49Z"))).toBe(290); + }); + + it("counts the whole episode without a window", () => { + expect(sumStandbySeconds([episode], null, null)).toBe(290); + }); + + it("returns null for an episode entirely outside the window", () => { + expect(sumStandbySeconds([episode], windowStart, T("2026-09-09T06:40:00Z"))).toBeNull(); + }); + + it("dedups the same episode observed twice", () => { + const again = sleepEpisode(200, "2026-09-09T06:40:28.6907161Z", "2026-09-09T06:45:19.0307161Z", 290); + expect(sumStandbySeconds([episode, again], null, null)).toBe(290); + }); + + it("falls back to durationSeconds when the payload carries no instants", () => { + const legacy = { + eventType: "system_sleep_episode", + source: "SystemTimelineWatcher", + timestamp: "2026-09-09T06:45:19Z", + sequence: 5, + message: "", + data: { kind: "sleep", durationSeconds: 120 }, + } as unknown as EnrollmentEvent; + expect(sumStandbySeconds([legacy], windowStart, completedAt)).toBe(120); + }); + + it("ignores other events and returns null when nothing slept", () => { + const other = { ...episode, eventType: "performance_snapshot" } as EnrollmentEvent; + expect(sumStandbySeconds([other], null, null)).toBeNull(); + }); +}); diff --git a/src/Web/autopilot-monitor-web/lib/standby.ts b/src/Web/autopilot-monitor-web/lib/standby.ts new file mode 100644 index 00000000..a96b1ddb --- /dev/null +++ b/src/Web/autopilot-monitor-web/lib/standby.ts @@ -0,0 +1,41 @@ +import type { EnrollmentEvent } from "@/types"; + +/** + * Seconds the device spent asleep inside a window, from `system_sleep_episode` ground truth. + * + * The payload's `enteredAt` / `exitedAt` are the authoritative instants (the event itself is + * stamped at wake). Each episode is clipped to `[windowStartMs, windowEndMs]` so the number sits + * next to a duration that covers the same window — an episode that straddles the end of the + * enrollment contributes only its in-window part, matching the backend's time-attribution + * `SleepSpans`. Episodes are dedup'd on `enteredAt`: an agent restart can re-backfill the same + * episode from a different event-log record. Returns null when nothing was asleep. + */ +export function sumStandbySeconds( + events: EnrollmentEvent[], + windowStartMs: number | null, + windowEndMs: number | null, +): number | null { + const seen = new Set(); + let totalMs = 0; + for (const e of events) { + if (e.eventType !== "system_sleep_episode" || !e.data) continue; + const enteredRaw = typeof e.data.enteredAt === "string" ? e.data.enteredAt : null; + const exitedRaw = typeof e.data.exitedAt === "string" ? e.data.exitedAt : null; + const key = enteredRaw ?? `seq-${e.sequence}`; + if (seen.has(key)) continue; + seen.add(key); + + let start = enteredRaw ? Date.parse(enteredRaw) : NaN; + let end = exitedRaw ? Date.parse(exitedRaw) : NaN; + if (!Number.isFinite(start) || !Number.isFinite(end)) { + // No usable instants: fall back to the reported duration, unclipped. + const duration = Number(e.data.durationSeconds); + if (Number.isFinite(duration) && duration > 0) totalMs += duration * 1000; + continue; + } + if (windowStartMs !== null) start = Math.max(start, windowStartMs); + if (windowEndMs !== null) end = Math.min(end, windowEndMs); + if (end > start) totalMs += end - start; + } + return totalMs > 0 ? Math.round(totalMs / 1000) : null; +}