IME tracker: tail AppActionProcessor.log; GRS + token-failure signals

P0b/P1 of the 2026-08-17 IME code audit (agent release required):

- Tail AppActionProcessor.log (+ rollover glob) in ImeLogTracker and the
  --run-ime-matching CLI. IME routes every [Win32App][ActionProcessor]
  line there (enforcement decision engine), so IME-NO-ACTION and
  IME-NOT-TARGETED-1/2 could never fire before, and GRS skips were
  invisible. Live session 0fe2c562 carried 16 no-action and 64
  classification lines in that file.

- New patterns (wordings verified in decompiled IME 1.97 AND 1.104):
  IME-GRS-SKIP ("is in GRS. The app will not be enforced." -> Postponed;
  THE canonical silent non-install reason), IME-GRS-CLEARED (early
  subgraph termination, retry next check-in -> Postponed),
  IME-TOKEN-FAILURE ("Failed to get AAD token ... errorCode = N").

- New action imeTokenFailure -> ime_token_failure Warning event (new
  EventType: Constants + MCP resource-catalog + shared manifests
  regenerated). Tracker dedups per distinct errorCode; included in
  the historic-replay guard so stale lines from a previous enrollment
  cannot emit a misleading warning. Complements IME-TOKEN-SUCCESS:
  an auth outage previously left check-ins silently doing nothing.

