mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 04:32:32 +00:00
feat(agent): system timeline watcher — clock steps + sleep episodes as ground truth
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 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
@@ -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.
|
||||
|
||||
@@ -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.
|
||||
@@ -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
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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"
|
||||
]
|
||||
}
|
||||
+48
@@ -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",
|
||||
|
||||
+429
@@ -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
|
||||
{
|
||||
/// <summary>
|
||||
/// SystemTimelineTracker — clock steps (Kernel-General 1) and completed sleep episodes
|
||||
/// (Power-Troubleshooter 1 / Kernel-Power 507) from the System channel. Drives the primitive
|
||||
/// <see cref="SystemTimelineTracker.ProcessEvent"/> test seam (no real EventRecord, which is
|
||||
/// abstract + Windows-only), mirroring the WindowsUpdateTracker test pattern.
|
||||
/// </summary>
|
||||
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<string, string>(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<string, string>(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<string, string>(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<FakeSignalIngressSink.PostedSignal> 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<string, object> Data(FakeSignalIngressSink.PostedSignal s) =>
|
||||
(IReadOnlyDictionary<string, object>)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<string, string>(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<string, string>(), isBackfill: false);
|
||||
_tracker.ProcessEvent("Some-Other-Provider", eventId: 1, recordId: _nextRecordId++,
|
||||
timeCreatedUtc: At, eventData: new Dictionary<string, string>(), 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 =
|
||||
"<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>" +
|
||||
"<System><Provider Name='Microsoft-Windows-Kernel-General'/><EventID>1</EventID></System>" +
|
||||
"<EventData>" +
|
||||
"<Data Name='NewTime'>2026-08-21T09:40:02.1987028Z</Data>" +
|
||||
"<Data Name='OldTime'>2026-08-21T09:40:02.1973028Z</Data>" +
|
||||
"<Data Name='TimeDeltaInMs'>1</Data>" +
|
||||
"<Data Name='Reason'>1</Data>" +
|
||||
"<Data Name='ProcessName'>\\Device\\HarddiskVolume3\\Windows\\System32\\svchost.exe</Data>" +
|
||||
"<Data Name='ProcessID'>6892</Data>" +
|
||||
"</EventData></Event>";
|
||||
|
||||
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\"));
|
||||
}
|
||||
}
|
||||
}
|
||||
+57
@@ -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
|
||||
{
|
||||
/// <summary>
|
||||
/// SystemTimelineWatcherHost — thin ICollectorHost wrapper over SystemTimelineTracker.
|
||||
/// Real event-log arming stays untested by convention (ConsoleBypassWatcher precedent);
|
||||
/// these tests pin the lifecycle contract only.
|
||||
/// </summary>
|
||||
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);
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+681
@@ -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
|
||||
{
|
||||
/// <summary>
|
||||
/// Watches the <c>System</c> event log for two enrollment blind spots and forwards them as
|
||||
/// timeline ground truth:
|
||||
/// <list type="bullet">
|
||||
/// <item><b>System clock steps</b> (Kernel-General EventID 1) → <c>system_clock_changed</c>.
|
||||
/// The payload carries <c>oldTime</c>/<c>newTime</c>/<c>timeDeltaMs</c> 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 <see cref="MinClockDeltaMs"/>.</item>
|
||||
/// <item><b>Completed sleep episodes</b> → <c>system_sleep_episode</c>. 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.</item>
|
||||
/// </list>
|
||||
/// <para>
|
||||
/// <b>Payload times are authoritative.</b> 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 <c>Timestamp</c>.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Backfill + cross-restart dedup</b> mirror <see cref="WindowsUpdateTracker"/>: 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.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
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<long> _seenThisRun = new HashSet<long>();
|
||||
// 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);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// </summary>
|
||||
internal static string BuildXPath() =>
|
||||
"*[System[" + ProviderIdClauses() + "]]";
|
||||
|
||||
/// <summary>Backfill variant of <see cref="BuildXPath"/> with the lookback window applied.</summary>
|
||||
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);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Core processing extracted to primitive inputs so tests can drive it without synthesizing
|
||||
/// an abstract, Windows-only <see cref="EventRecord"/> (WindowsUpdateTracker test-seam
|
||||
/// pattern; a plain dictionary instead of named args because three providers with ~10
|
||||
/// payload fields each make a fixed signature impractical).
|
||||
/// </summary>
|
||||
internal void ProcessEvent(
|
||||
string providerName,
|
||||
int eventId,
|
||||
long recordId,
|
||||
DateTime? timeCreatedUtc,
|
||||
Dictionary<string, string> eventData,
|
||||
bool isBackfill)
|
||||
{
|
||||
if (!MarkProcessed(recordId))
|
||||
return; // already emitted (cross-restart or duplicate delivery)
|
||||
|
||||
eventData = eventData ?? new Dictionary<string, string>(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<string, string> 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<string, object>
|
||||
{
|
||||
{ "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<string, string> 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<string, object>
|
||||
{
|
||||
{ "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<string, string> 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<string, object>
|
||||
{
|
||||
{ "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<string, object> 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
|
||||
// -----------------------------------------------------------------------
|
||||
|
||||
/// <summary>
|
||||
/// Extracts <c><Data Name="...">value</Data></c> 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.
|
||||
/// </summary>
|
||||
internal static Dictionary<string, string> ParseEventData(string xml)
|
||||
{
|
||||
var result = new Dictionary<string, string>(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;
|
||||
}
|
||||
|
||||
/// <summary>Compact human duration for messages: "2h 05m", "56m 12s", "45s".</summary>
|
||||
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";
|
||||
}
|
||||
|
||||
/// <summary>Leaf file name of a kernel device path like <c>\Device\HarddiskVolume3\Windows\System32\svchost.exe</c>.</summary>
|
||||
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);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Atomically claims <paramref name="recordId"/>. 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.
|
||||
/// </summary>
|
||||
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<WatermarkState>(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; }
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
|
||||
+68
@@ -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
|
||||
{
|
||||
/// <summary>
|
||||
/// Standalone host for the <see cref="SystemTimelineTracker"/> — watches the <c>System</c>
|
||||
/// 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 <see cref="WindowsUpdateWatcherHost"/>: builds its own
|
||||
/// <see cref="InformationalEventPost"/> and delegates Start/Stop to the tracker.
|
||||
/// </summary>
|
||||
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();
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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,
|
||||
|
||||
@@ -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;
|
||||
|
||||
/// <summary>
|
||||
/// ANALYZE-DEV-012 — pins the firing behaviour of the built-in that consumes the agent's
|
||||
/// <c>system_sleep_episode</c> 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.
|
||||
/// </summary>
|
||||
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<EnrollmentEvent>
|
||||
{
|
||||
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<EnrollmentEvent>
|
||||
{
|
||||
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<EnrollmentEvent>
|
||||
{
|
||||
new()
|
||||
{
|
||||
EventId = Guid.NewGuid().ToString(),
|
||||
TenantId = TenantId,
|
||||
SessionId = SessionId,
|
||||
EventType = "system_clock_changed",
|
||||
Timestamp = DateTime.UtcNow,
|
||||
Sequence = 7,
|
||||
Data = new Dictionary<string, object>
|
||||
{
|
||||
["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<string, object>
|
||||
{
|
||||
["kind"] = kind,
|
||||
["enteredAt"] = DateTime.UtcNow.AddSeconds(-durationSeconds).ToString("o"),
|
||||
["exitedAt"] = DateTime.UtcNow.ToString("o"),
|
||||
["durationSeconds"] = durationSeconds,
|
||||
["backfilled"] = false,
|
||||
}
|
||||
};
|
||||
|
||||
private static Dictionary<string, object> AsDict(object o)
|
||||
{
|
||||
if (o is Dictionary<string, object> d) return d;
|
||||
throw new InvalidOperationException($"Expected Dictionary<string,object>, got {o?.GetType().Name ?? "null"}");
|
||||
}
|
||||
|
||||
private static string AsString(object o) => o?.ToString() ?? string.Empty;
|
||||
|
||||
private static async Task<AnalysisOutcome> RunAsync(AnalyzeRule rule, List<EnrollmentEvent> events)
|
||||
{
|
||||
var ruleRepo = new Mock<IRuleRepository>();
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List<AnalyzeRule> { rule });
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List<AnalyzeRule>());
|
||||
ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny<string>())).ReturnsAsync(new Dictionary<string, RuleState>());
|
||||
ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny<string>(), It.IsAny<string>())).ReturnsAsync(new List<RuleResult>());
|
||||
|
||||
var sessionRepo = new Mock<ISessionRepository>();
|
||||
sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny<int>())).ReturnsAsync(events);
|
||||
|
||||
var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger<AnalyzeRuleService>.Instance);
|
||||
var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger<SleepEpisodeRuleTests>.Instance);
|
||||
|
||||
return await engine.AnalyzeSessionAsync(TenantId, SessionId);
|
||||
}
|
||||
}
|
||||
@@ -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<EnrollmentEvent>
|
||||
{
|
||||
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<string, object>
|
||||
{
|
||||
["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<string, object> Episode() => new Dictionary<string, object>
|
||||
{
|
||||
["kind"] = "sleep",
|
||||
["enteredAt"] = enteredAt.ToString("o"),
|
||||
["exitedAt"] = exitedAt.ToString("o"),
|
||||
};
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
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<EnrollmentEvent>
|
||||
{
|
||||
Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup),
|
||||
Evt(T0.AddMinutes(5), "system_sleep_episode", data: new Dictionary<string, object>
|
||||
{
|
||||
["kind"] = "sleep",
|
||||
["enteredAt"] = "not-a-timestamp",
|
||||
["exitedAt"] = T0.AddMinutes(5).ToString("o"),
|
||||
}),
|
||||
Evt(T0.AddMinutes(6), "system_sleep_episode", data: new Dictionary<string, object>
|
||||
{
|
||||
["kind"] = "sleep", // bounds missing entirely
|
||||
}),
|
||||
// exitedAt <= enteredAt — pathological, no claim.
|
||||
Evt(T0.AddMinutes(7), "system_sleep_episode", data: new Dictionary<string, object>
|
||||
{
|
||||
["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<EnrollmentEvent>
|
||||
{
|
||||
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<string, object>
|
||||
{
|
||||
["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 ─────────────
|
||||
|
||||
+12
@@ -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<SleepSpan>
|
||||
{
|
||||
new() { StartUtc = T0.AddMinutes(20), EndUtc = T0.AddMinutes(26), Seconds = 360, SegmentKey = TimeAttributionSegments.EspApps, Kind = "modern_standby" },
|
||||
},
|
||||
BlockingApps = new List<BlockingAppInterval>
|
||||
{
|
||||
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);
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -72,7 +72,9 @@ public static class TimeAttributionCalculator
|
||||
/// <summary>Bump on any semantic change so aggregates never mix definitions (truthfulness rule 8).</summary>
|
||||
// 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;
|
||||
|
||||
/// <summary>
|
||||
/// 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 ─────────────────────────────────────────────────────────
|
||||
|
||||
/// <summary>
|
||||
/// One span per completed sleep episode (<c>system_sleep_episode</c>). The payload's
|
||||
/// <c>enteredAt</c>/<c>exitedAt</c> are the authoritative instants — the event's own
|
||||
/// timestamp is stamped at wake and may have been clamped server-side. Structural clone of
|
||||
/// <see cref="BuildRebootSpans"/>: 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.
|
||||
/// </summary>
|
||||
private static List<SleepSpan> BuildSleepSpans(
|
||||
List<EnrollmentEvent> events, List<Window> windows, List<TimeAttributionSpan> spans)
|
||||
{
|
||||
var result = new List<SleepSpan>();
|
||||
var seenEpisodes = new HashSet<DateTime>();
|
||||
|
||||
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<string, object> 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<TimeAttributionSpan> spans, DateTime ts)
|
||||
{
|
||||
foreach (var span in spans)
|
||||
|
||||
@@ -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
|
||||
};
|
||||
|
||||
|
||||
@@ -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<TimeAttributionSpan>(entity.GetString("SegmentsJson")),
|
||||
RebootSpans = DeserializeJsonColumn<RebootSpan>(entity.GetString("RebootSpansJson")),
|
||||
SleepSpans = DeserializeJsonColumn<SleepSpan>(entity.GetString("SleepSpansJson")),
|
||||
BlockingApps = DeserializeJsonColumn<BlockingAppInterval>(entity.GetString("BlockingAppsJson")),
|
||||
};
|
||||
}
|
||||
|
||||
@@ -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',
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -530,6 +530,30 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public int MdmRebootPolicyBackfillLookbackMinutes { get; set; } = 60;
|
||||
|
||||
// -----------------------------------------------------------------------
|
||||
// System timeline watcher (System channel: clock changes + sleep episodes)
|
||||
// -----------------------------------------------------------------------
|
||||
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// </summary>
|
||||
public bool EnableSystemTimelineWatcher { get; set; } = true;
|
||||
|
||||
/// <summary>
|
||||
/// 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).
|
||||
/// </summary>
|
||||
public int SystemEventBackfillLookbackMinutes { get; set; } = 1440;
|
||||
|
||||
/// <summary>
|
||||
/// Creates default collector configuration
|
||||
/// </summary>
|
||||
|
||||
@@ -147,6 +147,27 @@ namespace AutopilotMonitor.Shared.Models
|
||||
public string SegmentKey { get; set; } = string.Empty;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// One completed sleep episode observed during the session (<c>system_sleep_episode</c>
|
||||
/// payload — <c>enteredAt</c>/<c>exitedAt</c> are the authoritative instants, never the
|
||||
/// event's own timestamp, which is stamped at wake and may be clamped). Cross-cutting
|
||||
/// annotation like <see cref="RebootSpan"/>: 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.
|
||||
/// </summary>
|
||||
public class SleepSpan
|
||||
{
|
||||
public DateTime StartUtc { get; set; }
|
||||
public DateTime EndUtc { get; set; }
|
||||
public int Seconds { get; set; }
|
||||
|
||||
/// <summary>Segment the episode started in (<see cref="TimeAttributionSegments"/> key, or "unattributed").</summary>
|
||||
public string SegmentKey { get; set; } = string.Empty;
|
||||
|
||||
/// <summary>Episode kind from the agent payload: "sleep", "hibernate" or "modern_standby".</summary>
|
||||
public string Kind { get; set; } = string.Empty;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// 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<RebootSpan> RebootSpans { get; set; } = new List<RebootSpan>();
|
||||
|
||||
/// <summary>Total observed in-window sleep seconds. Cross-cutting annotation like <see cref="RebootSeconds"/> — the wall clock keeps the pause; this discloses it.</summary>
|
||||
public int SleepSeconds { get; set; }
|
||||
|
||||
public List<SleepSpan> SleepSpans { get; set; } = new List<SleepSpan>();
|
||||
|
||||
/// <summary>
|
||||
/// Install intervals of ESP-blocking apps (positive-evidence join against the latest
|
||||
/// <c>esp_config_detected</c> lists), top 20 by duration. <see cref="BlockingAppCount"/>
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -220,6 +232,7 @@ export default function EventTimeline({
|
||||
onToggle={() => togglePhase(`pre-${phaseName}`)}
|
||||
showScriptOutput={showScriptOutput}
|
||||
borderColor="border-amber-400"
|
||||
clockDeltas={clockDeltas}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -257,6 +270,7 @@ export default function EventTimeline({
|
||||
isExpanded={expandedPhases.has(`user-${phaseName}`)}
|
||||
onToggle={() => togglePhase(`user-${phaseName}`)}
|
||||
showScriptOutput={showScriptOutput}
|
||||
clockDeltas={clockDeltas}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -304,6 +318,7 @@ export default function EventTimeline({
|
||||
isExpanded={expandedPhases.has(phaseName)}
|
||||
onToggle={() => togglePhase(phaseName)}
|
||||
showScriptOutput={showScriptOutput}
|
||||
clockDeltas={clockDeltas}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -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 (
|
||||
<div id={`phase-${phaseName.replace(/[^a-zA-Z0-9]/g, '-')}`} className={`border-l-4 ${borderColor} pl-4`}>
|
||||
@@ -353,6 +370,7 @@ function PhaseSection({
|
||||
event={event}
|
||||
showScriptOutput={showScriptOutput}
|
||||
prevEvent={i > 0 ? events[i - 1] : null}
|
||||
clockDeltas={clockDeltas}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -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
|
||||
)}
|
||||
</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} clockDeltas={clockDeltas} />
|
||||
<SeverityBadge severity={event.severity} />
|
||||
{isBackfilled && (
|
||||
<span
|
||||
@@ -686,6 +708,79 @@ function EventRow({ event, showScriptOutput, prevEvent }: { event: EnrollmentEve
|
||||
</div>
|
||||
);
|
||||
})()}
|
||||
{/* 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 (
|
||||
<div className="mt-1 flex flex-wrap items-center gap-2 text-xs">
|
||||
<span
|
||||
className={`px-1.5 py-0.5 rounded font-mono font-medium ${isLarge ? "bg-amber-100 text-amber-800" : "bg-sky-100 text-sky-800"}`}
|
||||
title={`The system clock was stepped ${forward ? "forward" : "backward"} by ${formatDuration(Math.abs(deltaMs) / 1000)}. oldTime/newTime in the event details are the authoritative instants.`}
|
||||
>
|
||||
⏱ {forward ? "+" : "−"}{formatDuration(Math.abs(deltaMs) / 1000)}
|
||||
</span>
|
||||
{reasonText && <span className="text-gray-500">{reasonText === "application_set" ? "set by a process" : reasonText === "hardware_clock_sync" ? "hardware clock sync" : reasonText}</span>}
|
||||
{processLeaf && <span className="text-gray-500 font-mono">{processLeaf}</span>}
|
||||
</div>
|
||||
);
|
||||
})()}
|
||||
{/* 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 (
|
||||
<div className="mt-1 flex flex-wrap items-center gap-2 text-xs">
|
||||
<span
|
||||
className="px-1.5 py-0.5 rounded bg-indigo-100 text-indigo-800 font-medium"
|
||||
title="The device completed a sleep episode; this event is recorded at wake. enteredAt/exitedAt in the details are the episode bounds — the surrounding timeline gap is explained by this pause."
|
||||
>
|
||||
🌙 {kindLabel}
|
||||
</span>
|
||||
{Number.isFinite(durationSeconds) && durationSeconds > 0 && (
|
||||
<span className="text-gray-600 font-medium">{formatDuration(durationSeconds)}</span>
|
||||
)}
|
||||
{wakeText && <span className="text-gray-500">wake: {wakeText}</span>}
|
||||
{onAcLabel && <span className="text-gray-500">{onAcLabel}</span>}
|
||||
</div>
|
||||
);
|
||||
})()}
|
||||
{/* 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 (
|
||||
<div className="mt-1 flex flex-wrap items-center gap-2 text-xs">
|
||||
<span className={`px-1.5 py-0.5 rounded font-medium ${chip.cls}`}>🔋 {chip.label}</span>
|
||||
{batteryPercent !== undefined && batteryPercent !== null && String(batteryPercent) !== "unknown" && (
|
||||
<span className="text-gray-500">{String(batteryPercent)}% charge</span>
|
||||
)}
|
||||
</div>
|
||||
);
|
||||
})()}
|
||||
<div className="mt-1 flex items-center gap-3 text-xs text-gray-500">
|
||||
<span>Source: {event.source}</span>
|
||||
<span>Seq: {event.sequence}</span>
|
||||
@@ -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?:
|
||||
<span className="text-gray-400 w-8 text-right flex-shrink-0">{event.sequence}</span>
|
||||
<span className="text-gray-500 flex-shrink-0">{(recordedAt ?? new Date(event.timestamp)).toLocaleTimeString()}</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} clockDeltas={clockDeltas} />
|
||||
<span className={`flex-shrink-0 w-14 ${sevColor[event.severity] || "text-gray-500"}`}>{event.severity}</span>
|
||||
{isBackfilled && (
|
||||
<span className="text-slate-500 flex-shrink-0" title={BACKFILL_TOOLTIP}>⟲</span>
|
||||
|
||||
@@ -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}
|
||||
/>
|
||||
<InfoItem label="Started" value={new Date(session.startedAt).toLocaleString([], { dateStyle: "short", timeStyle: "short" })} tooltip={lastContactTooltip} />
|
||||
<InfoItem label="Duration" value={enrollmentDuration ?? `${Math.round(session.durationSeconds / 60)} min`} tooltip={lastContactTooltip} />
|
||||
<InfoItem
|
||||
label="Duration"
|
||||
value={
|
||||
standbySeconds && standbySeconds >= 60 ? (
|
||||
<span>
|
||||
{enrollmentDuration ?? `${Math.round(session.durationSeconds / 60)} min`}
|
||||
<span
|
||||
className="text-indigo-600 font-normal"
|
||||
title={`The device spent ${formatStandby(standbySeconds)} asleep (standby/hibernate) during this window — the wall-clock duration includes that pause. Subtract it for the active enrollment time.`}
|
||||
>
|
||||
{" "}· 🌙 {formatStandby(standbySeconds)} standby
|
||||
</span>
|
||||
</span>
|
||||
) : (
|
||||
enrollmentDuration ?? `${Math.round(session.durationSeconds / 60)} min`
|
||||
)
|
||||
}
|
||||
tooltip={lastContactTooltip}
|
||||
/>
|
||||
<InfoItem label="Events" value={session.eventCount.toString()} tooltip={lastContactTooltip} />
|
||||
<InfoItem label="Reboots" value={(session.rebootCount ?? 0).toString()} tooltip="System reboots observed during enrollment (V2 only)" />
|
||||
<InfoItem label="Status" value={<StatusBadge status={displayStatus} failureReason={session.failureReason} failureSource={session.failureSource} adminMarkedAction={session.adminMarkedAction} reconcileReason={session.reconcileReason} espSoftFailure={session.espSoftFailure} />} />
|
||||
|
||||
@@ -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
|
||||
</span>
|
||||
</h3>
|
||||
{breakdown.rebootSeconds > 0 && (
|
||||
<span
|
||||
className="text-xs text-amber-700 bg-amber-50 border border-amber-200 rounded-full px-2 py-0.5"
|
||||
title="Reboot outage overlaps the segment it started in — it is not a separate slice of the bar."
|
||||
>
|
||||
⟳ {breakdown.rebootSpans.length} reboot{breakdown.rebootSpans.length !== 1 ? "s" : ""} · {formatDuration(breakdown.rebootSeconds)}
|
||||
</span>
|
||||
)}
|
||||
<span className="inline-flex items-center gap-2">
|
||||
{(breakdown.sleepSeconds ?? 0) > 0 && (
|
||||
<span
|
||||
className="text-xs text-indigo-700 bg-indigo-50 border border-indigo-200 rounded-full px-2 py-0.5"
|
||||
title="The device was asleep (standby/hibernate) for this long inside the enrollment window — the wall clock keeps the pause; this chip discloses it. Like reboots, sleep overlaps the segment it started in and is not a separate slice of the bar."
|
||||
>
|
||||
🌙 {(breakdown.sleepSpans ?? []).length} standby · {formatDuration(breakdown.sleepSeconds ?? 0)}
|
||||
</span>
|
||||
)}
|
||||
{breakdown.rebootSeconds > 0 && (
|
||||
<span
|
||||
className="text-xs text-amber-700 bg-amber-50 border border-amber-200 rounded-full px-2 py-0.5"
|
||||
title="Reboot outage overlaps the segment it started in — it is not a separate slice of the bar."
|
||||
>
|
||||
⟳ {breakdown.rebootSpans.length} reboot{breakdown.rebootSpans.length !== 1 ? "s" : ""} · {formatDuration(breakdown.rebootSeconds)}
|
||||
</span>
|
||||
)}
|
||||
</span>
|
||||
</div>
|
||||
|
||||
{/* Proportional stacked bar over the authoritative wall clock */}
|
||||
|
||||
@@ -25,6 +25,7 @@ export interface UseSessionDerivedDataReturn {
|
||||
gatherRulesSucceeded: boolean;
|
||||
displayStatus: string;
|
||||
enrollmentDurationFromEvents: string | null;
|
||||
standbySeconds: number | null;
|
||||
phaseNamesMap: Record<number, string>;
|
||||
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<string>();
|
||||
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,
|
||||
|
||||
@@ -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}
|
||||
/>
|
||||
</div>
|
||||
)}
|
||||
|
||||
@@ -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();
|
||||
});
|
||||
});
|
||||
|
||||
@@ -80,7 +80,7 @@ export function readTimeProvenance(data: Record<string, unknown> | 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<string, unknown> | 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";
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
Reference in New Issue
Block a user