diff --git a/rules/analyze/ANALYZE-APP-014.json b/rules/analyze/ANALYZE-APP-014.json new file mode 100644 index 00000000..b8dec6f9 --- /dev/null +++ b/rules/analyze/ANALYZE-APP-014.json @@ -0,0 +1,72 @@ +{ + "$schema": "../schema/analyze-rule.schema.json", + "ruleId": "ANALYZE-APP-014", + "title": "MSIX/Store App Failure During ESP (AppX Deployment)", + "description": "Detects when the Enrollment Status Page failed on the Apps subcategory and the agent's AppX deployment log scan identified a suspected MSIX/Store package. Store/MSIX apps install outside the Win32 pipeline, so the regular per-app tracking sees nothing — this correlation names the likely culprit.", + "severity": "warning", + "category": "apps", + "version": "1.0.0", + "enabled": true, + "baseConfidence": 75, + "preconditions": [ + { + "source": "event_data", + "eventType": "esp_appx_failure_analysis", + "dataField": "verdict", + "operator": "equals", + "value": "appx_candidate_identified", + "description": "Scope this rule to sessions where the settle-window AppX scan found a package whose deployment error matches the ESP failure HRESULT. Weaker verdicts (appx_activity_no_hresult_match, no_appx_candidates) intentionally do not fire this rule — they carry too little signal for an admin-facing finding." + } + ], + "conditions": [ + { + "signal": "appx_candidate", + "source": "event_type", + "eventType": "esp_appx_failure_analysis", + "dataField": "topCandidatePackageName", + "operator": "exists", + "required": true + }, + { + "signal": "esp_appx_family_errorcode", + "source": "event_type", + "eventType": "esp_failure_settle_started", + "dataField": "errorCode", + "operator": "regex", + "value": "^0x80073[cd]", + "required": false + } + ], + "explanation": "The ESP **{{espCategory}}/Apps** subcategory failed with HRESULT **{{espErrorCode}}** — an error from the AppX/MSIX deployment stack, i.e. a **Microsoft Store / MSIX app**, not a Win32 app. These apps install via the EnterpriseModernAppManagement CSP and never appear in the IME Win32 sidecar logs, which is why all tracked Win32/WinGet apps in this session can look green while ESP still reports an Apps failure.\n\nThe agent scanned the AppXDeploymentServer event log during the failure settle window and identified **{{topCandidatePackageName}}** (package `{{topCandidatePackage}}`) as the most likely culprit — its deployment error matches the ESP failure code ({{candidateCount}} candidate(s) total, confidence: {{confidence}}).\n\n**This is a correlation-based assessment, not a confirmed root cause** — validate against the AppXDeploymentServer/Operational event log on the device or in the diagnostics archive before acting.", + "remediation": [ + { + "title": "Confirm the failing package", + "steps": [ + "Open Event Viewer → Applications and Services Logs → Microsoft → Windows → AppXDeploymentServer → Operational on the device (or in the diagnostics archive if uploaded)", + "Filter for Error-level events around the ESP failure time and confirm the package name and HRESULT match this finding", + "Look up the HRESULT: 0x80073cf9 = generic install failure, 0x80073cf0 = invalid/corrupt package, 0x80073cff = sideloading/licensing policy block, 0x80073d02 = blocked because app is in use" + ] + }, + { + "title": "Check Store app assignment and licensing", + "steps": [ + "Intune portal → Apps → check the assignment of the suspected app: device context vs user context — user-context Store apps installing during Account Setup ESP are a common failure source", + "Verify the app's license type (online vs offline): online-licensed Store apps require the user's Entra ID token and Store connectivity during ESP", + "Check whether the Microsoft Store endpoints are reachable from the enrollment network (proxy/firewall allowlists)", + "If the app is not business-critical during provisioning: remove it from the ESP blocking-app list so a failure no longer terminates enrollment" + ] + }, + { + "title": "Consider repackaging", + "steps": [ + "For maximum ESP reliability, wrap the app as a Win32 (.intunewin) deployment instead of a Store/MSIX assignment — Win32 installs are fully tracked and produce per-app failure telemetry", + "Alternatively deploy the app post-enrollment (available, not required) so it cannot block the ESP" + ] + } + ], + "relatedDocs": [ + { "title": "Microsoft Learn: Troubleshoot Windows Autopilot ESP error codes", "url": "https://learn.microsoft.com/en-us/autopilot/troubleshoot-tsg" }, + { "title": "Add Microsoft Store apps to Intune", "url": "https://learn.microsoft.com/en-us/mem/intune/apps/store-apps-microsoft" } + ], + "tags": ["apps", "appx", "msix", "store", "esp", "0x80073cf9"] +} diff --git a/rules/dist/analyze-rules.json b/rules/dist/analyze-rules.json index 1dbd44c8..271a5f66 100644 --- a/rules/dist/analyze-rules.json +++ b/rules/dist/analyze-rules.json @@ -553,6 +553,90 @@ "intune" ] }, + { + "ruleId": "ANALYZE-APP-014", + "title": "MSIX/Store App Failure During ESP (AppX Deployment)", + "description": "Detects when the Enrollment Status Page failed on the Apps subcategory and the agent's AppX deployment log scan identified a suspected MSIX/Store package. Store/MSIX apps install outside the Win32 pipeline, so the regular per-app tracking sees nothing — this correlation names the likely culprit.", + "severity": "warning", + "category": "apps", + "version": "1.0.0", + "enabled": true, + "baseConfidence": 75, + "preconditions": [ + { + "source": "event_data", + "eventType": "esp_appx_failure_analysis", + "dataField": "verdict", + "operator": "equals", + "value": "appx_candidate_identified", + "description": "Scope this rule to sessions where the settle-window AppX scan found a package whose deployment error matches the ESP failure HRESULT. Weaker verdicts (appx_activity_no_hresult_match, no_appx_candidates) intentionally do not fire this rule — they carry too little signal for an admin-facing finding." + } + ], + "conditions": [ + { + "signal": "appx_candidate", + "source": "event_type", + "eventType": "esp_appx_failure_analysis", + "dataField": "topCandidatePackageName", + "operator": "exists", + "required": true + }, + { + "signal": "esp_appx_family_errorcode", + "source": "event_type", + "eventType": "esp_failure_settle_started", + "dataField": "errorCode", + "operator": "regex", + "value": "^0x80073[cd]", + "required": false + } + ], + "explanation": "The ESP **{{espCategory}}/Apps** subcategory failed with HRESULT **{{espErrorCode}}** — an error from the AppX/MSIX deployment stack, i.e. a **Microsoft Store / MSIX app**, not a Win32 app. These apps install via the EnterpriseModernAppManagement CSP and never appear in the IME Win32 sidecar logs, which is why all tracked Win32/WinGet apps in this session can look green while ESP still reports an Apps failure.\n\nThe agent scanned the AppXDeploymentServer event log during the failure settle window and identified **{{topCandidatePackageName}}** (package `{{topCandidatePackage}}`) as the most likely culprit — its deployment error matches the ESP failure code ({{candidateCount}} candidate(s) total, confidence: {{confidence}}).\n\n**This is a correlation-based assessment, not a confirmed root cause** — validate against the AppXDeploymentServer/Operational event log on the device or in the diagnostics archive before acting.", + "remediation": [ + { + "title": "Confirm the failing package", + "steps": [ + "Open Event Viewer → Applications and Services Logs → Microsoft → Windows → AppXDeploymentServer → Operational on the device (or in the diagnostics archive if uploaded)", + "Filter for Error-level events around the ESP failure time and confirm the package name and HRESULT match this finding", + "Look up the HRESULT: 0x80073cf9 = generic install failure, 0x80073cf0 = invalid/corrupt package, 0x80073cff = sideloading/licensing policy block, 0x80073d02 = blocked because app is in use" + ] + }, + { + "title": "Check Store app assignment and licensing", + "steps": [ + "Intune portal → Apps → check the assignment of the suspected app: device context vs user context — user-context Store apps installing during Account Setup ESP are a common failure source", + "Verify the app's license type (online vs offline): online-licensed Store apps require the user's Entra ID token and Store connectivity during ESP", + "Check whether the Microsoft Store endpoints are reachable from the enrollment network (proxy/firewall allowlists)", + "If the app is not business-critical during provisioning: remove it from the ESP blocking-app list so a failure no longer terminates enrollment" + ] + }, + { + "title": "Consider repackaging", + "steps": [ + "For maximum ESP reliability, wrap the app as a Win32 (.intunewin) deployment instead of a Store/MSIX assignment — Win32 installs are fully tracked and produce per-app failure telemetry", + "Alternatively deploy the app post-enrollment (available, not required) so it cannot block the ESP" + ] + } + ], + "relatedDocs": [ + { + "title": "Microsoft Learn: Troubleshoot Windows Autopilot ESP error codes", + "url": "https://learn.microsoft.com/en-us/autopilot/troubleshoot-tsg" + }, + { + "title": "Add Microsoft Store apps to Intune", + "url": "https://learn.microsoft.com/en-us/mem/intune/apps/store-apps-microsoft" + } + ], + "tags": [ + "apps", + "appx", + "msix", + "store", + "esp", + "0x80073cf9" + ] + }, { "ruleId": "ANALYZE-CORR-003", "title": "Proxy Configuration Causing Download Failure", diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureAnalyzerTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureAnalyzerTests.cs new file mode 100644 index 00000000..fa5e5c88 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureAnalyzerTests.cs @@ -0,0 +1,264 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals +{ + /// + /// Pure scoring/verdict coverage for the session-2bc884b6 AppX enrichment. No event log, + /// no tracker — records go in, scored candidates and an honest verdict come out. + /// + public sealed class AppxFailureAnalyzerTests + { + private static readonly DateTime FailureAt = new DateTime(2026, 7, 9, 12, 48, 57, DateTimeKind.Utc); + private static readonly DateTime WindowStart = FailureAt.AddMinutes(-30); + + private const string PkgA = "Contoso.LineOfBusiness_1.2.3.4_x64__8wekyb3d8bbwe"; + private const string PkgB = "Fabrikam.Tools_2.0.0.0_neutral__abcdefghjkmnp"; + + private static AppxFailureScanRequest Request(string? espErrorCode = "0x80073cf9") + => new AppxFailureScanRequest(WindowStart, FailureAt, espErrorCode, "AccountSetup", "Apps"); + + private static AppxLogRecord Record( + string? message, + DateTime? timeUtc = null, + int eventId = 401, + params string[] properties) + { + return new AppxLogRecord + { + TimeCreatedUtc = timeUtc ?? FailureAt.AddMinutes(-1), + EventId = eventId, + Level = 2, + Message = message, + PropertyStrings = properties.ToList() + }; + } + + private static AppxFailureScanResult ScanWith(params AppxLogRecord[] records) + => new AppxFailureScanResult { Records = records.ToList() }; + + // ------------------------------------------------------------------ + // Scoring + // ------------------------------------------------------------------ + + [Fact] + public void HresultMatch_OutranksTimeProximity() + { + // PkgB failed earlier with the exact ESP HRESULT; PkgA has a recent error without one. + var scan = ScanWith( + Record($"Deployment of package {PkgA} was blocked.", FailureAt.AddMinutes(-1)), + Record($"Deployment operation on {PkgB} failed with error 0x80073CF9.", FailureAt.AddMinutes(-20))); + + var analysis = AppxFailureAnalyzer.Analyze(Request(), scan); + + Assert.Equal(PkgB, analysis.Candidates[0].PackageFullName); + Assert.Equal(AppxFailureAnalyzer.MatchTypeHresultMatch, analysis.Candidates[0].MatchType); + Assert.Equal(AppxFailureAnalyzer.MatchTypeTimeProximity, analysis.Candidates[1].MatchType); + Assert.True(analysis.Candidates[0].Score > analysis.Candidates[1].Score); + } + + [Fact] + public void RecencyBonus_AppliedWithinTenMinutesOfFailure() + { + var recent = ScanWith(Record($"error 0x80073cf9 for {PkgA}", FailureAt.AddMinutes(-2))); + var old = ScanWith(Record($"error 0x80073cf9 for {PkgA}", FailureAt.AddMinutes(-25))); + + var recentScore = AppxFailureAnalyzer.Analyze(Request(), recent).Candidates[0].Score; + var oldScore = AppxFailureAnalyzer.Analyze(Request(), old).Candidates[0].Score; + + Assert.Equal(AppxFailureAnalyzer.ScoreHresultMatch + AppxFailureAnalyzer.ScoreRecencyBonus, recentScore); + Assert.Equal(AppxFailureAnalyzer.ScoreHresultMatch, oldScore); + } + + // ------------------------------------------------------------------ + // Extraction + // ------------------------------------------------------------------ + + [Fact] + public void PackageExtraction_FromMessage() + { + var packages = AppxFailureAnalyzer.ExtractPackageFullNames( + Record($"AppX Deployment operation failed for package {PkgA} with error 0x80073CF9.")); + Assert.Equal(new[] { PkgA }, packages); + } + + [Fact] + public void PackageExtraction_FromProperties_WhenFormatDescriptionFailed() + { + // Under SYSTEM/OOBE FormatDescription often throws → Message null; the raw event + // properties still carry the PackageFullName. + var record = Record(message: null, properties: new[] { PkgB, "some other property" }); + var packages = AppxFailureAnalyzer.ExtractPackageFullNames(record); + Assert.Equal(new[] { PkgB }, packages); + } + + [Fact] + public void NegativeDecimalProperty_ConvertsToHresult() + { + // -2147009287 == unchecked((int)0x80073CF9) — the form event properties use. + var record = Record(message: null, properties: new[] { "-2147009287" }); + var hresults = AppxFailureAnalyzer.ExtractHresults(record); + Assert.Equal(new[] { "0x80073cf9" }, hresults); + } + + [Fact] + public void HresultExtraction_NormalizesToLowercase_AndDedupes() + { + var record = Record($"error 0x80073CF9 then again 0x80073cf9", properties: new[] { "-2147009287" }); + var hresults = AppxFailureAnalyzer.ExtractHresults(record); + Assert.Equal(new[] { "0x80073cf9" }, hresults); + } + + // ------------------------------------------------------------------ + // Aggregation + // ------------------------------------------------------------------ + + [Fact] + public void PerPackageDedupe_CountsOccurrences_KeepsLatestTimestamp() + { + var scan = ScanWith( + Record($"retry 1 failed for {PkgA} 0x80073cf9", FailureAt.AddMinutes(-9)), + Record($"retry 2 failed for {PkgA} 0x80073cf9", FailureAt.AddMinutes(-5)), + Record($"retry 3 failed for {PkgA} 0x80073cf9", FailureAt.AddMinutes(-7))); + + var analysis = AppxFailureAnalyzer.Analyze(Request(), scan); + + var candidate = Assert.Single(analysis.Candidates); + Assert.Equal(3, candidate.Occurrences); + Assert.Equal(FailureAt.AddMinutes(-5), candidate.TimeUtc); + Assert.Equal(1, analysis.TotalCandidateCount); + } + + [Fact] + public void CandidatesCappedAtFive_TotalCountPreserved() + { + var records = Enumerable.Range(1, 7) + .Select(i => Record($"failed Vendor{i}.App{i}_1.0.0.{i}_x64__8wekyb3d8bbwe with 0x80073cf9")) + .ToArray(); + + var analysis = AppxFailureAnalyzer.Analyze(Request(), ScanWith(records)); + + Assert.Equal(AppxFailureAnalyzer.MaxCandidatesInPayload, analysis.Candidates.Count); + Assert.Equal(7, analysis.TotalCandidateCount); + } + + [Fact] + public void MessageExcerpt_Truncated_AndNewlinesFlattened() + { + var longMessage = $"failure of {PkgA}\r\nline2 " + new string('x', 500); + var analysis = AppxFailureAnalyzer.Analyze(Request(null), ScanWith(Record(longMessage))); + + var excerpt = analysis.Candidates[0].MessageExcerpt; + Assert.Equal(AppxFailureAnalyzer.MessageExcerptLength, excerpt.Length); + Assert.DoesNotContain("\n", excerpt); + } + + // ------------------------------------------------------------------ + // Verdicts / confidence + // ------------------------------------------------------------------ + + [Fact] + public void Verdict_CandidateIdentified_HighConfidence_WhenEspCodeIsAppxFamily() + { + var analysis = AppxFailureAnalyzer.Analyze( + Request("0x80073cf9"), + ScanWith(Record($"deployment of {PkgA} failed with 0x80073CF9"))); + + Assert.Equal(AppxFailureAnalyzer.VerdictCandidateIdentified, analysis.Verdict); + Assert.Equal("high", analysis.Confidence); + } + + [Fact] + public void Verdict_CandidateIdentified_MediumConfidence_WhenEspCodeNotAppxFamily() + { + var analysis = AppxFailureAnalyzer.Analyze( + Request("0x87d1041c"), + ScanWith(Record($"deployment of {PkgA} failed with 0x87d1041c"))); + + Assert.Equal(AppxFailureAnalyzer.VerdictCandidateIdentified, analysis.Verdict); + Assert.Equal("medium", analysis.Confidence); + } + + [Fact] + public void Verdict_ActivityNoHresultMatch_WhenErrorsDontMatchEspCode() + { + var analysis = AppxFailureAnalyzer.Analyze( + Request("0x80073cf9"), + ScanWith(Record($"deployment of {PkgA} failed with 0x80073d02"))); + + Assert.Equal(AppxFailureAnalyzer.VerdictActivityNoHresultMatch, analysis.Verdict); + Assert.Equal("low", analysis.Confidence); + Assert.Contains("0x80073d02", analysis.OtherHresultsSeen); + } + + [Fact] + public void Verdict_ActivityNoHresultMatch_MediumConfidence_WhenEspCodeNull_AndFamilyErrorsSeen() + { + var analysis = AppxFailureAnalyzer.Analyze( + Request(espErrorCode: null), + ScanWith(Record($"deployment of {PkgA} failed with 0x80073cff"))); + + Assert.Equal(AppxFailureAnalyzer.VerdictActivityNoHresultMatch, analysis.Verdict); + Assert.Equal("medium", analysis.Confidence); + } + + [Fact] + public void Verdict_ErrorsNoPackage_WhenHresultsButNoPackageName() + { + var analysis = AppxFailureAnalyzer.Analyze( + Request(), + ScanWith(Record("operation failed with 0x80073cf9 (no package in text)"))); + + Assert.Equal(AppxFailureAnalyzer.VerdictErrorsNoPackage, analysis.Verdict); + Assert.Empty(analysis.Candidates); + } + + [Fact] + public void Verdict_NoCandidates_WhenWindowEmpty() + { + var analysis = AppxFailureAnalyzer.Analyze(Request(), ScanWith()); + + Assert.Equal(AppxFailureAnalyzer.VerdictNoCandidates, analysis.Verdict); + Assert.Equal("medium", analysis.Confidence); + Assert.Equal(0, analysis.ErrorEventCount); + } + + [Fact] + public void Verdict_NoCandidates_LowConfidence_WhenScanTruncated() + { + var scan = ScanWith(); + scan.Truncated = true; + var analysis = AppxFailureAnalyzer.Analyze(Request(), scan); + + Assert.Equal(AppxFailureAnalyzer.VerdictNoCandidates, analysis.Verdict); + Assert.Equal("low", analysis.Confidence); + } + + [Fact] + public void Verdict_ScanUnavailable_WhenChannelMissing() + { + var scan = new AppxFailureScanResult { ChannelAvailable = false, UnavailableReason = "channel_not_found" }; + var analysis = AppxFailureAnalyzer.Analyze(Request(), scan); + + Assert.Equal(AppxFailureAnalyzer.VerdictScanUnavailable, analysis.Verdict); + Assert.Equal("channel_not_found", analysis.ScanUnavailableReason); + } + + [Theory] + [InlineData("0x80073cf9", true)] + [InlineData("0x80073CF0", true)] + [InlineData("0x80073d02", true)] + [InlineData("0x87d1041c", false)] + [InlineData("0x80070002", false)] + [InlineData(null, false)] + [InlineData("", false)] + [InlineData("0x8007", false)] + public void IsAppxFamilyHresult_MatchesOnlyAppxDeploymentRange(string hresult, bool expected) + { + Assert.Equal(expected, AppxFailureAnalyzer.IsAppxFamilyHresult(hresult)); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureScanTriggerTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureScanTriggerTests.cs new file mode 100644 index 00000000..77d3248a --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/AppxFailureScanTriggerTests.cs @@ -0,0 +1,251 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals +{ + /// + /// Test double for the settle-window AppX enrichment scan. Returns a canned result and + /// records every request — tests never touch the real event log (project rule: mock ALL + /// system calls). + /// + internal sealed class FakeAppxDeploymentFailureScanner : IAppxDeploymentFailureScanner + { + public AppxFailureScanResult Result { get; set; } = new AppxFailureScanResult(); + public Exception? ThrowOnScan { get; set; } + public List Requests { get; } = new List(); + + public AppxFailureScanResult Scan(AppxFailureScanRequest request) + { + Requests.Add(request); + if (ThrowOnScan != null) throw ThrowOnScan; + return Result; + } + } + + /// + /// Session 2bc884b6 coverage: an ESP Apps-subcategory failure (e.g. 0x80073cf9 from an + /// MSIX/Store app invisible to ImeLogTracker) must trigger exactly one AppX event-log scan + /// inside the settle window and emit esp_appx_failure_analysis with flat RuleEngine + /// fields — without disturbing the settle window's own EspFailureDetected flow. + /// + public sealed class AppxFailureScanTriggerTests + { + private static readonly DateTime Fixed = new DateTime(2026, 7, 9, 12, 48, 57, DateTimeKind.Utc); + + private const string InProgressJson = @"{ + ""categorySucceeded"": null, + ""AppsSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Apps (Working)""} + }"; + private const string AppsFailedJson = @"{ + ""categorySucceeded"": null, + ""AppsSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Apps (0x80073cf9)""} + }"; + + private sealed class Fixture : IDisposable + { + public TempDirectory Tmp { get; } = new TempDirectory(); + public FakeSignalIngressSink Sink { get; } = new FakeSignalIngressSink(); + public FakeAppxDeploymentFailureScanner Scanner { get; } = new FakeAppxDeploymentFailureScanner(); + public List EspFailures { get; } = new List(); + public ProvisioningStatusTracker Tracker { get; } + + public Fixture() + { + var clock = new VirtualClock(Fixed); + var post = new InformationalEventPost(Sink, clock); + var logger = new AgentLogger(Tmp.Path, AgentLogLevel.Info); + Tracker = new ProvisioningStatusTracker( + sessionId: "S1", + tenantId: "T1", + post: post, + logger: logger, + appxScanner: Scanner, + backgroundDispatcher: action => action()); // synchronous — deterministic tests + Tracker.EspFailureDetected += (_, args) => EspFailures.Add(args); + } + + public IReadOnlyList<(string EventType, string Severity, IReadOnlyDictionary Data)> CapturedEvents() + { + return Sink.Posted + .Where(p => p.Kind == DecisionSignalKind.InformationalEvent && p.Payload != null) + .Select(p => + { + var eventType = p.Payload!.TryGetValue(SignalPayloadKeys.EventType, out var et) ? et : ""; + var severity = p.Payload!.TryGetValue(SignalPayloadKeys.Severity, out var sev) ? sev : ""; + var data = p.TypedPayload as IReadOnlyDictionary + ?? (IReadOnlyDictionary)new Dictionary(); + return (eventType, severity, data); + }) + .ToList(); + } + + public (string EventType, string Severity, IReadOnlyDictionary Data) AnalysisEvent() + => CapturedEvents().SingleOrDefault(e => e.EventType == "esp_appx_failure_analysis"); + + public void Dispose() + { + Tracker.Dispose(); + Tmp.Dispose(); + } + } + + private static AppxLogRecord FailedPackageRecord(string packageFullName, string hresult) + => new AppxLogRecord + { + TimeCreatedUtc = Fixed.AddMinutes(-2), + EventId = 401, + Level = 2, + Message = $"Deployment operation on {packageFullName} failed with error {hresult}.", + }; + + [Fact] + public void AppsFailure_TriggersScan_WithEspContext_AndEmitsFlatFields() + { + using var f = new Fixture(); + f.Scanner.Result = new AppxFailureScanResult + { + Records = { FailedPackageRecord("Contoso.LineOfBusiness_1.2.3.4_x64__8wekyb3d8bbwe", "0x80073CF9") }, + ScanDurationMs = 42 + }; + + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", AppsFailedJson); + + var request = Assert.Single(f.Scanner.Requests); + Assert.Equal("0x80073cf9", request.EspErrorCode); + Assert.Equal("AccountSetup", request.EspCategory); + Assert.Equal("Apps", request.FailedSubcategory); + Assert.True(request.WindowStartUtc < request.WindowEndUtc); + + var analysis = f.AnalysisEvent(); + Assert.NotEqual(default, analysis); + Assert.Equal("Warning", analysis.Severity); + Assert.Equal("appx_candidate_identified", (string)analysis.Data["verdict"]); + Assert.Equal("high", (string)analysis.Data["confidence"]); + Assert.Equal("0x80073cf9", (string)analysis.Data["espErrorCode"]); + Assert.Equal("AccountSetup", (string)analysis.Data["espCategory"]); + Assert.Equal("Contoso.LineOfBusiness_1.2.3.4_x64__8wekyb3d8bbwe", (string)analysis.Data["topCandidatePackage"]); + Assert.Equal("Contoso.LineOfBusiness", (string)analysis.Data["topCandidatePackageName"]); + Assert.Equal("0x80073cf9", (string)analysis.Data["topCandidateHresult"]); + Assert.Equal("hresult_match", (string)analysis.Data["topCandidateMatchType"]); + Assert.Equal(1, (int)analysis.Data["candidateCount"]); + Assert.True(analysis.Data.ContainsKey("candidates")); + } + + [Fact] + public void EnrichmentPrecedesSettleExpiry_AndSettleStillFires() + { + using var f = new Fixture(); + + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", AppsFailedJson); + + // Analysis event is already emitted while the settle window is still pending. + Assert.NotEqual(default, f.AnalysisEvent()); + Assert.Empty(f.EspFailures); + + f.Tracker.TriggerSettleTimerForTest("AccountSetupCategory.Status"); + + var fired = Assert.Single(f.EspFailures); + Assert.Equal("Provisioning_AccountSetup_Apps_Failed", fired.FailureType); + Assert.Equal("0x80073cf9", fired.ErrorCode); + } + + [Fact] + public void NonAppsFailure_DoesNotScan() + { + using var f = new Fixture(); + + f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{ + ""categorySucceeded"": null, + ""SecurityPoliciesSubcategory"": {""subcategoryState"":""inProgress"",""subcategoryStatusText"":""Working""} + }"); + f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", @"{ + ""categorySucceeded"": null, + ""SecurityPoliciesSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Failed (0x800705b4)""} + }"); + + Assert.Empty(f.Scanner.Requests); + Assert.Equal(default, f.AnalysisEvent()); + } + + [Fact] + public void SecondAppsFailure_InOtherCategory_DoesNotRescan() + { + using var f = new Fixture(); + + f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("DeviceSetupCategory.Status", AppsFailedJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", AppsFailedJson); + + // Both categories arm their own settle window, but the scan is fire-once. + Assert.Single(f.Scanner.Requests); + Assert.Equal("DeviceSetup", f.Scanner.Requests[0].EspCategory); + } + + [Fact] + public void ScannerThrows_EmitsCollectorDegraded_SettleWindowUnaffected() + { + using var f = new Fixture(); + f.Scanner.ThrowOnScan = new InvalidOperationException("boom"); + + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", AppsFailedJson); + + var degraded = f.CapturedEvents().SingleOrDefault(e => e.EventType == "collector_degraded"); + Assert.NotEqual(default, degraded); + Assert.Equal("AppxDeploymentFailureScanner", (string)degraded.Data["collector"]); + Assert.Equal("scan_failed", (string)degraded.Data["reason"]); + Assert.Equal(default, f.AnalysisEvent()); + + f.Tracker.TriggerSettleTimerForTest("AccountSetupCategory.Status"); + Assert.Single(f.EspFailures); + } + + [Fact] + public void NoCandidates_EmitsInfoVerdict_NegativeEvidence() + { + using var f = new Fixture(); + // Empty scan result — no AppX errors in the window. + + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", AppsFailedJson); + + var analysis = f.AnalysisEvent(); + Assert.NotEqual(default, analysis); + Assert.Equal("Info", analysis.Severity); + Assert.Equal("no_appx_candidates", (string)analysis.Data["verdict"]); + Assert.Equal(0, (int)analysis.Data["candidateCount"]); + Assert.False(analysis.Data.ContainsKey("topCandidatePackage")); + } + + [Fact] + public void AppsFailureWithoutHresult_OmitsEspErrorCodeKey() + { + using var f = new Fixture(); + + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", InProgressJson); + f.Tracker.ProcessCategoryStatusForTest("AccountSetupCategory.Status", @"{ + ""categorySucceeded"": null, + ""AppsSubcategory"": {""subcategoryState"":""failed"",""subcategoryStatusText"":""Apps (Error)""} + }"); + + var request = Assert.Single(f.Scanner.Requests); + Assert.Null(request.EspErrorCode); + + var analysis = f.AnalysisEvent(); + Assert.NotEqual(default, analysis); + Assert.False(analysis.Data.ContainsKey("espErrorCode")); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ProvisioningFailureSettleWindowTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ProvisioningFailureSettleWindowTests.cs index f005affb..008bf961 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ProvisioningFailureSettleWindowTests.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ProvisioningFailureSettleWindowTests.cs @@ -48,7 +48,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals sessionId: "S1", tenantId: "T1", post: post, - logger: logger); + logger: logger, + // Fake scanner + synchronous dispatcher: the Apps-failure tests below arm the + // settle window, which triggers the AppX enrichment scan — the default seams + // would hit the real event log via Task.Run (mock ALL system calls). + appxScanner: new FakeAppxDeploymentFailureScanner(), + backgroundDispatcher: action => action()); Tracker.EspFailureDetected += (_, args) => EspFailures.Add(args); } diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxDeploymentFailureScanner.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxDeploymentFailureScanner.cs new file mode 100644 index 00000000..de8acaad --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxDeploymentFailureScanner.cs @@ -0,0 +1,164 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.Eventing.Reader; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals +{ + /// + /// Scan request for . Immutable snapshot of the + /// ESP failure context — the scan body runs on the threadpool and must not touch tracker state. + /// + internal sealed class AppxFailureScanRequest + { + /// Earliest TimeCreated to consider (monitoring start, capped lookback). + public DateTime WindowStartUtc { get; } + /// Time of the ESP failure observation (recency-bonus anchor). + public DateTime WindowEndUtc { get; } + /// ESP subcategory HRESULT (lower-case 0x-hex) or null. + public string EspErrorCode { get; } + /// ESP category label (DeviceSetup / AccountSetup). + public string EspCategory { get; } + /// Failed subcategory name (always "Apps" for this scan). + public string FailedSubcategory { get; } + + public AppxFailureScanRequest( + DateTime windowStartUtc, + DateTime windowEndUtc, + string espErrorCode, + string espCategory, + string failedSubcategory) + { + WindowStartUtc = windowStartUtc; + WindowEndUtc = windowEndUtc; + EspErrorCode = string.IsNullOrEmpty(espErrorCode) ? null : espErrorCode; + EspCategory = string.IsNullOrEmpty(espCategory) ? null : espCategory; + FailedSubcategory = string.IsNullOrEmpty(failedSubcategory) ? null : failedSubcategory; + } + } + + /// + /// One raw record read from the AppX deployment event log channel. Message and property + /// strings are both captured because FormatDescription() is unreliable under + /// SYSTEM/OOBE (missing message resources) while record.Properties usually still + /// carries the bare PackageFullName and error values. + /// + internal sealed class AppxLogRecord + { + public DateTime TimeCreatedUtc { get; set; } + public int EventId { get; set; } + public int Level { get; set; } + /// Rendered message, or null when FormatDescription failed. + public string Message { get; set; } + /// Raw event properties as strings (may be empty, never null). + public List PropertyStrings { get; set; } = new List(); + } + + /// Raw scan outcome — records plus availability/diagnostic info. + internal sealed class AppxFailureScanResult + { + /// False when the channel is missing or unreadable (scan_unavailable verdict). + public bool ChannelAvailable { get; set; } = true; + /// Short machine-readable reason when is false. + public string UnavailableReason { get; set; } + public List Records { get; set; } = new List(); + public long ScanDurationMs { get; set; } + /// True when the record/time cap stopped the scan before the window was exhausted. + public bool Truncated { get; set; } + } + + /// + /// Seam for the settle-window AppX enrichment scan — tests inject a fake; production uses + /// . + /// + internal interface IAppxDeploymentFailureScanner + { + AppxFailureScanResult Scan(AppxFailureScanRequest request); + } + + /// + /// One-shot reader of Microsoft-Windows-AppXDeploymentServer/Operational — the channel + /// where MSIX/Store deployment failures land. Those installs run outside the IME Win32 + /// pipeline, so ImeLogTracker never sees them; when ESP reports an Apps-subcategory failure + /// with an AppX-class HRESULT (e.g. 0x80073cf9) this scan is the only session-local source + /// that can name the failing package (session 2bc884b6). + /// Query pattern follows : XPath time+level filter, + /// ReverseDirection (newest first), hard record + wall-clock caps, per-record dispose. + /// + internal sealed class AppxDeploymentFailureScanner : IAppxDeploymentFailureScanner + { + internal const string Channel = "Microsoft-Windows-AppXDeploymentServer/Operational"; + // Critical (1) + Error (2) only — Warning-level entries in this channel are routine + // servicing noise and would drown the correlation. + internal const int MaxRecords = 200; + internal const int MaxScanMilliseconds = 10000; + + public AppxFailureScanResult Scan(AppxFailureScanRequest request) + { + var result = new AppxFailureScanResult(); + var stopwatch = Stopwatch.StartNew(); + + var sinceStr = request.WindowStartUtc.ToString("yyyy-MM-ddTHH:mm:ss.fffZ"); + var xpath = $"*[System[(Level >= 1 and Level <= 2) and TimeCreated[@SystemTime >= '{sinceStr}']]]"; + + try + { + var query = new EventLogQuery(Channel, PathType.LogName, xpath) { ReverseDirection = true }; + using (var reader = new EventLogReader(query)) + { + EventRecord record; + while ((record = reader.ReadEvent()) != null) + { + using (record) + { + if (result.Records.Count >= MaxRecords || stopwatch.ElapsedMilliseconds > MaxScanMilliseconds) + { + result.Truncated = true; + break; + } + + var entry = new AppxLogRecord + { + TimeCreatedUtc = record.TimeCreated?.ToUniversalTime() ?? DateTime.MinValue, + EventId = record.Id, + Level = record.Level ?? 0, + }; + + // FormatDescription can throw under SYSTEM/OOBE (message resources + // not loadable) — the Properties fallback below is mandatory. + try { entry.Message = record.FormatDescription(); } + catch { entry.Message = null; } + + try + { + foreach (var prop in record.Properties) + { + var s = prop?.Value?.ToString(); + if (!string.IsNullOrEmpty(s)) + entry.PropertyStrings.Add(s); + } + } + catch { /* best-effort — keep whatever was collected */ } + + result.Records.Add(entry); + } + } + } + } + catch (EventLogNotFoundException) + { + result.ChannelAvailable = false; + result.UnavailableReason = "channel_not_found"; + } + catch (UnauthorizedAccessException) + { + result.ChannelAvailable = false; + result.UnavailableReason = "access_denied"; + } + + stopwatch.Stop(); + result.ScanDurationMs = stopwatch.ElapsedMilliseconds; + return result; + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxFailureAnalyzer.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxFailureAnalyzer.cs new file mode 100644 index 00000000..032340e5 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/AppxFailureAnalyzer.cs @@ -0,0 +1,308 @@ +using System; +using System.Collections.Generic; +using System.Globalization; +using System.Linq; +using System.Text.RegularExpressions; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals +{ + /// + /// Aggregated candidate: one MSIX/Store package that failed in the scan window, + /// scored by how strongly its log records correlate with the ESP failure. + /// + internal sealed class AppxFailureCandidate + { + public string PackageFullName { get; set; } + /// Name segment of the PackageFullName (before the first underscore). + public string PackageName { get; set; } + public int Score { get; set; } + /// hresult_match | appx_family_error | time_proximity + public string MatchType { get; set; } + /// Distinct HRESULTs seen for this package (capped). + public List Hresults { get; set; } = new List(); + /// EventId of the best-scoring record. + public int EventId { get; set; } + /// Latest occurrence in the window. + public DateTime TimeUtc { get; set; } + public int Occurrences { get; set; } + /// Truncated message (or property dump) of the best-scoring record. + public string MessageExcerpt { get; set; } + } + + /// Analysis outcome — verdict + scored candidates, ready for event emission. + internal sealed class AppxFailureAnalysis + { + public string Verdict { get; set; } + /// high | medium | low — honesty marker, never certainty. + public string Confidence { get; set; } + /// Sorted descending by score, capped at . + public List Candidates { get; set; } = new List(); + /// Total distinct failing packages before the payload cap. + public int TotalCandidateCount { get; set; } + /// Error/critical records considered in the window. + public int ErrorEventCount { get; set; } + /// HRESULTs seen in the window that differ from the ESP error code (capped). + public List OtherHresultsSeen { get; set; } = new List(); + /// Set when verdict is scan_unavailable. + public string ScanUnavailableReason { get; set; } + } + + /// + /// Pure scoring/verdict logic for the settle-window AppX enrichment — no event log, no + /// tracker state, fully unit-testable. Careful time correlation is the point: the + /// AppXDeploymentServer channel also logs unrelated background servicing failures, so + /// candidates are scored (exact-HRESULT match > AppX-family error > time proximity) + /// and the verdict/confidence express suspicion, not certainty. + /// + internal static class AppxFailureAnalyzer + { + internal const int MaxCandidatesInPayload = 5; + internal const int MaxHresultsPerCandidate = 3; + internal const int MaxOtherHresults = 5; + internal const int MessageExcerptLength = 300; + internal const int RecencyBonusWindowMinutes = 10; + + internal const int ScoreHresultMatch = 100; + internal const int ScoreAppxFamilyError = 70; + internal const int ScoreTimeProximity = 40; + internal const int ScoreRecencyBonus = 10; + + internal const string MatchTypeHresultMatch = "hresult_match"; + internal const string MatchTypeAppxFamilyError = "appx_family_error"; + internal const string MatchTypeTimeProximity = "time_proximity"; + + internal const string VerdictCandidateIdentified = "appx_candidate_identified"; + internal const string VerdictActivityNoHresultMatch = "appx_activity_no_hresult_match"; + internal const string VerdictErrorsNoPackage = "appx_errors_no_package"; + internal const string VerdictNoCandidates = "no_appx_candidates"; + internal const string VerdictScanUnavailable = "scan_unavailable"; + + private static readonly Regex HResultPattern = new Regex( + @"\b0[xX][0-9a-fA-F]{8}\b", + RegexOptions.Compiled | RegexOptions.CultureInvariant); + + // PackageFullName: Name_Version_Arch_ResourceId_PublisherHash. + // Version is dotted-quad; arch is a fixed set; the publisher hash is 13 chars of the + // Crockford-base32 subset Windows uses (no i/l/o/u). ResourceId may be empty. + private static readonly Regex PackageFullNamePattern = new Regex( + @"\b(?[A-Za-z0-9][A-Za-z0-9.\-]{2,})_(?\d+(\.\d+){3})_(?x86|x64|arm|arm64|neutral)_(?[A-Za-z0-9.\-~]*)_(?[a-hjkmnp-tv-z0-9]{13})\b", + RegexOptions.Compiled | RegexOptions.CultureInvariant | RegexOptions.IgnoreCase); + + /// True for HRESULTs in the AppX/MSIX deployment error family (0x80073c##/0x80073d##). + internal static bool IsAppxFamilyHresult(string hresult) + { + if (string.IsNullOrEmpty(hresult) || hresult.Length != 10) return false; + return hresult.StartsWith("0x80073c", StringComparison.OrdinalIgnoreCase) + || hresult.StartsWith("0x80073d", StringComparison.OrdinalIgnoreCase); + } + + public static AppxFailureAnalysis Analyze(AppxFailureScanRequest request, AppxFailureScanResult scan) + { + var analysis = new AppxFailureAnalysis(); + + if (scan == null || !scan.ChannelAvailable) + { + analysis.Verdict = VerdictScanUnavailable; + analysis.Confidence = "low"; + analysis.ScanUnavailableReason = scan?.UnavailableReason ?? "no_result"; + return analysis; + } + + analysis.ErrorEventCount = scan.Records.Count; + + var byPackage = new Dictionary(StringComparer.OrdinalIgnoreCase); + var otherHresults = new List(); + bool anyHresultSeen = false; + + foreach (var record in scan.Records) + { + var hresults = ExtractHresults(record); + var packages = ExtractPackageFullNames(record); + if (hresults.Count > 0) anyHresultSeen = true; + + foreach (var hr in hresults) + { + if (!string.Equals(hr, request.EspErrorCode, StringComparison.OrdinalIgnoreCase) + && !otherHresults.Contains(hr, StringComparer.OrdinalIgnoreCase) + && otherHresults.Count < MaxOtherHresults) + { + otherHresults.Add(hr); + } + } + + if (packages.Count == 0) + continue; + + // Score this record once; every package named in it inherits the score. + string matchType; + int score; + if (request.EspErrorCode != null + && hresults.Any(h => string.Equals(h, request.EspErrorCode, StringComparison.OrdinalIgnoreCase))) + { + matchType = MatchTypeHresultMatch; + score = ScoreHresultMatch; + } + else if (hresults.Any(IsAppxFamilyHresult)) + { + matchType = MatchTypeAppxFamilyError; + score = ScoreAppxFamilyError; + } + else + { + matchType = MatchTypeTimeProximity; + score = ScoreTimeProximity; + } + + if (record.TimeCreatedUtc >= request.WindowEndUtc.AddMinutes(-RecencyBonusWindowMinutes)) + score += ScoreRecencyBonus; + + foreach (var pkg in packages) + { + if (!byPackage.TryGetValue(pkg, out var candidate)) + { + candidate = new AppxFailureCandidate + { + PackageFullName = pkg, + PackageName = pkg.Split('_')[0], + Score = -1, + }; + byPackage[pkg] = candidate; + } + + candidate.Occurrences++; + if (record.TimeCreatedUtc > candidate.TimeUtc) + candidate.TimeUtc = record.TimeCreatedUtc; + foreach (var hr in hresults) + { + if (candidate.Hresults.Count < MaxHresultsPerCandidate + && !candidate.Hresults.Contains(hr, StringComparer.OrdinalIgnoreCase)) + { + candidate.Hresults.Add(hr); + } + } + + if (score > candidate.Score) + { + candidate.Score = score; + candidate.MatchType = matchType; + candidate.EventId = record.EventId; + candidate.MessageExcerpt = BuildExcerpt(record); + } + } + } + + var sorted = byPackage.Values + .OrderByDescending(c => c.Score) + .ThenByDescending(c => c.TimeUtc) + .ToList(); + + analysis.TotalCandidateCount = sorted.Count; + analysis.Candidates = sorted.Take(MaxCandidatesInPayload).ToList(); + analysis.OtherHresultsSeen = otherHresults; + + // Verdict + confidence — suspicion levels, kept honest. + if (analysis.Candidates.Count > 0) + { + var top = analysis.Candidates[0]; + if (top.MatchType == MatchTypeHresultMatch) + { + analysis.Verdict = VerdictCandidateIdentified; + analysis.Confidence = IsAppxFamilyHresult(request.EspErrorCode) ? "high" : "medium"; + } + else + { + analysis.Verdict = VerdictActivityNoHresultMatch; + analysis.Confidence = request.EspErrorCode == null && top.MatchType == MatchTypeAppxFamilyError + ? "medium" + : "low"; + } + } + else if (anyHresultSeen) + { + analysis.Verdict = VerdictErrorsNoPackage; + analysis.Confidence = "low"; + } + else + { + // Negative evidence: no AppX deployment errors in the window → the ESP Apps + // failure most likely came from the Win32/IME pipeline after all. + analysis.Verdict = VerdictNoCandidates; + analysis.Confidence = scan.Truncated ? "low" : "medium"; + } + + return analysis; + } + + /// + /// Extracts normalized HRESULTs (lower-case 0x-hex) from the rendered message and from + /// raw property values, including the negative-decimal form event properties often use + /// (e.g. -2147009543 → 0x80073cf9). + /// + internal static List ExtractHresults(AppxLogRecord record) + { + var result = new List(); + + void AddNormalized(string hex) + { + var normalized = "0x" + hex.Substring(2).ToLowerInvariant(); + if (!result.Contains(normalized, StringComparer.OrdinalIgnoreCase)) + result.Add(normalized); + } + + if (!string.IsNullOrEmpty(record.Message)) + { + foreach (Match m in HResultPattern.Matches(record.Message)) + AddNormalized(m.Value); + } + + foreach (var prop in record.PropertyStrings) + { + foreach (Match m in HResultPattern.Matches(prop)) + AddNormalized(m.Value); + + // Whole-property negative decimal → HRESULT (high bit always set for negatives). + if (prop.Length <= 12 && prop.StartsWith("-", StringComparison.Ordinal) + && int.TryParse(prop, NumberStyles.Integer, CultureInfo.InvariantCulture, out var dec) + && dec < 0) + { + AddNormalized("0x" + ((uint)dec).ToString("x8", CultureInfo.InvariantCulture)); + } + } + + return result; + } + + /// Union of PackageFullNames found in message and property strings. + internal static List ExtractPackageFullNames(AppxLogRecord record) + { + var result = new List(); + + void Scan(string text) + { + if (string.IsNullOrEmpty(text)) return; + foreach (Match m in PackageFullNamePattern.Matches(text)) + { + if (!result.Contains(m.Value, StringComparer.OrdinalIgnoreCase)) + result.Add(m.Value); + } + } + + Scan(record.Message); + foreach (var prop in record.PropertyStrings) + Scan(prop); + + return result; + } + + private static string BuildExcerpt(AppxLogRecord record) + { + var text = !string.IsNullOrEmpty(record.Message) + ? record.Message + : string.Join("; ", record.PropertyStrings); + if (string.IsNullOrEmpty(text)) + return $"EventID {record.EventId}"; + text = text.Replace("\r", " ").Replace("\n", " "); + return text.Length <= MessageExcerptLength ? text : text.Substring(0, MessageExcerptLength); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ProvisioningStatusTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ProvisioningStatusTracker.cs index 06e612f5..5cf42828 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ProvisioningStatusTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ProvisioningStatusTracker.cs @@ -4,6 +4,7 @@ using System.Linq; using System.Text.Json; using System.Text.RegularExpressions; using System.Threading; +using System.Threading.Tasks; using AutopilotMonitor.Agent.V2.Core.Logging; using AutopilotMonitor.Agent.V2.Core.Monitoring.Interop; using AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime; @@ -58,6 +59,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // write and IME workload log). internal const int ProvisioningFailureSettleWindowSeconds = 30; + // Session 2bc884b6 enrichment: MSIX/Store app failures never touch the IME Win32 sidecar + // logs, so an ESP "Apps (0x80073cf9)" failure with all tracked apps green is a blackbox. + // When an Apps-subcategory failure arms the settle window, a one-shot scan of the AppX + // deployment event log runs on the threadpool and emits esp_appx_failure_analysis with + // scored package candidates. Lookback is capped so resumed/long sessions don't correlate + // against hours of unrelated servicing noise. + internal const int AppxScanLookbackCapHours = 4; + // Regex for HRESULT extraction from subcategory statusText (e.g. "Apps (0x87d1041c)"). // Language-invariant: the parenthesised hex tail is consistent across Windows locales. private static readonly Regex HResultPattern = new Regex( @@ -107,6 +116,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals // failure details that fire after the settle window expires. private Dictionary _provisioningFailureSettleTimers; private Dictionary _provisioningFailureSettleArgs; + // Session 2bc884b6: AppX enrichment scan seams + fire-once guard. The scanner and the + // dispatcher are injectable so tests never touch the real event log or the threadpool. + private readonly IAppxDeploymentFailureScanner _appxScanner; + private readonly Action _backgroundDispatcher; + private DateTime _monitoringStartUtc; + private bool _appxScanStarted; private readonly object _stateLock = new object(); public event EventHandler EspFailureDetected; @@ -125,12 +140,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals string sessionId, string tenantId, InformationalEventPost post, - AgentLogger logger) + AgentLogger logger, + IAppxDeploymentFailureScanner appxScanner = null, + Action backgroundDispatcher = null) { _sessionId = sessionId ?? throw new ArgumentNullException(nameof(sessionId)); _tenantId = tenantId ?? throw new ArgumentNullException(nameof(tenantId)); _post = post ?? throw new ArgumentNullException(nameof(post)); _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + _appxScanner = appxScanner ?? new AppxDeploymentFailureScanner(); + _backgroundDispatcher = backgroundDispatcher ?? (action => Task.Run(action)); } // ===================================================================== @@ -262,6 +281,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals _deviceSetupFallbackTimer = null; _accountSetupProvisioningCompleteFired = false; _accountSetupFallbackTimer = null; + _monitoringStartUtc = DateTime.UtcNow; + _appxScanStarted = false; // Try to start immediately; if key doesn't exist yet, retry every 2s if (!TryStartWatcher()) @@ -1042,6 +1063,175 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals $"Provisioning failure settle window armed: category={args.Category}, " + $"failedSubcategory={args.FailedSubcategory ?? "n/a"}, errorCode={args.ErrorCode ?? "n/a"}, " + $"settleSeconds={ProvisioningFailureSettleWindowSeconds}"); + + MaybeStartAppxFailureScan(args); + } + + /// + /// Session 2bc884b6 enrichment: on an Apps-subcategory failure, queue a one-shot scan of + /// the AppX deployment event log so MSIX/Store failures — invisible to ImeLogTracker — + /// get named while the settle window is still open (the enrichment event lands before + /// enrollment_failed in the timeline). Fire-once per session: a second Apps failure in + /// the other category would rescan the same window for no new information. + /// + /// Caller holds — only the QUEUING happens here; the scan body + /// runs lock-free on the threadpool against an immutable request. The settle-window + /// expiry never waits for the scan (worst case the enrichment is lost at shutdown — + /// degraded enrichment only, the failure path is unchanged). + /// + /// + private void MaybeStartAppxFailureScan(EspFailureDetectedEventArgs args) + { + if (!string.Equals(args.FailedSubcategory, "Apps", StringComparison.OrdinalIgnoreCase)) + return; + if (_appxScanStarted) + return; + _appxScanStarted = true; + + var now = DateTime.UtcNow; + var lookbackCap = now.AddHours(-AppxScanLookbackCapHours); + var windowStart = _monitoringStartUtc > lookbackCap ? _monitoringStartUtc : lookbackCap; + var request = new AppxFailureScanRequest( + windowStartUtc: windowStart, + windowEndUtc: now, + espErrorCode: args.ErrorCode, + espCategory: args.Category, + failedSubcategory: args.FailedSubcategory); + + _logger.Info( + $"AppX failure scan queued: category={args.Category ?? "n/a"}, " + + $"errorCode={args.ErrorCode ?? "n/a"}, windowStartUtc={windowStart:o}"); + + _backgroundDispatcher(() => RunAppxFailureScan(request)); + } + + private void RunAppxFailureScan(AppxFailureScanRequest request) + { + try + { + var scan = _appxScanner.Scan(request); + var analysis = AppxFailureAnalyzer.Analyze(request, scan); + EmitAppxFailureAnalysis(request, scan, analysis); + } + catch (Exception ex) + { + _logger.Error("AppX failure scan failed", ex); + CollectorDegradationReporter.Report( + _post, _sessionId, _tenantId, "AppxDeploymentFailureScanner", "scan_failed", ex); + } + } + + /// + /// Emits esp_appx_failure_analysis. Fields the RuleEngine matches on are FLAT + /// top-level (it cannot traverse nested collections — see the failedSubcategories + /// precedent in EmitProvisioningEvent); the candidates list is UI/MCP detail. + /// ImmediateUpload: the agent terminates ~30s after the settle window, same reasoning + /// as esp_apps_failure_correlation in EnrollmentTerminationHandler. + /// + private void EmitAppxFailureAnalysis( + AppxFailureScanRequest request, + AppxFailureScanResult scan, + AppxFailureAnalysis analysis) + { + var data = new Dictionary + { + { "verdict", analysis.Verdict }, + { "confidence", analysis.Confidence }, + { "espCategory", request.EspCategory ?? "unknown" }, + { "failedSubcategory", request.FailedSubcategory ?? "Apps" }, + { "candidateCount", analysis.TotalCandidateCount }, + { "errorEventCount", analysis.ErrorEventCount }, + { "windowStartUtc", request.WindowStartUtc.ToString("o") }, + { "windowEndUtc", request.WindowEndUtc.ToString("o") }, + { "scanDurationMs", scan.ScanDurationMs }, + { "channel", AppxDeploymentFailureScanner.Channel } + }; + if (request.EspErrorCode != null) + data["espErrorCode"] = request.EspErrorCode; + if (analysis.ScanUnavailableReason != null) + data["scanError"] = analysis.ScanUnavailableReason; + if (scan.Truncated) + data["scanTruncated"] = true; + if (analysis.OtherHresultsSeen.Count > 0) + data["otherHresultsSeen"] = string.Join(",", analysis.OtherHresultsSeen); + + var top = analysis.Candidates.FirstOrDefault(); + if (top != null) + { + data["topCandidatePackage"] = top.PackageFullName; + data["topCandidatePackageName"] = top.PackageName; + data["topCandidateMatchType"] = top.MatchType; + data["topCandidateEventId"] = top.EventId; + data["topCandidateTimeUtc"] = top.TimeUtc.ToString("o"); + if (top.Hresults.Count > 0) + data["topCandidateHresult"] = top.Hresults[0]; + + var candidateList = new List(); + foreach (var c in analysis.Candidates) + { + candidateList.Add(new Dictionary + { + { "packageFullName", c.PackageFullName }, + { "packageName", c.PackageName }, + { "score", c.Score }, + { "matchType", c.MatchType }, + { "hresults", string.Join(",", c.Hresults) }, + { "eventId", c.EventId }, + { "timeUtc", c.TimeUtc.ToString("o") }, + { "occurrences", c.Occurrences }, + { "messageExcerpt", c.MessageExcerpt } + }); + } + data["candidates"] = candidateList; + } + + string message; + var severity = EventSeverity.Info; + switch (analysis.Verdict) + { + case AppxFailureAnalyzer.VerdictCandidateIdentified: + severity = EventSeverity.Warning; + message = $"ESP Apps failure enrichment: suspected MSIX/Store package '{top.PackageName}'" + + (request.EspErrorCode != null ? $" matches ESP error {request.EspErrorCode}" : "") + + $" — {analysis.TotalCandidateCount} candidate(s) in AppX deployment log " + + "(assessment, not a confirmed root cause)"; + break; + case AppxFailureAnalyzer.VerdictActivityNoHresultMatch: + message = $"ESP Apps failure enrichment: AppX deployment errors found (top package '{top.PackageName}') " + + $"but none match ESP error {request.EspErrorCode ?? "n/a"} — weak correlation " + + "(assessment, not a confirmed root cause)"; + break; + case AppxFailureAnalyzer.VerdictErrorsNoPackage: + message = "ESP Apps failure enrichment: AppX deployment errors in window but no package name " + + "extractable — inconclusive"; + break; + case AppxFailureAnalyzer.VerdictScanUnavailable: + message = $"ESP Apps failure enrichment: AppX deployment log unavailable " + + $"({analysis.ScanUnavailableReason}) — no assessment possible"; + break; + default: // no_appx_candidates + message = "ESP Apps failure enrichment: no AppX deployment errors in window — failure likely " + + "originates outside the MSIX/Store pipeline (check Win32/IME apps)"; + break; + } + + _post.Emit(new EnrollmentEvent + { + SessionId = _sessionId, + TenantId = _tenantId, + EventType = Constants.EventTypes.EspAppxFailureAnalysis, + Severity = severity, + Source = "EspAndHelloTracker", + Phase = EnrollmentPhase.Unknown, + Message = message, + Data = data, + ImmediateUpload = true + }); + + _logger.Info( + $"AppX failure analysis emitted: verdict={analysis.Verdict}, confidence={analysis.Confidence}, " + + $"candidates={analysis.TotalCandidateCount}/{analysis.ErrorEventCount} records, " + + $"durationMs={scan.ScanDurationMs}"); } private void OnProvisioningFailureSettleExpired(string categoryName) diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt index adbc5cb0..4b809f8d 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt @@ -1 +1 @@ -1255 +1276 diff --git a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts index d2f92359..ac4dfae2 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts @@ -63,6 +63,7 @@ export const EVENT_TYPES_CATALOG = { 'app_install_skipped', 'app_install_starved', 'esp_apps_failure_correlation', + 'esp_appx_failure_analysis', 'download_progress', 'do_telemetry', 'all_apps_completed', diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs index cdc486a7..59c1bfaa 100644 --- a/src/Shared/AutopilotMonitor.Shared/Constants.cs +++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs @@ -471,6 +471,7 @@ namespace AutopilotMonitor.Shared // ESP provisioning detail public const string EspFailureSettleStarted = "esp_failure_settle_started"; + public const string EspAppxFailureAnalysis = "esp_appx_failure_analysis"; // One-shot AppXDeploymentServer/Operational scan during the ESP failure settle window: candidate MSIX/Store packages behind an "Apps (0x…)" subcategory failure invisible to ImeLogTracker (session 2bc884b6). Assessment, not a confirmed root cause. public const string EspProvisioningRaw = "esp_provisioning_raw"; public const string EspFailure = "esp_failure"; public const string EspExiting = "esp_exiting"; diff --git a/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts b/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts index 04a16d28..513c859b 100644 --- a/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts +++ b/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts @@ -88,6 +88,8 @@ export const KNOWN_EVENT_TYPES: EventTypeEntry[] = [ description: "Generic ESP state change event." }, { value: "esp_failure_advisory", label: "esp_failure_advisory", category: "esp", description: "ESP reported a subcategory failure but the device had already progressed to AccountSetup with ContinueAnyway enabled — non-terminal advisory, the agent continues monitoring." }, + { value: "esp_appx_failure_analysis", label: "esp_appx_failure_analysis", category: "esp", + description: "AppX deployment log scan during the ESP failure settle window: suspected MSIX/Store package candidates behind an Apps-subcategory failure (assessment, not a confirmed root cause)." }, // -------- App installs -------- { value: "app_install_started", label: "app_install_started", category: "app", diff --git a/src/Web/autopilot-monitor-web/app/sessions/[sessionId]/components/EventTimeline.tsx b/src/Web/autopilot-monitor-web/app/sessions/[sessionId]/components/EventTimeline.tsx index 3315e346..59b340aa 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/[sessionId]/components/EventTimeline.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/[sessionId]/components/EventTimeline.tsx @@ -485,8 +485,8 @@ function EventRow({ event, showScriptOutput }: { event: EnrollmentEvent; showScr defang). The HRESULT is extracted from the ESP registry statusText by the agent (e.g. "Apps (0x87d1041c)") and surfaced as top-level event data so the UI can render it without parsing nested text. */} - {(event.eventType === "enrollment_failed" || event.eventType === "esp_provisioning_status" || event.eventType === "esp_failure_advisory") && (() => { - const code = event.data?.errorCode ?? event.data?.failedSubcategoryErrorCode; + {(event.eventType === "enrollment_failed" || event.eventType === "esp_provisioning_status" || event.eventType === "esp_failure_advisory" || event.eventType === "esp_appx_failure_analysis") && (() => { + const code = event.data?.errorCode ?? event.data?.failedSubcategoryErrorCode ?? event.data?.espErrorCode; const sub = event.data?.failedSubcategory ?? event.data?.failedSubcategories; const isAdvisory = event.eventType === "esp_failure_advisory"; if (!code && !isAdvisory) return null;