mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
fix(agent,web): a script run duration is judged from both lines' provenance; an offset-error span is omitted, never shown (D-273)
A platform script that ran 10 s was shown as "1h 00m" (session 4377911b): its start line was self-anchored (+120 min) while its result line, re-read after an overwrite rewind and therefore never fresh, fell back to the agent's cached zone (+60 min), was rejected as ahead of the clock, and the duration was taken from the raw pair. The same shape fired script_timeout_suspected daily in one tenant on 2-9 s scripts read as 17 h. Fleet 2026-09-20..23: about 1 % of script durations, 28 of 28 inflated ones carrying derivedTimestamp. Agent: ScriptExecutionState binds the provenance of its start, result and exit lines (CmTraceLineProvenance, persisted); EmitScriptCompleted judges the pair - verified (both measured, or both assumed with the same offset from the same file), unverified, or suppressed with durationSuppressedReason (rejected-endpoint | offset-grid, CmTraceOffsetCalibrator.IsOnOffsetGrid) - and always emits durationProvenance plus startSourceOffset*. A held completion's sourceOffset* tags now describe its own result line; script_timeout_suspected only judges a measurable duration; the emitted-run marker is capped at the clock so a future-shifted result no longer swallows the next run's start. Web: the reducer applies the same rule to stored events from older agents, pairing a final with the latest script_started of its policy, and the panel shows "n/a" with the explanation where the run time would be. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
+1
-1
Submodule .claude/commands updated: 8c9023415a...3b805865eb
+1
-1
Submodule internal updated: 5a4b0257e1...234f4e1b08
+15
@@ -186,5 +186,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
DateTime resolved;
|
||||
Assert.False(sut.TryResolveUtc(Source, UtcNow, out resolved));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(3610.39, true, 4)] // session 4377911b: +1 h on a 10 s script
|
||||
[InlineData(61203.0, true, 68)] // 17 h on a 3 s script
|
||||
[InlineData(7205.66, true, 8)] // session cbaed57b: +2 h
|
||||
[InlineData(-3596.0, true, 4)] // the same error on the start end
|
||||
[InlineData(26.4, false, 0)] // a run time below one grid step
|
||||
[InlineData(1030.0, false, 1)] // 17 min 10 s: residual past the tolerance
|
||||
[InlineData(900.0, true, 1)] // exactly one step — a genuine 15-minute run reads the same, the caller needs mixed provenance too
|
||||
public void A_grid_sized_span_is_the_signature_of_an_offset_error(double seconds, bool onGrid, int expectedSteps)
|
||||
{
|
||||
int steps;
|
||||
Assert.Equal(onGrid, CmTraceOffsetCalibrator.IsOnOffsetGrid(TimeSpan.FromSeconds(seconds), out steps));
|
||||
if (onGrid) Assert.Equal(expectedSteps, steps);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+24
@@ -304,5 +304,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
tracker.HandlePlatformScriptStarted("policyZ");
|
||||
Assert.Single(started);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Emitted_marker_is_capped_at_the_clock_so_the_next_run_still_opens_a_slot()
|
||||
{
|
||||
// Session 4377911b: the result line was re-read after an overwrite rewind and resolved
|
||||
// in the reader's zone, one hour ahead of the clock. Stored uncapped, that stamp made
|
||||
// the genuine second run's start line read as a late line of the first run and its
|
||||
// result a duplicate.
|
||||
using var h = new Harness();
|
||||
h.Start("d94468af", T0.AddSeconds(-10));
|
||||
h.Result("d94468af", T0.AddHours(1));
|
||||
h.Exit("d94468af", T0.AddSeconds(-1));
|
||||
h.Flush();
|
||||
Assert.Single(h.Completed);
|
||||
|
||||
// The second run, two minutes later on the clock — still "before" the uncapped stamp.
|
||||
h.Now = T0.AddMinutes(2);
|
||||
h.Start("d94468af", h.Now.AddSeconds(-5));
|
||||
h.Result("d94468af", h.Now.AddSeconds(-1));
|
||||
h.Exit("d94468af", h.Now.AddSeconds(-2));
|
||||
h.Flush();
|
||||
|
||||
Assert.Equal(2, h.Completed.Count);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+40
@@ -154,5 +154,45 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
Assert.False(tracker2.TryClaimScriptTimeoutSuspected("policyF")); // cross-restart dedup
|
||||
Assert.True(tracker2.TryClaimScriptTimeoutSuspected("policyG")); // other policies unaffected
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Line_provenance_of_a_pending_script_survives_restart()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var observedAt = new DateTime(2026, 9, 17, 13, 20, 7, DateTimeKind.Utc);
|
||||
var start = new CmTraceLineProvenance
|
||||
{
|
||||
SourceLocalTs = new DateTime(2026, 9, 17, 15, 19, 57, DateTimeKind.Unspecified),
|
||||
Origin = CmTraceOffsetOrigin.LineAnchored,
|
||||
OffsetMinutes = 120,
|
||||
MeasuredWriterOffsetMinutes = 120,
|
||||
SourceFileName = "IntuneManagementExtension.log",
|
||||
};
|
||||
var exit = new CmTraceLineProvenance
|
||||
{
|
||||
SourceLocalTs = new DateTime(2026, 9, 17, 15, 20, 7, DateTimeKind.Unspecified),
|
||||
Origin = CmTraceOffsetOrigin.None,
|
||||
OffsetMinutes = 60,
|
||||
SourceFileName = "AgentExecutor.log",
|
||||
};
|
||||
|
||||
var tracker1 = BuildTracker(tmp, out _);
|
||||
tracker1.SeedPendingPlatformScriptForTesting("policyH", exitCode: 0, exitObservedAtUtc: observedAt,
|
||||
startedAtUtc: observedAt.AddSeconds(-10), startedAtProvenance: start, exitProvenance: exit);
|
||||
tracker1.SaveStateForTest();
|
||||
|
||||
var tracker2 = BuildTracker(tmp, out var emitted2);
|
||||
tracker2.LoadStateForTest();
|
||||
tracker2.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
|
||||
var script = Assert.Single(emitted2);
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, script.StartedAtProvenance.Origin);
|
||||
Assert.Equal(120, script.StartedAtProvenance.OffsetMinutes);
|
||||
Assert.Equal(start.SourceLocalTs, script.StartedAtProvenance.SourceLocalTs);
|
||||
Assert.Equal(DateTimeKind.Unspecified, script.StartedAtProvenance.SourceLocalTs!.Value.Kind); // no zone was ever attached
|
||||
Assert.Equal("AgentExecutor.log", script.ExitProvenance.SourceFileName);
|
||||
Assert.Equal(60, script.ExitProvenance.OffsetMinutes);
|
||||
Assert.Null(script.ResultProvenance);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+292
@@ -0,0 +1,292 @@
|
||||
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>
|
||||
/// A script run duration is the span between two CMTrace lines, each resolved on its own zone
|
||||
/// belief. When the beliefs differ the span is a whole number of offset-grid steps plus the run
|
||||
/// time, not the run time: session 4377911b read a 10 s script as 3610 s (start line-anchored
|
||||
/// +120, result re-read after an overwrite rewind in the reader's zone +60 and rejected as
|
||||
/// ahead of the clock), a fleet tenant read 2–9 s scripts as 17 h every day. The adapter judges
|
||||
/// the pair from the provenance bound to each line and omits the span rather than lie.
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerAdapterDurationProvenanceTests
|
||||
{
|
||||
private const string ServiceLog = "IntuneManagementExtension.log";
|
||||
private const string ExecutorLog = "AgentExecutor.log";
|
||||
|
||||
private static CmTraceLineProvenance Line(
|
||||
DateTime resolvedUtc, int offsetMinutes, CmTraceOffsetOrigin origin,
|
||||
string file = ServiceLog, string? anchor = null, int? measured = null) =>
|
||||
new CmTraceLineProvenance
|
||||
{
|
||||
// The writer's local time is the resolved value with the applied offset put back.
|
||||
SourceLocalTs = DateTime.SpecifyKind(resolvedUtc.AddMinutes(offsetMinutes), DateTimeKind.Unspecified),
|
||||
Origin = origin,
|
||||
OffsetMinutes = offsetMinutes,
|
||||
EraAnchorKind = anchor,
|
||||
MeasuredWriterOffsetMinutes = measured,
|
||||
SourceFileName = file,
|
||||
};
|
||||
|
||||
private static ScriptExecutionState Platform(string policyId, DateTime startedAtUtc, CmTraceLineProvenance start,
|
||||
DateTime? resultObservedAtUtc = null, CmTraceLineProvenance? result = null, string outcome = "Success", int exitCode = 0) =>
|
||||
new ScriptExecutionState
|
||||
{
|
||||
PolicyId = policyId,
|
||||
ScriptType = "platform",
|
||||
ExitCode = exitCode,
|
||||
Result = outcome,
|
||||
ResultSource = "ime_policy_result",
|
||||
StartedAtUtc = startedAtUtc,
|
||||
StartedAtProvenance = start,
|
||||
ResultObservedAtUtc = resultObservedAtUtc,
|
||||
ResultProvenance = result,
|
||||
};
|
||||
|
||||
[Fact]
|
||||
public void Rejected_result_line_against_a_line_anchored_start_omits_the_span()
|
||||
{
|
||||
// Session 4377911b, script d94468af: start 15:19:57.005 local, self-anchored (+120);
|
||||
// result 15:20:07.391 local, re-read after a rewind and resolved in the reader's
|
||||
// zone (+60) → 14:20:07Z, one hour ahead of the clock. The raw pair reads 3610 s.
|
||||
var clockNow = new DateTime(2026, 9, 17, 13, 20, 7, 437, DateTimeKind.Utc);
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var startUtc = new DateTime(2026, 9, 17, 13, 19, 57, 5, DateTimeKind.Utc);
|
||||
var resultRaw = new DateTime(2026, 9, 17, 14, 20, 7, 391, DateTimeKind.Utc);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("d94468af",
|
||||
startUtc, Line(startUtc, 120, CmTraceOffsetOrigin.LineAnchored, measured: 120),
|
||||
resultRaw, Line(resultRaw, 60, CmTraceOffsetOrigin.None, measured: 120)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal(clockNow, info.OccurredAtUtc); // stamp: clamped to the clock
|
||||
Assert.Equal("true", info.Payload!["derivedTimestamp"]);
|
||||
Assert.Equal(resultRaw.ToString("o"), info.Payload["rejectedSourceTimestamp"]);
|
||||
Assert.False(info.Payload.ContainsKey("durationSeconds"));
|
||||
Assert.False(info.Payload.ContainsKey("durationBasis"));
|
||||
Assert.Equal("rejected-endpoint", info.Payload["durationSuppressedReason"]);
|
||||
Assert.Equal("unverified", info.Payload["durationProvenance"]);
|
||||
// The end line's own provenance and the start line's, side by side.
|
||||
Assert.Equal("reader-zone-fallback", info.Payload["sourceOffsetOrigin"]);
|
||||
Assert.Equal("60", info.Payload["sourceOffsetMinutes"]);
|
||||
Assert.Equal("120", info.Payload["measuredWriterOffsetMinutes"]);
|
||||
Assert.Equal("2026-09-17T15:20:07.3910000", info.Payload["sourceLocalTs"]);
|
||||
Assert.Equal("line-anchored", info.Payload["startSourceOffsetOrigin"]);
|
||||
Assert.Equal("120", info.Payload["startSourceOffsetMinutes"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Rejected_era_anchored_result_of_a_failed_script_omits_the_span_and_the_timeout_verdict()
|
||||
{
|
||||
// Fleet shape (script_failed, daily in one tenant): result era-anchored at −420 (the
|
||||
// OOBE default zone's era) on a line written under +600 → 17 h ahead of the clock;
|
||||
// the 61203 s "run" of a 3 s script fired script_timeout_suspected every day.
|
||||
var clockNow = new DateTime(2026, 9, 21, 1, 30, 13, DateTimeKind.Utc);
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var startUtc = clockNow.AddSeconds(-8);
|
||||
var resultRaw = clockNow.AddSeconds(-5).AddHours(17);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("88d406eb",
|
||||
startUtc, Line(startUtc, 600, CmTraceOffsetOrigin.LineAnchored),
|
||||
resultRaw, Line(resultRaw, -420, CmTraceOffsetOrigin.EraAnchored, anchor: "bootstrap-policy-result", measured: 600),
|
||||
outcome: "Failed"));
|
||||
|
||||
var failed = f.InfoEvent(SharedEventTypes.ScriptFailed);
|
||||
Assert.Equal("rejected-endpoint", failed.Payload!["durationSuppressedReason"]);
|
||||
Assert.False(failed.Payload.ContainsKey("durationSeconds"));
|
||||
Assert.Equal("era-anchored", failed.Payload["sourceOffsetOrigin"]);
|
||||
Assert.Equal("bootstrap-policy-result", failed.Payload["sourceOffsetAnchor"]);
|
||||
Assert.Empty(f.InfoEvents(SharedEventTypes.ScriptTimeoutSuspected));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Mixed_pair_on_the_offset_grid_omits_the_span_even_when_nothing_was_rejected()
|
||||
{
|
||||
// Session cbaed57b: start from AgentExecutor.log in the reader's zone (+120, two
|
||||
// hours too early), result era-anchored at 0 in the service log → 7205 s.
|
||||
var clockNow = new DateTime(2026, 9, 11, 8, 48, 25, DateTimeKind.Utc);
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(-7205);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("846cea22",
|
||||
startUtc, Line(startUtc, 120, CmTraceOffsetOrigin.None, file: ExecutorLog),
|
||||
resultUtc, Line(resultUtc, 0, CmTraceOffsetOrigin.EraAnchored, anchor: "bootstrap-policy-result")));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.False(info.Payload!.ContainsKey("derivedTimestamp"));
|
||||
Assert.False(info.Payload.ContainsKey("durationSeconds"));
|
||||
Assert.Equal("offset-grid", info.Payload["durationSuppressedReason"]);
|
||||
Assert.Equal("unverified", info.Payload["durationProvenance"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Mixed_pair_off_the_grid_keeps_the_span_as_unverified()
|
||||
{
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(-26);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("f6f67f79",
|
||||
startUtc, Line(startUtc, 120, CmTraceOffsetOrigin.LineAnchored),
|
||||
resultUtc, Line(resultUtc, 120, CmTraceOffsetOrigin.None)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal("26.00", info.Payload!["durationSeconds"]);
|
||||
Assert.Equal("script_runtime", info.Payload["durationBasis"]);
|
||||
Assert.Equal("unverified", info.Payload["durationProvenance"]);
|
||||
Assert.False(info.Payload.ContainsKey("durationSuppressedReason"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Two_line_anchored_ends_on_the_grid_are_a_verified_fifteen_minute_run()
|
||||
{
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(-900);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("11111111",
|
||||
startUtc, Line(startUtc, 120, CmTraceOffsetOrigin.LineAnchored),
|
||||
resultUtc, Line(resultUtc, 120, CmTraceOffsetOrigin.LineAnchored)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal("900.00", info.Payload!["durationSeconds"]);
|
||||
Assert.Equal("verified", info.Payload["durationProvenance"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Two_fallback_ends_from_the_same_file_share_their_error_and_stay_measurable()
|
||||
{
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(-900);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("22222222",
|
||||
startUtc, Line(startUtc, 60, CmTraceOffsetOrigin.None),
|
||||
resultUtc, Line(resultUtc, 60, CmTraceOffsetOrigin.None)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal("900.00", info.Payload!["durationSeconds"]);
|
||||
Assert.Equal("verified", info.Payload["durationProvenance"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Two_fallback_ends_from_different_files_are_different_writers()
|
||||
{
|
||||
// Same reader zone applied to both, but the executor child process and the service
|
||||
// can hold different beliefs (cbaed57b) — a grid-sized span is not trusted.
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(-900);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("33333333",
|
||||
startUtc, Line(startUtc, 60, CmTraceOffsetOrigin.None, file: ExecutorLog),
|
||||
resultUtc, Line(resultUtc, 60, CmTraceOffsetOrigin.None)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.False(info.Payload!.ContainsKey("durationSeconds"));
|
||||
Assert.Equal("offset-grid", info.Payload["durationSuppressedReason"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Without_provenance_the_pair_is_taken_as_before()
|
||||
{
|
||||
// States from before the field (persisted by an older agent) and synthetic events:
|
||||
// no snapshot on either end, the 30-minute Failed run still reads as a timeout.
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
f.Tracker.LastMatchedLogTimestamp = clockNow.AddSeconds(-1);
|
||||
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
|
||||
{
|
||||
PolicyId = "44444444",
|
||||
ScriptType = "platform",
|
||||
ExitCode = 0,
|
||||
Result = "Failed",
|
||||
StartedAtUtc = clockNow.AddSeconds(-1801),
|
||||
});
|
||||
|
||||
var failed = f.InfoEvent(SharedEventTypes.ScriptFailed);
|
||||
Assert.Equal("1800.00", failed.Payload!["durationSeconds"]);
|
||||
Assert.False(failed.Payload.ContainsKey("durationProvenance"));
|
||||
Assert.False(failed.Payload.ContainsKey("durationSuppressedReason"));
|
||||
Assert.Single(f.InfoEvents(SharedEventTypes.ScriptTimeoutSuspected));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Negative_grid_sized_span_from_a_future_shifted_start_is_named_not_dropped_silently()
|
||||
{
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var resultUtc = clockNow.AddSeconds(-1);
|
||||
var startUtc = resultUtc.AddSeconds(3595); // resolved one hour ahead of its real instant
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(Platform("55555555",
|
||||
startUtc, Line(startUtc, 60, CmTraceOffsetOrigin.None),
|
||||
resultUtc, Line(resultUtc, 120, CmTraceOffsetOrigin.LineAnchored)));
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.False(info.Payload!.ContainsKey("durationSeconds"));
|
||||
Assert.Equal("offset-grid", info.Payload["durationSuppressedReason"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Health_script_cycle_is_judged_the_same_way()
|
||||
{
|
||||
// HS-SCRIPT-START self-anchored, HS-NEW-RESULT re-read in the reader's zone and
|
||||
// rejected: the cycle duration is omitted, the compliance verdict stays.
|
||||
var clockNow = ImeLogTrackerAdapterFixture.DefaultClockStart;
|
||||
using var f = new ImeLogTrackerAdapterFixture(clockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var startUtc = clockNow.AddSeconds(-40);
|
||||
var resultRaw = clockNow.AddSeconds(-2).AddHours(1);
|
||||
|
||||
adapter.TriggerScriptCompletedFromTest(new ScriptExecutionState
|
||||
{
|
||||
PolicyId = "66666666",
|
||||
ScriptType = "remediation",
|
||||
ScriptPart = "detection",
|
||||
ExitCode = 0,
|
||||
ComplianceResult = "True",
|
||||
StartedAtUtc = startUtc,
|
||||
StartedAtProvenance = Line(startUtc, 120, CmTraceOffsetOrigin.LineAnchored),
|
||||
ResultObservedAtUtc = resultRaw,
|
||||
ResultProvenance = Line(resultRaw, 60, CmTraceOffsetOrigin.None),
|
||||
DurationBasis = "cycle_including_reporting_latency",
|
||||
});
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal("True", info.Payload!["complianceResult"]);
|
||||
Assert.False(info.Payload.ContainsKey("durationSeconds"));
|
||||
Assert.Equal("rejected-endpoint", info.Payload["durationSuppressedReason"]);
|
||||
}
|
||||
}
|
||||
}
|
||||
+42
@@ -1,4 +1,5 @@
|
||||
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;
|
||||
@@ -45,5 +46,46 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
Assert.Equal("ime_policy_result", info.Payload["resultSource"]);
|
||||
Assert.Equal("92.00", info.Payload["durationSeconds"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Held_completion_carries_the_provenance_of_its_result_line()
|
||||
{
|
||||
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
|
||||
var startTs = ClockNow.AddSeconds(-95);
|
||||
var resultTs = ClockNow.AddSeconds(-3);
|
||||
|
||||
// Start and result lines both self-anchored (+120).
|
||||
f.Tracker.LastMatchedLogTimestamp = startTs;
|
||||
f.Tracker.LastMatchedSourceLocalTimestamp = DateTime.SpecifyKind(startTs.AddMinutes(120), DateTimeKind.Unspecified);
|
||||
f.Tracker.LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.LineAnchored;
|
||||
f.Tracker.LastMatchedSourceOffsetMinutes = 120;
|
||||
f.Tracker.HandlePlatformScriptStarted("376ee51a");
|
||||
|
||||
f.Tracker.LastMatchedLogTimestamp = resultTs;
|
||||
f.Tracker.LastMatchedSourceLocalTimestamp = DateTime.SpecifyKind(resultTs.AddMinutes(120), DateTimeKind.Unspecified);
|
||||
f.Tracker.LastMatchedPatternId = "PS-SCRIPT-RESULT";
|
||||
f.Tracker.CompletePlatformScriptFromImeResultForTesting("376ee51a", "Success", resultTs);
|
||||
|
||||
// By the time the held completion is emitted, the last matched line is an unrelated
|
||||
// one resolved in the reader's zone.
|
||||
f.Tracker.LastMatchedLogTimestamp = ClockNow.AddSeconds(-1);
|
||||
f.Tracker.LastMatchedSourceLocalTimestamp = DateTime.SpecifyKind(ClockNow.AddSeconds(-1).AddMinutes(60), DateTimeKind.Unspecified);
|
||||
f.Tracker.LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None;
|
||||
f.Tracker.LastMatchedSourceOffsetMinutes = 60;
|
||||
f.Tracker.LastMatchedPatternId = "IME-DOWNLOADING";
|
||||
f.Tracker.RecordPlatformScriptExitCodeForTesting("376ee51a", 0, resultTs.AddMilliseconds(-8));
|
||||
f.Tracker.FlushPendingPlatformScriptResults(f.Clock.UtcNow);
|
||||
|
||||
var info = f.InfoEvent(SharedEventTypes.ScriptCompleted);
|
||||
Assert.Equal("line-anchored", info.Payload!["sourceOffsetOrigin"]);
|
||||
Assert.Equal("120", info.Payload["sourceOffsetMinutes"]);
|
||||
Assert.Equal(resultTs.AddMinutes(120).ToString("yyyy-MM-ddTHH:mm:ss.fffffff"), info.Payload["sourceLocalTs"]);
|
||||
Assert.Equal("line-anchored", info.Payload["startSourceOffsetOrigin"]);
|
||||
Assert.Equal("120", info.Payload["startSourceOffsetMinutes"]);
|
||||
Assert.Equal("92.00", info.Payload["durationSeconds"]);
|
||||
Assert.Equal("verified", info.Payload["durationProvenance"]);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+57
@@ -0,0 +1,57 @@
|
||||
using System;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// How ONE CMTrace line's UTC value was arrived at, captured at the line itself.
|
||||
/// <para>
|
||||
/// The tracker exposes the provenance of the line it matched last. A consumer that acts later —
|
||||
/// a platform-script result held for its executor end block, a run duration spanning a start
|
||||
/// line and a result line — must describe ITS line, not whichever line happened to be matched
|
||||
/// last, so the snapshot travels on <see cref="ScriptExecutionState"/> (persisted as a plain
|
||||
/// DTO; null on state files written before it existed).
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class CmTraceLineProvenance
|
||||
{
|
||||
/// <summary>
|
||||
/// The line's local time exactly as the writer wrote it (Kind Unspecified, no zone). Null
|
||||
/// when the value did not come from a CMTrace line at all (clock fallback).
|
||||
/// </summary>
|
||||
public DateTime? SourceLocalTs { get; set; }
|
||||
|
||||
/// <summary>How the offset applied to <see cref="SourceLocalTs"/> was obtained.</summary>
|
||||
public CmTraceOffsetOrigin Origin { get; set; }
|
||||
|
||||
/// <summary>The offset that was applied, in minutes (local = UTC + offset).</summary>
|
||||
public int? OffsetMinutes { get; set; }
|
||||
|
||||
/// <summary>For <see cref="CmTraceOffsetOrigin.EraAnchored"/>: which anchor established the era's offset.</summary>
|
||||
public string EraAnchorKind { get; set; }
|
||||
|
||||
/// <summary>What the calibrator measured for the source file — observational, never applied.</summary>
|
||||
public int? MeasuredWriterOffsetMinutes { get; set; }
|
||||
|
||||
/// <summary>Name of the log file the line was read from — the closest thing to a writer identity the tracker has.</summary>
|
||||
public string SourceFileName { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// True when the applied offset was ASSUMED for this line rather than declared by the
|
||||
/// writer or measured against the agent clock: the reader's own zone (fallback), a writer
|
||||
/// era's anchor, or the retired per-file calibration. A clock-derived value (no source
|
||||
/// timestamp) sits on the true UTC axis and is not an assumption.
|
||||
/// </summary>
|
||||
public bool IsAssumed()
|
||||
{
|
||||
if (!SourceLocalTs.HasValue) return false;
|
||||
switch (Origin)
|
||||
{
|
||||
case CmTraceOffsetOrigin.Bias:
|
||||
case CmTraceOffsetOrigin.LineAnchored:
|
||||
return false;
|
||||
default:
|
||||
return true;
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+17
@@ -159,6 +159,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return true;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Whether a span between two resolved lines is the signature of a wrong offset on one
|
||||
/// of them rather than of elapsed time: a zone error is always a whole number of grid
|
||||
/// steps, so a span within <see cref="MaxGridResidual"/> of k × <see cref="OffsetGrid"/>
|
||||
/// (k ≥ 1) reads as an offset error plus a run time of seconds. Sign is ignored — a wrong
|
||||
/// offset on the START end produces the same magnitude with the opposite sign.
|
||||
/// </summary>
|
||||
internal static bool IsOnOffsetGrid(TimeSpan span, out int gridSteps)
|
||||
{
|
||||
var magnitude = span.Duration();
|
||||
gridSteps = (int)Math.Round(magnitude.TotalMinutes / OffsetGrid.TotalMinutes, MidpointRounding.AwayFromZero);
|
||||
if (gridSteps < 1) return false;
|
||||
|
||||
var nearest = TimeSpan.FromMinutes(gridSteps * OffsetGrid.TotalMinutes);
|
||||
return (magnitude - nearest).Duration() <= MaxGridResidual;
|
||||
}
|
||||
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
+59
-23
@@ -252,8 +252,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// duration when the consolidated [HS] new result line arrives (the slot above is
|
||||
// cleared by the early-signal HS-COMPLIANCE handler, so timing lives in its own
|
||||
// map). Prefer the source CMTrace timestamp; latest start wins on a policy re-run.
|
||||
var startedAtUtc = LastMatchedLogTimestamp ?? DateTime.UtcNow;
|
||||
_healthScriptStartTimes[id] = startedAtUtc;
|
||||
var startedAtUtc = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
_healthScriptStartTimes[id] = (startedAtUtc, CaptureLastMatchedProvenance());
|
||||
_logger.Info($"ImeLogTracker: health script started: {id}");
|
||||
|
||||
// A replayed line of a previous enrollment bypasses the recurrence gate: the
|
||||
@@ -281,6 +281,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
internal void HandlePlatformScriptStarted(string id, string source = null)
|
||||
{
|
||||
var currentStartTs = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
var currentStartProvenance = CaptureLastMatchedProvenance();
|
||||
|
||||
// A start line older than the result this policy already emitted is the late start
|
||||
// line of THAT run: its AgentExecutor block surfaced after the IME result — the two
|
||||
@@ -323,6 +324,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// The slot was opened by its result while the start block was still hidden;
|
||||
// the recovered start line dates the run.
|
||||
pendingSlot.StartedAtUtc = currentStartTs;
|
||||
pendingSlot.StartedAtProvenance = currentStartProvenance;
|
||||
_stateDirty = true;
|
||||
}
|
||||
}
|
||||
@@ -343,6 +345,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// Set only at slot creation: the start line fires twice (agentexecutor + ime
|
||||
// source) but the earliest wins.
|
||||
StartedAtUtc = currentStartTs,
|
||||
StartedAtProvenance = currentStartProvenance,
|
||||
};
|
||||
// Live "running" indicator — same signal health scripts emit. Gated on slot
|
||||
// creation so the duplicate start line (agentexecutor + ime source) doesn't
|
||||
@@ -433,7 +436,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
var script = GetCurrentScriptForLineUpdate(parameters, out var ownerPolicyId);
|
||||
if (script != null)
|
||||
ApplyExitCode(script, exitCode, LastMatchedLogTimestamp ?? UtcNowProvider());
|
||||
ApplyExitCode(script, exitCode, LastMatchedLogTimestamp ?? UtcNowProvider(), CaptureLastMatchedProvenance());
|
||||
else if (ownerPolicyId != null)
|
||||
_logger.Debug($"ImeLogTracker: exit code {exitCode} belongs to platform script {ownerPolicyId}, whose completion was already emitted — dropped");
|
||||
// An exit code means the executor just wrote its end block and IME is about to
|
||||
@@ -442,15 +445,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
RequestOverwriteCheck();
|
||||
}
|
||||
|
||||
private void ApplyExitCode(ScriptExecutionState script, int exitCode, DateTime observedAtUtc)
|
||||
private void ApplyExitCode(ScriptExecutionState script, int exitCode, DateTime observedAtUtc, CmTraceLineProvenance exitProvenance)
|
||||
{
|
||||
script.ExitCode = exitCode;
|
||||
// Stamp when we learned the script's exit code so the deadline-based fallback
|
||||
// (FlushPendingPlatformScriptResults) can fire if IME never logs its authoritative
|
||||
// PS-SCRIPT-RESULT line in time. Prefer the source CMTrace timestamp (already
|
||||
// UTC-normalized by the parser) so replayed log content is dated correctly.
|
||||
// UTC-normalized by the parser) so replayed log content is dated correctly. The
|
||||
// line's provenance rides along: the fallback emit is bound to this line.
|
||||
if (string.Equals(script.ScriptType, "platform", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
script.ExitObservedAtUtc = observedAtUtc;
|
||||
script.ExitProvenance = exitProvenance;
|
||||
}
|
||||
_logger.Debug($"ImeLogTracker: script exit code {exitCode} for {script.PolicyId}");
|
||||
}
|
||||
|
||||
@@ -500,7 +507,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (string.IsNullOrEmpty(id)) return;
|
||||
|
||||
CompletePlatformScriptFromImeResult(id, result, LastMatchedLogTimestamp, LastMatchedPatternId);
|
||||
CompletePlatformScriptFromImeResult(id, result, LastMatchedLogTimestamp, LastMatchedPatternId, CaptureLastMatchedProvenance());
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -514,7 +521,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// line reopened the slot, produced a fallback duplicate (session e7f3c910).
|
||||
/// <see cref="FlushPendingPlatformScriptResults"/> emits the held completion.
|
||||
/// </summary>
|
||||
internal void CompletePlatformScriptFromImeResult(string policyId, string result, DateTime? resultLineTimestampUtc, string patternId)
|
||||
internal void CompletePlatformScriptFromImeResult(string policyId, string result, DateTime? resultLineTimestampUtc, string patternId, CmTraceLineProvenance resultProvenance)
|
||||
{
|
||||
// Dedup: the deadline-based fallback (FlushPendingPlatformScriptResults) may already have
|
||||
// emitted this script from its AgentExecutor exit code because IME's authoritative
|
||||
@@ -559,6 +566,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
script.Result = result;
|
||||
script.ResultSource = "ime_policy_result";
|
||||
script.ResultObservedAtUtc = resultLineTimestampUtc ?? UtcNowProvider();
|
||||
script.ResultProvenance = resultProvenance;
|
||||
script.ResultPatternId = patternId;
|
||||
_stateDirty = true;
|
||||
|
||||
@@ -584,7 +592,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_logger.Info($"ImeLogTracker: platform script completed: {script.PolicyId}, result={script.Result}, exit={script.ExitCode}{(note != null ? $" ({note})" : string.Empty)}");
|
||||
EmitScriptEvent(script);
|
||||
_platformScriptResultEmitted[script.PolicyId] = script.ResultObservedAtUtc ?? script.ExitObservedAtUtc ?? UtcNowProvider();
|
||||
// The run's source stamp, capped at the clock: a result line cannot be read before it
|
||||
// was written, so a stamp ahead of the clock is a wrong zone assumption on that line
|
||||
// (a rewound result resolved in the reader's zone, session 4377911b: +1 h). Left
|
||||
// uncapped, the marker made the genuine NEXT run's start line read as a late line of
|
||||
// this run and its result a duplicate.
|
||||
var runStamp = script.ResultObservedAtUtc ?? script.ExitObservedAtUtc ?? UtcNowProvider();
|
||||
var nowUtc = UtcNowProvider();
|
||||
_platformScriptResultEmitted[script.PolicyId] = runStamp > nowUtc ? nowUtc : runStamp;
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
_stateDirty = true;
|
||||
}
|
||||
@@ -681,7 +696,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
/// <summary>Test seam: inject a pending platform script as if AgentExecutor.log had reported
|
||||
/// its start + exit code, without an IME PS-SCRIPT-RESULT line.</summary>
|
||||
internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null, DateTime? startedAtUtc = null)
|
||||
internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null, DateTime? startedAtUtc = null,
|
||||
CmTraceLineProvenance startedAtProvenance = null, CmTraceLineProvenance exitProvenance = null)
|
||||
{
|
||||
// Mirrors a fresh execution start: a new run clears any prior emitted-marker (see
|
||||
// HandleScriptStarted) so re-runs of the same policy within one lifetime emit again.
|
||||
@@ -694,6 +710,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
ExitObservedAtUtc = exitObservedAtUtc,
|
||||
Stdout = stdout,
|
||||
StartedAtUtc = startedAtUtc,
|
||||
StartedAtProvenance = startedAtProvenance,
|
||||
ExitProvenance = exitProvenance,
|
||||
};
|
||||
NextTestEntry();
|
||||
RecordInvocationMarker(policyId, isClose: false);
|
||||
@@ -703,18 +721,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// (the production handler minus regex extraction). <paramref name="resultLineTimestampUtc"/>
|
||||
/// stands in for the CMTrace timestamp of the PS-SCRIPT-RESULT line (production reads it
|
||||
/// via <see cref="LastMatchedLogTimestamp"/>, the fallback here).</summary>
|
||||
internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result, DateTime? resultLineTimestampUtc = null)
|
||||
internal void CompletePlatformScriptFromImeResultForTesting(string policyId, string result, DateTime? resultLineTimestampUtc = null, CmTraceLineProvenance resultProvenance = null)
|
||||
{
|
||||
if (string.IsNullOrEmpty(policyId)) return;
|
||||
CompletePlatformScriptFromImeResult(policyId, result, resultLineTimestampUtc ?? LastMatchedLogTimestamp, "PS-SCRIPT-RESULT");
|
||||
CompletePlatformScriptFromImeResult(policyId, result, resultLineTimestampUtc ?? LastMatchedLogTimestamp, "PS-SCRIPT-RESULT", resultProvenance ?? CaptureLastMatchedProvenance());
|
||||
}
|
||||
|
||||
/// <summary>Test seam: the AgentExecutor exit-code line of a pending platform script (the
|
||||
/// production handler minus regex extraction and positional ownership).</summary>
|
||||
internal void RecordPlatformScriptExitCodeForTesting(string policyId, int exitCode, DateTime observedAtUtc)
|
||||
internal void RecordPlatformScriptExitCodeForTesting(string policyId, int exitCode, DateTime observedAtUtc, CmTraceLineProvenance exitProvenance = null)
|
||||
{
|
||||
if (_pendingPlatformScripts.TryGetValue(policyId, out var script))
|
||||
ApplyExitCode(script, exitCode, observedAtUtc);
|
||||
ApplyExitCode(script, exitCode, observedAtUtc, exitProvenance);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -790,8 +808,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// HS-NEW-RESULT path whose end stamp includes IME's batched reporting latency.
|
||||
// Peek only: HS-NEW-RESULT still consumes + removes the entry for cycle timing.
|
||||
StartedAtUtc = _healthScriptStartTimes.TryGetValue(id, out var earlyStart)
|
||||
? earlyStart
|
||||
? earlyStart.Utc
|
||||
: (DateTime?)null,
|
||||
StartedAtProvenance = _healthScriptStartTimes.TryGetValue(id, out var earlyStartProvenance)
|
||||
? earlyStartProvenance.Provenance
|
||||
: null,
|
||||
// The HS-COMPLIANCE line is the end of this phase; emitted synchronously, so the
|
||||
// last matched line is it.
|
||||
ResultProvenance = CaptureLastMatchedProvenance(),
|
||||
DurationBasis = "script_runtime",
|
||||
};
|
||||
|
||||
@@ -860,10 +884,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// HS-SCRIPT-START line had been observed, so a subsequent
|
||||
/// <see cref="HandleHealthScriptResultJson"/> surfaces a run duration without driving the
|
||||
/// full regex pipeline.</summary>
|
||||
internal void SeedHealthScriptStartForTesting(string policyId, DateTime startedAtUtc)
|
||||
internal void SeedHealthScriptStartForTesting(string policyId, DateTime startedAtUtc, CmTraceLineProvenance provenance = null)
|
||||
{
|
||||
if (string.IsNullOrEmpty(policyId)) return;
|
||||
_healthScriptStartTimes[policyId] = startedAtUtc;
|
||||
_healthScriptStartTimes[policyId] = (startedAtUtc, provenance);
|
||||
}
|
||||
|
||||
private void HandleHealthScriptResult(Match match, Dictionary<string, string> parameters)
|
||||
@@ -920,10 +944,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// emitted phase events — the remediation analog of platform-script timing. Consumed +
|
||||
// removed so a later re-run of the same policy re-times from its own start. Null when
|
||||
// the start line was never seen in the agent's window (e.g. a replayed result).
|
||||
DateTime? cycleStartedAtUtc = _healthScriptStartTimes.TryGetValue(policyId, out var hsStart)
|
||||
? hsStart
|
||||
: (DateTime?)null;
|
||||
var hasCycleStart = _healthScriptStartTimes.TryGetValue(policyId, out var hsStart);
|
||||
DateTime? cycleStartedAtUtc = hasCycleStart ? hsStart.Utc : (DateTime?)null;
|
||||
var cycleStartProvenance = hasCycleStart ? hsStart.Provenance : null;
|
||||
_healthScriptStartTimes.Remove(policyId);
|
||||
// Every phase ends on this HS-NEW-RESULT line.
|
||||
var resultProvenance = CaptureLastMatchedProvenance();
|
||||
|
||||
// Common metadata — applied to every emitted phase event.
|
||||
var remediationStatus = TryGetInt(root, "RemediationStatus");
|
||||
@@ -963,7 +989,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
targetType: targetType,
|
||||
errorCode: errorCode,
|
||||
errorDetails: errorDetails,
|
||||
startedAtUtc: cycleStartedAtUtc);
|
||||
startedAtUtc: cycleStartedAtUtc,
|
||||
startedAtProvenance: cycleStartProvenance,
|
||||
resultProvenance: resultProvenance);
|
||||
// complianceResult mirrors the legacy HS-COMPLIANCE event semantics: True when the
|
||||
// pre-detection script reported compliant (exit 0), False otherwise.
|
||||
detection.ComplianceResult = firstDetectExit == 0 ? "True" : (firstDetectExit.HasValue ? "False" : null);
|
||||
@@ -987,7 +1015,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
targetType: targetType,
|
||||
errorCode: errorCode,
|
||||
errorDetails: errorDetails,
|
||||
startedAtUtc: cycleStartedAtUtc);
|
||||
startedAtUtc: cycleStartedAtUtc,
|
||||
startedAtProvenance: cycleStartProvenance,
|
||||
resultProvenance: resultProvenance);
|
||||
// No complianceResult on the remediation phase — there is nothing to be compliant about.
|
||||
EmitScriptEvent(remediation);
|
||||
}
|
||||
@@ -1009,7 +1039,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
targetType: targetType,
|
||||
errorCode: errorCode,
|
||||
errorDetails: errorDetails,
|
||||
startedAtUtc: cycleStartedAtUtc);
|
||||
startedAtUtc: cycleStartedAtUtc,
|
||||
startedAtProvenance: cycleStartProvenance,
|
||||
resultProvenance: resultProvenance);
|
||||
postDetection.ComplianceResult = lastDetectExit == 0 ? "True" : (lastDetectExit.HasValue ? "False" : null);
|
||||
EmitScriptEvent(postDetection);
|
||||
}
|
||||
@@ -1032,7 +1064,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
int? targetType,
|
||||
int? errorCode,
|
||||
string errorDetails,
|
||||
DateTime? startedAtUtc) =>
|
||||
DateTime? startedAtUtc,
|
||||
CmTraceLineProvenance startedAtProvenance,
|
||||
CmTraceLineProvenance resultProvenance) =>
|
||||
new ScriptExecutionState
|
||||
{
|
||||
PolicyId = policyId,
|
||||
@@ -1049,6 +1083,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// Cycle start (HS-SCRIPT-START). Every phase carries the same cycle start so the
|
||||
// adapter computes the total run duration; the Web surfaces it once at card level.
|
||||
StartedAtUtc = startedAtUtc,
|
||||
StartedAtProvenance = startedAtProvenance,
|
||||
ResultProvenance = resultProvenance,
|
||||
// End stamp is the HS-NEW-RESULT line — written only after IME's batched report
|
||||
// to the service, so this duration overstates the actual script execution time.
|
||||
DurationBasis = "cycle_including_reporting_latency"
|
||||
|
||||
+15
@@ -505,6 +505,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
"imetokenfailure",
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// Snapshot of the last matched line's provenance, for a consumer that acts later than
|
||||
/// the match (a held platform-script result, a run duration across two lines) and must
|
||||
/// describe THAT line rather than whichever line is matched by then.
|
||||
/// </summary>
|
||||
internal CmTraceLineProvenance CaptureLastMatchedProvenance() => new CmTraceLineProvenance
|
||||
{
|
||||
SourceLocalTs = LastMatchedSourceLocalTimestamp,
|
||||
Origin = LastMatchedSourceOffsetOrigin,
|
||||
OffsetMinutes = LastMatchedSourceOffsetMinutes,
|
||||
EraAnchorKind = LastMatchedEraAnchorKind,
|
||||
MeasuredWriterOffsetMinutes = LastMatchedMeasuredWriterOffsetMinutes,
|
||||
SourceFileName = _currentSourceFileName,
|
||||
};
|
||||
|
||||
private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry)
|
||||
{
|
||||
LastMatchedPatternId = pattern.PatternId;
|
||||
|
||||
@@ -205,8 +205,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// the remediation-script analog of the platform-script StartedAtUtc timing. Kept in a
|
||||
// dedicated map (not on _pendingHealthScript) because the early-signal HS-COMPLIANCE
|
||||
// handler clears that slot before HS-NEW-RESULT arrives. Consumed + removed on result emit.
|
||||
private readonly Dictionary<string, DateTime> _healthScriptStartTimes =
|
||||
new Dictionary<string, DateTime>(StringComparer.OrdinalIgnoreCase);
|
||||
// The start line's provenance rides along so the adapter can tell whether start and result
|
||||
// were resolved on the same zone assumption before it subtracts them.
|
||||
private readonly Dictionary<string, (DateTime Utc, CmTraceLineProvenance Provenance)> _healthScriptStartTimes =
|
||||
new Dictionary<string, (DateTime Utc, CmTraceLineProvenance Provenance)>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// Restart-safe dedup for the adapter's one-shot script_timeout_suspected Warning.
|
||||
// Owned by the tracker (not the adapter) solely so it rides the persisted state file —
|
||||
|
||||
+20
@@ -29,6 +29,15 @@ public class ScriptExecutionState
|
||||
/// </summary>
|
||||
public System.DateTime? StartedAtUtc { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Provenance of <see cref="StartedAtUtc"/>: how the start line's offset was obtained. Paired
|
||||
/// with <see cref="ResultProvenance"/> / <see cref="ExitProvenance"/> by the adapter to decide
|
||||
/// whether a run duration is measurable — two lines resolved on different zone assumptions
|
||||
/// differ by whole offset-grid steps, not by run time (session 4377911b: a 10 s script read
|
||||
/// as 3610 s). Null when the start was never observed or on state files from before the field.
|
||||
/// </summary>
|
||||
public CmTraceLineProvenance StartedAtProvenance { get; set; }
|
||||
|
||||
/// <summary>"detection", "remediation", or "post-detection" (remediation scripts only).</summary>
|
||||
public string ScriptPart { get; set; }
|
||||
|
||||
@@ -66,6 +75,9 @@ public class ScriptExecutionState
|
||||
/// </summary>
|
||||
public System.DateTime? ExitObservedAtUtc { get; set; }
|
||||
|
||||
/// <summary>Provenance of the exit-code line behind <see cref="ExitObservedAtUtc"/> (the fallback emit's end).</summary>
|
||||
public CmTraceLineProvenance ExitProvenance { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Source (CMTrace) timestamp of the IME <c>PS-SCRIPT-RESULT</c> line that delivered
|
||||
/// <see cref="Result"/> (platform scripts, <c>ime_policy_result</c> only). The emitted event is
|
||||
@@ -76,6 +88,14 @@ public class ScriptExecutionState
|
||||
/// </summary>
|
||||
public System.DateTime? ResultObservedAtUtc { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Provenance of the line that delivered <see cref="Result"/> — bound here for the same reason
|
||||
/// as <see cref="ResultObservedAtUtc"/>: a held completion is emitted passes later, when the
|
||||
/// tracker's "last matched" provenance describes an unrelated line. For health scripts the
|
||||
/// result line of the phase (HS-COMPLIANCE early signal or HS-NEW-RESULT).
|
||||
/// </summary>
|
||||
public CmTraceLineProvenance ResultProvenance { get; set; }
|
||||
|
||||
/// <summary>Pattern id of the line that delivered <see cref="Result"/> (surfaced as <c>patternId</c> on the event).</summary>
|
||||
public string ResultPatternId { get; set; }
|
||||
|
||||
|
||||
@@ -461,31 +461,35 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
/// no second clock frame, so there is nothing to record.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
private void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs)
|
||||
private void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs, CmTraceLineProvenance? lineProvenance = null)
|
||||
{
|
||||
var culture = System.Globalization.CultureInfo.InvariantCulture;
|
||||
|
||||
var sourceLocal = _tracker.LastMatchedSourceLocalTimestamp;
|
||||
// The line the event is bound to. Callers that emit later than the match (a held
|
||||
// platform-script result) pass the snapshot taken at their line; everyone else is
|
||||
// emitting while its line is still the last matched one.
|
||||
var line = lineProvenance ?? _tracker.CaptureLastMatchedProvenance();
|
||||
var sourceLocal = line.SourceLocalTs;
|
||||
if (sourceLocal.HasValue)
|
||||
{
|
||||
// No zone suffix: the value genuinely carries none, and formatting one in would
|
||||
// re-introduce the very assumption this whole change removes.
|
||||
data["sourceLocalTs"] = sourceLocal.Value.ToString("yyyy-MM-ddTHH:mm:ss.fffffff", culture);
|
||||
data["sourceOffsetOrigin"] = OriginTag(_tracker.LastMatchedSourceOffsetOrigin);
|
||||
data["sourceOffsetOrigin"] = OriginTag(line.Origin);
|
||||
|
||||
var offsetMinutes = _tracker.LastMatchedSourceOffsetMinutes;
|
||||
var offsetMinutes = line.OffsetMinutes;
|
||||
if (offsetMinutes.HasValue)
|
||||
data["sourceOffsetMinutes"] = offsetMinutes.Value.ToString(culture);
|
||||
|
||||
// Which era anchor the offset came from — forensics for the era-anchored origin.
|
||||
var anchorKind = _tracker.LastMatchedEraAnchorKind;
|
||||
var anchorKind = line.EraAnchorKind;
|
||||
if (!string.IsNullOrEmpty(anchorKind))
|
||||
data["sourceOffsetAnchor"] = anchorKind;
|
||||
|
||||
// Observational only — what the calibrator measured, which since the 2026-08-20
|
||||
// revert is deliberately NOT what was applied. Kept separate so the two can never
|
||||
// be read as the same thing.
|
||||
var measured = _tracker.LastMatchedMeasuredWriterOffsetMinutes;
|
||||
var measured = line.MeasuredWriterOffsetMinutes;
|
||||
if (measured.HasValue)
|
||||
data["measuredWriterOffsetMinutes"] = measured.Value.ToString(culture);
|
||||
}
|
||||
@@ -1293,7 +1297,11 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
if (SuppressIfHistoricReplay(derivedFromClock, rawSourceTs, eventType, script.PolicyId))
|
||||
return;
|
||||
|
||||
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
|
||||
// The line that delivered the result is bound on the state (D-247), so a completion
|
||||
// emitted passes later still describes ITS line. Null (states from before the field,
|
||||
// synthetic tests) falls back to the tracker's last matched line as before.
|
||||
var endProvenance = isFallback ? script.ExitProvenance : script.ResultProvenance;
|
||||
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs, endProvenance);
|
||||
|
||||
// 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
|
||||
@@ -1301,11 +1309,13 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// 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).
|
||||
// was rejected (future-skew — 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 span is taken from
|
||||
// the raw source pair. That pair is a run time only when both lines were resolved on
|
||||
// the same zone belief — JudgeDurationPair decides, from the provenance bound to each
|
||||
// line, whether the span is verified, unverified, or an offset error to omit (session
|
||||
// 4377911b: a 10 s script read as 3610 s). The event stamp stays `now`.
|
||||
//
|
||||
// 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
|
||||
@@ -1317,15 +1327,26 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
var completionForDuration = derivedFromClock && rawSourceTs.HasValue
|
||||
? NormalizeUtc(rawSourceTs.Value)
|
||||
: now;
|
||||
TimeSpan? measurableDuration = null;
|
||||
if (script.StartedAtUtc.HasValue)
|
||||
{
|
||||
var durationSeconds = (completionForDuration - script.StartedAtUtc.Value).TotalSeconds;
|
||||
var span = completionForDuration - script.StartedAtUtc.Value;
|
||||
var verdict = JudgeDurationPair(script.StartedAtProvenance, endProvenance,
|
||||
endStampRejected: derivedFromClock && rawSourceTs.HasValue, span, out var suppressedReason);
|
||||
if (verdict != DurationPairVerdict.Unknown)
|
||||
data["durationProvenance"] = verdict == DurationPairVerdict.Verified ? "verified" : "unverified";
|
||||
|
||||
if (verdict == DurationPairVerdict.Suppressed)
|
||||
{
|
||||
data["durationSuppressedReason"] = suppressedReason!;
|
||||
}
|
||||
// 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)
|
||||
else if (span >= TimeSpan.Zero && span <= StaleSourceThreshold)
|
||||
{
|
||||
data["durationSeconds"] = durationSeconds.ToString("F2", culture);
|
||||
measurableDuration = span;
|
||||
data["durationSeconds"] = span.TotalSeconds.ToString("F2", culture);
|
||||
data["durationBasis"] = script.DurationBasis
|
||||
?? (IsRemediation(script.ScriptType)
|
||||
? "cycle_including_reporting_latency"
|
||||
@@ -1333,6 +1354,18 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
}
|
||||
}
|
||||
|
||||
// The start line's provenance, next to the end line's (sourceOffset*), so the pair can
|
||||
// be judged downstream as well.
|
||||
var startProvenance = script.StartedAtProvenance;
|
||||
if (startProvenance != null && startProvenance.SourceLocalTs.HasValue)
|
||||
{
|
||||
data["startSourceOffsetOrigin"] = OriginTag(startProvenance.Origin);
|
||||
if (startProvenance.OffsetMinutes.HasValue)
|
||||
data["startSourceOffsetMinutes"] = startProvenance.OffsetMinutes.Value.ToString(culture);
|
||||
if (!string.IsNullOrEmpty(startProvenance.EraAnchorKind))
|
||||
data["startSourceOffsetAnchor"] = startProvenance.EraAnchorKind;
|
||||
}
|
||||
|
||||
var label = IsRemediation(script.ScriptType) ? "Remediation script" : "Platform script";
|
||||
var shortId = script.PolicyId.Length >= 8 ? script.PolicyId.Substring(0, 8) : script.PolicyId;
|
||||
string messageCore;
|
||||
@@ -1375,7 +1408,51 @@ 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, completionForDuration);
|
||||
MaybeEmitScriptTimeoutSuspected(script, now, measurableDuration);
|
||||
}
|
||||
|
||||
internal enum DurationPairVerdict { Unknown, Verified, Unverified, Suppressed }
|
||||
|
||||
/// <summary>
|
||||
/// Whether the span between a start line and an end line measures elapsed time.
|
||||
/// <para>
|
||||
/// Each CMTrace line is resolved on its own zone belief: declared or measured (bias,
|
||||
/// line-anchored, or the clock itself) — or ASSUMED (the reader's zone, a writer era's
|
||||
/// anchor). Two measured ends sit on the true UTC axis; two assumed ends resolved with the
|
||||
/// same offset from the same file share their error, which cancels (D-191). Any other pair
|
||||
/// is unverified, and its span is omitted when the end stamp was rejected as ahead of the
|
||||
/// clock — its assumption is proven wrong and the raw pair inherits the error (session
|
||||
/// 4377911b: a 10 s script read as 3610 s) — or when the span sits on the 15-minute offset
|
||||
/// grid, the signature of a wrong assumption on either end (session cbaed57b: 7200 s). A
|
||||
/// missing snapshot (state files from before the field, synthetic tests) leaves the rule
|
||||
/// off and the pair treated as before.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
internal static DurationPairVerdict JudgeDurationPair(
|
||||
CmTraceLineProvenance? start, CmTraceLineProvenance? end, bool endStampRejected, TimeSpan span, out string? suppressedReason)
|
||||
{
|
||||
suppressedReason = null;
|
||||
if (start == null || end == null) return DurationPairVerdict.Unknown;
|
||||
|
||||
var startAssumed = start.IsAssumed();
|
||||
var endAssumed = end.IsAssumed();
|
||||
var sameTimeline = (!startAssumed && !endAssumed)
|
||||
|| (startAssumed && endAssumed
|
||||
&& start.OffsetMinutes == end.OffsetMinutes
|
||||
&& string.Equals(start.SourceFileName, end.SourceFileName, StringComparison.OrdinalIgnoreCase));
|
||||
if (sameTimeline) return DurationPairVerdict.Verified;
|
||||
|
||||
if (endStampRejected)
|
||||
{
|
||||
suppressedReason = "rejected-endpoint";
|
||||
return DurationPairVerdict.Suppressed;
|
||||
}
|
||||
if (CmTraceOffsetCalibrator.IsOnOffsetGrid(span, out _))
|
||||
{
|
||||
suppressedReason = "offset-grid";
|
||||
return DurationPairVerdict.Suppressed;
|
||||
}
|
||||
return DurationPairVerdict.Unverified;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -1387,19 +1464,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.
|
||||
/// <paramref name="measurableDuration"/> is the run duration the completion event carries —
|
||||
/// null when it was omitted (no start line, implausible span, or a start/end pair resolved
|
||||
/// on different zone assumptions: the fleet's daily 17 h "timeouts" of 2–9 s scripts were
|
||||
/// offset errors); <paramref name="occurredAtUtc"/> stamps the emitted event.
|
||||
/// </summary>
|
||||
private void MaybeEmitScriptTimeoutSuspected(ScriptExecutionState script, DateTime occurredAtUtc, DateTime durationEndUtc)
|
||||
private void MaybeEmitScriptTimeoutSuspected(ScriptExecutionState script, DateTime occurredAtUtc, TimeSpan? measurableDuration)
|
||||
{
|
||||
if (IsRemediation(script.ScriptType)) return; // platform scripts only
|
||||
if (!script.StartedAtUtc.HasValue) return; // no start ⇒ no duration
|
||||
if (!measurableDuration.HasValue) return; // no measurable duration ⇒ no verdict
|
||||
if (!string.Equals(script.Result, "Failed", StringComparison.OrdinalIgnoreCase)) return;
|
||||
|
||||
var duration = durationEndUtc - script.StartedAtUtc.Value;
|
||||
var duration = measurableDuration.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)
|
||||
|
||||
|
||||
@@ -25,6 +25,11 @@ import { getErrorCodeEntry, formatErrorCode, errorCodeTooltip } from "@/utils/er
|
||||
import { userPhaseSplitIndex, type UserPhaseBoundary } from "@/lib/userPhaseBoundary";
|
||||
import PhaseDivider from "@/components/PhaseDivider";
|
||||
|
||||
// Shown where the run time would be when the agent (or the reducer, for older events) withheld
|
||||
// it: the start and end log lines were resolved on different timezone assumptions, so their
|
||||
// span is hours of offset error rather than run time (a 10 s script once read "1h 00m").
|
||||
const DURATION_SUPPRESSED_TITLE = "Run time not measurable: the start and end log lines were resolved on different timezone assumptions, so their span would be offset error, not run time";
|
||||
|
||||
interface ScriptExecutionsProps {
|
||||
events: ScriptInputEvent[];
|
||||
showScriptOutput?: boolean;
|
||||
@@ -531,6 +536,9 @@ function ScriptItemRow({ item, showScriptOutput, latestBootstrapVersion, nested,
|
||||
{durationLabel}
|
||||
</span>
|
||||
)}
|
||||
{!durationLabel && !nested && item.state !== "Running" && item.durationSuppressedReason && (
|
||||
<span className="font-mono text-gray-400" title={DURATION_SUPPRESSED_TITLE}>n/a</span>
|
||||
)}
|
||||
{item.state !== "Running" && (
|
||||
<button
|
||||
onClick={() => setShowDetails(!showDetails)}
|
||||
@@ -557,6 +565,9 @@ function ScriptItemRow({ item, showScriptOutput, latestBootstrapVersion, nested,
|
||||
{!nested && item.targetType != null && <span><span className="font-medium text-gray-700">Target:</span> {item.targetType === 2 ? "Device" : "User"}</span>}
|
||||
{item.exitCode != null && <span><span className="font-medium text-gray-700">Exit Code:</span> <span className="font-mono">{item.exitCode}</span></span>}
|
||||
{detailDurationLabel && <span><span className="font-medium text-gray-700">Duration:</span> <span className={`font-mono ${isSlowDuration ? "text-amber-600" : ""}`}>{detailDurationLabel}</span></span>}
|
||||
{!detailDurationLabel && item.durationSuppressedReason && (
|
||||
<span title={DURATION_SUPPRESSED_TITLE}><span className="font-medium text-gray-700">Duration:</span> <span className="font-mono text-gray-400">n/a</span></span>
|
||||
)}
|
||||
{reportedAfterLabel && (
|
||||
<span title="Time from script start until IME reported the result to the Intune service — includes IME's batched reporting delay, so it is longer than the script actually ran">
|
||||
<span className="font-medium text-gray-700">Reported after:</span> <span className="font-mono">{reportedAfterLabel}</span>
|
||||
|
||||
@@ -7,6 +7,7 @@ import {
|
||||
groupScriptItems,
|
||||
isDetectOnlyRow,
|
||||
isNonCompliantReport,
|
||||
isOnOffsetGrid,
|
||||
mapRemediationStatus,
|
||||
partitionHistoricScriptEvents,
|
||||
reduceScriptEvents,
|
||||
@@ -1069,3 +1070,134 @@ describe("applyObservationEnd", () => {
|
||||
expect(ended.headerLabel).toBe("Incomplete");
|
||||
});
|
||||
});
|
||||
|
||||
describe("reduceScriptEvents — duration provenance (offset error is not run time)", () => {
|
||||
const start = (data: Record<string, unknown>, at = 0): ScriptInputEvent =>
|
||||
finalEvent({ eventType: "script_started", ts: at, data: { policyId: "p1", scriptType: "platform", ...data } });
|
||||
const final = (data: Record<string, unknown>, at = 10): ScriptInputEvent =>
|
||||
finalEvent({ ts: at, data: { policyId: "p1", scriptType: "platform", exitCode: "0", result: "Success", ...data } });
|
||||
|
||||
it("drops a duration whose end line was rejected while the start line was measured (session 4377911b)", () => {
|
||||
// Start self-anchored (+120), result re-read after a rewind in the reader's zone (+60) and
|
||||
// rejected as one hour ahead of the clock: the stored 3610 s is offset error plus 10 s.
|
||||
const items = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }),
|
||||
final({
|
||||
durationSeconds: "3610.39", durationBasis: "script_runtime",
|
||||
sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60",
|
||||
derivedTimestamp: "true", rejectedSourceTimestamp: "2026-09-17T14:20:07.3915051Z",
|
||||
}),
|
||||
]);
|
||||
expect(items).toHaveLength(1);
|
||||
expect(items[0].durationSeconds).toBeUndefined();
|
||||
expect(items[0].durationSuppressedReason).toBe("rejected-endpoint");
|
||||
});
|
||||
|
||||
it("carries the agent's own verdict and never re-judges a pair the agent judged", () => {
|
||||
const suppressed = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }),
|
||||
final({ durationSuppressedReason: "offset-grid", durationProvenance: "unverified" }),
|
||||
]);
|
||||
expect(suppressed[0].durationSeconds).toBeUndefined();
|
||||
expect(suppressed[0].durationSuppressedReason).toBe("offset-grid");
|
||||
|
||||
const unverified = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }),
|
||||
final({
|
||||
durationSeconds: "3610.00", durationBasis: "script_runtime", durationProvenance: "unverified",
|
||||
sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60", derivedTimestamp: "true",
|
||||
}),
|
||||
]);
|
||||
expect(unverified[0].durationSeconds).toBe(3610);
|
||||
expect(unverified[0].durationSuppressedReason).toBeUndefined();
|
||||
});
|
||||
|
||||
it("drops a mixed pair on the offset grid even when nothing was rejected (session cbaed57b)", () => {
|
||||
const items = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "120" }),
|
||||
final({
|
||||
durationSeconds: "7205.66", durationBasis: "script_runtime",
|
||||
sourceOffsetOrigin: "era-anchored", sourceOffsetMinutes: "0",
|
||||
}, 7206),
|
||||
]);
|
||||
expect(items[0].durationSeconds).toBeUndefined();
|
||||
expect(items[0].durationSuppressedReason).toBe("offset-grid");
|
||||
});
|
||||
|
||||
it("keeps a mixed pair off the grid, and any pair on one timeline", () => {
|
||||
const offGrid = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }),
|
||||
final({ durationSeconds: "26.40", durationBasis: "script_runtime", sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "120" }, 27),
|
||||
]);
|
||||
expect(offGrid[0].durationSeconds).toBe(26.4);
|
||||
expect(offGrid[0].durationSuppressedReason).toBeUndefined();
|
||||
|
||||
const bothMeasured = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }),
|
||||
final({ durationSeconds: "900.00", durationBasis: "script_runtime", sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }, 900),
|
||||
]);
|
||||
expect(bothMeasured[0].durationSeconds).toBe(900);
|
||||
|
||||
const bothAssumedSameOffset = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60" }),
|
||||
final({ durationSeconds: "900.00", durationBasis: "script_runtime", sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60" }, 900),
|
||||
]);
|
||||
expect(bothAssumedSameOffset[0].durationSeconds).toBe(900);
|
||||
});
|
||||
|
||||
it("leaves events without provenance, or without a start line, as they were", () => {
|
||||
const noProvenance = reduceScriptEvents([
|
||||
start({}),
|
||||
final({ durationSeconds: "3610.00", durationBasis: "script_runtime", derivedTimestamp: "true" }),
|
||||
]);
|
||||
expect(noProvenance[0].durationSeconds).toBe(3610);
|
||||
|
||||
const noStart = reduceScriptEvents([
|
||||
final({ durationSeconds: "3610.00", durationBasis: "script_runtime", sourceOffsetOrigin: "reader-zone-fallback", derivedTimestamp: "true" }),
|
||||
]);
|
||||
expect(noStart[0].durationSeconds).toBe(3610);
|
||||
});
|
||||
|
||||
it("pairs a final with the latest start at or before it", () => {
|
||||
// Run 1 (measured start, rejected end) and run 2 (both measured) of the same policy.
|
||||
const items = reduceScriptEvents([
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }, 0),
|
||||
final({ durationSeconds: "3610.00", durationBasis: "script_runtime", sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60", derivedTimestamp: "true", exitCode: "1" }, 10),
|
||||
start({ sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }, 100),
|
||||
final({ durationSeconds: "8.57", durationBasis: "script_runtime", sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" }, 109),
|
||||
]);
|
||||
// Same key → the more complete entry wins; the second run's verified duration is kept.
|
||||
expect(items).toHaveLength(1);
|
||||
expect(items[0].durationSeconds).toBe(8.57);
|
||||
expect(items[0].durationSuppressedReason).toBeUndefined();
|
||||
});
|
||||
|
||||
it("withholds the cycle value of a remediation phase quietly (no note where no run time is shown)", () => {
|
||||
const items = reduceScriptEvents([
|
||||
finalEvent({ eventType: "script_started", ts: 0, data: { policyId: "h1", scriptType: "remediation", sourceOffsetOrigin: "line-anchored", sourceOffsetMinutes: "120" } }),
|
||||
finalEvent({ ts: 40, data: {
|
||||
policyId: "h1", scriptType: "remediation", scriptPart: "detection", exitCode: "0",
|
||||
durationSeconds: "3640.00", durationBasis: "cycle_including_reporting_latency",
|
||||
sourceOffsetOrigin: "reader-zone-fallback", sourceOffsetMinutes: "60", derivedTimestamp: "true",
|
||||
} }),
|
||||
]);
|
||||
expect(items[0].reportedAfterSeconds).toBeUndefined();
|
||||
expect(items[0].durationSeconds).toBeUndefined();
|
||||
expect(items[0].durationSuppressedReason).toBeUndefined();
|
||||
});
|
||||
});
|
||||
|
||||
describe("isOnOffsetGrid", () => {
|
||||
it("recognises whole offset-grid steps plus seconds of run time, in either direction", () => {
|
||||
expect(isOnOffsetGrid(3610.39)).toBe(true); // +1 h on a 10 s script
|
||||
expect(isOnOffsetGrid(61203)).toBe(true); // 17 h on a 3 s script
|
||||
expect(isOnOffsetGrid(7205.66)).toBe(true); // +2 h
|
||||
expect(isOnOffsetGrid(-3596)).toBe(true); // the same error on the start end
|
||||
expect(isOnOffsetGrid(900)).toBe(true); // one step — the caller needs mixed provenance too
|
||||
});
|
||||
it("rejects spans below one step or off the grid", () => {
|
||||
expect(isOnOffsetGrid(26.4)).toBe(false);
|
||||
expect(isOnOffsetGrid(1030)).toBe(false); // 17 min 10 s
|
||||
expect(isOnOffsetGrid(0)).toBe(false);
|
||||
});
|
||||
});
|
||||
|
||||
@@ -28,6 +28,14 @@ interface ScriptEventData {
|
||||
compliance_result?: string;
|
||||
errorDetails?: string;
|
||||
error_details?: string;
|
||||
/** Why the agent withheld the run duration ("rejected-endpoint" | "offset-grid"); agents from 2026-09 on. */
|
||||
durationSuppressedReason?: string;
|
||||
/** "verified" | "unverified": the agent judged the start/end pair itself; agents from 2026-09 on. */
|
||||
durationProvenance?: string;
|
||||
/** Timestamp provenance of the event's own log line (see lib/timeProvenance.ts). */
|
||||
sourceOffsetOrigin?: string;
|
||||
/** "true" when the line's own timestamp was rejected and the event was stamped from the clock. */
|
||||
derivedTimestamp?: string | boolean;
|
||||
}
|
||||
|
||||
export interface ScriptItem {
|
||||
@@ -61,6 +69,14 @@ export interface ScriptItem {
|
||||
* "Reported after Xm" in the details panel, never as the run duration.
|
||||
*/
|
||||
reportedAfterSeconds?: number;
|
||||
/**
|
||||
* Set when the run duration was withheld because the start and end log lines were resolved
|
||||
* on different timezone assumptions — the span is then whole hours of offset error, not run
|
||||
* time (a 10 s script read "1h 00m"). From the agent's own verdict, or from the same rule
|
||||
* applied here to events stored before the agent carried it. Rendered as "n/a" with an
|
||||
* explanation where the duration would be.
|
||||
*/
|
||||
durationSuppressedReason?: string;
|
||||
state: "Running" | "Success" | "Failed";
|
||||
timestamp: string;
|
||||
bootstrapVersion?: string | null;
|
||||
@@ -269,6 +285,69 @@ export function isNonCompliantReport(item: Pick<ScriptItem, "scriptType" | "scri
|
||||
&& item.complianceResult === "False";
|
||||
}
|
||||
|
||||
// Every real UTC offset is a whole number of 15-minute steps, so a span within two minutes of
|
||||
// k × 15 min (k ≥ 1) is the signature of a wrong offset on one endpoint plus seconds of run
|
||||
// time — the agent's CmTraceOffsetCalibrator.IsOnOffsetGrid, mirrored for stored events.
|
||||
const OFFSET_GRID_SECONDS = 15 * 60;
|
||||
const MAX_GRID_RESIDUAL_SECONDS = 2 * 60;
|
||||
|
||||
/** Timestamp origins where the offset was assumed rather than declared by the writer or measured. */
|
||||
const ASSUMED_ORIGINS: ReadonlySet<string> = new Set(["reader-zone-fallback", "era-anchored", "calibrated"]);
|
||||
|
||||
export function isOnOffsetGrid(seconds: number): boolean {
|
||||
const magnitude = Math.abs(seconds);
|
||||
const steps = Math.round(magnitude / OFFSET_GRID_SECONDS);
|
||||
if (steps < 1) return false;
|
||||
return Math.abs(magnitude - steps * OFFSET_GRID_SECONDS) <= MAX_GRID_RESIDUAL_SECONDS;
|
||||
}
|
||||
|
||||
/**
|
||||
* Why a final's run duration must not be shown, or null when it may. The agent's own verdict
|
||||
* wins (durationSuppressedReason / durationProvenance). For events from agents without it the
|
||||
* rule is applied here to the paired start line: a pair is on one timeline when both lines were
|
||||
* measured (line-anchored, bias) or both assumed with the same applied offset; any other pair
|
||||
* is dropped when the end line's own timestamp was rejected (its assumption is proven wrong and
|
||||
* the stored duration inherits the error) or when the span sits on the offset grid. Provenance
|
||||
* missing on either line (agents before 2026-08-20) leaves the value as it was.
|
||||
*/
|
||||
export function judgeDurationPair(
|
||||
start: ScriptEventData | undefined,
|
||||
final: ScriptEventData,
|
||||
durationSeconds: number | undefined
|
||||
): string | null {
|
||||
if (typeof final.durationSuppressedReason === "string" && final.durationSuppressedReason.length > 0) {
|
||||
return final.durationSuppressedReason;
|
||||
}
|
||||
if (typeof final.durationProvenance === "string") return null;
|
||||
if (durationSeconds == null || !start) return null;
|
||||
|
||||
const startOrigin = typeof start.sourceOffsetOrigin === "string" ? start.sourceOffsetOrigin : undefined;
|
||||
const endOrigin = typeof final.sourceOffsetOrigin === "string" ? final.sourceOffsetOrigin : undefined;
|
||||
if (!startOrigin || !endOrigin) return null;
|
||||
|
||||
const startAssumed = ASSUMED_ORIGINS.has(startOrigin);
|
||||
const endAssumed = ASSUMED_ORIGINS.has(endOrigin);
|
||||
const sameTimeline = (!startAssumed && !endAssumed)
|
||||
|| (startAssumed && endAssumed && toNumber(start.sourceOffsetMinutes) === toNumber(final.sourceOffsetMinutes));
|
||||
if (sameTimeline) return null;
|
||||
|
||||
const endRejected = final.derivedTimestamp === "true" || final.derivedTimestamp === true;
|
||||
if (endRejected) return "rejected-endpoint";
|
||||
return isOnOffsetGrid(durationSeconds) ? "offset-grid" : null;
|
||||
}
|
||||
|
||||
/** The latest start at or before `finalTimestamp` among a policy's starts (timestamp order). */
|
||||
function findPairedStart(starts: ScriptInputEvent[] | undefined, finalTimestamp: string): ScriptInputEvent | undefined {
|
||||
if (!starts || starts.length === 0) return undefined;
|
||||
const finalMs = new Date(finalTimestamp).getTime();
|
||||
let paired: ScriptInputEvent | undefined;
|
||||
for (const start of starts) {
|
||||
if (new Date(start.timestamp).getTime() > finalMs) break;
|
||||
paired = start;
|
||||
}
|
||||
return paired;
|
||||
}
|
||||
|
||||
/**
|
||||
* 2-pass reducer:
|
||||
* 1. Sort events by timestamp; collect every script_completed / script_failed final.
|
||||
@@ -296,6 +375,20 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
|
||||
const finalsByKey = new Map<string, ScriptItem>();
|
||||
const policyIdsWithFinal = new Set<string>();
|
||||
|
||||
// script_started events per (policyId, scriptType) in timestamp order — the start line a
|
||||
// final is paired with when its run duration is judged (see judgeDurationPair).
|
||||
const startsByPolicy = new Map<string, ScriptInputEvent[]>();
|
||||
for (const evt of sorted) {
|
||||
if (evt.eventType !== "script_started") continue;
|
||||
const d = evt.data as ScriptEventData | undefined;
|
||||
const startPolicyId = d?.policyId ?? d?.policy_id;
|
||||
if (!startPolicyId) continue;
|
||||
const policyKey = `${startPolicyId}-${d?.scriptType ?? d?.script_type ?? "platform"}`;
|
||||
const list = startsByPolicy.get(policyKey);
|
||||
if (list) list.push(evt);
|
||||
else startsByPolicy.set(policyKey, [evt]);
|
||||
}
|
||||
|
||||
for (let idx = 0; idx < sorted.length; idx++) {
|
||||
const evt = sorted[idx];
|
||||
if (evt.eventType !== "script_completed" && evt.eventType !== "script_failed") continue;
|
||||
@@ -331,8 +424,13 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
|
||||
const isCycleBasis = typeof rawBasis === "string"
|
||||
? rawBasis === "cycle_including_reporting_latency"
|
||||
: scriptType === "remediation";
|
||||
const durationSeconds = isCycleBasis ? undefined : rawDuration;
|
||||
const reportedAfterSeconds = isCycleBasis ? rawDuration : undefined;
|
||||
// A span across two lines resolved on different timezone assumptions is offset error, not
|
||||
// run time — the agent's verdict when it carries one, else the same rule applied to the
|
||||
// paired start line (session 4377911b: 10 s scripts stored as 3610 s).
|
||||
const pairedStart = policyId ? findPairedStart(startsByPolicy.get(`${policyId}-${scriptType}`), evt.timestamp) : undefined;
|
||||
const suppressedReason = judgeDurationPair(pairedStart?.data as ScriptEventData | undefined, d, rawDuration);
|
||||
const durationSeconds = isCycleBasis || suppressedReason ? undefined : rawDuration;
|
||||
const reportedAfterSeconds = !isCycleBasis || suppressedReason ? undefined : rawDuration;
|
||||
|
||||
const remediationStatus = toNumber(d.remediationStatus ?? d.remediation_status);
|
||||
const targetType = toNumber(d.targetType ?? d.target_type);
|
||||
@@ -372,6 +470,8 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
|
||||
stderr,
|
||||
durationSeconds,
|
||||
reportedAfterSeconds,
|
||||
// The note replaces the run duration only; a withheld cycle value is a detail nobody misses.
|
||||
durationSuppressedReason: suppressedReason && !isCycleBasis ? suppressedReason : undefined,
|
||||
state: isFailureSignal ? "Failed" : "Success",
|
||||
timestamp: evt.timestamp,
|
||||
bootstrapVersion: scriptType === "platform" ? extractBootstrapVersion(stdout) : null,
|
||||
@@ -389,6 +489,8 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] {
|
||||
const loser = winner === candidate ? existing : candidate;
|
||||
winner.durationSeconds ??= loser.durationSeconds;
|
||||
winner.reportedAfterSeconds ??= loser.reportedAfterSeconds;
|
||||
if (winner.durationSeconds != null) winner.durationSuppressedReason = undefined;
|
||||
else winner.durationSuppressedReason ??= loser.durationSuppressedReason;
|
||||
finalsByKey.set(key, winner);
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user