From 06cf1c4c1219ebfcf85744ffe6ba8183ef359cb3 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 21 Aug 2026 19:41:56 +0200 Subject: [PATCH] =?UTF-8?q?feat(agent):=20system=20timeline=20watcher=20?= =?UTF-8?q?=E2=80=94=20clock=20steps=20+=20sleep=20episodes=20as=20ground?= =?UTF-8?q?=20truth?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two enrollment blind spots become timeline ground truth from the System event log via one EventLogWatcher (WindowsUpdateTracker pattern, 24h backfill with RecordId watermark recovering pre-agent records): - system_clock_changed (Kernel-General 1): oldTime/newTime/signed timeDeltaMs, reason and the setting process. 2s floor suppresses w32time 1ms micro-slews; steps >= 5min are Warning + immediate upload. Payload instants are the authoritative source (event timestamps can be clamped server-side). - system_sleep_episode (Power-Troubleshooter 1 classic sleep/hibernate, Kernel-Power 507 Modern Standby; 506 deliberately unconsumed): kind, enteredAt/exitedAt, durationSeconds, wake source / AC state. 60s real-sleep floor filters Modern Standby screen-off scenarios. ConfigVersion 39 (Collectors.EnableSystemTimelineWatcher + SystemEventBackfillLookbackMinutes). Both types are non-activity on agent and backend (idle/stall clocks unaffected; a sleeping device stays Stalled). Consumers: TimeJumpBadge gains the ground-truth cause "clock-set" (classifyTimeJump matches backward display steps against recorded clock sets); EventTimeline badge blocks for both events plus the previously bare power_state_change; SessionInfoCard keeps the wall-clock duration and adds a standby note; TimeAttributionCalculator builds SleepSpans (RebootSpan clone, AttributionVersion 3) persisted as SleepSeconds/SleepSpansJson and rendered in TimeAttributionLane; ANALYZE-DEV-012 (info, single) fires once per session for episodes >= 5min - deliberately the only new rule, clock findings stay with DEV-008 to avoid duplicate-finding flood. Co-Authored-By: Claude Fable 5 --- docs/agent/index.md | 1 + docs/agent/system-timeline-watcher.md | 110 +++ docs/index.md | 1 + docs/log.md | 2 + rules/analyze/ANALYZE-DEV-012.json | 49 ++ rules/dist/analyze-rules.json | 48 ++ .../SystemTimelineTrackerTests.cs | 429 +++++++++++ .../SystemTimelineWatcherHostTests.cs | 57 ++ .../SystemSignals/SystemTimelineTracker.cs | 681 ++++++++++++++++++ .../Orchestration/DefaultComponentFactory.cs | 16 + .../Hosts/SystemTimelineWatcherHost.cs | 68 ++ .../Orchestration/SignalActivityClassifier.cs | 6 + .../SleepEpisodeRuleTests.cs | 137 ++++ .../TimeAttributionCalculatorTests.cs | 130 ++++ ...tributionPersistenceAndAggregationTests.cs | 12 + .../Config/GetAgentConfigFunction.cs | 2 +- .../Helpers/TimeAttributionCalculator.cs | 64 +- .../EventIngestProcessor.Classification.cs | 4 + .../TableStorageService.TimeAttribution.cs | 4 + .../src/resource-catalog.ts | 2 + .../src/tools/sessions.ts | 2 +- .../AutopilotMonitor.Shared/Constants.cs | 2 + .../Models/Config/AgentConfigResponse.cs | 24 + .../Models/Metrics/SessionTimeBreakdown.cs | 26 + .../app/gather-rules/eventTypes.ts | 4 + .../app/sessions/components/EventTimeline.tsx | 111 ++- .../sessions/components/SessionInfoCard.tsx | 30 +- .../components/TimeAttributionLane.tsx | 38 +- .../sessions/hooks/useSessionDerivedData.ts | 21 + .../app/sessions/page.tsx | 2 + .../lib/__tests__/timeProvenance.test.ts | 43 ++ .../lib/timeProvenance.ts | 41 +- .../utils/shared-manifests.generated.ts | 2 + .../utils/shared-manifests.json | 2 + 34 files changed, 2145 insertions(+), 26 deletions(-) create mode 100644 docs/agent/system-timeline-watcher.md create mode 100644 rules/analyze/ANALYZE-DEV-012.json create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/SystemTimelineTrackerTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/SystemTimelineWatcherHostTests.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs create mode 100644 src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/SystemTimelineWatcherHost.cs create mode 100644 src/Backend/AutopilotMonitor.Functions.Tests/SleepEpisodeRuleTests.cs diff --git a/docs/agent/index.md b/docs/agent/index.md index 192ec4eb..a5f74387 100644 --- a/docs/agent/index.md +++ b/docs/agent/index.md @@ -9,5 +9,6 @@ How the on-device agent works: * [Autopilot ZTD Diagnostics](autopilot-ztd-diagnostics.md) - Windows' own diagnostic surfaces for the profile-download flow: ModernDeployment event IDs (807/815/164/...), the Diagnostics\Autopilot registry key, deployment-service endpoints, and the known-issue error-code map. * [MDM Reboot Coalescing](mdm-reboot-coalescing.md) - attributing the mid-ESP coalesced reboot ("second sign-in") to the device-assigned policy URIs that forced it: aggregated 2800 observations (neutral, flush-time watermark) + ANALYZE-ESP-005 gated on an actually-observed reboot. * [Power-State Watcher](power-state-watcher.md) - live AC↔battery transitions and 50/30/15% downward threshold crossings via a WMI push subscription (no polling): power_state_change semantics (latch/debounce/cap, never armed without a battery) and the single-condition analyze rules ANALYZE-DEV-009/-010 on top. +* [System Timeline Watcher](system-timeline-watcher.md) - clock steps (system_clock_changed: oldTime/newTime/timeDeltaMs/process, micro-slew floor) and completed sleep episodes (system_sleep_episode: sleep/hibernate/Modern Standby with authoritative enteredAt/exitedAt) from one System-channel EventLogWatcher with pre-agent backfill; feeds the web clock-set jump cause, the standby duration note, time-attribution SleepSpans and ANALYZE-DEV-012. Reading order for newcomers: overview → decision engine → persistence. diff --git a/docs/agent/system-timeline-watcher.md b/docs/agent/system-timeline-watcher.md new file mode 100644 index 00000000..a5c72e51 --- /dev/null +++ b/docs/agent/system-timeline-watcher.md @@ -0,0 +1,110 @@ +--- +type: Concept +title: System Timeline Watcher — clock steps and sleep episodes from the System event log +description: How the agent turns two enrollment blind spots into timeline ground truth via one EventLogWatcher on the System channel — system_clock_changed (Kernel-General 1, oldTime/newTime/timeDeltaMs/process) and system_sleep_episode (Power-Troubleshooter 1 classic sleep/hibernate, Kernel-Power 507 Modern Standby) — including backfill of pre-agent records, the payload-times-are-authoritative rule, SleepSpans in time attribution, the web clock-set jump cause, and ANALYZE-DEV-012. +resource: /src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs +tags: + - agent + - eventlog + - time + - clock-skew + - standby + - collector + - time-attribution + - analyze-rules +timestamp: 2026-08-21T00:00:00+02:00 +--- + +# System Timeline Watcher + +Two things silently distort every session timeline and its wall-clock duration: + +1. **The OS clock gets stepped** — classically w32time correcting a wrong BIOS clock early + in OOBE, but also tzutil/MDM actions. Before this watcher the jump was only *inferred* + (TimeJumpBadge, `clock_skew`/DEV-008); Windows records the ground truth. +2. **The device sleeps mid-enrollment** — the timeline shows an unexplained gap, the + duration looks inflated, and nothing says "the device was simply asleep for 56 minutes". + +`SystemTimelineTracker` (hosted by `SystemTimelineWatcherHost`, config flag +`Collectors.EnableSystemTimelineWatcher`, ConfigVersion 39) subscribes to the **System** +channel with one provider-qualified XPath and forwards both facts as events. + +# Sources and events + +| Source (System channel) | Emitted event | Key payload | +|---|---|---| +| `Microsoft-Windows-Kernel-General` EventID 1 | `system_clock_changed` | `oldTime`, `newTime` (ISO-8601), signed `timeDeltaMs`, `reason`/`reasonText` (1=`application_set`, 2=`hardware_clock_sync`), `processName`/`processId` | +| `Microsoft-Windows-Power-Troubleshooter` EventID 1 | `system_sleep_episode` | `kind`=`sleep`/`hibernate` (EffectiveState 5 ⇒ hibernate), `enteredAt`=SleepTime, `exitedAt`=WakeTime, `durationSeconds`, `wakeSourceType`/`wakeSourceText` | +| `Microsoft-Windows-Kernel-Power` EventID 507 | `system_sleep_episode` | `kind`=`modern_standby`, `exitedAt`=TimeCreated, `enteredAt`=exit − DurationInUs, `durationSeconds` (scenario), `sleepDurationSeconds` (real sleep), `reason`, `onAcPower`, `batteryRemainingCapacityOnExit` | + +**506 is deliberately not consumed.** 507 carries the full episode; pairing 506/507 would +need an orphan-tolerant state machine across agent restarts for zero information gain — an +episode without a 507 never completed and would not be emitted under any design. + +# Thresholds (constants, not knobs) + +- `MinClockDeltaMs = 2000` — w32time logs Kernel-General 1 for routine **1 ms micro-slews** + (verified live, several per hour); only genuine steps are emitted. Suppressed records are + still claimed by the dedup watermark. +- `ClockDeltaWarningMs = 5 min` — larger steps are Warning + immediate upload (can break + token/cert validation windows; matches the web TimeJumpBadge threshold). +- `MinSleepDurationSeconds = 60` — **Modern Standby only**: every screen-off scenario logs a + 506/507 pair, including seconds-long ones with `SleepDurationInUs 0` (`SleepEntered=false`); + the single duration gate suppresses both. Classic Power-Troubleshooter episodes have no + floor — they only exist for genuinely completed S3/S4 transitions. + +# Payload times are authoritative + +The decisive clock correction happens exactly when the device clock is untrustworthy, and +the backend clamps implausible event timestamps (±168 h/24 h) to server time. Every semantic +instant therefore travels as an explicit ISO-8601 payload field (`oldTime`/`newTime`, +`enteredAt`/`exitedAt`); consumers must never read the event's own `Timestamp` for these. +The event `Timestamp` is set to the record's TimeCreated (WindowsUpdateTracker backfill +convention) so rows land where the wake/step happened. + +# Backfill and dedup + +Template: `WindowsUpdateTracker`. `LoadWatermark → arm watcher → backfill` with lookback +`SystemEventBackfillLookbackMinutes` (default 1440 = 24 h; 0 disables). The System .evtx +persists across OOBE reboots, so the pre-agent w32time correction and pre-agent standby +episodes are recovered with `backfilled=true`. Cross-restart dedup via RecordId watermark +(`system-timeline-watermark.json` in the state directory) plus an intra-run `HashSet` — +deliberately **not** a high-water mark, which would drop exactly the older, never-emitted +pre-agent records (the live watcher arms before the backfill scan). + +# Non-activity classification (both sides) + +Both event types are environment observation, not enrollment progress: +`SignalActivityClassifier.NonActivityEventTypes` (agent — must not reset idle/stall clocks) +and `EventIngestProcessor.IsPeriodicOrStallEvent` (backend — a device that slept through its +stall must stay Stalled). + +# Consumers + +- **Web timeline** (`EventTimeline.tsx`): badge blocks for both events; the TimeJumpBadge + gains the ground-truth cause `clock-set` — `classifyTimeJump` receives the session's + `system_clock_changed` deltas and matches a backward display step against a backward clock + set within max(60 s, 20 %) (`lib/timeProvenance.ts`). +- **Duration story** (`SessionInfoCard` via `useSessionDerivedData.standbySeconds`): the + wall-clock duration deliberately keeps the pause (the enrollment really took that long); + a `· 🌙 56m standby` note explains it. Episodes are dedup'd on `enteredAt`. +- **Time attribution** (`TimeAttributionCalculator.BuildSleepSpans`, AttributionVersion 3): + `SleepSpan`s mirror `RebootSpan`s — cross-cutting annotations clipped to the observation + windows (a WhiteGlove-pause episode contributes only its in-window flanks), never a slice + of the wall-clock partition. Persisted as `SleepSeconds`/`SleepSpansJson`; rendered as the + standby chip in `TimeAttributionLane`. +- **ANALYZE-DEV-012** (info, `trigger: single`, `on_event:system_sleep_episode`): fires once + per session for episodes ≥ 5 min. Deliberately the ONLY new rule: clock issues already + have DEV-008 (`clock_skew`) — a second clock rule would double-report the same action item + (user decision 2026-08-21); clock steps stay timeline ground truth with badges instead. + +# Citations + +- `src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs` +- `src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/SystemTimelineWatcherHost.cs` +- `src/Backend/AutopilotMonitor.Functions/Helpers/TimeAttributionCalculator.cs` (`BuildSleepSpans`) +- `src/Web/autopilot-monitor-web/lib/timeProvenance.ts` (`clock-set`, `findExplainingClockChange`) +- `rules/analyze/ANALYZE-DEV-012.json` +- Live payload evidence (2026-08-21, Win11 26220): Kernel-General 1 with `TimeDeltaInMs=1` + micro-slews; Kernel-Power 507 with `SleepDurationInUs=2324095807`; Power-Troubleshooter 1 + with `SleepTime`/`WakeTime` across a hibernate. diff --git a/docs/index.md b/docs/index.md index 763c6dfb..84d76080 100644 --- a/docs/index.md +++ b/docs/index.md @@ -31,6 +31,7 @@ https://docs.autopilotmonitor.com (separate repository). * [Registry App-State Second Pillar](agent/registry-app-state-pillar.md) - IME's authoritative per-app state read straight from the registry (Win32Apps EnforcementStateMessage, EspTrackingWin32Apps, StatusServiceReports) via a snapshot-and-diff watcher; registry/log reconciliation doubles as the built-in IME log-pattern drift alarm. * [WDP Scenario Gates & Completion Backstop](agent/wdp-scenario-gates.md) - How the agent gates Autopilot/ESP-only machinery off on Windows Device Preparation sessions (deterministic ExecutionContext marker, fail-toward-Classic), which noise it suppresses (ZTD probe, esp_config unknown, ModernDeployment 100/417/418/1005, starved sweep), and the WDP completion model: High-confidence seed, desktop-based arm D, and the 30-min device_prep_completion backstop. * [Power-State Watcher](agent/power-state-watcher.md) - Live AC↔battery transitions and 50/30/15% downward battery-threshold crossings during enrollment via a WMI Win32_PowerManagementEvent push subscription (zero polling, never armed on battery-less devices): the power_state_change event (transition field, per-level lifetime latch, 5s debounce, emission cap) and the analyze rules ANALYZE-DEV-009 (battery <15%, high) / ANALYZE-DEV-010 (AC→battery, warning) with on_event interim triggers. +* [System Timeline Watcher](agent/system-timeline-watcher.md) - Ground truth for two timeline blind spots from one System-channel EventLogWatcher with pre-agent backfill: system_clock_changed (Kernel-General 1 — oldTime/newTime/signed timeDeltaMs/reason/setting process; 2 s micro-slew floor, ≥5 min Warning+immediate) and system_sleep_episode (Power-Troubleshooter 1 sleep/hibernate + Kernel-Power 507 Modern Standby; authoritative enteredAt/exitedAt payload instants, 60 s Modern-Standby floor). Consumed by the TimeJumpBadge clock-set cause, the SessionInfoCard standby note, time-attribution SleepSpans (AttributionVersion 3) and ANALYZE-DEV-012. * [ESP Policy-Provider Stall Detection](agent/esp-policy-provider-stall.md) - The EnrollmentStatusTracking CSP's no-timeout Setup/Apps wait is keyed to the Intune-registered "Sidecar" provider by NAME: co-management's "ConfigMgr" parks the user ESP at "Apps (Identifying)" for days even with TrackingPoliciesCreated=1 (issue #106); the always-on two-arm esp_policy_provider_stalled tripwire (provider_incomplete | sidecar_provider_missing) and the SOFTWARE\Microsoft\Windows\Autopilot gather-rule allowlist entry that surface it. # Rules diff --git a/docs/log.md b/docs/log.md index 18a25a53..d3345310 100644 --- a/docs/log.md +++ b/docs/log.md @@ -2,6 +2,8 @@ ## 2026-08-21 +* **New**: `agent/system-timeline-watcher.md` — clock-step and sleep-episode ground truth from the System event log: one `EventLogWatcher` (Kernel-General 1, Power-Troubleshooter 1, Kernel-Power 507; 506 deliberately unconsumed) emits `system_clock_changed` (oldTime/newTime/signed timeDeltaMs/reason/process; 2 s micro-slew floor, ≥5 min = Warning+immediate) and `system_sleep_episode` (kind sleep/hibernate/modern_standby, authoritative `enteredAt`/`exitedAt` payload instants, 60 s Modern-Standby floor). WindowsUpdateTracker-style backfill (24 h default, `system-timeline-watermark.json`) recovers pre-agent records; ConfigVersion 39 (`Collectors.EnableSystemTimelineWatcher`). Consumers: TimeJumpBadge cause `clock-set` (ground truth beats inference), SessionInfoCard standby note next to the unchanged wall-clock duration, `SleepSpan`s in time attribution (AttributionVersion 3, RebootSpan clone), and ANALYZE-DEV-012 (info, single, ≥5 min episode; deliberately the only new rule — clock issues stay with DEV-008). + * **New**: `agent/power-state-watcher.md` — live AC/battery observation during enrollment: `PowerStateWatcherHost` subscribes to the WMI push `Win32_PowerManagementEvent EventCode 10` (no polling; re-probes `GetSystemPowerStatus` per push, 5 s trailing-edge debounce, never armed on battery-less devices, `Collectors.EnablePowerStateWatcher` kill-switch, ConfigVersion 38). The pure `PowerStateTransitionTracker` emits `power_state_change` with `transition` = ac_to_battery (Warning, immediate) / battery_to_ac (Info) / threshold_crossed at 50/30/15% (each level latched once per lifetime, lowest-crossed-only on jumps, baseline-below-level covered, emission cap 20). Classified non-activity on both sides (SignalActivityClassifier + IsPeriodicOrStallEvent). New analyze rules ANALYZE-DEV-009 (thresholdPercent=15, high) and ANALYZE-DEV-010 (transition=ac_to_battery, warning), both with `on_event:power_state_change` interim triggers and deliberately single-required-condition (event_data conditions have no same-instance join). * **Update**: `rules/rule-id-namespace.md` — the export→paste round-trip is no longer lossy: the JSON editors now map rule-shaped exports into the form (`gatherRuleToForm` unflattens the nested gather `parameters` object, analyze `jsonToForm` maps `evaluateOn` onto the eval checkboxes; `tags` and the effective `markSessionAsFailed` carry into the created rule). Both editors still accept the serialized-form shape; edit-mode pastes merge, with an explicit `parameters`/`evaluateOn` winning over stale flat fields. diff --git a/rules/analyze/ANALYZE-DEV-012.json b/rules/analyze/ANALYZE-DEV-012.json new file mode 100644 index 00000000..e3ec29bb --- /dev/null +++ b/rules/analyze/ANALYZE-DEV-012.json @@ -0,0 +1,49 @@ +{ + "$schema": "../schema/analyze-rule.schema.json", + "ruleId": "ANALYZE-DEV-012", + "title": "Device Entered Standby During Enrollment", + "description": "Detects that the device completed a sleep, hibernate or Modern Standby episode of at least 5 minutes while the enrollment was running (system_sleep_episode event from the agent's system timeline watcher, recorded retroactively at wake from the Windows event log — pre-agent episodes are backfilled). Uses a single required condition on the episode's durationSeconds so the match is pinned to one event instance and the interpolated duration is the matched value. Short Modern Standby screen-off scenarios (under 60 s of real sleep) never emit the event, and this rule adds a 5-minute floor so brief lid-close moments do not fire it.", + "severity": "info", + "category": "device", + "version": "1.0.0", + "enabled": true, + "evaluateOn": [ + "enrollment_end", + "whiteglove_sealed", + "on_event:system_sleep_episode" + ], + "trigger": "single", + "baseConfidence": 90, + "confidenceThreshold": 60, + "conditions": [ + { + "signal": "slept_during_enrollment", + "source": "event_data", + "eventType": "system_sleep_episode", + "dataField": "durationSeconds", + "operator": "gte", + "value": "300", + "required": true + } + ], + "explanation": "The device was asleep for {{durationSeconds}} seconds during the enrollment window. Nothing progresses while the device sleeps — downloads pause, the IME stops processing and the ESP simply waits — so the wall-clock enrollment duration includes this pause and can look much slower than the enrollment actually was. The matched system_sleep_episode event in the session timeline carries the exact enter/exit times, the episode kind (sleep, hibernate or Modern Standby) and, for Modern Standby, whether the device was on AC power. A long unexplained gap in the timeline right before that event is this pause, not missing telemetry.", + "remediation": [ + { + "title": "Keep the device awake during enrollment", + "steps": [ + "Check the matched system_sleep_episode event in the timeline for the episode bounds and kind — the enrollment duration minus the episode duration is the real active time.", + "If the device slept on battery, connect AC power during setup; Windows sleeps far more aggressively on battery.", + "Instruct users/technicians to keep the lid open and the device powered until the enrollment finishes.", + "For recurring cases, review the power plan applied during OOBE/ESP (e.g. via provisioning or Intune policy) — consider disabling sleep on AC for the enrollment window." + ] + } + ], + "markSessionAsFailedDefault": false, + "tags": [ + "device", + "power", + "standby", + "sleep", + "environment" + ] +} diff --git a/rules/dist/analyze-rules.json b/rules/dist/analyze-rules.json index ded7f32c..e3a5dacd 100644 --- a/rules/dist/analyze-rules.json +++ b/rules/dist/analyze-rules.json @@ -1678,6 +1678,54 @@ "environment" ] }, + { + "ruleId": "ANALYZE-DEV-012", + "title": "Device Entered Standby During Enrollment", + "description": "Detects that the device completed a sleep, hibernate or Modern Standby episode of at least 5 minutes while the enrollment was running (system_sleep_episode event from the agent's system timeline watcher, recorded retroactively at wake from the Windows event log — pre-agent episodes are backfilled). Uses a single required condition on the episode's durationSeconds so the match is pinned to one event instance and the interpolated duration is the matched value. Short Modern Standby screen-off scenarios (under 60 s of real sleep) never emit the event, and this rule adds a 5-minute floor so brief lid-close moments do not fire it.", + "severity": "info", + "category": "device", + "version": "1.0.0", + "enabled": true, + "evaluateOn": [ + "enrollment_end", + "whiteglove_sealed", + "on_event:system_sleep_episode" + ], + "trigger": "single", + "baseConfidence": 90, + "confidenceThreshold": 60, + "conditions": [ + { + "signal": "slept_during_enrollment", + "source": "event_data", + "eventType": "system_sleep_episode", + "dataField": "durationSeconds", + "operator": "gte", + "value": "300", + "required": true + } + ], + "explanation": "The device was asleep for {{durationSeconds}} seconds during the enrollment window. Nothing progresses while the device sleeps — downloads pause, the IME stops processing and the ESP simply waits — so the wall-clock enrollment duration includes this pause and can look much slower than the enrollment actually was. The matched system_sleep_episode event in the session timeline carries the exact enter/exit times, the episode kind (sleep, hibernate or Modern Standby) and, for Modern Standby, whether the device was on AC power. A long unexplained gap in the timeline right before that event is this pause, not missing telemetry.", + "remediation": [ + { + "title": "Keep the device awake during enrollment", + "steps": [ + "Check the matched system_sleep_episode event in the timeline for the episode bounds and kind — the enrollment duration minus the episode duration is the real active time.", + "If the device slept on battery, connect AC power during setup; Windows sleeps far more aggressively on battery.", + "Instruct users/technicians to keep the lid open and the device powered until the enrollment finishes.", + "For recurring cases, review the power plan applied during OOBE/ESP (e.g. via provisioning or Intune policy) — consider disabling sleep on AC for the enrollment window." + ] + } + ], + "markSessionAsFailedDefault": false, + "tags": [ + "device", + "power", + "standby", + "sleep", + "environment" + ] + }, { "ruleId": "ANALYZE-ENRL-001", "title": "Enrollment Failed", diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/SystemTimelineTrackerTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/SystemTimelineTrackerTests.cs new file mode 100644 index 00000000..eeddb18d --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Monitoring/SystemSignals/SystemTimelineTrackerTests.cs @@ -0,0 +1,429 @@ +#nullable enable +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 AutopilotMonitor.Shared; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals +{ + /// + /// SystemTimelineTracker — clock steps (Kernel-General 1) and completed sleep episodes + /// (Power-Troubleshooter 1 / Kernel-Power 507) from the System channel. Drives the primitive + /// test seam (no real EventRecord, which is + /// abstract + Windows-only), mirroring the WindowsUpdateTracker test pattern. + /// + public sealed class SystemTimelineTrackerTests : IDisposable + { + private static readonly DateTime At = new DateTime(2026, 8, 21, 10, 0, 0, DateTimeKind.Utc); + + private readonly TempDirectory _tmp = new TempDirectory(); + private readonly FakeSignalIngressSink _sink; + private readonly SystemTimelineTracker _tracker; + private long _nextRecordId = 1; + + public SystemTimelineTrackerTests() + { + _sink = new FakeSignalIngressSink(); + var post = new InformationalEventPost(_sink, new VirtualClock(At)); + var logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + _tracker = new SystemTimelineTracker( + sessionId: "sess-stl", + tenantId: "tenant-stl", + post: post, + logger: logger, + backfillEnabled: false, + stateDirectory: null); // in-memory dedup for most tests + } + + public void Dispose() => _tmp.Dispose(); + + // ------------------------------------------------------------------- + // Emission helpers + // ------------------------------------------------------------------- + + private void EmitClockChange( + DateTime? oldTime, DateTime? newTime, string? rawDeltaMs = null, + int reason = 1, long? recordId = null, bool isBackfill = false, DateTime? timeCreatedUtc = null) + { + var data = new Dictionary(StringComparer.OrdinalIgnoreCase); + if (oldTime.HasValue) data["OldTime"] = oldTime.Value.ToString("o"); + if (newTime.HasValue) data["NewTime"] = newTime.Value.ToString("o"); + if (rawDeltaMs != null) data["TimeDeltaInMs"] = rawDeltaMs; + data["Reason"] = reason.ToString(); + data["ProcessName"] = @"\Device\HarddiskVolume3\Windows\System32\svchost.exe"; + data["ProcessID"] = "6892"; + + _tracker.ProcessEvent( + providerName: SystemTimelineTracker.ProviderKernelGeneral, + eventId: SystemTimelineTracker.EventId_ClockChange, + recordId: recordId ?? _nextRecordId++, + timeCreatedUtc: timeCreatedUtc ?? At, + eventData: data, + isBackfill: isBackfill); + } + + private void EmitClassicResume( + DateTime sleepTime, DateTime wakeTime, string? effectiveState = "1", + string? wakeSourceText = null, long? recordId = null, bool isBackfill = false, DateTime? timeCreatedUtc = null) + { + var data = new Dictionary(StringComparer.OrdinalIgnoreCase) + { + ["SleepTime"] = sleepTime.ToString("o"), + ["WakeTime"] = wakeTime.ToString("o"), + ["WakeSourceType"] = "0", + }; + if (effectiveState != null) data["EffectiveState"] = effectiveState; + if (wakeSourceText != null) data["WakeSourceText"] = wakeSourceText; + + _tracker.ProcessEvent( + providerName: SystemTimelineTracker.ProviderPowerTroubleshooter, + eventId: SystemTimelineTracker.EventId_ClassicResume, + recordId: recordId ?? _nextRecordId++, + timeCreatedUtc: timeCreatedUtc ?? wakeTime, + eventData: data, + isBackfill: isBackfill); + } + + private void EmitModernStandbyExit( + long sleepDurationUs, long durationUs, string powerStateAc = "true", + long? recordId = null, bool isBackfill = false, DateTime? timeCreatedUtc = null) + { + var data = new Dictionary(StringComparer.OrdinalIgnoreCase) + { + ["SleepDurationInUs"] = sleepDurationUs.ToString(), + ["DurationInUs"] = durationUs.ToString(), + ["Reason"] = "32", + ["PowerStateAc"] = powerStateAc, + ["BatteryRemainingCapacityOnExit"] = "34180", + }; + + _tracker.ProcessEvent( + providerName: SystemTimelineTracker.ProviderKernelPower, + eventId: SystemTimelineTracker.EventId_ModernStandbyExit, + recordId: recordId ?? _nextRecordId++, + timeCreatedUtc: timeCreatedUtc ?? At, + eventData: data, + isBackfill: isBackfill); + } + + private IReadOnlyList ByType(string eventType) => + _sink.Posted.Where(p => + p.Kind == DecisionSignalKind.InformationalEvent + && p.Payload != null + && p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et) + && et == eventType).ToList(); + + private static IReadOnlyDictionary Data(FakeSignalIngressSink.PostedSignal s) => + (IReadOnlyDictionary)s.TypedPayload!; + + // ------------------------------------------------------------------- + // system_clock_changed + // ------------------------------------------------------------------- + + [Fact] + public void ClockStep_AboveThreshold_EmitsInfo_WithSignedDeltaAndNormalizedTimes() + { + var oldTime = At; + var newTime = At.AddSeconds(10); + EmitClockChange(oldTime, newTime, reason: 1); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + Assert.Equal("Info", s.Payload![SignalPayloadKeys.Severity]); + Assert.Equal("false", s.Payload![SignalPayloadKeys.ImmediateUpload]); + + var data = Data(s); + Assert.Equal(10_000L, data["timeDeltaMs"]); + Assert.Equal("application_set", data["reasonText"]); + Assert.Equal(1, data["reason"]); + Assert.Equal(oldTime.ToString("o"), data["oldTime"]); + Assert.Equal(newTime.ToString("o"), data["newTime"]); + Assert.Equal(6892, data["processId"]); + Assert.Contains("forward", (string)s.Payload![SignalPayloadKeys.Message]); + Assert.Contains("svchost.exe", (string)s.Payload![SignalPayloadKeys.Message]); + } + + [Theory] + [InlineData(1)] + [InlineData(1999)] + public void ClockMicroStep_BelowThreshold_Suppressed(int deltaMs) + { + EmitClockChange(At, At.AddMilliseconds(deltaMs)); + Assert.Empty(ByType(Constants.EventTypes.SystemClockChanged)); + } + + [Fact] + public void ClockStep_Backward_EmitsNegativeDelta() + { + EmitClockChange(oldTime: At, newTime: At.AddSeconds(-3)); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + Assert.Equal(-3000L, Data(s)["timeDeltaMs"]); + Assert.Contains("backward", (string)s.Payload![SignalPayloadKeys.Message]); + } + + [Fact] + public void ClockStep_AtLeastFiveMinutes_WarningAndImmediateUpload() + { + EmitClockChange(At, At.AddMinutes(5), reason: 2); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + Assert.Equal("Warning", s.Payload![SignalPayloadKeys.Severity]); + Assert.Equal("true", s.Payload![SignalPayloadKeys.ImmediateUpload]); + Assert.Equal("hardware_clock_sync", Data(s)["reasonText"]); + } + + [Fact] + public void ClockStep_NoUsableTimesOrDelta_Skipped() + { + EmitClockChange(oldTime: null, newTime: null, rawDeltaMs: "not-a-number"); + Assert.Empty(ByType(Constants.EventTypes.SystemClockChanged)); + } + + [Fact] + public void ClockStep_FallsBackToTimeDeltaInMs_WhenTimesUnparseable() + { + // Only the raw delta parses — the direction information of NewTime/OldTime is gone, + // but the magnitude still gates and emits. + EmitClockChange(oldTime: null, newTime: null, rawDeltaMs: "7200000"); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + Assert.Equal(7_200_000L, Data(s)["timeDeltaMs"]); + } + + // ------------------------------------------------------------------- + // system_sleep_episode — classic (Power-Troubleshooter 1) + // ------------------------------------------------------------------- + + [Fact] + public void ClassicResume_EffectiveState5_EmitsHibernateEpisode() + { + var sleepAt = At.AddHours(-2); + EmitClassicResume(sleepAt, At, effectiveState: "5", wakeSourceText: "Power Button"); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode)); + Assert.Equal("Info", s.Payload![SignalPayloadKeys.Severity]); + + var data = Data(s); + Assert.Equal("hibernate", data["kind"]); + Assert.Equal(7200L, data["durationSeconds"]); + Assert.Equal(sleepAt.ToString("o"), data["enteredAt"]); + Assert.Equal(At.ToString("o"), data["exitedAt"]); + Assert.Equal("Power Button", data["wakeSourceText"]); + Assert.Contains("hibernate", (string)s.Payload![SignalPayloadKeys.Message]); + } + + [Fact] + public void ClassicResume_NonHibernateState_EmitsSleepKind() + { + EmitClassicResume(At.AddMinutes(-30), At, effectiveState: "4"); + Assert.Equal("sleep", Data(Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode)))["kind"]); + } + + [Fact] + public void ClassicResume_ShortEpisode_StillEmits() + { + // No duration floor for classic sleep: the event only exists for genuinely completed + // S3/S4 transitions, so a 30 s real sleep is still signal. + EmitClassicResume(At.AddSeconds(-30), At); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode)); + Assert.Equal(30L, Data(s)["durationSeconds"]); + } + + // ------------------------------------------------------------------- + // system_sleep_episode — Modern Standby (Kernel-Power 507) + // ------------------------------------------------------------------- + + [Fact] + public void ModernStandbyExit_EmitsEpisode_WithDerivedEnterTime() + { + // Values from a live 507 on this dev machine: 38 min scenario, ~38 min actual sleep. + EmitModernStandbyExit(sleepDurationUs: 2_324_095_807, durationUs: 2_330_201_652); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode)); + var data = Data(s); + Assert.Equal("modern_standby", data["kind"]); + Assert.Equal(2330L, data["durationSeconds"]); + Assert.Equal(2324L, data["sleepDurationSeconds"]); + Assert.Equal(true, data["onAcPower"]); + Assert.Equal(34180L, data["batteryRemainingCapacityOnExit"]); + Assert.Equal(At.ToString("o"), data["exitedAt"]); + Assert.Equal(At.AddMilliseconds(-2_330_201.652).ToString("o"), data["enteredAt"]); + Assert.Contains("Modern Standby", (string)s.Payload![SignalPayloadKeys.Message]); + } + + [Fact] + public void ModernStandbyExit_SleepBelowFloor_Suppressed() + { + EmitModernStandbyExit(sleepDurationUs: 30_000_000, durationUs: 90_000_000); // 30 s sleep + Assert.Empty(ByType(Constants.EventTypes.SystemSleepEpisode)); + } + + [Fact] + public void ModernStandbyExit_ScreenOffWithoutSleep_Suppressed() + { + // SleepEntered=false scenarios carry SleepDurationInUs 0 — the single duration gate + // suppresses them without a separate branch. + EmitModernStandbyExit(sleepDurationUs: 0, durationUs: 6_106_696); + Assert.Empty(ByType(Constants.EventTypes.SystemSleepEpisode)); + } + + [Fact] + public void ModernStandbyExit_ScenarioShorterThanSleep_ClampsToSleepDuration() + { + EmitModernStandbyExit(sleepDurationUs: 120_000_000, durationUs: 0); + + var data = Data(Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode))); + Assert.Equal(120L, data["durationSeconds"]); + Assert.Equal(120L, data["sleepDurationSeconds"]); + } + + // ------------------------------------------------------------------- + // Backfill semantics + // ------------------------------------------------------------------- + + [Fact] + public void BackfilledEvent_UsesEventTimeForTimelineTimestamp_AndFlagsData() + { + // A pre-agent standby episode (record created before the agent started) must land on + // the timeline where the device actually woke, not at agent start. + var wakeTime = At.AddHours(-3); + EmitClassicResume(wakeTime.AddHours(-1), wakeTime, isBackfill: true, timeCreatedUtc: wakeTime); + + var s = Assert.Single(ByType(Constants.EventTypes.SystemSleepEpisode)); + Assert.Equal(wakeTime, s.OccurredAtUtc); + Assert.Equal(true, Data(s)["backfilled"]); + } + + // ------------------------------------------------------------------- + // Dedup / watermark + // ------------------------------------------------------------------- + + [Fact] + public void SameRecordId_ProcessedTwice_EmitsOnce() + { + EmitClockChange(At, At.AddMinutes(1), recordId: 42); + EmitClockChange(At, At.AddMinutes(1), recordId: 42); + + Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + } + + [Fact] + public void BackfillEventWithLowerRecordId_AfterLiveEvent_IsStillEmitted() + { + // The live watcher is armed BEFORE backfill runs, so a live record with a higher + // RecordId can be processed first. An older, never-emitted backfill record must NOT be + // suppressed — pre-agent episodes are the whole point (high-water-mark trap). + EmitClockChange(At, At.AddMinutes(1), recordId: 100); // live, high + EmitClockChange(At, At.AddMinutes(2), recordId: 50, isBackfill: true); // backfill, older + + Assert.Equal(2, ByType(Constants.EventTypes.SystemClockChanged).Count); + } + + [Fact] + public void Watermark_PersistsAcrossTrackerInstances() + { + var post = new InformationalEventPost(_sink, new VirtualClock(At)); + var logger = new AgentLogger(_tmp.Path, AgentLogLevel.Info); + var clockData = new Dictionary(StringComparer.OrdinalIgnoreCase) + { + ["OldTime"] = At.ToString("o"), + ["NewTime"] = At.AddMinutes(10).ToString("o"), + ["Reason"] = "1", + }; + + var first = new SystemTimelineTracker("s", "t", post, logger, backfillEnabled: false, stateDirectory: _tmp.Path); + first.ProcessEvent(SystemTimelineTracker.ProviderKernelGeneral, SystemTimelineTracker.EventId_ClockChange, + recordId: 500, timeCreatedUtc: At, eventData: clockData, isBackfill: false); + + // A fresh tracker (agent restart) must load the watermark and skip the already-emitted + // record when the backfill re-reads it. + var second = new SystemTimelineTracker("s", "t", post, logger, backfillEnabled: false, stateDirectory: _tmp.Path); + second.LoadWatermark(); + second.ProcessEvent(SystemTimelineTracker.ProviderKernelGeneral, SystemTimelineTracker.EventId_ClockChange, + recordId: 500, timeCreatedUtc: At, eventData: clockData, isBackfill: true); + + Assert.Single(ByType(Constants.EventTypes.SystemClockChanged)); + } + + [Fact] + public void UnknownProviderOrEventId_Ignored() + { + _tracker.ProcessEvent("Microsoft-Windows-Kernel-Power", eventId: 566, recordId: _nextRecordId++, + timeCreatedUtc: At, eventData: new Dictionary(), isBackfill: false); + _tracker.ProcessEvent("Some-Other-Provider", eventId: 1, recordId: _nextRecordId++, + timeCreatedUtc: At, eventData: new Dictionary(), isBackfill: false); + + Assert.Empty(_sink.Posted); + } + + // ------------------------------------------------------------------- + // XPath + parsing + // ------------------------------------------------------------------- + + [Fact] + public void BuildXPath_ContainsAllThreeProviderIdPairs_AndNo506() + { + var xpath = SystemTimelineTracker.BuildXPath(); + Assert.Contains("Provider[@Name='Microsoft-Windows-Kernel-General'] and EventID=1", xpath); + Assert.Contains("Provider[@Name='Microsoft-Windows-Power-Troubleshooter'] and EventID=1", xpath); + Assert.Contains("Provider[@Name='Microsoft-Windows-Kernel-Power'] and EventID=507", xpath); + Assert.DoesNotContain("506", xpath); + } + + [Fact] + public void BuildBackfillXPath_AppendsTimediffClause() + { + var xpath = SystemTimelineTracker.BuildBackfillXPath(86_400_000); + Assert.Contains("TimeCreated[timediff(@SystemTime) <= 86400000]", xpath); + Assert.Contains("EventID=507", xpath); + } + + [Fact] + public void ParseEventData_RealKernelGeneralPayload_YieldsAuthoritativeFields() + { + // Verbatim (values shortened) from a live Kernel-General 1 record on a 26220 dev machine. + const string xml = + "" + + "1" + + "" + + "2026-08-21T09:40:02.1987028Z" + + "2026-08-21T09:40:02.1973028Z" + + "1" + + "1" + + "\\Device\\HarddiskVolume3\\Windows\\System32\\svchost.exe" + + "6892" + + ""; + + var data = SystemTimelineTracker.ParseEventData(xml); + Assert.Equal("1", data["TimeDeltaInMs"]); + Assert.Equal("2026-08-21T09:40:02.1987028Z", data["newtime"]); // case-insensitive keys + Assert.NotNull(SystemTimelineTracker.TryParseUtc(data["OldTime"])); + } + + [Fact] + public void FormatDuration_CompactForms() + { + Assert.Equal("2h 05m", SystemTimelineTracker.FormatDuration(TimeSpan.FromMinutes(125))); + Assert.Equal("56m 12s", SystemTimelineTracker.FormatDuration(TimeSpan.FromSeconds(56 * 60 + 12))); + Assert.Equal("45s", SystemTimelineTracker.FormatDuration(TimeSpan.FromSeconds(45))); + } + + [Fact] + public void ProcessLeafName_StripsDevicePath() + { + Assert.Equal("svchost.exe", + SystemTimelineTracker.ProcessLeafName(@"\Device\HarddiskVolume3\Windows\System32\svchost.exe")); + Assert.Null(SystemTimelineTracker.ProcessLeafName(null)); + Assert.Null(SystemTimelineTracker.ProcessLeafName(@"\Device\HarddiskVolume3\")); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/SystemTimelineWatcherHostTests.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/SystemTimelineWatcherHostTests.cs new file mode 100644 index 00000000..2a584643 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core.Tests/Orchestration/SystemTimelineWatcherHostTests.cs @@ -0,0 +1,57 @@ +#nullable enable +using System; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Agent.V2.Core.Tests.Harness; +using AutopilotMonitor.DecisionCore.Engine; +using Xunit; + +namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration +{ + /// + /// SystemTimelineWatcherHost — thin ICollectorHost wrapper over SystemTimelineTracker. + /// Real event-log arming stays untested by convention (ConsoleBypassWatcher precedent); + /// these tests pin the lifecycle contract only. + /// + public sealed class SystemTimelineWatcherHostTests : IDisposable + { + private readonly TempDirectory _tmp = new TempDirectory(); + + public void Dispose() => _tmp.Dispose(); + + private SystemTimelineWatcherHost CreateHost() => new SystemTimelineWatcherHost( + sessionId: "sess-stl", + tenantId: "tenant-stl", + logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info), + ingress: new FakeSignalIngressSink(), + clock: new VirtualClock(new DateTime(2026, 8, 21, 10, 0, 0, DateTimeKind.Utc)), + backfillLookbackMinutes: 0, + stateDirectory: _tmp.Path); + + [Fact] + public void Stop_BeforeStart_DoesNotThrow() + { + using (var host = CreateHost()) + { + host.Stop(); + } + } + + [Fact] + public void Dispose_Twice_DoesNotThrow() + { + var host = CreateHost(); + host.Dispose(); + host.Dispose(); + } + + [Fact] + public void Name_IsStable() + { + using (var host = CreateHost()) + { + Assert.Equal("SystemTimelineTracker", host.Name); + } + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs new file mode 100644 index 00000000..c7997050 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/SystemSignals/SystemTimelineTracker.cs @@ -0,0 +1,681 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics.Eventing.Reader; +using System.Globalization; +using System.IO; +using System.Linq; +using System.Xml.Linq; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Orchestration; +using AutopilotMonitor.Shared; +using AutopilotMonitor.Shared.Models; +using Newtonsoft.Json; + +namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals +{ + /// + /// Watches the System event log for two enrollment blind spots and forwards them as + /// timeline ground truth: + /// + /// System clock steps (Kernel-General EventID 1) → system_clock_changed. + /// The payload carries oldTime/newTime/timeDeltaMs plus the + /// setting process — the "clock set from X to Y" fact that today has to be inferred + /// from timestamp discontinuities. w32time also logs frequent 1 ms micro-slews on the + /// same EventID, so emissions are gated on . + /// Completed sleep episodes → system_sleep_episode. Classic S3/S4 comes + /// from Power-Troubleshooter EventID 1 (one event per episode at wake, carrying + /// SleepTime + WakeTime). Modern Standby comes from Kernel-Power EventID 507 (exit), + /// whose payload carries the scenario duration and the actual sleep residency; the + /// enter time is derived as exit − duration. Kernel-Power 506 (enter) is deliberately + /// NOT consumed: 507 already carries everything, and pairing 506/507 would need an + /// orphan-tolerant state machine across agent restarts for zero information gain — + /// an episode without a 507 never completed and would not be emitted under any design. + /// + /// + /// Payload times are authoritative. The decisive clock correction (w32time fixing a + /// wrong BIOS clock) happens exactly when the device clock is untrustworthy, and the backend + /// clamps implausible event timestamps to server time. All semantic instants therefore travel + /// as explicit ISO-8601 payload fields, never only as the event's own Timestamp. + /// + /// + /// Backfill + cross-restart dedup mirror : the System + /// .evtx persists across the OOBE reboots, so a startup scan recovers pre-agent clock steps + /// and standby episodes; a persisted RecordId watermark plus an intra-run seen-set (a HashSet, + /// NOT a high-water mark — see the field comment) keep restarts from re-emitting. + /// + /// + internal sealed class SystemTimelineTracker : IDisposable + { + internal const string Channel = "System"; + + internal const string ProviderKernelGeneral = "Microsoft-Windows-Kernel-General"; // EventID 1: system time changed + internal const string ProviderPowerTroubleshooter = "Microsoft-Windows-Power-Troubleshooter"; // EventID 1: resumed from classic sleep/hibernate + internal const string ProviderKernelPower = "Microsoft-Windows-Kernel-Power"; // EventID 507: Modern Standby exit + + internal const int EventId_ClockChange = 1; + internal const int EventId_ClassicResume = 1; + internal const int EventId_ModernStandbyExit = 507; + + internal const string WatermarkStateFileName = "system-timeline-watermark.json"; + + // w32time logs Kernel-General 1 for routine 1 ms slew corrections (verified live: several + // per hour). Only genuine steps are timeline-relevant; anything below this is claimed in + // the dedup set but never emitted. + internal const long MinClockDeltaMs = 2000; + + // A step of at least 5 minutes can invalidate token/cert validation windows and visibly + // reorders the timeline (matches the web's TimeJumpBadge threshold) — surface it fast. + internal const long ClockDeltaWarningMs = 5 * 60 * 1000; + + // Modern Standby logs a 506/507 pair for every screen-off scenario, including seconds-long + // ones where the device never actually slept (SleepDurationInUs 0). Only episodes with + // real sleep residency are emitted. Classic Power-Troubleshooter episodes have no floor: + // they only exist for genuinely completed S3/S4 transitions. + internal const long MinSleepDurationSeconds = 60; + + private readonly AgentLogger _logger; + private readonly string _sessionId; + private readonly string _tenantId; + private readonly InformationalEventPost _post; + private readonly bool _backfillEnabled; + private readonly int _backfillLookbackMinutes; + private readonly string _stateDirectory; + + private EventLogWatcher _watcher; + + // Dedup. Guarded because EventRecordWritten callbacks run concurrently with the backfill scan. + // + // Cross-restart boundary loaded from disk: the highest RecordId emitted in a PRIOR run. + // Immutable during this run — records at/below it were already emitted before this process + // started and must not be re-emitted by the backfill scan. + private long _restartWatermark = -1; + // RecordIds claimed in THIS run — the intra-run dedup set. Deliberately a HashSet, NOT a + // high-water mark: the live watcher is armed before the backfill runs, so a live record with + // a HIGHER RecordId can be processed before/during backfill. A high-water mark would then + // make the dedup skip every older, never-emitted backfill record — silently dropping exactly + // the pre-agent clock corrections and standby episodes this tracker exists for. The targeted + // records are low-volume, so the set stays tiny. + private readonly HashSet _seenThisRun = new HashSet(); + // Highest RecordId claimed so far (max of restart watermark + this run). Persisted so the + // next run's restart watermark is correct. + private long _maxEmittedRecordId = -1; + private readonly object _watermarkLock = new object(); + + public SystemTimelineTracker( + string sessionId, + string tenantId, + InformationalEventPost post, + AgentLogger logger, + bool backfillEnabled = true, + int backfillLookbackMinutes = 1440, + string stateDirectory = 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)); + _backfillEnabled = backfillEnabled; + _backfillLookbackMinutes = backfillLookbackMinutes; + _stateDirectory = stateDirectory != null ? Environment.ExpandEnvironmentVariables(stateDirectory) : null; + } + + public void Start() + { + LoadWatermark(); + StartWatcher(); + + if (_backfillEnabled && _backfillLookbackMinutes > 0) + BackfillRecentEvents(); + else + _logger.Info("SystemTimeline backfill disabled by config"); + } + + public void Stop() + { + if (_watcher == null) return; + try + { + _watcher.Enabled = false; + _watcher.Dispose(); + _logger.Info("SystemTimeline watcher stopped"); + } + catch (Exception ex) + { + _logger.Error("Error stopping SystemTimeline watcher", ex); + } + finally + { + _watcher = null; + } + } + + public void Dispose() => Stop(); + + // ----------------------------------------------------------------------- + // Watcher lifecycle + // ----------------------------------------------------------------------- + + private void StartWatcher() + { + try + { + var query = new EventLogQuery(Channel, PathType.LogName, BuildXPath()); + _watcher = new EventLogWatcher(query); + _watcher.EventRecordWritten += OnEventRecordWritten; + _watcher.Enabled = true; + _logger.Info($"SystemTimeline watcher started: {Channel} (clock changes + sleep episodes)"); + } + catch (EventLogNotFoundException) + { + _logger.Warning($"SystemTimeline event log not found: {Channel} (normal on non-Windows test environments)"); + } + catch (UnauthorizedAccessException ex) + { + _logger.Warning($"SystemTimeline watcher access denied for {Channel}: {ex.Message}"); + } + catch (Exception ex) + { + _logger.Error($"Failed to start SystemTimeline watcher for {Channel}", ex); + CollectorDegradationReporter.Report(_post, _sessionId, _tenantId, + collectorName: "SystemTimelineTracker", reason: $"watcher_arm_failed:{Channel}", ex: ex); + } + } + + /// + /// Provider-qualified XPath for the three targeted signals. Provider filtering is mandatory + /// on the System channel — EventID 1 alone matches many unrelated providers. + /// Exposed as internal for tests. + /// + internal static string BuildXPath() => + "*[System[" + ProviderIdClauses() + "]]"; + + /// Backfill variant of with the lookback window applied. + internal static string BuildBackfillXPath(long lookbackMs) => + "*[System[(" + ProviderIdClauses() + $") and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]"; + + private static string ProviderIdClauses() => + $"(Provider[@Name='{ProviderKernelGeneral}'] and EventID={EventId_ClockChange})" + + $" or (Provider[@Name='{ProviderPowerTroubleshooter}'] and EventID={EventId_ClassicResume})" + + $" or (Provider[@Name='{ProviderKernelPower}'] and EventID={EventId_ModernStandbyExit})"; + + // ----------------------------------------------------------------------- + // Event processing + // ----------------------------------------------------------------------- + + private void OnEventRecordWritten(object sender, EventRecordWrittenEventArgs e) + { + if (e.EventRecord == null) return; + try + { + ProcessRecord(e.EventRecord, isBackfill: false); + } + catch (Exception ex) + { + _logger.Error("Error processing SystemTimeline event", ex); + } + } + + private void ProcessRecord(EventRecord record, bool isBackfill) + { + var recordId = record.RecordId ?? -1; + + // Cheap dedup gate BEFORE the XML rendering work. + if (IsAlreadyProcessed(recordId)) + return; + + string xml = null; + try { xml = record.ToXml(); } + catch { /* fall through with empty EventData */ } + + ProcessEvent( + providerName: record.ProviderName, + eventId: record.Id, + recordId: recordId, + timeCreatedUtc: record.TimeCreated?.ToUniversalTime(), + eventData: ParseEventData(xml), + isBackfill: isBackfill); + } + + /// + /// Core processing extracted to primitive inputs so tests can drive it without synthesizing + /// an abstract, Windows-only (WindowsUpdateTracker test-seam + /// pattern; a plain dictionary instead of named args because three providers with ~10 + /// payload fields each make a fixed signature impractical). + /// + internal void ProcessEvent( + string providerName, + int eventId, + long recordId, + DateTime? timeCreatedUtc, + Dictionary eventData, + bool isBackfill) + { + if (!MarkProcessed(recordId)) + return; // already emitted (cross-restart or duplicate delivery) + + eventData = eventData ?? new Dictionary(StringComparer.OrdinalIgnoreCase); + + if (string.Equals(providerName, ProviderKernelGeneral, StringComparison.OrdinalIgnoreCase) && eventId == EventId_ClockChange) + HandleClockChange(recordId, timeCreatedUtc, eventData, isBackfill); + else if (string.Equals(providerName, ProviderPowerTroubleshooter, StringComparison.OrdinalIgnoreCase) && eventId == EventId_ClassicResume) + HandleClassicResume(recordId, timeCreatedUtc, eventData, isBackfill); + else if (string.Equals(providerName, ProviderKernelPower, StringComparison.OrdinalIgnoreCase) && eventId == EventId_ModernStandbyExit) + HandleModernStandbyExit(recordId, timeCreatedUtc, eventData, isBackfill); + // Anything else slipped past the XPath filter — ignore. + } + + // ----------------------------------------------------------------------- + // system_clock_changed (Kernel-General EventID 1) + // ----------------------------------------------------------------------- + + private void HandleClockChange(long recordId, DateTime? timeCreatedUtc, Dictionary eventData, bool isBackfill) + { + eventData.TryGetValue("NewTime", out var newTimeRaw); + eventData.TryGetValue("OldTime", out var oldTimeRaw); + var newTime = TryParseUtc(newTimeRaw); + var oldTime = TryParseUtc(oldTimeRaw); + + // Signed delta preferably from the authoritative instants (NewTime − OldTime carries + // the direction unambiguously); TimeDeltaInMs is the fallback when either fails to + // parse. Records with neither are unusable and skipped (already claimed by dedup). + long deltaMs; + if (newTime.HasValue && oldTime.HasValue) + { + deltaMs = (long)Math.Round((newTime.Value - oldTime.Value).TotalMilliseconds); + } + else if (eventData.TryGetValue("TimeDeltaInMs", out var deltaRaw) && + long.TryParse(deltaRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var parsedDelta)) + { + deltaMs = parsedDelta; + } + else + { + _logger.Debug($"SystemTimeline: clock-change record {recordId} has no usable times/delta — skipped"); + return; + } + + if (Math.Abs(deltaMs) < MinClockDeltaMs) + return; // w32time micro-slew — claimed (MarkProcessed) but never emitted + + eventData.TryGetValue("Reason", out var reasonRaw); + int.TryParse(reasonRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var reason); + var reasonText = reason == 1 ? "application_set" + : reason == 2 ? "hardware_clock_sync" + : "unknown"; + + eventData.TryGetValue("ProcessName", out var processName); + + var data = new Dictionary + { + { "timeDeltaMs", deltaMs }, + { "reason", reason }, + { "reasonText", reasonText }, + { "backfilled", isBackfill }, + }; + // Authoritative instants: re-normalized ISO-8601 when parseable, raw pass-through + // otherwise — the payload must survive even a malformed provider rendering. + data["newTime"] = newTime.HasValue ? newTime.Value.ToString("o") : (object)(newTimeRaw ?? string.Empty); + data["oldTime"] = oldTime.HasValue ? oldTime.Value.ToString("o") : (object)(oldTimeRaw ?? string.Empty); + if (recordId >= 0) data["recordId"] = recordId; + if (timeCreatedUtc.HasValue) data["timeCreated"] = timeCreatedUtc.Value.ToString("o"); + if (!string.IsNullOrEmpty(processName)) data["processName"] = processName; + if (eventData.TryGetValue("ProcessID", out var pidRaw) && + int.TryParse(pidRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var pid)) + { + data["processId"] = pid; + } + + var direction = deltaMs >= 0 ? "forward" : "backward"; + var processLeaf = ProcessLeafName(processName); + var message = $"System clock stepped {direction} {FormatDuration(TimeSpan.FromMilliseconds(Math.Abs(deltaMs)))}" + + $" (reason: {reasonText}" + (processLeaf != null ? $", process: {processLeaf})" : ")"); + + var isLargeStep = Math.Abs(deltaMs) >= ClockDeltaWarningMs; + _post.Emit(new EnrollmentEvent + { + SessionId = _sessionId, + TenantId = _tenantId, + // The record's own creation time, not UtcNow: backfilled pre-agent clock steps must + // land on the timeline where they happened (WindowsUpdateTracker convention). + Timestamp = timeCreatedUtc ?? DateTime.UtcNow, + EventType = Constants.EventTypes.SystemClockChanged, + Severity = isLargeStep ? EventSeverity.Warning : EventSeverity.Info, + Source = "SystemTimelineWatcher", + Phase = EnrollmentPhase.Unknown, + Message = message, + Data = data, + ImmediateUpload = isLargeStep, + }); + } + + // ----------------------------------------------------------------------- + // system_sleep_episode — classic sleep/hibernate (Power-Troubleshooter EventID 1) + // ----------------------------------------------------------------------- + + private void HandleClassicResume(long recordId, DateTime? timeCreatedUtc, Dictionary eventData, bool isBackfill) + { + eventData.TryGetValue("SleepTime", out var sleepRaw); + eventData.TryGetValue("WakeTime", out var wakeRaw); + var enteredAt = TryParseUtc(sleepRaw); + var exitedAt = TryParseUtc(wakeRaw); + + // EffectiveState 5 = hibernate (S4); TargetState is the fallback when the effective + // state is missing (older event versions). + eventData.TryGetValue("EffectiveState", out var effectiveState); + eventData.TryGetValue("TargetState", out var targetState); + var stateValue = !string.IsNullOrEmpty(effectiveState) ? effectiveState : targetState; + var kind = stateValue == "5" ? "hibernate" : "sleep"; + + long? durationSeconds = null; + if (enteredAt.HasValue && exitedAt.HasValue && exitedAt.Value > enteredAt.Value) + durationSeconds = (long)Math.Round((exitedAt.Value - enteredAt.Value).TotalSeconds); + + var data = new Dictionary + { + { "kind", kind }, + { "backfilled", isBackfill }, + }; + data["enteredAt"] = enteredAt.HasValue ? enteredAt.Value.ToString("o") : (object)(sleepRaw ?? string.Empty); + data["exitedAt"] = exitedAt.HasValue ? exitedAt.Value.ToString("o") : (object)(wakeRaw ?? string.Empty); + if (durationSeconds.HasValue) data["durationSeconds"] = durationSeconds.Value; + if (recordId >= 0) data["recordId"] = recordId; + if (timeCreatedUtc.HasValue) data["timeCreated"] = timeCreatedUtc.Value.ToString("o"); + if (eventData.TryGetValue("WakeSourceType", out var wakeTypeRaw) && + int.TryParse(wakeTypeRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var wakeType)) + { + data["wakeSourceType"] = wakeType; + } + eventData.TryGetValue("WakeSourceText", out var wakeText); + if (!string.IsNullOrEmpty(wakeText)) data["wakeSourceText"] = wakeText; + + var durationLabel = durationSeconds.HasValue + ? " after " + FormatDuration(TimeSpan.FromSeconds(durationSeconds.Value)) + : string.Empty; + var wakeLabel = !string.IsNullOrEmpty(wakeText) ? $" (wake source: {wakeText})" : string.Empty; + + EmitSleepEpisode(timeCreatedUtc, data, + $"Device resumed from {kind}{durationLabel}{wakeLabel}"); + } + + // ----------------------------------------------------------------------- + // system_sleep_episode — Modern Standby (Kernel-Power EventID 507) + // ----------------------------------------------------------------------- + + private void HandleModernStandbyExit(long recordId, DateTime? timeCreatedUtc, Dictionary eventData, bool isBackfill) + { + eventData.TryGetValue("SleepDurationInUs", out var sleepUsRaw); + long.TryParse(sleepUsRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var sleepUs); + var sleepDurationSeconds = sleepUs / 1_000_000; + + // Every screen-off scenario logs a 507, including seconds-long ones where the device + // never slept (SleepDurationInUs 0, incl. SleepEntered=false) — one gate covers both. + if (sleepDurationSeconds < MinSleepDurationSeconds) + return; // claimed but not an episode worth the timeline + + eventData.TryGetValue("DurationInUs", out var durationUsRaw); + long.TryParse(durationUsRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var durationUs); + if (durationUs < sleepUs) durationUs = sleepUs; // scenario duration can never undercut its sleep residency + + var durationSeconds = durationUs / 1_000_000; + var exitedAt = timeCreatedUtc; // 507 is written at scenario exit + DateTime? enteredAt = exitedAt.HasValue + ? exitedAt.Value.AddMilliseconds(-(durationUs / 1000.0)) + : (DateTime?)null; + + var data = new Dictionary + { + { "kind", "modern_standby" }, + { "durationSeconds", durationSeconds }, + { "sleepDurationSeconds", sleepDurationSeconds }, + { "backfilled", isBackfill }, + }; + if (enteredAt.HasValue) data["enteredAt"] = enteredAt.Value.ToString("o"); + if (exitedAt.HasValue) data["exitedAt"] = exitedAt.Value.ToString("o"); + if (recordId >= 0) data["recordId"] = recordId; + if (timeCreatedUtc.HasValue) data["timeCreated"] = timeCreatedUtc.Value.ToString("o"); + if (eventData.TryGetValue("Reason", out var reasonRaw) && + int.TryParse(reasonRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var reason)) + { + data["reason"] = reason; + } + bool? onAcPower = null; + if (eventData.TryGetValue("PowerStateAc", out var acRaw) && bool.TryParse(acRaw, out var ac)) + { + onAcPower = ac; + data["onAcPower"] = ac; + } + if (eventData.TryGetValue("BatteryRemainingCapacityOnExit", out var battRaw) && + long.TryParse(battRaw, NumberStyles.Integer, CultureInfo.InvariantCulture, out var batt)) + { + data["batteryRemainingCapacityOnExit"] = batt; + } + + var powerLabel = onAcPower.HasValue ? (onAcPower.Value ? ", on AC" : ", on battery") : string.Empty; + EmitSleepEpisode(timeCreatedUtc, data, + $"Device exited Modern Standby after {FormatDuration(TimeSpan.FromSeconds(durationSeconds))}" + + $" (slept {FormatDuration(TimeSpan.FromSeconds(sleepDurationSeconds))}{powerLabel})"); + } + + private void EmitSleepEpisode(DateTime? timeCreatedUtc, Dictionary data, string message) + { + _post.Emit(new EnrollmentEvent + { + SessionId = _sessionId, + TenantId = _tenantId, + // Wake/exit moment (the record's creation time) — backfilled pre-agent episodes + // must land on the timeline where the device actually woke. + Timestamp = timeCreatedUtc ?? DateTime.UtcNow, + EventType = Constants.EventTypes.SystemSleepEpisode, + Severity = EventSeverity.Info, + Source = "SystemTimelineWatcher", + Phase = EnrollmentPhase.Unknown, + Message = message, + Data = data, + ImmediateUpload = false, + }); + } + + // ----------------------------------------------------------------------- + // Parsing helpers + // ----------------------------------------------------------------------- + + /// + /// Extracts <Data Name="...">value</Data> pairs from an event's rendered + /// XML, keyed case-insensitively. Namespace-agnostic (matches on local name). Returns an + /// empty map on null/malformed XML — never throws. + /// + internal static Dictionary ParseEventData(string xml) + { + var result = new Dictionary(StringComparer.OrdinalIgnoreCase); + if (string.IsNullOrEmpty(xml)) return result; + + try + { + var doc = XDocument.Parse(xml); + foreach (var el in doc.Descendants().Where(e => e.Name.LocalName == "Data")) + { + var nameAttr = el.Attribute("Name"); + if (nameAttr == null || string.IsNullOrEmpty(nameAttr.Value)) continue; + if (!result.ContainsKey(nameAttr.Value)) + result[nameAttr.Value] = el.Value; + } + } + catch + { + // Malformed / unexpected XML — best effort, return what we have. + } + + return result; + } + + internal static DateTime? TryParseUtc(string value) + { + if (string.IsNullOrWhiteSpace(value)) return null; + return DateTime.TryParse(value, CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, out var parsed) + ? parsed + : (DateTime?)null; + } + + /// Compact human duration for messages: "2h 05m", "56m 12s", "45s". + internal static string FormatDuration(TimeSpan span) + { + if (span.TotalHours >= 1) + return $"{(long)span.TotalHours}h {span.Minutes:D2}m"; + if (span.TotalMinutes >= 1) + return $"{span.Minutes}m {span.Seconds:D2}s"; + return $"{(long)Math.Ceiling(span.TotalSeconds)}s"; + } + + /// Leaf file name of a kernel device path like \Device\HarddiskVolume3\Windows\System32\svchost.exe. + internal static string ProcessLeafName(string devicePath) + { + if (string.IsNullOrEmpty(devicePath)) return null; + var idx = devicePath.LastIndexOf('\\'); + var leaf = idx >= 0 ? devicePath.Substring(idx + 1) : devicePath; + return string.IsNullOrEmpty(leaf) ? null : leaf; + } + + // ----------------------------------------------------------------------- + // Backfill + // ----------------------------------------------------------------------- + + private void BackfillRecentEvents() + { + try + { + var lookbackMs = (long)_backfillLookbackMinutes * 60 * 1000; + _logger.Info($"SystemTimeline backfill: scanning {Channel} " + + $"(lookback={_backfillLookbackMinutes}min, restartWatermark={_restartWatermark})"); + + var query = new EventLogQuery(Channel, PathType.LogName, BuildBackfillXPath(lookbackMs)); + + int processed = 0; + using (var reader = new EventLogReader(query)) + { + EventRecord record; + while ((record = reader.ReadEvent()) != null) + { + using (record) + { + ProcessRecord(record, isBackfill: true); + processed++; + } + } + } + + if (processed == 0) + _logger.Debug($"SystemTimeline backfill: no targeted events in last {_backfillLookbackMinutes} minutes"); + else + _logger.Info($"SystemTimeline backfill: scanned {processed} record(s)"); + } + catch (EventLogNotFoundException) + { + _logger.Warning($"SystemTimeline event log not found during backfill: {Channel} (normal on non-Windows test environments)"); + } + catch (UnauthorizedAccessException ex) + { + _logger.Warning($"SystemTimeline backfill access denied: {ex.Message}"); + } + catch (Exception ex) + { + _logger.Warning($"SystemTimeline backfill failed: {ex.Message}"); + } + } + + // ----------------------------------------------------------------------- + // Watermark dedup (cross-restart) + // ----------------------------------------------------------------------- + + private bool IsAlreadyProcessed(long recordId) + { + if (recordId < 0) return false; // no RecordId → cannot dedup, let it through + lock (_watermarkLock) + { + return recordId <= _restartWatermark || _seenThisRun.Contains(recordId); + } + } + + /// + /// Atomically claims . Returns true if this is the first time we + /// see it (caller should evaluate/emit), false if it was already processed — either in a + /// PRIOR run (at/below the restart watermark) or already this run (in the seen-set). Only + /// advances + persists the max on a genuinely-new, higher RecordId. Records without a + /// RecordId (-1) are always processed, never tracked or persisted. Note: threshold-suppressed + /// records are claimed too, so a restart's backfill does not re-evaluate them. + /// + private bool MarkProcessed(long recordId) + { + if (recordId < 0) return true; + + long toPersist = -1; + lock (_watermarkLock) + { + if (recordId <= _restartWatermark || !_seenThisRun.Add(recordId)) + return false; + + if (recordId > _maxEmittedRecordId) + { + _maxEmittedRecordId = recordId; + toPersist = _maxEmittedRecordId; + } + } + if (toPersist >= 0) PersistWatermark(toPersist); + return true; + } + + internal void LoadWatermark() + { + if (string.IsNullOrEmpty(_stateDirectory)) return; + + var filePath = Path.Combine(_stateDirectory, WatermarkStateFileName); + if (!File.Exists(filePath)) return; + + try + { + var json = File.ReadAllText(filePath); + var state = JsonConvert.DeserializeObject(json); + if (state != null) + { + lock (_watermarkLock) + { + _restartWatermark = state.LastRecordId; + _maxEmittedRecordId = state.LastRecordId; + } + _logger.Info($"SystemTimeline watermark loaded: lastRecordId={state.LastRecordId} (persisted {state.PersistedUtc:O})"); + } + } + catch (Exception ex) + { + _logger.Warning($"Failed to load SystemTimeline watermark: {ex.Message}"); + } + } + + private void PersistWatermark(long recordId) + { + if (string.IsNullOrEmpty(_stateDirectory)) return; + + try + { + Directory.CreateDirectory(_stateDirectory); + var filePath = Path.Combine(_stateDirectory, WatermarkStateFileName); + var state = new WatermarkState { LastRecordId = recordId, 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 SystemTimeline watermark: {ex.Message}"); + } + } + + internal sealed class WatermarkState + { + public long LastRecordId { get; set; } + public DateTime PersistedUtc { get; set; } + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs index 81bcf624..064fef4e 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/DefaultComponentFactory.cs @@ -557,6 +557,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration stateDirectory: _stateDirectory)); } + // System timeline watcher — System channel: Kernel-General 1 (system clock stepped, + // ground truth for time jumps incl. old/new time + setting process) and completed + // sleep/standby episodes (Power-Troubleshooter 1, Kernel-Power 507). Backfill recovers + // the pre-agent OOBE clock correction and standby episodes from the persistent .evtx. + if (collectors.EnableSystemTimelineWatcher) + { + hosts.Add(new SystemTimelineWatcherHost( + sessionId: sessionId, + tenantId: tenantId, + logger: logger, + ingress: ingress, + clock: clock, + backfillLookbackMinutes: collectors.SystemEventBackfillLookbackMinutes, + stateDirectory: _stateDirectory)); + } + // ----- Peripheral hosts (event-only; driven by remote-config toggles) -------------- // V1 parity (PeriodicCollectorManager) — combine Performance + AgentSelfMetrics under diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/SystemTimelineWatcherHost.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/SystemTimelineWatcherHost.cs new file mode 100644 index 00000000..2b55e845 --- /dev/null +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/Hosts/SystemTimelineWatcherHost.cs @@ -0,0 +1,68 @@ +#nullable enable +using System; +using System.Threading; +using AutopilotMonitor.Agent.V2.Core.Logging; +using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals; +using AutopilotMonitor.DecisionCore.Engine; +using AutopilotMonitor.DecisionCore.Signals; + +namespace AutopilotMonitor.Agent.V2.Core.Orchestration +{ + /// + /// Standalone host for the — watches the System + /// event log for system clock steps (Kernel-General 1) and completed sleep/standby episodes + /// (Power-Troubleshooter 1 / Kernel-Power 507) and forwards them via the shared single-rail + /// ingress. Mirrors : builds its own + /// and delegates Start/Stop to the tracker. + /// + internal sealed class SystemTimelineWatcherHost : ICollectorHost + { + public string Name => "SystemTimelineTracker"; + + private readonly SystemTimelineTracker _tracker; + private readonly AgentLogger _logger; + private int _disposed; + + public SystemTimelineWatcherHost( + string sessionId, + string tenantId, + AgentLogger logger, + ISignalIngressSink ingress, + IClock clock, + int backfillLookbackMinutes, + string stateDirectory) + { + if (ingress == null) throw new ArgumentNullException(nameof(ingress)); + if (clock == null) throw new ArgumentNullException(nameof(clock)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + + var post = new InformationalEventPost(ingress, clock, logger); + _tracker = new SystemTimelineTracker( + sessionId: sessionId, + tenantId: tenantId, + post: post, + logger: logger, + backfillEnabled: backfillLookbackMinutes > 0, + backfillLookbackMinutes: backfillLookbackMinutes, + stateDirectory: stateDirectory); + } + + public void Start() + { + _tracker.Start(); + _logger.Info("SystemTimelineWatcherHost: started."); + } + + public void Stop() + { + try { _tracker.Stop(); } + catch (Exception ex) { _logger.Warning($"SystemTimelineWatcherHost: stop failed: {ex.Message}"); } + } + + public void Dispose() + { + if (Interlocked.Exchange(ref _disposed, 1) == 1) return; + Stop(); + } + } +} diff --git a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalActivityClassifier.cs b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalActivityClassifier.cs index c6b97f36..98b4a57b 100644 --- a/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalActivityClassifier.cs +++ b/src/Agent/AutopilotMonitor.Agent.V2.Core/Orchestration/SignalActivityClassifier.cs @@ -61,6 +61,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration // detection — the exact scenario the power watcher exists to observe. SharedConstants.EventTypes.PowerStateChange, + // Same reasoning for the system timeline watcher: a clock step, a wake from standby, + // or a backfilled episode at agent start is environment observation and must not + // reset the idle/stall clocks. + SharedConstants.EventTypes.SystemClockChanged, + SharedConstants.EventTypes.SystemSleepEpisode, + // Agent health / control / transport — not device/enrollment progress. SharedConstants.EventTypes.CollectorDegraded, SharedConstants.EventTypes.TelemetryUploadPoisoned, diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/SleepEpisodeRuleTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/SleepEpisodeRuleTests.cs new file mode 100644 index 00000000..ec9aaaee --- /dev/null +++ b/src/Backend/AutopilotMonitor.Functions.Tests/SleepEpisodeRuleTests.cs @@ -0,0 +1,137 @@ +using AutopilotMonitor.Functions.Services; +using AutopilotMonitor.Shared.DataAccess; +using AutopilotMonitor.Shared.Models; +using Microsoft.Extensions.Logging.Abstractions; +using Moq; + +namespace AutopilotMonitor.Functions.Tests; + +/// +/// ANALYZE-DEV-012 — pins the firing behaviour of the built-in that consumes the agent's +/// system_sleep_episode events (SystemTimelineWatcherHost): informational, fires once +/// (trigger single) when a completed sleep/hibernate/Modern-Standby episode of at least +/// 5 minutes is observed. Single-required-condition on durationSeconds so the match is pinned +/// to one event instance and the interpolated duration is the matched value. Also pins that the +/// agent's numeric payload (long) satisfies the rule's string "300" via numeric gte. +/// +public class SleepEpisodeRuleTests +{ + private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890"; + private const string SessionId = "66666666-7777-8888-9999-aaaaaaaaaaaa"; + + [Fact] + public async Task ANALYZE_DEV_012_fires_info_on_a_five_minute_episode() + { + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-DEV-012"); + Assert.True(rule.Enabled); + Assert.Equal("info", rule.Severity); + Assert.False(rule.MarkSessionAsFailedDefault); // environment observation, never a KO verdict + + var events = new List + { + SleepEpisode(durationSeconds: 300, kind: "modern_standby"), + }; + + var outcome = await RunAsync(rule, events); + + var result = Assert.Single(outcome.Results); + Assert.Equal("ANALYZE-DEV-012", result.RuleId); + Assert.Equal("info", result.Severity); + + // durationSeconds is the matched condition's dataField, so {{durationSeconds}} in the + // explanation interpolates the matched value (the DEV-009 whitelist lesson). + var matched = AsDict(result.MatchedConditions["slept_during_enrollment"]); + Assert.Equal("durationSeconds", AsString(matched["field"])); + } + + [Theory] + [InlineData(60)] // real but short episode — below the rule's 5-minute floor + [InlineData(299)] // boundary: gte 300 must not fire at 299 + public async Task ANALYZE_DEV_012_does_not_fire_below_the_five_minute_floor(long durationSeconds) + { + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-DEV-012"); + + var events = new List + { + SleepEpisode(durationSeconds, kind: "sleep"), + }; + + var outcome = await RunAsync(rule, events); + Assert.Empty(outcome.Results); + } + + [Fact] + public async Task ANALYZE_DEV_012_does_not_fire_on_a_clock_change_event() + { + // The sibling watcher event carries a large timeDeltaMs but is a different event type — + // the rule must key on system_sleep_episode only. + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-DEV-012"); + + var events = new List + { + new() + { + EventId = Guid.NewGuid().ToString(), + TenantId = TenantId, + SessionId = SessionId, + EventType = "system_clock_changed", + Timestamp = DateTime.UtcNow, + Sequence = 7, + Data = new Dictionary + { + ["timeDeltaMs"] = 7_200_000L, + ["durationSeconds"] = 900L, // adversarial: same field name on the wrong type + ["reason"] = 1, + }, + }, + }; + + var outcome = await RunAsync(rule, events); + Assert.Empty(outcome.Results); + } + + // ===== Event builder — mirrors the SystemTimelineTracker emit shape ===== + + private static EnrollmentEvent SleepEpisode(long durationSeconds, string kind) => new() + { + EventId = Guid.NewGuid().ToString(), + TenantId = TenantId, + SessionId = SessionId, + EventType = "system_sleep_episode", + Timestamp = DateTime.UtcNow, + Sequence = 42, + Data = new Dictionary + { + ["kind"] = kind, + ["enteredAt"] = DateTime.UtcNow.AddSeconds(-durationSeconds).ToString("o"), + ["exitedAt"] = DateTime.UtcNow.ToString("o"), + ["durationSeconds"] = durationSeconds, + ["backfilled"] = false, + } + }; + + private static Dictionary AsDict(object o) + { + if (o is Dictionary d) return d; + throw new InvalidOperationException($"Expected Dictionary, got {o?.GetType().Name ?? "null"}"); + } + + private static string AsString(object o) => o?.ToString() ?? string.Empty; + + private static async Task RunAsync(AnalyzeRule rule, List events) + { + var ruleRepo = new Mock(); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List { rule }); + ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List()); + ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny())).ReturnsAsync(new Dictionary()); + ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny(), It.IsAny())).ReturnsAsync(new List()); + + var sessionRepo = new Mock(); + sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny())).ReturnsAsync(events); + + var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger.Instance); + var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger.Instance); + + return await engine.AnalyzeSessionAsync(TenantId, SessionId); + } +} diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionCalculatorTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionCalculatorTests.cs index bbd165d8..eb36d3d4 100644 --- a/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionCalculatorTests.cs +++ b/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionCalculatorTests.cs @@ -499,6 +499,136 @@ public class TimeAttributionCalculatorTests Assert.Equal(1200 - 300, b.GetSegmentTotals()[TimeAttributionSegments.EspApps]); } + // ── sleep spans: payload instants are authoritative, annotation not partition ───────── + + [Fact] + public void SleepSpan_ComesFromPayloadInstants_NotFromEventTimestamp() + { + var enteredAt = T0.AddMinutes(8); + var exitedAt = T0.AddMinutes(14); + var events = new List + { + Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup), + Evt(T0.AddMinutes(5), "esp_phase_changed", EnrollmentPhase.AppsDevice), + // Emitted at wake (its Timestamp is the wake moment, possibly clamped) — only the + // payload carries the true episode bounds. + Evt(T0.AddMinutes(14.2), "system_sleep_episode", data: new Dictionary + { + ["kind"] = "modern_standby", + ["enteredAt"] = enteredAt.ToString("o"), + ["exitedAt"] = exitedAt.ToString("o"), + ["durationSeconds"] = 360L, + }), + Evt(T0.AddMinutes(20), "enrollment_complete"), + }; + + var b = TimeAttributionCalculator.Compute( + Input(events, completedAt: T0.AddMinutes(20), durationSeconds: 1200))!; + + AssertExactPartition(b); // sleep is an annotation — the wall-clock partition is untouched + var span = Assert.Single(b.SleepSpans); + Assert.Equal(enteredAt, span.StartUtc); + Assert.Equal(exitedAt, span.EndUtc); + Assert.Equal(360, span.Seconds); + Assert.Equal(360, b.SleepSeconds); + Assert.Equal("modern_standby", span.Kind); + Assert.Equal(TimeAttributionSegments.EspApps, span.SegmentKey); + } + + [Fact] + public void SleepSpan_DuplicateEpisode_NotDoubleCounted() + { + var enteredAt = T0.AddMinutes(8); + var exitedAt = T0.AddMinutes(10); + Dictionary Episode() => new Dictionary + { + ["kind"] = "sleep", + ["enteredAt"] = enteredAt.ToString("o"), + ["exitedAt"] = exitedAt.ToString("o"), + }; + var events = new List + { + Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup), + // Same episode observed twice (e.g. backfilled again after an agent restart from a + // different event-log record). + Evt(T0.AddMinutes(10.1), "system_sleep_episode", data: Episode()), + Evt(T0.AddMinutes(12), "system_sleep_episode", data: Episode()), + Evt(T0.AddMinutes(20), "enrollment_complete"), + }; + + var b = TimeAttributionCalculator.Compute( + Input(events, completedAt: T0.AddMinutes(20), durationSeconds: 1200))!; + + Assert.Single(b.SleepSpans); + Assert.Equal(120, b.SleepSeconds); + } + + [Fact] + public void SleepSpan_MissingOrUnparseablePayload_Ignored() + { + var events = new List + { + Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup), + Evt(T0.AddMinutes(5), "system_sleep_episode", data: new Dictionary + { + ["kind"] = "sleep", + ["enteredAt"] = "not-a-timestamp", + ["exitedAt"] = T0.AddMinutes(5).ToString("o"), + }), + Evt(T0.AddMinutes(6), "system_sleep_episode", data: new Dictionary + { + ["kind"] = "sleep", // bounds missing entirely + }), + // exitedAt <= enteredAt — pathological, no claim. + Evt(T0.AddMinutes(7), "system_sleep_episode", data: new Dictionary + { + ["kind"] = "sleep", + ["enteredAt"] = T0.AddMinutes(7).ToString("o"), + ["exitedAt"] = T0.AddMinutes(6).ToString("o"), + }), + Evt(T0.AddMinutes(20), "enrollment_complete"), + }; + + var b = TimeAttributionCalculator.Compute( + Input(events, completedAt: T0.AddMinutes(20), durationSeconds: 1200))!; + + Assert.Empty(b.SleepSpans); + Assert.Equal(0, b.SleepSeconds); + } + + [Fact] + public void WhiteGlove_SleepAcrossPause_CountsOnlyInWindowFlanks() + { + var part1End = T0.AddMinutes(20); + var resumedAt = T0.AddDays(2); + var completedAt = resumedAt.AddMinutes(10); + + var events = new List + { + Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup), + Evt(T0.AddMinutes(2), "esp_phase_changed", EnrollmentPhase.AppsDevice), + Evt(part1End, "whiteglove_part1_complete"), + // Sealed device slept through the pause: episode starts 1 min before the seal and + // ends 30 s into part 2 — only the in-window flanks may count (90 s), never the + // ~2-day pause (RebootSpan precedent). + Evt(resumedAt.AddSeconds(35), "system_sleep_episode", data: new Dictionary + { + ["kind"] = "hibernate", + ["enteredAt"] = part1End.AddMinutes(-1).ToString("o"), + ["exitedAt"] = resumedAt.AddSeconds(30).ToString("o"), + }), + Evt(completedAt, "enrollment_complete"), + }; + + var b = TimeAttributionCalculator.Compute( + Input(events, completedAt, durationSeconds: 1800, wg: true, resumedAt: resumedAt))!; + + AssertExactPartition(b); + var span = Assert.Single(b.SleepSpans); + Assert.Equal(90, span.Seconds); + Assert.Equal(90, b.SleepSeconds); + } + // ── WhiteGlove pause vs. intervals/reboots (Codex review P1): the pause lies INSIDE // the windows' hull, so hull-clamping alone would count it — a reboot bracketing the // pause must contribute only its in-window flanks, never the pause itself ───────────── diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionPersistenceAndAggregationTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionPersistenceAndAggregationTests.cs index 3ab9181a..20fcb876 100644 --- a/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionPersistenceAndAggregationTests.cs +++ b/src/Backend/AutopilotMonitor.Functions.Tests/TimeAttributionPersistenceAndAggregationTests.cs @@ -46,6 +46,11 @@ public class TimeAttributionPersistenceAndAggregationTests { new() { StartUtc = T0.AddMinutes(10), EndUtc = T0.AddMinutes(14), Seconds = 240, SegmentKey = TimeAttributionSegments.EspApps }, }, + SleepSeconds = 360, + SleepSpans = new List + { + new() { StartUtc = T0.AddMinutes(20), EndUtc = T0.AddMinutes(26), Seconds = 360, SegmentKey = TimeAttributionSegments.EspApps, Kind = "modern_standby" }, + }, BlockingApps = new List { new() { AppId = AppX, AppName = "App X", StartUtc = T0.AddMinutes(6), EndUtc = T0.AddMinutes(16), Seconds = 600 }, @@ -77,6 +82,13 @@ public class TimeAttributionPersistenceAndAggregationTests Assert.Equal(TimeAttributionSegments.EspApps, reboot.SegmentKey); Assert.Equal(240, reboot.Seconds); + Assert.Equal(360, mapped.SleepSeconds); + var sleep = Assert.Single(mapped.SleepSpans); + Assert.Equal("modern_standby", sleep.Kind); + Assert.Equal(TimeAttributionSegments.EspApps, sleep.SegmentKey); + Assert.Equal(T0.AddMinutes(20), sleep.StartUtc); + Assert.Equal(360, sleep.Seconds); + var app = Assert.Single(mapped.BlockingApps); Assert.Equal(AppX, app.AppId); Assert.Equal("App X", app.AppName); diff --git a/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs b/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs index 0f361400..72c75da7 100644 --- a/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs +++ b/src/Backend/AutopilotMonitor.Functions/Functions/Config/GetAgentConfigFunction.cs @@ -274,7 +274,7 @@ namespace AutopilotMonitor.Functions.Functions.Config var response = req.CreateResponse(HttpStatusCode.OK); await response.WriteAsJsonAsync(new AgentConfigResponse { - ConfigVersion = 38, // Collectors.EnablePowerStateWatcher (live AC/battery watcher) + ConfigVersion = 39, // Collectors.EnableSystemTimelineWatcher + SystemEventBackfillLookbackMinutes (clock changes + sleep episodes) UploadIntervalSeconds = Shared.Constants.DefaultUploadIntervalSeconds, SelfDestructOnComplete = tenantConfig.SelfDestructOnComplete ?? true, KeepLogFile = tenantConfig.KeepLogFile ?? false, diff --git a/src/Backend/AutopilotMonitor.Functions/Helpers/TimeAttributionCalculator.cs b/src/Backend/AutopilotMonitor.Functions/Helpers/TimeAttributionCalculator.cs index 49e8e990..36973613 100644 --- a/src/Backend/AutopilotMonitor.Functions/Helpers/TimeAttributionCalculator.cs +++ b/src/Backend/AutopilotMonitor.Functions/Helpers/TimeAttributionCalculator.cs @@ -72,7 +72,9 @@ public static class TimeAttributionCalculator /// Bump on any semantic change so aggregates never mix definitions (truthfulness rule 8). // v2: PriorEnrollmentResidue flag — sessions whose phase anchors are distorted by // pre-enrollment state on disk are now flagged and excluded from fleet segment stats. - public const int CurrentVersion = 2; + // v3: SleepSpans — completed sleep/standby episodes (system_sleep_episode) as cross-cutting + // annotations mirroring RebootSpans; the maintenance sweep recomputes older rows. + public const int CurrentVersion = 3; /// /// Enrollment class for fleet aggregation — classes are NEVER mixed in one aggregate (a @@ -168,6 +170,7 @@ public static class TimeAttributionCalculator } var rebootSpans = BuildRebootSpans(events, windows, spans); + var sleepSpans = BuildSleepSpans(events, windows, spans); if (events.Any(e => e.EventType == Constants.EventTypes.AgentLateStart)) flags |= TimeAttributionFlags.PartialObservation; @@ -191,6 +194,8 @@ public static class TimeAttributionCalculator UnattributedSeconds = unattributed, RebootSeconds = rebootSpans.Sum(r => r.Seconds), RebootSpans = rebootSpans, + SleepSeconds = sleepSpans.Sum(s => s.Seconds), + SleepSpans = sleepSpans, BlockingApps = blockingApps .OrderByDescending(a => a.Seconds) .ThenBy(a => a.AppName, StringComparer.OrdinalIgnoreCase) @@ -709,6 +714,63 @@ public static class TimeAttributionCalculator return result; } + // ── sleep spans ───────────────────────────────────────────────────────── + + /// + /// One span per completed sleep episode (system_sleep_episode). The payload's + /// enteredAt/exitedAt are the authoritative instants — the event's own + /// timestamp is stamped at wake and may have been clamped server-side. Structural clone of + /// : spans are clipped to the observation hull (a WhiteGlove + /// pause episode contributes nothing), dedup'd on the enter instant (an episode straddling + /// an agent restart can be backfilled twice from different records), and annotate the + /// segment they started in — they are never a slice of the wall-clock partition. + /// + private static List BuildSleepSpans( + List events, List windows, List spans) + { + var result = new List(); + var seenEpisodes = new HashSet(); + + foreach (var evt in events) + { + if (evt.EventType != Constants.EventTypes.SystemSleepEpisode || evt.Data == null) continue; + + var enteredAt = ParseUtcInstant(evt.Data, "enteredAt"); + var exitedAt = ParseUtcInstant(evt.Data, "exitedAt"); + if (!enteredAt.HasValue || !exitedAt.HasValue || exitedAt.Value <= enteredAt.Value) continue; + if (!seenEpisodes.Add(enteredAt.Value)) continue; // duplicate observation of the same episode + + var clamped = ClampToWindows(enteredAt.Value, exitedAt.Value, windows); + if (!clamped.HasValue) continue; + var seconds = clamped.Value.Seconds; + if (seconds <= 0) continue; + + var kind = evt.Data.TryGetValue("kind", out var kindObj) ? kindObj?.ToString() ?? string.Empty : string.Empty; + + result.Add(new SleepSpan + { + StartUtc = clamped.Value.Start, + EndUtc = clamped.Value.End, + Seconds = seconds, + SegmentKey = SegmentAt(spans, clamped.Value.Start), + Kind = kind, + }); + } + + return result.OrderBy(s => s.StartUtc).ToList(); + } + + private static DateTime? ParseUtcInstant(Dictionary data, string key) + { + if (!data.TryGetValue(key, out var raw)) return null; + var text = raw?.ToString(); + if (string.IsNullOrEmpty(text)) return null; + return DateTime.TryParse(text, CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, out var parsed) + ? parsed + : (DateTime?)null; + } + private static string SegmentAt(List spans, DateTime ts) { foreach (var span in spans) diff --git a/src/Backend/AutopilotMonitor.Functions/Services/EventIngestProcessor.Classification.cs b/src/Backend/AutopilotMonitor.Functions/Services/EventIngestProcessor.Classification.cs index e050c000..8c43b9ec 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/EventIngestProcessor.Classification.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/EventIngestProcessor.Classification.cs @@ -381,6 +381,10 @@ namespace AutopilotMonitor.Functions.Services // Environment observation (battery drain / AC flap), not enrollment progress — // must not count as "real activity" that heals a Stalled session. "power_state_change" => true, + // System timeline watcher: a clock step or a completed standby episode is environment + // observation too — a device that slept through its stall must stay Stalled. + "system_clock_changed" => true, + "system_sleep_episode" => true, _ => false }; diff --git a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.TimeAttribution.cs b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.TimeAttribution.cs index 2fea8daf..1d35ba2b 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.TimeAttribution.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/TableStorageService.TimeAttribution.cs @@ -117,10 +117,12 @@ namespace AutopilotMonitor.Functions.Services ["WallClockSeconds"] = b.WallClockSeconds, ["UnattributedSeconds"] = b.UnattributedSeconds, ["RebootSeconds"] = b.RebootSeconds, + ["SleepSeconds"] = b.SleepSeconds, ["BlockingAppCount"] = b.BlockingAppCount, ["QualityFlags"] = (int)b.QualityFlags, ["SegmentsJson"] = JsonSerializer.Serialize(b.Segments), ["RebootSpansJson"] = JsonSerializer.Serialize(b.RebootSpans), + ["SleepSpansJson"] = JsonSerializer.Serialize(b.SleepSpans), ["BlockingAppsJson"] = JsonSerializer.Serialize(b.BlockingApps), ["ComputedAt"] = DateTime.UtcNow, }; @@ -142,11 +144,13 @@ namespace AutopilotMonitor.Functions.Services WallClockSeconds = entity.GetInt32("WallClockSeconds") ?? 0, UnattributedSeconds = entity.GetInt32("UnattributedSeconds") ?? 0, RebootSeconds = entity.GetInt32("RebootSeconds") ?? 0, + SleepSeconds = entity.GetInt32("SleepSeconds") ?? 0, BlockingAppCount = entity.GetInt32("BlockingAppCount") ?? 0, EspAppsOccupancySeconds = entity.GetInt32("EspAppsOccupancySeconds"), QualityFlags = (TimeAttributionFlags)(entity.GetInt32("QualityFlags") ?? 0), Segments = DeserializeJsonColumn(entity.GetString("SegmentsJson")), RebootSpans = DeserializeJsonColumn(entity.GetString("RebootSpansJson")), + SleepSpans = DeserializeJsonColumn(entity.GetString("SleepSpansJson")), BlockingApps = DeserializeJsonColumn(entity.GetString("BlockingAppsJson")), }; } diff --git a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts index d34d5d4f..1ee1e10a 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/resource-catalog.ts @@ -111,6 +111,7 @@ export const EVENT_TYPES_CATALOG = { 'ntp_time_check', 'power_state_check', 'power_state_change', + 'system_clock_changed', ], identity_events: [ 'aad_placeholder_user_detected', @@ -156,6 +157,7 @@ export const EVENT_TYPES_CATALOG = { 'ime_session_change', 'ime_process_exited', 'system_reboot_detected', + 'system_sleep_episode', 'prior_run_died_with_state', 'previous_crash_detected', 'agent_emergency_break', diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts index b11eed77..09fe1b86 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts @@ -29,7 +29,7 @@ export const KEY_EVENT_TYPES = new Set([ 'desktop_arrived', 'hello_policy_detected', 'waiting_for_hello', 'hello_completion_timeout', 'agent_started', 'agent_shutdown', 'agent_shutting_down', 'agent_trace', 'script_started', 'script_completed', 'script_failed', 'historic_ime_replay_detected', - 'vulnerability_report', + 'vulnerability_report', 'system_sleep_episode', ]); // Phase-defining events promoted to the top of the triage timeline. Module-level // (not handler-local) so the same drift test can validate it. diff --git a/src/Shared/AutopilotMonitor.Shared/Constants.cs b/src/Shared/AutopilotMonitor.Shared/Constants.cs index 3660294e..c28b762b 100644 --- a/src/Shared/AutopilotMonitor.Shared/Constants.cs +++ b/src/Shared/AutopilotMonitor.Shared/Constants.cs @@ -563,6 +563,8 @@ namespace AutopilotMonitor.Shared public const string NtpTimeCheck = "ntp_time_check"; public const string PowerStateCheck = "power_state_check"; public const string PowerStateChange = "power_state_change"; + public const string SystemClockChanged = "system_clock_changed"; // Kernel-General EventID 1: OS clock stepped (oldTime/newTime/timeDeltaMs in Data are authoritative — the event's own Timestamp may be clamped server-side). + public const string SystemSleepEpisode = "system_sleep_episode"; // Completed sleep/hibernate/modern-standby episode (Power-Troubleshooter 1 / Kernel-Power 507), emitted retroactively at wake. public const string AgentTrace = "agent_trace"; // Crash / process lifecycle diff --git a/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs b/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs index a22a1798..21077fce 100644 --- a/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs +++ b/src/Shared/AutopilotMonitor.Shared/Models/Config/AgentConfigResponse.cs @@ -530,6 +530,30 @@ namespace AutopilotMonitor.Shared.Models /// public int MdmRebootPolicyBackfillLookbackMinutes { get; set; } = 60; + // ----------------------------------------------------------------------- + // System timeline watcher (System channel: clock changes + sleep episodes) + // ----------------------------------------------------------------------- + + /// + /// Master switch for the system timeline watcher. When enabled the agent subscribes to the + /// System event log for Kernel-General EventID 1 (system clock stepped — ground truth for + /// time jumps incl. old/new time, delta and the setting process) and completed sleep + /// episodes (Power-Troubleshooter EventID 1 for classic sleep/hibernate, Kernel-Power + /// EventID 507 for Modern Standby) and emits system_clock_changed / system_sleep_episode + /// events. Explains timeline gaps and time jumps that are otherwise blind spots. + /// Default: true. + /// + public bool EnableSystemTimelineWatcher { get; set; } = true; + + /// + /// Lookback window in minutes for the system timeline backfill scan on startup. The + /// decisive clock correction (w32time fixing a wrong BIOS clock) and pre-agent standby + /// episodes happen early in OOBE, often before the agent starts; the System .evtx persists + /// across reboots, so a generous backfill recovers them. Bounded well inside the backend's + /// 168 h past-tolerance clamp. 0 = backfill disabled. Default: 1440 minutes (24 h). + /// + public int SystemEventBackfillLookbackMinutes { get; set; } = 1440; + /// /// Creates default collector configuration /// diff --git a/src/Shared/AutopilotMonitor.Shared/Models/Metrics/SessionTimeBreakdown.cs b/src/Shared/AutopilotMonitor.Shared/Models/Metrics/SessionTimeBreakdown.cs index 5f2bf845..f1a7d324 100644 --- a/src/Shared/AutopilotMonitor.Shared/Models/Metrics/SessionTimeBreakdown.cs +++ b/src/Shared/AutopilotMonitor.Shared/Models/Metrics/SessionTimeBreakdown.cs @@ -147,6 +147,27 @@ namespace AutopilotMonitor.Shared.Models public string SegmentKey { get; set; } = string.Empty; } + /// + /// One completed sleep episode observed during the session (system_sleep_episode + /// payload — enteredAt/exitedAt are the authoritative instants, never the + /// event's own timestamp, which is stamped at wake and may be clamped). Cross-cutting + /// annotation like : sleep overlaps the segment it started in and is + /// NOT part of the wall-clock partition — the session really took that long; the span + /// explains where the time went. + /// + public class SleepSpan + { + public DateTime StartUtc { get; set; } + public DateTime EndUtc { get; set; } + public int Seconds { get; set; } + + /// Segment the episode started in ( key, or "unattributed"). + public string SegmentKey { get; set; } = string.Empty; + + /// Episode kind from the agent payload: "sleep", "hibernate" or "modern_standby". + public string Kind { get; set; } = string.Empty; + } + /// /// Per-session enrollment time attribution (F1, insights spec) — an exact partition of the /// session's authoritative wall clock into named segments plus an explicit unattributed @@ -187,6 +208,11 @@ namespace AutopilotMonitor.Shared.Models public List RebootSpans { get; set; } = new List(); + /// Total observed in-window sleep seconds. Cross-cutting annotation like — the wall clock keeps the pause; this discloses it. + public int SleepSeconds { get; set; } + + public List SleepSpans { get; set; } = new List(); + /// /// Install intervals of ESP-blocking apps (positive-evidence join against the latest /// esp_config_detected lists), top 20 by duration. 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 22b9908b..0b8e04b2 100644 --- a/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts +++ b/src/Web/autopilot-monitor-web/app/gather-rules/eventTypes.ts @@ -154,6 +154,10 @@ export const KNOWN_EVENT_TYPES: EventTypeEntry[] = [ description: "Network state changed (online/offline/interface)." }, { value: "power_state_change", label: "power_state_change", category: "diagnostics", description: "Live AC/battery change during enrollment (WMI push, no polling): transition=ac_to_battery (Warning) / battery_to_ac (Info) / threshold_crossed with thresholdPercent 50/30/15 (each level latched once per session). Payload carries onAcPower, batteryPercent, isCharging, batteryLifeMinutes. Never emitted on devices without a battery." }, + { value: "system_clock_changed", label: "system_clock_changed", category: "diagnostics", + description: "The OS clock was stepped (System log, Kernel-General EventID 1) — ground truth for time jumps: oldTime/newTime (ISO-8601, authoritative — the event's own timestamp may be clamped), signed timeDeltaMs, reason/reasonText (application_set / hardware_clock_sync), processName/processId of the setter. Steps below 2 s (w32time micro-slews) are suppressed; steps of 5+ min are Warning with immediate upload. Backfilled from before agent start (backfilled=true) — catches the early-OOBE w32time correction of a wrong BIOS clock." }, + { value: "system_sleep_episode", label: "system_sleep_episode", category: "diagnostics", + description: "A completed sleep episode, emitted retroactively at wake: kind=sleep/hibernate (Power-Troubleshooter EventID 1, carries wakeSourceType/wakeSourceText) or modern_standby (Kernel-Power EventID 507, carries sleepDurationSeconds, reason, onAcPower, batteryRemainingCapacityOnExit). Payload enteredAt/exitedAt (ISO-8601, authoritative) and durationSeconds explain timeline gaps and inflated wall-clock durations. Modern-standby episodes under 60 s of real sleep are suppressed; pre-agent episodes are backfilled (backfilled=true)." }, { value: "network_bandwidth_estimate", label: "network_bandwidth_estimate", category: "diagnostics", description: "Session-level internet-bandwidth estimate derived passively from the Delivery Optimization byte counters (no synthetic traffic). At most twice per session: an interim snapshot after DeviceSetup (snapshotTrigger=device_setup_end — survives account-phase starvation) and the authoritative final at enrollment end (collector_stop). p90/max Mbit/s for internet-path (HTTP + internet peers) and LAN sources (peers/Connected Cache) separately, plus bucket (<10 / 10-50 / 50-100 / 100-250 / 250+) and confidence." }, { value: "vulnerability_report", label: "vulnerability_report", category: "diagnostics", diff --git a/src/Web/autopilot-monitor-web/app/sessions/components/EventTimeline.tsx b/src/Web/autopilot-monitor-web/app/sessions/components/EventTimeline.tsx index 31272ef4..a3feda3d 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/components/EventTimeline.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/components/EventTimeline.tsx @@ -4,7 +4,7 @@ import { useState, useMemo } from "react"; import { EnrollmentEvent, Session } from "@/types"; import { normalizeEventDataForDisplay, shortenBuildHashInMessage } from "../utils/eventHelpers"; import { getEnrichedOrLookup, formatErrorCode, type ErrorCodeEntry } from "@/utils/errorCodeMap"; -import { readTimeProvenance, classifyTimeJump } from "@/lib/timeProvenance"; +import { readTimeProvenance, classifyTimeJump, readClockChangeDeltaMs } from "@/lib/timeProvenance"; import { formatDuration, formatUtcOffset } from "@/lib/formatting"; interface EventTimelineProps { @@ -75,6 +75,17 @@ export default function EventTimeline({ return filtered.sort((a, b) => a.sequence - b.sequence); }, [events, severityFilters, matchesSearch]); + // Ground-truth clock steps recorded by the agent's system timeline watcher — lets the + // TimeJumpBadge name a backwards display step as an actual OS clock set instead of an + // unexplained amber anomaly. Collected from ALL events (filters must not hide the cause). + const clockDeltas = useMemo( + () => events + .filter(e => e.eventType === "system_clock_changed") + .map(e => readClockChangeDeltaMs(e.data)) + .filter((n): n is number => n !== null), + [events], + ); + const filterPhaseEvents = (phaseEvents: EnrollmentEvent[]) => matchesSearch ? phaseEvents.filter(matchesSearch) : phaseEvents; @@ -187,6 +198,7 @@ export default function EventTimeline({ key={ev.eventId || `${ev.sessionId}-${ev.sequence}`} event={ev} prevEvent={i > 0 ? sortedBySequence[i - 1] : null} + clockDeltas={clockDeltas} /> ))} @@ -220,6 +232,7 @@ export default function EventTimeline({ onToggle={() => togglePhase(`pre-${phaseName}`)} showScriptOutput={showScriptOutput} borderColor="border-amber-400" + clockDeltas={clockDeltas} /> ))} @@ -257,6 +270,7 @@ export default function EventTimeline({ isExpanded={expandedPhases.has(`user-${phaseName}`)} onToggle={() => togglePhase(`user-${phaseName}`)} showScriptOutput={showScriptOutput} + clockDeltas={clockDeltas} /> ))} @@ -304,6 +318,7 @@ export default function EventTimeline({ isExpanded={expandedPhases.has(phaseName)} onToggle={() => togglePhase(phaseName)} showScriptOutput={showScriptOutput} + clockDeltas={clockDeltas} /> ))} @@ -322,7 +337,8 @@ function PhaseSection({ isExpanded, onToggle, showScriptOutput, - borderColor = 'border-blue-500' + borderColor = 'border-blue-500', + clockDeltas, }: { phaseName: string; events: EnrollmentEvent[]; @@ -330,6 +346,7 @@ function PhaseSection({ onToggle: () => void; showScriptOutput?: boolean; borderColor?: string; + clockDeltas?: number[]; }) { return (
@@ -353,6 +370,7 @@ function PhaseSection({ event={event} showScriptOutput={showScriptOutput} prevEvent={i > 0 ? events[i - 1] : null} + clockDeltas={clockDeltas} /> ))}
@@ -413,11 +431,13 @@ function GapBadge({ prevTime, eventTime }: { prevTime: Date | null; eventTime: D // tier; an unexplained backwards step gets amber. const TIME_JUMP_ORDER_NOTE = "Events are shown in true write order (sequence)."; -function TimeJumpBadge({ prevEvent, event }: { prevEvent?: EnrollmentEvent | null; event: EnrollmentEvent }) { +function TimeJumpBadge({ prevEvent, event, clockDeltas }: { prevEvent?: EnrollmentEvent | null; event: EnrollmentEvent; clockDeltas?: number[] }) { if (!prevEvent) return null; const jump = classifyTimeJump( { displayTime: getDisplayTime(prevEvent), provenance: readTimeProvenance(prevEvent.data) }, { displayTime: getDisplayTime(event), provenance: readTimeProvenance(event.data) }, + undefined, + clockDeltas, ); if (!jump) return null; @@ -430,7 +450,9 @@ function TimeJumpBadge({ prevEvent, event }: { prevEvent?: EnrollmentEvent | nul const times = `(${getDisplayTime(prevEvent).toLocaleTimeString()} → ${getDisplayTime(event).toLocaleTimeString()})`; const title = - jump.cause === "era-offset" + jump.cause === "clock-set" + ? `Time moved backwards by ${human} vs the previous event ${times}. The OS clock was actually set back — a system_clock_changed event in this session records a matching step (ground truth, not an ordering artifact). ${TIME_JUMP_ORDER_NOTE}` + : jump.cause === "era-offset" ? `Time moved backwards by ${human} vs the previous event ${times}. The two log lines were corrected with different UTC offsets (era-mixed log) — the jump reflects the offset change, not reordering. ${TIME_JUMP_ORDER_NOTE}` : jump.cause === "derived-timestamp" ? `Backdated log line: written ${human} before the previous event's displayed time ${times}. Its own timestamp was unusable, so the agent's clock time is shown. ${TIME_JUMP_ORDER_NOTE}` @@ -449,7 +471,7 @@ function TimeJumpBadge({ prevEvent, event }: { prevEvent?: EnrollmentEvent | nul const CLAMPED_TOOLTIP_PREFIX = "The device-reported timestamp was outside the accepted range and was clamped to server receive time on ingest."; -function EventRow({ event, showScriptOutput, prevEvent }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevEvent?: EnrollmentEvent | null }) { +function EventRow({ event, showScriptOutput, prevEvent, clockDeltas }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevEvent?: EnrollmentEvent | null; clockDeltas?: number[] }) { const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null; const [showDetails, setShowDetails] = useState(false); const [showRaw, setShowRaw] = useState(false); @@ -541,7 +563,7 @@ function EventRow({ event, showScriptOutput, prevEvent }: { event: EnrollmentEve )} - + {isBackfilled && ( ); })()} + {/* Ground-truth clock step (system timeline watcher): the OS clock was set from + oldTime to newTime — payload times are authoritative. Amber at ≥5 min (can + invalidate token/cert windows and visibly reorders the timeline), sky below. */} + {event.eventType === "system_clock_changed" && (() => { + const deltaMs = readClockChangeDeltaMs(event.data); + if (deltaMs === null) return null; + const forward = deltaMs >= 0; + const isLarge = Math.abs(deltaMs) >= 5 * 60 * 1000; + const reasonText = event.data?.reasonText as string | undefined; + const processName = event.data?.processName as string | undefined; + const processLeaf = processName ? processName.split("\\").pop() : null; + return ( +
+ + ⏱ {forward ? "+" : "−"}{formatDuration(Math.abs(deltaMs) / 1000)} + + {reasonText && {reasonText === "application_set" ? "set by a process" : reasonText === "hardware_clock_sync" ? "hardware clock sync" : reasonText}} + {processLeaf && {processLeaf}} +
+ ); + })()} + {/* Completed sleep episode (emitted retroactively at wake): enteredAt/exitedAt in the + payload are the authoritative bounds — the gap in the surrounding timeline is this + episode, not missing telemetry. */} + {event.eventType === "system_sleep_episode" && (() => { + const kind = event.data?.kind as string | undefined; + const kindLabel = kind === "modern_standby" ? "Modern Standby" : kind === "hibernate" ? "Hibernate" : "Sleep"; + const durationSeconds = Number(event.data?.durationSeconds); + const wakeText = event.data?.wakeSourceText as string | undefined; + const onAc = event.data?.onAcPower; + const onAcLabel = onAc === true || onAc === "true" ? "on AC" : onAc === false || onAc === "false" ? "on battery" : null; + return ( +
+ + 🌙 {kindLabel} + + {Number.isFinite(durationSeconds) && durationSeconds > 0 && ( + {formatDuration(durationSeconds)} + )} + {wakeText && wake: {wakeText}} + {onAcLabel && {onAcLabel}} +
+ ); + })()} + {/* Live power-state change (power watcher, DEV-009/010): make the transition readable + without expanding the details. */} + {event.eventType === "power_state_change" && (() => { + const transition = event.data?.transition as string | undefined; + const batteryPercent = event.data?.batteryPercent; + const threshold = event.data?.thresholdPercent; + const chip = transition === "ac_to_battery" + ? { label: "AC → battery", cls: "bg-amber-100 text-amber-800" } + : transition === "battery_to_ac" + ? { label: "Battery → AC", cls: "bg-emerald-100 text-emerald-800" } + : transition === "threshold_crossed" + ? { label: `Battery below ${String(threshold ?? "?")}%`, cls: String(threshold) === "15" ? "bg-red-100 text-red-800" : "bg-amber-100 text-amber-800" } + : null; + if (!chip) return null; + return ( +
+ 🔋 {chip.label} + {batteryPercent !== undefined && batteryPercent !== null && String(batteryPercent) !== "unknown" && ( + {String(batteryPercent)}% charge + )} +
+ ); + })()}
Source: {event.source} Seq: {event.sequence} @@ -989,7 +1084,7 @@ function TimeProvenanceRows({ event, provenance }: { event: EnrollmentEvent; pro ); } -function RawEventRow({ event, prevEvent }: { event: EnrollmentEvent; prevEvent?: EnrollmentEvent | null }) { +function RawEventRow({ event, prevEvent, clockDeltas }: { event: EnrollmentEvent; prevEvent?: EnrollmentEvent | null; clockDeltas?: number[] }) { const [expanded, setExpanded] = useState(false); const detailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]); const hasDetails = detailData && Object.keys(detailData).length > 0; @@ -1011,7 +1106,7 @@ function RawEventRow({ event, prevEvent }: { event: EnrollmentEvent; prevEvent?: {event.sequence} {(recordedAt ?? new Date(event.timestamp)).toLocaleTimeString()} - + {event.severity} {isBackfilled && ( ⟲ diff --git a/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx b/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx index 2a3187d2..afda8084 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/components/SessionInfoCard.tsx @@ -12,9 +12,17 @@ interface SessionInfoCardProps { isGatherRulesSession: boolean; ntpOffset?: { offsetSeconds: number; ntpServer?: string } | null; configMgrDetected?: { ccmVersion?: string; ccmServiceState?: string; siteCode?: string; confidenceScore?: number } | null; + /** Total observed sleep/standby seconds (system_sleep_episode ground truth) — explains an inflated wall-clock duration. */ + standbySeconds?: number | null; } -export default function SessionInfoCard({ session, enrollmentDuration, displayStatus, isGatherRulesSession, ntpOffset, configMgrDetected }: SessionInfoCardProps) { +// Compact duration for the standby note: "56m", "1h 2m". +function formatStandby(seconds: number): string { + if (seconds >= 3600) return `${Math.floor(seconds / 3600)}h ${Math.floor((seconds % 3600) / 60)}m`; + return `${Math.max(1, Math.round(seconds / 60))}m`; +} + +export default function SessionInfoCard({ session, enrollmentDuration, displayStatus, isGatherRulesSession, ntpOffset, configMgrDetected, standbySeconds }: SessionInfoCardProps) { const lastContactTooltip = session.lastEventAt ? `Last contact: ${new Date(session.lastEventAt).toLocaleString([], { dateStyle: "short", timeStyle: "medium" })}` : undefined; @@ -56,7 +64,25 @@ export default function SessionInfoCard({ session, enrollmentDuration, displaySt copyText={session.sessionId} /> - + = 60 ? ( + + {enrollmentDuration ?? `${Math.round(session.durationSeconds / 60)} min`} + + {" "}· 🌙 {formatStandby(standbySeconds)} standby + + + ) : ( + enrollmentDuration ?? `${Math.round(session.durationSeconds / 60)} min` + ) + } + tooltip={lastContactTooltip} + /> } /> diff --git a/src/Web/autopilot-monitor-web/app/sessions/components/TimeAttributionLane.tsx b/src/Web/autopilot-monitor-web/app/sessions/components/TimeAttributionLane.tsx index 22beeaf2..8dab7a05 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/components/TimeAttributionLane.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/components/TimeAttributionLane.tsx @@ -33,6 +33,15 @@ export interface RebootSpanDto { segmentKey: string; } +export interface SleepSpanDto { + startUtc: string; + endUtc: string; + seconds: number; + segmentKey: string; + /** "sleep" | "hibernate" | "modern_standby" (from the system_sleep_episode payload). */ + kind: string; +} + export interface SessionTimeBreakdownDto { tenantId: string; sessionId: string; @@ -42,6 +51,9 @@ export interface SessionTimeBreakdownDto { unattributedSeconds: number; rebootSeconds: number; rebootSpans: RebootSpanDto[]; + /** Optional: rows computed before AttributionVersion 3 lack these. */ + sleepSeconds?: number; + sleepSpans?: SleepSpanDto[]; blockingApps: BlockingAppIntervalDto[]; blockingAppCount: number; espAppsOccupancySeconds: number | null; @@ -108,14 +120,24 @@ export default function TimeAttributionLane({ breakdown }: { breakdown: SessionT {formatDuration(wallClock)} enrollment time - {breakdown.rebootSeconds > 0 && ( - - ⟳ {breakdown.rebootSpans.length} reboot{breakdown.rebootSpans.length !== 1 ? "s" : ""} · {formatDuration(breakdown.rebootSeconds)} - - )} + + {(breakdown.sleepSeconds ?? 0) > 0 && ( + + 🌙 {(breakdown.sleepSpans ?? []).length} standby · {formatDuration(breakdown.sleepSeconds ?? 0)} + + )} + {breakdown.rebootSeconds > 0 && ( + + ⟳ {breakdown.rebootSpans.length} reboot{breakdown.rebootSpans.length !== 1 ? "s" : ""} · {formatDuration(breakdown.rebootSeconds)} + + )} +
{/* Proportional stacked bar over the authoritative wall clock */} diff --git a/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts b/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts index 7c27f36b..2e3322b4 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts +++ b/src/Web/autopilot-monitor-web/app/sessions/hooks/useSessionDerivedData.ts @@ -25,6 +25,7 @@ export interface UseSessionDerivedDataReturn { gatherRulesSucceeded: boolean; displayStatus: string; enrollmentDurationFromEvents: string | null; + standbySeconds: number | null; phaseNamesMap: Record; phaseOrder: string[]; isSkipUserStatusPage: boolean; @@ -138,6 +139,25 @@ export function useSessionDerivedData( return `${Math.floor(durationSec / 3600)}h ${Math.floor((durationSec % 3600) / 60)}m`; }, [events]); + // Total observed sleep/standby seconds (system_sleep_episode ground truth). The wall-clock + // duration deliberately keeps the pause — this number tells the story next to it ("1h 20m, + // 56m of it standby"). Dedup on enteredAt: the same episode can be observed twice (agent + // restart re-backfills it from a different event-log record). + const standbySeconds = useMemo(() => { + const seenEpisodes = new Set(); + let total = 0; + for (const e of events) { + if (e.eventType !== "system_sleep_episode" || !e.data) continue; + const duration = Number(e.data.durationSeconds); + if (!Number.isFinite(duration) || duration <= 0) continue; + const enteredAt = typeof e.data.enteredAt === "string" ? e.data.enteredAt : `seq-${e.sequence}`; + if (seenEpisodes.has(enteredAt)) continue; + seenEpisodes.add(enteredAt); + total += duration; + } + return total > 0 ? Math.round(total) : null; + }, [events]); + const phaseNamesMap = session?.enrollmentType === "v2" ? V2_PHASE_NAMES : V1_PHASE_NAMES; const phaseOrder = session?.enrollmentType === "v2" ? V2_PHASE_ORDER : V1_PHASE_ORDER; @@ -213,6 +233,7 @@ export function useSessionDerivedData( gatherRulesSucceeded: !!gatherRulesSucceeded, displayStatus, enrollmentDurationFromEvents, + standbySeconds, phaseNamesMap, phaseOrder, isSkipUserStatusPage, diff --git a/src/Web/autopilot-monitor-web/app/sessions/page.tsx b/src/Web/autopilot-monitor-web/app/sessions/page.tsx index 23bad706..e042956f 100644 --- a/src/Web/autopilot-monitor-web/app/sessions/page.tsx +++ b/src/Web/autopilot-monitor-web/app/sessions/page.tsx @@ -191,6 +191,7 @@ function SessionDetailContent() { isGatherRulesSession, displayStatus, enrollmentDurationFromEvents, + standbySeconds, isSkipUserStatusPage, isWhiteGloveSession, whiteGloveSplitSequence, @@ -565,6 +566,7 @@ function SessionDetailContent() { isGatherRulesSession={isGatherRulesSession} ntpOffset={ntpOffset} configMgrDetected={configMgrDetected} + standbySeconds={standbySeconds} /> )} diff --git a/src/Web/autopilot-monitor-web/lib/__tests__/timeProvenance.test.ts b/src/Web/autopilot-monitor-web/lib/__tests__/timeProvenance.test.ts index 09ae8d59..fd605bf4 100644 --- a/src/Web/autopilot-monitor-web/lib/__tests__/timeProvenance.test.ts +++ b/src/Web/autopilot-monitor-web/lib/__tests__/timeProvenance.test.ts @@ -2,6 +2,8 @@ import { describe, it, expect } from "vitest"; import { readTimeProvenance, classifyTimeJump, + readClockChangeDeltaMs, + findExplainingClockChange, BACKWARD_JUMP_THRESHOLD_MS, type TimeJumpInput, } from "../timeProvenance"; @@ -115,4 +117,45 @@ describe("classifyTimeJump", () => { it("respects a caller-supplied threshold", () => { expect(classifyTimeJump(input(T0), input(minutes(-3)), 120_000)).toEqual({ deltaMs: 180_000, cause: null }); }); + + it("names a recorded OS clock set (ground truth) matching the jump magnitude", () => { + // A −60 min system_clock_changed step explains a ~60 min backwards display step. + const jump = classifyTimeJump(input(T0), input(minutes(-60)), undefined, [-60 * 60 * 1000]); + expect(jump!.cause).toBe("clock-set"); + }); + + it("clock-set (ground truth) wins over derived-timestamp inference (precedence)", () => { + const curr = input(minutes(-60), { derivedTimestamp: "true" }); + const jump = classifyTimeJump(input(T0), curr, undefined, [-60 * 60 * 1000]); + expect(jump!.cause).toBe("clock-set"); + }); + + it("stays unexplained when the recorded clock deltas do not match the jump", () => { + // Forward set, and a backward set of a very different magnitude — neither explains −60 min. + const jump = classifyTimeJump(input(T0), input(minutes(-60)), undefined, [60 * 60 * 1000, -5 * 60 * 1000]); + expect(jump!.cause).toBeNull(); + }); +}); + +describe("clock-change ground truth helpers", () => { + it("reads the signed payload delta (number or numeric string)", () => { + expect(readClockChangeDeltaMs({ timeDeltaMs: -3_600_000 })).toBe(-3_600_000); + expect(readClockChangeDeltaMs({ timeDeltaMs: "7200000" })).toBe(7_200_000); + expect(readClockChangeDeltaMs({ time_delta_ms: "-1000" })).toBe(-1000); + expect(readClockChangeDeltaMs({})).toBeNull(); + expect(readClockChangeDeltaMs(undefined)).toBeNull(); + }); + + it("matches within max(60 s, 20 %) tolerance — the display step includes elapsed real time", () => { + const hour = 60 * 60 * 1000; + expect(findExplainingClockChange(hour, [-hour])).toBe(-hour); + // 10 min drift on a 60 min jump is inside the 20 % band … + expect(findExplainingClockChange(hour, [-(hour - 10 * 60 * 1000)])).toBe(-(hour - 10 * 60 * 1000)); + // … 20 min is outside. + expect(findExplainingClockChange(hour, [-(hour - 20 * 60 * 1000)])).toBeNull(); + // Small jumps use the absolute 60 s floor. + expect(findExplainingClockChange(6 * 60 * 1000, [-(5 * 60 * 1000)])).toBe(-(5 * 60 * 1000)); + // A forward set never explains a backward step. + expect(findExplainingClockChange(hour, [hour])).toBeNull(); + }); }); diff --git a/src/Web/autopilot-monitor-web/lib/timeProvenance.ts b/src/Web/autopilot-monitor-web/lib/timeProvenance.ts index 401b1f74..5fba8f41 100644 --- a/src/Web/autopilot-monitor-web/lib/timeProvenance.ts +++ b/src/Web/autopilot-monitor-web/lib/timeProvenance.ts @@ -80,7 +80,7 @@ export function readTimeProvenance(data: Record | undefined | n */ export const BACKWARD_JUMP_THRESHOLD_MS = 5 * 60 * 1000; -export type TimeJumpCause = "era-offset" | "derived-timestamp" | "rejected-source" | null; +export type TimeJumpCause = "clock-set" | "era-offset" | "derived-timestamp" | "rejected-source" | null; export interface TimeJump { /** Positive magnitude of the backwards step in milliseconds. */ @@ -93,24 +93,55 @@ export interface TimeJumpInput { provenance: TimeProvenance | null; } +/** + * Reads the signed step of a `system_clock_changed` event's payload — the OS-level ground + * truth for "the clock was set from X to Y" (Kernel-General EventID 1, forwarded by the + * agent's system timeline watcher). Returns null for any other payload. + */ +export function readClockChangeDeltaMs(data: Record | undefined | null): number | null { + if (!data || typeof data !== "object") return null; + return readNumber(data, "timeDeltaMs", "time_delta_ms"); +} + +/** + * Matches an observed backwards display step against the session's recorded clock sets. + * A backwards step of J ms is explained by a clock set of −D ms when the magnitudes agree + * within max(60 s, 20 % of the jump) — the display step includes whatever real time + * elapsed between the two rows, so exact equality never holds. Returns the matching + * (negative) clock delta, or null. + */ +export function findExplainingClockChange(backwardJumpMs: number, clockDeltasMs: readonly number[]): number | null { + for (const delta of clockDeltasMs) { + if (delta >= 0) continue; // only a backward set explains a backward display step + const tolerance = Math.max(60_000, backwardJumpMs * 0.2); + if (Math.abs(-delta - backwardJumpMs) <= tolerance) return delta; + } + return null; +} + /** * Detects a backwards step of the displayed time versus the previous RENDERED row and - * names its cause when the provenance identifies one. Cause precedence: a clock-fallback - * (derived) timestamp explains the row by itself; a rejected source timestamp likewise; - * only then is an offset difference between the two rows read as an era-mixed log. + * names its cause when the provenance identifies one. Cause precedence: a recorded OS + * clock set (ground truth, when the session's `system_clock_changed` deltas are passed) + * beats every inference; then a clock-fallback (derived) timestamp explains the row by + * itself; a rejected source timestamp likewise; only then is an offset difference between + * the two rows read as an era-mixed log. * Callers pass prev = null at phase-section starts (jump detection never spans sections). */ export function classifyTimeJump( prev: TimeJumpInput | null, curr: TimeJumpInput, thresholdMs: number = BACKWARD_JUMP_THRESHOLD_MS, + clockDeltasMs?: readonly number[], ): TimeJump | null { if (!prev) return null; const deltaMs = prev.displayTime.getTime() - curr.displayTime.getTime(); if (!Number.isFinite(deltaMs) || deltaMs < thresholdMs) return null; let cause: TimeJumpCause = null; - if (curr.provenance?.derivedTimestamp) { + if (clockDeltasMs && findExplainingClockChange(deltaMs, clockDeltasMs) !== null) { + cause = "clock-set"; + } else if (curr.provenance?.derivedTimestamp) { cause = "derived-timestamp"; } else if (curr.provenance?.rejectedSourceTimestamp) { cause = "rejected-source"; diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts index f883e33a..21520fc8 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.generated.ts @@ -633,7 +633,9 @@ export const SHARED_MANIFEST = { "stall_probe_check", "stall_probe_result", "state_quarantine_recovered", + "system_clock_changed", "system_reboot_detected", + "system_sleep_episode", "telemetry_upload_blocked", "telemetry_upload_poisoned", "timezone_auto_set", diff --git a/src/Web/autopilot-monitor-web/utils/shared-manifests.json b/src/Web/autopilot-monitor-web/utils/shared-manifests.json index 7be85b28..f296934e 100644 --- a/src/Web/autopilot-monitor-web/utils/shared-manifests.json +++ b/src/Web/autopilot-monitor-web/utils/shared-manifests.json @@ -629,7 +629,9 @@ "stall_probe_check", "stall_probe_result", "state_quarantine_recovered", + "system_clock_changed", "system_reboot_detected", + "system_sleep_episode", "telemetry_upload_blocked", "telemetry_upload_poisoned", "timezone_auto_set",