mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 05:00:07 +00:00
Compare commits
2 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 540f543834 | |||
| 088c3b0479 |
@@ -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) =>
|
||||
|
||||
+166
@@ -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());
|
||||
}
|
||||
}
|
||||
}
|
||||
+157
@@ -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));
|
||||
}
|
||||
}
|
||||
}
|
||||
+257
@@ -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 > 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"]);
|
||||
}
|
||||
}
|
||||
}
|
||||
+51
-30
@@ -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.
|
||||
|
||||
+34
@@ -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;
|
||||
|
||||
@@ -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)
|
||||
{
|
||||
|
||||
@@ -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,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;
|
||||
|
||||
|
||||
+29
@@ -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);
|
||||
});
|
||||
});
|
||||
@@ -80,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;
|
||||
|
||||
@@ -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";
|
||||
|
||||
@@ -142,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",
|
||||
|
||||
@@ -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"
|
||||
|
||||
Reference in New Issue
Block a user