diff --git a/docs/agent/autopilot-ztd-diagnostics.md b/docs/agent/autopilot-ztd-diagnostics.md index e689c80f..eae88ffa 100644 --- a/docs/agent/autopilot-ztd-diagnostics.md +++ b/docs/agent/autopilot-ztd-diagnostics.md @@ -95,16 +95,29 @@ handshake itself) is over before our process exists. | Failure class | Normal flow (IME install) | Bootstrap token mode | Await-enrollment mode | | --- | --- | --- | --- | | Enrollment blocked (0x80180014/18, 0xC1036501, 0x801C03F3 → ANALYZE-ENRL-004) | **Invisible** — no enrollment ⇒ no agent, no session. | **Visible** — the bootstrap token exists precisely to report pre-MDM (as of 2026-07: one customer piloting). | **Invisible to the backend** — the agent binary is present but only polls for the MDM certificate; without the cert it cannot authenticate, and monitoring starts only after the cert appears. A hard blocker ends in the await timeout (default 480 min) with nothing uploaded. | -| TPM attestation (ANALYZE-ENRL-003) | **Almost never live** — attestation precedes enrollment. Retry-then-success leaves the earlier errors in the Autopilot channel, but the continuous watcher is live-only and the startup backfill targets ManagementService 509 only, so they are not forwarded. | Visible. | Same limits as normal flow once monitoring starts. | +| TPM attestation (ANALYZE-ENRL-003) | **Visible via error backfill** — attestation precedes enrollment, but the startup error backfill (below) replays Autopilot-channel Level 1-2 records from the last 4h, so retry-then-success attempts surface as `backfilled=true` events. | Visible. | Visible via error backfill once monitoring starts. | | Hybrid-join 0x80004005 (ANALYZE-ENRL-005) | **Visible** — the ODJ/hybrid phase runs during device ESP while the agent is active. | Visible. | Visible after cert arrival. | | Clock skew (ANALYZE-DEV-007) | **Always** — ntp_time_check is our own event. | Always. | Always. | The rules stay enabled despite the narrow normal-flow windows: they are evidence-gated (zero cost when the codes never appear) and they future-proof the bootstrap and -await-enrollment paths. Known follow-up option: extend the ModernDeploymentTracker -startup backfill to also replay Autopilot-channel Error-level records (807/809/815/908, -171/172) from before agent start — that would make the retry-then-success TPM case and -late-visible ZTD errors observable in the normal flow too. +await-enrollment paths. + +## Startup error backfill (ModernDeploymentTracker) + +At agent start (backfill enabled), the tracker replays Autopilot-channel **Level 1-2** +records from the last **4 hours** through the normal emission pipeline — this is what makes +pre-install errors (TPM attestation retries, ZTD errors 807/809/815/908) visible in the +normal IME deployment flow. Spam containment, in order: + +1. **Errors only** — the Warning-level 100 heartbeat storm is excluded by the XPath. +2. **Harmless-ID downgrade + burst rollup** still applies to backfilled records. +3. **Cap** of 25 records per scan (newest first; the tail is logged, not emitted). +4. **RecordId watermark** (`autopilot-error-backfill.json`, advanced by both the backfill + scan and the live watcher) — restarts never re-emit records a previous run forwarded. +5. Backfilled events carry `backfilled: true` plus the original `timeCreated` in their + payload; the event's own timestamp is the emission time, so the session's `StartedAt` + (which the backend aligns to the earliest event) is not dragged backwards. # Schema — Error codes (backend known-issue map) diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ModernDeploymentTrackerErrorBackfillTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ModernDeploymentTrackerErrorBackfillTests.cs new file mode 100644 index 00000000..c33520db --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ModernDeploymentTrackerErrorBackfillTests.cs @@ -0,0 +1,144 @@ +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 +{ + /// + /// Autopilot-channel error backfill (docs/agent/autopilot-ztd-diagnostics.md, + /// Observability section): TPM/ZTD errors precede the agent's IME install, so a + /// retry-then-success attempt leaves them in the event log with nobody watching. + /// The backfill replays them as backfilled=true modern_deployment_error events; the + /// RecordId watermark makes replays restart-safe. These tests pin the XPath, the + /// watermark persistence roundtrip, and the backfilled payload marker. + /// + public sealed class ModernDeploymentTrackerErrorBackfillTests : IDisposable + { + private static readonly DateTime At = new DateTime(2026, 7, 16, 14, 0, 0, DateTimeKind.Utc); + + private readonly TempDirectory _tmp = new TempDirectory(); + private readonly FakeSignalIngressSink _sink; + private readonly ModernDeploymentTracker _tracker; + + public ModernDeploymentTrackerErrorBackfillTests() + { + _sink = new FakeSignalIngressSink(); + var post = new InformationalEventPost(_sink, new VirtualClock(At)); + var logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + _tracker = new ModernDeploymentTracker( + sessionId: "sess-error-backfill", + tenantId: "tenant-error-backfill", + post: post, + logger: logger, + backfillEnabled: false, + stateDirectory: _tmp.Path); + } + + public void Dispose() => _tmp.Dispose(); + + [Fact] + public void BuildErrorBackfillXPath_FiltersToCriticalAndErrorWithinLookback() + { + var xpath = ModernDeploymentTracker.BuildErrorBackfillXPath(240); + + Assert.Equal("*[System[(Level >= 1 and Level <= 2) and TimeCreated[timediff(@SystemTime) <= 14400000]]]", xpath); + } + + [Fact] + public void Watermark_RoundtripsThroughStateFile_AndIsMonotonic() + { + Assert.Null(_tracker.LoadAutopilotErrorBackfillState()); + + _tracker.AdvanceAutopilotErrorWatermark(4711); + Assert.Equal(4711, _tracker.LoadAutopilotErrorBackfillState()!.MaxRecordId); + + // Lower RecordIds must never regress the persisted watermark. + _tracker.AdvanceAutopilotErrorWatermark(42); + Assert.Equal(4711, _tracker.LoadAutopilotErrorBackfillState()!.MaxRecordId); + + _tracker.AdvanceAutopilotErrorWatermark(4712); + Assert.Equal(4712, _tracker.LoadAutopilotErrorBackfillState()!.MaxRecordId); + } + + [Fact] + public void BackfilledErrorRecord_EmitsModernDeploymentError_WithBackfilledMarkerAndOriginalTime() + { + var originalTime = At.AddMinutes(-45); // written long before agent start + + _tracker.ProcessEvent( + eventId: 815, + level: 2, + levelDisplayName: "Error", + providerName: "ModernDeployment-Diagnostics-Provider", + timeCreatedUtc: originalTime, + formattedDescription: "ZtdDeviceHasNoAssignedProfile - No profile assigned to the device, and no default profile found in the tenant.", + shortName: "Autopilot", + channelName: ModernDeploymentTracker.AutopilotChannel, + isBackfill: true); + + var posted = _sink.Posted.Single(p => p.Kind == DecisionSignalKind.InformationalEvent); + Assert.Equal("modern_deployment_error", posted.Payload![SignalPayloadKeys.EventType]); + + var data = Assert.IsAssignableFrom>(posted.TypedPayload); + Assert.Equal(true, data["backfilled"]); + Assert.Equal(originalTime.ToString("o"), data["timeCreated"]); + Assert.Equal(815, data["eventId"]); + } + + [Fact] + public void LiveErrorRecord_CarriesBackfilledFalse() + { + _tracker.ProcessEvent( + eventId: 807, + level: 2, + levelDisplayName: "Error", + providerName: "ModernDeployment-Diagnostics-Provider", + timeCreatedUtc: At, + formattedDescription: "ZtdDeviceIsNotRegistered", + shortName: "Autopilot", + channelName: ModernDeploymentTracker.AutopilotChannel, + isBackfill: false); + + var posted = _sink.Posted.Single(p => p.Kind == DecisionSignalKind.InformationalEvent); + var data = Assert.IsAssignableFrom>(posted.TypedPayload); + Assert.Equal(false, data["backfilled"]); + } + + [Fact] + public void BackfilledHarmlessId_StillRunsThroughRollupSuppression() + { + // Even in a backfill scan, the harmless-downgrade + burst rollup must apply — a + // pre-start burst of a known-harmless Error-level ID must not flood the timeline. + for (var i = 0; i < ModernDeploymentTracker.HarmlessRollupIndividualLimit + 10; i++) + { + _tracker.ProcessEvent( + eventId: 1005, + level: 2, + levelDisplayName: "Error", + providerName: "ModernDeployment-Diagnostics-Provider", + timeCreatedUtc: At.AddMinutes(-30).AddSeconds(i), + formattedDescription: "Known-harmless error burst", + shortName: "Autopilot", + channelName: ModernDeploymentTracker.AutopilotChannel, + isBackfill: true); + } + + // Only the first N individual occurrences are forwarded (downgraded to + // modern_deployment_log); the burst tail is suppressed until the next rollup step. + var forwarded = _sink.Posted.Count(p => + p.Kind == DecisionSignalKind.InformationalEvent + && p.Payload != null + && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et == "modern_deployment_log"); + Assert.Equal(ModernDeploymentTracker.HarmlessRollupIndividualLimit, forwarded); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ModernDeploymentTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ModernDeploymentTracker.cs index 969a9a9c..f9d6ccd3 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ModernDeploymentTracker.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/ModernDeploymentTracker.cs @@ -45,6 +45,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals internal const string WhiteGloveBackfillStateFileName = "whiteglove-backfill.json"; + /// + /// Error-record backfill for the Autopilot channel: TPM attestation and ZTD + /// registration/assignment errors (171/172, 807/809/815/908, all Level 1-2) happen + /// BEFORE the agent is installed in the normal IME deployment model — a failed + /// attempt that was resolved by a retry would stay invisible without replaying the + /// channel history at startup. See docs/agent/autopilot-ztd-diagnostics.md + /// (Observability section). Fixed 4h lookback: OOBE start → agent install is + /// normally well under that, and the RecordId watermark below prevents replays + /// from re-emitting on every agent restart. + /// + internal const int ErrorBackfillLookbackMinutes = 240; + + /// + /// Hard cap of records processed per backfill scan (newest first). A pathological + /// error storm before agent start must not flood the session timeline — the newest + /// records carry the diagnosis; anything beyond the cap is summarized in the log. + /// + internal const int ErrorBackfillMaxRecords = 25; + + internal const string AutopilotErrorBackfillStateFileName = "autopilot-error-backfill.json"; + /// /// Per-EventId emission caps for harmless-downgraded events (session 8bc1180f, /// 2026-06-12). Windows can dump hundreds of identical EventID-100 "Autopilot policy @@ -78,6 +99,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals private bool _whiteGloveStartDetected; private readonly object _stateLock = new object(); + // Highest Autopilot-channel error RecordId already forwarded (backfill or live). + // Persisted so a restart's backfill scan never re-emits records a previous run + // already sent. Guarded by _errorWatermarkLock. + private long _autopilotErrorMaxRecordId; + private readonly object _errorWatermarkLock = new object(); + // Cumulative per-EventId occurrence counters for harmless-downgraded events. // EventRecordWritten callbacks can run concurrently → guarded by its own lock. private readonly Dictionary _harmlessOccurrenceCounts = new Dictionary(); @@ -130,11 +157,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals public void Start() { + // Load the error watermark BEFORE arming the watchers so live records that race + // the backfill scan still advance a correctly-initialized watermark. + _autopilotErrorMaxRecordId = LoadAutopilotErrorBackfillState()?.MaxRecordId ?? 0; + StartWatchers(); if (_backfillEnabled) { BackfillTargetedEvents(); + BackfillAutopilotErrors(); } else { @@ -236,6 +268,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals try { ProcessRecord(e.EventRecord, shortName, channelName, isBackfill: false); + + // Advance the persisted error watermark for live Autopilot-channel errors so a + // later restart's backfill scan does not re-emit them (errors are rare — the + // per-record disk write is negligible). + if (channelName == AutopilotChannel + && (e.EventRecord.Level ?? 4) <= 2 + && e.EventRecord.RecordId.HasValue) + { + AdvanceAutopilotErrorWatermark(e.EventRecord.RecordId.Value); + } } catch (Exception ex) { @@ -571,6 +613,161 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals } } + /// + /// XPath for the Autopilot-channel error backfill: Level 1-2 (Critical/Error) only — + /// this deliberately excludes the Warning-level 100 heartbeat storm; the harmless-ID + /// downgrade + rollup still applies to whatever the scan forwards. + /// + internal static string BuildErrorBackfillXPath(int lookbackMinutes) + { + long lookbackMs = (long)lookbackMinutes * 60_000L; + return $"*[System[(Level >= 1 and Level <= 2) and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]"; + } + + /// + /// Replays Autopilot-channel error records written BEFORE the agent started (normal IME + /// deployment: TPM attestation / ZTD errors precede our install — a retry-then-success + /// attempt leaves them in the log with no live watcher to see them). Records flow through + /// the regular pipeline with isBackfill=true, so they arrive + /// as modern_deployment_error events carrying backfilled=true plus the original + /// timeCreated; the event's own timestamp is emission time, so session StartedAt is not + /// dragged backwards. Newest-first, capped, watermark-deduped across restarts. + /// + private void BackfillAutopilotErrors() + { + try + { + long watermark; + lock (_errorWatermarkLock) { watermark = _autopilotErrorMaxRecordId; } + + var xpath = BuildErrorBackfillXPath(ErrorBackfillLookbackMinutes); + _logger.Info($"ModernDeployment error backfill: scanning {AutopilotChannel} " + + $"(lookback={ErrorBackfillLookbackMinutes}min, watermark={watermark}, cap={ErrorBackfillMaxRecords})"); + + var query = new EventLogQuery(AutopilotChannel, PathType.LogName, xpath) + { + ReverseDirection = true + }; + + int processed = 0, skippedWatermark = 0, droppedOverCap = 0; + long maxSeen = watermark; + + using (var reader = new EventLogReader(query)) + { + EventRecord record; + while ((record = reader.ReadEvent()) != null) + { + using (record) + { + var recordId = record.RecordId ?? 0; + if (recordId > maxSeen) maxSeen = recordId; + + if (recordId != 0 && recordId <= watermark) + { + skippedWatermark++; + continue; + } + + if (processed >= ErrorBackfillMaxRecords) + { + droppedOverCap++; + continue; + } + + processed++; + ProcessRecord(record, "Autopilot", AutopilotChannel, isBackfill: true); + } + } + } + + if (maxSeen > watermark) + AdvanceAutopilotErrorWatermark(maxSeen); + + if (processed == 0 && droppedOverCap == 0) + _logger.Debug($"ModernDeployment error backfill: nothing new (skippedByWatermark={skippedWatermark})"); + else + _logger.Info($"ModernDeployment error backfill: forwarded {processed} record(s) " + + $"(skippedByWatermark={skippedWatermark}, droppedOverCap={droppedOverCap})"); + } + catch (EventLogNotFoundException) + { + _logger.Warning($"ModernDeployment event log not found during error backfill: {AutopilotChannel} (normal on non-Windows 10/11 test environments)"); + } + catch (UnauthorizedAccessException ex) + { + _logger.Warning($"ModernDeployment error backfill access denied: {ex.Message}"); + } + catch (Exception ex) + { + _logger.Warning($"ModernDeployment error backfill failed: {ex.Message}"); + } + } + + /// + /// Raises the persisted error watermark to (monotonic — + /// lower values are ignored). Called from both the backfill scan and the live watcher. + /// + internal void AdvanceAutopilotErrorWatermark(long recordId) + { + lock (_errorWatermarkLock) + { + if (recordId <= _autopilotErrorMaxRecordId) return; + _autopilotErrorMaxRecordId = recordId; + } + + PersistAutopilotErrorBackfillState(recordId); + } + + private void PersistAutopilotErrorBackfillState(long maxRecordId) + { + if (string.IsNullOrEmpty(_stateDirectory)) return; + + try + { + Directory.CreateDirectory(_stateDirectory); + var filePath = Path.Combine(_stateDirectory, AutopilotErrorBackfillStateFileName); + var state = new AutopilotErrorBackfillState + { + MaxRecordId = maxRecordId, + PersistedUtc = DateTime.UtcNow + }; + var json = JsonConvert.SerializeObject(state, Formatting.Indented); + var tempPath = filePath + ".tmp"; + File.WriteAllText(tempPath, json); + File.Copy(tempPath, filePath, overwrite: true); + try { File.Delete(tempPath); } catch { } + } + catch (Exception ex) + { + _logger.Warning($"Failed to persist Autopilot error backfill state: {ex.Message}"); + } + } + + internal AutopilotErrorBackfillState LoadAutopilotErrorBackfillState() + { + if (string.IsNullOrEmpty(_stateDirectory)) return null; + + var filePath = Path.Combine(_stateDirectory, AutopilotErrorBackfillStateFileName); + if (!File.Exists(filePath)) return null; + + try + { + var json = File.ReadAllText(filePath); + return JsonConvert.DeserializeObject(json); + } + catch (Exception ex) + { + _logger.Warning($"Failed to load Autopilot error backfill state: {ex.Message}"); + return null; + } + } + + internal class AutopilotErrorBackfillState + { + public long MaxRecordId { get; set; } + public DateTime PersistedUtc { get; set; } + } + // ----------------------------------------------------------------------- // Backfill state persistence // ----------------------------------------------------------------------- diff --git a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt index dda50873..1b1818ca 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt +++ b/src/Agent/AutopilotMonitor.Agent.V2/buildcounter.txt @@ -1 +1 @@ -1350 +1353