From 0ec481b479468e90a98f9f607db1baa36f7ac047 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Tue, 28 Jul 2026 12:53:17 +0200 Subject: [PATCH] feat(agent): outcome-calibrated agent_late_start severity and phrasing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fleet data (2026-07-28, agent 2.0.1380) showed the late-start detector was outcome-blind: tenant 659c3a90 collected 12 Warnings with the post-mortem/ hung-script note on enrollments that succeeded — the bootstrap merely ran late in the ESP queue and the agent observed the healthy final minutes live. New pure helper ObservationCoverage.DescribeLateStart: - Succeeded -> Info with a tail-only-coverage note (IME-replay hint, bootstrap-ordering review if recurring); no alarm framing. - Failed/TimedOut -> Warning with the existing post-mortem/hung-script note. - oobeStateAtAgentStart refines the message only: "completed" = pure post-mortem, "in_progress" = live tail observed; not_started/unavailable add no claim (value flips to not_started after mid-OOBE reboots and "completed" is routine on post-desktop restarts). The coverage gate (10 min boot-to-start / 5 min uptime) is unchanged, and the OOBE state is deliberately NOT a gate: the canonical hung-script failure (f148976f) terminates on the still-shown ESP screen, i.e. with OOBE reading in_progress. 8 new tests (outcome x oobe-state matrix); V2.Core suite 2067 green. Co-Authored-By: Claude Fable 5 --- .../Termination/ObservationCoverageTests.cs | 79 +++++++++++++++++++ .../EnrollmentTerminationHandler.cs | 22 ++++-- .../Termination/ObservationCoverage.cs | 54 +++++++++++++ 3 files changed, 147 insertions(+), 8 deletions(-) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/ObservationCoverageTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/ObservationCoverageTests.cs index bed076c5..25369600 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/ObservationCoverageTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Termination/ObservationCoverageTests.cs @@ -1,5 +1,7 @@ using System; +using AutopilotMonitor.Agent.V2.Core.Orchestration; using AutopilotMonitor.Agent.V2.Core.Termination; +using AutopilotMonitor.Shared.Models; using Xunit; namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination @@ -70,5 +72,82 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Termination Assert.Equal(0, bootToStart, 0); Assert.Equal(10, uptime, 0); } + + // --- DescribeLateStart: outcome-calibrated severity + phrasing (fleet 2026-07-28) --- + + private static void Describe( + EnrollmentTerminationOutcome outcome, string oobeState, + out EventSeverity severity, out string message, out string note) + => ObservationCoverage.DescribeLateStart( + outcome, oobeState, bootToStartSeconds: 34 * 60, uptimeSeconds: 30, + out severity, out message, out note); + + [Fact] + public void Failed_outcome_is_a_warning_with_the_hung_script_post_mortem_note() + { + Describe(EnrollmentTerminationOutcome.Failed, "in_progress", + out var severity, out var message, out var note); + + Assert.Equal(EventSeverity.Warning, severity); + Assert.Contains("low coverage of the enrollment window", message); + Assert.Contains("post-mortem", note); + Assert.Contains("hung ahead of the bootstrap", note); + } + + [Fact] + public void TimedOut_outcome_is_a_warning_like_a_failure() + { + Describe(EnrollmentTerminationOutcome.TimedOut, "in_progress", + out var severity, out _, out var note); + + Assert.Equal(EventSeverity.Warning, severity); + Assert.Contains("post-mortem", note); + } + + [Fact] + public void Succeeded_outcome_is_an_info_about_tail_only_coverage_without_alarm_framing() + { + // The 659c3a90 shape: healthy enrollment, bootstrap merely ran late in the ESP queue. + Describe(EnrollmentTerminationOutcome.Succeeded, "in_progress", + out var severity, out _, out var note); + + Assert.Equal(EventSeverity.Info, severity); + Assert.Contains("succeeded", note); + Assert.Contains("IME log replay", note); + Assert.DoesNotContain("post-mortem", note); + Assert.DoesNotContain("hung", note); + } + + [Fact] + public void Oobe_completed_at_start_phrases_a_pure_post_mortem() + { + Describe(EnrollmentTerminationOutcome.Failed, "completed", + out _, out var message, out _); + + Assert.Contains("OOBE was already completed when the agent started", message); + } + + [Fact] + public void Oobe_in_progress_at_start_phrases_the_live_tail() + { + Describe(EnrollmentTerminationOutcome.Failed, "in_progress", + out _, out var message, out _); + + Assert.Contains("OOBE was still in progress at agent start", message); + Assert.Contains("final 30s live", message); + } + + [Theory] + [InlineData("not_started")] // flips in after a mid-OOBE reboot — not interpretable + [InlineData("unavailable")] // WinRT contract absent / read failed + [InlineData("unknown_3")] // unexpected enum value + public void Uninterpretable_oobe_states_add_no_claim_to_the_message(string oobeState) + { + Describe(EnrollmentTerminationOutcome.Failed, oobeState, + out _, out var message, out _); + + Assert.DoesNotContain("OOBE", message); + Assert.EndsWith("low coverage of the enrollment window.", message); + } } } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs index cb504e02..d9911c8a 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/EnrollmentTerminationHandler.cs @@ -623,12 +623,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination } /// - /// Emits a one-shot agent_late_start Warning when the agent had low observation + /// Emits a one-shot agent_late_start event when the agent had low observation /// coverage: it started a long time after device boot AND lived only briefly before this /// terminal outcome (gate in ). Such a session looks like a /// normal multi-minute failure in the list (StartedAt is back-dated to the earliest replayed - /// IME-log event) but the agent actually observed only the end-state — so the operator should - /// read the diagnosis as a post-mortem reconstruction, not live evidence. No state mutation. + /// IME-log event) but the agent actually observed only the end-state. Severity and phrasing + /// are outcome-calibrated via : a failure + /// stays a Warning with the post-mortem/hung-script note, a success is an Info about + /// tail-only coverage (fleet 2026-07-28: tenant 659c3a90 collected 12 Warnings on healthy + /// enrollments whose bootstrap merely ran late). No state mutation. /// private void MaybeEmitAgentLateStart(EnrollmentTerminatedEventArgs args) { @@ -642,21 +645,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination out var bootToStartSeconds, out var uptimeSeconds)) return; + ObservationCoverage.DescribeLateStart( + args.Outcome, _oobeStateAtAgentStart, bootToStartSeconds, uptimeSeconds, + out var severity, out var message, out var note); + _logger.Info( $"EnrollmentTerminationHandler: low observation coverage — agent started " + $"{bootToStartSeconds / 60.0:F1} min after boot and lived {uptimeSeconds:F0}s; " + - $"emitting agent_late_start."); + $"emitting agent_late_start ({severity}, outcome {args.Outcome})."); _post.Emit(new EnrollmentEvent { SessionId = _configuration.SessionId, TenantId = _configuration.TenantId, EventType = Constants.EventTypes.AgentLateStart, - Severity = EventSeverity.Warning, + Severity = severity, Source = "EnrollmentTerminationHandler", Phase = EnrollmentPhase.Unknown, - Message = $"Agent started {bootToStartSeconds / 60.0:F0} min after boot and observed only " + - $"{uptimeSeconds:F0}s before terminating ({args.Outcome}) — low coverage of the enrollment window.", + Message = message, Data = new Dictionary { { "bootToAgentStartSeconds", Math.Round(bootToStartSeconds, 1) }, @@ -665,7 +671,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination { "agentStartUtc", _agentStartTimeUtc.ToString("o") }, { "oobeStateAtAgentStart", _oobeStateAtAgentStart }, { "outcome", args.Outcome.ToString() }, - { "note", "The agent's bootstrap (an Intune platform script) ran only near the end of the enrollment, so the agent observed the already-decided end-state rather than the failure window. Treat the diagnosis as a post-mortem; check for a platform/remediation script that hung ahead of the bootstrap (see script_timeout_suspected)." }, + { "note", note }, }, ImmediateUpload = true, }); diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/ObservationCoverage.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/ObservationCoverage.cs index d716e1a1..214dd2e2 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/ObservationCoverage.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Termination/ObservationCoverage.cs @@ -1,6 +1,8 @@ #nullable enable using System; using System.Runtime.InteropServices; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Shared.Models; namespace AutopilotMonitor.Agent.V2.Core.Termination { @@ -76,5 +78,57 @@ namespace AutopilotMonitor.Agent.V2.Core.Termination uptimeSeconds = Math.Max(0, uptime.TotalSeconds); return bootToStart >= LateStartBootThreshold && uptime <= LowCoverageUptime; } + + /// + /// Severity + operator-facing phrasing for the agent_late_start event, calibrated + /// by fleet data (2026-07-28): the gate alone is outcome-blind and attached a + /// "post-mortem / check for a hung script" Warning to sessions that in fact succeeded — + /// there the late bootstrap is deployment hygiene, not an alarm. The OOBE state refines + /// the phrasing but must never gate: the canonical hung-script failure terminates on the + /// still-shown ESP screen, i.e. with OOBE reading in_progress. + /// + /// Terminal outcome the enrollment reached. + /// + /// sample taken at THIS process's start. Only completed / in_progress are + /// interpreted; not_started flips in after mid-OOBE reboots and completed is + /// routine for post-desktop restarts, so no claim is phrased from the other values. + /// From . + /// From . + internal static void DescribeLateStart( + EnrollmentTerminationOutcome outcome, + string oobeStateAtAgentStart, + double bootToStartSeconds, + double uptimeSeconds, + out EventSeverity severity, + out string message, + out string note) + { + var succeeded = outcome == EnrollmentTerminationOutcome.Succeeded; + severity = succeeded ? EventSeverity.Info : EventSeverity.Warning; + + message = $"Agent started {bootToStartSeconds / 60.0:F0} min after boot and observed only " + + $"{uptimeSeconds:F0}s before terminating ({outcome}) — low coverage of the enrollment window."; + switch (oobeStateAtAgentStart) + { + case "completed": + message += " OOBE was already completed when the agent started — the diagnosis is a " + + "post-mortem reconstruction, not live observation."; + break; + case "in_progress": + message += $" OOBE was still in progress at agent start — the agent did observe the " + + $"final {uptimeSeconds:F0}s live."; + break; + } + + note = succeeded + ? "The agent's bootstrap (an Intune platform script) ran late in the enrollment, so only the " + + "final stretch was observed live; earlier timeline entries are reconstructed from IME log " + + "replay. The enrollment itself succeeded. If this recurs across sessions, review which " + + "platform/remediation scripts run ahead of the bootstrap (see script_timeout_suspected)." + : "The agent's bootstrap (an Intune platform script) ran only near the end of the enrollment, " + + "so the agent observed the already-decided end-state rather than the failure window. Treat " + + "the diagnosis as a post-mortem; check for a platform/remediation script that hung ahead of " + + "the bootstrap (see script_timeout_suspected)."; + } } }