fix(agent): defer ImeUserSessionCompleted while required user-ESP installs are pending

IME writes its "[Win32App] .... Completed user session N ...." line at the
end of EVERY user-session processing pass, not when user-scope enforcement
is finished. Field sessions 14690fc2 and 6cb01530 (2026-07-10, WhiteGlove
Part 2 + mid-AccountSetup reboot) matched the line on the first post-reboot
pass with 13-18 required apps still pending; arm C of
ShouldTransitionToAwaitingHello took the signal as its fourth fact and the
session completed Succeeded five minutes later (HelloSafety timeout ->
FinalizingGrace) mid-install, spraying app_install_starved events.

Harden at the signal source: ImeLogTrackerAdapter.EmitUserSessionCompleted
now consults the new ImeLogTracker.GetPendingRequiredUserEspInstallApps()
probe (AccountSetup phase, Install intent, not terminal) and defers the
decision signal while the list is non-empty. The fire-once flag stays
unclaimed, so the completion line of a later pass re-evaluates and posts
once the apps have settled. Error counts as terminal (GRS owns retries) so
a permanently failed app cannot park the signal - and with it the
AdvisoryCompletion conjunction - into a 30-min-backstop false Failed.
Non-AccountSetup completions post as before (pre-anchor stamps stay
harmless via IsImeUserSessionGenuine).

Observability for the field watch: INFO log line per suppressed pass plus
a one-shot agent_trace (decision=ime_user_session_completion_deferred,
pending count + capped names) on the session timeline.

