diff --git a/.claude/commands b/.claude/commands index 8c902341..3b805865 160000 --- a/.claude/commands +++ b/.claude/commands @@ -1 +1 @@ -Subproject commit 8c9023415a2a9f1e1cf9e5a9e083bd86f8e97033 +Subproject commit 3b805865ebaee9150047d01747f1347ffb757339 diff --git a/internal b/internal index 5a4b0257..234f4e1b 160000 --- a/internal +++ b/internal @@ -1 +1 @@ -Subproject commit 5a4b0257e1bcff1924c0cf8d0e5f55d6c658b462 +Subproject commit 234f4e1b08ef9c5ba676da9d7368691fc2759539 diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs index 3e453a60..fc6866e3 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/CmTraceOffsetCalibratorTests.cs @@ -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); + } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerResultHoldTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerResultHoldTests.cs index 3d6d52dd..6b82edca 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerResultHoldTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerResultHoldTests.cs @@ -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); + } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs index c9648299..5265fb0c 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerScriptStatePersistenceTests.cs @@ -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); + } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterDurationProvenanceTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterDurationProvenanceTests.cs new file mode 100644 index 00000000..8cbd0704 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterDurationProvenanceTests.cs @@ -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 +{ + /// + /// 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. + /// + 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"]); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterResultHoldTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterResultHoldTests.cs index e7dc6d77..98cb436d 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterResultHoldTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterResultHoldTests.cs @@ -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"]); + } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceLineProvenance.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceLineProvenance.cs new file mode 100644 index 00000000..6af5a79f --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceLineProvenance.cs @@ -0,0 +1,57 @@ +using System; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime +{ + /// + /// How ONE CMTrace line's UTC value was arrived at, captured at the line itself. + /// + /// 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 (persisted as a plain + /// DTO; null on state files written before it existed). + /// + /// + public sealed class CmTraceLineProvenance + { + /// + /// 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). + /// + public DateTime? SourceLocalTs { get; set; } + + /// How the offset applied to was obtained. + public CmTraceOffsetOrigin Origin { get; set; } + + /// The offset that was applied, in minutes (local = UTC + offset). + public int? OffsetMinutes { get; set; } + + /// For : which anchor established the era's offset. + public string EraAnchorKind { get; set; } + + /// What the calibrator measured for the source file — observational, never applied. + public int? MeasuredWriterOffsetMinutes { get; set; } + + /// Name of the log file the line was read from — the closest thing to a writer identity the tracker has. + public string SourceFileName { get; set; } + + /// + /// 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. + /// + public bool IsAssumed() + { + if (!SourceLocalTs.HasValue) return false; + switch (Origin) + { + case CmTraceOffsetOrigin.Bias: + case CmTraceOffsetOrigin.LineAnchored: + return false; + default: + return true; + } + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs index f1a39728..64956cd9 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/CmTraceOffsetCalibrator.cs @@ -159,6 +159,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime return true; } + /// + /// 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 of k × + /// (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. + /// + 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; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs index 61d7656b..351b70b9 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.Handlers.cs @@ -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()); } /// @@ -514,7 +521,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime /// line reopened the slot, produced a fallback duplicate (session e7f3c910). /// emits the held completion. /// - 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 /// Test seam: inject a pending platform script as if AgentExecutor.log had reported /// its start + exit code, without an IME PS-SCRIPT-RESULT line. - 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). /// stands in for the CMTrace timestamp of the PS-SCRIPT-RESULT line (production reads it /// via , the fallback here). - 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()); } /// Test seam: the AgentExecutor exit-code line of a pending platform script (the /// production handler minus regex extraction and positional ownership). - 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); } /// @@ -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 /// surfaces a run duration without driving the /// full regex pipeline. - 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 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" diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs index d81937f1..ce7fe183 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.LogProcessing.cs @@ -505,6 +505,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime "imetokenfailure", }; + /// + /// 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. + /// + 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; diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs index eba451b6..d47fe8c1 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ImeLogTracker.cs @@ -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 _healthScriptStartTimes = - new Dictionary(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 _healthScriptStartTimes = + new Dictionary(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 — diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs index 3a7cd700..3b59cfc7 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime/ScriptExecutionState.cs @@ -29,6 +29,15 @@ public class ScriptExecutionState /// public System.DateTime? StartedAtUtc { get; set; } + /// + /// Provenance of : how the start line's offset was obtained. Paired + /// with / 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. + /// + public CmTraceLineProvenance StartedAtProvenance { get; set; } + /// "detection", "remediation", or "post-detection" (remediation scripts only). public string ScriptPart { get; set; } @@ -66,6 +75,9 @@ public class ScriptExecutionState /// public System.DateTime? ExitObservedAtUtc { get; set; } + /// Provenance of the exit-code line behind (the fallback emit's end). + public CmTraceLineProvenance ExitProvenance { get; set; } + /// /// Source (CMTrace) timestamp of the IME PS-SCRIPT-RESULT line that delivered /// (platform scripts, ime_policy_result only). The emitted event is @@ -76,6 +88,14 @@ public class ScriptExecutionState /// public System.DateTime? ResultObservedAtUtc { get; set; } + /// + /// Provenance of the line that delivered — bound here for the same reason + /// as : 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). + /// + public CmTraceLineProvenance ResultProvenance { get; set; } + /// Pattern id of the line that delivered (surfaced as patternId on the event). public string ResultPatternId { get; set; } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index 1d5a3b28..3509fdd4 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -461,31 +461,35 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters /// no second clock frame, so there is nothing to record. /// /// - private void TagDerivedTimestamp(IDictionary data, bool derivedFromClock, DateTime? rawSourceTs) + private void TagDerivedTimestamp(IDictionary 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 } + + /// + /// Whether the span between a start line and an end line measures elapsed time. + /// + /// 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. + /// + /// + 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; } /// @@ -1387,19 +1464,19 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters /// late start / pre-failed ESP. Advisory only: no state mutation, the underlying /// script_failed is still emitted separately. Health (remediation) scripts are /// excluded — they re-run on their own cadence and have a different timeout regime. - /// is the timeline-consistent completion for duration - /// math (raw source ts on rejected-timestamp emissions); - /// stamps the emitted event. + /// 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); stamps the emitted event. /// - 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) diff --git a/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx b/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx index 4a170a9b..614f608a 100644 --- a/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx +++ b/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx @@ -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} )} + {!durationLabel && !nested && item.state !== "Running" && item.durationSuppressedReason && ( + n/a + )} {item.state !== "Running" && (