gsadmin/AutopilotMonitor
1
0
Fork 0
mirror of https://github.com/okieselbach/AutopilotMonitor.git synced 2026-10-24 20:53:06 +00:00
Code Issues Packages Projects Releases Wiki Activity

fix(v2): preserve source timestamps + boot-anchor deadline math

Browse Source 
Replay-safety fix for two related defects that surface when the agent
reads accumulated CMTrace / Shell-Core log content on first boot
(per-enrollment lifecycle, fresh install).

PR1 — IME adapter (SignalAdapters/ImeLogTrackerAdapter.cs)
  Every emit site (EspPhaseChanged, AppState, UserSessionCompleted,
  WhiteGloveSealing, ImeAgentVersion, DoTelemetry, ScriptCompleted)
  now stamps DecisionSignal.OccurredAtUtc and the InformationalEvent
  with the CMTrace log entry timestamp the tracker captures into
  LastMatchedLogTimestamp. Falls back to clock when no source time is
  available; tags the event with derivedTimestamp=true on fallback.
  Pathological clamp: source TS older than 24h or in the future >1h
  is rejected, original preserved as rejectedSourceTimestamp.

PR2 — Shell-Core backfill + EspAndHelloTrackerAdapter
  ShellCoreTracker.HandleBackfillRecord now propagates record.TimeCreated
  via a new LastEventOccurredAtUtc property on the tracker; the
  EspAndHelloTracker coordinator mirrors this property in its event
  forwarders. EspAndHelloTrackerAdapter reads the coordinator value at
  every Post site (HelloResolved, FinalizingSetup, WhiteGloveSuccess,
  EspTerminalFailure, DeviceSetupComplete, HelloPolicyDetected) so
  backfilled events carry source time, not "agent woke up just now".

PR3 — DecisionState.AgentBootUtc + boot-anchor guard
  Without this guard, PR1+PR2 are a footgun: replayed signals carry
  historical timestamps, and the reducer sites that arm deadlines as
  signal.OccurredAtUtc + window would produce due-times in the past,
  collapsing the Hello-safety window, device-only ESP detection,
  finalizing grace, and classifier-tick to immediate fires at boot.

  Added DecisionState.AgentBootUtc + DecisionEngine.EffectiveDeadlineBase
  helper that floors the arming base at the boot anchor. Applied at all
  six reducer sites (HelloSafety, DeviceOnlyEspDetection, FinalizingGrace,
  ClassifierTick @ SessionStarted + AttachWG + re-arm).

  EnrollmentOrchestrator.Start() stamps AgentBootUtc from the live IClock
  on initial state and re-stamps it on snapshot rehydration so the prior
  run's anchor doesn't bleed into deadline math after restart. Backward
  compat: legacy snapshots without the field deserialize with null and
  fall back to signal.OccurredAtUtc — pre-fix behavior preserved.

