diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptStartedTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptStartedTests.cs new file mode 100644 index 00000000..0e711a8e --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/Ime/ImeLogTrackerPlatformScriptStartedTests.cs @@ -0,0 +1,110 @@ +using System; +using System.Collections.Generic; +using System.IO; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Shared.Models; +using Newtonsoft.Json; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime +{ + /// + /// Platform scripts emit the same live OnScriptStarted signal health scripts always + /// had, so the UI shows a running indicator for them too. The start line fires twice per + /// execution (agentexecutor + ime source), so the signal is gated on pending-slot creation — + /// exactly once per execution, re-armed after the execution completes. + /// + public sealed class ImeLogTrackerPlatformScriptStartedTests + { + private static readonly string[] RequiredPatternIds = + { + "PS-AGENT-INVOCATION", "PS-AGENT-SCRIPT-START", "PS-SCRIPT-RESULT", + }; + + // Same shipped-pattern loading approach as ImeLogTrackerPlatformScriptContaminationTests: + // guard the real regex contract rather than a stale inline copy. + private static List ScriptPatterns() + { + var dir = FindRulesPatternDir(); + var byId = new Dictionary(StringComparer.OrdinalIgnoreCase); + foreach (var file in Directory.GetFiles(dir, "*.json")) + { + var pattern = JsonConvert.DeserializeObject(File.ReadAllText(file)); + if (pattern?.PatternId != null) + byId[pattern.PatternId] = pattern; + } + + var result = new List(); + foreach (var id in RequiredPatternIds) + { + Assert.True(byId.TryGetValue(id, out var p), + $"Shipped IME pattern '{id}' not found under {dir}."); + result.Add(p!); + } + return result; + } + + private static string FindRulesPatternDir() + { + var dir = new DirectoryInfo(AppContext.BaseDirectory); + while (dir != null) + { + var candidate = Path.Combine(dir.FullName, "rules", "ime-log-patterns"); + if (Directory.Exists(candidate)) return candidate; + dir = dir.Parent; + } + throw new DirectoryNotFoundException( + $"Could not locate rules/ime-log-patterns walking up from {AppContext.BaseDirectory}"); + } + + private const string PlatformId = "c3e0124c-4936-4bfd-afcc-c7fe1d84d104"; + + private const string PlatformStartLine = + @"Adding argument powershell with value C:\Program Files (x86)\Microsoft Intune Management Extension\Policies\Scripts\00000000-0000-0000-0000-000000000000_c3e0124c-4936-4bfd-afcc-c7fe1d84d104.ps1 to the named argument list."; + + private const string PlatformResultLine = + "[PowerShell] User Id = 00000000-0000-0000-0000-000000000000, " + + "Policy id = " + PlatformId + ", policy result = Success"; + + [Fact] + public void Platform_start_emits_OnScriptStarted_once_per_execution() + { + using var tmp = new TempDirectory(); + var started = new List(); + var tracker = new ImeLogTracker(tmp.Path, ScriptPatterns(), new AgentLogger(tmp.Path, AgentLogLevel.Info)); + tracker.OnScriptStarted = info => started.Add(info); + + tracker.ProcessLogMessageForTest("ExecutorLog AgentExecutor gets invoked"); + tracker.ProcessLogMessageForTest(PlatformStartLine); + // Duplicate start line for the same execution (the line fires from both the + // agentexecutor and the ime source) — must NOT emit a second started signal. + tracker.ProcessLogMessageForTest(PlatformStartLine); + + var info = Assert.Single(started); + Assert.Equal(PlatformId, info.PolicyId); + Assert.Equal("platform", info.ScriptType); + } + + [Fact] + public void Platform_rerun_after_completion_emits_OnScriptStarted_again() + { + using var tmp = new TempDirectory(); + var started = new List(); + var tracker = new ImeLogTracker(tmp.Path, ScriptPatterns(), new AgentLogger(tmp.Path, AgentLogLevel.Info)); + tracker.OnScriptStarted = info => started.Add(info); + + // Run 1: start → authoritative result (removes the pending slot). + tracker.ProcessLogMessageForTest("ExecutorLog AgentExecutor gets invoked"); + tracker.ProcessLogMessageForTest(PlatformStartLine); + tracker.ProcessLogMessageForTest(PlatformResultLine); + + // Run 2 (IME re-evaluation of the same policy) begins a new execution. + tracker.ProcessLogMessageForTest("ExecutorLog AgentExecutor gets invoked"); + tracker.ProcessLogMessageForTest(PlatformStartLine); + + Assert.Equal(2, started.Count); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs index 1828272c..3ed504f4 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/SignalAdapters/ImeLogTrackerAdapterTimingTests.cs @@ -164,6 +164,52 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted)); Assert.Equal("65.00", info.Payload!["durationSeconds"]); + // HS-NEW-RESULT is written only after IME's batched report to the service, so this + // value overstates the script run time — the basis names that so consumers (Web + // "Reported after", MCP) never display it as the run time. + Assert.Equal("cycle_including_reporting_latency", info.Payload["durationBasis"]); + } + + [Fact] + public void HealthScriptDetection_early_signal_emits_runtime_duration_and_keeps_cycle_start() + { + using var f = new ImeLogTrackerAdapterFixture(T0); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + // Detection script started 20s ago; the HS-COMPLIANCE line is logged right after the + // script exits, so the early-signal completion carries the ACTUAL run time. + f.Tracker.SeedHealthScriptStartForTesting( + "75d14a95-d49f-473d-9d65-d4b006bc7468", T0.AddSeconds(-20)); + f.Tracker.HandleHealthScriptDetectionResultForTest( + "75d14a95-d49f-473d-9d65-d4b006bc7468", "True", "pre"); + + var early = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted)); + Assert.Equal("20.00", early.Payload!["durationSeconds"]); + Assert.Equal("script_runtime", early.Payload["durationBasis"]); + + // The early signal must only PEEK the cycle start — the consolidated HS-NEW-RESULT + // arriving 45s later still times the whole cycle from the same start (65s total). + f.Clock.Advance(TimeSpan.FromSeconds(45)); + f.Tracker.HandleHealthScriptResultJson(DetectOnlyResultJson); + + var all = f.InfoEvents(SharedEventTypes.ScriptCompleted); + Assert.Equal(2, all.Count); + Assert.Equal("65.00", all[1].Payload!["durationSeconds"]); + Assert.Equal("cycle_including_reporting_latency", all[1].Payload["durationBasis"]); + } + + [Fact] + public void HealthScriptDetection_early_signal_without_observed_start_omits_duration() + { + using var f = new ImeLogTrackerAdapterFixture(T0); + using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock); + + f.Tracker.HandleHealthScriptDetectionResultForTest( + "75d14a95-d49f-473d-9d65-d4b006bc7468", "True", "pre"); + + var info = Assert.Single(f.InfoEvents(SharedEventTypes.ScriptCompleted)); + Assert.False(info.Payload!.ContainsKey("durationSeconds")); + Assert.False(info.Payload.ContainsKey("durationBasis")); } [Fact] 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 5c601c79..7e1e24eb 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 @@ -227,6 +227,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime // source) but the earliest wins. StartedAtUtc = LastMatchedLogTimestamp ?? DateTime.UtcNow, }; + // Live "running" indicator — same signal health scripts emit. Gated on slot + // creation so the duplicate start line (agentexecutor + ime source) doesn't + // double-emit for the same execution. + try { OnScriptStarted?.Invoke(new ScriptStartedInfo { PolicyId = id, ScriptType = "platform" }); } + catch (Exception ex) { _logger.Warning($"ImeLogTracker: OnScriptStarted handler threw: {ex.Message}"); } } _lastPlatformScriptPolicyId = id; // Started lines fire twice per script (agentexecutor + ime source) and carry no @@ -624,6 +629,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime RunContext = runContext, Stdout = stdout, Stderr = stderr, + // The compliance line is logged right after the (pre/post) detection script + // exits, so cycle-start → this line is the actual execution time — unlike the + // 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 + : (DateTime?)null, + DurationBasis = "script_runtime", }; _logger.Info($"ImeLogTracker: health-script {scriptPart} early-signal for {id}: " + @@ -866,7 +879,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime ErrorDetails = errorDetails, // 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 + StartedAtUtc = startedAtUtc, + // 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" }; private static string TryGetString(JsonElement parent, string name) 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 0f9aa459..d785d334 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 @@ -88,13 +88,26 @@ public class ScriptExecutionState /// Top-level Info.ErrorDetails string from the [HS] new result JSON. public string ErrorDetails { get; set; } + + /// + /// Semantics of the duration derived from → completion, surfaced + /// as durationBasis next to durationSeconds on the emitted event: + /// "script_runtime" — completion stamp is the script's own end signal (platform + /// PS-SCRIPT-RESULT / AgentExecutor exit, or the health-script HS-COMPLIANCE line logged + /// right after the detection script exits); "cycle_including_reporting_latency" — + /// completion stamp is the HS-NEW-RESULT line, which IME only writes after its batched + /// report to the Microsoft service (30 s – minutes after the scripts actually finished), + /// so the value systematically overstates the run time. Set by the emitting handler; when + /// null the adapter falls back to the scriptType-based default (remediation → cycle). + /// + public string DurationBasis { get; set; } } /// -/// Lightweight live-progress signal emitted when IME logs the start of a script -/// (currently only health scripts via the HS-SCRIPT-START pattern). -/// Gives the UI a "running" indicator before the consolidated final result arrives -/// (which may be 30 s – 3 min later). +/// Lightweight live-progress signal emitted when IME logs the start of a script — +/// health scripts via the HS-SCRIPT-START pattern, platform scripts on +/// pending-slot creation from their start line. Gives the UI a "running" indicator +/// before the final result arrives (health scripts: 30 s – 3 min later). /// public class ScriptStartedInfo { diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs index a2c36fab..7a1abdb1 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/SignalAdapters/ImeLogTrackerAdapter.cs @@ -849,19 +849,22 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters // against clock skew between the (possibly clock-derived) completion stamp and start. // // L19 (delta review 2026-07-02): the same field name carries two different semantics — - // platform scripts measure start→result (≈ script runtime), remediation scripts measure - // HS-SCRIPT-START→HS-NEW-RESULT (the whole cycle INCLUDING IME's 30 s–3 min batched - // reporting latency, i.e. systematically longer than the script ran). `durationBasis` - // names which one applies so downstream consumers never compare the two as equals. + // start→own-end-signal (≈ script runtime) vs HS-SCRIPT-START→HS-NEW-RESULT (the whole + // cycle INCLUDING IME's 30 s–3 min batched reporting latency, i.e. systematically + // longer than the script ran). `durationBasis` names which one applies so downstream + // consumers never compare the two as equals. The emitting handler stamps the basis on + // the state (health-script early-signal completions are script_runtime too); the + // scriptType fallback covers states from paths that predate the field. if (script.StartedAtUtc.HasValue) { var durationSeconds = (now - script.StartedAtUtc.Value).TotalSeconds; if (durationSeconds >= 0) { data["durationSeconds"] = durationSeconds.ToString("F2", culture); - data["durationBasis"] = IsRemediation(script.ScriptType) - ? "cycle_including_reporting_latency" - : "script_runtime"; + data["durationBasis"] = script.DurationBasis + ?? (IsRemediation(script.ScriptType) + ? "cycle_including_reporting_latency" + : "script_runtime"); } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt index 5e9ad0bf..a848267e 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt @@ -1 +1 @@ -1279 +1281 diff --git a/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx b/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx index deae8658..c5dc5afb 100644 --- a/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx +++ b/src/Web/autopilot-monitor-web/components/ScriptExecutions.tsx @@ -191,8 +191,10 @@ function ScriptCardView({ card, showScriptOutput, latestBootstrapVersion, displa const remediationStatusLabel = mapRemediationStatus(remediationStatus); const cardDisplayName = lookupScriptDisplayName(displayNamesByRefKey, card.scriptType, card.policyId); - // Whole-cycle run duration (HS-SCRIPT-START → HS-NEW-RESULT). Shown once on the header so the - // user sees how long the remediation ran without the same number repeated on every phase row. + // Actual cycle run time (max of the phases' cumulative script_runtime durations). Shown once + // on the header so the user sees how long the remediation ran without the same number repeated + // on every phase row. The reporting-latency-inflated cycle value lives in the phase details + // ("Reported after"), never here. const cardDurationLabel = formatScriptDuration(card.durationSeconds); const isCardSlow = card.durationSeconds != null && card.durationSeconds >= STALE_RUNNING_THRESHOLD_SECONDS; @@ -335,12 +337,16 @@ function ScriptItemRow({ item, showScriptOutput, latestBootstrapVersion, nested, statusText = item.result ?? (item.state === "Success" ? "Success" : "Failed"); } - // Run duration (from the agent's start→completion timing). Surfaced for every completed - // script so slow / inefficient scripts stand out; styled amber past the stale threshold - // (10 min) since at that range a script is a plausible enrollment-pipeline blocker. Suppressed - // on nested phase rows: a remediation cycle's phases all carry the same whole-cycle duration, - // which is shown once on the parent card header instead of repeated on each phase. + // Actual run time (from the agent's start → own-end-signal timing). Surfaced for every + // completed script so slow / inefficient scripts stand out; styled amber past the stale + // threshold (10 min) since at that range a script is a plausible enrollment-pipeline blocker. + // Suppressed on nested phase rows' compact line — the parent card header already shows the + // cycle run time — but still listed in each phase's details panel alongside "Reported after" + // (the cycle value inflated by IME's batched reporting latency, kept out of the compact row + // so it is never mistaken for the run time). const durationLabel = item.state !== "Running" && !nested ? formatScriptDuration(item.durationSeconds) : null; + const detailDurationLabel = item.state !== "Running" ? formatScriptDuration(item.durationSeconds) : null; + const reportedAfterLabel = item.state !== "Running" ? formatScriptDuration(item.reportedAfterSeconds) : null; const isSlowDuration = item.durationSeconds != null && item.durationSeconds >= STALE_RUNNING_THRESHOLD_SECONDS; const hasStdout = item.state !== "Running" && showScriptOutput !== false && item.stdout && item.stdout.trim().length > 0; @@ -473,7 +479,12 @@ function ScriptItemRow({ item, showScriptOutput, latestBootstrapVersion, nested, {!nested && item.runContext && Context: {item.runContext}} {!nested && item.targetType != null && Target: {item.targetType === 2 ? "Device" : "User"}} {item.exitCode != null && Exit Code: {item.exitCode}} - {durationLabel && Duration: {durationLabel}} + {detailDurationLabel && Duration: {detailDurationLabel}} + {reportedAfterLabel && ( + + Reported after: {reportedAfterLabel} + + )} {item.result && Result: {item.result}} {item.complianceResult && Compliance: {item.complianceResult === "True" ? "Compliant" : "Non-compliant"}} {!nested && remediationStatusLabel && Status: {remediationStatusLabel}} diff --git a/src/Web/autopilot-monitor-web/lib/__tests__/scriptExecutions.test.ts b/src/Web/autopilot-monitor-web/lib/__tests__/scriptExecutions.test.ts index e52cd9d4..04fb7521 100644 --- a/src/Web/autopilot-monitor-web/lib/__tests__/scriptExecutions.test.ts +++ b/src/Web/autopilot-monitor-web/lib/__tests__/scriptExecutions.test.ts @@ -798,4 +798,110 @@ describe("reduceScriptEvents — durationSeconds", () => { ]); expect(item.durationSeconds).toBeUndefined(); }); + + // ── durationBasis normalization: run time vs "reported after" (cycle incl. IME latency) ── + it("platform durations stay run time (no reportedAfter) — legacy events without a basis field", () => { + const [item] = reduceScriptEvents([ + finalEvent({ data: { policyId: "p1", scriptType: "platform", result: "Success", durationSeconds: "42.00" } }), + ]); + expect(item.durationSeconds).toBe(42); + expect(item.reportedAfterSeconds).toBeUndefined(); + }); + + it("legacy remediation duration (no basis field) is treated as reportedAfter, NOT run time", () => { + // Pre-basis agents measured remediation durations to the HS-NEW-RESULT line, which IME + // only writes after its batched service report — displaying that as run time was the + // user-reported "script ran seconds, list says 8m" bug. Old data must never regress. + const [item] = reduceScriptEvents([ + finalEvent({ + data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", + exitCode: "1", complianceResult: "False", durationSeconds: "480.00" }, + }), + ]); + expect(item.durationSeconds).toBeUndefined(); + expect(item.reportedAfterSeconds).toBe(480); + }); + + it("remediation duration with basis script_runtime (early-signal emission) is real run time", () => { + const [item] = reduceScriptEvents([ + finalEvent({ + data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", + exitCode: "0", complianceResult: "True", + durationSeconds: "20.00", durationBasis: "script_runtime" }, + }), + ]); + expect(item.durationSeconds).toBe(20); + expect(item.reportedAfterSeconds).toBeUndefined(); + }); + + it("explicit cycle basis routes the value to reportedAfterSeconds (snake_case too)", () => { + const [item] = reduceScriptEvents([ + finalEvent({ + data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", + exit_code: "0", compliance_result: "True", + duration_seconds: "95.00", duration_basis: "cycle_including_reporting_latency" }, + }), + ]); + expect(item.durationSeconds).toBeUndefined(); + expect(item.reportedAfterSeconds).toBe(95); + }); + + it("dedupe merges the early-signal run time with the late HS-NEW-RESULT reportedAfter", () => { + // The two-stage remediation emission: early HS-COMPLIANCE carries the run time, the + // later (more complete) HS-NEW-RESULT carries the cycle value. The completeness winner + // must keep BOTH timings — dropping the run time was the "counter said 20s, list says + // 8m" mismatch. + const [item] = reduceScriptEvents([ + finalEvent({ + eventType: "script_completed", ts: 0, + data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", + exitCode: "0", complianceResult: "True", + durationSeconds: "20.00", durationBasis: "script_runtime" }, + }), + finalEvent({ + eventType: "script_completed", ts: 74, + data: { policyId: "p1", scriptType: "remediation", scriptPart: "detection", + exitCode: "0", complianceResult: "True", + stdout: "LocalAdminIsEnabled=False", + remediationStatus: "4", targetType: "2", runContext: "System", + durationSeconds: "94.00", durationBasis: "cycle_including_reporting_latency" }, + }), + ]); + // Late event wins on completeness (stdout, remediationStatus, runContext)… + expect(item.stdout).toBe("LocalAdminIsEnabled=False"); + expect(item.remediationStatus).toBe(4); + // …but the early run time survives the merge alongside the cycle value. + expect(item.durationSeconds).toBe(20); + expect(item.reportedAfterSeconds).toBe(94); + }); +}); + +describe("groupScriptItems — card durationSeconds is the max phase run time", () => { + const item = (overrides: Partial): ScriptItem => ({ + policyId: "p1", + scriptType: "remediation", + state: "Success", + timestamp: ts(0), + ...overrides, + }); + + it("multi-phase cycle takes the max (phase runtimes are cumulative from the cycle start)", () => { + const cards = groupScriptItems([ + item({ scriptPart: "detection", complianceResult: "False", exitCode: 1, remediationStatus: 2, durationSeconds: 8, timestamp: ts(0) }), + item({ scriptPart: "remediation", exitCode: 0, remediationStatus: 2, reportedAfterSeconds: 300, timestamp: ts(1) }), + item({ scriptPart: "post-detection", complianceResult: "True", exitCode: 0, remediationStatus: 2, durationSeconds: 25, timestamp: ts(2) }), + ]); + expect(cards[0].isCycle).toBe(true); + expect(cards[0].durationSeconds).toBe(25); + }); + + it("phases with only reportedAfterSeconds contribute nothing to the card run time", () => { + // Legacy cycle: every phase carried only the reporting-latency-inflated value → the + // header shows no run time at all (the details panels still show "Reported after"). + const cards = groupScriptItems([ + item({ scriptPart: "detection", complianceResult: "False", exitCode: 1, remediationStatus: 3, reportedAfterSeconds: 480, timestamp: ts(0) }), + item({ scriptPart: "post-detection", complianceResult: "False", exitCode: 1, remediationStatus: 3, reportedAfterSeconds: 480, timestamp: ts(2) }), + ]); + expect(cards[0].durationSeconds).toBeUndefined(); + }); }); diff --git a/src/Web/autopilot-monitor-web/lib/scriptExecutions.ts b/src/Web/autopilot-monitor-web/lib/scriptExecutions.ts index 4a2f739b..531c6cd9 100644 --- a/src/Web/autopilot-monitor-web/lib/scriptExecutions.ts +++ b/src/Web/autopilot-monitor-web/lib/scriptExecutions.ts @@ -27,12 +27,22 @@ export interface ScriptItem { stdout?: string; stderr?: string; /** - * Observed run duration in seconds (start line → completion), surfaced by the agent on - * every platform-script completion. Lets the UI flag slow / inefficient scripts. Absent - * when the agent never saw the script's start line (e.g. a completion observed on replay - * without a matching start). + * Actual script run time in seconds (start line → the script's own end signal). Only + * populated from events whose durationBasis is "script_runtime" — platform scripts and + * health-script early-signal (HS-COMPLIANCE) completions. Absent when the agent never + * saw the start line, or when only the cycle-basis value is known (see + * reportedAfterSeconds). */ durationSeconds?: number; + /** + * Whole-cycle duration in seconds measured to the HS-NEW-RESULT line, which IME only + * writes after its batched report to the Microsoft service — systematically longer than + * the scripts actually ran (30 s – minutes of reporting latency). Populated from events + * with durationBasis "cycle_including_reporting_latency" (and from legacy remediation + * events that predate the basis field, which measured the same span). Shown as + * "Reported after Xm" in the details panel, never as the run duration. + */ + reportedAfterSeconds?: number; state: "Running" | "Success" | "Failed"; timestamp: string; bootstrapVersion?: string | null; @@ -91,10 +101,11 @@ export interface ScriptCard { /** First-phase timestamp; used for sorting cards chronologically in the UI. */ timestamp: string; /** - * Cycle-level run duration in seconds. For platform / single-phase cards this is the lone - * phase's duration; for multi-phase remediation cycles every phase event carries the same - * whole-cycle duration (HS-SCRIPT-START → HS-NEW-RESULT), so we lift it once onto the card - * header rather than repeating it on each nested phase row. Absent when no phase reported one. + * Card-level actual run time in seconds. Phases carry cumulative script_runtime durations + * measured from the same cycle start (detection ≤ post-detection), so the max across + * phases is the execution time through the latest observed phase. Shown once on the card + * header rather than repeated on each nested phase row. Absent when no phase reported a + * runtime-basis duration (e.g. legacy events that only carried the cycle-basis value). */ durationSeconds?: number; } @@ -123,6 +134,7 @@ function dataCompleteness(item: ScriptItem): number { if (item.stderr && item.stderr.length > 0) score += 1; if (item.runContext) score += 1; if (item.durationSeconds != null) score += 1; + if (item.reportedAfterSeconds != null) score += 1; return score; } @@ -239,7 +251,24 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] { if (policyId) policyIdsWithFinal.add(`${policyId}-${scriptType}`); const exitCode = toNumber(d.exitCode ?? d.exit_code); - const durationSeconds = toNumber(d.durationSeconds ?? d.duration_seconds); + + // Duration normalization — the wire field durationSeconds carries two different + // semantics, named by durationBasis (see the ScriptItem field docs): + // "script_runtime" → actual run time → durationSeconds + // "cycle_including_reporting_latency" → HS-NEW-RESULT stamp incl. IME's batched + // reporting delay → reportedAfterSeconds + // Legacy events predate the basis field: platform durations were always measured to + // the script's own result line (runtime), remediation durations to HS-NEW-RESULT + // (cycle) — infer accordingly so old data is never displayed as run time when it + // isn't one. + const rawDuration = toNumber(d.durationSeconds ?? d.duration_seconds); + const rawBasis = d.durationBasis ?? d.duration_basis; + const isCycleBasis = typeof rawBasis === "string" + ? rawBasis === "cycle_including_reporting_latency" + : scriptType === "remediation"; + const durationSeconds = isCycleBasis ? undefined : rawDuration; + const reportedAfterSeconds = isCycleBasis ? rawDuration : undefined; + const remediationStatus = toNumber(d.remediationStatus ?? d.remediation_status); const targetType = toNumber(d.targetType ?? d.target_type); const errorCode = toNumber(d.errorCode ?? d.error_code); @@ -277,14 +306,24 @@ export function reduceScriptEvents(events: ScriptInputEvent[]): ScriptItem[] { stdout, stderr, durationSeconds, + reportedAfterSeconds, state: isFailureSignal ? "Failed" : "Success", timestamp: evt.timestamp, bootstrapVersion: scriptType === "platform" ? extractBootstrapVersion(stdout) : null, }; + // Keep the most-complete entry, but merge the duration fields across both: the + // early-signal emission carries the runtime, the later HS-NEW-RESULT emission the + // cycle value — whichever entry wins on completeness must not drop the other's timing. const existing = finalsByKey.get(key); - if (!existing || dataCompleteness(candidate) > dataCompleteness(existing)) { + if (!existing) { finalsByKey.set(key, candidate); + } else { + const winner = dataCompleteness(candidate) > dataCompleteness(existing) ? candidate : existing; + const loser = winner === candidate ? existing : candidate; + winner.durationSeconds ??= loser.durationSeconds; + winner.reportedAfterSeconds ??= loser.reportedAfterSeconds; + finalsByKey.set(key, winner); } } @@ -488,10 +527,14 @@ export function groupScriptItems(items: ScriptItem[]): ScriptCard[] { : (first.result ?? (first.state === "Failed" ? "Failed" : "Success")); } - // Cycle-level duration: phases of a remediation cycle all carry the same whole-cycle - // duration, so the first defined value is representative. Platform / single-phase cards - // inherit their lone phase's duration (rendered on the row itself, not the header). - const cardDuration = phases.map(p => p.durationSeconds).find(d => d != null); + // Card-level run time: phase runtimes are cumulative from the same cycle start + // (detection ≤ post-detection), so the max is the execution time through the latest + // observed phase. Platform / single-phase cards inherit their lone phase's duration + // (rendered on the row itself, not the header). + const phaseDurations = phases + .map(p => p.durationSeconds) + .filter((d): d is number => d != null); + const cardDuration = phaseDurations.length > 0 ? Math.max(...phaseDurations) : undefined; cards.push({ policyId: first.policyId,