From 19e796820eb7cce2468f3aabbae973392955a6f0 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Thu, 16 Jul 2026 19:28:49 +0200 Subject: [PATCH] feat(agent): backfill Autopilot-channel error records at startup MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In the normal IME deployment model the agent installs only after MDM enrollment, so TPM attestation and ZTD errors from earlier (retried) attempts sat invisible in the event log. The tracker now replays Autopilot-channel Level 1-2 records from the last 4h at startup through the regular emission pipeline. Spam containment (answering "spam or backfilled event?" — individual events, but marked and bounded): - errors only (Warning-level 100 heartbeat excluded by XPath) - harmless-ID downgrade + burst rollup still applies to backfilled records - cap of 25 records per scan, newest first (tail logged, not emitted) - RecordId watermark persisted to autopilot-error-backfill.json, advanced by both backfill and live watcher -> restarts never re-emit - events carry backfilled=true + original timeCreated; the event's own timestamp is emission time, so backend StartedAt alignment is not dragged backwards by pre-enrollment records Docs: Observability matrix updated (TPM row now visible-via-backfill) + new "Startup error backfill" section. Tests: 5 new (XPath, watermark roundtrip/monotonicity, backfilled/live markers, rollup-on-backfill); full V2 suite 1804 green. Co-Authored-By: Claude Fable 5 --- docs/agent/autopilot-ztd-diagnostics.md | 23 +- ...dernDeploymentTrackerErrorBackfillTests.cs | 144 +++++++++++++ .../SystemSignals/ModernDeploymentTracker.cs | 197 ++++++++++++++++++ .../buildcounter.txt | 2 +- 4 files changed, 360 insertions(+), 6 deletions(-) create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/ModernDeploymentTrackerErrorBackfillTests.cs 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