Compare commits

...

4 Commits

Author SHA1 Message Date
Oliver Kieselbach 540f543834 feat(agent): extend historic IME-replay suppression to app events + app aggregation
Part 2 of the eaf3d8c4 fix (follows 088c3b04). In that session 147 of 157 app
events were replayed from a previous enrollment's IME log — all 10 "installed
apps" were phantoms, polluting the timeline, AppInstallSummaries, MCP counts,
the app_tracking_summary header, culprit lists and final-status.json.

Rename (nothing deployed yet): historic_script_replay_detected →
historic_ime_replay_detected; SuppressIfHistoricReplay / IsHistoricImeReplay.

Agent:
- EmitAppState suppresses stale-replay transitions BEFORE the sub-phase
  declaration, timing bookkeeping and terminal-signal dedup — covers the
  informational event, the AppInstallCompleted/Failed DecisionSignal, the
  shadow download_progress and the summary snapshot. Behavior note: phantom
  terminal signals can no longer spuriously re-arm the AdvisoryCompletion
  window (app signals are otherwise observation-only — verified no completion
  gate reads them). EmitDoTelemetry gets the same guard.
- Tracker-level guard at the HandlePatternMatch choke point skips the 23
  app-mutating actions (incl. espphasedetected — a stale AccountSetup line
  would make fresh DeviceSetup lines bounce as "backward") for source lines
  >24h stale, so replayed apps never enter PackageStates, persistence,
  app_tracking_summary, culprit lists or final-status. New internal
  UtcNowProvider seam (no ctor change), threshold single-sourced as
  ImeLogTracker.HistoricReplayThreshold.
- SimulationMode now bypasses all replay suppression — 088c3b04 had broken
  the --replay-log-dir dev tool, which feeds historic lines on purpose.

Backend: IsHistoricImeReplay guard in AggregateAppInstallEvent keeps replayed
events out of AppInstallSummaries (SLA/dashboards/metrics inherit).

Web: generic lib/historicReplay.ts partition (scriptExecutions becomes a
wrapper); InstallProgress hides replayed installs with a muted note;
DownloadProgress filters silently.

MCP: get_session_summary filters replayed events — cleans appInstalls stats,
errorCount (replayed app_install_failed are Error-severity) and keyEvents.

Tests: +13 agent (app suppression, tracker guard), +1 backend, +7 web,
+6 MCP. Agent 2039, backend 3211, web 602, MCP 455 all green; drift test
validates the rename.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-23 23:43:59 +02:00
Oliver Kieselbach 088c3b0479 fix(agent): suppress historic IME-log script replay + timeline-consistent durations
Session eaf3d8c4: a previous enrollment's IME logs survived on disk (dated
2026-07-16, 7 days old) and the agent replayed them at startup — 156 phantom
script_completed events in a 7-minute session, each showing ~170h durations
(clock-clamped completion minus RAW stale start), plus an immediateUpload
flood (3x ingress_backpressure) and RemediationScriptCount inflated to 156.

Agent:
- Script events whose source line is >24h stale are suppressed entirely; a
  one-shot historic_script_replay_detected Info event (new EventType) dates
  the replayed window via earliestRejectedSourceTimestamp. Future-skew
  rejections and clock-only fallbacks still emit.
- durationSeconds now uses a timeline-consistent pair: on rejected-timestamp
  emissions the raw source completion pairs with the raw start (true runtime
  instead of cross-timeline garbage). 24h plausibility backstop omits
  implausible values; same consistency for script_timeout_suspected.
- Stale pending platform-script slots (>24h older than the current start
  line) are discarded so an old orphaned start can't pair with a fresh run
  (extracted HandlePlatformScriptStarted as internal test seam).

Web: partitionHistoricScriptEvents hides legacy-agent replay events (muted
"N historic executions hidden" note) and the reducer blanks >24h durations —
covers sessions recorded before the agent fix rolls out.

Backend: IsHistoricScriptReplay guard keeps replayed events from inflating
Platform-/RemediationScriptCount during the rollout window.

Registered historic_script_replay_detected in Constants.EventTypes, MCP
resource-catalog (script_events) + KEY_EVENT_TYPES, gather-rules eventTypes.

