Token-failure grace window + registry_app_baseline summary

Live findings from the first two 2.0.1402 sessions (Oliver, 2026-08-18):

1. "Failed to get AAD token" is logged routinely during the device phase
   (no user token exists yet) - both test sessions raised the Warning
   although nothing was wrong. The failure is now held pending: any
   IME-TOKEN-SUCCESS match clears it (staleness-gated so a replayed
   success from a previous enrollment cannot mask a current outage), and
   ime_token_failure fires only when no success follows for the 30-min
   grace window, then deduped per errorCode. Genuine auth outages run
   long enough to hit the window; routine device-phase failures never do.

2. New one-shot registry_app_baseline event (Info, only when non-empty):
   summary of the Win32Apps state that predates the agent run - counts
   by enforcement class + capped 50-app typed payload incl.
   LastUpdatedTimeUtc. On WDP the DPP-policy apps install in Batch 1
   before the bootstrap-script agent exists; their outcomes live only in
   this baseline, closing the pre-agent app gap without log backfill.
   The diff rail stays silent on baseline state (anti-replay unchanged).

Event type dual-registered (Constants + MCP catalog + manifests regen).
Tests: grace-window cycle (resolved / unresolved / re-arm dedup),
baseline summary (counts, one-shot, empty). All suites green
(Agent 2274, Functions 4262, MCP 561, web 762), 0 warnings.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-08-18 03:16:58 +02:00
parent 587adc5ddf
commit 2cf7216be5
12 changed files with 192 additions and 14 deletions
+1 -1
View File
@@ -629,7 +629,7 @@
"category": "always",
"pattern": "Failed to get AAD token\\..*?errorCode = (?<errorCode>.*?)$",
"action": "imeTokenFailure",
"description": "IME token acquisition failure ('Failed to get AAD token. len = N using client id ... and resource id ..., errorCode = N', IntuneTokenManager, IntuneManagementExtension.log). Complements IME-TOKEN-SUCCESS: an auth outage (WAM broken, conditional access, network) previously left every check-in silently doing nothing with no timeline evidence. errorCode can be empty when IME logged none; the agent dedups to one Warning per distinct code. Verified against IME 1.97 and 1.104 decompiled sources.",
"description": "IME token acquisition failure ('Failed to get AAD token. len = N using client id ... and resource id ..., errorCode = N', IntuneTokenManager, IntuneManagementExtension.log). This line appears ROUTINELY during the device phase (no user token exists yet), so the agent holds the failure pending: any IME-TOKEN-SUCCESS match clears it, and the ime_token_failure Warning fires only when no success follows for the whole 30-min grace window (then deduped to one Warning per distinct errorCode). A genuine auth outage (WAM broken, conditional access, network) runs long enough to hit the window. Verified against IME 1.97 and 1.104 decompiled sources.",
"enabled": true
},
{
@@ -4,6 +4,6 @@
"category": "always",
"pattern": "Failed to get AAD token\\..*?errorCode = (?<errorCode>.*?)$",
"action": "imeTokenFailure",
"description": "IME token acquisition failure ('Failed to get AAD token. len = N using client id ... and resource id ..., errorCode = N', IntuneTokenManager, IntuneManagementExtension.log). Complements IME-TOKEN-SUCCESS: an auth outage (WAM broken, conditional access, network) previously left every check-in silently doing nothing with no timeline evidence. errorCode can be empty when IME logged none; the agent dedups to one Warning per distinct code. Verified against IME 1.97 and 1.104 decompiled sources.",
"description": "IME token acquisition failure ('Failed to get AAD token. len = N using client id ... and resource id ..., errorCode = N', IntuneTokenManager, IntuneManagementExtension.log). This line appears ROUTINELY during the device phase (no user token exists yet), so the agent holds the failure pending: any IME-TOKEN-SUCCESS match clears it, and the ime_token_failure Warning fires only when no success follows for the whole 30-min grace window (then deduped to one Warning per distinct errorCode). A genuine auth outage (WAM broken, conditional access, network) runs long enough to hit the window. Verified against IME 1.97 and 1.104 decompiled sources.",
"enabled": true
}
@@ -119,6 +119,40 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals
Assert.Equal("success", evt.Payload["enforcementClass"]);
}
[Fact]
public void NonEmpty_baseline_emits_one_summary_with_counts()
{
var (sink, clock, observer) = CreateObserver(trackerApps: null);
var current = Snapshot((App1, 1000, 0), (App2, 5003, 101));
using (new ImeRegistryAppStateObserver.ScopedSnapshotOverride(() => current))
{
observer.Tick("baseline");
observer.Tick("periodic"); // summary is one-shot, not per tick
}
var summary = Assert.Single(Events(sink, SharedEventTypes.RegistryAppBaseline));
Assert.Equal("2", summary.Payload!["totalApps"]);
Assert.Equal("1", summary.Payload["successCount"]);
Assert.Equal("1", summary.Payload["errorCount"]);
// The baseline stays silent on the diff rail.
Assert.Empty(Events(sink, SharedEventTypes.RegistryAppState));
}
[Fact]
public void Empty_baseline_emits_no_summary()
{
var (sink, clock, observer) = CreateObserver(trackerApps: null);
var current = new ImeRegistrySnapshot();
using (new ImeRegistryAppStateObserver.ScopedSnapshotOverride(() => current))
{
observer.Tick("baseline");
}
Assert.Empty(Events(sink, SharedEventTypes.RegistryAppBaseline));
}
[Fact]
public void Unchanged_snapshot_emits_nothing()
{
@@ -479,16 +479,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
}
[Fact]
public void ImeTokenFailure_tracker_dedups_per_error_code()
public void ImeTokenFailure_grace_window_emits_only_without_token_success()
{
// "Failed to get AAD token" appears routinely during the device phase (no user
// token yet) — the Warning must fire only when NO success follows for the whole
// grace window.
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
var t0 = DateTime.UtcNow;
// Failure resolved by a token success: never emitted, not even after the window.
f.Tracker.HandleImeTokenFailureForTest("100", "line a");
f.Tracker.HandleImeTokenFailureForTest("100", "line b"); // same code — suppressed
f.Tracker.HandleImeTokenFailureForTest("200", "line c"); // new code — emitted
f.Tracker.NoteTokenSuccessForTest();
f.Tracker.CheckPendingTokenFailure(t0 + ImeLogTracker.TokenFailureGraceWindow + TimeSpan.FromMinutes(1));
Assert.Empty(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
Assert.Equal(2, f.InfoEvents(SharedEventTypes.ImeTokenFailure).Count);
// Unresolved failure: silent before the window, one Warning after it.
f.Tracker.HandleImeTokenFailureForTest("100", "line b");
f.Tracker.CheckPendingTokenFailure(t0 + TimeSpan.FromMinutes(5));
Assert.Empty(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
f.Tracker.CheckPendingTokenFailure(t0 + ImeLogTracker.TokenFailureGraceWindow + TimeSpan.FromHours(1));
Assert.Single(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
// Same code again: re-armed window expires but the per-code dedup suppresses.
f.Tracker.HandleImeTokenFailureForTest("100", "line c");
f.Tracker.CheckPendingTokenFailure(t0 + TimeSpan.FromHours(3));
Assert.Single(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
}
[Fact]
@@ -25,25 +25,70 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private DateTime _impersonationLastRollupUtc = DateTime.MinValue;
private static readonly TimeSpan ImpersonationRollupInterval = TimeSpan.FromSeconds(60);
// IME retries token acquisition on every check-in — dedup per distinct error
// code so an outage yields one Warning, not a timeline flood.
// "Failed to get AAD token" is logged ROUTINELY during the device phase (no user
// token exists yet — field-confirmed: the line appears en masse in every enrollment,
// Oliver 2026-08-18). A failure is therefore only meaningful when NO token success
// follows: the failure is held pending, any IME-TOKEN-SUCCESS match clears it, and
// the Warning fires only after the grace window elapses without a success. Genuine
// auth outages (WAM broken, conditional access, network) run long enough to hit it.
// Not persisted across restarts — failures keep arriving, the window re-arms.
internal static readonly TimeSpan TokenFailureGraceWindow = TimeSpan.FromMinutes(30);
private sealed class PendingTokenFailure
{
public string Code = "unknown";
public string Excerpt = string.Empty;
public DateTime FirstFailureUtc;
}
private PendingTokenFailure _pendingTokenFailure;
// Dedup per distinct error code so a persistent outage yields one Warning total.
private readonly HashSet<string> _reportedTokenFailureCodes = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
private void HandleImeTokenFailure(string errorCode, string message)
{
var code = string.IsNullOrEmpty(errorCode) ? "unknown" : errorCode.Trim();
if (!_reportedTokenFailureCodes.Add(code)) return;
if (_pendingTokenFailure != null) return; // earliest unresolved failure wins
var code = string.IsNullOrEmpty(errorCode) ? "unknown" : errorCode.Trim();
var excerpt = message ?? string.Empty;
if (excerpt.Length > 300) excerpt = excerpt.Substring(0, 300);
_logger.Warning($"ImeLogTracker: IME token acquisition failure (errorCode={code})");
OnImeTokenFailure?.Invoke(code, excerpt);
_pendingTokenFailure = new PendingTokenFailure
{
Code = code,
Excerpt = excerpt,
// Source-line time so a late-starting agent replaying an ongoing outage
// ages the window correctly; a success later in the same log still clears
// before the expiry check runs (lines are drained first, expiry after).
FirstFailureUtc = LastMatchedLogTimestamp ?? DateTime.UtcNow,
};
}
// Test seam: drives HandleImeTokenFailure without the regex pipeline.
private void ClearPendingTokenFailure()
{
if (_pendingTokenFailure == null) return;
_logger.Debug($"ImeLogTracker: token success observed — pending token failure (errorCode={_pendingTokenFailure.Code}) cleared");
_pendingTokenFailure = null;
}
/// <summary>Called once per poll cycle after the log drain (and testable directly).</summary>
internal void CheckPendingTokenFailure(DateTime nowUtc)
{
var pending = _pendingTokenFailure;
if (pending == null) return;
if (nowUtc - pending.FirstFailureUtc < TokenFailureGraceWindow) return;
_pendingTokenFailure = null; // next failure line re-arms a fresh window
if (!_reportedTokenFailureCodes.Add(pending.Code)) return;
_logger.Warning($"ImeLogTracker: IME token acquisition failing for >= {TokenFailureGraceWindow.TotalMinutes:0} min without a success (errorCode={pending.Code})");
OnImeTokenFailure?.Invoke(pending.Code, pending.Excerpt);
}
// Test seams: drive the pending/clear/expiry cycle without the regex pipeline.
internal void HandleImeTokenFailureForTest(string errorCode, string message)
=> HandleImeTokenFailure(errorCode, message);
internal void NoteTokenSuccessForTest() => ClearPendingTokenFailure();
private void HandleImeImpersonation(string user)
{
@@ -244,6 +244,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
return;
}
// A token success resolves any pending token failure (grace-window model, see
// HandleImeTokenFailure). Matched on our own stable pattern ID — the line also
// drives espPhaseDetected, whose handler must stay unaware of token semantics.
// Placed after the staleness gate so a success replayed from a previous
// enrollment's log cannot clear a genuine current outage.
if (!isStaleReplayLine && string.Equals(pattern.PatternId, "IME-TOKEN-SUCCESS", StringComparison.OrdinalIgnoreCase))
ClearPendingTokenFailure();
try
{
var id = match.Groups["id"]?.Value;
@@ -607,6 +607,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// line never arrived within the grace period. Runs on this same loop
// thread (no locking) so it observes the buffer right after parsing.
FlushStalePlatformScriptResults(DateTime.UtcNow);
// Token-failure grace window: fires only when the failure stayed
// unresolved (no IME-TOKEN-SUCCESS) for the whole window. Runs after
// the drain so a success later in the same batch clears first.
CheckPendingTokenFailure(DateTime.UtcNow);
}
catch (OperationCanceledException) { break; }
catch (Exception ex)
@@ -119,9 +119,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
if (_last == null)
{
// Silent baseline — see class doc.
// Silent baseline for the DIFF stream — see class doc. But the baseline
// itself is valuable evidence: on WDP the DPP-policy apps install in
// Batch 1 BEFORE the agent (bootstrap = Batch 2), so their terminal
// states exist ONLY here. One capped summary event closes that
// pre-agent gap without any log backfill (Oliver, 2026-08-18).
_last = snapshot;
_logger?.Info($"RegistryAppState: baseline captured ({snapshot.Entries.Count} app entries, trigger={reason})");
if (snapshot.Entries.Count > 0)
EmitBaselineSummary(snapshot, nowUtc);
return;
}
@@ -181,6 +187,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
var entry = snapshot.GetOrAdd(userName, appId);
entry.ExitCode = TryReadInt(appKey.GetValue("ExitCode"));
entry.Intent = TryReadInt(appKey.GetValue("Intent"));
entry.LastUpdatedUtc = appKey.GetValue("LastUpdatedTimeUtc") as string;
using var esm = appKey.OpenSubKey("EnforcementStateMessage");
var json = esm?.GetValue("EnforcementStateMessage") as string;
@@ -452,6 +459,64 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
occurredAtUtc: nowUtc);
}
// Baseline entries in the summary's typed payload are capped — a long-lived device
// with many historical Win32Apps entries must not produce an oversized event.
internal const int MaxBaselineSummaryApps = 50;
private void EmitBaselineSummary(ImeRegistrySnapshot snapshot, DateTime nowUtc)
{
int success = 0, error = 0, inProgress = 0, other = 0;
var apps = new List<Dictionary<string, string>>();
foreach (var entry in snapshot.Entries.Values)
{
var cls = entry.EnforcementState is int es ? ClassifyEnforcementState(es) : null;
switch (cls)
{
case "success": success++; break;
case "error": error++; break;
case "inProgress": inProgress++; break;
default: other++; break;
}
if (apps.Count >= MaxBaselineSummaryApps) continue;
var app = new Dictionary<string, string>(StringComparer.Ordinal)
{
["appId"] = entry.AppId,
["userContext"] = entry.UserContext,
};
if (entry.EnforcementState is int state)
{
app["enforcementState"] = state.ToString(CultureInfo.InvariantCulture);
app["enforcementClass"] = ClassifyEnforcementState(state);
}
if (entry.ErrorCode is long ec) app["errorCode"] = ec.ToString(CultureInfo.InvariantCulture);
if (entry.ExitCode is int xc) app["exitCode"] = xc.ToString(CultureInfo.InvariantCulture);
if (!string.IsNullOrEmpty(entry.LastUpdatedUtc)) app["lastUpdatedUtc"] = entry.LastUpdatedUtc!;
if (entry.EspTracked) app["espTracked"] = "true";
apps.Add(app);
}
var data = new Dictionary<string, string>(StringComparer.Ordinal)
{
["totalApps"] = snapshot.Entries.Count.ToString(CultureInfo.InvariantCulture),
["successCount"] = success.ToString(CultureInfo.InvariantCulture),
["errorCount"] = error.ToString(CultureInfo.InvariantCulture),
["inProgressCount"] = inProgress.ToString(CultureInfo.InvariantCulture),
["otherCount"] = other.ToString(CultureInfo.InvariantCulture),
};
if (snapshot.Entries.Count > MaxBaselineSummaryApps)
data["appListTruncated"] = "true";
_post.Emit(
eventType: SharedEventTypes.RegistryAppBaseline,
source: SourceLabel,
message: $"Registry app baseline at agent start: {snapshot.Entries.Count} apps ({success} success, {error} error, {inProgress} in progress) — state that predates this agent run",
severity: EventSeverity.Info,
data: data,
occurredAtUtc: nowUtc,
typedPayload: new { apps });
}
private void TrackTerminalTransitions(ImeRegistrySnapshot snapshot, DateTime nowUtc)
{
foreach (var kv in snapshot.Entries)
@@ -552,6 +617,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
public string Key { get; }
public string UserContext { get; }
public string AppId { get; }
public string? LastUpdatedUtc { get; set; }
public int? EnforcementState { get; set; }
public long? ErrorCode { get; set; }
public int? ExitCode { get; set; }
@@ -148,6 +148,7 @@ export const EVENT_TYPES_CATALOG = {
'ime_agent_version',
'ime_token_failure',
'registry_app_state',
'registry_app_baseline',
'app_state_reconciliation',
'ime_user_session_completed',
'ime_session_change',
@@ -421,6 +421,7 @@ namespace AutopilotMonitor.Shared
// per-app state read straight from HKLM\...\IntuneManagementExtension. Observability only —
// never consumed by the DecisionEngine.
public const string RegistryAppState = "registry_app_state"; // Info, state-change-only (snapshot-diff vs silent startup baseline; capped 200/session, cap announced once as Warning): per-app EnforcementState/ErrorCode/ExitCode/StatusService status/ESP-tracking from the registry.
public const string RegistryAppBaseline = "registry_app_baseline"; // Info, one-shot at agent start (only when non-empty): summary of the Win32Apps state that PREDATES this agent run. Closes the WDP pre-agent gap — DPP-policy apps install in Batch 1 before the bootstrap-script agent exists, so their outcomes live only in this baseline (typed payload capped at 50 apps).
public const string AppStateReconciliation = "app_state_reconciliation"; // Warning, once per app, immediate upload: registry terminal outcome (settled >= 90 s) diverges from the IME-log-derived app state — the built-in log-pattern drift alarm (registry = truth, logs = narrative).
public const string ImeUserSessionCompleted = "ime_user_session_completed";
public const string DoTelemetry = "do_telemetry";
@@ -604,6 +604,7 @@ export const SHARED_MANIFEST = {
"realmjoin_resolved",
"realmjoin_timeout",
"reboot_triggered",
"registry_app_baseline",
"registry_app_state",
"remote_config_fetch_failed",
"script_completed",
@@ -600,6 +600,7 @@
"realmjoin_resolved",
"realmjoin_timeout",
"reboot_triggered",
"registry_app_baseline",
"registry_app_state",
"remote_config_fetch_failed",
"script_completed",