diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs new file mode 100644 index 00000000..c22185bb --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs @@ -0,0 +1,152 @@ +using System; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.SignalAdapters; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using AutopilotMonitor.Shared.Models; +using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters +{ + /// + /// Replay-safety regression: when ImeLogTracker processes a CMTrace log entry it + /// stamps + /// with the source-line time. The adapter must use that timestamp on both the emitted + /// and the corresponding informational event — collapsing + /// to _clock.UtcNow would lose forensic time on agent first-boot replay. + /// + /// Pathological-clock guard: a source timestamp older than 24h or in the future by >1h + /// is rejected; the adapter falls back to the clock and tags the event with + /// derivedTimestamp=true + rejectedSourceTimestamp=<original> so the + /// anomaly is forensically visible (per feedback_timestamp_clamping). + /// + /// + public sealed class ImeLogTrackerAdapterSourceTimestampTests + { + private static readonly DateTime ClockNow = new DateTime(2026, 5, 4, 12, 0, 0, DateTimeKind.Utc); + + [Fact] + public void EspPhase_uses_source_log_timestamp_when_present() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + var sourceTs = ClockNow.AddMinutes(-30); + f.Tracker.LastMatchedLogTimestamp = sourceTs; + + adapter.TriggerEspPhaseFromTest("DeviceSetup"); + + // DecisionSignal carries the source time, NOT clock.UtcNow. + var decision = f.DecisionSignals(DecisionSignalKind.EspPhaseChanged).Single(); + Assert.Equal(sourceTs, decision.OccurredAtUtc); + Assert.False(decision.Evidence!.DerivationInputs!.ContainsKey("derivedTimestamp")); + + // InformationalEvent mirrors the source time so the timeline ordering on the UI + // shows when the phase actually transitioned, not when the agent caught up. + var info = f.InfoEvent(SharedEventTypes.EspPhaseChanged); + Assert.Equal(sourceTs, info.OccurredAtUtc); + Assert.False(info.Payload!.ContainsKey("derivedTimestamp")); + } + + [Fact] + public void EspPhase_falls_back_to_clock_when_no_source_timestamp_and_flags_derivation() + { + // No LastMatchedLogTimestamp set — fixture default is null. + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + adapter.TriggerEspPhaseFromTest("DeviceSetup"); + + var decision = f.DecisionSignals(DecisionSignalKind.EspPhaseChanged).Single(); + Assert.Equal(ClockNow, decision.OccurredAtUtc); + Assert.Equal("true", decision.Evidence!.DerivationInputs!["derivedTimestamp"]); + + var info = f.InfoEvent(SharedEventTypes.EspPhaseChanged); + Assert.Equal(ClockNow, info.OccurredAtUtc); + Assert.Equal("true", info.Payload!["derivedTimestamp"]); + } + + [Fact] + public void EspPhase_clamps_pathologically_old_source_timestamp_and_flags_rejected_value() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + // 25h-old source timestamp — pathological (skewed CMTrace clock or multi-day log). + var ancient = ClockNow.AddHours(-25); + f.Tracker.LastMatchedLogTimestamp = ancient; + + adapter.TriggerEspPhaseFromTest("DeviceSetup"); + + var decision = f.DecisionSignals(DecisionSignalKind.EspPhaseChanged).Single(); + Assert.Equal(ClockNow, decision.OccurredAtUtc); + Assert.Equal("true", decision.Evidence!.DerivationInputs!["derivedTimestamp"]); + Assert.Equal(ancient.ToString("o"), decision.Evidence.DerivationInputs["rejectedSourceTimestamp"]); + + var info = f.InfoEvent(SharedEventTypes.EspPhaseChanged); + Assert.Equal("true", info.Payload!["derivedTimestamp"]); + Assert.Equal(ancient.ToString("o"), info.Payload["rejectedSourceTimestamp"]); + } + + [Fact] + public void UserSessionCompleted_uses_source_log_timestamp_when_present() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + var sourceTs = ClockNow.AddMinutes(-15); + f.Tracker.LastMatchedLogTimestamp = sourceTs; + + adapter.TriggerUserSessionCompletedFromTest(); + + var decision = f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted).Single(); + Assert.Equal(sourceTs, decision.OccurredAtUtc); + + var info = f.InfoEvent(SharedEventTypes.ImeUserSessionCompleted); + Assert.Equal(sourceTs, info.OccurredAtUtc); + Assert.Equal(sourceTs.ToString("o"), info.Payload!["detectedAt"]); + } + + [Fact] + public void AppStateChange_uses_source_log_timestamp_when_present() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + var sourceTs = ClockNow.AddMinutes(-5); + f.Tracker.LastMatchedLogTimestamp = sourceTs; + var app = new AppPackageState("app-X", 0); + + adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installed); + + var decision = f.DecisionSignals(DecisionSignalKind.AppInstallCompleted).Single(); + Assert.Equal(sourceTs, decision.OccurredAtUtc); + + var info = f.InfoEvent(SharedEventTypes.AppInstallComplete); + Assert.Equal(sourceTs, info.OccurredAtUtc); + // Timing payload also pinned to source time — startedAt/completedAt reflect when + // the app *actually* finished, not when the agent read the log line. + Assert.Equal(sourceTs.ToString("o"), info.Payload!["completedAt"]); + } + + [Fact] + public void WhiteGloveSealingPattern_uses_source_log_timestamp() + { + using var f = new ImeLogTrackerAdapterFixture(ClockNow); + using var adapter = new ImeLogTrackerAdapter( + f.Tracker, f.Ingress, f.Clock, + whiteGloveSealingPatternIds: new[] { "wg-seal-pattern" }); + + var sourceTs = ClockNow.AddMinutes(-2); + f.Tracker.LastMatchedLogTimestamp = sourceTs; + + adapter.TriggerPatternMatchedFromTest("wg-seal-pattern"); + + var decision = f.DecisionSignals(DecisionSignalKind.WhiteGloveSealingPatternDetected).Single(); + Assert.Equal(sourceTs, decision.OccurredAtUtc); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs index 5e12c631..780b6b71 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs @@ -107,9 +107,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime private const int MaxScriptOutputLength = 2048; private const int MaxMultiLineBufferLines = 100; - // Set synchronously during HandlePatternMatch so callbacks can read it - public string LastMatchedPatternId { get; private set; } - public DateTime? LastMatchedLogTimestamp { get; private set; } + // Set synchronously during HandlePatternMatch so callbacks can read it. + // Setters are `internal` so V2.Core.Tests can drive the source-timestamp path + // through the adapter's TriggerXxxFromTest seams without spinning up a real log file. + public string LastMatchedPatternId { get; internal set; } + public DateTime? LastMatchedLogTimestamp { get; internal set; } // Callbacks to EnrollmentTracker public Action OnEspPhaseChanged { get; set; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs index 7296e278..33035bd6 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs @@ -85,6 +85,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // DecisionSignalKind.HelloPolicyDetected signal. public event Action HelloPolicyDetected; + /// + /// UTC timestamp of the most recent sub-tracker event currently being raised + /// (mirrored from for ShellCore- + /// originated events). Read by EspAndHelloTrackerAdapter inside its synchronous + /// event handler so the emitted DecisionSignal carries the source-event time rather + /// than wall-clock-now — critical on the backfill path. Null when not currently + /// inside a forwarded event invocation, or when the originating sub-tracker doesn't + /// surface a timestamp (Hello / Provisioning trackers fall back to clock at the + /// adapter). + /// + public DateTime? LastEventOccurredAtUtc { get; private set; } + /// /// Outcome of Hello provisioning. Set when Hello resolves (via events, timeout, or not configured). /// Values: "completed", "skipped", "timeout", "not_configured", "wizard_not_started", null (not yet resolved). @@ -313,12 +325,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private void OnHelloCompleted(object sender, EventArgs e) { + // HelloTracker doesn't currently surface a per-event timestamp; adapter falls + // back to clock for Hello-originated events. Set null explicitly so a stale + // ShellCore value cannot bleed across. + LastEventOccurredAtUtc = null; try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch (Exception ex) { _logger.Error("Error forwarding HelloCompleted", ex); } } private void OnHelloPolicyDetected(bool helloEnabled, string source) { + LastEventOccurredAtUtc = null; try { HelloPolicyDetected?.Invoke(helloEnabled, source); } catch (Exception ex) { _logger.Error("Error forwarding HelloPolicyDetected", ex); } } @@ -340,8 +357,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals return; } + // Mirror the originating ShellCoreTracker's source-event timestamp so adapters + // can read it via this coordinator's LastEventOccurredAtUtc. Backfill path keeps + // the historical timestamp; live path matches record.TimeCreated. + LastEventOccurredAtUtc = (sender as ShellCoreTracker)?.LastEventOccurredAtUtc; try { FinalizingSetupPhaseTriggered?.Invoke(this, reason); } catch (Exception ex) { _logger.Error("Error forwarding FinalizingSetupPhaseTriggered", ex); } + finally { LastEventOccurredAtUtc = null; } } /// @@ -407,18 +429,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private void OnWhiteGloveCompleted(object sender, EventArgs e) { + LastEventOccurredAtUtc = (sender as ShellCoreTracker)?.LastEventOccurredAtUtc; try { WhiteGloveCompleted?.Invoke(this, EventArgs.Empty); } catch (Exception ex) { _logger.Error("Error forwarding WhiteGloveCompleted", ex); } + finally { LastEventOccurredAtUtc = null; } } private void OnEspFailureDetected(object sender, string failureType) { + // EspFailureDetected fires from ShellCoreTracker (carries timestamp) AND + // ProvisioningStatusTracker (no timestamp surfaced today — adapter falls back + // to clock). Cast attempt below picks up the timestamp on the ShellCore path. + LastEventOccurredAtUtc = (sender as ShellCoreTracker)?.LastEventOccurredAtUtc; try { EspFailureDetected?.Invoke(this, failureType); } catch (Exception ex) { _logger.Error($"Error forwarding EspFailureDetected for '{failureType}'", ex); } + finally { LastEventOccurredAtUtc = null; } } private void OnDeviceSetupProvisioningComplete(object sender, EventArgs e) { + // Provisioning tracker doesn't surface a timestamp; adapter falls back to clock. + LastEventOccurredAtUtc = null; try { DeviceSetupProvisioningComplete?.Invoke(this, EventArgs.Empty); } catch (Exception ex) { _logger.Error("Error forwarding DeviceSetupProvisioningComplete", ex); } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs index a8a05979..ccd0d5c1 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs @@ -47,6 +47,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private bool _whiteGloveDetected; private readonly object _stateLock = new object(); + /// + /// UTC timestamp of the most recent event whose handlers are currently running. + /// Set immediately before each event is raised (live or backfill); cleared back to + /// null after the synchronous invoke chain returns. Subscribers read this + /// in their handler to get the source-event timestamp without a signature change + /// to the event delegates — preserves the historical time across backfill (where + /// we'd otherwise collapse to wall-clock-now) without touching every callsite. + /// + public DateTime? LastEventOccurredAtUtc { get; private set; } + public event EventHandler FinalizingSetupPhaseTriggered; public event EventHandler WhiteGloveCompleted; public event EventHandler EspFailureDetected; @@ -247,26 +257,37 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals _logger.Info($"Shell-Core event detected: {eventType} (EventID {eventId})"); - if (triggerFinalizingSetup) + // Set the source-event timestamp BEFORE each event raise so adapters / coordinators + // can read it during their synchronous handler. Cleared in finally so a stale value + // doesn't bleed across event types. + LastEventOccurredAtUtc = timestamp; + try { - try { FinalizingSetupPhaseTriggered?.Invoke(this, finalizingSetupReason); } - catch (Exception ex) { _logger.Error("FinalizingSetupPhaseTriggered handler failed", ex); } - } + if (triggerFinalizingSetup) + { + try { FinalizingSetupPhaseTriggered?.Invoke(this, finalizingSetupReason); } + catch (Exception ex) { _logger.Error("FinalizingSetupPhaseTriggered handler failed", ex); } + } - // Fire WhiteGloveCompleted AFTER event emission so the whiteglove_complete event - // is in the spool before the agent exits. - if (eventType == "whiteglove_complete") - { - try { WhiteGloveCompleted?.Invoke(this, EventArgs.Empty); } - catch (Exception ex) { _logger.Error("WhiteGloveCompleted handler failed", ex); } - } + // Fire WhiteGloveCompleted AFTER event emission so the whiteglove_complete event + // is in the spool before the agent exits. + if (eventType == "whiteglove_complete") + { + try { WhiteGloveCompleted?.Invoke(this, EventArgs.Empty); } + catch (Exception ex) { _logger.Error("WhiteGloveCompleted handler failed", ex); } + } - // Fire EspFailureDetected AFTER event emission so the esp_failure event is in the - // spool before the agent potentially shuts down. - if (eventType == "esp_failure" && detectedFailureType != null) + // Fire EspFailureDetected AFTER event emission so the esp_failure event is in the + // spool before the agent potentially shuts down. + if (eventType == "esp_failure" && detectedFailureType != null) + { + try { EspFailureDetected?.Invoke(this, detectedFailureType); } + catch (Exception ex) { _logger.Error($"EspFailureDetected handler failed for '{detectedFailureType}'", ex); } + } + } + finally { - try { EspFailureDetected?.Invoke(this, detectedFailureType); } - catch (Exception ex) { _logger.Error($"EspFailureDetected handler failed for '{detectedFailureType}'", ex); } + LastEventOccurredAtUtc = null; } } @@ -295,7 +316,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals using (record) { var description = record.FormatDescription() ?? ""; - HandleBackfillRecord(description); + // Preserve the historical event time across backfill so subscribers + // (EspAndHelloTrackerAdapter) can stamp signals with the source time + // rather than collapsing to wall-clock-now. + var timestamp = (record.TimeCreated ?? DateTime.UtcNow).ToUniversalTime(); + HandleBackfillRecord(description, timestamp); } } } @@ -308,9 +333,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals /// /// Internal backfill record handler — extracted for testability and to keep the - /// backfill loop free of direct event-processing logic. + /// backfill loop free of direct event-processing logic. The + /// is the original Shell-Core event time + /// (record.TimeCreated); subscribers read it via + /// during their synchronous event handler. /// - internal void HandleBackfillRecord(string description) + internal void HandleBackfillRecord(string description, DateTime occurredAtUtc) { if (EspExitingPattern.IsMatch(description)) { @@ -326,18 +354,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals if (shouldNotify) { _helloTracker?.NotifyEspExited(); - _logger.Info("Backfill: ESP exit event found in recent Shell-Core logs"); + _logger.Info($"Backfill: ESP exit event found in recent Shell-Core logs (originalAt={occurredAtUtc:o})"); + LastEventOccurredAtUtc = occurredAtUtc; try { FinalizingSetupPhaseTriggered?.Invoke(this, "esp_exiting"); } catch (Exception ex) { _logger.Error("Backfill: FinalizingSetupPhaseTriggered handler failed", ex); } + finally { LastEventOccurredAtUtc = null; } } } if (HasEspFailurePattern(description)) { var failureType = ExtractEspFailureType(description); - _logger.Info($"Backfill: ESP failure event found in recent Shell-Core logs: {failureType}"); + _logger.Info($"Backfill: ESP failure event found in recent Shell-Core logs: {failureType} (originalAt={occurredAtUtc:o})"); + LastEventOccurredAtUtc = occurredAtUtc; try { EspFailureDetected?.Invoke(this, failureType); } catch (Exception ex) { _logger.Error($"Backfill: EspFailureDetected handler failed for '{failureType}'", ex); } + finally { LastEventOccurredAtUtc = null; } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs index dbae9a09..5e7ce3f9 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs @@ -397,7 +397,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // Dispatch: pick the seed + signal stream per branch. Null seed is impossible past // this block (every path assigns it), but the compiler needs the explicit init. - DecisionState seed = DecisionState.CreateInitial(_sessionId, _tenantId); + // AgentBootUtc gets stamped from the live clock so reducer deadline-arming sites + // can floor replayed-signal timestamps at the current run's start (replay-safety). + var agentBootUtc = _clock.UtcNow; + DecisionState seed = DecisionState.CreateInitial(_sessionId, _tenantId, agentBootUtc); IReadOnlyList signalsToReplay = Array.Empty(); string branchTag; @@ -439,7 +442,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration else if (loadedState != null) { // Branch (b) — Snapshot loaded. Catch up any SignalLog tail past the snapshot. - seed = loadedState; + // Re-stamp AgentBootUtc so the current run's deadlines floor at "now" — the + // persisted boot anchor is from the prior run and using it would let replayed + // tail signals arm deadlines that are already past-due (premature fire). + seed = loadedState.ToBuilder().WithAgentBootUtc(agentBootUtc).Build(); signalsToReplay = CollectSignalLogTailAfter(loadedState.LastAppliedSignalOrdinal); branchTag = signalsToReplay.Count > 0 ? "b-tail-replay" : "b-snapshot-current"; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/EspAndHelloTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/EspAndHelloTrackerAdapter.cs index fc694b84..13e7bc57 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/EspAndHelloTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/EspAndHelloTrackerAdapter.cs @@ -105,26 +105,58 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters /// Test-only hook to exercise + the full event-handler emit path without driving the inner HelloTracker's live event sources. internal void TriggerHelloFromCoordinatorPropertyForTest() => EmitHello(ReadHelloOutcome()); + /// + /// Resolve the timestamp to stamp on a coordinator-forwarded signal: prefer the + /// originating sub-tracker's source-event time (mirrored on + /// ) over wall-clock-now. + /// Critical on the Shell-Core backfill path where reading _clock.UtcNow would + /// collapse historical event timestamps to "agent woke up just now". Emits + /// derivedTimestamp=true in the evidence inputs when falling back so the + /// Inspector can flag non-source-grounded signals. + /// + private DateTime ResolveOccurredAt(out bool derivedFromClock) + { + var src = _coordinator.LastEventOccurredAtUtc; + if (src.HasValue) + { + derivedFromClock = false; + return src.Value.Kind == DateTimeKind.Utc + ? src.Value + : DateTime.SpecifyKind(src.Value, DateTimeKind.Utc); + } + derivedFromClock = true; + return _clock.UtcNow; + } + + private static void TagDerivedTimestamp(IDictionary data, bool derivedFromClock) + { + if (derivedFromClock) data["derivedTimestamp"] = "true"; + } + private void EmitHello(string? helloOutcome) { if (_helloPosted) return; _helloPosted = true; var outcome = string.IsNullOrEmpty(helloOutcome) ? "unknown" : helloOutcome!; + var now = ResolveOccurredAt(out var derivedFromClock); + + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "HelloTracker", + [SignalPayloadKeys.HelloOutcome] = outcome, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); _ingress.Post( kind: DecisionSignalKind.HelloResolved, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: $"Hello resolved via coordinator (outcome={outcome})", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "HelloTracker", - [SignalPayloadKeys.HelloOutcome] = outcome, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { [SignalPayloadKeys.HelloOutcome] = outcome, @@ -136,19 +168,23 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (_finalizingPosted) return; _finalizingPosted = true; + var now = ResolveOccurredAt(out var derivedFromClock); + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "ShellCoreTracker", + ["phaseReason"] = reason ?? string.Empty, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); + _ingress.Post( kind: DecisionSignalKind.EspPhaseChanged, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: "ESP Finalizing phase triggered (coordinator-forwarded)", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "ShellCoreTracker", - ["phaseReason"] = reason ?? string.Empty, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { [SignalPayloadKeys.EspPhase] = EnrollmentPhase.FinalizingSetup.ToString(), @@ -161,18 +197,22 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (_whiteGloveSuccessPosted) return; _whiteGloveSuccessPosted = true; + var now = ResolveOccurredAt(out var derivedFromClock); + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "ShellCoreTracker", + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); + _ingress.Post( kind: DecisionSignalKind.WhiteGloveShellCoreSuccess, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: "WhiteGlove sealing success (coordinator-forwarded)", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "ShellCoreTracker", - })); + derivationInputs: derivationInputs)); } private void EmitEspFailure(string failureType) @@ -181,20 +221,23 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters _espFailurePosted = true; var safeType = string.IsNullOrEmpty(failureType) ? "unknown" : failureType!; + var now = ResolveOccurredAt(out var derivedFromClock); + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "ShellCoreTracker+ProvisioningStatusTracker (merged)", + ["failureType"] = safeType, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); _ingress.Post( kind: DecisionSignalKind.EspTerminalFailure, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: $"ESP terminal failure (coordinator-merged, type={safeType})", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "ShellCoreTracker+ProvisioningStatusTracker (merged)", - ["failureType"] = safeType, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { ["failureType"] = safeType, @@ -212,21 +255,25 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var helloEnabledStr = helloEnabled ? "true" : "false"; var safeSource = string.IsNullOrEmpty(source) ? "unknown" : source!; + var now = ResolveOccurredAt(out var derivedFromClock); + + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "HelloTracker", + [SignalPayloadKeys.HelloEnabled] = helloEnabledStr, + [SignalPayloadKeys.HelloPolicySource] = safeSource, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); _ingress.Post( kind: DecisionSignalKind.HelloPolicyDetected, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: $"Hello policy detected (helloEnabled={helloEnabledStr}, source={safeSource})", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "HelloTracker", - [SignalPayloadKeys.HelloEnabled] = helloEnabledStr, - [SignalPayloadKeys.HelloPolicySource] = safeSource, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { [SignalPayloadKeys.HelloEnabled] = helloEnabledStr, @@ -244,20 +291,24 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters snapshot.TryGetValue("DeviceSetup", out var ds) && ds.HasValue ? ds.Value.ToString().ToLowerInvariant() : "unknown"; + var now = ResolveOccurredAt(out var derivedFromClock); + + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["subSource"] = "ProvisioningStatusTracker", + ["deviceSetupResolved"] = deviceSetupResolved, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock); _ingress.Post( kind: DecisionSignalKind.DeviceSetupProvisioningComplete, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceOrigin, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: DetectorId, summary: "DeviceSetupCategory provisioning completed (coordinator-forwarded)", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["subSource"] = "ProvisioningStatusTracker", - ["deviceSetupResolved"] = deviceSetupResolved, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { ["deviceSetupResolved"] = deviceSetupResolved, diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index 177d761c..e74135a5 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -218,6 +218,64 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters internal void TriggerDoTelemetryFromTest(AppPackageState app) => EmitDoTelemetry(app); internal void TriggerScriptCompletedFromTest(ScriptExecutionState script) => EmitScriptCompleted(script); + /// + /// Prefer the CMTrace log entry timestamp recorded by the most recent pattern match + /// over . Replay scenario (agent first boot reads + /// accumulated IME log content) needs the historical timestamp so the timeline shows + /// when activity actually happened, not when the agent woke up. Falls back to the + /// clock when no source timestamp is available (synthetic test events, callbacks not + /// driven by a pattern match). The fallback case sets + /// so the emitted event can flag itself as not-source-grounded for the Inspector. + /// + /// Clamping: a source timestamp older than 24 h relative to the clock is treated as + /// pathological (skewed CMTrace clock, multi-day stale log) — the fallback to + /// kicks in and derivedFromClock is set so the + /// anomaly is visible. Original value is recorded in the + /// out param so the emit-site can attach it as + /// evidence (PR4 — preserve originals + flag for troubleshooting). + /// + /// + private DateTime ResolveOccurredAt(out bool derivedFromClock, out DateTime? rawSourceTimestamp) + { + rawSourceTimestamp = _tracker.LastMatchedLogTimestamp; + if (rawSourceTimestamp.HasValue) + { + // CMTrace log timestamps from IME are emitted in UTC, but DateTimeKind may + // arrive as Unspecified depending on the parser path. Normalize via + // SpecifyKind=Utc rather than ToUniversalTime() to avoid double-conversion + // when Kind is already UTC. + var asUtc = rawSourceTimestamp.Value.Kind == DateTimeKind.Utc + ? rawSourceTimestamp.Value + : DateTime.SpecifyKind(rawSourceTimestamp.Value, DateTimeKind.Utc); + + var clockNow = _clock.UtcNow; + var ageHours = (clockNow - asUtc).TotalHours; + if (ageHours > 24.0 || ageHours < -1.0) + { + // Pathologically stale (>24h old) or in the future (>1h skew) — log, + // fall back, and let the caller flag the event. + _logger?.Warning( + $"ImeAdapter: source timestamp {asUtc:o} rejected (ageHours={ageHours:F1}); falling back to clock"); + derivedFromClock = true; + return clockNow; + } + + derivedFromClock = false; + return asUtc; + } + + derivedFromClock = true; + return _clock.UtcNow; + } + + private static void TagDerivedTimestamp(IDictionary data, bool derivedFromClock, DateTime? rawSourceTs) + { + if (!derivedFromClock) return; + data["derivedTimestamp"] = "true"; + if (rawSourceTs.HasValue) + data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture); + } + private void EmitEspPhase(string phase) { if (string.IsNullOrEmpty(phase)) return; @@ -231,7 +289,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters _lastEspPhase = phase; } - var now = _clock.UtcNow; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["detectionSource"] = "IME log regex pattern", + ["phase"] = phase, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock, rawSourceTs); _ingress.Post( kind: DecisionSignalKind.EspPhaseChanged, @@ -241,11 +306,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters kind: EvidenceKind.Derived, identifier: "ime-log-tracker-v1", summary: $"IME log phase transition → {phase}", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["detectionSource"] = "IME log regex pattern", - ["phase"] = phase, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { [SignalPayloadKeys.EspPhase] = phase, @@ -262,6 +323,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); _post.Emit( eventType: SharedEventTypes.EspPhaseChanged, @@ -286,7 +348,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters _userSessionCompletedPosted = true; } - var now = _clock.UtcNow; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["detectionSource"] = "IME log pattern (UserSessionCompleted)", + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock, rawSourceTs); _ingress.Post( kind: DecisionSignalKind.ImeUserSessionCompleted, @@ -296,10 +364,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters kind: EvidenceKind.Derived, identifier: "ime-log-tracker-v1", summary: "IME user session completed (all user-scope apps finished)", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["detectionSource"] = "IME log pattern (UserSessionCompleted)", - })); + derivationInputs: derivationInputs)); var data = new Dictionary(StringComparer.Ordinal) { @@ -308,6 +373,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); _post.Emit( eventType: SharedEventTypes.ImeUserSessionCompleted, @@ -324,7 +390,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters { if (app == null || string.IsNullOrEmpty(app.Id)) return; - var now = _clock.UtcNow; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); // Plan §5 Fix 2: first app activity in a given ESP phase opens the sub-phase on // the UI timeline via a `phase_transition` declaration event. Fire-once per ESP @@ -348,6 +414,15 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters if (fireDecisionSignal) { + var appDerivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["appId"] = app.Id, + ["appName"] = app.Name ?? string.Empty, + ["previousState"] = oldState.ToString(), + ["newState"] = newState.ToString(), + }; + TagDerivedTimestamp(appDerivationInputs, derivedFromClock, rawSourceTs); + _ingress.Post( kind: terminalKind.Value, occurredAtUtc: now, @@ -356,13 +431,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters kind: EvidenceKind.Derived, identifier: "ime-log-tracker-v1", summary: $"App {app.Id} → {newState}", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["appId"] = app.Id, - ["appName"] = app.Name ?? string.Empty, - ["previousState"] = oldState.ToString(), - ["newState"] = newState.ToString(), - }), + derivationInputs: appDerivationInputs), payload: new Dictionary(StringComparer.Ordinal) { ["appId"] = app.Id, @@ -377,6 +446,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var (eventType, severity) = mapped.Value; var payload = BuildAppStatePayload(app, newState, timing); + TagDerivedTimestamp(payload, derivedFromClock, rawSourceTs); // All app-state transitions flush immediately, including `download_progress`: // progress ticks run every 3s and only while a download is actively in flight // (bounded by download duration), so live UI responsiveness wins over the small @@ -549,19 +619,23 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters _sealingPatternPosted = true; } + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + var derivationInputs = new Dictionary(StringComparer.Ordinal) + { + ["detectionSource"] = "IME log regex pattern (WG-sealing set)", + [SignalPayloadKeys.ImePatternId] = patternId, + }; + TagDerivedTimestamp(derivationInputs, derivedFromClock, rawSourceTs); + _ingress.Post( kind: DecisionSignalKind.WhiteGloveSealingPatternDetected, - occurredAtUtc: _clock.UtcNow, + occurredAtUtc: now, sourceOrigin: SourceLabel, evidence: new Evidence( kind: EvidenceKind.Derived, identifier: "ime-log-tracker-v1", summary: $"WG sealing pattern match → {patternId}", - derivationInputs: new Dictionary(StringComparer.Ordinal) - { - ["detectionSource"] = "IME log regex pattern (WG-sealing set)", - [SignalPayloadKeys.ImePatternId] = patternId, - }), + derivationInputs: derivationInputs), payload: new Dictionary(StringComparer.Ordinal) { [SignalPayloadKeys.ImePatternId] = patternId, @@ -575,6 +649,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters { if (string.IsNullOrEmpty(version)) return; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); var data = new Dictionary(StringComparer.Ordinal) { ["agentVersion"] = version, @@ -582,13 +657,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); _post.Emit( eventType: SharedEventTypes.ImeAgentVersion, source: SourceLabel, message: $"IME Agent version: {version}", data: data, - occurredAtUtc: _clock.UtcNow); + occurredAtUtc: now); // PR3-D4: fire-once and useful for compatibility-debugging — INFO level. _logger?.Info($"ImeAdapter: IME agent version detected: {version}"); @@ -627,6 +703,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); + var label = string.IsNullOrEmpty(app.Name) ? app.Id : app.Name; var msg = $"{label}: DO complete - {app.DoPercentPeerCaching}% peers, mode={app.DoDownloadMode}"; @@ -638,7 +717,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters // the UI sees peer-caching stats without waiting for the next batch. immediateUpload: true, data: data, - occurredAtUtc: _clock.UtcNow); + occurredAtUtc: now); // PR3-D4: per-app DO summary at DEBUG with the headline metrics. _logger?.Debug( @@ -670,6 +749,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters var patternId = _tracker.LastMatchedPatternId; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; + var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); + TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); + var label = IsRemediation(script.ScriptType) ? "Remediation script" : "Platform script"; var shortId = script.PolicyId.Length >= 8 ? script.PolicyId.Substring(0, 8) : script.PolicyId; string messageCore; @@ -694,7 +776,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters message: msg, severity: severity, data: data, - occurredAtUtc: _clock.UtcNow); + occurredAtUtc: now); // PR3-D4: per-script summary at DEBUG (failures already surface via Severity=Error // in the event itself; the log line carries forensic context for both outcomes). @@ -814,7 +896,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters return $"{label}: {newState}"; } - private static IReadOnlyDictionary BuildAppStatePayload( + private static Dictionary BuildAppStatePayload( AppPackageState app, AppInstallationState newState, AppInstallTiming timing) diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt index 85c3d27e..924a9261 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt @@ -1 +1 @@ -602 +606 diff --git a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt index 6bbc2a3c..837dd962 100644 --- a/src/Agent/AutopilotMonitor.Agent/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent/buildcounter.txt @@ -1 +1 @@ -1257 +1258 diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/BootAnchorDeadlineFloorTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/BootAnchorDeadlineFloorTests.cs new file mode 100644 index 00000000..d480dd0d --- /dev/null +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/BootAnchorDeadlineFloorTests.cs @@ -0,0 +1,172 @@ +using System; +using System.Collections.Generic; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using AutopilotMonitor.DecisionCore.State; +using Xunit; + +namespace AutopilotMonitor.DecisionCore.Tests +{ + /// + /// Replay-safety regression: when the agent reads accumulated CMTrace / Shell-Core log + /// content on first boot, signals carry historical OccurredAtUtc values that + /// would otherwise drive the reducer to arm deadlines already in the past — collapsing + /// the Hello-safety window, the device-only ESP detection window, and the FinalizingGrace + /// window to immediate fires. floors + /// the arming base at ; this suite locks every + /// affected reducer site against a regression that bypasses the helper. + /// + public sealed class BootAnchorDeadlineFloorTests + { + private static readonly DateTime LogPast = new DateTime(2026, 4, 20, 9, 30, 0, DateTimeKind.Utc); + private static readonly DateTime AgentBoot = new DateTime(2026, 4, 20, 10, 0, 0, DateTimeKind.Utc); + + private static DecisionState FreshAtBoot() => + DecisionState.CreateInitial("sess-boot", "tenant-boot", AgentBoot); + + 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, $"replay-{kind}-{ordinal}", "synthetic"), + payload: payload); + + [Fact] + public void HelloSafety_armed_from_replayed_EspExiting_floors_at_AgentBootUtc() + { + // Setup: state already in EspAccountSetup so EspExiting takes the AwaitingHello + // path. Build it with a non-replayed AccountSetup signal so the boot-anchor floor + // only matters for the EspExiting arming step. + var engine = new DecisionEngine(); + var state = FreshAtBoot(); + state = engine.Reduce(state, + MakeSignal(0, DecisionSignalKind.SessionStarted, AgentBoot)).NewState; + state = engine.Reduce(state, + MakeSignal(1, DecisionSignalKind.EspPhaseChanged, AgentBoot.AddSeconds(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + + // Replayed CMTrace EspExiting from before the agent booted. + var replayed = MakeSignal(2, DecisionSignalKind.EspExiting, LogPast); + var step = engine.Reduce(state, replayed); + + var helloSafety = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.HelloSafety); + // Without the floor: dueAt = LogPast + 300s = 9:35 (past-due → fires immediately). + // With the floor: dueAt = AgentBoot + 300s = 10:05 (the proper grace window). + Assert.Equal(AgentBoot.AddSeconds(300), helloSafety.DueAtUtc); + } + + [Fact] + public void DeviceOnlyEspDetection_armed_from_replayed_DeviceSetup_floors_at_AgentBootUtc() + { + var engine = new DecisionEngine(); + var state = FreshAtBoot(); + state = engine.Reduce(state, + MakeSignal(0, DecisionSignalKind.SessionStarted, AgentBoot)).NewState; + + // Replayed DeviceSetup phase change carrying a 30-min-old CMTrace timestamp. + var replayed = MakeSignal(1, DecisionSignalKind.EspPhaseChanged, LogPast, + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" }); + var step = engine.Reduce(state, replayed); + + var devOnly = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.DeviceOnlyEspDetection); + // Without the floor: dueAt = LogPast + 5min = 9:35 → fires immediately, classifier + // promotes DeviceOnlyDeployment to Strong. With the floor: dueAt = AgentBoot + 5min. + Assert.Equal(AgentBoot.AddMinutes(5), devOnly.DueAtUtc); + } + + [Fact] + public void FinalizingGrace_armed_from_replayed_HelloDesktop_pair_floors_at_AgentBootUtc() + { + // Drive state to AwaitingHello via current-clock signals, then deliver a replayed + // HelloResolved + DesktopArrived pair from log-tail. The TransitionToFinalizing + // path arms FinalizingGrace; without the floor that fires immediately and emits + // a premature enrollment_complete on agent boot. + var engine = new DecisionEngine(); + var state = FreshAtBoot(); + state = engine.Reduce(state, + MakeSignal(0, DecisionSignalKind.SessionStarted, AgentBoot)).NewState; + state = engine.Reduce(state, + MakeSignal(1, DecisionSignalKind.EspPhaseChanged, AgentBoot.AddSeconds(1), + new Dictionary { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState; + state = engine.Reduce(state, + MakeSignal(2, DecisionSignalKind.EspExiting, AgentBoot.AddSeconds(2))).NewState; + + // Replayed HelloResolved (parks in AwaitingDesktop) and replayed DesktopArrived + // (drives Finalizing — this is the deadline-arming site we're testing). + state = engine.Reduce(state, + MakeSignal(3, DecisionSignalKind.HelloResolved, LogPast, + new Dictionary { [SignalPayloadKeys.HelloOutcome] = "Success" })).NewState; + var step = engine.Reduce(state, + MakeSignal(4, DecisionSignalKind.DesktopArrived, LogPast.AddSeconds(1))); + + Assert.Equal(SessionStage.Finalizing, step.NewState.Stage); + var grace = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.FinalizingGrace); + // Without the floor: dueAt = LogPast + 5s → fires immediately, premature complete. + // With the floor: dueAt = AgentBoot + 5s. + Assert.Equal(AgentBoot.AddSeconds(5), grace.DueAtUtc); + } + + [Fact] + public void Live_signal_after_boot_uses_signalOccurredAtUtc_not_AgentBootUtc() + { + // Sanity: the floor is one-sided. A signal whose OccurredAtUtc is *after* the + // boot anchor gets its raw timestamp through — the floor only kicks in when the + // signal is older than the boot. + var engine = new DecisionEngine(); + var state = FreshAtBoot(); + state = engine.Reduce(state, + MakeSignal(0, DecisionSignalKind.SessionStarted, AgentBoot)).NewState; + + var liveAfterBoot = AgentBoot.AddMinutes(2); + var step = engine.Reduce(state, + MakeSignal(1, DecisionSignalKind.EspPhaseChanged, liveAfterBoot, + new Dictionary { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })); + + var devOnly = Assert.Single(step.NewState.Deadlines, d => d.Name == DeadlineNames.DeviceOnlyEspDetection); + Assert.Equal(liveAfterBoot.AddMinutes(5), devOnly.DueAtUtc); + } + + [Fact] + public void Legacy_state_with_null_AgentBootUtc_falls_back_to_signalOccurredAtUtc() + { + // Backward-compat: snapshots from before this field existed deserialize with + // AgentBootUtc=null. The helper must fall back to signal.OccurredAtUtc so legacy + // sessions reproduce their pre-fix deadline values exactly (no replay correction). + var engine = new DecisionEngine(); + var legacy = new DecisionState( + sessionId: "sess-legacy", + tenantId: "tenant-legacy", + stage: SessionStage.SessionStarted, + outcome: null, + currentEnrollmentPhase: null, + deviceSetupEnteredUtc: null, + accountSetupEnteredUtc: null, + finalizingEnteredUtc: null, + espFinalExitUtc: null, + desktopArrivedUtc: null, + helloResolvedUtc: null, + systemRebootUtc: null, + helloOutcome: null, + imeMatchedPatternId: null, + deadlines: Array.Empty(), + lastAppliedSignalOrdinal: -1, + stepIndex: 0, + agentBootUtc: null); + + var step = engine.Reduce(legacy, + MakeSignal(0, DecisionSignalKind.SessionStarted, LogPast)); + var tick = Assert.Single(step.NewState.Deadlines); + + Assert.Null(step.NewState.AgentBootUtc); + Assert.Equal(LogPast.AddSeconds(30), tick.DueAtUtc); + } + } +} diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassifierTickFromSessionStartTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassifierTickFromSessionStartTests.cs index 39af8c67..b9bca18e 100644 --- a/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassifierTickFromSessionStartTests.cs +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassifierTickFromSessionStartTests.cs @@ -16,11 +16,17 @@ namespace AutopilotMonitor.DecisionCore.Tests { private static readonly DateTime SessionStartUtc = new DateTime(2026, 4, 20, 10, 0, 0, DateTimeKind.Utc); + // Pass SessionStartUtc as the agent-boot anchor so the EffectiveDeadlineBase guard + // doesn't floor signal-time-based deadlines at the test runner's wall-clock now + // (which would always be later than the deterministic SessionStartUtc constant). + private static DecisionState FreshState() => + DecisionState.CreateInitial("s", "t", SessionStartUtc); + [Fact] public void SessionStarted_from_fresh_state_arms_ClassifierTick_deadline() { var engine = new DecisionEngine(); - var state = DecisionState.CreateInitial("s", "t"); + var state = FreshState(); var step = engine.Reduce(state, MakeSessionStarted(ordinal: 0)); @@ -35,7 +41,7 @@ namespace AutopilotMonitor.DecisionCore.Tests // Plan §2.6 — deadline dueAt is deterministic from the triggering signal's // OccurredAtUtc, not from clock.UtcNow. Replay must reproduce it. var engine = new DecisionEngine(); - var state = DecisionState.CreateInitial("s", "t"); + var state = FreshState(); var step = engine.Reduce(state, MakeSessionStarted(ordinal: 0)); var tick = step.NewState.Deadlines[0]; @@ -50,7 +56,7 @@ namespace AutopilotMonitor.DecisionCore.Tests public void SessionStarted_emits_ScheduleDeadline_effect_for_ClassifierTick() { var engine = new DecisionEngine(); - var state = DecisionState.CreateInitial("s", "t"); + var state = FreshState(); var step = engine.Reduce(state, MakeSessionStarted(ordinal: 0)); @@ -68,7 +74,7 @@ namespace AutopilotMonitor.DecisionCore.Tests // Plan §2.5 — dead-end branch (replay of truncated log, session already mid-flight) // must not reset state; specifically, no new deadline. var engine = new DecisionEngine(); - var active = DecisionState.CreateInitial("s", "t") + var active = FreshState() .ToBuilder() .WithStage(SessionStage.AwaitingHello) .WithStepIndex(5) @@ -89,7 +95,7 @@ namespace AutopilotMonitor.DecisionCore.Tests // re-arms. Wiring depends only on the generic DeadlineFired dispatcher + the // existing HandleClassifierTickDeadlineFired handler from M3.3+. var engine = new DecisionEngine(); - var state = DecisionState.CreateInitial("s", "t"); + var state = FreshState(); var startStep = engine.Reduce(state, MakeSessionStarted(ordinal: 0)); Assert.Single(startStep.NewState.Deadlines); diff --git a/src/Agent/AutopilotMonitor.DecisionCore.Tests/FinalizingStageTests.cs b/src/Agent/AutopilotMonitor.DecisionCore.Tests/FinalizingStageTests.cs index 686ea6bf..ec68252e 100644 --- a/src/Agent/AutopilotMonitor.DecisionCore.Tests/FinalizingStageTests.cs +++ b/src/Agent/AutopilotMonitor.DecisionCore.Tests/FinalizingStageTests.cs @@ -23,7 +23,9 @@ namespace AutopilotMonitor.DecisionCore.Tests { // Build a state where ESP has reached AccountSetup, EspExiting arrived, Hello has // already resolved — the reducer parks in AwaitingDesktop waiting for the desktop. - var state = DecisionState.CreateInitial("sess-fin", "tenant-fin"); + // Pass T0 as the agent-boot anchor so the EffectiveDeadlineBase guard doesn't + // floor the deterministic T0-based deadline math at the test runner's wall clock. + var state = DecisionState.CreateInitial("sess-fin", "tenant-fin", T0); state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0, null)).NewState; state = engine.Reduce(state, MakeSignal(1, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(1), diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Classic.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Classic.cs index 7713cb55..2ea6e231 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Classic.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Classic.cs @@ -83,11 +83,15 @@ namespace AutopilotMonitor.DecisionCore.Engine // Device-Only ESP detection (plan §2.7): arm on first DeviceSetup, cancel on AccountSetup. // See DecisionEngine.SelfDeploying.cs for the deadline-fired handler. + // EffectiveDeadlineBase floors the 5-min window at AgentBootUtc so a replayed + // DeviceSetup signal from an older CMTrace log entry doesn't collapse the deadline + // to immediate-fire — that would mark a perfectly normal Classic enrollment as + // device-only at boot (premature classifier promotion to DeviceOnly@Strong). var effectsList = new List(); if (enrollmentPhase == EnrollmentPhase.DeviceSetup && state.DeviceSetupEnteredUtc == null) { - var devOnlyDl = BuildDeviceOnlyEspDetectionDeadline(signal.OccurredAtUtc); + var devOnlyDl = BuildDeviceOnlyEspDetectionDeadline(EffectiveDeadlineBase(state, signal)); builder.AddDeadline(devOnlyDl); effectsList.Add(new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: devOnlyDl)); } @@ -155,7 +159,10 @@ namespace AutopilotMonitor.DecisionCore.Engine return new DecisionStep(builder.Build(), noopTransition, Array.Empty()); } - var dueAtUtc = signal.OccurredAtUtc.Add(s_helloSafetyWindow); + // Replay-safety: floor the 300-s Hello-safety window at AgentBootUtc so a replayed + // EspExiting signal from CMTrace doesn't fire HelloSafety immediately at boot + // (which would mark Hello as Timeout the moment the agent reads the log tail). + var dueAtUtc = EffectiveDeadlineBase(state, signal).Add(s_helloSafetyWindow); var helloSafety = new ActiveDeadline( name: DeadlineNames.HelloSafety, dueAtUtc: dueAtUtc, @@ -378,7 +385,10 @@ namespace AutopilotMonitor.DecisionCore.Engine int nextStepIndex, string trigger) { - var dueAtUtc = signal.OccurredAtUtc.Add(s_finalizingGraceWindow); + // Replay-safety: floor the 5-s grace window at AgentBootUtc so a replayed Hello/ + // Desktop signal pair doesn't drive an immediate enrollment_complete the moment + // the agent boots and reads accumulated logs. + var dueAtUtc = EffectiveDeadlineBase(state, signal).Add(s_finalizingGraceWindow); var deadline = new ActiveDeadline( name: DeadlineNames.FinalizingGrace, dueAtUtc: dueAtUtc, diff --git a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs index d7982938..d4520dc4 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs @@ -51,7 +51,9 @@ namespace AutopilotMonitor.DecisionCore.Engine // Arm ClassifierTick up-front so the White-Glove classifier re-evaluates // periodically from the very start of the session — Plan §4.x M4.4.4. - var classifierTick = BuildClassifierTickDeadline(signal.OccurredAtUtc); + // Floor the base at AgentBootUtc to keep the tick anchored to "now" even when + // SessionStarted itself ever carries a replayed historical timestamp. + var classifierTick = BuildClassifierTickDeadline(EffectiveDeadlineBase(state, signal)); // V2 race-fix (10c8e0bf debrief, 2026-04-26): SessionStarted is now a pure // lifecycle anchor (stage / classifier-tick deadline / step bookkeeping). @@ -689,6 +691,29 @@ namespace AutopilotMonitor.DecisionCore.Engine return false; } + /// + /// Floor a deadline-arming base timestamp at the current agent run's boot anchor. + /// Replay-safety guard: when a signal carries a historical OccurredAtUtc from + /// a CMTrace log entry or backfilled event-log record, naively using it as + /// dueAtUtc = signal.OccurredAtUtc + window would produce a past-due deadline + /// that the scheduler fires immediately, collapsing real-time semantics (Hello timeout, + /// device-only ESP detection, finalizing grace) into "agent woke up just now and + /// everything already expired". + /// + /// Returns signal.OccurredAtUtc when it is at or after + /// , otherwise the boot anchor. Falls back to + /// the raw signal time when the state has no boot anchor (legacy snapshots from + /// before this field existed) — preserves the prior, pre-fix behavior on those. + /// + /// + internal static DateTime EffectiveDeadlineBase(DecisionState state, DecisionSignal signal) + { + var boot = state.AgentBootUtc; + if (boot.HasValue && signal.OccurredAtUtc < boot.Value) + return boot.Value; + 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 4f855811..02a13b2a 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs @@ -281,7 +281,12 @@ namespace AutopilotMonitor.DecisionCore.Engine if (!reachedTerminal) { - var rearm = BuildClassifierTickDeadline(signal.OccurredAtUtc); + // 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. + var rearm = BuildClassifierTickDeadline(EffectiveDeadlineBase(state, signal)); builder.AddDeadline(rearm); effects.Add(new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: rearm)); } @@ -319,7 +324,10 @@ namespace AutopilotMonitor.DecisionCore.Engine if (!hasTick) { - var tick = BuildClassifierTickDeadline(triggerSignal.OccurredAtUtc); + // Replay-safety: a WG-relevant signal coming from a CMTrace replay would + // otherwise arm the first classifier tick in the past — fires immediately, + // pulls in a stale snapshot, no real harm but pollutes the timeline. + var tick = BuildClassifierTickDeadline(EffectiveDeadlineBase(state, triggerSignal)); state = state.ToBuilder().AddDeadline(tick).Build(); effects.Add(new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: tick)); } diff --git a/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionState.cs b/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionState.cs index 3498e078..88e9dd69 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionState.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionState.cs @@ -55,6 +55,7 @@ namespace AutopilotMonitor.DecisionCore.State EnrollmentScenarioObservations? scenarioObservations = null, ClassifierOutcomes? classifierOutcomes = null, SignalFact? helloPolicyEnabled = null, + DateTime? agentBootUtc = null, string? schemaVersion = null) { if (string.IsNullOrEmpty(sessionId)) @@ -89,6 +90,7 @@ namespace AutopilotMonitor.DecisionCore.State ScenarioObservations = scenarioObservations ?? EnrollmentScenarioObservations.Empty; ClassifierOutcomes = classifierOutcomes ?? ClassifierOutcomes.Empty; HelloPolicyEnabled = helloPolicyEnabled; + AgentBootUtc = agentBootUtc; SchemaVersion = schemaVersion ?? CurrentSchemaVersion; } @@ -170,6 +172,21 @@ namespace AutopilotMonitor.DecisionCore.State /// public SignalFact? HelloPolicyEnabled { get; } + /// + /// UTC wall-clock instant at which the current agent process took ownership of this + /// session. Set by on first construction and re-stamped + /// by the orchestrator on rehydration so deadline-arming sites in the reducer can + /// floor their effective base at this anchor — preventing replayed signals from + /// historical log entries from collapsing window/timeout deadlines into immediate + /// fires when the agent first reads accumulated content. + /// + /// Null means "agent never declared a boot anchor" — only possible on legacy + /// snapshots from before this field existed; the deadline helper falls back to + /// signal.OccurredAtUtc in that case (i.e. previous behavior). + /// + /// + public DateTime? AgentBootUtc { get; } + public string SchemaVersion { get; } /// @@ -179,11 +196,27 @@ namespace AutopilotMonitor.DecisionCore.State /// public DecisionStateBuilder ToBuilder() => new DecisionStateBuilder(this); + /// + /// Convenience overload — defaults 's boot anchor to + /// . Used by tests and code paths that don't care about + /// replay-safety. Production callers (orchestrator, recovery) should use the explicit + /// overload so the boot anchor + /// is sourced from the agent's IClock. + /// + public static DecisionState CreateInitial(string sessionId, string tenantId) => + CreateInitial(sessionId, tenantId, DateTime.UtcNow); + /// /// Construct the initial non-terminal state for a new session. /// Used by the reducer's SessionStarted handler in M3. /// - public static DecisionState CreateInitial(string sessionId, string tenantId) => + /// + /// Wall-clock instant at which the current agent process started owning this session. + /// Stamped onto so the reducer can floor deadline-arming + /// timestamps at this anchor (replay-safety). Production callers must source this + /// from the same IClock the orchestrator uses. + /// + public static DecisionState CreateInitial(string sessionId, string tenantId, DateTime agentBootUtc) => new DecisionState( sessionId: sessionId, tenantId: tenantId, @@ -206,6 +239,7 @@ namespace AutopilotMonitor.DecisionCore.State scenarioProfile: EnrollmentScenarioProfile.Empty, scenarioObservations: EnrollmentScenarioObservations.Empty, classifierOutcomes: ClassifierOutcomes.Empty, - helloPolicyEnabled: null); + helloPolicyEnabled: null, + agentBootUtc: agentBootUtc); } } diff --git a/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionStateBuilder.cs b/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionStateBuilder.cs index 8e6107ad..761a0da0 100644 --- a/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionStateBuilder.cs +++ b/src/Shared/AutopilotMonitor.DecisionCore/State/DecisionStateBuilder.cs @@ -41,6 +41,7 @@ namespace AutopilotMonitor.DecisionCore.State ScenarioObservations = source.ScenarioObservations; ClassifierOutcomes = source.ClassifierOutcomes; HelloPolicyEnabled = source.HelloPolicyEnabled; + AgentBootUtc = source.AgentBootUtc; SchemaVersion = source.SchemaVersion; } @@ -66,6 +67,7 @@ namespace AutopilotMonitor.DecisionCore.State public EnrollmentScenarioObservations ScenarioObservations { get; set; } = EnrollmentScenarioObservations.Empty; public ClassifierOutcomes ClassifierOutcomes { get; set; } = ClassifierOutcomes.Empty; public SignalFact? HelloPolicyEnabled { get; set; } + public DateTime? AgentBootUtc { get; set; } public string SchemaVersion { get; set; } // ---------- fluent helpers for the most common reducer operations ---------- @@ -143,6 +145,17 @@ namespace AutopilotMonitor.DecisionCore.State return this; } + /// + /// Re-stamp the agent-boot anchor used for deadline arming. Called by the orchestrator + /// on rehydration so deadlines armed by replayed signals get floored at "now" (the + /// current run's boot time) rather than the prior session's boot time. + /// + public DecisionStateBuilder WithAgentBootUtc(DateTime agentBootUtc) + { + AgentBootUtc = agentBootUtc; + return this; + } + public DecisionState Build() => new DecisionState( sessionId: SessionId, @@ -167,6 +180,7 @@ namespace AutopilotMonitor.DecisionCore.State scenarioObservations: ScenarioObservations, classifierOutcomes: ClassifierOutcomes, helloPolicyEnabled: HelloPolicyEnabled, + agentBootUtc: AgentBootUtc, schemaVersion: SchemaVersion); } }