Tests: 8 agent (suppression/one-shot/raw-pair/backstop/slot-hardening),
8 web (partition/blanking), 10 backend (predicate). Agent 2026, backend
3210, web 595, MCP 449 all green.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-23 18:39:11 +02:00
Oliver Kieselbach 3224774752 fix(test): EDR-safe straggler replay — no more renamed system executable
The straggler integration test copied powershell.exe under a synthetic
agent name and launched it — textbook MITRE T1036.003 ("Rename Legitimate
Utilities"). Defender for Endpoint flagged the run ("System executable
renamed and launched", initiating process testhost.net48.exe) and ISOLATED
the dev machine.

Replaced with function shadowing: a harness script defines Get-Process /
Stop-Process stub functions (PowerShell resolves functions before cmdlets)
and dot-sources the cleanup script. The stubs report a live agent-named
straggler on every probe and record the kill, pinning the identical
contract — poll by NAME until the deadline, force-kill by NAME, then
delete — with zero process spawns, zero PE copies, nothing EDR-visible.

The production routine never renames or copies executables; the flagged
technique existed only in this test. Lesson recorded in tasks/lessons.md.

22/22 cleanup tests green.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-23 17:24:07 +02:00
Oliver Kieselbach e7ea431ccf feat(esp): recovery story for terminally reported ESP failures (session 4910a5a5)
DeviceSetup/Apps failed, the user pressed "Try again" ~23 min later, apps
recovered to 10/10 and DeviceSetup resolved - yet the advisory_completion
window un-defanged the stale failure and failed the live enrollment,
because the advisory variant was exempt from all re-arm/rebase guards.

Engine fix (DecisionCore):
- New facts EspAdvisoryFailureResolvedUtc + EspAdvisoryFailureCategory
  (state-borne; deadline payload would be lost on re-arm/rebase).
- TryResolveAdvisoryOnCategoryRecovery in both ProvisioningComplete
  handlers: category match sets the fact + emits
  esp_failure_advisory_resolved.
- Guards now (!hasAdvisoryAnchor || advisoryResolved): enforcement-progress
  re-arm, hello-never-observed promote and the reboot rebase apply again
  once the failure demonstrably un-happened; unresolved advisories keep
  the legacy un-defang exactly.
- Truthful terminal reason esp_recovered_without_completion_evidence
  (+ failureRecovered=true, LastFailureTrigger=DeadlineFired so the
  likely-stuck app promotion stays off).

Story events (agent tracker):
- esp_failure_retry_detected: failed subcategory leaves "failed" after the
  terminal fire - consistent with the user pressing "Try again".
- esp_failure_recovered: previously failed category reaches success.
- EspFailureDetectedEventArgs.LikelyCulpritApps (never-started first,
  cap 3) rides the EspTerminalFailure payload so esp_failure_advisory /
  enrollment_failed name the culprit app directly.

Surfacing: MCP resource-catalog, web timeline badges (Recovered /
User retry pills, culprit chip on advisory), gather-rule autocomplete,
ANALYZE-ESP-006 "ESP Failure Recovered After User Retry".

Tests: AdvisoryRecoveryTests (13, incl. the 527/611/635/671 field-ordinal
replay that no longer fails the session), EspFailureRecoveryStoryTests (5),
snapshot-builder guards 18 -> 20. All suites green (DecisionCore 493,
V2.Core 2018, Backend 3201, web vitest 589, MCP 449 incl. drift).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-23 17:03:44 +02:00
42 changed files with 2757 additions and 142 deletions
+90
View File
@@ -0,0 +1,90 @@
{
"$schema": "../schema/analyze-rule.schema.json",
"ruleId": "ANALYZE-ESP-006",
"title": "ESP Failure Recovered After User Retry",
"description": "Detects the recovery story: the ESP reported a terminal failure (typically DeviceSetup/Apps), the user most likely pressed 'Try again' on the failure page, the failed step re-ran and completed successfully. The earlier failure did not stick — the enrollment continued past it.",
"severity": "info",
"category": "esp",
"version": "1.0.0",
"enabled": true,
"baseConfidence": 85,
"conditions": [
{
"signal": "advisory",
"source": "event_type",
"eventType": "esp_failure_advisory",
"operator": "exists",
"value": "",
"required": true
},
{
"signal": "recovered",
"source": "event_type",
"eventType": "esp_failure_recovered",
"operator": "exists",
"value": "",
"required": true
},
{
"signal": "retry",
"source": "event_type",
"eventType": "esp_failure_retry_detected",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "category",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "category",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "failedSubcategory",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "failedSubcategory",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "likelyCulpritApps",
"source": "event_type",
"eventType": "esp_failure_advisory",
"dataField": "likelyCulpritApps",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "minutesSinceFailure",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "minutesSinceFailure",
"operator": "exists",
"value": "",
"required": false
}
],
"confidenceFactors": [
{ "signal": "retry", "condition": "exists", "weight": 10 },
{ "signal": "likelyCulpritApps", "condition": "exists", "weight": 5 }
],
"explanation": "The Enrollment Status Page reported a **failure** in the `{{category}}` phase (`{{failedSubcategory}}` subcategory, most likely app(s): `{{likelyCulpritApps}}`) — and then **recovered**: the failed step left its failed state and completed successfully about `{{minutesSinceFailure}}` min later.\n\nThat pattern is consistent with the user pressing **'Try again'** on the ESP failure page (the profile allows failure-page actions; the agent cannot observe the click itself). The failure the user saw was real, but it did not stick — the ESP re-ran the step, it succeeded, and the enrollment continued.\n\nRead the session timeline as one arc: `esp_failure_advisory` (the failure, with the likely culprit app) → `esp_failure_retry_detected` (the retry) → `esp_failure_recovered` (the recovery). If this pattern repeats across devices for the same app, that app's install is flaky on first attempt — fix the app rather than the devices. Any literal `{{…}}` placeholder means that detail was not recorded for this session.",
"remediation": [
{
"title": "Make the first install attempt stick",
"steps": [
"Check the likely culprit app(s) (`{{likelyCulpritApps}}`) in Intune: an app that fails on the first ESP pass but succeeds on retry usually has a dependency/ordering or detection-timing problem.",
"If the app shows 'never started installing' in esp_failure_settle_started, verify its assignment and applicability rules — ESP counted it as required, but IME never processed it.",
"If the pattern repeats across the tenant, consider removing the app from the ESP blocking list until the first-attempt install is reliable — users are seeing an avoidable failure screen.",
"No device-side action is needed for this session: the failure recovered and the enrollment continued."
]
}
],
"tags": ["esp", "recovery", "try-again", "retry", "continue-anyway", "enrollment"]
}
+104
View File
@@ -1884,6 +1884,110 @@
"user-experience"
]
},
{
"ruleId": "ANALYZE-ESP-006",
"title": "ESP Failure Recovered After User Retry",
"description": "Detects the recovery story: the ESP reported a terminal failure (typically DeviceSetup/Apps), the user most likely pressed 'Try again' on the failure page, the failed step re-ran and completed successfully. The earlier failure did not stick — the enrollment continued past it.",
"severity": "info",
"category": "esp",
"version": "1.0.0",
"enabled": true,
"baseConfidence": 85,
"conditions": [
{
"signal": "advisory",
"source": "event_type",
"eventType": "esp_failure_advisory",
"operator": "exists",
"value": "",
"required": true
},
{
"signal": "recovered",
"source": "event_type",
"eventType": "esp_failure_recovered",
"operator": "exists",
"value": "",
"required": true
},
{
"signal": "retry",
"source": "event_type",
"eventType": "esp_failure_retry_detected",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "category",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "category",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "failedSubcategory",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "failedSubcategory",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "likelyCulpritApps",
"source": "event_type",
"eventType": "esp_failure_advisory",
"dataField": "likelyCulpritApps",
"operator": "exists",
"value": "",
"required": false
},
{
"signal": "minutesSinceFailure",
"source": "event_type",
"eventType": "esp_failure_recovered",
"dataField": "minutesSinceFailure",
"operator": "exists",
"value": "",
"required": false
}
],
"confidenceFactors": [
{
"signal": "retry",
"condition": "exists",
"weight": 10
},
{
"signal": "likelyCulpritApps",
"condition": "exists",
"weight": 5
}
],
"explanation": "The Enrollment Status Page reported a **failure** in the `{{category}}` phase (`{{failedSubcategory}}` subcategory, most likely app(s): `{{likelyCulpritApps}}`) — and then **recovered**: the failed step left its failed state and completed successfully about `{{minutesSinceFailure}}` min later.\n\nThat pattern is consistent with the user pressing **'Try again'** on the ESP failure page (the profile allows failure-page actions; the agent cannot observe the click itself). The failure the user saw was real, but it did not stick — the ESP re-ran the step, it succeeded, and the enrollment continued.\n\nRead the session timeline as one arc: `esp_failure_advisory` (the failure, with the likely culprit app) → `esp_failure_retry_detected` (the retry) → `esp_failure_recovered` (the recovery). If this pattern repeats across devices for the same app, that app's install is flaky on first attempt — fix the app rather than the devices. Any literal `{{…}}` placeholder means that detail was not recorded for this session.",
"remediation": [
{
"title": "Make the first install attempt stick",
"steps": [
"Check the likely culprit app(s) (`{{likelyCulpritApps}}`) in Intune: an app that fails on the first ESP pass but succeeds on retry usually has a dependency/ordering or detection-timing problem.",
"If the app shows 'never started installing' in esp_failure_settle_started, verify its assignment and applicability rules — ESP counted it as required, but IME never processed it.",
"If the pattern repeats across the tenant, consider removing the app from the ESP blocking list until the first-attempt install is reliable — users are seeing an avoidable failure screen.",
"No device-side action is needed for this session: the failure recovered and the enrollment continued."
]
}
],
"tags": [
"esp",
"recovery",
"try-again",
"retry",
"continue-anyway",
"enrollment"
]
},
{
"ruleId": "ANALYZE-ID-001",
"title": "Expected Machine Certificate Not Found",
@@ -39,6 +39,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Harness
logFolder: Tmp.Path,
patterns: new List<ImeLogPattern>(),
logger: Logger);
// Mirror ImeLogHost wiring: the historic-replay guard judges staleness against the
// (virtual) agent clock so tests stay deterministic.
Tracker.UtcNowProvider = () => Clock.UtcNow;
}
public IReadOnlyList<FakeSignalIngressSink.PostedSignal> DecisionSignals(DecisionSignalKind kind) =>
@@ -0,0 +1,166 @@
using System;
using System.Collections.Generic;
using AutopilotMonitor.Agent.V2.Core.Logging;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
using AutopilotMonitor.Shared.Models;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
{
/// <summary>
/// Tracker-level historic-replay guard (session eaf3d8c4 part 2): source lines > 24 h older
/// than now are content from a previous enrollment whose IME log survived on disk. The guard
/// in <c>HandlePatternMatch</c> skips app-mutating actions for such lines so replayed apps
/// never enter <c>_packageStates</c> / phase snapshots / persistence — keeping
/// app_tracking_summary, culprit lists and final-status clean. Script actions pass through
/// (the adapter suppresses their emissions), and SimulationMode bypasses the guard entirely.
/// </summary>
public sealed class ImeLogTrackerHistoricReplayGuardTests
{
private static readonly DateTime Now = new DateTime(2026, 7, 23, 15, 42, 0, DateTimeKind.Utc);
private static List<ImeLogPattern> TestPatterns() => new List<ImeLogPattern>
{
new ImeLogPattern
{
PatternId = "T-POLICIES", Category = "always", Enabled = true,
Pattern = @"policies discovered = (?<policies>\[.*\])",
Action = "policiesDiscovered",
Parameters = new Dictionary<string, string>(),
},
new ImeLogPattern
{
PatternId = "T-INSTALLED", Category = "always", Enabled = true,
Pattern = @"app (?<id>[\w-]+) installed",
Action = "updateStateInstalled",
Parameters = new Dictionary<string, string>(),
},
new ImeLogPattern
{
PatternId = "T-ESP-PHASE", Category = "always", Enabled = true,
Pattern = @"In EspPhase: (?<espPhase>\w+)",
Action = "espPhaseDetected",
Parameters = new Dictionary<string, string>(),
},
new ImeLogPattern
{
PatternId = "T-SCRIPT-START", Category = "always", Enabled = true,
Pattern = @"script (?<id>[\w-]+) started",
Action = "scriptStarted",
Parameters = new Dictionary<string, string> { ["scriptType"] = "platform" },
},
};
private static ImeLogTracker BuildTracker(TempDirectory tmp)
{
var tracker = new ImeLogTracker(
logFolder: tmp.Path,
patterns: TestPatterns(),
logger: new AgentLogger(tmp.Path, AgentLogLevel.Info));
tracker.UtcNowProvider = () => Now;
return tracker;
}
private const string PoliciesLine = @"policies discovered = [{""Id"":""app-1"",""Name"":""App One""}]";
[Fact]
public void Stale_policies_line_does_not_populate_package_states()
{
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
tracker.ProcessLogMessageForTest(PoliciesLine, Now.AddDays(-7));
Assert.Empty(tracker.GetAllKnownPackageStates());
}
[Fact]
public void Fresh_relog_of_same_policies_is_tracked_after_stale_skip()
{
// IME re-logs the full policy JSON on every app-policy check-in — skipping the
// stale copy cannot starve the current enrollment.
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
tracker.ProcessLogMessageForTest(PoliciesLine, Now.AddDays(-7));
tracker.ProcessLogMessageForTest(PoliciesLine, Now.AddMinutes(-2));
var all = tracker.GetAllKnownPackageStates();
var pkg = Assert.Single(all);
Assert.Equal("app-1", pkg.Id);
}
[Fact]
public void Stale_state_update_against_fresh_app_is_skipped()
{
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
var stateChanges = 0;
tracker.OnAppStateChanged = (_, __, ___) => stateChanges++;
tracker.ProcessLogMessageForTest(PoliciesLine, Now.AddMinutes(-5)); // fresh discovery
tracker.ProcessLogMessageForTest("app app-1 installed", Now.AddDays(-7)); // stale mutation
Assert.Equal(0, stateChanges);
var pkg = Assert.Single(tracker.GetAllKnownPackageStates());
Assert.NotEqual(AppInstallationState.Installed, pkg.InstallationState);
}
[Fact]
public void Stale_esp_phase_line_does_not_block_fresh_phase_detection()
{
// A stale "AccountSetup" would advance _currentPhaseOrder and make the fresh
// enrollment's DeviceSetup bounce as "backward" — the guard must skip it.
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
var phases = new List<string>();
tracker.OnEspPhaseChanged = p => phases.Add(p);
tracker.ProcessLogMessageForTest("In EspPhase: AccountSetup", Now.AddDays(-7));
tracker.ProcessLogMessageForTest("In EspPhase: DeviceSetup", Now.AddMinutes(-1));
Assert.Equal(new[] { "DeviceSetup" }, phases);
}
[Fact]
public void Stale_script_line_still_reaches_script_handlers()
{
// Script tracker state is harmless for stale lines (adapter suppresses the
// emissions; the stale-slot hardening covers leftovers) — the guard must not
// swallow script actions.
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
var started = new List<ScriptStartedInfo>();
tracker.OnScriptStarted = i => started.Add(i);
tracker.ProcessLogMessageForTest("script aaaa1111-0000-0000-0000-000000000000 started", Now.AddDays(-7));
Assert.Single(started);
}
[Fact]
public void SimulationMode_bypasses_the_guard()
{
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
tracker.SimulationMode = true;
tracker.ProcessLogMessageForTest(PoliciesLine, Now.AddDays(-7));
Assert.Single(tracker.GetAllKnownPackageStates());
}
[Fact]
public void Lines_without_timestamp_are_not_treated_as_stale()
{
// Non-CMTrace lines carry no source timestamp (entry == null) — never stale.
using var tmp = new TempDirectory();
using var tracker = BuildTracker(tmp);
tracker.ProcessLogMessageForTest(PoliciesLine, sourceTimestampUtc: null);
Assert.Single(tracker.GetAllKnownPackageStates());
}
}
}
@@ -15,7 +15,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Runtime
/// <item>a locked tree must abort WITHOUT deleting anything (old script force-deleted
/// marker + state around the locks and orphaned the binaries),</item>
/// <item>a straggler agent process (the incident's second instance) must be found by
/// NAME, killed, and the cleanup must then complete,</item>
/// NAME, killed, and the cleanup must then complete — simulated via function
/// shadowing, NEVER by launching a renamed executable (EDR isolation, see the test),</item>
/// <item>concurrent cleanup scripts must be serialized by the lock file.</item>
/// </list>
/// Timings are dialed down via the test-only BuildCleanupScript parameters so each case
@@ -111,60 +112,55 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Runtime
}
[Fact]
public void Straggler_process_holding_the_tree_is_killed_and_cleanup_completes()
public void Straggler_agent_process_is_waited_on_and_force_killed_via_name_backstop()
{
// Full incident replay: a SECOND agent-named process (here: a renamed
// powershell.exe, matching how only the process NAME identifies agents) holds a
// file in the tree open. The old script waited on the launcher PID only and ran
// its force-delete against the live locks. The hardened script must find the
// straggler by name, kill it after the wait deadline, and then delete everything.
var fakeExe = Path.Combine(_root, _fakeProcessName + ".exe");
File.Copy(SystemPaths.PowerShell, fakeExe);
// Incident replay of the second-instance mechanics WITHOUT spawning a process:
// an earlier version of this test copied powershell.exe under the fake agent name
// and launched it — textbook MITRE T1036.003 ("Rename Legitimate Utilities"),
// which Defender for Endpoint answered with a machine ISOLATION on the dev box
// (see tasks/lessons.md). Instead, a harness script shadows Get-Process /
// Stop-Process with functions (PowerShell resolves functions before cmdlets, so
// the dot-sourced cleanup script binds to the stubs): Get-Process reports a live
// agent-named straggler on every probe; Stop-Process records the kill. This pins
// the same contract — the script polls by NAME until the deadline, then
// force-kills by NAME before deleting — with zero EDR-visible behavior.
var probeLog = Path.Combine(_root, "probe.log");
var cleanupScriptPath = Path.Combine(_root, $"cleanup-{Guid.NewGuid():N}.ps1");
File.WriteAllText(cleanupScriptPath, BuildScript(processWaitSeconds: 2));
var lockTarget = Path.Combine(_basePath, "Agent", "fake.exe").Replace("'", "''");
Process straggler = null;
try
{
straggler = Process.Start(new ProcessStartInfo
{
FileName = fakeExe,
Arguments = "-NoProfile -Command \"$f = [IO.File]::Open('" + lockTarget +
"', 'Open', 'Read', 'None'); Start-Sleep -Seconds 120\"",
UseShellExecute = false,
CreateNoWindow = true,
});
var harness = @"
$probeLog = 'LOG_PATH'
$global:AmProbeCount = 0
function Get-Process {
[CmdletBinding()]
param([string[]]$Name)
if ($Name -contains 'FAKE_NAME') {
$global:AmProbeCount++
Add-Content -Path $probeLog -Value ('probe ' + $global:AmProbeCount)
return [pscustomobject]@{ Name = 'FAKE_NAME'; Id = 424242 }
}
Microsoft.PowerShell.Management\Get-Process @PSBoundParameters
}
function Stop-Process {
[CmdletBinding()]
param([Parameter(ValueFromPipeline = $true)]$InputObject, [switch]$Force)
process { Add-Content -Path $probeLog -Value ('kill ' + $InputObject.Id + ' force=' + $Force) }
}
. 'SCRIPT_PATH'
"
.Replace("LOG_PATH", probeLog)
.Replace("FAKE_NAME", _fakeProcessName)
.Replace("SCRIPT_PATH", cleanupScriptPath);
// Give the straggler time to acquire its file handle before cleanup starts.
var acquireDeadline = DateTime.UtcNow.AddSeconds(20);
var acquired = false;
while (!acquired && DateTime.UtcNow < acquireDeadline)
{
try
{
using (File.Open(Path.Combine(_basePath, "Agent", "fake.exe"),
FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
{
}
}
catch (IOException)
{
acquired = true; // share violation ⇒ straggler holds the file
}
if (!acquired) System.Threading.Thread.Sleep(200);
}
Assert.True(acquired, "straggler never acquired its file lock");
RunScript(harness);
RunScript(BuildScript(processWaitSeconds: 2));
Assert.True(straggler.HasExited, "straggler must be force-killed by the name-based backstop");
Assert.False(Directory.Exists(_basePath), "after the kill the tree must be fully deleted");
Assert.Empty(Directory.GetFileSystemEntries(_root, "*.del-*"));
}
finally
{
try { if (straggler != null && !straggler.HasExited) straggler.Kill(); } catch { }
try { straggler?.Dispose(); } catch { }
}
var log = File.ReadAllLines(probeLog);
Assert.Contains("kill 424242 force=True", log);
Assert.True(Array.FindAll(log, l => l.StartsWith("probe")).Length >= 2,
"script must poll by name in the wait loop AND re-probe for the kill backstop");
Assert.False(Directory.Exists(_basePath), "after the kill the tree must be fully deleted");
Assert.Empty(Directory.GetFileSystemEntries(_root, "*.del-*"));
Assert.False(File.Exists(LockPath));
}
[Fact]
@@ -0,0 +1,256 @@
using System;
using System.Collections.Generic;
using System.Linq;
using AutopilotMonitor.Agent.V2.Core.Logging;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals;
using AutopilotMonitor.Agent.V2.Core.Orchestration;
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration;
using AutopilotMonitor.DecisionCore.Engine;
using AutopilotMonitor.DecisionCore.Signals;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals
{
/// <summary>
/// Session 4910a5a5 (2026-07-23) — post-terminal recovery story. Field sequence:
/// DeviceSetup/Apps failed (culprit app never started installing) → settle window expired
/// → terminal EspFailureDetected → the user pressed "Try again" ~23 min later → Apps left
/// the failed state → 10/10 installed → DeviceSetup resolved. Pre-fix, that recovery only
/// appeared as a generic <c>subcategory_state_change</c>. Coverage:
/// <list type="bullet">
/// <item><c>esp_failure_retry_detected</c> fires once when the failed subcategory leaves
/// the failed state AFTER the terminal fire.</item>
/// <item><c>esp_failure_recovered</c> fires once when the category then resolves to
/// success.</item>
/// <item>An in-settle-window recovery keeps emitting only
/// <c>esp_failure_settle_recovered</c> — the post-terminal pair stays silent.</item>
/// <item>Apps failures carry <c>LikelyCulpritApps</c> on the EspFailureDetected args,
/// never-started apps ranked first.</item>
/// </list>
/// </summary>
public sealed class EspFailureRecoveryStoryTests
{
private static readonly DateTime Fixed = new DateTime(2026, 7, 23, 4, 30, 0, DateTimeKind.Utc);
private sealed class Fixture : IDisposable
{
public TempDirectory Tmp { get; } = new TempDirectory();
public FakeSignalIngressSink Sink { get; } = new FakeSignalIngressSink();
public List<EspFailureDetectedEventArgs> EspFailures { get; } = new List<EspFailureDetectedEventArgs>();
public ProvisioningStatusTracker Tracker { get; }
public Fixture(Func<IReadOnlyList<AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppPackageState>>? packageStatesProbe = null)
{
var clock = new VirtualClock(Fixed);
var post = new InformationalEventPost(Sink, clock);
var logger = new AgentLogger(Tmp.Path, AgentLogLevel.Info);
Tracker = new ProvisioningStatusTracker(
sessionId: "S1",
tenantId: "T1",
post: post,
logger: logger,
appxScanner: new FakeAppxDeploymentFailureScanner(),
backgroundDispatcher: action => action(),
packageStatesProbe: packageStatesProbe);
Tracker.EspFailureDetected += (_, args) => EspFailures.Add(args);
}
public IReadOnlyList<(string EventType, IReadOnlyDictionary<string, object> Data)> CapturedEvents()
{
return Sink.Posted
.Where(p => p.Kind == DecisionSignalKind.InformationalEvent && p.Payload != null)
.Select(p =>
{
var eventType = p.Payload!.TryGetValue(SignalPayloadKeys.EventType, out var et) ? et : "";
var data = p.TypedPayload as IReadOnlyDictionary<string, object>
?? (IReadOnlyDictionary<string, object>)new Dictionary<string, object>();
return (eventType, data);
})
.ToList();
}
/// <summary>Drive the session-4910a5a5 shape up to the terminal fire.</summary>
public void DriveToTerminalDeviceSetupAppsFailure()
{
Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (9 of 10 installed)""}
}");
Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Apps (Error)""}
}");
Tracker.TriggerSettleTimerForTest("DeviceSetupCategory.Status");
}
public void Dispose()
{
Tracker.Dispose();
Tmp.Dispose();
}
}
[Fact]
public void PostTerminalRetry_EmitsRetryDetected_Once()
{
using var f = new Fixture();
f.DriveToTerminalDeviceSetupAppsFailure();
Assert.Single(f.EspFailures);
// "Try again": Apps leaves the failed state well after the settle window.
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (Working on it...)""}
}");
var retry = Assert.Single(f.CapturedEvents(), e => e.EventType == "esp_failure_retry_detected");
Assert.Equal("DeviceSetup", (string)retry.Data["category"]);
Assert.Equal("Apps", (string)retry.Data["subcategory"]);
Assert.Equal("failed", (string)retry.Data["previousState"]);
Assert.Equal("inProgress", (string)retry.Data["newState"]);
Assert.Equal("Provisioning_DeviceSetup_Apps_Failed", (string)retry.Data["failureType"]);
Assert.True(retry.Data.ContainsKey("minutesSinceFailure"));
// A later unrelated transition does not re-emit.
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Apps (10 of 10 installed)""}
}");
Assert.Single(f.CapturedEvents(), e => e.EventType == "esp_failure_retry_detected");
}
[Fact]
public void PostTerminalRecovery_EmitsRecovered_OnCategorySuccess()
{
using var f = new Fixture();
f.DriveToTerminalDeviceSetupAppsFailure();
// Retry → all apps installed → Windows resolves the category boolean.
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (Working on it...)""}
}");
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": true,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Apps (10 of 10 installed)""}
}");
var recovered = Assert.Single(f.CapturedEvents(), e => e.EventType == "esp_failure_recovered");
Assert.Equal("DeviceSetup", (string)recovered.Data["category"]);
Assert.Equal("Apps", (string)recovered.Data["failedSubcategory"]);
Assert.Equal("Provisioning_DeviceSetup_Apps_Failed", (string)recovered.Data["failureType"]);
Assert.True(recovered.Data.ContainsKey("minutesSinceFailure"));
// Duplicate category-success writes do not re-emit (fire-once).
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": true,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Security policies (1 of 1 applied)""},
""AppsSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Apps (10 of 10 installed, take 2)""}
}");
Assert.Single(f.CapturedEvents(), e => e.EventType == "esp_failure_recovered");
}
[Fact]
public void InSettleWindowRecovery_KeepsPostTerminalPairSilent()
{
using var f = new Fixture();
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (0 of 1 installed)""}
}");
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""AppsSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Apps (Error)""}
}");
// Recovery INSIDE the settle window — terminal fire is suppressed.
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (Working on it...)""}
}");
f.Tracker.TriggerSettleTimerForTest("DeviceSetupCategory.Status");
Assert.Empty(f.EspFailures);
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": true,
""AppsSubcategory"": {""subcategoryState"":""succeeded"",""subcategoryStatusText"":""Apps (1 of 1 installed)""}
}");
var events = f.CapturedEvents();
Assert.Contains(events, e => e.EventType == "esp_failure_settle_recovered");
Assert.DoesNotContain(events, e => e.EventType == "esp_failure_retry_detected");
Assert.DoesNotContain(events, e => e.EventType == "esp_failure_recovered");
}
[Fact]
public void AppsFailure_TerminalArgs_CarryLikelyCulprits_NeverStartedFirst()
{
var neverStarted = BuildApp("app-bg", "Teams Backgrounds v2",
AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Unknown,
downloadingSeen: false);
var startedButPending = BuildApp("app-slow", "Slow Installer",
AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Unknown,
downloadingSeen: true);
var installed = BuildApp("app-ok", "Falcon Sensor",
AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Installed,
downloadingSeen: true);
using var f = new Fixture(() => new[] { startedButPending, neverStarted, installed });
f.DriveToTerminalDeviceSetupAppsFailure();
var fired = Assert.Single(f.EspFailures);
Assert.Equal(2, fired.LikelyCulpritApps.Count);
// Never-started app ranked first — it starved the ESP gate without any IME event.
Assert.Equal("Teams Backgrounds v2", fired.LikelyCulpritApps[0]);
Assert.Equal("Slow Installer", fired.LikelyCulpritApps[1]);
}
[Fact]
public void NonAppsFailure_TerminalArgs_CarryNoCulprits()
{
var neverStarted = BuildApp("app-bg", "Teams Backgrounds v2",
AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Unknown,
downloadingSeen: false);
using var f = new Fixture(() => new[] { neverStarted });
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Working""}
}");
f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{
""categorySucceeded"": null,
""SecurityPoliciesSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Failed""}
}");
f.Tracker.TriggerSettleTimerForTest("DeviceSetupCategory.Status");
var fired = Assert.Single(f.EspFailures);
Assert.Empty(fired.LikelyCulpritApps);
}
private static AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppPackageState BuildApp(
string id, string name,
AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState state,
bool downloadingSeen)
{
var pkg = new AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppPackageState(id, 0);
pkg.UpdateName(name);
pkg.UpdateIntent(AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppIntent.Install);
pkg.UpdateTargeted(AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppTargeted.Device);
// DownloadingOrInstallingSeen is derived inside UpdateState (Downloading..Installing
// range) — drive it through a Downloading transition instead of setting it directly.
if (downloadingSeen)
pkg.UpdateState(AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Downloading);
if (state != AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Unknown
&& state != AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime.AppInstallationState.Downloading)
pkg.UpdateState(state);
return pkg;
}
}
}
@@ -0,0 +1,157 @@
using System;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
using AutopilotMonitor.DecisionCore.Signals;
using AutopilotMonitor.Shared.Models;
using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
{
/// <summary>
/// Historic-replay suppression for APP events (session eaf3d8c4 part 2): 147 of 157 app
/// events in that session were replayed from a previous enrollment's IME log — all 10
/// "installed apps" were phantoms. Stale app-state transitions and DO telemetry must be
/// suppressed BEFORE the sub-phase declaration, the timing bookkeeping and the terminal
/// DecisionSignal dedup, so fire-once flags stay unconsumed and no phantom
/// AppInstallCompleted/Failed reaches the engine (which could spuriously re-arm the
/// AdvisoryCompletion window). The script twin lives in
/// <see cref="ImeLogTrackerAdapterHistoricReplayTests"/>.
/// </summary>
public sealed class ImeLogTrackerAdapterHistoricAppReplayTests
{
private static readonly DateTime ClockNow = new DateTime(2026, 7, 23, 15, 42, 0, DateTimeKind.Utc);
[Fact]
public void Stale_terminal_app_transition_is_fully_suppressed()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var app = new AppPackageState("app-old", 0);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installed);
Assert.Empty(f.InfoEvents(SharedEventTypes.AppInstallComplete));
Assert.Empty(f.DecisionSignals(DecisionSignalKind.AppInstallCompleted));
// Shadow download_progress (status=completed) and the summary snapshot ride the
// same emit — both must be gone too.
Assert.Empty(f.InfoEvents(SharedEventTypes.DownloadProgress));
Assert.Empty(f.InfoEvents(SharedEventTypes.AppTrackingSummary));
// Timing bookkeeping must not be poisoned (feeds FinalStatusBuilder).
Assert.False(adapter.AppTimings.ContainsKey("app-old"));
Assert.Single(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
[Fact]
public void Fresh_run_after_suppressed_stale_run_fires_signal_timing_and_subphase()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var app = new AppPackageState("app-X", 0);
// Fresh ESP phase so the sub-phase declaration is armed.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-5);
adapter.TriggerEspPhaseFromTest("DeviceSetup");
// Stale replay of the same app — suppressed, must consume NEITHER the sub-phase
// fire-once NOR the terminal-signal dedup for this appId.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installed);
Assert.Empty(f.InfoEvents(SharedEventTypes.PhaseTransition));
Assert.Empty(f.DecisionSignals(DecisionSignalKind.AppInstallCompleted));
// The app genuinely runs in THIS enrollment.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-2);
adapter.TriggerAppStateFromTest(app, AppInstallationState.Unknown, AppInstallationState.Installing);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-1);
adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installed);
Assert.Single(f.InfoEvents(SharedEventTypes.PhaseTransition)); // sub-phase fired fresh
Assert.Single(f.DecisionSignals(DecisionSignalKind.AppInstallCompleted)); // signal fired fresh
var timing = adapter.AppTimings["app-X"];
Assert.Equal(ClockNow.AddMinutes(-2), timing.StartedAtUtc); // fresh stamps, not stale
Assert.Equal(ClockNow.AddMinutes(-1), timing.CompletedAtUtc);
}
[Fact]
public void Stale_do_telemetry_is_suppressed_fresh_emits()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var app = new AppPackageState("app-do", 0);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerDoTelemetryFromTest(app);
Assert.Empty(f.InfoEvents(SharedEventTypes.DoTelemetry));
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-1);
adapter.TriggerDoTelemetryFromTest(app);
Assert.Single(f.InfoEvents(SharedEventTypes.DoTelemetry));
}
[Fact]
public void Oneshot_summary_is_shared_between_script_and_app_suppressions()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "aaa11111",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
});
adapter.TriggerAppStateFromTest(new AppPackageState("app-old", 0),
AppInstallationState.Installing, AppInstallationState.Installed);
Assert.Single(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
[Fact]
public void FutureSkew_app_transition_still_emits()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var app = new AppPackageState("app-skew", 0);
// Mid-enrollment clock jump — genuine current activity, stamped to the clock.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddHours(2);
adapter.TriggerAppStateFromTest(app, AppInstallationState.Installing, AppInstallationState.Installed);
var info = Assert.Single(f.InfoEvents(SharedEventTypes.AppInstallComplete));
Assert.Equal(ClockNow, info.OccurredAtUtc);
Assert.Equal("true", info.Payload!["derivedTimestamp"]);
Assert.Single(f.DecisionSignals(DecisionSignalKind.AppInstallCompleted));
Assert.Empty(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
[Fact]
public void SimulationMode_bypasses_suppression_for_apps_and_scripts()
{
// The --replay-log-dir dev tool intentionally feeds historic lines.
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SimulationMode = true;
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerAppStateFromTest(new AppPackageState("app-sim", 0),
AppInstallationState.Installing, AppInstallationState.Installed);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "bbb22222",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
});
Assert.Single(f.InfoEvents(SharedEventTypes.AppInstallComplete));
Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted));
Assert.Empty(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
}
}
@@ -0,0 +1,257 @@
using System;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
{
/// <summary>
/// Historic-replay handling (session eaf3d8c4): a previous enrollment's IME log surviving
/// on disk made the agent replay week-old script activity — 156 phantom script_completed
/// events with ~170 h durations (clock-clamped completion minus RAW stale start) and an
/// immediate-upload flood. Script events whose source line is &gt; 24 h stale are now
/// suppressed entirely (one-shot <c>historic_ime_replay_detected</c> summary instead),
/// and durations are computed from a timeline-consistent timestamp pair with a 24 h
/// plausibility backstop.
/// </summary>
public sealed class ImeLogTrackerAdapterHistoricReplayTests
{
private static readonly DateTime ClockNow = new DateTime(2026, 7, 23, 15, 42, 0, DateTimeKind.Utc);
// ---------------------------------------------------------------------
// Suppression: stale (> 24 h past) source lines are a previous enrollment
// ---------------------------------------------------------------------
[Fact]
public void Stale_completion_is_suppressed_and_emits_oneshot_summary()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var ancient = ClockNow.AddDays(-7);
f.Tracker.LastMatchedLogTimestamp = ancient;
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "d78c1822",
ScriptType = "platform",
ExitCode = 0,
Result = "Failed",
StartedAtUtc = ancient.AddMinutes(-30),
// Bootstrap marker in stdout — week-old evidence must not drive the
// bootstrap-detected trace either.
Stdout = "Bootstrap script version: v2.0",
});
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptCompleted));
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptFailed));
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptTimeoutSuspected));
Assert.Empty(f.InfoEvents(SharedEventTypes.AgentTrace));
var summary = f.InfoEvent(SharedEventTypes.HistoricImeReplayDetected);
Assert.Equal(ancient.ToString("o"), summary.Payload!["earliestRejectedSourceTimestamp"]);
}
[Fact]
public void Summary_is_oneshot_across_started_and_completed_suppressions()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerScriptStartedFromTest(new ScriptStartedInfo { PolicyId = "aaa11111", ScriptType = "platform" });
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7).AddMinutes(1);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "aaa11111",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
});
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7).AddMinutes(2);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "bbb22222",
ScriptType = "remediation",
ScriptPart = "detection",
ExitCode = 0,
ComplianceResult = "True",
});
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptStarted));
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptCompleted));
// Exactly ONE summary regardless of how many replayed lines followed — and it dates
// the replay window from the FIRST (earliest) suppressed line.
var summary = Assert.Single(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
Assert.Equal(ClockNow.AddDays(-7).ToString("o"), summary.Payload!["earliestRejectedSourceTimestamp"]);
}
[Fact]
public void Fresh_events_after_suppression_emit_normally()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddDays(-7);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "aaa11111",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
});
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptCompleted));
// The agent catches up to current log content — normal emission resumes.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-2);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "ccc33333",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
StartedAtUtc = ClockNow.AddMinutes(-3),
});
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted));
Assert.Equal("ccc33333", info.Payload!["policyId"]);
Assert.Equal("60.00", info.Payload["durationSeconds"]);
}
[Fact]
public void Clock_fallback_without_source_timestamp_still_emits()
{
// derivedFromClock with NO rejected source ts (synthetic/callback path) is not a
// replay — must emit, and must not trigger the summary.
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "ddd44444",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
});
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted));
Assert.Equal("true", info.Payload!["derivedTimestamp"]);
Assert.False(info.Payload.ContainsKey("rejectedSourceTimestamp"));
Assert.Empty(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
// ---------------------------------------------------------------------
// Duration: timeline-consistent pair + plausibility backstop
// ---------------------------------------------------------------------
[Fact]
public void FutureSkew_completion_emits_with_clamped_stamp_and_raw_pair_duration()
{
// Mid-enrollment clock jump (WhiteGlove +1h CMTrace skew case): the source ts is
// rejected as future-skewed — NOT suppressed — and the duration must come from the
// raw source pair (both ends on the same skewed timeline), not clamped-now − raw-start.
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var skewed = ClockNow.AddHours(2);
f.Tracker.LastMatchedLogTimestamp = skewed;
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "eee55555",
ScriptType = "platform",
ExitCode = 0,
Result = "Success",
StartedAtUtc = skewed.AddSeconds(-360),
});
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted));
Assert.Equal(ClockNow, info.OccurredAtUtc); // stamp: clamped to clock
Assert.Equal("true", info.Payload!["derivedTimestamp"]);
Assert.Equal(skewed.ToString("o"), info.Payload["rejectedSourceTimestamp"]);
Assert.Equal("360.00", info.Payload["durationSeconds"]); // duration: raw pair
Assert.Empty(f.InfoEvents(SharedEventTypes.HistoricImeReplayDetected));
}
[Fact]
public void FutureSkew_failed_platform_script_timeout_heuristic_uses_raw_pair()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var skewed = ClockNow.AddHours(2);
f.Tracker.LastMatchedLogTimestamp = skewed;
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "fff66666",
ScriptType = "platform",
ExitCode = 0,
Result = "Failed",
StartedAtUtc = skewed.AddMinutes(-26), // past the 25-min suspicion threshold
});
var suspected = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptTimeoutSuspected));
Assert.Equal("1560.00", suspected.Payload!["durationSeconds"]);
Assert.Equal(ClockNow, suspected.OccurredAtUtc);
}
[Fact]
public void Implausible_duration_above_24h_is_omitted()
{
// Fresh (accepted) completion paired with an ancient start — e.g. a stale pending
// slot a legacy path left behind. The duration would be a cross-run lie; omit it.
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddMinutes(-2);
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
{
PolicyId = "abc12345",
ScriptType = "platform",
ExitCode = 0,
Result = "Failed",
StartedAtUtc = ClockNow.AddHours(-30),
});
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptFailed));
Assert.False(info.Payload!.ContainsKey("durationSeconds"));
Assert.False(info.Payload.ContainsKey("durationBasis"));
// The 30 h "duration" must not read as a hung script either.
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptTimeoutSuspected));
}
// ---------------------------------------------------------------------
// Tracker slot hardening: stale pending start must not pair with a fresh run
// ---------------------------------------------------------------------
[Fact]
public void Fresh_start_discards_stale_pending_slot_from_previous_enrollment()
{
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
// Previous enrollment: replayed start line whose matching result never appeared
// (the script was mid-run when that enrollment ended).
f.Tracker.SeedPendingPlatformScriptForTesting("beef7777", exitCode: null, exitObservedAtUtc: null,
startedAtUtc: ClockNow.AddDays(-7));
// Same policy genuinely re-runs now — the fresh start must begin a NEW execution.
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddSeconds(-90);
f.Tracker.HandlePlatformScriptStarted("beef7777");
f.Tracker.LastMatchedLogTimestamp = ClockNow;
f.Tracker.CompletePlatformScriptFromImeResultForTesting("beef7777", "Success", ClockNow);
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
// Without the hardening the slot kept the 7-day-old start: the duration would have
// been dropped by the 24 h backstop (or, before that, shown as ~168 h).
Assert.Equal("90.00", info.Payload!["durationSeconds"]);
}
}
}
@@ -208,39 +208,60 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
}
else
{
// Platform script: AgentExecutor.log entries create/enrich, IME log entries also create
if (!_pendingPlatformScripts.ContainsKey(id))
{
// A fresh start for this policy (no pending entry) begins a NEW execution.
// Clear any emitted-marker from a prior run so IME re-evaluations / retries of
// the same platform-script policy within one agent lifetime are not silently
// deduped away. Within a single run the start always precedes exit/result, so
// this never clears the current run's own marker.
_platformScriptResultEmitted.Remove(id);
_pendingPlatformScripts[id] = new ScriptExecutionState
{
PolicyId = id,
ScriptType = "platform",
// Prefer the source CMTrace timestamp so a script that started before the
// agent launched (replayed log content) is dated to its real start, not now.
// Set only at slot creation: the start line fires twice (agentexecutor + ime
// source) but the earliest wins.
StartedAtUtc = LastMatchedLogTimestamp ?? DateTime.UtcNow,
};
// Live "running" indicator — same signal health scripts emit. Gated on slot
// creation so the duplicate start line (agentexecutor + ime source) doesn't
// double-emit for the same execution.
try { OnScriptStarted?.Invoke(new ScriptStartedInfo { PolicyId = id, ScriptType = "platform" }); }
catch (Exception ex) { _logger.Warning($"ImeLogTracker: OnScriptStarted handler threw: {ex.Message}"); }
}
_lastPlatformScriptPolicyId = id;
// Started lines fire twice per script (agentexecutor + ime source) and carry no
// outcome — the matching `platform script completed` line below carries result+exit
// and stays on Info. Keep starts on Debug so Info reflects script outcomes only.
_logger.Debug($"ImeLogTracker: platform script started: {id} (source: {source ?? "ime"})");
HandlePlatformScriptStarted(id, source);
}
}
// Platform script: AgentExecutor.log entries create/enrich, IME log entries also create.
// Internal so the stale-slot hardening is directly testable (the public path arrives via
// a regex Match).
internal void HandlePlatformScriptStarted(string id, string source = null)
{
// Stale-slot hardening (session eaf3d8c4): a replayed start line from a previous
// enrollment whose matching result never appeared (script was mid-run when that
// enrollment ended) leaves a pending slot with a days-old StartedAtUtc. When the
// same policy genuinely re-runs now, the fresh start must begin a NEW execution —
// otherwise the ancient start pairs with the fresh completion and the duration
// lies. > 24 h mirrors the adapter's source-timestamp staleness clamp.
var currentStartTs = LastMatchedLogTimestamp ?? DateTime.UtcNow;
if (_pendingPlatformScripts.TryGetValue(id, out var pendingSlot)
&& pendingSlot.StartedAtUtc.HasValue
&& currentStartTs - pendingSlot.StartedAtUtc.Value > TimeSpan.FromHours(24))
{
_logger.Debug($"ImeLogTracker: discarding stale pending platform-script slot for {id} (started {pendingSlot.StartedAtUtc:o})");
_pendingPlatformScripts.Remove(id);
}
if (!_pendingPlatformScripts.ContainsKey(id))
{
// A fresh start for this policy (no pending entry) begins a NEW execution.
// Clear any emitted-marker from a prior run so IME re-evaluations / retries of
// the same platform-script policy within one agent lifetime are not silently
// deduped away. Within a single run the start always precedes exit/result, so
// this never clears the current run's own marker.
_platformScriptResultEmitted.Remove(id);
_pendingPlatformScripts[id] = new ScriptExecutionState
{
PolicyId = id,
ScriptType = "platform",
// Prefer the source CMTrace timestamp so a script that started before the
// agent launched (replayed log content) is dated to its real start, not now.
// Set only at slot creation: the start line fires twice (agentexecutor + ime
// source) but the earliest wins.
StartedAtUtc = currentStartTs,
};
// Live "running" indicator — same signal health scripts emit. Gated on slot
// creation so the duplicate start line (agentexecutor + ime source) doesn't
// double-emit for the same execution.
try { OnScriptStarted?.Invoke(new ScriptStartedInfo { PolicyId = id, ScriptType = "platform" }); }
catch (Exception ex) { _logger.Warning($"ImeLogTracker: OnScriptStarted handler threw: {ex.Message}"); }
}
_lastPlatformScriptPolicyId = id;
// Started lines fire twice per script (agentexecutor + ime source) and carry no
// outcome — the matching `platform script completed` line below carries result+exit
// and stays on Info. Keep starts on Debug so Info reflects script outcomes only.
_logger.Debug($"ImeLogTracker: platform script started: {id} (source: {source ?? "ime"})");
}
// Routes line-by-line script-data handlers (context / exitCode / output) to the right
// accumulator based on the pattern's scriptType parameter. Health-script lines feed the
// single-slot _pendingHealthScript; platform-script lines feed _pendingPlatformScripts.
@@ -194,6 +194,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
}
}
// Actions that mutate app/phase tracking state (_packageStates, _phasePackageSnapshots,
// _currentPhaseOrder, DO telemetry) — the historic-replay guard skips these for source
// lines from a previous enrollment so replayed apps never enter tracked state,
// persistence, app_tracking_summary, culprit lists or final-status. Script actions are
// deliberately NOT here: their tracker state is harmless (stale-slot hardening covers
// leftovers) and the adapter suppresses their emissions. espphasedetected IS here — a
// stale "In EspPhase: AccountSetup" would advance _currentPhaseOrder and make the fresh
// enrollment's DeviceSetup lines bounce as "backward"; IME re-logs the phase constantly,
// so fresh lines re-deliver it immediately.
private static readonly HashSet<string> AppMutatingActions = new HashSet<string>(StringComparer.Ordinal)
{
"imeshutdown", "espphasedetected", "setcurrentapp",
"updatestateinstalled", "updatestatedownloading", "updatestateinstalling",
"updatestateskipped", "updatestateerror", "updatestatepostponed",
"captureexitcode", "capturehresult", "captureappversion",
"captureapptypewinget", "captureapptypemsi", "captureattemptnumber",
"capturedetectionresult", "esptrackstatus", "policiesdiscovered",
"ignorecompletedapp", "updatename", "updatewin32appstate",
"cancelstuckandsetcurrent", "updatedotelemetry",
};
private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry)
{
LastMatchedPatternId = pattern.PatternId;
@@ -206,6 +227,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
try { OnPatternMatched?.Invoke(pattern.PatternId); }
catch (Exception ex) { _logger?.Warning($"OnPatternMatched handler threw: {ex.Message}"); }
// Historic-replay guard (session eaf3d8c4): a source line > 24 h older than now is
// content from a previous enrollment whose IME log survived on disk. App-mutating
// actions are skipped BEFORE _seenAppIds so replayed apps poison neither the tracked
// state nor the phase-change ignore list. SimulationMode (--replay-log-dir dev tool)
// replays historic logs on purpose and bypasses the guard.
var isStaleReplayLine = !SimulationMode && entry != null
&& (UtcNowProvider() - NormalizeUtc(entry.Timestamp)) > HistoricReplayThreshold;
if (isStaleReplayLine && AppMutatingActions.Contains(pattern.Action?.ToLower() ?? string.Empty))
{
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({entry.Timestamp:o})");
return;
}
try
{
var id = match.Groups["id"]?.Value;
@@ -71,6 +71,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public double SpeedFactor { get; set; } = 50;
private DateTime _lastLogTimestamp = DateTime.MinValue;
// Source log lines older than this relative to now are content from a previous
// enrollment (IME logs surviving a re-enrollment, session eaf3d8c4). Single source of
// truth shared with the adapter's ResolveOccurredAt clamp and replay suppression.
internal static readonly TimeSpan HistoricReplayThreshold = TimeSpan.FromHours(24);
// Deterministic-time seam for the historic-replay guard; production default is the
// system clock, ImeLogHost rewires it to the agent IClock, tests to their VirtualClock.
internal Func<DateTime> UtcNowProvider { get; set; } = () => DateTime.UtcNow;
/// <summary>
/// CMTrace 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.
/// </summary>
internal static DateTime NormalizeUtc(DateTime value) =>
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
// Background task
private Task _pollingTask;
private CancellationTokenSource _cts;
@@ -1,4 +1,5 @@
using System;
using System.Collections.Generic;
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
{
@@ -38,16 +39,30 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
/// </summary>
public string Category { get; }
/// <summary>
/// Session 4910a5a5: names of the tracked apps most likely behind an Apps-subcategory
/// failure (capped, never-started apps ranked first — those starve ESP's app gate
/// without ever producing an IME install event). Snapshot from
/// <c>ProvisioningStatusTracker.SnapshotTrackedAppsNotCompleted</c> at failure-arming
/// time; empty for non-Apps failures and event-log-derived failures. Propagated onto
/// the EspTerminalFailure signal payload so the DecisionEngine's
/// <c>esp_failure_advisory</c> / <c>enrollment_failed</c> events can name the culprit
/// directly.
/// </summary>
public IReadOnlyList<string> LikelyCulpritApps { get; }
public EspFailureDetectedEventArgs(
string failureType,
string errorCode = null,
string failedSubcategory = null,
string category = null)
string category = null,
IReadOnlyList<string> likelyCulpritApps = null)
{
FailureType = string.IsNullOrEmpty(failureType) ? "unknown" : failureType;
ErrorCode = string.IsNullOrEmpty(errorCode) ? null : errorCode;
FailedSubcategory = string.IsNullOrEmpty(failedSubcategory) ? null : failedSubcategory;
Category = string.IsNullOrEmpty(category) ? null : category;
LikelyCulpritApps = likelyCulpritApps ?? Array.Empty<string>();
}
}
}
@@ -116,6 +116,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
// failure details that fire after the settle window expires.
private Dictionary<string, Timer> _provisioningFailureSettleTimers;
private Dictionary<string, EspFailureDetectedEventArgs> _provisioningFailureSettleArgs;
// Session 4910a5a5 — post-terminal recovery story. Populated when the settle window
// expires and EspFailureDetected actually fires (terminal path); consumed by the
// esp_failure_retry_detected / esp_failure_recovered emitters so a late "Try again"
// recovery (23 min after the failure in the field session) is visible on the timeline
// instead of hiding inside a generic subcategory_state_change. Keyed by category-name.
private Dictionary<string, EspFailureDetectedEventArgs> _provisioningFailureTerminalArgs;
private Dictionary<string, DateTime> _provisioningFailureTerminalUtc;
private HashSet<string> _postFailureRetryEmitted;
private HashSet<string> _postFailureRecoveredEmitted;
// Session 2bc884b6: AppX enrichment scan seams + fire-once guard. The scanner and the
// dispatcher are injectable so tests never touch the real event log or the threadpool.
private readonly IAppxDeploymentFailureScanner _appxScanner;
@@ -285,6 +294,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
_lastSubcategoryStates = new Dictionary<string, Dictionary<string, string>>(StringComparer.OrdinalIgnoreCase);
_provisioningFailureSettleTimers = new Dictionary<string, Timer>(StringComparer.OrdinalIgnoreCase);
_provisioningFailureSettleArgs = new Dictionary<string, EspFailureDetectedEventArgs>(StringComparer.OrdinalIgnoreCase);
_provisioningFailureTerminalArgs = new Dictionary<string, EspFailureDetectedEventArgs>(StringComparer.OrdinalIgnoreCase);
_provisioningFailureTerminalUtc = new Dictionary<string, DateTime>(StringComparer.OrdinalIgnoreCase);
_postFailureRetryEmitted = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
_postFailureRecoveredEmitted = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
_deviceSetupProvisioningCompleteFired = false;
_deviceSetupFallbackTimer = null;
_accountSetupProvisioningCompleteFired = false;
@@ -665,6 +678,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
// null-ing here is correctness-neutral on the start-condition side.
ResetAccountSetupFallbackTimer();
_accountSetupProvisioningCompleteFired = true;
MaybeEmitPostFailureRecovered("AccountSetupCategory.Status", "AccountSetup");
try { AccountSetupProvisioningComplete?.Invoke(this, EventArgs.Empty); }
catch (Exception ex) { _logger.Error("AccountSetupProvisioningComplete handler failed (fallback path)", ex); }
}
@@ -833,6 +847,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
// null-ing here is correctness-neutral on the start-condition side.
ResetDeviceSetupFallbackTimer();
_deviceSetupProvisioningCompleteFired = true;
MaybeEmitPostFailureRecovered("DeviceSetupCategory.Status", "DeviceSetup");
try { DeviceSetupProvisioningComplete?.Invoke(this, EventArgs.Empty); }
catch (Exception ex) { _logger.Error("DeviceSetupProvisioningComplete handler failed (fallback path)", ex); }
}
@@ -946,12 +961,25 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
var severity = categorySucceeded == false ? EventSeverity.Warning : EventSeverity.Info;
EmitProvisioningEvent(categoryLabel, categorySucceeded, statusText, subcategories, severity);
EmitRawRegistryDump(categoryLabel, jsonValue, $"category_resolved_{(categorySucceeded == true ? "success" : "failed")}");
// Session 4910a5a5: category resolving to success after a terminally
// fired failure = the failure recovered (fallback-path successes call
// this from their own timer handlers).
if (categorySucceeded == true)
{
MaybeEmitPostFailureRecovered(categoryName, categoryLabel);
}
}
else
{
var transitions = DetectSubcategoryTransitions(categoryName, subcategories);
StoreSubcategoryStates(categoryName, subcategories);
// Session 4910a5a5: after a terminally fired failure, the failed
// subcategory leaving "failed" is the ESP re-running the step —
// consistent with the user pressing "Try again" on the failure page.
MaybeEmitPostFailureRetry(categoryName, categoryLabel, transitions);
var failureTransitions = transitions.Where(t => t.IsFailure).ToList();
if (transitions.Count > 0)
{
@@ -1025,6 +1053,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
$"escalating as {failureTypeName} (errorCode={errorCode ?? "n/a"})");
_logger.Warning($"Provisioning failure detected: {failureTypeName}");
// Session 4910a5a5: name the likely culprit app(s) directly on the failure args so
// the DecisionEngine's advisory/terminal events carry them — never-started apps
// first (they starve ESP's app gate without ever producing an IME install event),
// capped at 3 names.
IReadOnlyList<string> likelyCulpritApps = null;
if (string.Equals(failedSubcategoryName, "Apps", StringComparison.OrdinalIgnoreCase))
{
likelyCulpritApps = SnapshotTrackedAppsNotCompleted()
.OrderBy(a => a["everStartedInstalling"] is bool started && started ? 1 : 0)
.Select(a => a["appName"]?.ToString())
.Where(n => !string.IsNullOrEmpty(n))
.Take(3)
.ToList();
}
// Caller already holds _stateLock.
ArmFailureSettleTimer(
categoryName: categoryName,
@@ -1032,7 +1075,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
failureType: failureTypeName,
errorCode: errorCode,
failedSubcategory: failedSubcategoryName,
category: categoryLabel));
category: categoryLabel,
likelyCulpritApps: likelyCulpritApps));
// Settle-window owns the actual EspFailureDetected fire. The legacy "fire-after-emit"
// path in CheckProvisioningStatus is now a no-op for this code-path; it stays in place
@@ -1292,6 +1336,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
_provisioningCategoriesResolved.Remove(categoryName);
}
}
else
{
// Session 4910a5a5: remember the terminally fired failure so a LATE
// recovery (outside the settle window — e.g. user pressing "Try again"
// minutes later) can be told as esp_failure_retry_detected /
// esp_failure_recovered instead of hiding in a generic state-change.
_provisioningFailureTerminalArgs[categoryName] = args;
_provisioningFailureTerminalUtc[categoryName] = DateTime.UtcNow;
}
}
if (recovered)
@@ -1382,6 +1435,133 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
});
}
/// <summary>
/// Session 4910a5a5: after a terminally fired failure (settle window expired,
/// EspFailureDetected raised), the failed subcategory leaving the <c>failed</c> state
/// means the ESP re-ran the step — consistent with the user pressing "Try again" on
/// the ESP failure page (the agent cannot observe the click itself). Emits
/// <c>esp_failure_retry_detected</c> once per terminally fired category. Caller holds
/// <see cref="_stateLock"/>.
/// </summary>
private void MaybeEmitPostFailureRetry(string categoryName, string categoryLabel, List<SubcategoryTransition> transitions)
{
if (transitions == null || transitions.Count == 0) return;
if (_postFailureRetryEmitted.Contains(categoryName)) return;
if (_provisioningFailureTerminalArgs == null
|| !_provisioningFailureTerminalArgs.TryGetValue(categoryName, out var terminalArgs))
{
return; // No terminal fire on record — in-window recovery is settle_recovered's job.
}
SubcategoryTransition? retryTransition = null;
foreach (var t in transitions)
{
if (string.Equals(t.OldState, "failed", StringComparison.OrdinalIgnoreCase)
&& !string.Equals(t.NewState, "failed", StringComparison.OrdinalIgnoreCase))
{
retryTransition = t;
break;
}
}
if (retryTransition == null) return;
var retry = retryTransition.Value;
_postFailureRetryEmitted.Add(categoryName);
var minutesSinceFailure = MinutesSinceTerminalFailure(categoryName);
var data = new Dictionary<string, object>
{
{ "category", categoryLabel },
{ "subcategory", retry.SubcategoryName },
{ "previousState", retry.OldState },
{ "newState", retry.NewState },
{ "failureType", terminalArgs.FailureType },
{ "minutesSinceFailure", minutesSinceFailure },
};
if (!string.IsNullOrEmpty(terminalArgs.ErrorCode))
data["errorCode"] = terminalArgs.ErrorCode;
_post.Emit(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = Constants.EventTypes.EspFailureRetryDetected,
Severity = EventSeverity.Info,
Source = "EspAndHelloTracker",
Phase = EnrollmentPhase.Unknown,
Message = $"ESP retry detected — {categoryLabel}/{retry.SubcategoryName} left the failed state " +
$"({retry.OldState} → {retry.NewState}) {minutesSinceFailure} min after the failure — " +
"consistent with the user pressing 'Try again' on the ESP failure page.",
Data = data,
ImmediateUpload = true
});
}
/// <summary>
/// Session 4910a5a5: the category behind a terminally fired failure reached success
/// (categorySucceeded=true or the all-subcategories-succeeded fallback) — the failure
/// demonstrably recovered. Emits <c>esp_failure_recovered</c> once per terminally
/// fired category so the timeline tells "failed → retried → recovered" instead of
/// leaving the stale failure as the last word. Caller holds <see cref="_stateLock"/>.
/// </summary>
private void MaybeEmitPostFailureRecovered(string categoryName, string categoryLabel)
{
if (_postFailureRecoveredEmitted == null || _postFailureRecoveredEmitted.Contains(categoryName)) return;
if (_provisioningFailureTerminalArgs == null
|| !_provisioningFailureTerminalArgs.TryGetValue(categoryName, out var terminalArgs))
{
return;
}
_postFailureRecoveredEmitted.Add(categoryName);
var minutesSinceFailure = MinutesSinceTerminalFailure(categoryName);
string subcategoryStatus = null;
if (terminalArgs.FailedSubcategory != null
&& _lastSubcategoryStates != null
&& _lastSubcategoryStates.TryGetValue(categoryName, out var subs)
&& subs.TryGetValue(terminalArgs.FailedSubcategory, out var currentState))
{
subcategoryStatus = currentState;
}
var data = new Dictionary<string, object>
{
{ "category", categoryLabel },
{ "failedSubcategory", terminalArgs.FailedSubcategory ?? "category-level" },
{ "failureType", terminalArgs.FailureType },
{ "minutesSinceFailure", minutesSinceFailure },
};
if (!string.IsNullOrEmpty(terminalArgs.ErrorCode))
data["errorCode"] = terminalArgs.ErrorCode;
if (subcategoryStatus != null)
data["subcategoryState"] = subcategoryStatus;
_post.Emit(new EnrollmentEvent
{
SessionId = _sessionId,
TenantId = _tenantId,
EventType = Constants.EventTypes.EspFailureRecovered,
Severity = EventSeverity.Info,
Source = "EspAndHelloTracker",
Phase = EnrollmentPhase.Unknown,
Message = $"ESP failure recovered — {categoryLabel}/{terminalArgs.FailedSubcategory ?? "category-level"} " +
$"completed successfully {minutesSinceFailure} min after the failure; the earlier ESP failure no longer applies.",
Data = data,
ImmediateUpload = true
});
}
private int MinutesSinceTerminalFailure(string categoryName)
{
if (_provisioningFailureTerminalUtc != null
&& _provisioningFailureTerminalUtc.TryGetValue(categoryName, out var firedAt))
{
return Math.Max(0, (int)Math.Round((DateTime.UtcNow - firedAt).TotalMinutes));
}
return 0;
}
private void EmitFailureSettleStarted(EspFailureDetectedEventArgs args)
{
var data = new Dictionary<string, object>
@@ -1863,6 +2043,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
_provisioningFailureSettleTimers = new Dictionary<string, Timer>(StringComparer.OrdinalIgnoreCase);
if (_provisioningFailureSettleArgs == null)
_provisioningFailureSettleArgs = new Dictionary<string, EspFailureDetectedEventArgs>(StringComparer.OrdinalIgnoreCase);
if (_provisioningFailureTerminalArgs == null)
_provisioningFailureTerminalArgs = new Dictionary<string, EspFailureDetectedEventArgs>(StringComparer.OrdinalIgnoreCase);
if (_provisioningFailureTerminalUtc == null)
_provisioningFailureTerminalUtc = new Dictionary<string, DateTime>(StringComparer.OrdinalIgnoreCase);
if (_postFailureRetryEmitted == null)
_postFailureRetryEmitted = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
if (_postFailureRecoveredEmitted == null)
_postFailureRecoveredEmitted = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
}
}
@@ -111,6 +111,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
logger: logger,
matchLogPath: expandedMatchLogPath,
stateDirectory: stateDirectory);
// Historic-replay guard runs against the agent clock, not the raw system clock —
// keeps the tracker's staleness verdicts consistent with the adapter's clamp.
_tracker.UtcNowProvider = () => clock.UtcNow;
if (simulationMode)
{
@@ -1,6 +1,7 @@
#nullable enable
using System;
using System.Collections.Generic;
using System.Globalization;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals;
using AutopilotMonitor.Agent.V2.Core.Orchestration;
using AutopilotMonitor.DecisionCore.Engine;
@@ -267,6 +268,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
payload["failedSubcategory"] = failedSubcategory!;
if (!string.IsNullOrEmpty(category))
payload["category"] = category!;
// Session 4910a5a5: culprit-app names ride the signal so the DecisionEngine's
// esp_failure_advisory / enrollment_failed events can name them directly.
var culprits = args?.LikelyCulpritApps;
if (culprits != null && culprits.Count > 0)
{
payload["likelyCulpritApps"] = string.Join(", ", culprits);
payload["likelyCulpritAppCount"] = culprits.Count.ToString(CultureInfo.InvariantCulture);
}
_ingress.Post(
kind: DecisionSignalKind.EspTerminalFailure,
@@ -97,12 +97,24 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// bootstrap marker line. Lets MCP report "which device runs which bootstrap version".
private bool _bootstrapDetectedPosted;
// One-shot: historic script replay detected (a previous enrollment's IME log content
// surviving on disk) — its script events are suppressed, and a single
// historic_ime_replay_detected Info event explains the gap in the timeline.
private bool _historicReplayNoted;
private int _suppressedHistoricReplayEvents; // forensic count for the log line
// A platform script whose observed run duration reaches this is treated as having hit the
// IME script-execution timeout (default ~30 min). 25 min leaves headroom below 30 so clock
// jitter / the agent's late replay window can't miss it, while staying well above any
// legitimately long install wrapper that completes on its own.
private static readonly TimeSpan ScriptTimeoutSuspectedThreshold = TimeSpan.FromMinutes(25);
// Source log lines older than this relative to the clock are pathological — shared by
// ResolveOccurredAt's staleness clamp, the historic-replay suppression, the duration
// plausibility backstop AND the tracker's app-mutation guard (single source of truth
// in ImeLogTracker so the layers can never drift apart).
private static readonly TimeSpan StaleSourceThreshold = ImeLogTracker.HistoricReplayThreshold;
// Matches the deterministic marker line the bootstrap script writes via Write-Log,
// e.g. "Bootstrap script version: v2.0" — see scripts/Bootstrap/Install-AutopilotMonitor.ps1.
// Same shape as the web-side regex in utils/bootstrapVersion.ts; kept in sync intentionally.
@@ -289,17 +301,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
rawSourceTimestamp = sourceTsOverride ?? _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 asUtc = NormalizeUtc(rawSourceTimestamp.Value);
var clockNow = _clock.UtcNow;
var ageHours = (clockNow - asUtc).TotalHours;
if (ageHours > 24.0 || ageHours < -1.0)
if (ageHours > StaleSourceThreshold.TotalHours || ageHours < -1.0)
{
// Pathologically stale (>24h old) or in the future (>1h skew) — log,
// fall back, and let the caller flag the event.
@@ -325,6 +331,67 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture);
}
// CMTrace Kind normalization — shared implementation lives on the tracker (used by its
// historic-replay guard too).
private static DateTime NormalizeUtc(DateTime value) => ImeLogTracker.NormalizeUtc(value);
/// <summary>
/// True when an event's source log line is a historic replay: the source timestamp
/// was rejected as stale (> <see cref="StaleSourceThreshold"/> in the PAST). Those lines
/// are script runs and app installs from a previous enrollment whose IME log survived on
/// disk (session eaf3d8c4: 156 replayed script completions + 147 replayed app events
/// shown as current activity, immediate-upload flood → ingress_backpressure). Future-skew
/// rejections (negative age — mid-enrollment clock jump) and clock-only fallbacks (no
/// source timestamp at all) are NOT replay and must still emit. Emits the one-shot
/// <c>historic_ime_replay_detected</c> summary on the first suppression; replay is
/// chronological, so that first suppressed line carries the earliest rejected source
/// timestamp. Bypassed in <see cref="ImeLogTracker.SimulationMode"/> — the
/// --replay-log-dir dev tool feeds historic lines on purpose.
/// </summary>
private bool SuppressIfHistoricReplay(
bool derivedFromClock, DateTime? rawSourceTs, string eventLabel, string entityId)
{
if (_tracker.SimulationMode) return false;
if (!derivedFromClock || !rawSourceTs.HasValue) return false;
var asUtc = NormalizeUtc(rawSourceTs.Value);
var clockNow = _clock.UtcNow;
var age = clockNow - asUtc;
if (age <= StaleSourceThreshold) return false; // future-skew or fresh → emit
bool emitSummary;
int suppressedSoFar;
lock (_lock)
{
suppressedSoFar = ++_suppressedHistoricReplayEvents;
emitSummary = !_historicReplayNoted;
_historicReplayNoted = true;
}
if (emitSummary)
{
var culture = System.Globalization.CultureInfo.InvariantCulture;
// Standard batch upload on purpose — no immediateUpload; the whole point of the
// suppression is to stop the replayed batch from flooding the ingest.
_post.Emit(
eventType: SharedEventTypes.HistoricImeReplayDetected,
source: SourceLabel,
message: "Historic IME activity from a previous enrollment detected in the log "
+ $"(earliest source timestamp {asUtc:o}) — its script and app events are suppressed for this session.",
severity: EventSeverity.Info,
data: new Dictionary<string, string>(StringComparer.Ordinal)
{
["decision"] = "historic_ime_replay_suppressed",
["earliestRejectedSourceTimestamp"] = asUtc.ToString("o", culture),
["staleThresholdHours"] = StaleSourceThreshold.TotalHours.ToString("F0", culture),
});
}
_logger?.Debug(
$"ImeAdapter: suppressed historic {eventLabel} for {entityId} "
+ $"(source ts {asUtc:o}, age {age.TotalHours:F1}h, suppressed so far: {suppressedSoFar})");
return true;
}
private void EmitEspPhase(string phase)
{
if (string.IsNullOrEmpty(phase)) return;
@@ -504,6 +571,14 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs);
// Historic replay (a previous enrollment's log) — do not emit at all. Placed BEFORE
// the sub-phase declaration, the timing bookkeeping and the terminal-signal dedup so
// a replayed app neither consumes the fire-once flags nor poisons _appTimings (which
// feeds FinalStatusBuilder) nor posts a phantom DecisionSignal. The early return also
// covers the shadow download_progress and the app_tracking_summary snapshot below.
if (SuppressIfHistoricReplay(derivedFromClock, rawSourceTs, $"app-state {oldState}->{newState}", app.Id))
return;
// 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
// phase; emission happens BEFORE the actual app_* event so the UI sees the phase
@@ -819,6 +894,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!;
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs);
// Historic replay — a week-old DO summary is not this enrollment's download.
if (SuppressIfHistoricReplay(derivedFromClock, rawSourceTs, SharedEventTypes.DoTelemetry, app.Id))
return;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
var label = string.IsNullOrEmpty(app.Name) ? app.Id : app.Name;
@@ -910,13 +990,27 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
now = ResolveOccurredAt(script.ExitObservedAtUtc, out derivedFromClock, out rawSourceTs);
else
now = ResolveOccurredAt(out derivedFromClock, out rawSourceTs);
// Historic replay (a previous enrollment's log) — do not emit at all. The early
// return also skips MaybeEmitBootstrapDetected / MaybeEmitScriptTimeoutSuspected,
// which would otherwise fire on week-old evidence.
if (SuppressIfHistoricReplay(derivedFromClock, rawSourceTs, eventType, script.PolicyId))
return;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
// Per-script run duration (start line → this completion, `now`). Surfaced on every
// Per-script run duration (start line → this completion). Surfaced on every
// script completion so the UI can flag slow / inefficient scripts, not just timed-out
// ones. Omitted when the start line was never observed (StartedAtUtc null); clamped at 0
// against clock skew between the (possibly clock-derived) completion stamp and start.
//
// When the completion timestamp was clock-derived because the source line's timestamp
// was rejected (future-skew CMTrace clock jump — the stale case never reaches here),
// `now` lives on the clock's timeline while StartedAtUtc was captured RAW from the
// source log. Mixing the two produced absurd durations (session eaf3d8c4: 170 h), so
// the duration uses the raw source pair — both ends on the same timeline, the
// difference is the true runtime. The event stamp stays `now` (timeline position).
//
// L19 (delta review 2026-07-02): the same field name carries two different semantics —
// start→own-end-signal (≈ script runtime) vs HS-SCRIPT-START→HS-NEW-RESULT (the whole
// cycle INCLUDING IME's 30 s–3 min batched reporting latency, i.e. systematically
@@ -924,10 +1018,16 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// consumers never compare the two as equals. The emitting handler stamps the basis on
// the state (health-script early-signal completions are script_runtime too); the
// scriptType fallback covers states from paths that predate the field.
var completionForDuration = derivedFromClock && rawSourceTs.HasValue
? NormalizeUtc(rawSourceTs.Value)
: now;
if (script.StartedAtUtc.HasValue)
{
var durationSeconds = (now - script.StartedAtUtc.Value).TotalSeconds;
if (durationSeconds >= 0)
var durationSeconds = (completionForDuration - script.StartedAtUtc.Value).TotalSeconds;
// Plausibility backstop: IME's script execution timeout is ~30 min; anything above
// 24 h is a cross-run artifact (e.g. a stale pending start slot from a previous
// enrollment paired with a fresh completion) — omit rather than lie.
if (durationSeconds >= 0 && durationSeconds <= StaleSourceThreshold.TotalSeconds)
{
data["durationSeconds"] = durationSeconds.ToString("F2", culture);
data["durationBasis"] = script.DurationBasis
@@ -979,7 +1079,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
$"ImeAdapter: script completed policyId={shortId} type={script.ScriptType ?? "?"} result={script.Result ?? "?"} exit={(script.ExitCode.HasValue ? script.ExitCode.Value.ToString() : "n/a")}");
MaybeEmitBootstrapDetected(script, now);
MaybeEmitScriptTimeoutSuspected(script, now);
MaybeEmitScriptTimeoutSuspected(script, now, completionForDuration);
}
/// <summary>
@@ -991,15 +1091,19 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
/// late start / pre-failed ESP. Advisory only: no state mutation, the underlying
/// <c>script_failed</c> is still emitted separately. Health (remediation) scripts are
/// excluded — they re-run on their own cadence and have a different timeout regime.
/// <paramref name="durationEndUtc"/> is the timeline-consistent completion for duration
/// math (raw source ts on rejected-timestamp emissions); <paramref name="occurredAtUtc"/>
/// stamps the emitted event.
/// </summary>
private void MaybeEmitScriptTimeoutSuspected(ScriptExecutionState script, DateTime completionUtc)
private void MaybeEmitScriptTimeoutSuspected(ScriptExecutionState script, DateTime occurredAtUtc, DateTime durationEndUtc)
{
if (IsRemediation(script.ScriptType)) return; // platform scripts only
if (!script.StartedAtUtc.HasValue) return; // no start ⇒ no duration
if (!string.Equals(script.Result, "Failed", StringComparison.OrdinalIgnoreCase)) return;
var duration = completionUtc - script.StartedAtUtc.Value;
var duration = durationEndUtc - script.StartedAtUtc.Value;
if (duration < ScriptTimeoutSuspectedThreshold) return;
if (duration > StaleSourceThreshold) return; // implausible — cross-run artifact, not a hung script
if (!_tracker.TryClaimScriptTimeoutSuspected(script.PolicyId)) return; // restart-safe dedup per policyId (persisted tracker state)
@@ -1026,7 +1130,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
message: $"Platform script {shortId} ran {durationMinutes:F0} min and was marked Failed — suspected IME script timeout blocking the enrollment.",
severity: EventSeverity.Warning,
data: data,
occurredAtUtc: completionUtc);
occurredAtUtc: occurredAtUtc);
_logger?.Info(
$"ImeAdapter: script_timeout_suspected policyId={shortId} duration={durationMinutes:F1}min result={script.Result} espPhase={espPhase ?? "(none)"}");
@@ -1081,6 +1185,12 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!;
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs);
// Historic replay — suppressing here also kills the immediateUpload flood the
// replayed batch caused (session eaf3d8c4: 3× ingress_backpressure).
if (SuppressIfHistoricReplay(derivedFromClock, rawSourceTs, SharedEventTypes.ScriptStarted, info.PolicyId))
return;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
var label = IsRemediation(info.ScriptType) ? "Health script" : "Platform script";
@@ -0,0 +1,382 @@
using System;
using System.Collections.Generic;
using System.Linq;
using AutopilotMonitor.DecisionCore.Engine;
using AutopilotMonitor.DecisionCore.Serialization;
using AutopilotMonitor.DecisionCore.Signals;
using AutopilotMonitor.DecisionCore.State;
using Xunit;
namespace AutopilotMonitor.DecisionCore.Tests
{
/// <summary>
/// Session 4910a5a5 (2026-07-23) — advisory recovery. Field failure: DeviceSetup/Apps
/// failed (culprit app never started installing), the advisory defang armed the
/// <c>advisory_completion</c> window, the user pressed "Try again" ~23 min later, the apps
/// re-ran to 10/10 and <c>DeviceSetupProvisioningComplete</c> arrived — yet the window
/// fired 30 min after the advisory and un-defanged the stale failure
/// (<c>enrollment_failed: esp_terminal_failure</c>) on a live enrollment mid-AccountSetup,
/// because the advisory variant was exempt from ALL re-arm/rebase guards. Coverage:
/// <list type="bullet">
/// <item>The advisory records the failed category + culprit apps.</item>
/// <item>A ProvisioningComplete of the SAME category sets the resolved fact + emits
/// <c>esp_failure_advisory_resolved</c>; a different category does not.</item>
/// <item>Deadline fire after recovery + enforcement progress → re-arm, not Failed.</item>
/// <item>Deadline fire after recovery without progress → Failed with the truthful
/// <c>esp_recovered_without_completion_evidence</c> reason and
/// LastFailureTrigger=DeadlineFired (likely-stuck promotion off).</item>
/// <item>Unrecovered advisory keeps the legacy un-defang exactly (regression guard).</item>
/// <item>Reboot re-bases a recovered-advisory window (and still does NOT touch an
/// unrecovered one).</item>
/// <item>Snapshot round-trip + census surfacing of the new facts.</item>
/// </list>
/// </summary>
public sealed class AdvisoryRecoveryTests
{
private static readonly DateTime T0 = new DateTime(2026, 7, 23, 3, 30, 0, DateTimeKind.Utc);
private static DecisionSignal MakeSignal(
long ordinal,
DecisionSignalKind kind,
DateTime occurredAtUtc,
IReadOnlyDictionary<string, string>? payload = null)
{
return new DecisionSignal(
sessionSignalOrdinal: ordinal,
sessionTraceOrdinal: ordinal,
kind: kind,
kindSchemaVersion: 1,
occurredAtUtc: occurredAtUtc,
sourceOrigin: "test",
evidence: new Evidence(EvidenceKind.Synthetic, $"{kind}-{ordinal}", "test"),
payload: payload);
}
private static DecisionSignal DeadlineFired(long ordinal, DateTime occurredAtUtc) =>
MakeSignal(ordinal, DecisionSignalKind.DeadlineFired, occurredAtUtc,
new Dictionary<string, string> { [SignalPayloadKeys.Deadline] = DeadlineNames.AdvisoryCompletion });
private static DecisionEffect? FindTimelineEffect(DecisionStep step, string eventType) =>
step.Effects.FirstOrDefault(e =>
e.Kind == DecisionEffectKind.EmitEventTimelineEntry
&& e.Parameters != null
&& e.Parameters.TryGetValue("eventType", out var et)
&& et == eventType);
private static ActiveDeadline? FindDeadline(DecisionState state, string name) =>
state.Deadlines.FirstOrDefault(d => d.Name == name);
/// <summary>
/// Replays the session-4910a5a5 shape up to (but excluding) the ESP terminal failure:
/// Classic UserDriven, ContinueAnyway profile, Hello disabled, DeviceSetup entered,
/// AccountSetup entered (04:18, BEFORE the 04:34 DeviceSetup/Apps failure — the IME
/// phase line landed while device apps were still at 9/10).
/// </summary>
private static DecisionState SetupSession(DecisionEngine engine)
{
var state = DecisionState.CreateInitial("sess-4910a5a5", "tenant-e46bc88e", T0);
state = engine.Reduce(state, MakeSignal(0, DecisionSignalKind.SessionStarted, T0)).NewState;
state = engine.Reduce(state, MakeSignal(
5, DecisionSignalKind.EspConfigDetected, T0.AddMinutes(1),
new Dictionary<string, string>
{
[SignalPayloadKeys.SkipUserEsp] = "false",
[SignalPayloadKeys.SkipDeviceEsp] = "false",
[SignalPayloadKeys.EspSyncFailureTimeoutMinutes] = "60",
[SignalPayloadKeys.EspAllowContinueAnyway] = "true",
})).NewState;
state = engine.Reduce(state, MakeSignal(
8, DecisionSignalKind.HelloPolicyDetected, T0.AddMinutes(2),
new Dictionary<string, string> { [SignalPayloadKeys.HelloEnabled] = "false" })).NewState;
state = engine.Reduce(state, MakeSignal(
10, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(6),
new Dictionary<string, string> { [SignalPayloadKeys.EspPhase] = "DeviceSetup" })).NewState;
state = engine.Reduce(state, MakeSignal(
20, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(48),
new Dictionary<string, string> { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState;
return state;
}
private static DecisionStep ApplyDeviceSetupAppsFailure(DecisionEngine engine, DecisionState state, long ordinal = 50) =>
engine.Reduce(state, MakeSignal(
ordinal, DecisionSignalKind.EspTerminalFailure, T0.AddMinutes(64),
new Dictionary<string, string>
{
["failureType"] = "Provisioning_DeviceSetup_Apps_Failed",
["failedSubcategory"] = "Apps",
["category"] = "DeviceSetup",
["likelyCulpritApps"] = "Oriflame Cosmectics - Teams Backgroundsv v2",
["likelyCulpritAppCount"] = "1",
}));
private static DecisionStep ApplyDeviceSetupResolved(DecisionEngine engine, DecisionState state, long ordinal = 60) =>
engine.Reduce(state, MakeSignal(
ordinal, DecisionSignalKind.DeviceSetupProvisioningComplete, T0.AddMinutes(87)));
// ================================================== advisory arming context ====
[Fact]
public void Advisory_RecordsFailedCategory_AndCulpritApps()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
var step = ApplyDeviceSetupAppsFailure(engine, state);
Assert.NotNull(step.NewState.EspAdvisoryFailureRecordedUtc);
Assert.Equal("DeviceSetup", step.NewState.EspAdvisoryFailureCategory?.Value);
Assert.Null(step.NewState.EspAdvisoryFailureResolvedUtc);
var advisory = FindTimelineEffect(step, "esp_failure_advisory");
Assert.NotNull(advisory);
Assert.Equal("Oriflame Cosmectics - Teams Backgroundsv v2", advisory!.Parameters!["likelyCulpritApps"]);
}
// ===================================================== recovery hook ====
[Fact]
public void DeviceSetupComplete_SameCategory_ResolvesAdvisory_AndEmitsStoryEvent()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
var step = ApplyDeviceSetupResolved(engine, state);
Assert.NotNull(step.NewState.EspAdvisoryFailureResolvedUtc);
Assert.Equal(60, step.NewState.EspAdvisoryFailureResolvedUtc!.SourceSignalOrdinal);
// The anchor itself stays — the advisory happened; it just no longer blocks.
Assert.NotNull(step.NewState.EspAdvisoryFailureRecordedUtc);
var resolved = FindTimelineEffect(step, "esp_failure_advisory_resolved");
Assert.NotNull(resolved);
Assert.Equal("DeviceSetup", resolved!.Parameters!["category"]);
Assert.Equal("23", resolved.Parameters["minutesSinceAdvisory"]);
}
[Fact]
public void DeviceSetupComplete_DifferentCategory_DoesNotResolve()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
// Advisory for AccountSetup — DeviceSetup resolving must not defuse it.
state = engine.Reduce(state, MakeSignal(
50, DecisionSignalKind.EspTerminalFailure, T0.AddMinutes(64),
new Dictionary<string, string>
{
["failureType"] = "Provisioning_AccountSetup_Apps_Failed",
["failedSubcategory"] = "Apps",
["category"] = "AccountSetup",
})).NewState;
var step = ApplyDeviceSetupResolved(engine, state);
Assert.Null(step.NewState.EspAdvisoryFailureResolvedUtc);
Assert.Null(FindTimelineEffect(step, "esp_failure_advisory_resolved"));
}
[Fact]
public void DeviceSetupComplete_Duplicate_ResolvesOnlyOnce()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
// Post-reboot duplicate (AnchorAlreadySet passthrough branch).
var duplicate = engine.Reduce(state, MakeSignal(
65, DecisionSignalKind.DeviceSetupProvisioningComplete, T0.AddMinutes(92)));
Assert.Equal(60, duplicate.NewState.EspAdvisoryFailureResolvedUtc!.SourceSignalOrdinal);
Assert.Null(FindTimelineEffect(duplicate, "esp_failure_advisory_resolved"));
}
// ================================================ deadline fire semantics ====
[Fact]
public void DeadlineFire_AfterRecovery_WithEnforcementProgress_ReArmsInsteadOfFailing()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
// Post-reboot IME re-assert of AccountSetup (session shape: 05:02:59, ordinal 654)
// — user-phase enforcement demonstrably progressed since the arming at ordinal 50.
state = engine.Reduce(state, MakeSignal(
70, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(92),
new Dictionary<string, string> { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState;
var step = engine.Reduce(state, DeadlineFired(80, T0.AddMinutes(94)));
// Not failed — the window re-arms with fresh baselines instead.
Assert.Null(step.NewState.Outcome);
Assert.NotEqual(SessionStage.Failed, step.NewState.Stage);
var rearmed = FindDeadline(step.NewState, DeadlineNames.AdvisoryCompletion);
Assert.NotNull(rearmed);
Assert.Equal(T0.AddMinutes(94).AddMinutes(30), rearmed!.DueAtUtc);
Assert.Contains(step.Effects, e => e.Kind == DecisionEffectKind.ScheduleDeadline);
}
[Fact]
public void DeadlineFire_AfterRecovery_NoProgress_FailsWithRecoveredReason()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
var step = engine.Reduce(state, DeadlineFired(80, T0.AddMinutes(94)));
Assert.Equal(SessionStage.Failed, step.NewState.Stage);
Assert.Equal(SessionOutcome.EnrollmentFailed, step.NewState.Outcome);
var failed = FindTimelineEffect(step, "enrollment_failed");
Assert.NotNull(failed);
// Truthful reason: the original failure recovered — do not blame it.
Assert.Equal("esp_recovered_without_completion_evidence", failed!.Parameters!["reason"]);
Assert.Equal("true", failed.Parameters["failureRecovered"]);
Assert.Equal("advisory_recovered_window_expired_without_completion_evidence", failed.Parameters["advisoryReason"]);
// Likely-stuck app promotion stays off: apps are not stuck, they succeeded.
Assert.Equal(nameof(DecisionSignalKind.DeadlineFired), step.NewState.LastFailureTrigger?.Value);
}
[Fact]
public void DeadlineFire_WithoutRecovery_KeepsLegacyUndefang()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
// No recovery — even with enforcement progress the advisory variant must
// un-defang exactly as before (its anchor failure never un-happened).
state = engine.Reduce(state, MakeSignal(
70, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(92),
new Dictionary<string, string> { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState;
var step = engine.Reduce(state, DeadlineFired(80, T0.AddMinutes(94)));
Assert.Equal(SessionStage.Failed, step.NewState.Stage);
var failed = FindTimelineEffect(step, "enrollment_failed");
Assert.NotNull(failed);
Assert.Equal("esp_terminal_failure", failed!.Parameters!["reason"]);
Assert.Equal(nameof(DecisionSignalKind.EspTerminalFailure), step.NewState.LastFailureTrigger?.Value);
}
// ======================================================= reboot rebase ====
[Fact]
public void Reboot_AfterRecovery_RebasesAdvisoryWindow()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
var step = engine.Reduce(state, MakeSignal(
70, DecisionSignalKind.SystemRebootObserved, T0.AddMinutes(92)));
Assert.Contains(step.Effects, e =>
e.Kind == DecisionEffectKind.CancelDeadline
&& e.CancelDeadlineName == DeadlineNames.AdvisoryCompletion);
var rebased = FindDeadline(step.NewState, DeadlineNames.AdvisoryCompletion);
Assert.NotNull(rebased);
Assert.Equal(T0.AddMinutes(92).AddMinutes(30), rebased!.DueAtUtc);
}
[Fact]
public void Reboot_WithoutRecovery_DoesNotTouchAdvisoryWindow()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
var originalDue = FindDeadline(state, DeadlineNames.AdvisoryCompletion)!.DueAtUtc;
var step = engine.Reduce(state, MakeSignal(
70, DecisionSignalKind.SystemRebootObserved, T0.AddMinutes(92)));
Assert.DoesNotContain(step.Effects, e => e.Kind == DecisionEffectKind.CancelDeadline);
Assert.Equal(originalDue, FindDeadline(step.NewState, DeadlineNames.AdvisoryCompletion)!.DueAtUtc);
}
// ============================================== full session-4910a5a5 replay ====
[Fact]
public void Session4910a5a5_FailureRecoveryRebootFire_DoesNotFailTheLiveEnrollment()
{
// Field ordinals: 527 EspTerminalFailure → 611 DeviceSetupProvisioningComplete
// (post "Try again", apps 10/10) → 635 SystemRebootObserved → 654 AccountSetup
// re-assert → 671 DeadlineFired. Pre-fix outcome: enrollment_failed at the fire.
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state, ordinal: 527).NewState;
state = ApplyDeviceSetupResolved(engine, state, ordinal: 611).NewState;
state = engine.Reduce(state, MakeSignal(
635, DecisionSignalKind.SystemRebootObserved, T0.AddMinutes(92))).NewState;
state = engine.Reduce(state, MakeSignal(
654, DecisionSignalKind.EspPhaseChanged, T0.AddMinutes(93),
new Dictionary<string, string> { [SignalPayloadKeys.EspPhase] = "AccountSetup" })).NewState;
var step = engine.Reduce(state, DeadlineFired(671, T0.AddMinutes(94)));
Assert.Null(step.NewState.Outcome);
Assert.NotEqual(SessionStage.Failed, step.NewState.Stage);
Assert.NotNull(FindDeadline(step.NewState, DeadlineNames.AdvisoryCompletion));
}
// =============================================== serialization + census ====
[Fact]
public void SnapshotRoundTrip_PreservesRecoveryFacts()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
var roundtripped = StateSerializer.Deserialize(StateSerializer.Serialize(state));
Assert.Equal("DeviceSetup", roundtripped.EspAdvisoryFailureCategory?.Value);
Assert.Equal(state.EspAdvisoryFailureResolvedUtc!.Value, roundtripped.EspAdvisoryFailureResolvedUtc?.Value);
Assert.Equal(state.EspAdvisoryFailureResolvedUtc.SourceSignalOrdinal, roundtripped.EspAdvisoryFailureResolvedUtc?.SourceSignalOrdinal);
}
[Fact]
public void LegacySnapshot_WithoutRecoveryFacts_DeserializesToNull()
{
// Simulate a snapshot written by a pre-fix agent: strip the new properties from
// the JSON entirely — deserialization must default them to null (additive compat).
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
var legacy = Newtonsoft.Json.Linq.JObject.Parse(StateSerializer.Serialize(state));
foreach (var prop in legacy.Properties()
.Where(p => p.Name.IndexOf("EspAdvisoryFailureResolved", StringComparison.OrdinalIgnoreCase) >= 0
|| p.Name.IndexOf("EspAdvisoryFailureCategory", StringComparison.OrdinalIgnoreCase) >= 0)
.ToList())
{
prop.Remove();
}
var roundtripped = StateSerializer.Deserialize(legacy.ToString());
Assert.Null(roundtripped.EspAdvisoryFailureResolvedUtc);
Assert.Null(roundtripped.EspAdvisoryFailureCategory);
// The pre-existing advisory anchor still round-trips.
Assert.NotNull(roundtripped.EspAdvisoryFailureRecordedUtc);
}
[Fact]
public void Census_SurfacesAdvisoryResolved()
{
var engine = new DecisionEngine();
var state = SetupSession(engine);
state = ApplyDeviceSetupAppsFailure(engine, state).NewState;
state = ApplyDeviceSetupResolved(engine, state).NewState;
var census = DecisionStateSignalCensus.Build(state);
Assert.Contains("esp_advisory_failure_resolved", census.SignalsSeen);
Assert.True(census.SignalTimestamps.ContainsKey("espAdvisoryFailureResolved"));
}
}
}
@@ -114,7 +114,10 @@ namespace AutopilotMonitor.DecisionCore.Tests
// state-change-only dedupe anchor for the completion_waiting event → 17.
// Session 772fe502 (2026-07-13) added `helloWizardStartedUtc` — genuine
// Shell-Core 62404 wizard launch; vetoes the policy-disabled Hello skip → 18.
Assert.Equal(18, facts.Count);
// Session 4910a5a5 (2026-07-23) added `espAdvisoryFailureResolvedUtc` (the failed
// category recovered — lifts the advisory's re-arm/rebase guard exemption) and
// `espAdvisoryFailureCategory` (which category the advisory was for) → 20.
Assert.Equal(20, facts.Count);
Assert.All(facts.Values, v => Assert.Null(v));
}
@@ -236,10 +239,12 @@ namespace AutopilotMonitor.DecisionCore.Tests
// `completionWaitingFingerprint` as the state-change-only dedupe anchor for
// the completion_waiting event → 17. Session 772fe502 (2026-07-13) added
// `helloWizardStartedUtc` — the genuine Shell-Core 62404 wizard-launch fact
// that vetoes/retracts the policy-disabled Hello skip → 18. If this number
// ever changes, both the count expectation AND the actual snapshot output
// need to evolve in lockstep.
Assert.Equal(18, expectedFactKeys.Count);
// that vetoes/retracts the policy-disabled Hello skip → 18. Session 4910a5a5
// (2026-07-23) added `espAdvisoryFailureResolvedUtc` + `espAdvisoryFailureCategory`
// — advisory-recovery facts that lift the AdvisoryCompletion guard exemption → 20.
// If this number ever changes, both the count expectation AND the actual snapshot
// output need to evolve in lockstep.
Assert.Equal(20, expectedFactKeys.Count);
var snapshot = DecisionStateSnapshotBuilder.Build(DecisionState.CreateInitial("s", "t"));
var facts = (Dictionary<string, object?>)snapshot["facts"]!;
@@ -0,0 +1,107 @@
using AutopilotMonitor.Functions.Services;
using AutopilotMonitor.Shared.Models;
using Xunit;
namespace AutopilotMonitor.Functions.Tests;
/// <summary>
/// Session eaf3d8c4 (2026-07-23): a previous enrollment's IME log surviving on disk made the
/// agent replay a week-old script history — 156 replayed <c>script_completed</c> events
/// inflated the session's RemediationScriptCount. Newer agents suppress the replay at the
/// source; this predicate covers the fleet of not-yet-updated agents by skipping the script
/// counter increment for events whose <c>rejectedSourceTimestamp</c> (the source log line's
/// own time, preserved by the agent's staleness clamp) is more than 24 h older than the
/// event's clock-clamped stamp.
/// </summary>
public class IngestHistoricImeReplayTests
{
private static readonly DateTime EventStamp = new(2026, 7, 23, 15, 42, 0, DateTimeKind.Utc);
private static EnrollmentEvent ScriptEvent(object? rejectedSourceTimestamp, bool includeKey = true)
{
var evt = new EnrollmentEvent
{
EventType = "script_completed",
Timestamp = EventStamp,
Data = new Dictionary<string, object> { ["scriptType"] = "remediation" },
};
if (includeKey)
evt.Data["rejectedSourceTimestamp"] = rejectedSourceTimestamp!;
return evt;
}
[Fact]
public void StaleRejectedSourceTimestamp_IsHistoricReplay()
{
var evt = ScriptEvent(EventStamp.AddDays(-7).ToString("o"));
Assert.True(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Fact]
public void StaleAppInstallEvent_IsHistoricReplay()
{
// The predicate is event-type-agnostic — it also guards AggregateAppInstallEvent
// (AppInstallSummaries would otherwise be overwritten with week-old runs).
var evt = new EnrollmentEvent
{
EventType = "app_install_completed",
Timestamp = EventStamp,
Data = new Dictionary<string, object>
{
["appName"] = "Contoso App",
["rejectedSourceTimestamp"] = EventStamp.AddDays(-7).ToString("o"),
},
};
Assert.True(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Fact]
public void JustOver24h_IsHistoricReplay()
{
var evt = ScriptEvent(EventStamp.AddHours(-25).ToString("o"));
Assert.True(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Fact]
public void Within24h_IsNotHistoricReplay()
{
var evt = ScriptEvent(EventStamp.AddHours(-23).ToString("o"));
Assert.False(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Fact]
public void FutureSkewRejection_IsNotHistoricReplay()
{
// A rejected source timestamp AHEAD of the event stamp is a mid-enrollment clock
// jump (WhiteGlove +1h CMTrace skew), not replayed history.
var evt = ScriptEvent(EventStamp.AddHours(2).ToString("o"));
Assert.False(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Fact]
public void MissingKey_IsNotHistoricReplay()
{
Assert.False(EventIngestProcessor.IsHistoricImeReplay(ScriptEvent(null, includeKey: false)));
}
[Fact]
public void NullData_IsNotHistoricReplay()
{
var evt = new EnrollmentEvent { EventType = "script_completed", Timestamp = EventStamp, Data = null! };
Assert.False(EventIngestProcessor.IsHistoricImeReplay(evt));
}
[Theory]
[InlineData("")]
[InlineData("not-a-date")]
public void UnparseableValue_IsNotHistoricReplay(string raw)
{
Assert.False(EventIngestProcessor.IsHistoricImeReplay(ScriptEvent(raw)));
}
[Fact]
public void NullEvent_IsNotHistoricReplay()
{
Assert.False(EventIngestProcessor.IsHistoricImeReplay(null));
}
}
@@ -22,6 +22,13 @@ namespace AutopilotMonitor.Functions.Services
if (!isRelevant) return;
// Legacy-agent stale-replay guard (session eaf3d8c4): app events replayed from a
// previous enrollment's IME log carry a rejectedSourceTimestamp > 24 h older than
// the event stamp. They would create/overwrite this session's AppInstallSummaries
// rows with week-old runs. The fixed agent suppresses them at the source; this
// covers agents not yet rolled out.
if (IsHistoricImeReplay(evt)) return;
var appName = evt.Data?.ContainsKey("appName") == true ? evt.Data["appName"]?.ToString()?.Trim() : null;
if (string.IsNullOrEmpty(appName)) return;
@@ -82,6 +82,13 @@ namespace AutopilotMonitor.Functions.Services
break;
case "script_completed":
case "script_failed":
// Legacy-agent stale-replay guard: events flagged with a
// rejectedSourceTimestamp > 24 h older than the event stamp are replayed
// history from a previous enrollment (session eaf3d8c4 inflated
// RemediationScriptCount to 156 in a 7-min session). The fixed agent
// suppresses them at the source; this covers agents not yet rolled out.
if (IsHistoricImeReplay(evt))
break;
var scriptType = evt.Data?.ContainsKey("scriptType") == true
? evt.Data["scriptType"]?.ToString() : null;
if (string.Equals(scriptType, "platform", StringComparison.OrdinalIgnoreCase))
@@ -119,6 +126,28 @@ namespace AutopilotMonitor.Functions.Services
return string.Equals(reason, "max_lifetime", StringComparison.OrdinalIgnoreCase);
}
/// <summary>
/// True for an agent event whose <c>Data.rejectedSourceTimestamp</c> is more than 24 h
/// older than the event's own (clock-clamped) timestamp: the agent replayed IME log
/// content from a previous enrollment that survived on disk. Such runs happened days ago
/// and must not count as this session's script executions. A rejected source timestamp
/// in the FUTURE (negative difference) is a mid-enrollment clock jump, not a replay.
/// The 24 h bound mirrors the agent's source-timestamp staleness clamp.
/// </summary>
internal static bool IsHistoricImeReplay(EnrollmentEvent? evt)
{
if (evt?.Data == null || !evt.Data.ContainsKey("rejectedSourceTimestamp"))
return false;
var raw = evt.Data["rejectedSourceTimestamp"]?.ToString();
if (string.IsNullOrEmpty(raw))
return false;
if (!DateTime.TryParse(raw, System.Globalization.CultureInfo.InvariantCulture,
System.Globalization.DateTimeStyles.AssumeUniversal | System.Globalization.DateTimeStyles.AdjustToUniversal,
out var rejected))
return false;
return evt.Timestamp - rejected > TimeSpan.FromHours(24);
}
/// <summary>
/// True for an <c>enrollment_failed</c> event whose <c>Data.failureType</c> is
/// <c>agent_timeout</c> — the V1-parity companion of the max-lifetime watchdog shutdown
@@ -0,0 +1,53 @@
/**
* Historic-replay predicate (session eaf3d8c4): legacy agents replay IME log content from a
* previous enrollment; the replayed events carry `data.rejectedSourceTimestamp` > 24 h older
* than the event stamp. `get_session_summary` filters them out so appInstalls counts,
* errorCount (replayed app_install_failed are Error-severity) and the keyEvents triage
* timeline reflect only this enrollment's activity.
*/
import { describe, it, expect } from 'vitest';
import { isHistoricImeReplay } from '../tools/sessions.js';
const BASE = Date.UTC(2026, 6, 23, 15, 42, 0);
const DAY_MS = 24 * 60 * 60 * 1000;
const evt = (rejected?: unknown, timestamp: string = new Date(BASE).toISOString()): Record<string, unknown> => ({
timestamp,
eventType: 'app_install_completed',
data: rejected === undefined ? {} : { rejectedSourceTimestamp: rejected },
});
describe('isHistoricImeReplay', () => {
it('detects a rejected source timestamp > 24h older than the event stamp', () => {
expect(isHistoricImeReplay(evt(new Date(BASE - 7 * DAY_MS).toISOString()))).toBe(true);
expect(isHistoricImeReplay(evt(new Date(BASE - 25 * 60 * 60 * 1000).toISOString()))).toBe(true);
});
it('keeps within-24h rejections', () => {
expect(isHistoricImeReplay(evt(new Date(BASE - 23 * 60 * 60 * 1000).toISOString()))).toBe(false);
});
it('keeps future-skew rejections (clock jump, not replay)', () => {
expect(isHistoricImeReplay(evt(new Date(BASE + 2 * 60 * 60 * 1000).toISOString()))).toBe(false);
});
it('keeps events without or with malformed rejectedSourceTimestamp', () => {
expect(isHistoricImeReplay(evt())).toBe(false);
expect(isHistoricImeReplay(evt(''))).toBe(false);
expect(isHistoricImeReplay(evt('not-a-date'))).toBe(false);
expect(isHistoricImeReplay(evt(12345))).toBe(false);
expect(isHistoricImeReplay({ timestamp: new Date(BASE).toISOString() })).toBe(false);
});
it('keeps events with an unparseable event timestamp', () => {
expect(isHistoricImeReplay(evt(new Date(BASE - 7 * DAY_MS).toISOString(), 'garbage'))).toBe(false);
});
it('reads the snake_case wire variant', () => {
const e = {
timestamp: new Date(BASE).toISOString(),
data: { rejected_source_timestamp: new Date(BASE - 7 * DAY_MS).toISOString() },
};
expect(isHistoricImeReplay(e)).toBe(true);
});
});
@@ -23,6 +23,9 @@ export const EVENT_TYPES_CATALOG = {
'esp_failure_advisory',
'esp_failure_settle_started',
'esp_failure_settle_recovered',
'esp_failure_retry_detected',
'esp_failure_recovered',
'esp_failure_advisory_resolved',
'esp_exiting',
'mdm_policy_reboot_required',
'esp_config_detected',
@@ -77,7 +80,7 @@ export const EVENT_TYPES_CATALOG = {
'office_install_failed',
'office_preinstalled_detected',
],
script_events: ['script_started', 'script_completed', 'script_failed', 'script_timeout_suspected'],
script_events: ['script_started', 'script_completed', 'script_failed', 'script_timeout_suspected', 'historic_ime_replay_detected'],
network_events: [
'network_state_change',
'network_connectivity_check',
@@ -28,7 +28,8 @@ export const KEY_EVENT_TYPES = new Set([
'enrollment_complete', 'enrollment_failed', 'completion_check',
'desktop_arrived', 'hello_policy_detected', 'waiting_for_hello', 'hello_completion_timeout',
'agent_started', 'agent_shutdown', 'agent_shutting_down', 'agent_trace',
'script_started', 'script_completed', 'script_failed', 'vulnerability_report',
'script_started', 'script_completed', 'script_failed', 'historic_ime_replay_detected',
'vulnerability_report',
]);
// Phase-defining events promoted to the top of the triage timeline. Module-level
// (not handler-local) so the same drift test can validate it.
@@ -36,6 +37,27 @@ export const PHASE_EVENT_TYPES = new Set([
'phase_transition', 'esp_phase_changed', 'enrollment_type_detected',
'enrollment_complete', 'enrollment_failed', 'desktop_arrived',
]);
// Mirrors the agent's 24 h source-timestamp staleness clamp (session eaf3d8c4).
const HISTORIC_REPLAY_THRESHOLD_MS = 24 * 60 * 60 * 1000;
/**
* True when an event is replayed history from a previous enrollment: legacy agents replay
* IME log content surviving a re-enrollment, stamping the rejected source-line time as
* `data.rejectedSourceTimestamp` — more than 24 h older than the event stamp means the
* activity happened during a previous enrollment. Newer agents suppress these at the
* source; this filter covers sessions recorded by older agents. A rejected timestamp in
* the FUTURE (clock jump) is genuine current activity and passes through. Exported so the
* unit tests can pin the predicate.
*/
export function isHistoricImeReplay(e: Record<string, unknown>): boolean {
const data = e.data as Record<string, unknown> | undefined;
const rejected = data?.rejectedSourceTimestamp ?? data?.rejected_source_timestamp;
if (typeof rejected !== 'string' || rejected.length === 0) return false;
const rej = Date.parse(rejected);
const ts = Date.parse(String(e.timestamp ?? ''));
return Number.isFinite(rej) && Number.isFinite(ts) && ts - rej > HISTORIC_REPLAY_THRESHOLD_MS;
}
// Permissive ISO-8601 guard: rejects unparseable junk (which the backend would
// silently treat as no filter) while still accepting the date-only and
// timezone-offset forms the backend honors.
@@ -482,7 +504,12 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated:
: null,
};
const allEvents = (eventsData?.events ?? []) as Array<Record<string, unknown>>;
// Historic-replay filter: replayed app_install_failed events are Error-severity and
// would inflate errorCount; replayed app_install_* would inflate the appInstalls
// stats; replayed events would pollute the keyEvents triage timeline. One filter
// cleans all three. stats.totalEvents therefore counts non-replayed events.
const allEvents = ((eventsData?.events ?? []) as Array<Record<string, unknown>>)
.filter((e) => !isHistoricImeReplay(e));
let errorCount = 0;
let warningCount = 0;
@@ -73,6 +73,11 @@ namespace AutopilotMonitor.DecisionCore.Engine
/// The advisory variant (<see cref="DecisionState.EspAdvisoryFailureRecordedUtc"/>
/// set) is deliberately NOT touched: its anchor is a real ESP terminal failure and
/// a reboot does not un-happen that failure — the window must still un-defang it.
/// EXCEPTION (session 4910a5a5, 2026-07-23): when
/// <see cref="DecisionState.EspAdvisoryFailureResolvedUtc"/> is set the failed
/// category demonstrably recovered to success — the failure DID un-happen, and a
/// reboot mid-recovery (ESP continuing into AccountSetup) must re-base the window
/// exactly like the esp-exit variant instead of letting it fail a live enrollment.
/// </para>
/// Returns the effects (cancel + schedule + a fingerprint-bypassing
/// <c>completion_waiting</c> carrying the re-based due-time, mirroring the
@@ -84,7 +89,9 @@ namespace AutopilotMonitor.DecisionCore.Engine
DecisionStateBuilder builder,
DecisionSignal signal)
{
if (state.EspAdvisoryFailureRecordedUtc != null || !HasAdvisoryCompletionDeadline(state))
var unresolvedAdvisoryAnchored = state.EspAdvisoryFailureRecordedUtc != null
&& state.EspAdvisoryFailureResolvedUtc == null;
if (unresolvedAdvisoryAnchored || !HasAdvisoryCompletionDeadline(state))
{
return Array.Empty<DecisionEffect>();
}
@@ -139,6 +146,10 @@ namespace AutopilotMonitor.DecisionCore.Engine
"mayHaveContinuedAnyway",
"continueAnywayHint",
"advisoryReason",
// Session 4910a5a5 — recovery story context.
"failureRecovered",
"likelyCulpritApps",
"likelyCulpritAppCount",
};
/// <summary>
@@ -408,10 +419,17 @@ namespace AutopilotMonitor.DecisionCore.Engine
string reason,
Dictionary<string, string> parameters)
{
// Session 4910a5a5: remember WHICH category failed so the recovery hook
// (TryResolveAdvisoryOnCategoryRecovery) can later match a ProvisioningComplete
// signal of the same category against this advisory. Absent on event-log-derived
// failures — the hook then never matches.
string? failedCategory = null;
signal.Payload?.TryGetValue("category", out failedCategory);
var builder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal)
.WithEspAdvisoryFailureRecorded(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
.WithEspAdvisoryFailureRecorded(signal.OccurredAtUtc, signal.SessionSignalOrdinal, failedCategory);
// Stage / Outcome deliberately untouched — monitoring continues. The session's
// normal completion paths (Hello/Desktop, IME pattern, AccountSetup provisioning
@@ -454,6 +472,63 @@ namespace AutopilotMonitor.DecisionCore.Engine
return new DecisionStep(newState, transition, effects);
}
/// <summary>
/// Session 4910a5a5 (2026-07-23) — recovery hook for a defanged ESP failure. When a
/// <c>DeviceSetupProvisioningComplete</c> / <c>AccountSetupProvisioningComplete</c>
/// signal reports the SAME category the advisory failure was recorded for, the failure
/// demonstrably un-happened (DeviceSetup/Apps failed → user pressed "Try again" ~23 min
/// later → apps re-ran to 10/10 → category resolved). Sets the set-once
/// <see cref="DecisionState.EspAdvisoryFailureResolvedUtc"/> fact on
/// <paramref name="builder"/> and returns an <c>esp_failure_advisory_resolved</c>
/// timeline effect telling the recovery story; returns null (builder untouched) when
/// there is no advisory, it is already resolved, or the category does not match.
/// <para>
/// The fact lifts the advisory variant's exemption from the AdvisoryCompletion
/// re-arm/rebase guards (see <see cref="HandleAdvisoryCompletionDeadlineFired"/> and
/// <see cref="RebaseEspExitVariantAdvisoryWindowOnReboot"/>) — without it the window
/// un-defangs the stale failure and fails a live enrollment mid-AccountSetup.
/// </para>
/// </summary>
private static DecisionEffect? TryResolveAdvisoryOnCategoryRecovery(
DecisionState state,
DecisionStateBuilder builder,
DecisionSignal signal,
string resolvedCategory)
{
if (state.EspAdvisoryFailureRecordedUtc == null) return null;
if (state.EspAdvisoryFailureResolvedUtc != null) return null;
var advisoryCategory = state.EspAdvisoryFailureCategory?.Value;
if (!string.Equals(advisoryCategory, resolvedCategory, StringComparison.OrdinalIgnoreCase))
{
return null;
}
builder.WithEspAdvisoryFailureResolved(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
var minutesSinceAdvisory = Math.Max(0,
(int)Math.Round((signal.OccurredAtUtc - state.EspAdvisoryFailureRecordedUtc.Value).TotalMinutes));
var continueAnywayAllowed = state.ScenarioObservations?.EspAllowContinueAnyway?.Value == true;
var parameters = new Dictionary<string, string>
{
["eventType"] = SharedConstants.EventTypes.EspFailureAdvisoryResolved,
["source"] = "DecisionEngine",
["severity"] = "Info",
["immediateUpload"] = "false",
["message"] = $"ESP failure advisory resolved: {resolvedCategory} completed successfully "
+ $"{minutesSinceAdvisory} min after the advisory — the ESP re-ran the failed step "
+ "(consistent with a user-initiated retry on the ESP failure page"
+ (continueAnywayAllowed ? "; the profile allows Try again / Continue anyway" : "")
+ "). The earlier failure no longer blocks completion.",
["category"] = resolvedCategory,
["minutesSinceAdvisory"] = minutesSinceAdvisory.ToString(CultureInfo.InvariantCulture),
["espAllowContinueAnyway"] = continueAnywayAllowed ? "true" : "false",
};
return new DecisionEffect(DecisionEffectKind.EmitEventTimelineEntry, parameters: parameters);
}
/// <summary>
/// <see cref="DeadlineNames.AdvisoryCompletion"/> fired — the resolution window after a
/// completion dead-end expired without one of the normal completion paths terminating
@@ -511,6 +586,12 @@ namespace AutopilotMonitor.DecisionCore.Engine
var deadlineStillArmed = armedDeadline != null;
var hasAdvisoryAnchor = state.EspAdvisoryFailureRecordedUtc != null;
// Session 4910a5a5: once the failed category demonstrably recovered
// (TryResolveAdvisoryOnCategoryRecovery set the fact), the advisory variant's
// "a real ESP terminal failure does not un-happen" premise is disproven — the
// guards below that protect live enrollments (enforcement-progress re-arm,
// hello-never-observed promote) apply to it again.
var advisoryResolved = state.EspAdvisoryFailureResolvedUtc != null;
// Presence-only anchor (L5, delta review 2026-07-02). The esp-exit arming site only
// runs when AccountSetupEnteredUtc is already set, so both facts being present is
// the anchor; `deadlineStillArmed` below is what rejects stray timer fires. The old
@@ -635,8 +716,13 @@ namespace AutopilotMonitor.DecisionCore.Engine
// When user-phase enforcement demonstrably progressed since arming, the dead-end
// shape is disproven: re-arm a fresh window with updated baselines instead of
// failing a live enrollment mid-install. The advisory variant is exempt — its
// anchor is a real ESP terminal failure that a busy IME does not un-happen.
if (!hasAdvisoryAnchor && HasEnforcementProgressSinceArming(state, armedDeadline!))
// anchor is a real ESP terminal failure that a busy IME does not un-happen —
// UNLESS the failed category later resolved to success (session 4910a5a5:
// DeviceSetup/Apps failed, user retried, apps reached 10/10, DeviceSetup resolved
// — the failure DID un-happen, so a live AccountSetup must not be failed on the
// stale advisory). Convergent either way: each re-arm renews the baselines, so a
// session that stalls after the recovery still fails one window later.
if ((!hasAdvisoryAnchor || advisoryResolved) && HasEnforcementProgressSinceArming(state, armedDeadline!))
{
var rearmedDeadline = BuildAdvisoryCompletionDeadline(state, signal);
builder.AddDeadline(rearmedDeadline);
@@ -692,7 +778,7 @@ namespace AutopilotMonitor.DecisionCore.Engine
// through Finalizing. Deliberately does NOT require the IME user-session gate —
// the FP sessions never saw an IME user-session completion (that gate guards
// completion evidence, not user presence; presence is the DAD-validated desktop).
if (!hasAdvisoryAnchor
if ((!hasAdvisoryAnchor || advisoryResolved)
&& desktopArrived
&& state.HelloResolvedUtc == null
&& state.HelloPolicyEnabled == null
@@ -741,7 +827,30 @@ namespace AutopilotMonitor.DecisionCore.Engine
// stays the deadline, not EspTerminalFailure).
string reason;
Dictionary<string, string> parameters;
if (hasAdvisoryAnchor)
if (hasAdvisoryAnchor && advisoryResolved)
{
// Session 4910a5a5: the original ESP failure demonstrably recovered (failed
// category resolved to success after the advisory), so claiming
// `esp_terminal_failure` would blame a failure that un-happened. The device
// recovered its device phase but then produced no completion evidence for a
// whole (re-armed, progress-gated) window. LastFailureTrigger stays the
// deadline so the EnrollmentTerminationHandler's likely-stuck app promotion
// stays OFF — the apps are not stuck, they succeeded.
reason = "esp_recovered_without_completion_evidence";
parameters = BuildEspFailureParameters(
signal: signal,
reason: reason,
advisoryPath: false,
observations: state.ScenarioObservations);
parameters["advisoryReason"] = "advisory_recovered_window_expired_without_completion_evidence";
parameters["failureRecovered"] = "true";
if (state.EspAdvisoryFailureCategory != null)
{
parameters["category"] = state.EspAdvisoryFailureCategory.Value;
}
builder.WithLastFailureTrigger(nameof(DecisionSignalKind.DeadlineFired), signal.SessionSignalOrdinal);
}
else if (hasAdvisoryAnchor)
{
// Registry-derived failure context (failureType/errorCode/...) lived on the
// original signal and is already on the wire via the esp_failure_advisory
@@ -885,6 +994,12 @@ namespace AutopilotMonitor.DecisionCore.Engine
parameters["failedSubcategory"] = failedSubcategory;
if (signal.Payload.TryGetValue("category", out var category) && !string.IsNullOrEmpty(category))
parameters["category"] = category;
// Session 4910a5a5 — tracker-snapshotted culprit-app names for Apps failures,
// so the advisory/terminal event tells WHICH app ESP most likely failed on.
if (signal.Payload.TryGetValue("likelyCulpritApps", out var culpritApps) && !string.IsNullOrEmpty(culpritApps))
parameters["likelyCulpritApps"] = culpritApps;
if (signal.Payload.TryGetValue("likelyCulpritAppCount", out var culpritCount) && !string.IsNullOrEmpty(culpritCount))
parameters["likelyCulpritAppCount"] = culpritCount;
}
// FirstSync-derived ESP failure-handling settings — observable hint that
@@ -98,17 +98,28 @@ namespace AutopilotMonitor.DecisionCore.Engine
// was already armed (or already cancelled by AccountSetup). Pass-through.
if (state.DeviceSetupResolvedUtc != null)
{
var passthroughState = state.ToBuilder()
var passthroughBuilder = state.ToBuilder()
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal)
.Build();
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
// Session 4910a5a5 recovery hook: a duplicate arrival (e.g. the post-reboot
// registry re-read) can still be the first evidence that the advisory's failed
// category recovered — set-once + category-match inside the helper keep this
// a no-op everywhere else.
var passthroughResolveEffect = TryResolveAdvisoryOnCategoryRecovery(
state, passthroughBuilder, signal, resolvedCategory: "DeviceSetup");
var passthroughState = passthroughBuilder.Build();
var passthroughTransition = BuildTakenTransition(
before: state,
signal: signal,
toStage: state.Stage,
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.DeviceSetupProvisioningComplete) + ":AnchorAlreadySet");
return new DecisionStep(passthroughState, passthroughTransition, Array.Empty<DecisionEffect>());
return new DecisionStep(
passthroughState,
passthroughTransition,
passthroughResolveEffect != null
? new[] { passthroughResolveEffect }
: Array.Empty<DecisionEffect>());
}
// Step 2 — Set the DeviceSetupResolvedUtc anchor UNCONDITIONALLY. Even when Classic
@@ -119,6 +130,13 @@ namespace AutopilotMonitor.DecisionCore.Engine
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
builder.DeviceSetupResolvedUtc = new SignalFact<DateTime>(signal.OccurredAtUtc, signal.SessionSignalOrdinal);
// Session 4910a5a5 recovery hook: DeviceSetup resolving to success while a
// DeviceSetup advisory failure is on record means the failure un-happened (user
// "Try again" retry). Sets the set-once resolved fact + emits the
// esp_failure_advisory_resolved story event; no-op otherwise.
var advisoryResolveEffect = TryResolveAdvisoryOnCategoryRecovery(
state, builder, signal, resolvedCategory: "DeviceSetup");
// Step 3 — Classic-path short-circuit: AccountSetup already started. The DeviceOnly
// deadline is moot (already cancelled by HandleEspPhaseChangedV1's AccountSetup branch,
// or never armed under the new code). No deadline arm here.
@@ -136,7 +154,12 @@ namespace AutopilotMonitor.DecisionCore.Engine
toStage: state.Stage,
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.DeviceSetupProvisioningComplete) + ":AccountSetupAlreadyEntered");
return new DecisionStep(classicState, classicTransition, Array.Empty<DecisionEffect>());
return new DecisionStep(
classicState,
classicTransition,
advisoryResolveEffect != null
? new[] { advisoryResolveEffect }
: Array.Empty<DecisionEffect>());
}
// Step 4 — Arm the deadline. Cancel any existing DeviceOnlyEspDetection first
@@ -156,13 +179,14 @@ namespace AutopilotMonitor.DecisionCore.Engine
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.DeviceSetupProvisioningComplete) + ":DeadlineArmed");
var effects = new[]
var effects = new List<DecisionEffect>(3)
{
new DecisionEffect(DecisionEffectKind.CancelDeadline, cancelDeadlineName: DeadlineNames.DeviceOnlyEspDetection),
new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: deadline),
};
if (advisoryResolveEffect != null) effects.Add(advisoryResolveEffect);
return new DecisionStep(newState, transition, effects);
return new DecisionStep(newState, transition, effects.ToArray());
}
/// <summary>
@@ -836,6 +836,13 @@ namespace AutopilotMonitor.DecisionCore.Engine
.WithStepIndex(nextStep)
.WithLastAppliedSignalOrdinal(signal.SessionSignalOrdinal);
// Session 4910a5a5 recovery hook (AccountSetup counterpart): the user-phase
// category resolving to success while an AccountSetup advisory failure is on
// record means that failure un-happened. Sets the set-once resolved fact + emits
// the esp_failure_advisory_resolved story event; no-op otherwise.
var advisoryResolveEffect = TryResolveAdvisoryOnCategoryRecovery(
state, builder, signal, resolvedCategory: "AccountSetup");
var alreadyRecorded = state.AccountSetupProvisioningSucceededUtc != null;
if (!alreadyRecorded)
{
@@ -876,10 +883,10 @@ namespace AutopilotMonitor.DecisionCore.Engine
toStage: state.Stage,
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.AccountSetupProvisioningComplete));
return new DecisionStep(
newState,
transition,
waitingEffect != null ? new[] { waitingEffect } : Array.Empty<DecisionEffect>());
var noPromoteEffects = new List<DecisionEffect>(2);
if (advisoryResolveEffect != null) noPromoteEffects.Add(advisoryResolveEffect);
if (waitingEffect != null) noPromoteEffects.Add(waitingEffect);
return new DecisionStep(newState, transition, noPromoteEffects.ToArray());
}
// Deferred-completion parity (session caa6cf50 fix, 2026-06-11): when the strong gate
@@ -910,14 +917,18 @@ namespace AutopilotMonitor.DecisionCore.Engine
builder.CancelDeadline(DeadlineNames.HelloSafety);
}
var deferredLeadingEffects = new List<DecisionEffect>(2);
if (advisoryResolveEffect != null) deferredLeadingEffects.Add(advisoryResolveEffect);
if (helloSafetyCancelEffect != null) deferredLeadingEffects.Add(helloSafetyCancelEffect);
return CompleteThroughFinalizingOrDefer(
state: state,
signal: signal,
preparedBuilder: builder,
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.AccountSetupProvisioningComplete) + ":DeferredCompletion",
leadingEffects: helloSafetyCancelEffect != null
? new[] { helloSafetyCancelEffect }
leadingEffects: deferredLeadingEffects.Count > 0
? deferredLeadingEffects.ToArray()
: null);
}
@@ -946,12 +957,13 @@ namespace AutopilotMonitor.DecisionCore.Engine
nextStepIndex: nextStep,
trigger: nameof(DecisionSignalKind.AccountSetupProvisioningComplete) + ":DeferredPromote");
var promotedEffects = new[]
var promotedEffects = new List<DecisionEffect>(2)
{
new DecisionEffect(DecisionEffectKind.ScheduleDeadline, deadline: helloSafety),
};
if (advisoryResolveEffect != null) promotedEffects.Add(advisoryResolveEffect);
return new DecisionStep(promotedState, promotedTransition, promotedEffects);
return new DecisionStep(promotedState, promotedTransition, promotedEffects.ToArray());
}
/// <summary>
@@ -110,6 +110,17 @@ namespace AutopilotMonitor.DecisionCore.Engine
timestamps["imeUserSessionCompleted"] = FormatUtc(state.ImeUserSessionCompletedUtc.Value);
evidence["imeUserSessionCompleted"] = TimestampedEvidence(state.ImeUserSessionCompletedUtc);
}
// Session 4910a5a5 — the ESP category behind a defanged advisory failure later
// resolved to success (user "Try again" recovery). Surfaced so terminal audit
// trails show that the original failure demonstrably un-happened — the
// discriminant between "failed and stayed failed" and "failed, recovered, but
// produced no completion evidence".
if (state.EspAdvisoryFailureResolvedUtc != null)
{
seen.Add("esp_advisory_failure_resolved");
timestamps["espAdvisoryFailureResolved"] = FormatUtc(state.EspAdvisoryFailureResolvedUtc.Value);
evidence["espAdvisoryFailureResolved"] = TimestampedEvidence(state.EspAdvisoryFailureResolvedUtc);
}
// Session 772fe502 — genuine Hello-wizard launch (Shell-Core 62404, CXID AADHello/
// NGC). Surfaced in the census so terminal audit trails show whether a wizard was
// observed — the discriminant between "Hello skipped by policy" and "Hello skipped
@@ -63,6 +63,8 @@ namespace AutopilotMonitor.DecisionCore.Engine
["helloPolicyEnabled"] = SerializeFact(state.HelloPolicyEnabled, v => (object)v),
["lastFailureTrigger"] = SerializeFact(state.LastFailureTrigger, v => v),
["espAdvisoryFailureRecordedUtc"] = SerializeFact(state.EspAdvisoryFailureRecordedUtc, FormatUtc),
["espAdvisoryFailureResolvedUtc"] = SerializeFact(state.EspAdvisoryFailureResolvedUtc, FormatUtc),
["espAdvisoryFailureCategory"] = SerializeFact(state.EspAdvisoryFailureCategory, v => v),
["imeUserSessionCompletedUtc"] = SerializeFact(state.ImeUserSessionCompletedUtc, FormatUtc),
["completionWaitingFingerprint"] = SerializeFact(state.CompletionWaitingFingerprint, v => v),
["helloWizardStartedUtc"] = SerializeFact(state.HelloWizardStartedUtc, FormatUtc),
@@ -64,7 +64,9 @@ namespace AutopilotMonitor.DecisionCore.State
SignalFact<DateTime>? espAdvisoryFailureRecordedUtc = null,
SignalFact<DateTime>? imeUserSessionCompletedUtc = null,
SignalFact<string>? completionWaitingFingerprint = null,
SignalFact<DateTime>? helloWizardStartedUtc = null)
SignalFact<DateTime>? helloWizardStartedUtc = null,
SignalFact<DateTime>? espAdvisoryFailureResolvedUtc = null,
SignalFact<string>? espAdvisoryFailureCategory = null)
{
if (string.IsNullOrEmpty(sessionId))
{
@@ -108,6 +110,8 @@ namespace AutopilotMonitor.DecisionCore.State
ImeUserSessionCompletedUtc = imeUserSessionCompletedUtc;
CompletionWaitingFingerprint = completionWaitingFingerprint;
HelloWizardStartedUtc = helloWizardStartedUtc;
EspAdvisoryFailureResolvedUtc = espAdvisoryFailureResolvedUtc;
EspAdvisoryFailureCategory = espAdvisoryFailureCategory;
}
public string SessionId { get; }
@@ -320,6 +324,36 @@ namespace AutopilotMonitor.DecisionCore.State
/// </summary>
public SignalFact<DateTime>? HelloWizardStartedUtc { get; }
/// <summary>
/// Set when the ESP category behind a recorded advisory failure
/// (<see cref="EspAdvisoryFailureRecordedUtc"/>) later resolves to success — i.e. the
/// failure demonstrably un-happened. Session 4910a5a5 (2026-07-23): DeviceSetup/Apps
/// failed, the user pressed "Try again" ~23 min later, the apps re-ran to 10/10 and
/// <c>DeviceSetupProvisioningComplete</c> arrived — yet the <c>AdvisoryCompletion</c>
/// window still un-defanged the stale failure and failed the live enrollment.
/// <para>
/// Set-once by the shared recovery hook in the ProvisioningComplete handlers when the
/// resolved category matches the <c>armFailedCategory</c> carried on the armed
/// <c>AdvisoryCompletion</c> deadline. Once set, the advisory variant loses its
/// exemption from the enforcement-progress re-arm, the reboot rebase and the Hello
/// promotes — those guards exist to protect live enrollments, and with this fact the
/// "a real ESP terminal failure does not un-happen" premise is disproven for this
/// session. Additive-nullable, no snapshot-schema bump.
/// </para>
/// </summary>
public SignalFact<DateTime>? EspAdvisoryFailureResolvedUtc { get; }
/// <summary>
/// The ESP category (<c>DeviceSetup</c> / <c>AccountSetup</c>) named by the advisory
/// failure's signal payload, recorded alongside <see cref="EspAdvisoryFailureRecordedUtc"/>.
/// Lives on state — not on the <c>AdvisoryCompletion</c> deadline payload — because
/// re-arm and reboot-rebase sites rebuild that deadline and would silently drop a
/// payload-carried category. Null when the arming signal carried no category (e.g.
/// event-log-derived failures); the recovery hook then never matches and behavior is
/// unchanged. Additive-nullable, no snapshot-schema bump.
/// </summary>
public SignalFact<string>? EspAdvisoryFailureCategory { get; }
public string SchemaVersion { get; }
/// <summary>
@@ -51,6 +51,8 @@ namespace AutopilotMonitor.DecisionCore.State
ImeUserSessionCompletedUtc = source.ImeUserSessionCompletedUtc;
CompletionWaitingFingerprint = source.CompletionWaitingFingerprint;
HelloWizardStartedUtc = source.HelloWizardStartedUtc;
EspAdvisoryFailureResolvedUtc = source.EspAdvisoryFailureResolvedUtc;
EspAdvisoryFailureCategory = source.EspAdvisoryFailureCategory;
}
public string SessionId { get; set; }
@@ -84,6 +86,8 @@ namespace AutopilotMonitor.DecisionCore.State
public SignalFact<DateTime>? ImeUserSessionCompletedUtc { get; set; }
public SignalFact<string>? CompletionWaitingFingerprint { get; set; }
public SignalFact<DateTime>? HelloWizardStartedUtc { get; set; }
public SignalFact<DateTime>? EspAdvisoryFailureResolvedUtc { get; set; }
public SignalFact<string>? EspAdvisoryFailureCategory { get; set; }
public string SchemaVersion { get; set; }
// ---------- fluent helpers for the most common reducer operations ----------
@@ -197,9 +201,25 @@ namespace AutopilotMonitor.DecisionCore.State
/// Fire-once gate: subsequent <c>EspTerminalFailure</c> signals see this fact set and
/// dead-end without further effect.
/// </summary>
public DecisionStateBuilder WithEspAdvisoryFailureRecorded(DateTime utc, long sourceSignalOrdinal)
public DecisionStateBuilder WithEspAdvisoryFailureRecorded(
DateTime utc, long sourceSignalOrdinal, string? failedCategory = null)
{
EspAdvisoryFailureRecordedUtc = new SignalFact<DateTime>(utc, sourceSignalOrdinal);
if (!string.IsNullOrEmpty(failedCategory))
{
EspAdvisoryFailureCategory = new SignalFact<string>(failedCategory!, sourceSignalOrdinal);
}
return this;
}
/// <summary>
/// Record that the ESP category behind the recorded advisory failure later resolved to
/// success (session 4910a5a5 — "Try again" recovery). Set-once; lifts the advisory
/// variant's exemption from the AdvisoryCompletion re-arm/rebase guards.
/// </summary>
public DecisionStateBuilder WithEspAdvisoryFailureResolved(DateTime utc, long sourceSignalOrdinal)
{
EspAdvisoryFailureResolvedUtc = new SignalFact<DateTime>(utc, sourceSignalOrdinal);
return this;
}
@@ -236,6 +256,8 @@ namespace AutopilotMonitor.DecisionCore.State
espAdvisoryFailureRecordedUtc: EspAdvisoryFailureRecordedUtc,
imeUserSessionCompletedUtc: ImeUserSessionCompletedUtc,
completionWaitingFingerprint: CompletionWaitingFingerprint,
helloWizardStartedUtc: HelloWizardStartedUtc);
helloWizardStartedUtc: HelloWizardStartedUtc,
espAdvisoryFailureResolvedUtc: EspAdvisoryFailureResolvedUtc,
espAdvisoryFailureCategory: EspAdvisoryFailureCategory);
}
}
@@ -340,6 +340,13 @@ namespace AutopilotMonitor.Shared
// start→completion duration (works on replay since start carries the source log
// timestamp). Warning, advisory ("suspected"); no state mutation.
public const string ScriptTimeoutSuspected = "script_timeout_suspected";
// One-shot per agent run: the IME adapter detected replayed log content from a
// previous enrollment (source lines > 24 h stale, e.g. IME logs surviving a
// re-enrollment) and suppressed the historic script (script_started/completed/
// failed) and app (app_install_*/download_progress/do_telemetry) events.
// Data.earliestRejectedSourceTimestamp dates the replayed content so operators
// know why those events are missing (session eaf3d8c4).
public const string HistoricImeReplayDetected = "historic_ime_replay_detected";
public const string EspProvisioningStatus = "esp_provisioning_status";
public const string SoftwareInventoryAnalysis = "software_inventory_analysis";
public const string VulnerabilityReport = "vulnerability_report";
@@ -539,6 +546,17 @@ namespace AutopilotMonitor.Shared
public const string EspFailureSettleRecovered = "esp_failure_settle_recovered"; // The failed subcategory left the "failed" state during the settle window (e.g. ESP "Try again" retry, session c071e92b) — the terminal EspFailureDetected fire is suppressed and monitoring continues; a subsequent failure re-arms a fresh settle window.
public const string EspAppxFailureAnalysis = "esp_appx_failure_analysis"; // One-shot AppXDeploymentServer/Operational scan during the ESP failure settle window: candidate MSIX/Store packages behind an "Apps (0x…)" subcategory failure invisible to ImeLogTracker (session 2bc884b6). Assessment, not a confirmed root cause.
public const string EspProvisioningRaw = "esp_provisioning_raw";
// Recovery story AFTER a terminally fired ESP failure (session 4910a5a5, 2026-07-23 —
// DeviceSetup/Apps failed, user pressed "Try again" ~23 min later, apps re-ran to
// 10/10). Distinct from EspFailureSettleRecovered, which covers recovery INSIDE the
// 30s settle window (terminal fire suppressed); these fire when the failure already
// went terminal (advisory/enrollment_failed) and the registry later disproves it.
public const string EspFailureRetryDetected = "esp_failure_retry_detected"; // failed subcategory left "failed" post-terminal — consistent with the user pressing "Try again"
public const string EspFailureRecovered = "esp_failure_recovered"; // previously failed category reached all-subcategories-succeeded post-terminal
// DecisionEngine counterpart (survives reboots via snapshot, unlike the in-run tracker
// pair above): the category behind a defanged esp_failure_advisory later resolved to
// success — the advisory no longer blocks; re-arm/rebase guards apply again.
public const string EspFailureAdvisoryResolved = "esp_failure_advisory_resolved";
public const string EspFailure = "esp_failure";
public const string EspExiting = "esp_exiting";
@@ -98,6 +98,12 @@ export const KNOWN_EVENT_TYPES: EventTypeEntry[] = [
description: "ESP reported a subcategory failure but the device had already progressed to AccountSetup with ContinueAnyway enabled — non-terminal advisory, the agent continues monitoring." },
{ value: "esp_appx_failure_analysis", label: "esp_appx_failure_analysis", category: "esp",
description: "AppX deployment log scan during the ESP failure settle window: suspected MSIX/Store package candidates behind an Apps-subcategory failure (assessment, not a confirmed root cause)." },
{ value: "esp_failure_retry_detected", label: "esp_failure_retry_detected", category: "esp",
description: "After a terminally reported ESP failure, the failed subcategory left the failed state — consistent with the user pressing 'Try again' on the ESP failure page." },
{ value: "esp_failure_recovered", label: "esp_failure_recovered", category: "esp",
description: "The ESP category behind a terminally reported failure later completed successfully — the earlier failure recovered (e.g. after a user retry)." },
{ value: "esp_failure_advisory_resolved", label: "esp_failure_advisory_resolved", category: "esp",
description: "DecisionEngine: the category behind a defanged esp_failure_advisory resolved to success — the advisory no longer blocks completion." },
// -------- App installs --------
{ value: "app_install_started", label: "app_install_started", category: "app",
@@ -136,6 +142,8 @@ export const KNOWN_EVENT_TYPES: EventTypeEntry[] = [
description: "A platform script crashed (exit code != 0), or the remediation phase of a health script crashed. Health-script detection / post-detection phases use exit code as a compliance verdict (non-zero = non-compliant) and emit script_completed even on non-zero exit; only a true script crash in those phases would surface here." },
{ value: "script_timeout_suspected", label: "script_timeout_suspected", category: "script",
description: "A platform script ran to the IME script-execution timeout (~30 min; threshold 25 min) and was marked Failed while the enrollment was in progress. IME runs platform scripts serially, so a hung script starves app installs and the Autopilot-Monitor bootstrap — the prime suspect behind a late agent start / pre-failed ESP. Advisory (one per policyId); carries durationSeconds, exitCode and espPhase." },
{ value: "historic_ime_replay_detected", label: "historic_ime_replay_detected", category: "diagnostics",
description: "One-shot per agent run: the IME log contained replayed script and app activity from a previous enrollment (source lines more than 24 h stale, e.g. IME logs surviving a re-enrollment). The historic script_* and app_install_*/download_progress/do_telemetry events were suppressed for this session; carries earliestRejectedSourceTimestamp so the replayed window is datable." },
// -------- Diagnostics / misc --------
{ value: "error_detected", label: "error_detected", category: "diagnostics",
@@ -521,6 +521,46 @@ function EventRow({ event, showScriptOutput }: { event: EnrollmentEvent; showScr
subcategory: <span className="font-mono">{String(sub)}</span>
</span>
)}
{event.data?.likelyCulpritApps && (
<span
className="px-1.5 py-0.5 rounded bg-orange-100 text-orange-800 font-medium"
title="Tracked app(s) ESP most likely failed on — never-started apps ranked first (snapshot at failure time)."
>
Likely app: {String(event.data.likelyCulpritApps)}
</span>
)}
</div>
);
})()}
{/* Recovery-story badges (session 4910a5a5): a terminally reported ESP failure that
later un-happened — the user retried ("Try again"), the failed step re-ran and
recovered. Green/teal palette so the timeline visually closes the earlier red/amber
failure arc. */}
{(event.eventType === "esp_failure_retry_detected" || event.eventType === "esp_failure_recovered" || event.eventType === "esp_failure_advisory_resolved") && (() => {
const isRetry = event.eventType === "esp_failure_retry_detected";
const label = isRetry ? "User retry" : "Recovered";
const badgeCls = isRetry ? "bg-sky-100 text-sky-800" : "bg-emerald-100 text-emerald-800";
const cat = event.data?.category;
const sub = event.data?.subcategory ?? event.data?.failedSubcategory;
const mins = event.data?.minutesSinceFailure ?? event.data?.minutesSinceAdvisory;
return (
<div className="mt-1 flex flex-wrap items-center gap-2 text-xs">
<span
className={`px-1.5 py-0.5 rounded ${badgeCls} font-medium`}
title={isRetry
? "The failed ESP step left the failed state — consistent with the user pressing 'Try again' on the ESP failure page."
: "The previously failed ESP category completed successfully — the earlier failure no longer applies."}
>
{label}
</span>
{cat && (
<span className="text-gray-500">
{String(cat)}{sub ? <> / <span className="font-mono">{String(sub)}</span></> : null}
</span>
)}
{mins !== undefined && mins !== null && (
<span className="text-gray-500">{String(mins)} min after the failure</span>
)}
</div>
);
})()}
@@ -62,6 +62,10 @@ export function useSessionDerivedData(
// Extract latest app_tracking_summary state-breakdown for progress headers.
// Schema is the flat V1 shape — see AppTrackingSummaryBuilder.cs for the contract.
// Known legacy limitation: on sessions recorded by agents without the tracker-level
// historic-replay guard, the snapshot may count apps replayed from a previous
// enrollment's IME log — accepted; fixed agents keep replayed apps out of the summary
// at the source (ImeLogTracker AppMutatingActions guard).
const appSummaryStats = useMemo(() => {
const summaryEvents = events.filter(e => e.eventType === "app_tracking_summary");
if (summaryEvents.length === 0) return null;
@@ -1,6 +1,7 @@
"use client";
import { useMemo, useState } from "react";
import { partitionHistoricReplayEvents } from "@/lib/historicReplay";
import { shouldSkipLowBytesTotal, shouldSkipNoActivity } from "@/lib/downloadProgressFilters";
import { formatBytes, formatThroughput, formatDuration } from "@/lib/formatting";
import DoBreakdownBar from "./DoBreakdownBar";
@@ -84,10 +85,18 @@ function formatDoDuration(duration: string): string {
}
export default function DownloadProgress({ events, summaryStats }: DownloadProgressProps) {
const downloads = useMemo(() => {
if (events.length === 0) return [];
// Legacy-agent guard: drop download events replayed from a previous enrollment's IME log.
// Silent (empty finals set) — the InstallProgress panel already reports the hidden count
// for the same apps; a second note here would double-report them.
const current = useMemo(
() => partitionHistoricReplayEvents(events, new Set<string>()).current,
[events]
);
const sortedEvents = [...events].sort(
const downloads = useMemo(() => {
if (current.length === 0) return [];
const sortedEvents = [...current].sort(
(a, b) => new Date(a.timestamp).getTime() - new Date(b.timestamp).getTime()
);
@@ -185,7 +194,7 @@ export default function DownloadProgress({ events, summaryStats }: DownloadProgr
// This avoids active items jumping when completion status changes.
return a.firstSeenIndex - b.firstSeenIndex;
});
}, [events]);
}, [current]);
const [expanded, setExpanded] = useState(true);
const [showSkipped, setShowSkipped] = useState(false);
@@ -2,6 +2,7 @@
import { useEffect, useMemo, useState } from "react";
import { getErrorCodeEntry, formatErrorCode } from "@/utils/errorCodeMap";
import { partitionHistoricReplayEvents } from "@/lib/historicReplay";
interface InstallEvent {
timestamp: string;
@@ -29,6 +30,10 @@ const ESP_APPS_TIMEOUT = "esp_apps_timeout";
const ESP_APPS_DETECTION_FAILURE = "esp_apps_detection_failure";
const ESP_APPS_INSTALL_FAILURE = "esp_apps_install_failure";
// Finals counted by the historic-replay partition — one per hidden install, so the note
// is not inflated by started/progress events of the same app.
const APP_FINAL_TYPES: ReadonlySet<string> = new Set(["app_install_completed", "app_install_failed"]);
interface InstallItem {
appName: string;
appId: string;
@@ -76,10 +81,18 @@ function formatDuration(ms: number): string {
}
export default function InstallProgress({ events, summaryStats }: InstallProgressProps) {
const installs = useMemo(() => {
if (events.length === 0) return [];
// Legacy-agent guard: split off app events replayed from a previous enrollment's IME log
// (newer agents suppress them at the source) so week-old installs never render as current.
// office_*/realmjoin_* events never carry rejectedSourceTimestamp and pass through untouched.
const { current, historicCount } = useMemo(
() => partitionHistoricReplayEvents(events, APP_FINAL_TYPES),
[events]
);
const sortedEvents = [...events].sort(
const installs = useMemo(() => {
if (current.length === 0) return [];
const sortedEvents = [...current].sort(
(a, b) => new Date(a.timestamp).getTime() - new Date(b.timestamp).getTime()
);
@@ -265,7 +278,7 @@ export default function InstallProgress({ events, summaryStats }: InstallProgres
}
return Array.from(installMap.values()).sort((a, b) => a.firstSeenIndex - b.firstSeenIndex);
}, [events]);
}, [current]);
const [expanded, setExpanded] = useState(true);
const [showSkipped, setShowSkipped] = useState(false);
@@ -288,7 +301,7 @@ export default function InstallProgress({ events, summaryStats }: InstallProgres
return showSkipped ? installs : installs.filter(d => d.state !== "Skipped");
}, [installs, showSkipped]);
if (installs.length === 0) return null;
if (installs.length === 0 && historicCount === 0) return null;
const activeCount = installs.filter(d => d.state === "Installing").length;
const completedCount = installs.filter(d => d.state === "Installed").length;
@@ -376,6 +389,14 @@ export default function InstallProgress({ events, summaryStats }: InstallProgres
{filteredInstalls.map((item) => (
<InstallItemRow key={item.appName} item={item} />
))}
{historicCount > 0 && (
<div
className="text-xs text-gray-400 italic"
title="These installs were replayed from IME log content that predates this enrollment by more than 24 hours — they ran during a previous enrollment on this device"
>
{historicCount} historic app install{historicCount === 1 ? "" : "s"} from a previous enrollment hidden
</div>
)}
</div>}
</div>
);
@@ -10,6 +10,7 @@ import {
isDetectOnlyRow,
isNonCompliantReport,
mapRemediationStatus,
partitionHistoricScriptEvents,
reduceScriptEvents,
scriptCardKey,
scriptItemKey,
@@ -38,11 +39,15 @@ interface ScriptExecutionsProps {
}
export default function ScriptExecutions({ events, showScriptOutput, latestBootstrapVersion, displayNamesByRefKey }: ScriptExecutionsProps) {
const cards = useMemo(() => groupScriptItems(reduceScriptEvents(events)), [events]);
// Legacy-agent guard: split off script events replayed from a previous enrollment's IME
// log (newer agents suppress them at the source) so week-old runs never render as current
// executions. The muted note below keeps the gap explainable.
const { current, historicCount } = useMemo(() => partitionHistoricScriptEvents(events), [events]);
const cards = useMemo(() => groupScriptItems(reduceScriptEvents(current)), [current]);
const [expanded, setExpanded] = useState(true);
if (cards.length === 0) return null;
if (cards.length === 0 && historicCount === 0) return null;
// Header counters work on cards (one per policy), so a remediated cycle reads as
// "1 succeeded" rather than "1 succeeded + 2 non-compliant" when its detection /
@@ -114,6 +119,14 @@ export default function ScriptExecutions({ events, showScriptOutput, latestBoots
displayNamesByRefKey={displayNamesByRefKey}
/>
))}
{historicCount > 0 && (
<div
className="text-xs text-gray-400 italic"
title="These executions were replayed from IME log content that predates this enrollment by more than 24 hours — they ran during a previous enrollment on this device"
>
{historicCount} historic script execution{historicCount === 1 ? "" : "s"} from a previous enrollment hidden
</div>
)}
</div>
)}
</div>
@@ -0,0 +1,77 @@
import { describe, it, expect } from "vitest";
import {
HISTORIC_REPLAY_THRESHOLD_MS,
partitionHistoricReplayEvents,
type ReplayInputEvent,
} from "../historicReplay";
const BASE = 1700000000000;
const DAY_MS = 24 * 60 * 60 * 1000;
const evt = (overrides: Partial<ReplayInputEvent> = {}): ReplayInputEvent => ({
timestamp: new Date(BASE).toISOString(),
eventType: "app_install_completed",
data: {},
...overrides,
});
const APP_FINALS = new Set(["app_install_completed", "app_install_failed"]);
describe("partitionHistoricReplayEvents", () => {
it("drops events whose rejectedSourceTimestamp is > 24h older than the event stamp", () => {
const historic = evt({ data: { rejectedSourceTimestamp: new Date(BASE - 7 * DAY_MS).toISOString() } });
const fresh = evt({ data: {} });
const { current, historicCount } = partitionHistoricReplayEvents([historic, fresh], APP_FINALS);
expect(current).toEqual([fresh]);
expect(historicCount).toBe(1);
});
it("counts only finals — dropped non-final events are removed uncounted", () => {
const staleTs = new Date(BASE - 7 * DAY_MS).toISOString();
const events = [
evt({ eventType: "app_download_started", data: { rejectedSourceTimestamp: staleTs } }),
evt({ eventType: "download_progress", data: { rejectedSourceTimestamp: staleTs } }),
evt({ eventType: "app_install_started", data: { rejectedSourceTimestamp: staleTs } }),
evt({ eventType: "app_install_completed", data: { rejectedSourceTimestamp: staleTs } }),
evt({ eventType: "app_install_failed", data: { rejectedSourceTimestamp: staleTs } }),
];
const { current, historicCount } = partitionHistoricReplayEvents(events, APP_FINALS);
expect(current).toEqual([]);
expect(historicCount).toBe(2);
});
it("keeps future-skew rejections (source timestamp ahead of the event stamp)", () => {
const skewed = evt({ data: { rejectedSourceTimestamp: new Date(BASE + 2 * 60 * 60 * 1000).toISOString() } });
const { current, historicCount } = partitionHistoricReplayEvents([skewed], APP_FINALS);
expect(current).toEqual([skewed]);
expect(historicCount).toBe(0);
});
it("keeps within-24h rejections, missing and malformed rejectedSourceTimestamp", () => {
const within = evt({ data: { rejectedSourceTimestamp: new Date(BASE - 23 * 60 * 60 * 1000).toISOString() } });
const none = evt({ data: {} });
const noData = evt({ data: undefined });
const malformed = evt({ data: { rejectedSourceTimestamp: "not-a-date" } });
const { current, historicCount } = partitionHistoricReplayEvents([within, none, noData, malformed], APP_FINALS);
expect(current).toHaveLength(4);
expect(historicCount).toBe(0);
});
it("reads the snake_case wire variant", () => {
const historic = evt({ data: { rejected_source_timestamp: new Date(BASE - 7 * DAY_MS).toISOString() } });
const { current, historicCount } = partitionHistoricReplayEvents([historic], APP_FINALS);
expect(current).toEqual([]);
expect(historicCount).toBe(1);
});
it("empty finals set filters silently (DownloadProgress mode)", () => {
const historic = evt({ data: { rejectedSourceTimestamp: new Date(BASE - 7 * DAY_MS).toISOString() } });
const { current, historicCount } = partitionHistoricReplayEvents([historic], new Set<string>());
expect(current).toEqual([]);
expect(historicCount).toBe(0);
});
it("exposes the 24h threshold constant", () => {
expect(HISTORIC_REPLAY_THRESHOLD_MS).toBe(DAY_MS);
});
});
@@ -7,6 +7,7 @@ import {
isDetectOnlyRow,
isNonCompliantReport,
mapRemediationStatus,
partitionHistoricScriptEvents,
reduceScriptEvents,
scriptItemKey,
toNumber,
@@ -905,3 +906,82 @@ describe("groupScriptItems — card durationSeconds is the max phase run time",
expect(cards[0].durationSeconds).toBeUndefined();
});
});
describe("partitionHistoricScriptEvents", () => {
// Agent-side clamp evidence: rejectedSourceTimestamp = the source log line's own time,
// timestamp = the clock-clamped event stamp. > 24 h older ⇒ replayed history from a
// previous enrollment (session eaf3d8c4).
const DAY_MS = 24 * 60 * 60 * 1000;
it("drops events whose rejectedSourceTimestamp is > 24 h older than the event stamp and counts finals", () => {
const historicFinal = finalEvent({
ts: 0,
data: { policyId: "p1", scriptType: "remediation", rejectedSourceTimestamp: new Date(1700000000000 - 7 * DAY_MS).toISOString() },
});
const historicStart = finalEvent({
eventType: "script_started",
ts: 1,
data: { policyId: "p1", scriptType: "remediation", rejectedSourceTimestamp: new Date(1700000000000 - 7 * DAY_MS).toISOString() },
});
const fresh = finalEvent({ ts: 2, data: { policyId: "p2", scriptType: "platform" } });
const { current, historicCount } = partitionHistoricScriptEvents([historicFinal, historicStart, fresh]);
expect(current).toEqual([fresh]);
// Only finals count toward the "hidden executions" note — dropped starts would
// double-count the same run.
expect(historicCount).toBe(1);
});
it("keeps future-skew rejections (source timestamp ahead of the event stamp)", () => {
const skewed = finalEvent({
ts: 0,
data: { policyId: "p1", scriptType: "platform", rejectedSourceTimestamp: new Date(1700000000000 + 2 * 60 * 60 * 1000).toISOString() },
});
const { current, historicCount } = partitionHistoricScriptEvents([skewed]);
expect(current).toEqual([skewed]);
expect(historicCount).toBe(0);
});
it("keeps within-24h rejections and events without or with malformed rejectedSourceTimestamp", () => {
const within = finalEvent({
ts: 0,
data: { policyId: "p1", scriptType: "platform", rejectedSourceTimestamp: new Date(1700000000000 - 23 * 60 * 60 * 1000).toISOString() },
});
const none = finalEvent({ ts: 1, data: { policyId: "p2", scriptType: "platform" } });
const malformed = finalEvent({ ts: 2, data: { policyId: "p3", scriptType: "platform", rejectedSourceTimestamp: "not-a-date" } });
const { current, historicCount } = partitionHistoricScriptEvents([within, none, malformed]);
expect(current).toHaveLength(3);
expect(historicCount).toBe(0);
});
it("reads the snake_case wire variant too", () => {
const historic = finalEvent({
ts: 0,
data: { policyId: "p1", scriptType: "platform", rejected_source_timestamp: new Date(1700000000000 - 7 * DAY_MS).toISOString() },
});
const { current, historicCount } = partitionHistoricScriptEvents([historic]);
expect(current).toEqual([]);
expect(historicCount).toBe(1);
});
});
describe("reduceScriptEvents — implausible duration blanking", () => {
it("blanks durations above 24 h (mixed-timeline artifacts from legacy agents)", () => {
// Session eaf3d8c4: clock-clamped completion minus raw week-old start = 612225 s ≈ 170 h.
const items = reduceScriptEvents([
finalEvent({ data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", exitCode: "0", complianceResult: "True", durationSeconds: "612225.00", durationBasis: "script_runtime" } }),
]);
expect(items[0].durationSeconds).toBeUndefined();
expect(items[0].reportedAfterSeconds).toBeUndefined();
});
it("keeps the 24 h boundary value and blanks cycle-basis values the same way", () => {
const items = reduceScriptEvents([
finalEvent({ data: { policyId: "p1", scriptType: "platform", exitCode: "0", result: "Success", durationSeconds: "86400", durationBasis: "script_runtime" } }),
finalEvent({ ts: 1, data: { policyId: "p2", scriptType: "remediation", scriptPart: "detection", exitCode: "0", complianceResult: "True", durationSeconds: "90000", durationBasis: "cycle_including_reporting_latency" } }),
]);
expect(items[0].durationSeconds).toBe(86400);
expect(items[1].reportedAfterSeconds).toBeUndefined();
});
});
@@ -0,0 +1,55 @@
/**
* Client-side guard against historic IME-log replay (session eaf3d8c4): when a previous
* enrollment's IME log survives a re-enrollment, legacy agents replay its content and emit
* week-old script runs and app installs as if they were current activity. The agent's
* timestamp clamp preserves the evidence as `rejectedSourceTimestamp` on the event data —
* a source timestamp more than 24 h OLDER than the event stamp marks the event as replayed
* history. Newer agents suppress those events at the source (historic_ime_replay_detected);
* this partition covers sessions recorded by older agents.
*/
/** Mirrors the agent's 24 h source-timestamp staleness clamp. */
export const HISTORIC_REPLAY_THRESHOLD_MS = 24 * 60 * 60 * 1000;
export interface ReplayInputEvent {
timestamp: string;
eventType?: string;
data?: Record<string, any>;
}
export interface HistoricPartition<T extends ReplayInputEvent> {
current: T[];
/**
* Count of dropped events whose eventType is in `countedFinalTypes` — the number the UI
* reports as "hidden". Dropped non-final events (starts, progress ticks) are removed but
* not counted, so the note is not inflated by multiple events of the same run.
*/
historicCount: number;
}
/**
* Splits off events that are replayed history from a previous enrollment. Future-skew
* rejections (source timestamp AHEAD of the event stamp — mid-enrollment clock jump) are
* genuine current activity and stay in `current`, as do events without (or with malformed)
* `rejectedSourceTimestamp`.
*/
export function partitionHistoricReplayEvents<T extends ReplayInputEvent>(
events: T[],
countedFinalTypes: ReadonlySet<string>,
): HistoricPartition<T> {
const current: T[] = [];
let historicCount = 0;
for (const evt of events) {
const rejected = evt.data?.rejectedSourceTimestamp ?? evt.data?.rejected_source_timestamp;
if (typeof rejected === "string" && rejected.length > 0) {
const rej = Date.parse(rejected);
const ts = Date.parse(evt.timestamp);
if (Number.isFinite(rej) && Number.isFinite(ts) && ts - rej > HISTORIC_REPLAY_THRESHOLD_MS) {
if (evt.eventType && countedFinalTypes.has(evt.eventType)) historicCount++;
continue;
}
}
current.push(evt);
}
return { current, historicCount };
}
@@ -5,6 +5,7 @@
* mapping can be unit-tested without React Testing Library.
*/
import { extractBootstrapVersion } from "@/utils/bootstrapVersion";
import { HISTORIC_REPLAY_THRESHOLD_MS, partitionHistoricReplayEvents } from "./historicReplay";
export interface ScriptInputEvent {
timestamp: string;
@@ -119,6 +120,30 @@ export function scriptCardKey(card: Pick<ScriptCard, "policyId" | "scriptType" |
/** Threshold above which a Running placeholder is rendered as "stuck?" rather than animated. */
export const STALE_RUNNING_THRESHOLD_SECONDS = 600;
export { HISTORIC_REPLAY_THRESHOLD_MS };
const SCRIPT_FINAL_TYPES: ReadonlySet<string> = new Set(["script_completed", "script_failed"]);
export interface HistoricPartition {
current: ScriptInputEvent[];
/**
* Count of dropped FINAL events (script_completed / script_failed) — what the user reads
* as "hidden executions". Dropped script_started events are removed but not counted, so
* the note is not inflated by start/end pairs of the same run.
*/
historicCount: number;
}
/**
* Script-specific wrapper over `partitionHistoricReplayEvents` (see lib/historicReplay.ts
* for the replay semantics): drops script events replayed from a previous enrollment
* (session eaf3d8c4: 156 replayed runs shown with ~170 h durations) and counts the finals
* for the "N hidden" note.
*/
export function partitionHistoricScriptEvents(events: ScriptInputEvent[]): HistoricPartition {
return partitionHistoricReplayEvents(events, SCRIPT_FINAL_TYPES);
}
/**
* Score how complete a script item's data is (higher = better). Used by the reducer to
* pick the best entry when re-emissions of the same script collapse into one row.
@@ -261,7 +286,13 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
// the script's own result line (runtime), remediation durations to HS-NEW-RESULT
// (cycle) — infer accordingly so old data is never displayed as run time when it
// isn't one.
const rawDuration = toNumber(d.durationSeconds ?? d.duration_seconds);
// Scripts cannot run > 24 h inside an enrollment (IME's execution timeout is ~30 min);
// larger values are mixed-timeline artifacts from legacy agents (raw stale start paired
// with a clock-clamped completion — session eaf3d8c4 showed 170 h). Hide, don't lie.
const rawDurationUnchecked = toNumber(d.durationSeconds ?? d.duration_seconds);
const rawDuration = rawDurationUnchecked != null && rawDurationUnchecked <= HISTORIC_REPLAY_THRESHOLD_MS / 1000
? rawDurationUnchecked
: undefined;
const rawBasis = d.durationBasis ?? d.duration_basis;
const isCycleBasis = typeof rawBasis === "string"
? rawBasis === "cycle_including_reporting_latency"