Tests: adapter emission + unknown-code + tracker dedup; known-actions
catalog extended; all suites green (Functions 4262, Agent 2252, web 762).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-08-18 01:01:02 +02:00
parent ab0f27b5ab
commit 68eb2da283
16 changed files with 179 additions and 1 deletions
+24
View File
@@ -358,6 +358,22 @@
"description": "Marks the current app as failed when its exit code maps to Failed via the admin-defined return-code table ('[Win32App] lpExitCode is defined as <Failed|Success|SoftReboot|HardReboot|Retry>', Win32AppInstaller.cs). This is the NORMAL mapped-exit-code outcome; the previously matched 'Setting enforcementState as ... Error' line only fires on the rare no-mapping fallback path. The numeric exit code is captured separately by IME-EXITCODE, which precedes this line.",
"enabled": true
},
{
"patternId": "IME-GRS-CLEARED",
"category": "currentPhase",
"pattern": "\\[Win32App\\]\\[ExecutionActionHandler\\] Encountered early subgraph termination\\. Clearing GRS for app with id: {GUID} so it can be retried during the next check-in\\.",
"action": "updateStatePostponed",
"description": "IME aborted the app's subgraph before enforcement finished and cleared its GRS entry so the app retries on the next check-in (ExecutionActionHandler, AppWorkload.log). Maps to Postponed: the install did not complete this pass but is scheduled to run again - previously this looked like an unexplained gap. Wording verified in IME 1.97 and 1.104.",
"enabled": true
},
{
"patternId": "IME-GRS-SKIP",
"category": "currentPhase",
"pattern": "\\[Win32App\\]\\[ActionProcessor\\] App with id: {GUID} to (?:install|uninstall) is in GRS\\. The app will not be enforced\\.",
"action": "updateStatePostponed",
"description": "GRS (Global Retry Schedule) skip: the app failed recently and IME will not re-enforce it this check-in ('App with id: <guid> to install is in GRS. The app will not be enforced.', EnforcementActionProcessor / MixedEnforcementActionProcessor). THE canonical reason an app silently does nothing for up to 24h - previously invisible. Lives in AppActionProcessor.log, which the agent tails since the 2026-08-18 release; wording verified in IME 1.97 and 1.104.",
"enabled": true
},
{
"patternId": "IME-HRESULT",
"category": "currentPhase",
@@ -608,6 +624,14 @@
"description": "Detects when V3Processor starts a new subgraph, cancelling any stuck app and setting the new app as current.",
"enabled": true
},
{
"patternId": "IME-TOKEN-FAILURE",
"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.",
"enabled": true
},
{
"patternId": "IME-TOKEN-SUCCESS",
"category": "always",
@@ -0,0 +1,9 @@
{
"$schema": "../schema/ime-log-pattern.schema.json",
"patternId": "IME-GRS-CLEARED",
"category": "currentPhase",
"pattern": "\\[Win32App\\]\\[ExecutionActionHandler\\] Encountered early subgraph termination\\. Clearing GRS for app with id: {GUID} so it can be retried during the next check-in\\.",
"action": "updateStatePostponed",
"description": "IME aborted the app's subgraph before enforcement finished and cleared its GRS entry so the app retries on the next check-in (ExecutionActionHandler, AppWorkload.log). Maps to Postponed: the install did not complete this pass but is scheduled to run again - previously this looked like an unexplained gap. Wording verified in IME 1.97 and 1.104.",
"enabled": true
}
+9
View File
@@ -0,0 +1,9 @@
{
"$schema": "../schema/ime-log-pattern.schema.json",
"patternId": "IME-GRS-SKIP",
"category": "currentPhase",
"pattern": "\\[Win32App\\]\\[ActionProcessor\\] App with id: {GUID} to (?:install|uninstall) is in GRS\\. The app will not be enforced\\.",
"action": "updateStatePostponed",
"description": "GRS (Global Retry Schedule) skip: the app failed recently and IME will not re-enforce it this check-in ('App with id: <guid> to install is in GRS. The app will not be enforced.', EnforcementActionProcessor / MixedEnforcementActionProcessor). THE canonical reason an app silently does nothing for up to 24h - previously invisible. Lives in AppActionProcessor.log, which the agent tails since the 2026-08-18 release; wording verified in IME 1.97 and 1.104.",
"enabled": true
}
@@ -0,0 +1,9 @@
{
"$schema": "../schema/ime-log-pattern.schema.json",
"patternId": "IME-TOKEN-FAILURE",
"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.",
"enabled": true
}
+1
View File
@@ -61,6 +61,7 @@
"cancelStuckAndSetCurrent",
"imeSessionChange",
"imeImpersonation",
"imeTokenFailure",
"enrollmentCompleted",
"updateDoTelemetry",
"scriptStarted",
@@ -462,6 +462,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
Assert.Equal("IME Agent version: 1.101.109.0", info.Payload[SignalPayloadKeys.Message]);
}
[Fact]
public void ImeTokenFailure_emits_warning_event_with_error_code()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
adapter.TriggerImeTokenFailureFromTest("3399614467",
"Failed to get AAD token. len = 0 using client id x and resource id y, errorCode = 3399614467");
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
Assert.Equal("ImeLogTracker", info.Payload![SignalPayloadKeys.Source]);
Assert.Equal("3399614467", info.Payload["errorCode"]);
Assert.Contains("errorCode=3399614467", info.Payload[SignalPayloadKeys.Message]);
Assert.Contains("Failed to get AAD token", info.Payload["logLine"]);
}
[Fact]
public void ImeTokenFailure_tracker_dedups_per_error_code()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
f.Tracker.HandleImeTokenFailureForTest("100", "line a");
f.Tracker.HandleImeTokenFailureForTest("100", "line b"); // same code — suppressed
f.Tracker.HandleImeTokenFailureForTest("200", "line c"); // new code — emitted
Assert.Equal(2, f.InfoEvents(SharedEventTypes.ImeTokenFailure).Count);
}
[Fact]
public void ImeTokenFailure_empty_error_code_reports_unknown()
{
using var f = new ImeLogTrackerAdapterFixture();
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
adapter.TriggerImeTokenFailureFromTest("", null!);
var info = Assert.Single(f.InfoEvents(SharedEventTypes.ImeTokenFailure));
Assert.Equal("unknown", info.Payload!["errorCode"]);
Assert.False(info.Payload.ContainsKey("logLine"));
}
[Fact]
public void ImeAgentVersion_null_or_empty_is_skipped()
{
@@ -25,6 +25,26 @@ 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.
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;
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);
}
// Test seam: drives HandleImeTokenFailure without the regex pipeline.
internal void HandleImeTokenFailureForTest(string errorCode, string message)
=> HandleImeTokenFailure(errorCode, message);
private void HandleImeImpersonation(string user)
{
var current = string.IsNullOrEmpty(user) ? "(unknown)" : user;
@@ -214,6 +214,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
"capturedetectionresult", "esptrackstatus", "policiesdiscovered",
"ignorecompletedapp", "updatename", "updatewin32appstate",
"cancelstuckandsetcurrent", "updatedotelemetry",
// Not app-mutating, but a stale token-failure replayed from a previous
// enrollment's log would emit a misleading Warning for THIS session.
"imetokenfailure",
};
private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry)
@@ -296,6 +299,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
OnImeAgentVersion?.Invoke(version);
break;
case "imetokenfailure":
HandleImeTokenFailure(match.Groups["errorCode"]?.Value, message);
break;
case "imeimpersonation":
// PR3-A2: dedup. The same user triggers ~24 identical lines per session;
// log on first/changed user, otherwise count and emit a single rollup
@@ -119,6 +119,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
"IntuneManagementExtension-????????-??????.log",
"AppWorkload.log",
"AppWorkload-????????-??????.log",
// Enforcement decision engine (V3 ActionProcessor). IME routes every
// [Win32App][ActionProcessor] line here (app.config TraceSource mapping) —
// NO-ACTION / NOT-TARGETED classifications and the GRS "will not be
// enforced" skips are ONLY visible in this file (audit 2026-08-17).
"AppActionProcessor.log",
"AppActionProcessor-????????-??????.log",
// PowerShell script tracking
"AgentExecutor.log",
"AgentExecutor-????????-??????.log",
@@ -194,6 +200,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
public Action OnAllAppsCompleted { get; set; }
public Action OnUserSessionCompleted { get; set; }
public Action<string> OnImeSessionChange { get; set; }
// Args: errorCode (may be empty when IME logged none), raw failure line excerpt.
// Fired once per distinct errorCode per tracker lifetime (see HandleImeTokenFailure).
public Action<string, string> OnImeTokenFailure { get; set; }
// Second arg: the [DO TEL] source log line's timestamp when the DO data came from a
// log line, null when the DO collector observed the completion live via polling. The
// consumer must stamp poll-driven telemetry with the clock — inheriting an unrelated
@@ -76,6 +76,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
private readonly Action<AppPackageState, DateTime?>? _prevOnDoTelemetryReceived;
private readonly Action<ScriptExecutionState>? _prevOnScriptCompleted;
private readonly Action<ScriptStartedInfo>? _prevOnScriptStarted;
private readonly Action<string, string>? _prevOnImeTokenFailure;
// Our own delegate instances — stored once so Dispose can compare by reference.
private readonly Action<string> _ourOnEspPhaseChanged;
@@ -86,6 +87,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
private readonly Action<AppPackageState, DateTime?> _ourOnDoTelemetryReceived;
private readonly Action<ScriptExecutionState> _ourOnScriptCompleted;
private readonly Action<ScriptStartedInfo> _ourOnScriptStarted;
private readonly Action<string, string> _ourOnImeTokenFailure;
// Dedup state for DecisionSignals.
private string? _lastEspPhase;
@@ -175,6 +177,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
_prevOnDoTelemetryReceived = _tracker.OnDoTelemetryReceived;
_prevOnScriptCompleted = _tracker.OnScriptCompleted;
_prevOnScriptStarted = _tracker.OnScriptStarted;
_prevOnImeTokenFailure = _tracker.OnImeTokenFailure;
// Store our delegate instances once — implicit method-group conversions
// create a new delegate each time, which would break Dispose's reference check.
@@ -186,6 +189,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
_ourOnDoTelemetryReceived = OnDoTelemetryReceived;
_ourOnScriptCompleted = OnScriptCompleted;
_ourOnScriptStarted = OnScriptStarted;
_ourOnImeTokenFailure = OnImeTokenFailure;
_tracker.OnEspPhaseChanged = _ourOnEspPhaseChanged;
_tracker.OnUserSessionCompleted = _ourOnUserSessionCompleted;
@@ -195,6 +199,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
_tracker.OnDoTelemetryReceived = _ourOnDoTelemetryReceived;
_tracker.OnScriptCompleted = _ourOnScriptCompleted;
_tracker.OnScriptStarted = _ourOnScriptStarted;
_tracker.OnImeTokenFailure = _ourOnImeTokenFailure;
}
public void Dispose()
@@ -217,6 +222,8 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
_tracker.OnScriptCompleted = _prevOnScriptCompleted;
if (ReferenceEquals(_tracker.OnScriptStarted, _ourOnScriptStarted))
_tracker.OnScriptStarted = _prevOnScriptStarted;
if (ReferenceEquals(_tracker.OnImeTokenFailure, _ourOnImeTokenFailure))
_tracker.OnImeTokenFailure = _prevOnImeTokenFailure;
}
private void OnEspPhaseChanged(string phase)
@@ -267,6 +274,12 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
EmitScriptStarted(info);
}
private void OnImeTokenFailure(string errorCode, string message)
{
_prevOnImeTokenFailure?.Invoke(errorCode, message);
EmitImeTokenFailure(errorCode, message);
}
internal void TriggerEspPhaseFromTest(string phase) => EmitEspPhase(phase);
internal void TriggerUserSessionCompletedFromTest() => EmitUserSessionCompleted();
internal void TriggerAppStateFromTest(AppPackageState app, AppInstallationState oldState, AppInstallationState newState) =>
@@ -277,6 +290,7 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
EmitDoTelemetry(app, sourceTimestampUtc);
internal void TriggerScriptCompletedFromTest(ScriptExecutionState script) => EmitScriptCompleted(script);
internal void TriggerScriptStartedFromTest(ScriptStartedInfo info) => EmitScriptStarted(info);
internal void TriggerImeTokenFailureFromTest(string errorCode, string message) => EmitImeTokenFailure(errorCode, message);
/// <summary>
/// Prefer the CMTrace log entry timestamp recorded by the most recent pattern match
@@ -899,6 +913,34 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
: $"ImeAdapter: IME agent version detected: {version}");
}
// IME token-acquisition failure ("Failed to get AAD token ... errorCode = N",
// IntuneTokenManager). Previously we only matched the success line — an outage
// (WAM broken, conditional access, network) was invisible while every check-in
// silently did nothing. Tracker-side dedup: once per distinct errorCode.
private void EmitImeTokenFailure(string errorCode, string message)
{
var now = ResolveOccurredAt(out var derivedFromClock, out var rawSourceTs);
var data = new Dictionary<string, string>(StringComparer.Ordinal)
{
["errorCode"] = string.IsNullOrEmpty(errorCode) ? "unknown" : errorCode,
};
if (!string.IsNullOrEmpty(message))
data["logLine"] = message;
var patternId = _tracker.LastMatchedPatternId;
if (!string.IsNullOrEmpty(patternId))
data["patternId"] = patternId!;
TagDerivedTimestamp(data, derivedFromClock, rawSourceTs);
_post.Emit(
eventType: SharedEventTypes.ImeTokenFailure,
source: SourceLabel,
message: $"IME token acquisition failed (errorCode={data["errorCode"]})",
data: data,
severity: EventSeverity.Warning,
occurredAtUtc: now);
}
private ImeMsiInstallSource ResolveMsiInstallSource(string version)
{
if (_msiSourceCachedForVersion == version) return _msiSourceCache;
@@ -30,6 +30,8 @@ namespace AutopilotMonitor.Agent.V2
"IntuneManagementExtension-????????-??????.log",
"AppWorkload.log",
"AppWorkload-????????-??????.log",
"AppActionProcessor.log",
"AppActionProcessor-????????-??????.log",
"AgentExecutor.log",
"AgentExecutor-????????-??????.log",
"HealthScripts.log",
@@ -171,7 +171,7 @@ public class BuiltInRulesTests
"updateStatePostponed", "espPhaseDetected", "imeStarted",
"policiesDiscovered", "ignoreCompletedApp", "imeAgentVersion",
"espTrackStatus", "updateName", "updateWin32AppState",
"cancelStuckAndSetCurrent", "imeSessionChange", "imeImpersonation",
"cancelStuckAndSetCurrent", "imeSessionChange", "imeImpersonation", "imeTokenFailure",
"enrollmentCompleted", "updateDoTelemetry", "scriptStarted",
"scriptContext", "scriptExitCode", "scriptOutput", "scriptCompleted",
"resetPlatformScriptContext",
@@ -146,6 +146,7 @@ export const EVENT_TYPES_CATALOG = {
'agent_shutdown',
'agent_version_check',
'ime_agent_version',
'ime_token_failure',
'ime_user_session_completed',
'ime_session_change',
'ime_process_exited',
@@ -416,6 +416,7 @@ namespace AutopilotMonitor.Shared
// IME log tracker — app / device / script telemetry (V2 single-rail plan §5.9)
public const string EspPhaseChanged = "esp_phase_changed";
public const string ImeAgentVersion = "ime_agent_version";
public const string ImeTokenFailure = "ime_token_failure"; // Warning, once per distinct errorCode: IME token acquisition failed (IntuneTokenManager "Failed to get AAD token ... errorCode = N"). Complements IME-TOKEN-SUCCESS: an auth outage previously left every check-in silently doing nothing with no timeline evidence.
public const string ImeUserSessionCompleted = "ime_user_session_completed";
public const string DoTelemetry = "do_telemetry";
public const string AllAppsCompleted = "all_apps_completed";
@@ -559,6 +559,7 @@ export const SHARED_MANIFEST = {
"ime_agent_version",
"ime_process_exited",
"ime_session_change",
"ime_token_failure",
"ime_user_session_completed",
"ingress_backpressure",
"integrity_bypass_analysis",
@@ -555,6 +555,7 @@
"ime_agent_version",
"ime_process_exited",
"ime_session_change",
"ime_token_failure",
"ime_user_session_completed",
"ingress_backpressure",
"integrity_bypass_analysis",