Tests: 287/287 DecisionCore + 1007/1007 V2.Core + 862/862 Functions +
530/530 Agent.Core. New: BootAnchorDeadlineFloorTests (5) +
ImeLogTrackerAdapterSourceTimestampTests (6).

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-05-04 20:24:24 +02:00
parent 84610f9fb0
commit 0687612a96
17 changed files with 734 additions and 107 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterSourceTimestampTests.cs
+152
View File
@@ -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
{
/// <summary>
/// Replay-safety regression: when <c>ImeLogTracker</c> processes a CMTrace log entry it
/// stamps <see cref="Monitoring.Enrollment.Ime.ImeLogTracker.LastMatchedLogTimestamp"/>
/// with the source-line time. The adapter must use that timestamp on both the emitted
/// <see cref="DecisionSignal"/> and the corresponding informational event — collapsing
/// to <c>_clock.UtcNow</c> would lose forensic time on agent first-boot replay.
/// <para>
/// Pathological-clock guard: a source timestamp older than 24h or in the future by &gt;1h
/// is rejected; the adapter falls back to the clock and tags the event with
/// <c>derivedTimestamp=true</c> + <c>rejectedSourceTimestamp=&lt;original&gt;</c> so the
/// anomaly is forensically visible (per <c>feedback_timestamp_clamping</c>).
/// </para>
/// </summary>
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);
}
}
}
src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs
+5 -3
View File
@@ -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<string> OnEspPhaseChanged { get; set; }
src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/EspAndHelloTracker.cs
+31
View File
@@ -85,6 +85,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
// DecisionSignalKind.HelloPolicyDetected signal.
public event Action<bool, string> HelloPolicyDetected;
/// <summary>
/// UTC timestamp of the most recent sub-tracker event currently being raised
/// (mirrored from <see cref="ShellCoreTracker.LastEventOccurredAtUtc"/> for ShellCore-
/// originated events). Read by <c>EspAndHelloTrackerAdapter</c> 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).
/// </summary>
public DateTime? LastEventOccurredAtUtc { get; private set; }
/// <summary>
/// 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; }
}
/// <summary>
@@ -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); }
}
src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ShellCoreTracker.cs
+53 -21
View File
@@ -47,6 +47,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
private bool _whiteGloveDetected;
private readonly object _stateLock = new object();
/// <summary>
/// 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
/// <c>null</c> 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.
/// </summary>
public DateTime? LastEventOccurredAtUtc { get; private set; }
public event EventHandler<string> FinalizingSetupPhaseTriggered;
public event EventHandler WhiteGloveCompleted;
public event EventHandler<string> 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
/// <summary>
/// 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
/// <paramref name="occurredAtUtc"/> is the original Shell-Core event time
/// (<c>record.TimeCreated</c>); subscribers read it via
/// <see cref="LastEventOccurredAtUtc"/> during their synchronous event handler.
/// </summary>
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; }
}
}
src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/EnrollmentOrchestrator.cs
+8 -2
View File
@@ -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<DecisionSignal> signalsToReplay = Array.Empty<DecisionSignal>();
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";
}
src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/EspAndHelloTrackerAdapter.cs
+87 -36
View File
@@ -105,26 +105,58 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
/// <summary>Test-only hook to exercise <see cref="ReadHelloOutcome"/> + the full event-handler emit path without driving the inner HelloTracker's live event sources.</summary>
internal void TriggerHelloFromCoordinatorPropertyForTest() => EmitHello(ReadHelloOutcome());
/// <summary>
/// Resolve the timestamp to stamp on a coordinator-forwarded signal: prefer the
/// originating sub-tracker's source-event time (mirrored on
/// <see cref="EspAndHelloTracker.LastEventOccurredAtUtc"/>) over wall-clock-now.
/// Critical on the Shell-Core backfill path where reading <c>_clock.UtcNow</c> would
/// collapse historical event timestamps to "agent woke up just now". Emits
/// <c>derivedTimestamp=true</c> in the evidence inputs when falling back so the
/// Inspector can flag non-source-grounded signals.
/// </summary>
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<string, string> 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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["subSource"] = "HelloTracker",
[SignalPayloadKeys.HelloOutcome] = outcome,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["subSource"] = "ShellCoreTracker",
["phaseReason"] = reason ?? string.Empty,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["subSource"] = "ShellCoreTracker+ProvisioningStatusTracker (merged)",
["failureType"] = safeType,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["subSource"] = "HelloTracker",
[SignalPayloadKeys.HelloEnabled] = helloEnabledStr,
[SignalPayloadKeys.HelloPolicySource] = safeSource,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["subSource"] = "ProvisioningStatusTracker",
["deviceSetupResolved"] = deviceSetupResolved,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(StringComparer.Ordinal)
{
["deviceSetupResolved"] = deviceSetupResolved,
src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs
+111 -29
View File
@@ -218,6 +218,64 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
internal void TriggerDoTelemetryFromTest(AppPackageState app) => EmitDoTelemetry(app);
internal void TriggerScriptCompletedFromTest(ScriptExecutionState script) => EmitScriptCompleted(script);
/// <summary>
/// Prefer the CMTrace log entry timestamp recorded by the most recent pattern match
/// over <see cref="IClock.UtcNow"/>. 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 <paramref name="derivedFromClock"/>
/// so the emitted event can flag itself as not-source-grounded for the Inspector.
/// <para>
/// 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
/// <see cref="IClock.UtcNow"/> kicks in and <c>derivedFromClock</c> is set so the
/// anomaly is visible. Original value is recorded in the
/// <paramref name="rawSourceTimestamp"/> out param so the emit-site can attach it as
/// evidence (PR4 — preserve originals + flag for troubleshooting).
/// </para>
/// </summary>
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<string, string> 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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["detectionSource"] = "IME log regex pattern",
["phase"] = phase,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["detectionSource"] = "IME log pattern (UserSessionCompleted)",
}));
derivationInputs: derivationInputs));
var data = new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["appId"] = app.Id,
["appName"] = app.Name ?? string.Empty,
["previousState"] = oldState.ToString(),
["newState"] = newState.ToString(),
}),
derivationInputs: appDerivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string>(StringComparer.Ordinal)
{
["detectionSource"] = "IME log regex pattern (WG-sealing set)",
[SignalPayloadKeys.ImePatternId] = patternId,
}),
derivationInputs: derivationInputs),
payload: new Dictionary<string, string>(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<string, string>(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<string, string> BuildAppStatePayload(
private static Dictionary<string, string> BuildAppStatePayload(
AppPackageState app,
AppInstallationState newState,
AppInstallTiming timing)
src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt
+1 -1
View File
@@ -1 +1 @@
602
606
src/Agent/AutopilotMonitor.Agent/buildcounter.txt
+1 -1
View File
@@ -1 +1 @@
1257
1258
src/Agent/AutopilotMonitor.DecisionCore.Tests/BootAnchorDeadlineFloorTests.cs
+172
View File
@@ -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
{
/// <summary>
/// Replay-safety regression: when the agent reads accumulated CMTrace / Shell-Core log
/// content on first boot, signals carry historical <c>OccurredAtUtc</c> 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. <see cref="DecisionEngine.EffectiveDeadlineBase"/> floors
/// the arming base at <see cref="DecisionState.AgentBootUtc"/>; this suite locks every
/// affected reducer site against a regression that bypasses the helper.
/// </summary>
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<string, string>? 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<string, string> { [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<string, string> { [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<string, string> { [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<string, string> { [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<string, string> { [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<ActiveDeadline>(),
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);
}
}
}
src/Agent/AutopilotMonitor.DecisionCore.Tests/ClassifierTickFromSessionStartTests.cs
+11 -5
View File
@@ -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);
src/Agent/AutopilotMonitor.DecisionCore.Tests/FinalizingStageTests.cs
+3 -1
View File
@@ -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),
src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Classic.cs
+13 -3
View File
@@ -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<DecisionEffect>();
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<DecisionEffect>());
}
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,
src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.Shared.cs
+26 -1
View File
@@ -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;
}
/// <summary>
/// Floor a deadline-arming base timestamp at the current agent run's boot anchor.
/// Replay-safety guard: when a signal carries a historical <c>OccurredAtUtc</c> from
/// a CMTrace log entry or backfilled event-log record, naively using it as
/// <c>dueAtUtc = signal.OccurredAtUtc + window</c> 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".
/// <para>
/// Returns <c>signal.OccurredAtUtc</c> when it is at or after
/// <see cref="DecisionState.AgentBootUtc"/>, 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.
/// </para>
/// </summary>
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;
}
/// <summary>
/// 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.
src/Shared/AutopilotMonitor.DecisionCore/Engine/DecisionEngine.WhiteGlove.cs
+10 -2
View File
@@ -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));
}
src/Shared/AutopilotMonitor.DecisionCore/State/DecisionState.cs
+36 -2
View File
@@ -55,6 +55,7 @@ namespace AutopilotMonitor.DecisionCore.State
EnrollmentScenarioObservations? scenarioObservations = null,
ClassifierOutcomes? classifierOutcomes = null,
SignalFact<bool>? 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
/// </remarks>
public SignalFact<bool>? HelloPolicyEnabled { get; }
/// <summary>
/// UTC wall-clock instant at which the current agent process took ownership of this
/// session. Set by <see cref="CreateInitial"/> 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.
/// <para>
/// Null means "agent never declared a boot anchor" — only possible on legacy
/// snapshots from before this field existed; the deadline helper falls back to
/// <c>signal.OccurredAtUtc</c> in that case (i.e. previous behavior).
/// </para>
/// </summary>
public DateTime? AgentBootUtc { get; }
public string SchemaVersion { get; }
/// <summary>
@@ -179,11 +196,27 @@ namespace AutopilotMonitor.DecisionCore.State
/// </summary>
public DecisionStateBuilder ToBuilder() => new DecisionStateBuilder(this);
/// <summary>
/// Convenience overload — defaults <paramref name="sessionId"/>'s boot anchor to
/// <see cref="DateTime.UtcNow"/>. Used by tests and code paths that don't care about
/// replay-safety. Production callers (orchestrator, recovery) should use the explicit
/// <see cref="CreateInitial(string, string, DateTime)"/> overload so the boot anchor
/// is sourced from the agent's <c>IClock</c>.
/// </summary>
public static DecisionState CreateInitial(string sessionId, string tenantId) =>
CreateInitial(sessionId, tenantId, DateTime.UtcNow);
/// <summary>
/// Construct the initial non-terminal state for a new session.
/// Used by the reducer's <c>SessionStarted</c> handler in M3.
/// </summary>
public static DecisionState CreateInitial(string sessionId, string tenantId) =>
/// <param name="agentBootUtc">
/// Wall-clock instant at which the current agent process started owning this session.
/// Stamped onto <see cref="AgentBootUtc"/> so the reducer can floor deadline-arming
/// timestamps at this anchor (replay-safety). Production callers must source this
/// from the same <c>IClock</c> the orchestrator uses.
/// </param>
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);
}
}
src/Shared/AutopilotMonitor.DecisionCore/State/DecisionStateBuilder.cs
+14
View File
@@ -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<bool>? 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;
}
/// <summary>
/// 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.
/// </summary>
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);
}
}