Session 04e8d52e

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-07-10 21:17:45 +02:00
parent fa03e290b2
commit 611db9261c
3 changed files with 285 additions and 2 deletions
@@ -0,0 +1,167 @@
using System.Collections.Generic;
using System.Linq;
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration;
using AutopilotMonitor.DecisionCore.Signals;
using SharedEventTypes = AutopilotMonitor.Shared.Constants.EventTypes;
using Xunit;
namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
{
/// <summary>
/// Sessions 14690fc2/6cb01530 hardening (2026-07-10): IME writes its "Completed user
/// session N" line at the end of EVERY user-session processing pass — the first
/// post-reboot pass completed with 13–18 required apps still pending and arm C stamped
/// the session Succeeded 5 minutes later mid-install. The adapter must defer the
/// <see cref="DecisionSignalKind.ImeUserSessionCompleted"/> signal while required
/// Install-intent user-ESP apps are pending, and post it on the first pass-completion
/// after they settle. Error counts as terminal (GRS owns retries) so a failed app can
/// never park the signal — and with it the AdvisoryCompletion conjunction — forever.
/// </summary>
public sealed class ImeLogTrackerAdapterUserSessionGateTests
{
private static AppPackageState AddApp(
ImeLogTracker tracker,
string id,
AppIntent intent,
AppInstallationState state)
{
var pkg = tracker.PackageStates.GetPackage(id, createIfNotFound: true);
pkg.UpdateIntent(intent);
if (state == AppInstallationState.Installed)
{
pkg.UpdateState(AppInstallationState.Installing);
}
if (state != AppInstallationState.Unknown)
{
pkg.UpdateState(state);
}
return pkg;
}
private static IReadOnlyList<FakeSignalIngressSink.PostedSignal> DeferralTraces(ImeLogTrackerAdapterFixture f) =>
f.InfoEvents(SharedEventTypes.AgentTrace)
.Where(p => p.Payload!.TryGetValue("decision", out var d)
&& d == "ime_user_session_completion_deferred")
.ToList();
[Fact]
public void Pending_required_install_app_defers_signal_and_emits_oneshot_deferral_trace()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
AddApp(f.Tracker, "app-pending", AppIntent.Install, AppInstallationState.Unknown);
adapter.TriggerUserSessionCompletedFromTest();
adapter.TriggerUserSessionCompletedFromTest(); // second pass, still pending
Assert.Empty(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
Assert.Empty(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted));
var trace = Assert.Single(DeferralTraces(f));
Assert.Equal("1", trace.Payload!["pendingRequiredInstallApps"]);
Assert.Contains("app-pending", trace.Payload["pendingAppNames"]);
}
[Fact]
public void Signal_posts_on_next_pass_after_pending_app_settles()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
var pkg = AddApp(f.Tracker, "app-pending", AppIntent.Install, AppInstallationState.Unknown);
adapter.TriggerUserSessionCompletedFromTest();
Assert.Empty(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
pkg.UpdateState(AppInstallationState.Installing);
pkg.UpdateState(AppInstallationState.Installed);
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
Assert.Single(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted));
}
[Fact]
public void Error_state_app_counts_as_terminal_and_does_not_defer()
{
// A permanently failed app must not park the signal: the AdvisoryCompletion
// conjunction needs the IME fact, and blocking it would flip an otherwise
// completed enrollment into a 30-minute-backstop Failed.
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
AddApp(f.Tracker, "app-failed", AppIntent.Install, AppInstallationState.Error);
AddApp(f.Tracker, "app-installed", AppIntent.Install, AppInstallationState.Installed);
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
Assert.Empty(DeferralTraces(f));
}
[Fact]
public void Pending_uninstall_intent_app_does_not_defer()
{
// The ESP apps gate does not block on uninstalls (session a4537c36) — a pending
// system-app removal must not delay the completion signal.
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
AddApp(f.Tracker, "app-uninstall-pending", AppIntent.Uninstall, AppInstallationState.Unknown);
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
}
[Fact]
public void Outside_AccountSetup_phase_posts_as_before()
{
// Pre-anchor completions (defaultuser0 / technician frame) keep their existing
// semantics — DecisionCore's IsImeUserSessionGenuine guard already prevents them
// from ever triggering completion, and the M2 recording rule needs the stamp.
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("DeviceSetup");
AddApp(f.Tracker, "app-pending", AppIntent.Install, AppInstallationState.Unknown);
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
Assert.Empty(DeferralTraces(f));
}
[Fact]
public void No_tracked_apps_posts_signal()
{
// Zero user-scope apps assigned is a legitimate immediate completion — an empty
// catalog must not defer (fail-open to the pre-hardening behaviour).
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
}
[Fact]
public void Fire_once_preserved_after_signal_posts()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.SeedCurrentPhaseForTesting("AccountSetup");
AddApp(f.Tracker, "app-installed", AppIntent.Install, AppInstallationState.Installed);
adapter.TriggerUserSessionCompletedFromTest();
adapter.TriggerUserSessionCompletedFromTest();
Assert.Single(f.DecisionSignals(DecisionSignalKind.ImeUserSessionCompleted));
Assert.Single(f.InfoEvents(SharedEventTypes.ImeUserSessionCompleted));
}
}
}
@@ -321,6 +321,53 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
}
}
/// <summary>
/// Sessions 14690fc2/6cb01530 arm-C hardening (2026-07-10): returns the required
/// user-ESP Install-intent apps that have NOT reached a terminal state
/// (Installed / Skipped / Postponed / Error) in the current AccountSetup phase.
/// IME writes its <c>Completed user session N</c> line at the end of EVERY
/// user-session processing pass — including a first pass that merely enumerated the
/// app catalog — so <c>ImeLogTrackerAdapter</c> defers the
/// <c>ImeUserSessionCompleted</c> decision signal while this list is non-empty.
/// <para>
/// Unlike <see cref="AreUserEspAppsSettled"/>, <see cref="AppInstallationState.Error"/>
/// counts as settled here: IME delivered its verdict for that app (GRS re-tries hours
/// later, far outside the enrollment window), and blocking the signal on a failed app
/// would starve the AdvisoryCompletion conjunction into failing sessions whose user
/// has long been at the desktop. Uninstall-intent apps are excluded for the same
/// reason as in <see cref="GetStarvedUserEspApps"/>. Non-AccountSetup phases return
/// empty — pre-anchor completions keep their existing (never completion-triggering)
/// semantics. Same thread-safety contract as the sibling probes: snapshot copy, any
/// race-induced exception returns an empty list (fail-open to the pre-hardening
/// behaviour rather than parking completion on a probe bug).
/// </para>
/// </summary>
public IReadOnlyList<AppPackageState> GetPendingRequiredUserEspInstallApps()
{
try
{
if (!string.Equals(_lastEspPhaseDetected, "AccountSetup", StringComparison.OrdinalIgnoreCase))
return Array.Empty<AppPackageState>();
var apps = new List<AppPackageState>(_packageStates);
if (apps.Count == 0) return Array.Empty<AppPackageState>();
var pending = new List<AppPackageState>();
foreach (var pkg in apps)
{
if (pkg == null || pkg.Intent != AppIntent.Install) continue;
if (pkg.IsCompleted) continue; // terminal incl. Error
pending.Add(pkg);
}
return pending;
}
catch (Exception ex)
{
_logger.Debug($"ImeLogTracker: GetPendingRequiredUserEspInstallApps probe threw: {ex.Message}");
return Array.Empty<AppPackageState>();
}
}
/// <summary>
/// Liveness plan PR3 — returns the required user-ESP apps that are STARVING the
/// AccountSetup apps gate: tracked in the current AccountSetup phase, Install intent
@@ -34,7 +34,10 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
/// <list type="bullet">
/// <item><c>OnEspPhaseChanged(phase)</c> → <see cref="DecisionSignalKind.EspPhaseChanged"/>
/// (dedup per distinct phase value — Reducer Plan §2.1a idempotenz-Anforderung).</item>
/// <item><c>OnUserSessionCompleted()</c> → <see cref="DecisionSignalKind.ImeUserSessionCompleted"/> (fire-once).</item>
/// <item><c>OnUserSessionCompleted()</c> → <see cref="DecisionSignalKind.ImeUserSessionCompleted"/> (fire-once;
/// deferred while required user-ESP Install-intent apps are still pending — IME's
/// "Completed user session" line fires per processing pass, see
/// <see cref="ImeLogTracker.GetPendingRequiredUserEspInstallApps"/>).</item>
/// <item><c>OnAppStateChanged(app, old, new)</c> → <see cref="DecisionSignalKind.AppInstallCompleted"/>
/// (state=Installed/Skipped/Postponed) oder <see cref="DecisionSignalKind.AppInstallFailed"/> (state=Error).
/// Dedup pro (AppId, terminal-state-tuple).</item>
@@ -86,6 +89,9 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
// Dedup state for DecisionSignals.
private string? _lastEspPhase;
private bool _userSessionCompletedPosted;
// One-shot flag for the user-session-completion deferral trace event — the INFO log
// line repeats per suppressed pass, the timeline event fires once per agent run.
private bool _userSessionDeferralNoted;
private bool _sealingPatternPosted;
// Fires once per session when a Platform Script stdout contains the Autopilot-Monitor
// bootstrap marker line. Lets MCP report "which device runs which bootstrap version".
@@ -385,6 +391,23 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
private void EmitUserSessionCompleted()
{
// Sessions 14690fc2/6cb01530 hardening (2026-07-10): IME writes its "Completed
// user session N" line at the end of EVERY user-session processing pass, not when
// user-scope enforcement is done — both field sessions had 13–18 required apps
// still pending when the first post-reboot pass completed, and arm C
// (ShouldTransitionToAwaitingHello) stamped the session Succeeded 5 minutes later
// mid-install. Defer the decision signal while required Install-intent user-ESP
// apps are pending; the fire-once flag stays unclaimed, so the completion line of
// a later pass re-evaluates and posts once the apps have settled. Error counts as
// terminal in the probe (GRS owns retries), so a permanently failed app cannot
// park the signal — and with it the AdvisoryCompletion conjunction — forever.
var pendingApps = _tracker.GetPendingRequiredUserEspInstallApps();
if (pendingApps.Count > 0)
{
NoteUserSessionCompletionDeferred(pendingApps);
return;
}
lock (_lock)
{
if (_userSessionCompletedPosted) return;
@@ -406,7 +429,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
evidence: new Evidence(
kind: EvidenceKind.Derived,
identifier: "ime-log-tracker-v1",
summary: "IME user session completed (all user-scope apps finished)",
summary: "IME user session completed (no required user-scope apps pending)",
derivationInputs: derivationInputs));
var data = new Dictionary<string, string>(StringComparer.Ordinal)
@@ -429,6 +452,52 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
_logger?.Info($"ImeAdapter: user session completed -> posting ImeUserSessionCompleted (patternId={patternId ?? "(none)"})");
}
/// <summary>
/// Observability for the deferred user-session completion (sessions 14690fc2/6cb01530):
/// an INFO log line per suppressed pass plus a one-shot <c>agent_trace</c> timeline
/// event, so a field session shows WHY <c>ime_user_session_completed</c> arrived late
/// (or never) without needing the diagnostics ZIP.
/// </summary>
private void NoteUserSessionCompletionDeferred(IReadOnlyList<AppPackageState> pendingApps)
{
const int maxNames = 10;
var names = new List<string>(Math.Min(pendingApps.Count, maxNames));
foreach (var pkg in pendingApps)
{
if (names.Count >= maxNames) break;
if (pkg == null) continue;
names.Add(string.IsNullOrEmpty(pkg.Name) ? pkg.Id : pkg.Name!);
}
var namesJoined = string.Join("; ", names)
+ (pendingApps.Count > maxNames ? $" (+{pendingApps.Count - maxNames} more)" : string.Empty);
_logger?.Info(
$"ImeAdapter: IME 'Completed user session' line observed but {pendingApps.Count} required user-ESP app(s) still pending -> deferring ImeUserSessionCompleted (pending: {namesJoined})");
lock (_lock)
{
if (_userSessionDeferralNoted) return;
_userSessionDeferralNoted = true;
}
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs);
var data = new Dictionary<string, string>(StringComparer.Ordinal)
{
["decision"] = "ime_user_session_completion_deferred",
["pendingRequiredInstallApps"] = pendingApps.Count.ToString(System.Globalization.CultureInfo.InvariantCulture),
["pendingAppNames"] = namesJoined,
};
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
_post.Emit(
eventType: SharedEventTypes.AgentTrace,
source: SourceLabel,
message: $"IME user-session completion line observed while {pendingApps.Count} required user app(s) pending — completion signal deferred until they settle",
severity: EventSeverity.Info,
data: data,
occurredAtUtc: now);
}
private void EmitAppState(AppPackageState app, AppInstallationState oldState, AppInstallationState newState)
{
if (app == null || string.IsNullOrEmpty(app.Id)) return;