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>
This commit is contained in:
Oliver Kieselbach
2026-07-23 18:39:11 +02:00
parent 3224774752
commit 088c3b0479
12 changed files with 696 additions and 50 deletions
@@ -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_script_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.HistoricScriptReplayDetected);
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.HistoricScriptReplayDetected));
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.HistoricScriptReplayDetected));
}
// ---------------------------------------------------------------------
// 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.HistoricScriptReplayDetected));
}
[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 else
{ {
// Platform script: AgentExecutor.log entries create/enrich, IME log entries also create HandlePlatformScriptStarted(id, source);
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"})");
} }
} }
// 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 // 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 // accumulator based on the pattern's scriptType parameter. Health-script lines feed the
// single-slot _pendingHealthScript; platform-script lines feed _pendingPlatformScripts. // single-slot _pendingHealthScript; platform-script lines feed _pendingPlatformScripts.
@@ -97,12 +97,23 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// bootstrap marker line. Lets MCP report "which device runs which bootstrap version". // bootstrap marker line. Lets MCP report "which device runs which bootstrap version".
private bool _bootstrapDetectedPosted; 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_script_replay_detected Info event explains the gap in the timeline.
private bool _historicReplayNoted;
private int _suppressedHistoricScriptEvents; // forensic count for the log line
// A platform script whose observed run duration reaches this is treated as having hit the // 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 // 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 // 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. // legitimately long install wrapper that completes on its own.
private static readonly TimeSpan ScriptTimeoutSuspectedThreshold = TimeSpan.FromMinutes(25); 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 and the duration
// plausibility backstop, one constant so the three can never drift apart.
private static readonly TimeSpan StaleSourceThreshold = TimeSpan.FromHours(24);
// Matches the deterministic marker line the bootstrap script writes via Write-Log, // 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. // 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. // Same shape as the web-side regex in utils/bootstrapVersion.ts; kept in sync intentionally.
@@ -289,17 +300,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
rawSourceTimestamp = sourceTsOverride ?? _tracker.LastMatchedLogTimestamp; rawSourceTimestamp = sourceTsOverride ?? _tracker.LastMatchedLogTimestamp;
if (rawSourceTimestamp.HasValue) if (rawSourceTimestamp.HasValue)
{ {
// CMTrace log timestamps from IME are emitted in UTC, but DateTimeKind may var asUtc = NormalizeUtc(rawSourceTimestamp.Value);
// arrive as Unspecified depending on the parser path. Normalize via
// SpecifyKind=Utc rather than ToUniversalTime() to avoid double-conversion
// when Kind is already UTC.
var asUtc = rawSourceTimestamp.Value.Kind == DateTimeKind.Utc
? rawSourceTimestamp.Value
: DateTime.SpecifyKind(rawSourceTimestamp.Value, DateTimeKind.Utc);
var clockNow = _clock.UtcNow; var clockNow = _clock.UtcNow;
var ageHours = (clockNow - asUtc).TotalHours; 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, // Pathologically stale (>24h old) or in the future (>1h skew) — log,
// fall back, and let the caller flag the event. // fall back, and let the caller flag the event.
@@ -325,6 +330,68 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture); data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture);
} }
/// <summary>
/// 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.
/// </summary>
private static DateTime NormalizeUtc(DateTime value) =>
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
/// <summary>
/// True when a script 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 runs from a previous enrollment whose IME log survived on disk (session eaf3d8c4:
/// 156 replayed script completions shown as current executions, 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_script_replay_detected</c> summary on the
/// first suppression; replay is chronological, so that first suppressed line carries the
/// earliest rejected source timestamp.
/// </summary>
private bool SuppressIfHistoricScriptReplay(
bool derivedFromClock, DateTime? rawSourceTs, string eventLabel, string policyId)
{
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 = ++_suppressedHistoricScriptEvents;
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.HistoricScriptReplayDetected,
source: SourceLabel,
message: "Historic script executions from a previous enrollment detected in the IME log "
+ $"(earliest source timestamp {asUtc:o}) — their script events are suppressed for this session.",
severity: EventSeverity.Info,
data: new Dictionary<string, string>(StringComparer.Ordinal)
{
["decision"] = "historic_script_replay_suppressed",
["earliestRejectedSourceTimestamp"] = asUtc.ToString("o", culture),
["staleThresholdHours"] = StaleSourceThreshold.TotalHours.ToString("F0", culture),
});
}
_logger?.Debug(
$"ImeAdapter: suppressed historic {eventLabel} for policy {policyId} "
+ $"(source ts {asUtc:o}, age {age.TotalHours:F1}h, suppressed so far: {suppressedSoFar})");
return true;
}
private void EmitEspPhase(string phase) private void EmitEspPhase(string phase)
{ {
if (string.IsNullOrEmpty(phase)) return; if (string.IsNullOrEmpty(phase)) return;
@@ -910,13 +977,27 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
now = ResolveOccurredAt(script.ExitObservedAtUtc, out derivedFromClock, out rawSourceTs); now = ResolveOccurredAt(script.ExitObservedAtUtc, out derivedFromClock, out rawSourceTs);
else else
now = ResolveOccurredAt(out derivedFromClock, out rawSourceTs); 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 (SuppressIfHistoricScriptReplay(derivedFromClock, rawSourceTs, eventType, script.PolicyId))
return;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); 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 // 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 // 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. // 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 — // 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 // 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 // cycle INCLUDING IME's 30 s–3 min batched reporting latency, i.e. systematically
@@ -924,10 +1005,16 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// consumers never compare the two as equals. The emitting handler stamps the basis on // 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 // the state (health-script early-signal completions are script_runtime too); the
// scriptType fallback covers states from paths that predate the field. // scriptType fallback covers states from paths that predate the field.
var completionForDuration = derivedFromClock && rawSourceTs.HasValue
? NormalizeUtc(rawSourceTs.Value)
: now;
if (script.StartedAtUtc.HasValue) if (script.StartedAtUtc.HasValue)
{ {
var durationSeconds = (now - script.StartedAtUtc.Value).TotalSeconds; var durationSeconds = (completionForDuration - script.StartedAtUtc.Value).TotalSeconds;
if (durationSeconds >= 0) // 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["durationSeconds"] = durationSeconds.ToString("F2", culture);
data["durationBasis"] = script.DurationBasis data["durationBasis"] = script.DurationBasis
@@ -979,7 +1066,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")}"); $"ImeAdapter: script completed policyId={shortId} type={script.ScriptType ?? "?"} result={script.Result ?? "?"} exit={(script.ExitCode.HasValue ? script.ExitCode.Value.ToString() : "n/a")}");
MaybeEmitBootstrapDetected(script, now); MaybeEmitBootstrapDetected(script, now);
MaybeEmitScriptTimeoutSuspected(script, now); MaybeEmitScriptTimeoutSuspected(script, now, completionForDuration);
} }
/// <summary> /// <summary>
@@ -991,15 +1078,19 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
/// late start / pre-failed ESP. Advisory only: no state mutation, the underlying /// late start / pre-failed ESP. Advisory only: no state mutation, the underlying
/// <c>script_failed</c> is still emitted separately. Health (remediation) scripts are /// <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. /// 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> /// </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 (IsRemediation(script.ScriptType)) return; // platform scripts only
if (!script.StartedAtUtc.HasValue) return; // no start ⇒ no duration if (!script.StartedAtUtc.HasValue) return; // no start ⇒ no duration
if (!string.Equals(script.Result, "Failed", StringComparison.OrdinalIgnoreCase)) return; 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 < 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) if (!_tracker.TryClaimScriptTimeoutSuspected(script.PolicyId)) return; // restart-safe dedup per policyId (persisted tracker state)
@@ -1026,7 +1117,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.", message: $"Platform script {shortId} ran {durationMinutes:F0} min and was marked Failed — suspected IME script timeout blocking the enrollment.",
severity: EventSeverity.Warning, severity: EventSeverity.Warning,
data: data, data: data,
occurredAtUtc: completionUtc); occurredAtUtc: occurredAtUtc);
_logger?.Info( _logger?.Info(
$"ImeAdapter: script_timeout_suspected policyId={shortId} duration={durationMinutes:F1}min result={script.Result} espPhase={espPhase ?? "(none)"}"); $"ImeAdapter: script_timeout_suspected policyId={shortId} duration={durationMinutes:F1}min result={script.Result} espPhase={espPhase ?? "(none)"}");
@@ -1081,6 +1172,12 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!; if (!string.IsNullOrEmpty(patternId)) data["patternId"] = patternId!;
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs); 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 (SuppressIfHistoricScriptReplay(derivedFromClock, rawSourceTs, SharedEventTypes.ScriptStarted, info.PolicyId))
return;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs); TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
var label = IsRemediation(info.ScriptType) ? "Health script" : "Platform script"; var label = IsRemediation(info.ScriptType) ? "Health script" : "Platform script";
@@ -0,0 +1,89 @@
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 IngestHistoricScriptReplayTests
{
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.IsHistoricScriptReplay(evt));
}
[Fact]
public void JustOver24h_IsHistoricReplay()
{
var evt = ScriptEvent(EventStamp.AddHours(-25).ToString("o"));
Assert.True(EventIngestProcessor.IsHistoricScriptReplay(evt));
}
[Fact]
public void Within24h_IsNotHistoricReplay()
{
var evt = ScriptEvent(EventStamp.AddHours(-23).ToString("o"));
Assert.False(EventIngestProcessor.IsHistoricScriptReplay(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.IsHistoricScriptReplay(evt));
}
[Fact]
public void MissingKey_IsNotHistoricReplay()
{
Assert.False(EventIngestProcessor.IsHistoricScriptReplay(ScriptEvent(null, includeKey: false)));
}
[Fact]
public void NullData_IsNotHistoricReplay()
{
var evt = new EnrollmentEvent { EventType = "script_completed", Timestamp = EventStamp, Data = null! };
Assert.False(EventIngestProcessor.IsHistoricScriptReplay(evt));
}
[Theory]
[InlineData("")]
[InlineData("not-a-date")]
public void UnparseableValue_IsNotHistoricReplay(string raw)
{
Assert.False(EventIngestProcessor.IsHistoricScriptReplay(ScriptEvent(raw)));
}
[Fact]
public void NullEvent_IsNotHistoricReplay()
{
Assert.False(EventIngestProcessor.IsHistoricScriptReplay(null));
}
}
@@ -82,6 +82,13 @@ namespace AutopilotMonitor.Functions.Services
break; break;
case "script_completed": case "script_completed":
case "script_failed": 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 (IsHistoricScriptReplay(evt))
break;
var scriptType = evt.Data?.ContainsKey("scriptType") == true var scriptType = evt.Data?.ContainsKey("scriptType") == true
? evt.Data["scriptType"]?.ToString() : null; ? evt.Data["scriptType"]?.ToString() : null;
if (string.Equals(scriptType, "platform", StringComparison.OrdinalIgnoreCase)) if (string.Equals(scriptType, "platform", StringComparison.OrdinalIgnoreCase))
@@ -119,6 +126,28 @@ namespace AutopilotMonitor.Functions.Services
return string.Equals(reason, "max_lifetime", StringComparison.OrdinalIgnoreCase); return string.Equals(reason, "max_lifetime", StringComparison.OrdinalIgnoreCase);
} }
/// <summary>
/// True for a script 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 IsHistoricScriptReplay(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> /// <summary>
/// True for an <c>enrollment_failed</c> event whose <c>Data.failureType</c> is /// 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 /// <c>agent_timeout</c> — the V1-parity companion of the max-lifetime watchdog shutdown
@@ -80,7 +80,7 @@ export const EVENT_TYPES_CATALOG = {
'office_install_failed', 'office_install_failed',
'office_preinstalled_detected', '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_script_replay_detected'],
network_events: [ network_events: [
'network_state_change', 'network_state_change',
'network_connectivity_check', 'network_connectivity_check',
@@ -28,7 +28,8 @@ export const KEY_EVENT_TYPES = new Set([
'enrollment_complete', 'enrollment_failed', 'completion_check', 'enrollment_complete', 'enrollment_failed', 'completion_check',
'desktop_arrived', 'hello_policy_detected', 'waiting_for_hello', 'hello_completion_timeout', 'desktop_arrived', 'hello_policy_detected', 'waiting_for_hello', 'hello_completion_timeout',
'agent_started', 'agent_shutdown', 'agent_shutting_down', 'agent_trace', 'agent_started', 'agent_shutdown', 'agent_shutting_down', 'agent_trace',
'script_started', 'script_completed', 'script_failed', 'vulnerability_report', 'script_started', 'script_completed', 'script_failed', 'historic_script_replay_detected',
'vulnerability_report',
]); ]);
// Phase-defining events promoted to the top of the triage timeline. Module-level // Phase-defining events promoted to the top of the triage timeline. Module-level
// (not handler-local) so the same drift test can validate it. // (not handler-local) so the same drift test can validate it.
@@ -340,6 +340,12 @@ namespace AutopilotMonitor.Shared
// start→completion duration (works on replay since start carries the source log // start→completion duration (works on replay since start carries the source log
// timestamp). Warning, advisory ("suspected"); no state mutation. // timestamp). Warning, advisory ("suspected"); no state mutation.
public const string ScriptTimeoutSuspected = "script_timeout_suspected"; public const string ScriptTimeoutSuspected = "script_timeout_suspected";
// One-shot per agent run: the IME adapter detected replayed log content from a
// previous enrollment (script source lines > 24 h stale, e.g. IME logs surviving a
// re-enrollment) and suppressed the historic script_started/script_completed/
// script_failed events. Data.earliestRejectedSourceTimestamp dates the replayed
// content so operators know why script events are missing (session eaf3d8c4).
public const string HistoricScriptReplayDetected = "historic_script_replay_detected";
public const string EspProvisioningStatus = "esp_provisioning_status"; public const string EspProvisioningStatus = "esp_provisioning_status";
public const string SoftwareInventoryAnalysis = "software_inventory_analysis"; public const string SoftwareInventoryAnalysis = "software_inventory_analysis";
public const string VulnerabilityReport = "vulnerability_report"; 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." }, 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", { 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." }, 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_script_replay_detected", label: "historic_script_replay_detected", category: "script",
description: "One-shot per agent run: the IME log contained replayed script activity from a previous enrollment (source lines more than 24 h stale, e.g. IME logs surviving a re-enrollment). The historic script_started/script_completed/script_failed events were suppressed for this session; carries earliestRejectedSourceTimestamp so the replayed window is datable." },
// -------- Diagnostics / misc -------- // -------- Diagnostics / misc --------
{ value: "error_detected", label: "error_detected", category: "diagnostics", { value: "error_detected", label: "error_detected", category: "diagnostics",
@@ -10,6 +10,7 @@ import {
isDetectOnlyRow, isDetectOnlyRow,
isNonCompliantReport, isNonCompliantReport,
mapRemediationStatus, mapRemediationStatus,
partitionHistoricScriptEvents,
reduceScriptEvents, reduceScriptEvents,
scriptCardKey, scriptCardKey,
scriptItemKey, scriptItemKey,
@@ -38,11 +39,15 @@ interface ScriptExecutionsProps {
} }
export default function ScriptExecutions({ events, showScriptOutput, latestBootstrapVersion, displayNamesByRefKey }: 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); 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 // 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 / // "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} 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>
)} )}
</div> </div>
@@ -7,6 +7,7 @@ import {
isDetectOnlyRow, isDetectOnlyRow,
isNonCompliantReport, isNonCompliantReport,
mapRemediationStatus, mapRemediationStatus,
partitionHistoricScriptEvents,
reduceScriptEvents, reduceScriptEvents,
scriptItemKey, scriptItemKey,
toNumber, toNumber,
@@ -905,3 +906,82 @@ describe("groupScriptItems — card durationSeconds is the max phase run time",
expect(cards[0].durationSeconds).toBeUndefined(); 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();
});
});
@@ -119,6 +119,51 @@ export function scriptCardKey(card: Pick<ScriptCard, "policyId" | "scriptType" |
/** Threshold above which a Running placeholder is rendered as "stuck?" rather than animated. */ /** Threshold above which a Running placeholder is rendered as "stuck?" rather than animated. */
export const STALE_RUNNING_THRESHOLD_SECONDS = 600; export const STALE_RUNNING_THRESHOLD_SECONDS = 600;
/**
* Age above which a rejectedSourceTimestamp marks the event as a historic replay from a
* previous enrollment (mirrors the agent's 24 h source-timestamp staleness clamp). Newer
* agents suppress such events at the source (historic_script_replay_detected); this
* client-side partition covers sessions recorded by older agents.
*/
export const HISTORIC_REPLAY_THRESHOLD_MS = 24 * 60 * 60 * 1000;
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;
}
/**
* Splits off script events that are replayed history from a previous enrollment: the agent
* stamps `rejectedSourceTimestamp` when it rejected the source log line's own timestamp and
* fell back to the clock. A source timestamp more than 24 h OLDER than the event stamp means
* the line predates this enrollment — the run happened days ago and must not render as a
* current execution (session eaf3d8c4: 156 replayed runs shown with ~170 h durations).
* Future-skew rejections (source timestamp AHEAD of the event stamp — mid-enrollment clock
* jump) are genuine current runs and stay visible.
*/
export function partitionHistoricScriptEvents(events: ScriptInputEvent[]): HistoricPartition {
const current: ScriptInputEvent[] = [];
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 === "script_completed" || evt.eventType === "script_failed") historicCount++;
continue;
}
}
current.push(evt);
}
return { current, historicCount };
}
/** /**
* Score how complete a script item's data is (higher = better). Used by the reducer to * 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. * pick the best entry when re-emissions of the same script collapse into one row.
@@ -261,7 +306,13 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
// the script's own result line (runtime), remediation durations to HS-NEW-RESULT // 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 // (cycle) — infer accordingly so old data is never displayed as run time when it
// isn't one. // 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 rawBasis = d.durationBasis ?? d.duration_basis;
const isCycleBasis = typeof rawBasis === "string" const isCycleBasis = typeof rawBasis === "string"
? rawBasis === "cycle_including_reporting_latency" ? rawBasis === "cycle_including_reporting_latency"